PDA

View Full Version : Failed. Service unavailable


sadrake
15-08-2005, 03:59 PM
Friday the 15th was the last time my Tivo was able to get guide data from the emulator.

I have forced the call with "forcedailycall.tcl" but it fails with

Failed. Service unavailable

Aug 15 18:54:13 (none) comm[162]: CallService: Start err 0
Aug 15 18:54:13 (none) comm[162]: CAM_ID not found.
Aug 15 18:54:13 (none) comm[162]: CallStatusReporter: Phase: Dial, Status In Progress
Aug 15 18:54:13 (none) comm[162]: CallStatusReporter: sending message "CL|30"
Aug 15 18:54:13 (none) comm[162]: Backdoor code 4, enable calls via broadband
Aug 15 18:54:13 (none) comm[162]: Using Ethernet. Not starting modem/pppd.
Aug 15 18:54:13 (none) comm[162]: CallStatusReporter: Phase: Start_Auth, Status In Progress
Aug 15 18:54:13 (none) comm[162]: CallStatusReporter: sending message "ST|33"
Aug 15 18:54:14 (none) comm[162]: CommUtil: connection to host 64.151.65.200, port 80, err 0x0
Aug 15 18:54:14 (none) comm[162]: Uploading HTTP Header for modLog of /var/log/svclog: POST /tivo-service/mlog.cgi HTTP/1.0^M Content-Length: 358^M ^M
Aug 15 18:54:17 (none) comm[162]: read HTTP Header: HTTP/1.0 200 OK^M Date: Mon, 15 Aug 2005 06:54:15 GMT^M Server: Apache/1.3.33 (Unix) (Gentoo/Linux) PHP/4.3.11 mod_gzip/1.3.26.1a^M Content-Type: text/plain; ch****t=ISO-8859-1^M X-Cache: MISS from cache1.qsi.net.nz^M Connection: close
Aug 15 18:54:17 (none) comm[162]: SvcLogRqst::verify: enter
Aug 15 18:54:17 (none) comm[162]: SvcLogRqst::verify: unlink(/var/log/svclog.upload)ed (status = 0)
Aug 15 18:54:17 (none) comm[162]: couldn't stat input file, reason = No such file or directory
Aug 15 18:54:17 (none) comm[162]: NetAgent::doXfer: open failed on Rqst : No such file or directory
Aug 15 18:54:17 (none) comm[162]: drainGetPostQ: doXfer failed err=65535 (0xffff)
Aug 15 18:54:17 (none) comm[162]: Xfer Performance Log says errors are Ok!
Aug 15 18:54:17 (none) comm[162]: CommUtil: connection to host 64.151.65.200, port 80, err 0x0
Aug 15 18:54:17 (none) comm[162]: read 384 bytes of upload data for FourOneOneRqst
Aug 15 18:54:18 (none) comm[162]: CommUtil: connection to host 64.151.65.200, port 80, err 0x0
Aug 15 18:54:18 (none) comm[162]: read 2002 bytes of upload data for HServerRqst
Aug 15 18:54:18 (none) comm[162]: HTTP header: HTTP/1.0 200 OK^M
Aug 15 18:54:18 (none) comm[162]: HTTP header: Date: Mon, 15 Aug 2005 06:54:15 GMT^M
Aug 15 18:54:18 (none) comm[162]: HTTP header: Server: Apache/1.3.33 (Unix) (Gentoo/Linux) PHP/4.3.11 mod_gzip/1.3.26.1a^M
Aug 15 18:54:18 (none) comm[162]: HTTP header: Content-Type: text/plain; ch****t=ISO-8859-1^M
Aug 15 18:54:18 (none) comm[162]: HTTP header: X-Cache: MISS from cache1.qsi.net.nz^M
Aug 15 18:54:18 (none) comm[162]: HTTP header: Connection: close^M
Aug 15 18:54:18 (none) comm[162]: HTTP header: ^M
Aug 15 18:54:18 (none) comm[162]: Start TCD411Resp =====================
Aug 15 18:54:18 (none) comm[162]: errMsg:
Aug 15 18:54:18 (none) comm[162]: areaCodeObj: OK
Aug 15 18:54:18 (none) comm[162]: tollFreeAuth: 0
Aug 15 18:54:18 (none) comm[162]: tollFreeNum:
Aug 15 18:54:18 (none) comm[162]: End TCD411Resp =====================
Aug 15 18:54:18 (none) comm[162]: current AreaCode object is OK
Aug 15 18:54:18 (none) comm[162]: HServerRqst::evaluate starting
Aug 15 18:54:18 (none) comm[162]: HTTP header: HTTP/1.0 411 Length Required^M
Aug 15 18:54:18 (none) comm[162]: HTTP header: Server: squid/2.5.STABLE3^M
Aug 15 18:54:18 (none) comm[162]: HTTP header: Mime-Version: 1.0^M
Aug 15 18:54:18 (none) comm[162]: HTTP header: Date: Mon, 15 Aug 2005 06:54:16 GMT^M
Aug 15 18:54:18 (none) comm[162]: HTTP header: Content-Type: text/html^M
Aug 15 18:54:18 (none) comm[162]: HTTP header: Content-Length: 3263^M
Aug 15 18:54:18 (none) comm[162]: HTTP header: Expires: Mon, 15 Aug 2005 06:54:16 GMT^M
Aug 15 18:54:18 (none) comm[162]: HTTP header: X-Squid-Error: ERR_INVALID_REQ 0^M
Aug 15 18:54:18 (none) comm[162]: HTTP header: X-Cache: MISS from cache1.qsi.net.nz^M
Aug 15 18:54:18 (none) comm[162]: HTTP header: Connection: close^M
Aug 15 18:54:18 (none) comm[162]: HTTP header: ^M
Aug 15 18:54:18 (none) comm[162]: Required Parameter ERR_MSG not present
Aug 15 18:54:18 (none) comm[162]: Required Parameter VERSION not present
Aug 15 18:54:18 (none) comm[162]: Required Parameter CODE not present
Aug 15 18:54:18 (none) comm[162]: Required Parameter SW_LIST not present
Aug 15 18:54:18 (none) comm[162]: Required Parameter BACK_CH_PRV not present
Aug 15 18:54:18 (none) comm[162]: Required Parameter BACK_CH_PUB not present
Aug 15 18:54:18 (none) comm[162]: Required Parameter BACK_CH_LOG not present
Aug 15 18:54:18 (none) comm[162]: Required Parameter TIME_SVC not present
Aug 15 18:54:18 (none) comm[162]: Required Parameter SEQ_COOKIE not present
Aug 15 18:54:18 (none) comm[162]: Required Parameter INV_FILE not present
Aug 15 18:54:18 (none) comm[162]: Required Parameter NO_PRV_BACKHAUL not present
Aug 15 18:54:18 (none) comm[162]: Required Parameter SERVICE_STATE not present
Aug 15 18:54:18 (none) comm[162]: Required Parameter STATE_EXPIRE not present
Aug 15 18:54:18 (none) comm[162]: Required Parameter SW_SYSTEM_NAME not present
Aug 15 18:54:18 (none) comm[162]: HServerRqst: readBlock failed, err = 0xffff
Aug 15 18:54:18 (none) comm[162]: NetAgent: drainEvalQ failed, err = 0xffff
Aug 15 18:54:18 (none) comm[162]: CallService: NetAgent Process err 65535
Aug 15 18:54:18 (none) comm[162]: CallService: NetAgent failed, status 0xffff
Aug 15 18:54:18 (none) comm[162]: CallService: EndCall start
Aug 15 18:54:20 (none) comm[162]: CallStatusReporter: Turning off-hook LED off
Aug 15 18:54:21 (none) comm[162]: Recover private logs
Aug 15 18:54:21 (none) comm[162]: Opening old private log files
Aug 15 18:54:21 (none) comm[162]: Reverting private logs
Aug 15 18:54:21 (none) comm[162]: Cleanup: GetAddDiskBasedDirectories returned <70001> "0x70001"...skipping cleanup
Aug 15 18:54:21 (none) tcphonehome[162]: CallService return status 0xffff
Aug 15 18:54:21 (none) tcphonehome[162]: GetPostalCodeVersion - /PostalCode/02113 ServerVersion=27
Aug 15 18:54:21 (none) tcphonehome[162]: debug: sumServerVersion=27
Aug 15 18:54:21 (none) comm[162]: CallStatusReporter: Phase: Start_Auth, Status Failed
Aug 15 18:54:21 (none) comm[162]: CallStatusReporter: sending message "EX|14"
Aug 15 18:54:21 (none) tcphonehome[162]: TClient failed: EX|14
Aug 15 18:54:21 (none) tcphonehome[162]: Sending dialup event, subtype 8, msg EX|14
Aug 15 18:54:21 (none) tcphonehome[162]: setCallStatus called with: Failed state 0
Aug 15 18:54:21 (none) tcphonehome[162]: LastCallAttempt at 1124132019
Aug 15 18:54:21 (none) tcphonehome[162]: setting call status to: Failed
Aug 15 18:54:25 (none) tcphonehome[162]: setting call in progress to 0 (second successCount)
Aug 15 18:54:25 (none) tcphonehome[162]: Setting callActive to 0
Aug 15 18:54:25 (none) comm[162]: CallStatusReporter: sending data changed event 20
Aug 15 18:54:25 (none) tcphonehome[162]: destroying CommGlobals!
Aug 15 18:54:25 (none) tcphonehome[162]: pCommMempool empty
Aug 15 18:54:35 (none) tcphonehome[162]: Setting MCP PhoneHome action: ENABLED
DJC
15-08-2005, 08:28 PM
Has your isp changed their proxy recently?

