[DanBates]

This is confusing me - my last successful daily call was early in the morning on Monday. I have a turbonet and the calls are set to use the internet. I've introduced a hub at the Tivo end recently, but I know I'm getting connectivity still because I can still tivoweb into the box.

Anyone got any ideas why the outgoing data call might be failing when the network is still good, and what I might do to solve the problem ?

 

[Glesgie]

Does the test call work ?

Check the logs, specifically 0tvlog (if you have tivoweb).

 

[DanBates]

Test call doesn't work either.

The log stops at 9 January for some reason ?! Last logs look like this:

Jan 9 06:28:30 (none) Recorder[153]: Free live cache chunk: 1550622
Jan 9 06:28:30 (none) Recorder[153]: Adding check schedule task
Jan 9 06:28:38 (none) mempool[146]: MyWorld block: 902kB/1137kB chunk: 242kB/422kB unused: 2082kB search: 1 (size=3731424)
Jan 9 06:28:38 (none) mempool[146]: Osd block: 74kB/83kB chunk: 949kB/1245kB unused: 1649kB search: 0 (size=3051488)
Jan 9 06:30:05 (none) Recorder[153]: AllocateFiles for live cache
Jan 9 06:30:05 (none) Recorder[153]: Live cache size 1462272
Jan 9 06:30:05 (none) Recorder[153]: User recording 104700288 free 1137024
Jan 9 06:30:05 (none) Recorder[153]: TivoClip total 10000000 free 9712256
Jan 9 06:30:05 (none) Recorder[153]: Allocated stream Id 1550678, size 208896
Jan 9 06:30:05 (none) mediamgr[153]: AddLiveFile input#0
Jan 9 06:30:06 (none) Recorder[153]: Adding check schedule task
Jan 9 06:31:22 (none) TmkTransform::Trace[152]: ClipCache 0x300143d8 Secondary Reset
Jan 9 06:31:22 (none) ClipCache[148]: 0x300143d8 in Entry(), thread 148
Jan 9 06:32:04 (none) TmkMediaswitch::Trace[152]: Drift = -5
Jan 9 06:34:26 (none) mediamgr[153]: RemoveWrittenLiveFile input#0
Jan 9 06:34:26 (none) MultiMpegCache[153]: Delete stream 1550623(inx = 0, read = 0, write =7) totalCount 8
Jan 9 06:34:26 (none) TmkMultiMpegClip::Trace[153]: Tried to delete reader clip
Jan 9 06:34:26 (none) TmkMultiMpegClip::Trace[153]: bactrace is 01be8018 01be75bc 01bdf048 01b06378 01b05c90 01b98f88 01b98e24 01b03f80 01b04e88 01b91bb4
Jan 9 06:34:26 (none) Recorder[153]: Free live cache chunk: 1550623
Jan 9 06:34:26 (none) Recorder[153]: Adding check schedule task
Jan 9 06:35:07 (none) Recorder[153]: AllocateFiles for live cache
Jan 9 06:35:07 (none) Recorder[153]: Live cache size 1462272
Jan 9 06:35:07 (none) Recorder[153]: User recording 104700288 free 1137024
Jan 9 06:35:07 (none) Recorder[153]: TivoClip total 10000000 free 9712256
Jan 9 06:35:07 (none) Recorder[153]: Allocated stream Id 1550679, size 208896
Jan 9 06:35:07 (none) mediamgr[153]: AddLiveFile input#0
Jan 9 06:35:07 (none) Recorder[153]: Adding check schedule task
Jan 9 06:36:17 (none) TmkTransform::Trace[152]: ClipCache 0x3000697c Secondary Reset
Jan 9 06:36:17 (none) ClipCache[147]: 0x3000697c in Entry(), thread 147
Jan 9 06:37:57 (none) MCPaction[119]: Trigger action 2 client 1!
Jan 9 06:37:57 (none) tcphonehome[119]: getting /Setup/Complete
Jan 9 06:37:57 (none) MCPaction[119]: Set complete: 7
Jan 9 06:37:57 (none) tcphonehome[119]: useBackupTollFree is 0
Jan 9 06:37:57 (none) tcphonehome[119]: phonehome: recieved message. type = 30 subtype = 6
Jan 9 06:37:57 (none) tcphonehome[119]: Invoking TClient with arg
Jan 9 06:37:57 (none) tcphonehome[119]: GetPostalCodeVersion - /PostalCode/PE28 ServerVersion=675
Jan 9 06:37:57 (none) tcphonehome[119]: getting LastSuccessfulCall
Jan 9 06:37:58 (none) tcphonehome[119]: called getTZ
Jan 9 06:37:58 (none) tcphonehome[119]: IsPrimeTime: tz_off = 0, now = 31137704, adj_hour = 6
Jan 9 06:37:58 (none) tcphonehome[119]: checking ServiceState
Jan 9 06:37:58 (none) tcphonehome[119]: setCallStatus called with: In Progress state 1
Jan 9 06:37:58 (none) tcphonehome[119]: Successfully got /Setup object
Jan 9 06:37:58 (none) tcphonehome[119]: Last call attempt at 1136701681
Jan 9 06:37:58 (none) tcphonehome[119]: setting call status to: In Progress
Jan 9 06:37:58 (none) tcphonehome[119]: Successfully got ServiceInfo subobject (first successCount)
Jan 9 06:37:58 (none) tcphonehome[119]: setting call in progress to 1 (second successCount)
Jan 9 06:37:58 (none) tcphonehome[119]: End of transaction, err is 0 0x00000000
Jan 9 06:37:58 (none) tcphonehome[119]: Setting callActive to 1
Jan 9 06:37:58 (none) tcphonehome[119]: setting call attempt
Jan 9 06:37:58 (none) tcphonehome[119]: Running TClient
Jan 9 06:37:58 (none) tcphonehome[119]: Running command: $TIVO_ROOT/tvbin/tivosh $TIVO_ROOT/tvbin/TClient -auto>> /var/log/tclient
Jan 9 06:37:58 (none) tcl[349]: Tcl created pool of 3145728 bytes
Jan 9 06:38:09 (none) EvtSwitcher[74]: Tmk client 14 (pid=349) has attached
Jan 9 06:38:09 (none) EvtSwitcher[74]: Client 14 (Phone Home, pid=349) is service Phone Home
Jan 9 06:38:09 (none) EvtSwitcher[74]: Client 14 (Phone Home, pid=349), thread 349 has activated MFS
Jan 9 06:38:09 (none) TClient[349]: activated
Jan 9 06:38:09 (none) EvtSwitcher[74]: Client 14 (Phone Home, pid=349) has asked for 30 events
Jan 9 06:38:15 (none) mediamgr[153]: RemoveWrittenLiveFile input#0
Jan 9 06:38:15 (none) MultiMpegCache[153]: Delete stream 1550624(inx = 0, read = 0, write =7) totalCount 8
Jan 9 06:38:15 (none) TmkMultiMpegClip::Trace[153]: Tried to delete reader clip
Jan 9 06:38:15 (none) TmkMultiMpegClip::Trace[153]: bactrace is 01be8018 01be75bc 01bdf048 01b06378 01b05c90 01b98f88 01b98e24 01b03f80 01b04e88 01b91bb4
Jan 9 06:38:16 (none) Recorder[153]: Free live cache chunk: 1550624
Jan 9 06:38:16 (none) Recorder[153]: Adding check schedule task
Jan 9 06:38:36 (none) EvtSwitcher[74]: Client 14 (Phone Home, pid=349) has asked for 26 events
Jan 9 06:39:36 (none) Recorder[153]: AllocateFiles for live cache
Jan 9 06:39:36 (none) Recorder[153]: Live cache size 1462272
Jan 9 06:39:36 (none) Recorder[153]: User recording 104700288 free 1137024
Jan 9 06:39:36 (none) Recorder[153]: TivoClip total 10000000 free 9712256
Jan 9 06:39:36 (none) Recorder[153]: Allocated stream Id 1550680, size 208896
Jan 9 06:39:36 (none) mediamgr[153]: AddLiveFile input#0
Jan 9 06:39:36 (none) Recorder[153]: Adding check schedule task
Jan 9 06:40:08 (none) TClient[349]: connect 204.176.49.3:80
Jan 9 06:40:32 (none) FinishedLoading[349]: done
Jan 9 06:40:33 (none) EvtSwitcher[74]: Client 14 (Phone Home, pid=349) has asked for 77 events
Jan 9 06:40:40 (none) EvtSwitcher[74]: Client 14 (Phone Home, pid=349) has asked for 23 events
Jan 9 06:40:40 (none) last message repeated 3 times
Jan 9 06:40:40 (none) DbGc[139]: got EVT_DATA_CHANGED/DATA_PROGRAM_GUIDE
Jan 9 06:40:40 (none) DbGc[139]: got INDEX_SOON
Jan 9 06:40:40 (none) DbGc[139]: setting action's timeout to INDEX_SOON
Jan 9 06:40:40 (none) DbGcBaseAction[139]: Background->SetTimeout( 2 )
Jan 9 06:40:40 (none) DbGc[139]: got EVT_DATA_CHANGED/DATA_SHOWCASE
Jan 9 06:40:40 (none) DbGc[139]: got INDEX_SOON
Jan 9 06:40:40 (none) DbGc[139]: setting action's timeout to INDEX_SOON
Jan 9 06:40:40 (none) EventLogger[144]: Calling ForcePeriodicLog in DATA_LOG_REVERT
Jan 9 06:40:41 (none) EventLogger[144]: EventLogger: Cached Now Showing, 72 items
Jan 9 06:40:41 (none) EventLogger[144]: EventLogger: Cached Wish Lists, 6 items
Jan 9 06:40:41 (none) EventLogger[144]: EventLogger clip list is empty, resetting timer
Jan 9 06:40:41 (none) EventLogger[144]: EventLogger: Cached clips, 0 items
Jan 9 06:40:41 (none) EventLogger[144]: EventLogger promoWiener list is empty, resetting timer
Jan 9 06:40:41 (none) EventLogger[144]: EventLogger: Cached promowiener, 0 items
Jan 9 06:40:41 (none) TClient[349]: completed
Jan 9 06:40:41 (none) EvtSwitcher[74]: Client 14 (Phone Home, pid=349) says he has finished
Jan 9 06:40:41 (none) EvtSwitcher[74]: Client 14 (Phone Home, pid=349) being removed
Jan 9 06:40:41 (none) tcphonehome[119]: Command finished status: 0, errno = 2
Jan 9 06:40:41 (none) tcphonehome[119]: TClient returns status 0
Jan 9 06:40:41 (none) tcphonehome[119]: TClient success
Jan 9 06:40:41 (none) tcphonehome[119]: read /var/tmp/TClient.res TClient::login:retcode 0
Jan 9 06:40:41 (none) tcphonehome[119]: matched, retcode = 0
Jan 9 06:40:41 (none) tcphonehome[119]: read /var/tmp/TClient.res TClient::backHaulDone 1
Jan 9 06:40:41 (none) tcphonehome[119]: matched, backHaulDone = 1
Jan 9 06:40:41 (none) tcphonehome[119]: read /var/tmp/TClient.res TClient::backHaulDone 1
Jan 9 06:40:41 (none) tcphonehome[119]: matched, backHaulDone = 1
Jan 9 06:40:41 (none) tcphonehome[119]: tcphonehome: found TClient retcode = 0
Jan 9 06:40:41 (none) tcphonehome[119]: tcphonehome: found TClient backHaulDone = 1
Jan 9 06:40:41 (none) tcphonehome[119]: checking ServiceState
Jan 9 06:40:42 (none) tcphonehome[119]: ReschedCall: reason = 0, secSinceLast = 0, numFails = 0
Jan 9 06:40:42 (none) tcphonehome[119]: ReschedCall: reschedule after success
Jan 9 06:40:42 (none) tcphonehome[119]: setting next attempt at 1136875302 (Tue Jan 10 06:41:42 2006 )
Jan 9 06:40:42 (none) tcphonehome[119]: Resched Call: resched for 1441 min; should happen at Tue Jan 10 06:41:42 2006
Jan 9 06:40:42 (none) tcphonehome[119]: Running command: $TIVO_ROOT/tvbin/modemtest AT\&V1\&V2
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: AT&V1&V2
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: TERMINATION REASON.......... LOCAL REQUEST
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: LAST TX rate................ 24000 BPS
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: HIGHEST TX rate............. 24000 BPS
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: LAST RX rate................ 31200 BPS
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: HIGHEST RX rate............. 31200 BPS
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: PROTOCOL.................... LAPM
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: COMPRESSION................. NONE
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: Line QUALITY................ 042
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: Rx LEVEL.................... 028
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: Highest Rx State............ 67
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: Highest TX State............ 67
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: EQM Sum..................... 003C
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: RBS Pattern................. FF
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: Rate Drop................... FF
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: Digital Loss................ None
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: Local Rtrn Count............ 00
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: Remote Rtrn Count........... 00
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: Flex fail
Jan 9 06:40:43 (none) tcphonehome[119]: Command output:
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: BEGINaa12ab12ac12ad12ba15bb15bc15bd15ca77cb69cc205da5ea0eb0fa68fb67fc68ga12gb3ha42hb36hc44hd0he65hf60hg0hh0hi0hj40hk44hl40hm40h
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: n39ho43hp42hq39hr41hs43ia23ib23ic23ja0jb0jc0jd0je0jf0ka1kb1kc1kd1ke16kf16kg0kh4ki38kj0kk0kl37km33kn255la103lb103lc103ld103ma0mb
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: 0mc22na0nb0oa0ob255oc255od20oe254of7og181pa1pb0pc0pd0qa0qb1qc6ra2rb255rc255rd255re255rf255rg255rh213sa255sb255sc255sd255ta15tb0
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: tc0td218te255tf255tg255th0ti0END
Jan 9 06:40:43 (none) tcphonehome[119]: Command output:
Jan 9 06:40:43 (none) tcphonehome[119]: Command output: OK
Jan 9 06:40:43 (none) tcphonehome[119]: Command finished status: 0, errno = 2
Jan 9 06:40:43 (none) tcphonehome[119]: Rotating log files

 

