Alpha Tester - Getting hideous reboots

[groovyclam]

Alpha tester using cachecard to connect to server.

Didn't do new installation - just did a new guided setup and changed the IP to the AltEPG server the TiVo goes to to suck the listings.

I did get a couple of reboots over the first few days of using the TiVo ( which was pretty well behaved normally prior to AltEPG )

Today I am getting LOTS of random reboots whilst both watching or recording programmes.

I have been setting manual recordings for tennis on EuroSport which doesn't have listings at the moment which is the only weirdness I can think I have been doing.

Any thoughts ? Is this a sign of a bad disk ?

[mutant_matt]

Unhelpful I know, but, no Eurosport listings, say it ain't so!!!! (Eurosport is the one reason I begrudgingly pay Sky for a subscription! )

[poppadum]

Unhelpful I know, but, no Eurosport listings, say it ain't so!!!! (Eurosport is the one reason I begrudgingly pay Sky for a subscription! )

We're not including listings for all channels yet, but 'British Eurosport' and 'British Eurosport 2' are available from our source so it should be possible to include them later.

Today I am getting LOTS of random reboots whilst both watching or recording programmes.

Slightly worrying - is there anything helpful in the logs on your Tivo?

[groovyclam]

this was from the kernel log from a time when it booted and almost immediately failed and rebooted:

May 25 08:30:05 (none) kernel: Time set to: Wed May 25 08:30:05 2011
May 25 08:30:05 (none) kernel: Have a nice day.
May 25 08:30:05 (none) kernel: Checking for additional disk...
May 25 08:30:05 (none) kernel: Starting EventSwitcher...
May 25 08:30:07 (none) kernel: Start fan control...
May 25 08:30:08 (none) kernel: Scanning for phase2 repair scripts
May 25 08:30:10 (none) kernel: Checking for database conversions...
May 25 08:30:11 (none) kernel: Checking new software installation
May 25 08:30:12 (none) kernel: SwSystem 2.5.5-01-1-023 is already active, nothing to do.
May 25 08:30:12 (none) kernel: Scanning for phase3 repair scripts
May 25 08:30:12 (none) kernel: Starting Services.
May 25 08:30:12 (none) kernel: Scanning for phase4 repair scripts
May 25 08:30:12 (none) kernel: MCP startup complete
May 25 08:30:13 (none) kernel: rc.sysinit is complete
May 25 08:30:13 (none) kernel: turbonet2: driver version 20050218
May 25 08:30:13 (none) kernel: turbonet2: using MAC address 00:0B:AD:41:8D:B9
May 25 08:30:13 (none) kernel: turbonet2: driver successfully installed
May 25 08:30:13 (none) kernel: turbonet2: driver successfully installed
May 25 08:30:14 (none) kernel: IP struct was not filled in!
May 25 08:30:14 (none) kernel: sa is: 0x20000 0xc0a801fa 0x7ffffcd4 0x7ffffcf0
May 25 08:30:14 (none) kernel: sa.sin_addr = 0x7ffffc38 a sockaddr is 16 bytes
May 25 08:30:17 (none) kernel: turbonet2: link = 100Mbps full-duplex
May 25 08:30:22 (none) kernel: Microcode version 00034
May 25 08:30:23 (none) kernel: Initialize with 1 live caches
May 25 08:30:23 (none) kernel: mediaswitch: resetting adjustments
May 25 08:30:23 (none) kernel: tivoblaster.C::ReadTivoFormatKey(), Line : 356, Found 350 ms. Prefix.
May 25 08:30:23 (none) kernel: osd buffer size = 1080000
May 25 08:30:28 (none) kernel: mediaswitch: returning -1 from standin tune after tuning to ch -3 with adjust 0
May 25 08:30:28 (none) kernel: tuning:lock 1
May 25 08:30:30 (none) kernel: EXT2-fs warning: mounting unchecked fs, running e2fsck is recommended
May 25 08:30:32 (none) kernel: EXT2-fs warning: mounting unchecked fs, running e2fsck is recommended
May 25 08:30:32 (none) kernel: Done with this packet
May 25 08:30:32 (none) kernel: EXT2-fs warning: mounting unchecked fs, running e2fsck is recommended
May 25 08:31:37 (none) kernel: tcp_keepalive: call keepopen(0x80818d20)
May 25 08:32:52 (none) kernel: tcp_keepalive: call keepopen(0x80818d20)
May 25 08:34:07 (none) kernel: tcp_keepalive: call keepopen(0x80818d20)
May 25 08:35:22 (none) kernel: tcp_keepalive: call keepopen(0x80818d20)
May 25 08:36:37 (none) kernel: tcp_keepalive: call keepopen(0x80818d20)
May 25 08:37:52 (none) kernel: tcp_keepalive: call keepopen(0x80818d20)
May 25 08:39:07 (none) kernel: tcp_keepalive: call keepopen(0x80818d20)
May 25 08:39:42 (none) kernel: Tmk Assertion Failure:
May 25 08:39:42 (none) kernel: AssertValidPointer, line 2021 ()
May 25 08:39:42 (none) kernel: Tmk Fatal Error: Thread ContextMgr event handler <149> died due to signal -2
Jan 1 00:04:14 (none) kernel: Loaded 29 symbols from 9 modules.
Jan 1 00:04:14 (none) kernel: Old MediaSwitch address map
Jan 1 00:04:14 (none) kernel: Memory configured for 16MB

