Hmm - Daily Call no-longer connecting

Discussion in 'TiVo Series 1 - UK' started by DanBates, Jan 19, 2006.

  1. DanBates

    DanBates New Member

    18
    0
    Jun 10, 2002
    Cambridge

    Advertisements

    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 ?
     
  2. Glesgie

    Glesgie New Member

    194
    0
    Feb 3, 2003
    London
    Does the test call work ?

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

    DanBates New Member

    18
    0
    Jun 10, 2002
    Cambridge
    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
     
  4. DanBates

    DanBates New Member

    18
    0
    Jun 10, 2002
    Cambridge
    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::DoUpdates() has completed
    Jan 20 09:01:21 (none) tcphonehome[119]: LineupUpdate::DoUpdates 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.
     
  5. DanBates

    DanBates New Member

    18
    0
    Jun 10, 2002
    Cambridge

    Advertisements

    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:AD:D0: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]?
     
  6. Glesgie

    Glesgie New Member

    194
    0
    Feb 3, 2003
    London
    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.
     
  7. DanBates

    DanBates New Member

    18
    0
    Jun 10, 2002
    Cambridge
    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.
     
  8. Glesgie

    Glesgie New Member

    194
    0
    Feb 3, 2003
    London
    A reboot is all you need for this to happen.

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

    DanBates New Member

    18
    0
    Jun 10, 2002
    Cambridge
    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 :D
     

Share This Page

spam firewall

Advertisements