Does your oztivo image run emuProxy?
sadrake
16-08-2005, 04:04 AM
On Friday I changed from xtra to Quicksilver as my broadband provider

http://forums.oztivo.net/showthread.php?t=179&highlight=proxy

Peterd - solved this issue by turning off his proxy.

I don't run a proxy or does he mean turn off proxy on the Tivo??
sadrake
16-08-2005, 06:37 AM
Has your isp changed their proxy recently?

Does your oztivo image run emuProxy?

Im using the 1.4 image, is the emuProxy setting in tclient.conf?

I havent changed the emuProxy setting from what came with the image if that helps - should i turn it off?

edit- just found

http://minnie.tuhs.org/twiki/bin/view/Network/BypassTransparentProxyServer

Should I setup the emuProxy to solve my problem?
DJC
16-08-2005, 07:35 AM
Ok, so the problem obviously coincides with the change of ISP.

Looks to me like squid (proxy) does not like the tivo request.

Check your tclient file, if you are NOT using emuProxy it will have the emulator ip for 127.

If you are using emuProxy, it will look like this 127::127.0.0.1:8000:::

if you are not using it, I suggest installing/trying it, apparently it is designed to 'linearise' the http request stream to be more compatible...

A suggestion at least :)
sadrake
16-08-2005, 07:40 AM
Thanks DJC