Looks like the troublesome thing is:

May 25 08:39:42 (none) kernel: Tmk Assertion Failure:
May 25 08:39:42 (none) kernel: AssertValidPointer, line 2021 ()
May 25 08:39:42 (none) kernel: Tmk Fatal Error: Thread ContextMgr event handler <149> died due to signal -2

tverr for then shows:

May 25 08:39:42 (none) TmkAssertionFailure[149]: (AssertValidPointer, line 2021 ())
May 25 08:39:42 (none) ContextMgr event handler[149]: Tmk Fatal Error: Thread ContextMgr event handler <149> died due to signal -2
May 25 08:39:42 (none) ContextMgr event handler[149]: Tmk Thread Backtrace: 1a344ec 1a32a44 1b96114 1b9645c 1b95fd4 1b96bfc 1b9b30c 1b96d20 1b49078 1aa4508 1b96d20 1b3c9f4 1b3d0dc 1b3de98 1b3dafc 1b3d460 1b3d240 1b46720 1b29b20 1b299bc 1b1e88c 1ac3254 1ac2320 1ac3974 1abdef8 1bc97c8 1ac2c80 1abef88 1ac249c 1ac4ddc 1ac4358 1b91bb4 1c01e6c 1c249b8 1c23c84 1c23db0 1c27364 1c28374 1c28420 1c27504 1c23eb4 1c248fc 1c01ca8 1bf73bc 1c239b0 1c2764c 1c28374 1c28420 1c27748 1c2379c 1c24388 1c2400c 1bf6b00 1c28af4 1800
May 25 08:39:42 (none) ContextMgr event handler[149]: Tmk Fatal Error: Thread died due to signal -2
May 25 08:39:42 (none) ContextMgr event handler[149]: Invoking rule 834: rebooting system

tvlog has:

May 25 08:35:15 (none) Deadline[145]: VERY_LATE:Task CheckSchedule started late by 7438ms
May 25 08:35:44 (none) TmkMediaswitch::Trace[144]: Lost VBI lock
May 25 08:36:10 (none) last message repeated 231 times
May 25 08:36:10 (none) TmkTransform::Trace[144]: ClipCache 0x3000e488 Secondary Reset
May 25 08:36:10 (none) ClipCache[141]: 0x3000e488 in Entry(), thread 141
May 25 08:36:10 (none) TmkMediaswitch::Trace[144]: Lost VBI lock
May 25 08:36:41 (none) last message repeated 276 times
May 25 08:37:42 (none) last message repeated 254 times
May 25 08:39:15 (none) last message repeated 365 times
May 25 08:39:35 (none) last message repeated 187 times
May 25 08:39:35 (none) Deadline[145]: Creating task already 5984 milliseconds late
May 25 08:39:35 (none) Deadline[145]: VERY_LATE:Task AllocateLiveCache started late by 5985ms
May 25 08:39:35 (none) Recorder[145]: AllocateFiles for live cache
May 25 08:39:35 (none) Recorder[145]: Live cache size 417792
May 25 08:39:35 (none) Recorder[145]: User recording 232544640 free 4068736
May 25 08:39:35 (none) Recorder[145]: TivoClip total 10000000 free 9712256
May 25 08:39:35 (none) Recorder[145]: Allocated stream Id 3972082, size 208896
May 25 08:39:35 (none) mediamgr[145]: AddLiveFile input#0
May 25 08:39:35 (none) Recorder[145]: Adding check schedule task
May 25 08:39:35 (none) TmkMediaswitch::Trace[144]: Lost VBI lock

[Tcm2007]

Starting to worry that effectively having two complete databases is just overloading the poor thing, esp with Sky which is huge already. The old data won't be expunged from the system until 28 days after the last old recording is deleted at the earliest.

[groovyclam]

Another death at an earlier time had this in the kernel log:

May 24 23:45:30 (none) kernel: tcp_keepalive: call keepopen(0x80af8160)
May 24 23:45:41 (none) kernel: CodeFromNec(853044b0) is meaningless
May 24 23:46:45 (none) kernel: tcp_keepalive: call keepopen(0x80af8160)
May 24 23:48:00 (none) kernel: tcp_keepalive: call keepopen(0x80af8160)
May 24 23:49:13 (none) kernel: Tmk Assertion Failure:
May 24 23:49:13 (none) kernel: AssertValidPointer, line 2021 ()
May 24 23:49:13 (none) kernel: Tmk Fatal Error: Thread Scheduler <147> died due to signal -2
May 24 23:49:15 (none) kernel: 1a344ec 1a32a44 1b96114 1b9645c 1b95fd4 19a04ec 19a0378 1b347dc 1b33934 1b1d990 1b1d70c 1af55a4 1af898c 1c3ac30 1bdd718 1bde5c4 1bf42a8 1b5b5f8 1bdd1b0 1b91bb4 1c0644c 1c063bc 1c23c84 1c23df4 1c27364 1c28374 1c28420 1c27504 1c06298 1c06148 1bf71a4 1c239b0 1c2764c 1c28374 1c28420 1c27748 1c2379c 1c24388 1c2400c 1bf6b00 1c28af4 1800134 <3>tcp_keepalive: call keepopen(0x80af8160)

tverr has:

May 24 23:49:13 (none) TmkAssertionFailure[147]: (AssertValidPointer, line 2021 ())
May 24 23:49:13 (none) Scheduler[147]: Tmk Fatal Error: Thread Scheduler <147> died due to signal -2
May 24 23:49:13 (none) Scheduler[147]: Tmk Thread Backtrace: 1a344ec 1a32a44 1b96114 1b9645c 1b95fd4 19a04ec 19a0378 1b347dc 1b33934 1b1d990 1b1d70c 1af55a4 1af898c 1c3ac30 1bdd718 1bde5c4 1bf42a8 1b5b5f8 1bdd1b0 1b91bb4 1c0644c 1c063bc 1c23c84 1c23df4 1c27364 1c28374 1c28420 1c27504 1c06298 1c06148 1bf71a4 1c239b0 1c2764c 1c28374 1c28420 1c27748 1c2379c 1c24388 1c2400c 1bf6b00 1c28af4 1800134 ipe
May 24 23:49:13 (none) Scheduler[147]: Tmk Fatal Error: Thread died due to signal -2
May 24 23:49:13 (none) Scheduler[147]: Invoking rule 834: rebooting system

tvlog has:

May 24 23:47:45 (none) Recorder[145]: AllocateFiles for live cache
May 24 23:47:45 (none) Recorder[145]: Live cache size 208896
May 24 23:47:45 (none) Recorder[145]: User recording 232753536 free 4277632
May 24 23:47:45 (none) Recorder[145]: TivoClip total 10000000 free 9712256
May 24 23:47:45 (none) Recorder[145]: Allocated stream Id 3971871, size 208896
May 24 23:47:45 (none) mediamgr[145]: AddLiveFile input#0
May 24 23:47:45 (none) Recorder[145]: Adding check schedule task
May 24 23:48:06 (none) Scheduler[147]: Mempool highwater 164
May 24 23:48:06 (none) Scheduler[147]: DataChanged:PROGRAM_GUIDE
May 24 23:48:07 (none) Scheduler[147]: Abr-- DataChanged:0x00090009
May 24 23:48:38 (none) Scheduler[147]: Mempool highwater 164
May 24 23:48:38 (none) Scheduler[147]: DataChanged:PROGRAM_GUIDE
May 24 23:48:39 (none) Scheduler[147]: Abr-- DataChanged:0x00090009
May 24 23:48:58 (none) TmkTransform::Trace[144]: ClipCache 0x30012058 Secondary Reset
May 24 23:48:58 (none) ClipCache[140]: 0x30012058 in Entry(), thread 140
May 24 23:49:10 (none) Scheduler[147]: Mempool highwater 164
May 24 23:49:10 (none) Scheduler[147]: DataChanged:PROGRAM_GUIDE
May 24 23:49:11 (none) Scheduler[147]: Abr-- reason changed from 'UI' to 'None'
May 24 23:49:11 (none) Scheduler[147]: DISK SPACE: Total: 227502 Live cache: 1930 Overhead: 378
May 24 23:49:11 (none) Scheduler[147]: TIVO CLIPS DISK SPACE: Total: 9765 Overhead: 64
May 24 23:49:12 (none) Scheduler[147]: Done Checking high priority Capture Requests

[groovyclam]

The old data won't be expunged from the system until 28 days after the last old recording is deleted at the earliest.

I don't understand - has my TiVo got all the old tribune data still as well ?

Should I do a complete cleardown and setup ?

[Tcm2007]

this was from the kernel log from a time when it booted and almost immediately failed and rebooted:

Any clues in the other logs with the same timestamp, tverr maybe?

[groovyclam]

Another death point:

May 25 01:35:09 (none) kernel: osd buffer size = 1080000
May 25 01:35:14 (none) kernel: mediaswitch: returning -1 from standin tune after tuning to ch -3 with adjust 0
May 25 01:35:14 (none) kernel: tuning:lock 1
May 25 01:35:16 (none) kernel: EXT2-fs warning: mounting unchecked fs, running e2fsck is recommended
May 25 01:35:18 (none) kernel: Done with this packet
May 25 01:35:19 (none) kernel: EXT2-fs warning: mounting unchecked fs, running e2fsck is recommended
May 25 01:35:19 (none) kernel: EXT2-fs warning: mounting unchecked fs, running e2fsck is recommended
May 25 01:35:38 (none) kernel: Tmk Fatal Error: Thread Scheduler <147> died due to signal 11
May 25 01:35:38 (none) kernel: NIP 0x1b1dc94 link 0x1b1dc8c ctr 28873300
May 25 01:35:38 (none) kernel: R00 0x01b1dc8c R01 0x7fffeee0 R02 0x00000100 R03 0x7fb4bc98
May 25 01:35:38 (none) kernel: R04 0x7fb40b78 R05 0x00000002 R06 0x00000001 R07 0x7fffef20
May 25 01:35:38 (none) kernel: R08 0xdeadbeef R09 0xadbeefde R10 0x80483ea0 R11 0x7fffef50
May 25 01:35:38 (none) kernel: R12 0x84200022 R13 0x01da9208 R14 0x00000000 R15 0x00000000
May 25 01:35:38 (none) kernel: R16 0x018bdd8c R17 0x00000000 R18 0xffffffff R19 0xffffffff
May 25 01:35:38 (none) kernel: R20 0xffffffff R21 0x00000000 R22 0x7fb86bfc R23 0x00000000
May 25 01:35:38 (none) kernel: R24 0x7ffff098 R25 0x7fffef98 R26 0x7fffefb8 R27 0x7fffef88
May 25 01:35:38 (none) kernel: R28 0x7fb86bd0 R29 0x00000000 R30 0x00000000 R31 0x7fb86bd0