[DanBates]

Looking in tvlog rather than 0tvlog (after trying a test call and a daily call) I see this:

Jan 20 08:51:42 (none) TmkMediaswitch::Trace[152]: Drift = -5
Jan 20 08:52:22 (none) Recorder[153]: AllocateFiles for live cache
Jan 20 08:52:22 (none) Recorder[153]: Live cache size 1253376
Jan 20 08:52:22 (none) Recorder[153]: User recording 104909184 free 2004352
Jan 20 08:52:22 (none) Recorder[153]: TivoClip total 10000000 free 9712256
Jan 20 08:52:22 (none) Recorder[153]: Allocated stream Id 1566646, size 208896
Jan 20 08:52:22 (none) mediamgr[153]: AddLiveFile input#0
Jan 20 08:52:22 (none) Recorder[153]: Adding check schedule task
Jan 20 08:52:49 (none) TmkMediaswitch::Trace[152]: Lost VBI lock
Jan 20 08:52:52 (none) last message repeated 23 times
Jan 20 08:53:27 (none) DbGc[139]: DbGc::HandleTriggerWhileIdle -- clock is warped -- re-marking in 300 seconds
Jan 20 08:53:31 (none) TmkTransform::Trace[152]: ClipCache 0x30014358 Secondary Reset
Jan 20 08:53:31 (none) ClipCache[149]: 0x30014358 in Entry(), thread 149
Jan 20 08:54:07 (none) TmkMediaswitch::Trace[152]: Lost VBI lock
Jan 20 08:55:07 (none) last message repeated 349 times
Jan 20 08:57:38 (none) last message repeated 595 times
Jan 20 08:57:38 (none) TmkTransform::Trace[157]: set_scartstate to 0
Jan 20 08:57:38 (none) TmkMediaswitch::Trace[152]: Lost VBI lock
Jan 20 08:57:38 (none) TmkMediaswitch::Trace[152]: Lost VBI lock
Jan 20 08:57:38 (none) VideoGuts[157]: PlayLive for Proxy 55
Jan 20 08:57:38 (none) TvVideoPolicy[157]: LiveTunerRequest on 55
Jan 20 08:57:38 (none) VideoGuts[157]: LiveTunerResult ALLOWED 55
Jan 20 08:57:38 (none) InputState[157]: AttachProxyForOutput 0
Jan 20 08:57:38 (none) OutputState[157]: PlayLive 0
Jan 20 08:57:38 (none) TmkMediaswitch::Trace[152]: Lost VBI lock
Jan 20 08:57:38 (none) LogTime[157]: WatchTV: setup live: 0.197 sec
Jan 20 08:57:38 (none) TmkMediaswitch::Trace[152]: Lost VBI lock
Jan 20 08:57:38 (none) last message repeated 2 times
Jan 20 08:57:51 (none) last message repeated 114 times
Jan 20 08:57:51 (none) Promo[157]: Promo errNmNameNotFound: line 557
Jan 20 08:57:51 (none) Promo[157]: PromoRotation::NextValid cannot find valid promotion.
Jan 20 08:57:51 (none) Promo[157]: PromoRotation::SetupPromotion Could not find a valid Promotion
Jan 20 08:57:51 (none) TmkMediaswitch::Trace[152]: Lost VBI lock
Jan 20 08:58:00 (none) tcphonehome[119]: useBackupTollFree is 0
Jan 20 08:58:00 (none) tcphonehome[119]: phonehome: recieved message. type = 30 subtype = 3
Jan 20 08:58:00 (none) tcphonehome[119]: Invoking TClient with arg -t
Jan 20 08:58:09 (none) tcphonehome[119]: setCallStatus called with: In Progress state 1
Jan 20 08:58:09 (none) tcphonehome[119]: Successfully got /Setup object
Jan 20 08:58:09 (none) tcphonehome[119]: Last call attempt at 1137708704
Jan 20 08:58:09 (none) tcphonehome[119]: setting call status to: In Progress
Jan 20 08:58:09 (none) tcphonehome[119]: Successfully got ServiceInfo subobject (first successCount)
Jan 20 08:58:09 (none) tcphonehome[119]: setting call in progress to 1 (second successCount)
Jan 20 08:58:09 (none) tcphonehome[119]: End of transaction, err is 0 0x00000000
Jan 20 08:58:09 (none) tcphonehome[119]: Setting callActive to 1
Jan 20 08:58:09 (none) tcphonehome[119]: setting call attempt
Jan 20 08:58:09 (none) tcphonehome[119]: Running TClient -t
Jan 20 08:58:09 (none) tcphonehome[119]: Running command: $TIVO_ROOT/tvbin/tivosh $TIVO_ROOT/tvbin/TClient -t>> /var/log/tclient
Jan 20 08:58:09 (none) last message repeated 97 times
Jan 20 08:58:11 (none) tcl[219]: Tcl created pool of 3145728 bytes
Jan 20 08:58:23 (none) EvtSwitcher[74]: Tmk client 14 (pid=219) has attached
Jan 20 08:58:23 (none) EvtSwitcher[74]: Client 14 (Phone Home, pid=219) is service Phone Home
Jan 20 08:58:23 (none) EvtSwitcher[74]: Client 14 (Phone Home, pid=219), thread 219 has activated MFS
Jan 20 08:58:24 (none) TClient[219]: activated
Jan 20 08:58:24 (none) EvtSwitcher[74]: Client 14 (Phone Home, pid=219) has asked for 30 events
Jan 20 08:58:42 (none) EvtSwitcher[74]: Client 14 (Phone Home, pid=219) says he has finished
Jan 20 08:58:42 (none) EvtSwitcher[74]: Client 14 (Phone Home, pid=219) being removed
Jan 20 08:58:42 (none) tcphonehome[119]: Command finished status: 0, errno = 2
Jan 20 08:58:42 (none) tcphonehome[119]: TClient returns status 0
Jan 20 08:58:42 (none) tcphonehome[119]: TClient success
Jan 20 08:58:42 (none) tcphonehome[119]: read /var/tmp/TClient.res TClient::login:retcode 1
Jan 20 08:58:42 (none) tcphonehome[119]: matched, retcode = 1
Jan 20 08:58:42 (none) tcphonehome[119]: read /var/tmp/TClient.res TClient::backHaulDone 0
Jan 20 08:58:42 (none) tcphonehome[119]: matched, backHaulDone = 0
Jan 20 08:58:42 (none) tcphonehome[119]: read /var/tmp/TClient.res TClient::backHaulDone 0
Jan 20 08:58:42 (none) tcphonehome[119]: matched, backHaulDone = 0
Jan 20 08:58:42 (none) tcphonehome[119]: tcphonehome: found TClient retcode = 1
Jan 20 08:58:42 (none) tcphonehome[119]: tcphonehome: found TClient backHaulDone = 0
Jan 20 08:58:42 (none) tcphonehome[119]: TClient failed: CL|12
Jan 20 08:58:42 (none) tcphonehome[119]: Running command: $TIVO_ROOT/tvbin/modemtest AT\&V1\&V2
Jan 20 08:58:43 (none) tcphonehome[119]: Command output: AT&V1&V2
Jan 20 08:58:43 (none) tcphonehome[119]: Command output: TERMINATION REASON.......... NONE
Jan 20 08:58:43 (none) tcphonehome[119]: Command output: LAST TX rate................ N/A
Jan 20 08:58:43 (none) tcphonehome[119]: Command output: HIGHEST TX rate............. 300 BPS
Jan 20 08:58:43 (none) tcphonehome[119]: Command output: LAST RX rate................ N/A
Jan 20 08:58:43 (none) tcphonehome[119]: Command output: HIGHEST RX rate............. 300 BPS
Jan 20 08:58:43 (none) tcphonehome[119]: Command output: PROTOCOL.................... N/A
Jan 20 08:58:43 (none) tcphonehome[119]: Command output: COMPRESSION................. N/A
Jan 20 08:58:43 (none) tcphonehome[119]: Command output: Line QUALITY................ 255
Jan 20 08:58:43 (none) tcphonehome[119]: Command output: Rx LEVEL.................... 215
Jan 20 08:58:43 (none) tcphonehome[119]: Command output: Highest Rx State............ 00
Jan 20 08:58:43 (none) tcphonehome[119]: Command output: Highest TX State............ 00
Jan 20 08:58:43 (none) tcphonehome[119]: Command output: EQM Sum..................... FFFF
Jan 20 08:58:43 (none) tcphonehome[119]: Command output: RBS Pattern................. FF
Jan 20 08:58:43 (none) tcphonehome[119]: Command output: Rate Drop................... FF
Jan 20 08:58:43 (none) tcphonehome[119]: Command output: Digital Loss................ None
Jan 20 08:58:44 (none) tcphonehome[119]: Command output: Local Rtrn Count............ 00
Jan 20 08:58:44 (none) tcphonehome[119]: Command output: Remote Rtrn Count........... 00
Jan 20 08:58:44 (none) tcphonehome[119]: Command output: Flex fail
Jan 20 08:58:44 (none) tcphonehome[119]: Command output:
Jan 20 08:58:44 (none) tcphonehome[119]: Command output: BEGINaa255ab255ac0ad255ba255bb255bc0bd255ca255cb255cc255da255ea255eb255fa255fb255fc0ga255gb255ha255hb255hc0hd0he255hf255hg255hh
Jan 20 08:58:44 (none) tcphonehome[119]: Command output: 255hi255hj255hk255hl255hm255hn255ho255hp255hq255hr255hs255ia255ib255ic0ja0jb0jc0jd0je0jf0ka255kb255kc255kd255ke255kf255kg255kh2
Jan 20 08:58:44 (none) tcphonehome[119]: Command output: 55ki255kj255kk255kl255km255kn255la0lb0lc255ld255ma0mb0mc0na255nb255oa255ob255oc255od255oe255of255og255pa255pb0pc255pd255qa21qb0
Jan 20 08:58:44 (none) tcphonehome[119]: Command output: qc255ra255rb255rc255rd255re255rf255rg255rh255sa255sb255sc255sd255ta255tb0tc255td255te255tf255tg255th0ti0END
Jan 20 08:58:44 (none) tcphonehome[119]: Command output:
Jan 20 08:58:44 (none) tcphonehome[119]: Command output: OK
Jan 20 08:58:44 (none) tcphonehome[119]: Command finished status: 0, errno = 2
Jan 20 08:58:44 (none) tcphonehome[119]: setCallStatus called with: Failed state 0
Jan 20 08:58:44 (none) tcphonehome[119]: Successfully got /Setup object
Jan 20 08:58:44 (none) tcphonehome[119]: Last call attempt at 1137747489
Jan 20 08:58:44 (none) tcphonehome[119]: setting call status to: Failed
Jan 20 08:58:44 (none) tcphonehome[119]: Successfully got ServiceInfo subobject (first successCount)
Jan 20 08:58:44 (none) tcphonehome[119]: setting call in progress to 0 (second successCount)
Jan 20 08:58:44 (none) tcphonehome[119]: End of transaction, err is 0 0x00000000
Jan 20 08:58:44 (none) tcphonehome[119]: Setting callActive to 0
Jan 20 08:58:44 (none) mediamgr[153]: RemoveWrittenLiveFile input#0
Jan 20 08:58:44 (none) MultiMpegCache[153]: Delete stream 1566640(inx = 0, read = 6, write =6) totalCount 7
Jan 20 08:58:44 (none) Recorder[153]: Free live cache chunk: 1566640
Jan 20 08:58:45 (none) Recorder[153]: Adding check schedule task
Jan 20 08:58:51 (none) tcphonehome[119]: getting /Setup/Complete
Jan 20 08:59:05 (none) tcphonehome[119]: useBackupTollFree is 1
Jan 20 08:59:05 (none) tcphonehome[119]: phonehome: recieved message. type = 30 subtype = 0
Jan 20 08:59:05 (none) tcphonehome[119]: Invoking TClient with arg -f
Jan 20 08:59:05 (none) tcphonehome[119]: GetPostalCodeVersion - /PostalCode/PE28 ServerVersion=675
Jan 20 08:59:05 (none) tcphonehome[119]: setCallStatus called with: In Progress state 1
Jan 20 08:59:06 (none) tcphonehome[119]: Successfully got /Setup object
Jan 20 08:59:06 (none) tcphonehome[119]: Last call attempt at 1137747489
Jan 20 08:59:06 (none) tcphonehome[119]: setting call status to: In Progress
Jan 20 08:59:06 (none) tcphonehome[119]: Successfully got ServiceInfo subobject (first successCount)
Jan 20 08:59:06 (none) tcphonehome[119]: setting call in progress to 1 (second successCount)
Jan 20 08:59:06 (none) Recorder[153]: Adding check schedule task
Jan 20 08:59:06 (none) Recorder[153]: CheckSchedule: creating action for: rec 1566117
Jan 20 08:59:06 (none) Recorder[153]: Creating normal action
Jan 20 08:59:06 (none) Recorder[153]: Creating normal action
Jan 20 08:59:06 (none) Recorder[153]: CheckSchedule: next creation at 13168 38346: rec 1566615
Jan 20 08:59:06 (none) Recorder[153]: InitialAction rec 1566117
Jan 20 08:59:06 (none) Recorder[153]: InitialAction RecId 1566117
Jan 20 08:59:06 (none) Recorder[153]: Item 1566117: estimate kb per second: 1154
Jan 20 08:59:06 (none) tcphonehome[119]: End of transaction, err is 0 0x00000000
Jan 20 08:59:06 (none) tcphonehome[119]: Setting callActive to 1
Jan 20 08:59:06 (none) tcphonehome[119]: setting call attempt
Jan 20 08:59:06 (none) tcphonehome[119]: Running TClient
Jan 20 08:59:06 (none) tcphonehome[119]: Running command: $TIVO_ROOT/tvbin/tivosh $TIVO_ROOT/tvbin/TClient -backup>> /var/log/tclient
Jan 20 08:59:06 (none) tcl[227]: Tcl created pool of 3145728 bytes
Jan 20 08:59:07 (none) Recorder[153]: RequestTuner rec 1566117
Jan 20 08:59:07 (none) TvVideoPolicy[153]: RecordingTunerRequest on 62
Jan 20 08:59:07 (none) VideoGuts[153]: RecordingTunerResult DENIED 62
Jan 20 08:59:07 (none) Recorder[153]: Got EVT_VIDEO_SESSION 5
Jan 20 08:59:07 (none) Recorder[153]: DeniedTunerLock event received
Jan 20 08:59:07 (none) Recorder[153]: DeniedTunerLock event received
Jan 20 08:59:07 (none) Recorder[153]: Abr-- recording 1566117 reason DeniedTunerLock event in recording engine
Jan 20 08:59:07 (none) Recorder[153]: Adding check schedule task
Jan 20 08:59:16 (none) EvtSwitcher[74]: Tmk client 15 (pid=227) has attached
Jan 20 08:59:16 (none) EvtSwitcher[74]: Client 15 (Phone Home, pid=227) is service Phone Home
Jan 20 08:59:16 (none) EvtSwitcher[74]: Client 15 (Phone Home, pid=227), thread 227 has activated MFS
Jan 20 08:59:16 (none) TClient[227]: activated
Jan 20 08:59:17 (none) EvtSwitcher[74]: Client 15 (Phone Home, pid=227) has asked for 30 events
Jan 20 08:59:48 (none) EvtSwitcher[74]: Client 15 (Phone Home, pid=227) has asked for 26 events
Jan 20 09:00:35 (none) Recorder[153]: AllocateFiles for live cache
Jan 20 09:00:35 (none) Recorder[153]: Live cache size 1253376
Jan 20 09:00:35 (none) Recorder[153]: User recording 104909184 free 2004352
Jan 20 09:00:35 (none) Recorder[153]: TivoClip total 10000000 free 9712256
Jan 20 09:00:35 (none) Recorder[153]: Allocated stream Id 1566647, size 208896
Jan 20 09:00:35 (none) mediamgr[153]: AddLiveFile input#0
Jan 20 09:00:36 (none) Recorder[153]: Adding check schedule task
Jan 20 09:00:55 (none) MCPaction[117]: WatchdogAction::Trigger: callActive for 900 interval-secs
Jan 20 09:01:08 (none) EventLogger[145]: Calling ForcePeriodicLog in DATA_LOG_REVERT
Jan 20 09:01:13 (none) EvtSwitcher[74]: Client 15 (Phone Home, pid=227) says he has finished
Jan 20 09:01:13 (none) EvtSwitcher[74]: Client 15 (Phone Home, pid=227) being removed
Jan 20 09:01:13 (none) tcphonehome[119]: Command finished status: 0, errno = 2
Jan 20 09:01:13 (none) tcphonehome[119]: TClient returns status 0
Jan 20 09:01:13 (none) tcphonehome[119]: TClient success
Jan 20 09:01:13 (none) tcphonehome[119]: read /var/tmp/TClient.res TClient::login:retcode 1
Jan 20 09:01:13 (none) tcphonehome[119]: matched, retcode = 1
Jan 20 09:01:13 (none) tcphonehome[119]: read /var/tmp/TClient.res TClient::backHaulDone 0
Jan 20 09:01:13 (none) tcphonehome[119]: matched, backHaulDone = 0
Jan 20 09:01:13 (none) tcphonehome[119]: read /var/tmp/TClient.res TClient::backHaulDone 0
Jan 20 09:01:13 (none) tcphonehome[119]: matched, backHaulDone = 0
Jan 20 09:01:13 (none) tcphonehome[119]: tcphonehome: found TClient retcode = 1
Jan 20 09:01:13 (none) tcphonehome[119]: tcphonehome: found TClient backHaulDone = 0
Jan 20 09:01:13 (none) tcphonehome[119]: TClient failed: CL|12
Jan 20 09:01:13 (none) tcphonehome[119]: Running command: $TIVO_ROOT/tvbin/modemtest AT\&V1\&V2
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: AT&V1&V2
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: TERMINATION REASON.......... NONE
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: LAST TX rate................ N/A
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: HIGHEST TX rate............. 300 BPS
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: LAST RX rate................ N/A
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: HIGHEST RX rate............. 300 BPS
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: PROTOCOL.................... N/A
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: COMPRESSION................. N/A
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: Line QUALITY................ 255
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: Rx LEVEL.................... 215
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: Highest Rx State............ 00
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: Highest TX State............ 00
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: EQM Sum..................... FFFF
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: RBS Pattern................. FF
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: Rate Drop................... FF
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: Digital Loss................ None
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: Local Rtrn Count............ 00
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: Remote Rtrn Count........... 00
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: Flex fail
Jan 20 09:01:14 (none) tcphonehome[119]: Command output:
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: BEGINaa255ab255ac0ad255ba255bb255bc0bd255ca255cb255cc255da255ea255eb255fa255fb255fc0ga255gb255ha255hb255hc0hd0he255hf255hg255hh
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: 255hi255hj255hk255hl255hm255hn255ho255hp255hq255hr255hs255ia255ib255ic0ja0jb0jc0jd0je0jf0ka255kb255kc255kd255ke255kf255kg255kh2
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: 55ki255kj255kk255kl255km255kn255la0lb0lc255ld255ma0mb0mc0na255nb255oa255ob255oc255od255oe255of255og255pa255pb0pc255pd255qa21qb0
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: qc255ra255rb255rc255rd255re255rf255rg255rh255sa255sb255sc255sd255ta255tb0tc255td255te255tf255tg255th0ti0END
Jan 20 09:01:14 (none) tcphonehome[119]: Command output:
Jan 20 09:01:14 (none) tcphonehome[119]: Command output: OK
Jan 20 09:01:14 (none) tcphonehome[119]: Command finished status: 0, errno = 2
Jan 20 09:01:14 (none) tcphonehome[119]: setCallStatus called with: Failed state 0
Jan 20 09:01:14 (none) tcphonehome[119]: Successfully got /Setup object
Jan 20 09:01:14 (none) tcphonehome[119]: Last call attempt at 1137747546
Jan 20 09:01:14 (none) tcphonehome[119]: setting call status to: Failed
Jan 20 09:01:14 (none) tcphonehome[119]: Successfully got ServiceInfo subobject (first successCount)
Jan 20 09:01:14 (none) tcphonehome[119]: setting call in progress to 0 (second successCount)
Jan 20 09:01:14 (none) tcphonehome[119]: End of transaction, err is 0 0x00000000
Jan 20 09:01:14 (none) tcphonehome[119]: Setting callActive to 0
Jan 20 09:01:14 (none) tcphonehome[119]: GetPostalCodeVersion - /PostalCode/PE28 ServerVersion=675
Jan 20 09:01:21 (none) tcphonehome[119]: GetPostalCodeVersion - /PostalCode/PE28 ServerVersion=675
Jan 20 09:01:21 (none) LineupUpdate[119]: Gathering current Channel settings
Jan 20 09:01:21 (none) LineupUpdate[119]: Checking Headend Lineups
Jan 20 09:01:21 (none) LineupUpdate[119]: Sorting and reporting changes
Jan 20 09:01:21 (none) LineupUpdate[119]: No lineup changes were detected
Jan 20 09:01:21 (none) LineupUpdate[119]: LineupUpdate:oUpdates() has completed
Jan 20 09:01:21 (none) tcphonehome[119]: LineupUpdate:oUpdates returned 0
Jan 20 09:01:22 (none) DbGc[139]: DbGc::HandleTriggerWhileIdle -- clock is warped -- re-marking in 300 seconds
Jan 20 09:01:27 (none) EventLogger[145]: EventLogger: Cached Now Showing, 71 items
Jan 20 09:01:27 (none) EventLogger[145]: EventLogger: Cached Wish Lists, 6 items
Jan 20 09:01:27 (none) EventLogger[145]: EventLogger clip list is empty, resetting timer
Jan 20 09:01:27 (none) EventLogger[145]: EventLogger: Cached clips, 0 items
Jan 20 09:01:27 (none) EventLogger[145]: EventLogger promoWiener list is empty, resetting timer
Jan 20 09:01:27 (none) EventLogger[145]: EventLogger: Cached promowiener, 0 items
Jan 20 09:01:30 (none) mempool[147]: MyWorld block: 715kB/943kB chunk: 234kB/370kB unused: 2328kB search: 1 (size=3731424)
Jan 20 09:01:30 (none) mempool[147]: Osd block: 79kB/87kB chunk: 839kB/1244kB unused: 1646kB search: 0 (size=3051488)
Jan 20 09:01:32 (none) EventLogger[145]: Done Logging wish lists
Jan 20 09:01:49 (none) TmkTransform::Trace[157]: set_scartstate to 1
Jan 20 09:02:04 (none) TmkTransform::Trace[152]: ClipCache 0x30014138 Secondary Reset
Jan 20 09:02:04 (none) ClipCache[148]: 0x30014138 in Entry(), thread 148
Jan 20 09:02:27 (none) TmkMediaswitch::Trace[152]: Lost VBI lock