I'll give the emuproxy a go tonight, sounds like it may solve my issue, I have asked if Quicksilver can exclude 64.151.65.200 from caching on the proxy also but wont hold my breath.
sadrake
16-08-2005, 07:54 AM
Question To get this to work for NZ in the instructions for editing rc.sysinit I would have to add the IP address for the New Zealand emulator.


Edit /etc/rc.d/rc.sysinit.author, Append the line:
/hack/bin/emuProxy2 &

Change to:
/hack/bin/emuProxy2 -s 64.151.65.200 &

This is so it would point to the New Zealand emulator and not the hardcoded Aussie one.

The reason I ask as I looked in emuProxy2.c it has the server IP hardcoded as 131.244.9.101 and in New Zealand we are using 64.151.65.200.
petestrash
16-08-2005, 01:21 PM
Just thought I'd drop a note in here for people searching the threads.

Whenever you see 'HTTP header: HTTP/1.0' in tclient that usually means the ISP's transparent proxy is not handling the tivo correctly.

A successful tclient will list 'HTTP Header: HTTP/1.1'.

As sadrake has done, the best solution is to ask your ISP to exclude the emulator IP from the transparent proxy service (or fix the proxy). New Zealand IP 64.151.65.200 or Australia IP 131.244.9.101

If you are using OzTiVo image r1.4 you 'should' be able to use emuproxy2 for the NZ emulator if it is setup to use it, just by changing the IP in /etc/rc.d/rc.sysinit.author


