S1 now failing to connect for daily call or test call

[peter]

Hi guys,
Peter suggested I post my latest tclient log here for help as I can't work out what is wrong.
Could you please take a look and see if you can tell what it is.
(I have the full log but forum is only 10k in characters)
Thanks heaps, Peter D

TivoWebPlus
v1.3.1
[10.1.1.200] Channel Grid Conflict Resolve Folders HiGuide Info Logs Mail Manual Record Phone Screen Search SysAdmin Theme User Interface Web Remote What's On more... Restart
/var/log/tclient/


Nov 8 14:11:01 (none) WatchdogAction[143]: WatchdogAction::Trigger: callActive for 90900 interval-secs
Nov 8 14:27:00 (none) tcphonehome[129]: TCphonehome active
Nov 8 14:27:00 (none) tcphonehome[146]: cleaning /Setup
Nov 8 14:27:00 (none) tcphonehome[146]: Fetching /SwSystemACTIVE/Name
Nov 8 14:27:00 (none) tcphonehome[146]: Last Call Status Was: 'In Progress' (size 11)
Nov 8 14:27:00 (none) tcphonehome[146]: Last Call Status Will Be: Failed
Nov 8 14:27:00 (none) tcphonehome[146]: setCallStatus called with: Failed state 0
Nov 8 14:27:00 (none) tcphonehome[146]: LastCallAttempt at 1257597748
Nov 8 14:27:00 (none) tcphonehome[146]: setting call status to: Failed
Nov 8 14:27:00 (none) tcphonehome[146]: setting call in progress to 0 (second successCount)
Nov 8 14:27:00 (none) tcphonehome[146]: setting CallStatusInfo to: 6
Nov 8 14:27:00 (none) tcphonehome[146]: Setting callActive to 0
Nov 8 14:27:00 (none) tcphonehome[146]: PhoneHome: statusValue = <0>, getResult = <0>
Nov 8 14:27:00 (none) tcphonehome[146]: /State/Avalanche LastStatus was <0> and getResult was <0>, changing to unknown
Nov 8 14:27:00 (none) tcphonehome[146]: finished cleaning /Setup
Nov 8 14:27:00 (none) tcphonehome[146]: About to execute: /sbin/ifconfig eth0 2>&1
Nov 8 14:27:00 (none) tcphonehome[146]: Command Output: eth0 Link encap:Ethernet HWaddr 00:0B:AD:27:40:95
Nov 8 14:27:00 (none) tcphonehome[146]: Command Output: inet addr:10.1.1.200 Bcast:10.255.255.255 Mask:255.255.255.0
Nov 8 14:27:00 (none) tcphonehome[146]: Command Output: UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1
Nov 8 14:27:00 (none) tcphonehome[146]: Command Output: RX packets:2 errors:0 dropped:0 overruns:0 frame:0
Nov 8 14:27:00 (none) tcphonehome[146]: Command Output: TX packets:0 errors:0 dropped:0 overruns:0 carrier:0 coll:0
Nov 8 14:27:00 (none) tcphonehome[146]: Command Output: Interrupt:29
Nov 8 14:27:00 (none) tcphonehome[146]: Command Output:
Nov 8 14:27:00 (none) tcphonehome[146]: Command succeeded
Nov 8 14:27:00 (none) tcphonehome[146]: NOT Using debug ethernet
Nov 8 14:27:00 (none) tcphonehome[146]: Error statting file /var/log/http: No such file or directory (errno=2)
Nov 8 14:27:00 (none) tcphonehome[146]: Error statting file /var/log/Ohttp: No such file or directory (errno=2)
Nov 8 14:27:00 (none) tcphonehome[146]: Timesync is within the past 5 days... all is well
Nov 8 14:27:00 (none) tcphonehome[146]: ReschedCall: reason = 7, secSinceLast = 0, numFails = 0
Nov 8 14:27:00 (none) tcphonehome[146]: Schedule call after failure
Nov 8 14:27:00 (none) tcphonehome[146]: setting next attempt at 1257693240 (Sun Nov 8 15:14:00 2009 )
Nov 8 14:27:00 (none) tcphonehome[146]: ReschedCall(7, 0) in 47 min
Nov 8 14:27:01 (none) PhoneAction[146]: PhoneAction 2 register complete timeout 2820
Nov 8 14:27:01 (none) PhoneAction[146]: Register Complete: Next call should happen at Sun Nov 8 15:14:01 2009
Nov 8 14:27:01 (none) tcphonehome[146]: called getTZ
Nov 8 14:27:01 (none) WatchdogAction[146]: WatchdogAction register complete
Nov 8 14:28:20 (none) tcphonehome[146]: getting /State/GeneralConfig/Complete
Nov 8 14:28:20 (none) tcphonehome[146]: Setting MCP PhoneHome action: RUNNING
Nov 8 14:28:20 (none) tcphonehome[146]: pCommMempool empty
Nov 8 14:28:20 (none) tcphonehome[146]: useBackupTollFree is 1
Nov 8 14:28:20 (none) tcphonehome[146]: phonehome: received message. type = 30 subtype = 0
Nov 8 14:28:20 (none) tcphonehome[146]: creating CommGlobals
Nov 8 14:28:24 (none) tcphonehome[146]: created CommGlobals
Nov 8 14:28:24 (none) tcphonehome[146]: PerformCall, subtype=0 forceTollFree=0 automated=0
Nov 8 14:28:24 (none) tcphonehome[146]: GetPostalCodeVersion - /PostalCode/02000 ServerVersion=90
Nov 8 14:28:24 (none) tcphonehome[146]: debug: sumServerVersion=90
Nov 8 14:28:24 (none) tcphonehome[146]: setCallStatus called with: In Progress state 1
Nov 8 14:28:24 (none) tcphonehome[146]: LastCallAttempt at 1257597748
Nov 8 14:28:24 (none) tcphonehome[146]: setting call status to: In Progress
Nov 8 14:28:24 (none) tcphonehome[146]: setting call in progress to 1 (second successCount)
Nov 8 14:28:24 (none) tcphonehome[146]: Setting callActive to 1
Nov 8 14:28:24 (none) tcphonehome[146]: setting call attempt
Nov 8 14:28:24 (none) tcphonehome[146]: Error statting file /var/log/http: No such file or directory (errno=2)
Nov 8 14:28:24 (none) tcphonehome[146]: Error statting file /var/log/Ohttp: No such file or directory (errno=2)
Nov 8 14:28:24 (none) tcphonehome[146]: Calling TClient
Nov 8 14:28:24 (none) comm[146]: CallStatusReporter: Phase: Select_Phone, Status In Progress
Nov 8 14:28:24 (none) comm[146]: CallStatusReporter: sending message "EX|29"
Nov 8 14:28:24 (none) comm[146]: CallService: preprocessing call.
Nov 8 14:28:24 (none) comm[146]: CallStatusReporter: Phase: Prepare_Call, Status In Progress
Nov 8 14:28:24 (none) comm[146]: CallStatusReporter: sending message "EX|29"
Nov 8 14:28:24 (none) comm[146]: LogMgr: start writing to GzPacker(/var/tmp/syslog.gz)
Nov 8 14:28:25 (none) comm[146]: skipping filter line itself!
Nov 8 14:28:33 (none) last message repeated 2669 times
Nov 8 14:28:33 (none) comm[146]: LogMgr: end writing to GzPacker(/var/tmp/syslog.gz)
Nov 8 14:28:33 (none) comm[146]: Starting Private Logs processing; send event to MW
Nov 8 14:28:34 (none) comm[146]: waiting for logs to divert...
Nov 8 14:28:34 (none) comm[143]: Received the LOGMGR WAIT event
Nov 8 14:28:34 (none) comm[146]: logs diverted.
Nov 8 14:28:34 (none) comm[146]: Do actual private logs processing
Nov 8 14:28:42 (none) comm[146]: Error getting demographic info: No Tuner Count
Nov 8 14:28:42 (none) comm[146]: encryptFile: infile = /var/persist/thumbslog.log.gz outfile = /var/persist/thumbslog.log.gz.bfg keyname = BACKHAUL_THUMB
Nov 8 14:28:42 (none) comm[146]: encryptFile: file non-existent or zero size: /var/persist/thumbslog.log.gz
Nov 8 14:28:47 (none) comm[146]: CmdProc: wrote /var/log/tivoLog.prv.gz
Nov 8 14:28:47 (none) comm[146]: encryptFile: infile = /var/log/tivoLog.prv.gz outfile = /var/log/tivoLog.prv.gz.bfg keyname = BACKHAUL_PRIVATE
Nov 8 14:28:47 (none) comm[146]: About to execute: /tvbin/genkey 128 1 2>&1
Nov 8 14:28:48 (none) comm[146]: Command succeeded
Nov 8 14:28:48 (none) comm[146]: EncryptLog: key was empty for BACKHAUL_PRIVATE
Nov 8 14:28:48 (none) comm[146]: Done with actual private logs processing
Nov 8 14:28:48 (none) comm[146]: About to execute: /tvbin/crypto -gsn 2>&1
Nov 8 14:28:49 (none) comm[146]: Command succeeded
Nov 8 14:28:49 (none) comm[146]: About to execute: /tvbin/crypto -gsv 2>&1
Nov 8 14:28:50 (none) comm[146]: Command succeeded
Nov 8 14:28:56 (none) comm[146]: About to execute: /tvbin/crypto -x -gek 2>&1
Nov 8 14:29:04 (none) comm[146]: Command succeeded
Nov 8 14:29:05 (none) comm[146]: ProgramDataUtil: Accumulated 31 station days
Nov 8 14:29:05 (none) comm[146]: working on headend, TMS Id: NS12001
Nov 8 14:29:06 (none) comm[146]: ProgramDataUtil: found 39 of 39 station IDs
Nov 8 14:29:06 (none) comm[146]: ProgramDataUtil: begin station masks for headend NS12001
Nov 8 14:29:06 (none) comm[146]: ProgramDataUtil: base date is 14552, today's date is 14556
Nov 8 14:29:06 (none) comm[146]: #7999999-1fc #7300012-0 #7200002-7e #7200003-7e #7200028-7e
Nov 8