tverr:

May 25 01:35:38 (none) Scheduler[147]: Tmk Fatal Error: Thread Scheduler <147> died due to signal 11
May 25 01:35:38 (none) Scheduler[147]: NIP 0x1b1dc94 link 0x1b1dc8c ctr 28873300
May 25 01:35:38 (none) Scheduler[147]: R00 0x01b1dc8c R01 0x7fffeee0 R02 0x00000100 R03 0x7fb4bc98
May 25 01:35:38 (none) Scheduler[147]: R04 0x7fb40b78 R05 0x00000002 R06 0x00000001 R07 0x7fffef20
May 25 01:35:38 (none) Scheduler[147]: R08 0xdeadbeef R09 0xadbeefde R10 0x80483ea0 R11 0x7fffef50
May 25 01:35:38 (none) Scheduler[147]: R12 0x84200022 R13 0x01da9208 R14 0x00000000 R15 0x00000000
May 25 01:35:38 (none) Scheduler[147]: R16 0x018bdd8c R17 0x00000000 R18 0xffffffff R19 0xffffffff
May 25 01:35:38 (none) Scheduler[147]: R20 0xffffffff R21 0x00000000 R22 0x7fb86bfc R23 0x00000000
May 25 01:35:38 (none) Scheduler[147]: R24 0x7ffff098 R25 0x7fffef98 R26 0x7fffefb8 R27 0x7fffef88
May 25 01:35:38 (none) Scheduler[147]: R28 0x7fb86bd0 R29 0x00000000 R30 0x00000000 R31 0x7fb86bd0
May 25 01:35:38 (none) Scheduler[147]: Tmk Thread Backtrace: 1a344fc 7fffedf8 1b1dc8c 1b1dc04 1b1d70c 1af55a4 1af99fc 1c3acb8 1bdd718 1bde5c4 1bf42a8 1b5b5f8 1bdd1b0 1b91bb4 1c0644c 1c063bc 1c23c84 1c23df4 1c27364 1c28374 1c28420 1c27504 1c06298 1c06148 1bf71a4 1c239b0 1c2764c 1c28374 1c28420 1c27748 1c2379c 1c24388 1c2400c 1bf6b00 1c28af4 1800134 ipe
May 25 01:35:38 (none) Scheduler[147]: Tmk Fatal Error: Thread died due to signal 11
May 25 01:35:38 (none) Scheduler[147]: Invoking rule 834: rebooting system

tvlog:

May 25 01:35:25 (none) TvDbUtil[147]: LogRecordings3: 3966657, 294912, 351, 6721, 0x5, 0x5, 0x1
May 25 01:35:25 (none) TvDbUtil[147]: LogRecordings3: 3966667, 561152, 687, 6534, 0x5, 0x5, 0x1
May 25 01:35:25 (none) TvDbUtil[147]: LogRecordings3: 3966678, 40960, 348, 941, 0x5, 0x5, 0x1
May 25 01:35:25 (none) TvDbUtil[147]: LogRecordings3: 3966687, 32768, 360, 728, 0x5, 0x5, 0x1
May 25 01:35:25 (none) TvDbUtil[147]: LogRecordings3: 3966696, 6615040, 8324, 6357, 0x5, 0x5, 0x1
May 25 01:35:25 (none) TvDbUtil[147]: LogRecordings3: 3966730, 28672, 676, 339, 0x5, 0x5, 0x1
May 25 01:35:25 (none) TvDbUtil[147]: LogRecordings3: 3966739, 4096000, 5598, 5853, 0x5, 0x5, 0x1
May 25 01:35:25 (none) TvDbUtil[147]: LogRecordings3: 3966779, 264192, 489, 4322, 0x5, 0x5, 0x1
May 25 01:35:25 (none) TvDbUtil[147]: LogRecordings3: 3966550, 2859008, 6422, 3561, 0x5, 0x5, 0x1
May 25 01:35:25 (none) TvDbUtil[147]: LogRecordings3: 3964824, 28862464, 37322, 6186, 0x5, 0x5, 0x1
May 25 01:35:25 (none) TvDbUtil[147]: LogRecordings3: 3966579, 2867200, 4022, 5703, 0x5, 0x9, 0x1
May 25 01:35:25 (none) TvDbUtil[147]: LogRecordings3: 3965187, 2252800, 4022, 4480, 0x4, 0x5, 0x1
May 25 01:35:25 (none) TvDbUtil[147]: LogRecordings3: 3966552, 1138688, 2222, 4099, 0x5, 0x5, 0x1
May 25 01:35:25 (none) TvDbUtil[147]: LogRecordings3: 3967085, 20467712, 25317, 6467, 0x5, 0x5, 0x1
May 25 01:35:25 (none) TvDbUtil[147]: LogRecordings3: 3970739, 479232, 681, 5629, 0x5, 0x5, 0x1
May 25 01:35:25 (none) TvDbUtil[147]: LogRecordings3: 3970781, 569344, 834, 5461, 0x5, 0x5, 0x1
May 25 01:35:25 (none) TvDbUtil[147]: LogRecordings3: 3970791, 5545984, 7393, 6001, 0x4, 0x5, 0x1
May 25 01:35:25 (none) TvDbUtil[147]: LogRecordings3: 3966567, 606208, 1038, 4672, 0x5, 0x9, 0x1
May 25 01:35:25 (none) TvDbUtil[147]: LogRecordings3: End
May 25 01:35:27 (none) Scheduler[147]: Mempool highwater 152
May 25 01:35:27 (none) Scheduler[147]: DataChanged:PROGRAM_GUIDE
May 25 01:35:30 (none) Scheduler[147]: DataChanged:CAPTURE_REQUEST
May 25 01:35:34 (none) Scheduler[147]: DISK SPACE: Total: 227502 Live cache: 1930 Overhead: 378
May 25 01:35:34 (none) Scheduler[147]: TIVO CLIPS DISK SPACE: Total: 9765 Overhead: 64
May 25 01:35:36 (none) Scheduler[147]: Done Checking high priority Capture Requests

[groovyclam]

Give me a few minutes and I'll sort all the reboot instances and different logs into a coherent post.

[Tcm2007]

The old data won't be expunged from the system until 28 days after the last old recording is deleted at the earliest.

I don't understand - has my TiVo got all the old tribune data still as well ?

Should I do a complete cleardown and setup ?

If you just re-ran guided setup, yes (although you won't be able to access it directly, only through TW).

A clear and delete all might well solve things, but it would be good to try to debug first if possible.

[groovyclam]

I can live with reboots if it helps solve the problem.

After I did guided setup when I first joined the AltEPG a couple of days ago I did notice a few reboots so I chose the option to clear my thumbs and suggestions and the option to clear programme data a todo and then did another guided setup. So does that mean there could still be Tribune data even if I did a "clear prog data and to do" ?

I do still have saved recordings from the Tribune days ( and these are on channels which currently do not have AltEPG listing data ).

Do you want me to post more logs when it happens ?

[groovyclam]

I also used TiVoWeb to re-import wishlists for "Director Wishlists" from the old Tribune days.

I put in my season passes only for those shows now in AltEPG data

I have set manual recordings for EuroSport ( no AltEPG data )

[groovyclam]

Only kernel, tverr and tvlog show any useful data around the reboots.

I have put all three logs into each post that shows a reboot above.

I can post more if required.

[groovyclam]

Might this be anything to do with having literally NO data in a channel without listings ( as compared to Tribune who put generic 2-hour blocks into channels they didn't carry listings for ) ?

Since I am using the Sky lineup I have LOTS of such channels as channels I receive.