Emu Proxy
# A tool for cleaning up the HTTP output by the Tivo in order to pass through
# transparent proxies, etc.
# Works in conjunction with a small hack to the emulator to accept the header
# "TivoURLBase" which is the base url to give back to the Tivo when specifying
# data paths.
# Runs by default and is dependent on the
# 127::127.0.0.1:8000:::
# entry in tclient.conf
# IF YOU COMMENT THIS OUT SO IT DOESN'T RUN, YOU MUST EDIT THE "127" entry
# in /etc/tclient.conf to reflect the IP and port of the emulator you are using
# There is a backup of the original here: /etc/tclient.conf-oztivo
# Usage: %s [-d] [-h] [-l localport] [-L listenAddr] [-s serverip]
# [-p serverport]
emuProxy2 -s 64.151.65.200 &


Haven't tried it myself though, since I'm in Australia.

Peter.
sadrake
16-08-2005, 01:51 PM
As I expected the ISP wont exclude the IP from the proxy's cache.

Will let you know how using the emuproxy goes tonight - fingers crossed.
sadrake
16-08-2005, 03:15 PM
:confused:

The ISP's proxy still does not like it. as long as everything is configured correctly to use it...

rc.d.author
# Usage: %s [-d] [-h] [-l localport] [-L listenAddr] [-s serverip]
# [-p serverport]
emuProxy2 -s 64.151.65.200 &


tclient.conf
#
# This is the default port, it's values come from Addr.itcl not here
#
000:
# Dennis' Emulator
#126::66.23.218.193:80:::
# This is for the server emulator on minnie. Trouble if your ISP blocks HTTP .9
# 127::64.151.65.200:80:::

# This uses emuProxy2 to avoid problems with transparent proxy. Thanks Tim!
127::127.0.0.1:8000:::

tclient log file....

