tivo crash - help with decoding logs

[worm]

tivo just decided to reboot itself for no apparant reason

I'm useless with reading log file, so does anyone see anything dodgy in this ? (this is the part just before the reboot - from tvlog)

Jun 13 21:21:44 (none) MultiMpegCache[147]: Delete stream 921386(inx = 0, read = 7, write =7) totalCount 8
Jun 13 21:21:44 (none) Recorder[147]: Free live cache chunk: 921386
Jun 13 21:21:44 (none) Recorder[147]: Adding check schedule task
Jun 13 21:24:06 (none) Recorder[147]: AllocateFiles for live cache
Jun 13 21:24:06 (none) Recorder[147]: Live cache size 1462272
Jun 13 21:24:06 (none) Recorder[147]: User recording 147279232 free 1413504
Jun 13 21:24:06 (none) Recorder[147]: TivoClip total 10000000 free 9712256
Jun 13 21:24:06 (none) Recorder[147]: Allocated stream Id 921394, size 208896
Jun 13 21:24:06 (none) mediamgr[147]: AddLiveFile input#0
Jun 13 21:24:06 (none) Recorder[147]: Adding check schedule task
Jun 13 21:25:09 (none) mempool[141]: MyWorld block: 885kB/1339kB chunk: 244kB/449kB unused: 1853kB search: 1 (size=3731424)
Jun 13 21:25:09 (none) mempool[141]: Osd block: 140kB/158kB chunk: 1004kB/1531kB unused: 1288kB search: 0 (size=3051488)
Jun 13 21:25:16 (none) TmkTransform::Trace[146]: ClipCache 0x300155b4 Secondary Reset
Jun 13 21:25:16 (none) ClipCache[142]: 0x300155b4 in Entry(), thread 142
Jun 13 21:25:41 (none) TmkMediaswitch::Trace[146]: Lost VBI lock
Jun 13 21:26:12 (none) last message repeated 275 times
Jun 13 21:26:34 (none) last message repeated 202 times
Jun 13 21:26:34 (none) mediamgr[147]: RemoveWrittenLiveFile input#0
Jun 13 21:26:34 (none) MultiMpegCache[147]: Delete stream 921387(inx = 0, read = 7, write =7) totalCount 8
Jun 13 21:26:34 (none) Recorder[147]: Free live cache chunk: 921387
Jun 13 21:26:34 (none) TmkMediaswitch::Trace[146]: Lost VBI lock
Jun 13 21:26:34 (none) Recorder[147]: Adding check schedule task
Jun 13 21:26:34 (none) TmkMediaswitch::Trace[146]: Lost VBI lock

[ColinYounger]

There's nothing in that log that looks suspicious - what about the end of Otvlog?

[worm]

that just showed the end of the previous day and the log rotation

I have now come home to find that Tivo rebooted in the afternoon.

relevant time from kernel log:

Jun 14 13:33:18 (none) kernel: tcp_keepalive: call keepopen(0x806d3320)
Jun 14 13:34:33 (none) kernel: tcp_keepalive: call keepopen(0x806d3320)
Jun 14 13:35:07 (none) kernel: cachecard: stats = hit:475, miss:0, write:817
Jun 14 13:35:48 (none) kernel: tcp_keepalive: call keepopen(0x806d3320)
Jan 1 00:03:16 (none) kernel: Kernel virtual start=0x81000000, end=0x81d6c000
Jan 1 00:03:16 (none) kernel: Swansea University Computer Society NET3.038 for Linux 2.1
Jan 1 00:03:16 (none) kernel: NET3: Unix domain sockets 0.15 for Linux NET3.038.

etc...

from that time in tvlog:

Jun 14 13:11:48 (none) TmkMediaswitch::Trace[147]: Lost VBI lock
Jun 14 13:12:19 (none) last message repeated 279 times
Jun 14 13:12:49 (none) last message repeated 278 times
Jun 14 13:12:49 (none) ContextMgr[152]: ##### Context::OnHeartbeat(): context 6 said NOT to time out to Live TV. (idle time 15:00) #####
Jun 14 13:12:50 (none) TmkMediaswitch::Trace[147]: Lost VBI lock
Jun 14 13:13:28 (none) last message repeated 166 times
Jun 14 13:14:12 (none) last message repeated 394 times
Jun 14 13:14:30 (none) Recorder[148]: Adding check schedule task
Jun 14 13:15:10 (none) TmkMediaswitch::Trace[147]: Drift = -3
Jun 14 13:16:45 (none) Recorder[148]: Adding check schedule task
Jun 14 13:17:08 (none) mempool[142]: MyWorld block: 656kB/965kB chunk: 133kB/179kB unused: 2498kB search: 1 (size=3731424)
Jun 14 13:17:08 (none) mempool[142]: Osd block: 90kB/102kB chunk: 950kB/950kB unused: 1925kB search: 0 (size=3051488)
Jun 14 13:17:12 (none) TmkMediaswitch::Trace[147]: Lost VBI lock
Jun 14 13:17:17 (none) last message repeated 42 times
Jun 14 13:17:17 (none) Recorder[148]: Adding check schedule task
Jun 14 13:17:17 (none) TmkMediaswitch::Trace[147]: Lost VBI lock
Jun 14 13:17:48 (none) last message repeated 280 times
Jun 14 13:18:49 (none) last message repeated 554 times
Jun 14 13:19:50 (none) last message repeated 553 times
Jun 14 13:20:03 (none) last message repeated 126 times
Jun 14 13:20:04 (none) Recorder[148]: Adding check schedule task
Jun 14 13:20:04 (none) TmkMediaswitch::Trace[147]: Lost VBI lock
Jun 14 13:20:35 (none) last message repeated 280 times
Jun 14 13:20:44 (none) last message repeated 86 times
Jun 14 13:20:44 (none) Recorder[148]: IncrementalAlloc rec 912344
Jun 14 13:20:44 (none) Recorder[148]: Allocating new recording file. Size 524288
Jun 14 13:20:44 (none) Recorder[148]: Live cache size 1880064
Jun 14 13:20:44 (none) Recorder[148]: Recording Id 912344 size 1048576
Jun 14 13:20:44 (none) Recorder[148]: User recording 146861440 free 1033600
Jun 14 13:20:44 (none) Recorder[148]: TivoClip total 10000000 free 9712256
Jun 14 13:20:44 (none) Recorder[148]: Allocated stream Id 922004, size 524288
Jun 14 13:20:44 (none) mediamgr[148]: AddRecordFile input#0
Jun 14 13:20:44 (none) TmkMediaswitch::Trace[147]: Lost VBI lock
Jun 14 13:20:44 (none) Recorder[148]: Adding check schedule task
Jun 14 13:20:44 (none) TmkMediaswitch::Trace[147]: Lost VBI lock
Jun 14 13:21:15 (none) last message repeated 274 times
Jun 14 13:21:44 (none) last message repeated 269 times
Jun 14 13:21:44 (none) TmkTransform::Trace[147]: ClipCache 0x300198e4 Secondary Reset
Jun 14 13:21:44 (none) ClipCache[143]: 0x300198e4 in Entry(), thread 143
Jun 14 13:21:44 (none) TmkMediaswitch::Trace[147]: Lost VBI lock
Jun 14 13:22:15 (none) last message repeated 275 times
Jun 14 13:22:43 (none) last message repeated 256 times
Jun 14 13:22:43 (none) Recorder[148]: Adding check schedule task
Jun 14 13:22:43 (none) TmkMediaswitch::Trace[147]: Lost VBI lock
Jun 14 13:23:14 (none) last message repeated 278 times
Jun 14 13:24:15 (none) last message repeated 554 times
Jun 14 13:24:56 (none) last message repeated 374 times
Jun 14 13:25:29 (none) Recorder[148]: Adding check schedule task
Jun 14 13:27:19 (none) Deadline[148]: Tasks run 2600
Jun 14 13:27:19 (none) Deadline[148]: Existed for 0:47919:905168
Jun 14 13:27:19 (none) Deadline[148]: Overhead time 0:0:521186
Jun 14 13:28:14 (none) Recorder[148]: Adding check schedule task
Jun 14 13:31:00 (none) Recorder[148]: Adding check schedule task
Jun 14 13:32:37 (none) Recorder[148]: IncrementalAlloc rec 912344
Jun 14 13:32:37 (none) Recorder[148]: Allocating new recording file. Size 524288
Jun 14 13:32:37 (none) Recorder[148]: Live cache size 1880064
Jun 14 13:32:37 (none) Recorder[148]: Recording Id 912344 size 1572864
Jun 14 13:32:37 (none) Recorder[148]: User recording 146861440 free 509312
Jun 14 13:32:37 (none) Recorder[148]: TivoClip total 10000000 free 9712256
Jun 14 13:32:37 (none) Recorder[148]: DeleteSomething fUserSaidOk=1
Jun 14 13:32:37 (none) Recorder[148]: allocate: 22:00000000:00000000 rec 912344
Jun 14 13:32:37 (none) Recorder[148]: live cache: 3:00000000:00000000
Jun 14 13:32:38 (none) Recorder[148]: candidate: 1:00000000:00000000 914499
Jun 14 13:32:38 (none) Recorder[148]: deleting rec 914499
Jun 14 13:32:38 (none) Recorder[148]: Abr--Now: rec 914499
Jun 14 13:32:38 (none) Recorder[148]: Live cache size 1880064
Jun 14 13:32:38 (none) Recorder[148]: Recording Id 912344 size 1572864
Jun 14 13:32:38 (none) Recorder[148]: User recording 146861440 free 1394048
Jun 14 13:32:38 (none) Recorder[148]: TivoClip total 10000000 free 9712256
Jun 14 13:32:38 (none) Recorder[148]: Allocated stream Id 922005, size 524288
Jun 14 13:32:38 (none) mediamgr[148]: AddRecordFile input#0
Jun 14 13:32:38 (none) Recorder[148]: Adding check schedule task
Jun 14 13:33:37 (none) TmkTransform::Trace[147]: ClipCache 0x3001ab38 Secondary Reset
Jun 14 13:33:37 (none) ClipCache[144]: 0x3001ab38 in Entry(), thread 144
Jun 14 13:33:41 (none) Recorder[148]: Adding check schedule task
Jun 14 13:33:50 (none) TmkMediaswitch::Trace[147]: Lost VBI lock
Jun 14 13:34:21 (none) last message repeated 280 times
Jun 14 13:35:22 (none) last message repeated 549 times
Jun 14 13:35:28 (none) last message repeated 54 times
Jun 14 13:35:28 (none) mempool[142]: MyWorld block: 655kB/965kB chunk: 133kB/224kB unused: 2452kB search: 1 (size=3731424)
Jun 14 13:35:28 (none) mempool[142]: Osd block: 90kB/102kB chunk: 950kB/950kB unused: 1925kB search: 0 (size=3051488)
Jun 14 13:35:28 (none) TmkMediaswitch::Trace[147]: Lost VBI lock
Jun 14 13:35:59 (none) last message repeated 273 times
Jun 14 13:36:27 (none) last message repeated 252 times
Jun 14 13:36:27 (none) Recorder[148]: Adding check schedule task
Jun 14 13:36:27 (none) TmkMediaswitch::Trace[147]: Lost VBI lock
Jun 14 13:41:15 (none) MfsDaemon[78]: MFS Daemon started, id is 78
Jun 14 13:41:15 (none) MfsDaemon[78]: Initializing MFS

etc...

slightly worried as to why it's started doing this.

I have put a new hard disk in recently, imaged from a failing disk - could it be connected ?

[Ian_m]

If there no trace of disk DMA error then try a new PSU. An old and/or failing PSU causes reboots with no log entries.

Also if you have smartctl installed look at the reallocated sector count and see if that is increasing at each error. I had a randomly rebooting TiVo that after each reboot the reallocated sector count had increased by one. I wrote a script that outputted the reallocated sector count to a log file once a day and the reallocated sector count got to 9 in the period of a week or two during which random reboots occurred and since staying at 9 I have had no random reboots. My current uptime is 181 days (last power cycle just before Xmas).

This stuck at 9 is not good of course a recorded program could be occupying the defective disk area and if accessed could again cause disk errors and random reboots. Though in my favour I ran the Seagate advanced surface scan on the disk for a day or two and the reallocated sector count did not increase, though as soon as it changes again might be time to get a new disk just in case.