Any ideas ? My data is getting out of date to the extent it's causing problems now.

 

[DanBates]

This from tivoweb when executing nic_config_tivo:

bash-2.02# nic_config_tivo

TiVo TurboNet/AirNet/CacheCard on Tivo Configure - 20050218

Copyright 2002-2004 Silicondust Engineering Ltd. All rights reserved.

Detecting TiVo hard drive...

Detecting TiVo partitions...
Active kernel partition = /dev/hda3.
Inactive kernel partition = /dev/hda6.
Active root partition = /dev/hda4.
Inactive root partition = /dev/hda7.
Var partition = /dev/hda9.

Determining software version...
Thomson UK Stand Alone TiVo running 2.5.5-01-1-023

Remounting root partition...
Root successfully remounted as writable.

Checking installation type...
Configuring TurboNet installation.

Checking script...
Complete.

Current/New Configuration:
timing setting = optimal
mac address = 00:0B:AD0:BA:54
ip address = 192.168.0.20
ip subnet mask = 255.255.255.0
ip gateway = 192.168.0.1
debug level = off
daily call = network

Options
1: Change timing setting
2: Change MAC address
3: Change IP address/gateway
4: Change debug logging option
5: Change daily call option
9: View/extract log file
0: Apply and exit
!: Exit without saving

[0..6]?

 

[Glesgie]

Can you attach the TiVo to a phone line and check if it tries to dial out ?

If it does, then it is possibly the infamous race condition at startup.
The solution to that is to background all the commands in

/etc/rc.d/rc.sysinit.author

by making sure/adding a space followed by an & at the end of each line.

 

[DanBates]

Have reconnected the phone line and it works (despite the TiVO being set to 'make daily call over network')... At least the data is there which is the most important thing.

I'm going to fiddle with the rc.sysinit.author next. I saw the other threads, but wasn't sure they applied to me because they always seemed to have an event triggering the problem. I can't identify anything which might have caused this.

I'll update once the download has finished and I've tried the background thing.

 

[Glesgie]

A reboot is all you need for this to happen.

Often a second reboot will fix it, but not always.

 

[DanBates]

An additional reboot didn't work, even though the data was now in from the phone line. Thankfully though, when I edited the author file, one of the commands didn't have a " &" on it, and when I added it and rebooted it's all working again - whew !

No idea why it started happening, but frankly I don't care now I'm getting my data again !

Thanks so much for all your help Glesgie