Aug 16 17:54:15 (none) comm[157]: CallService: Start err 0
Aug 16 17:54:15 (none) comm[157]: CAM_ID not found.
Aug 16 17:54:15 (none) comm[157]: CallStatusReporter: Phase: Dial, Status In Progress
Aug 16 17:54:15 (none) comm[157]: CallStatusReporter: sending message "CL|30"
Aug 16 17:54:16 (none) comm[157]: Backdoor code 4, enable calls via broadband
Aug 16 17:54:16 (none) comm[157]: Using Ethernet. Not starting modem/pppd.
Aug 16 17:54:16 (none) comm[157]: CallStatusReporter: Phase: Start_Auth, Status In Progress
Aug 16 17:54:16 (none) comm[157]: CallStatusReporter: sending message "ST|33"
Aug 16 17:54:16 (none) comm[157]: CommUtil: connection to host 127.0.0.1, port 8000, err 0x0
Aug 16 17:54:16 (none) comm[157]: Uploading HTTP Header for modLog of /var/log/svclog: POST /tivo-service/mlog.cgi HTTP/1.0^M Content-Length: 358^M ^M
Aug 16 17:54:16 (none) comm[157]: read HTTP Header: HTTP/1.0 200 OK^M Date: Tue, 16 Aug 2005 05:54:07 GMT^M Server: Apache/2.0.53^M Content-Type: text/plain; ch****t=ISO-8859-1^M X-Cache: MISS from cache1.qsi.net.nz^M Connection: close
Aug 16 17:54:16 (none) comm[157]: SvcLogRqst::verify: enter
Aug 16 17:54:16 (none) comm[157]: SvcLogRqst::verify: unlink(/var/log/svclog.upload)ed (status = 0)
Aug 16 17:54:17 (none) comm[157]: couldn't stat input file, reason = No such file or directory
Aug 16 17:54:17 (none) comm[157]: NetAgent::doXfer: open failed on Rqst : No such file or directory
Aug 16 17:54:17 (none) comm[157]: drainGetPostQ: doXfer failed err=65535 (0xffff)
Aug 16 17:54:17 (none) comm[157]: Xfer Performance Log says errors are Ok!
Aug 16 17:54:17 (none) comm[157]: CommUtil: connection to host 127.0.0.1, port 8000, err 0x0
Aug 16 17:54:17 (none) comm[157]: read 384 bytes of upload data for FourOneOneRqst
Aug 16 17:54:18 (none) comm[157]: CommUtil: connection to host 127.0.0.1, port 8000, err 0x0
Aug 16 17:54:18 (none) comm[157]: read 2000 bytes of upload data for HServerRqst
Aug 16 17:54:18 (none) comm[157]: HTTP header: HTTP/1.0 200 OK^M
Aug 16 17:54:18 (none) comm[157]: HTTP header: Date: Tue, 16 Aug 2005 05:54:08 GMT^M
Aug 16 17:54:18 (none) comm[157]: HTTP header: Server: Apache/2.0.53^M
Aug 16 17:54:18 (none) comm[157]: HTTP header: Content-Type: text/plain; ch****t=ISO-8859-1^M
Aug 16 17:54:18 (none) comm[157]: HTTP header: X-Cache: MISS from cache1.qsi.net.nz^M
Aug 16 17:54:18 (none) comm[157]: HTTP header: Connection: close^M
Aug 16 17:54:18 (none) comm[157]: HTTP header: ^M
Aug 16 17:54:18 (none) comm[157]: Start TCD411Resp =====================
Aug 16 17:54:18 (none) comm[157]: errMsg:
Aug 16 17:54:18 (none) comm[157]: areaCodeObj: &http://127.0.0.1:8000/tivo-static/headends/AC-002-v1.slice|
Aug 16 17:54:18 (none) comm[157]: tollFreeAuth: 0
Aug 16 17:54:18 (none) comm[157]: tollFreeNum: 0
Aug 16 17:54:18 (none) comm[157]: End TCD411Resp =====================
Aug 16 17:54:18 (none) comm[157]: HServerRqst::evaluate starting
Aug 16 17:54:18 (none) comm[157]: HTTP header: HTTP/1.0 411 Length Required^M
Aug 16 17:54:18 (none) comm[157]: HTTP header: Server: squid/2.5.STABLE3^M
Aug 16 17:54:18 (none) comm[157]: HTTP header: Mime-Version: 1.0^M
Aug 16 17:54:18 (none) comm[157]: HTTP header: Date: Tue, 16 Aug 2005 05:54:15 GMT^M
Aug 16 17:54:18 (none) comm[157]: HTTP header: Content-Type: text/html^M
Aug 16 17:54:18 (none) comm[157]: HTTP header: Content-Length: 3319^M
Aug 16 17:54:18 (none) comm[157]: HTTP header: Expires: Tue, 16 Aug 2005 05:54:15 GMT^M
Aug 16 17:54:18 (none) comm[157]: HTTP header: X-Squid-Error: ERR_INVALID_REQ 0^M
Aug 16 17:54:18 (none) comm[157]: HTTP header: X-Cache: MISS from cache1.qsi.net.nz^M
Aug 16 17:54:18 (none) comm[157]: HTTP header: Connection: close^M
Aug 16 17:54:18 (none) comm[157]: HTTP header: ^M
Aug 16 17:54:18 (none) comm[157]: Required Parameter ERR_MSG not present
Aug 16 17:54:18 (none) comm[157]: Required Parameter VERSION not present
Aug 16 17:54:18 (none) comm[157]: Required Parameter CODE not present
Aug 16 17:54:18 (none) comm[157]: Required Parameter SW_LIST not present
Aug 16 17:54:18 (none) comm[157]: Required Parameter BACK_CH_PRV not present
Aug 16 17:54:18 (none) comm[157]: Required Parameter BACK_CH_PUB not present
Aug 16 17:54:18 (none) comm[157]: Required Parameter BACK_CH_LOG not present
Aug 16 17:54:18 (none) comm[157]: Required Parameter TIME_SVC not present
Aug 16 17:54:18 (none) comm[157]: Required Parameter SEQ_COOKIE not present
Aug 16 17:54:18 (none) comm[157]: Required Parameter INV_FILE not present
Aug 16 17:54:18 (none) comm[157]: Required Parameter NO_PRV_BACKHAUL not present
Aug 16 17:54:18 (none) comm[157]: Required Parameter SERVICE_STATE not present
Aug 16 17:54:18 (none) comm[157]: Required Parameter STATE_EXPIRE not present
Aug 16 17:54:18 (none) comm[157]: Required Parameter SW_SYSTEM_NAME not present
Aug 16 17:54:18 (none) comm[157]: HServerRqst: readBlock failed, err = 0xffff
Aug 16 17:54:18 (none) comm[157]: NetAgent: drainEvalQ failed, err = 0xffff
Aug 16 17:54:18 (none) comm[157]: CallService: NetAgent Process err 65535
Aug 16 17:54:18 (none) comm[157]: CallService: NetAgent failed, status 0xffff
Aug 16 17:54:18 (none) comm[157]: CallService: EndCall start
DJC
16-08-2005, 07:02 PM
Hmmm, looks like the 2nd attempt got further as its recognising the area code slice....?