[petestrash]

Could you please zip the whole log and post it.

Peter.

[peter]

Hi Peter, here it is zipped (i hope uploaded as it says it is).
Thank you

[petestrash]

Ok, the problem is at this line:
Nov 8 14:32:05 (none) comm[146]: XferRqst timeout waiting to read

1. Has anything changed on your home network
2. What ISP are you using.
3. What version of the OzTiVo software are you using?

Peter.

[peter]

Yes - I have always been on Optus ADSL+2 and changed modems about 2 months ago to the Sagem Fast 1201 v2 modem which would not connect Tivo but then settled I thought. I am on 1.6.2.-20081005

[petestrash]

Alright, I will first assume that your modem is not causing the problem if it has worked since changing it (but is likely to be the cause if it has not worked since).

My first suggestion would be to change your configuration file to point to our server on port 9090 to bypass any potential proxy servers Optus may have installed.

You need to edit /etc/oztivo.conf and change the emulator and emulatorport lines so that they show:

emulator=www.oztivo.net
emulatorport=9090

After making the filesystem read only again reboot the TiVo and try forcing a call.

Peter.

[peter]

Thanks Peter, I will give it a go by the weekend and post the results. It still could be the newish modem as it is freezing every hour on the internet - and Optus said it was Explorer but Google Chrome does the same! Peter

[petestrash]

ok, then I probably wouldn't play with the TiVo until you get the modem sorted.

Peter.