Heres another thing to try.. the development emulator [woooo] is on port 8000, its likely that your isp isn't transparent proxy'ing that port.

Might be worth a crack, provided you haven't got any logos loaded...
petestrash
16-08-2005, 07:30 PM
Aug 16 17:54:16 (none) comm[157]: Uploading HTTP Header for modLog of /var/log/svclog: POST /tivo-service/mlog.cgi HTTP/1.0^M Content-Length: 358^M ^M

Aug 16 17:54:16 (none) comm[157]: read HTTP Header: HTTP/1.0 200 OK^M Date: Tue, 16 Aug 2005 05:54:07 GMT^M Server: Apache/2.0.53^M Content-Type: text/plain; ch****t=ISO-8859-1^M X-Cache: MISS from cache1.qsi.net.nz^M Connection: close

If the emuproxy2 was working properly the 2nd 'HTTP Header' line should be 1.1 and not 1.0 still. It's ok for the 'Uploading Header' line to show 1.0.

Perhaps the hack has not been implemented on the NZ server.

Peter.
sadrake
17-08-2005, 06:13 AM
As you suggested trying the Dev server I changed rc.sysinit.author to point at the dev server and added the port and rebooted

emuProxy2 -s 210.48.107.133 -p 8000 &

It has gone through and downloaded the guide data - so happy days. I was almost ready to switch back to xtra (as much as I hate telecom at least their service worked for all of my equipment)

Seeing as this worked it tells me that emuproxy was working correctly when I was pointing it at the production emulator but for some reason still did not work. As peter mentioned maybe the hack has not been implemented on it yet?
DJC
17-08-2005, 09:40 AM
Its an interesting little experiment, and handy to know that an emulator on a port other than 80 is a useful thing. Welcome to the dev emulator setup, presume you have logos slices and so on now, data updates daily ~ any issues post them into the dev forum so we don't get confused.

Cheers/DJC