Runaway recording

[KaroriPete]

Hi,

I have a Philips Tivo runing Tivo V2.5 and TivoWebPlus 1.3. It's configured for NZ Telstra Digital.

Last night I added two Season Passes - one for House (20:30 - 21:30 on TV3) and another for Boston Legal (21:30 -22:30 also on TV3). The record light came on at 20:25 as it should, but was still on after 23:00 - long after it should have finished. At this point the Tivo would not respond to the remote control, or TivoWebPlus. I did manage to Telnet in and reboot after which everything behaved as normal except neither show was listed in the Now Playing list. Perhaps rebooting was a mistake.

My questions are:
1) is it possible that all or part of these programs did record and are sitting in a file on the disk somewhere, but didn't get added to the list due to me rebooting? If so is there anyway to recover them?

2) any clues why this would have happened in the first place? I've grabbed the log files from yesterday and there do seem to be curious things about the time everything went pear shaped. I've pasted some snippets below which hopefully might mean more to someone than they do to me.

Any help or suggestions greatly appreciated.

Cheers,
Pete.



Here's the Endpad log just before I restarted:

Tuesday 23:25:16 : Rise and shine!
Tuesday 23:25:16 : Processing current recording(s):
Tuesday 23:25:16 : * House on [3 TV3] until 21:30 (Season Pass)
Tuesday 23:25:16 : Scheduled recording lasts throughout requested padding
Tuesday 23:25:16 : Tuner 1 has 0 seconds available
Tuesday 23:25:16 : Tuner in use; no padding available
Tuesday 23:25:16 : Can't add end padding due to conflict
Tuesday 23:25:16 : Processing next recording(s):
Tuesday 23:25:16 : * Boston Legal on [3 TV3] from 21:30 to 22:30 (Season Pass)
Tuesday 23:25:16 : Active recording lasts throughout requested padding
Tuesday 23:25:16 : Tuner 1 has 0 seconds available
Tuesday 23:25:16 : Tuner in use; no padding available
Tuesday 23:25:16 : Can't add start padding due to conflict
Tuesday 23:25:16 : Next end padding setting due 22:23
Tuesday 23:25:16 : Next wake up will be 23:25
Tuesday 23:25:16 : Back to sleep...
Tuesday 23:25:16 : Checking every minute for kill signal..
Tuesday 23:25:47 :


Here's all the entries from the TV log between starting to record and when I restarted:

May 22 20:24:06 (none) Recorder[199]: Adding check schedule task
May 22 20:24:06 (none) Recorder[199]: CheckSchedule: creating action for: rec 2861521
May 22 20:24:06 (none) Recorder[199]: Creating normal action
May 22 20:24:06 (none) Recorder[199]: CheckSchedule: next creation at 13655:77346 : rec 2861524
May 22 20:24:06 (none) Recorder[199]: InitialAction rec 2861521
May 22 20:24:06 (none) Recorder[199]: Item 2861521: estimate kb per second: 227
May 22 20:24:07 (none) Recorder[199]: RequestTuner rec 2861521
May 22 20:24:07 (none) TvVideoPolicy[199]: RecordingTunerRequest on 481
May 22 20:24:07 (none) TvVideoPolicy[199]: RecordingTunerRequest conflict on 481
May 22 20:24:49 (none) Recorder[199]: Allocate rec 2861521
May 22 20:24:49 (none) Recorder[199]: Allocating new recording file. Size 524288
May 22 20:24:49 (none) Recorder[199]: Live cache size 1671168
May 22 20:24:49 (none) Recorder[199]: Recording Id 2861521 size 0
May 22 20:24:49 (none) Recorder[199]: User recording 231336320 free 5298560
May 22 20:24:49 (none) Recorder[199]: TivoClip total 10000000 free 9948800
May 22 20:24:49 (none) Recorder[199]: Allocated stream Id 2861534, size 524288
May 22 20:24:49 (none) Recorder[199]: Allocate success! Adding START task
May 22 20:24:49 (none) Recorder[199]: Adding check schedule task
May 22 20:24:50 (none) Recorder[199]: Got EVT_VIDEO_SESSION 3
May 22 20:24:50 (none) Recorder[199]: AquiredTunerLock event received
May 22 20:24:50 (none) VideoGuts[198]: RecordingTunerResult ALLOWED 481
May 22 20:24:58 (none) Recorder[199]: Start rec 2861521
May 22 20:24:58 (none) VideoGuts[199]: StartRecording 481
May 22 20:24:58 (none) InputState[199]: StartRecording 0
May 22 20:24:58 (none) TmkMediaswitch::Trace[197]: using CBR, bitRate=1630000, maxBitrate=1630000
May 22 20:24:58 (none) OutputState[199]: PlayLive 0
May 22 20:24:58 (none) TmkTransform::Trace[197]: ClipCache 0x30014ed4 Secondary Reset
May 22 20:24:58 (none) Recorder[199]: found showing 2837795/200 (program 2851105)
May 22 20:24:58 (none) ClipCache[193]: 0x30014ed4 in Entry(), thread 193
May 22 21:07:23 (none) TmkTransform::Trace[197]: ClipCache 0x3000cf00 Secondary Reset
May 22 21:07:23 (none) ClipCache[194]: 0x3000cf00 in Entry(), thread 194
May 22 21:24:36 (none) TmkTransform::Trace[197]: ClipCache 0x30004d24 Secondary Reset
May 22 21:24:36 (none) ClipCache[193]: 0x30004d24 in Entry(), thread 193
May 22 21:41:49 (none) TmkTransform::Trace[197]: ClipCache 0x30012078 Secondary Reset
May 22 21:41:49 (none) ClipCache[194]: 0x30012078 in Entry(), thread 194
May 22 21:59:02 (none) TmkTransform::Trace[197]: ClipCache 0x30013ee8 Secondary Reset
May 22 21:59:02 (none) ClipCache[193]: 0x30013ee8 in Entry(), thread 193
May 22 22:16:15 (none) TmkTransform::Trace[197]: ClipCache 0x30011108 Secondary Reset
May 22 22:16:15 (none) ClipCache[194]: 0x30011108 in Entry(), thread 194
May 22 22:33:28 (none) TmkTransform::Trace[197]: ClipCache 0x300046b0 Secondary Reset
May 22 22:33:28 (none) ClipCache[193]: 0x300046b0 in Entry(), thread 193
May 22 22:50:41 (none) TmkTransform::Trace[197]: ClipCache 0x3000fe8c Secondary Reset
May 22 22:50:41 (none) ClipCache[194]: 0x3000fe8c in Entry(), thread 194
May 22 23:07:54 (none) TmkTransform::Trace[197]: ClipCache 0x30013860 Secondary Reset
May 22 23:07:54 (none) ClipCache[193]: 0x30013860 in Entry(), thread 193
May 22 23:24:59 (none) EvtSwitcher[84]: EventSwitcher is starting up
May 22 23:24:59 (none) EvtService[84]: Service Test has NULL executable name!
May 22 23:25:00 (none) MfsDaemon[85]: MFS Daemon started, id is 85
May 22 23:25:00 (none) MfsDaemon[85]: Initializing MFS
May 22 23:25:00 (none) NmCache[85]: Cache at 0x0x7fee4f0c, array of 100 entries at 0x0x7fee4f90
May 22 23:25:01 (none) MfsDaemon[85]: The MfsDaemon is starting up
May 22 23:25:01 (none) EvtSwitcher[84]: Tmk client 1 (pid=82) has attached
May 22 23:25:01 (none) EvtSwitcher[84]: Invalid service attempted to attach?
May 22 23:25:01 (none) EvtSwitcher[84]: Group 82 was not an MFS group
May 22 23:25:01 (none) EvtSwitcher[84]: Client 1 (pid=82) being removed
May 22 23:25:01 (none) EvtSwitcher[84]: Tmk client 2 (pid=85) has attached
May 22 23:25:01 (none) EvtSwitcher[84]: Invalid service attempted to attach?
May 22 23:25:01 (none) EvtSwitcher[84]: Client 2 (pid=85), thread 85 has activated MFS
May 22 23:25:05 (none) EvtSwitcher[84]: Tmk client 3 (pid=116) has attached
May 22 23:25:05 (none) EvtSwitcher[84]: Invalid service attempted to attach?
May 22 23:25:05 (none) EvtSwitcher[84]: Client 3 (pid=116), thread 116 has activated MFS
May 22 23:25:05 (none) DbUpgrader[116]: majorVersionNum:5
May 22 23:25:05 (none) DbUpgrader[116]: minorVersionNum:72
May 22 23:25:05 (none) DbUpgrader[116]: converted majorVersionNum:5
May 22 23:25:05 (none) DbUpgrader[116]: converted minorVersionNum:72
May 22 23:25:05 (none) DbUpgrader[116]: Existing version: 5.72

[thomson]

I did manage to Telnet in and reboot after which everything behaved as normal except neither show was listed in the Now Playing list. Perhaps rebooting was a mistake.

I would say that the MFS (database) was upset. Database entries are created as soon as a recording starts so it should definitely still be there after a reboot even if restarted in the middle of a recording.

If you are sure you have enough swap setup then you could trigger an MFS Check which "may" resolved any outstanding issues. This can be done using either of the following methods (WARNING: This could definitely upset your TiVo and you may get stuck in a GSOD - Green Screen Of Death)

This will take a few minutes and then reboot:


# rw
# mfscheck -fix -progress -stream -sizes


This will take a few minutes and shutdown the event switcher (which can be restarted with "/tvbin/switcherstart -m"), although it could trigger a reboot:


# rw
# mfscheck -fix -progress -stream -sizes


or

This will trigger a GSOD which could take a while (20+ minutes) to complete:


# mfsassert -please

[KaroriPete]

Hi - I gave both methods a crack but without any joy. I do notice looking at the MFS browser that there are a few orphan files, but I'm not sure if these are relevant.

Directory listing of /Database
Name Type Id Date Time Size
Orphan2870485 tyDb 2870485 27/05/07 23:50 84
Orphan2870486 tyDb 2870486 27/05/07 23:50 72
Orphan2877962 tyDb 2877962 31/05/07 21:03 84
Orphan2877963 tyDb 2877963 31/05/07 21:03 72

Anyway thanks for the help. The lost programs are not really the end of the world, but was just curious if there was a way to recover.

Cheers,
Pete.

[Wibble]

You might also want to check your syslog for disk errors.

I was getting similar behaviour on and off for a few weeks, until I checked the disk which turned out to be toast according to the manufacturer's utility. (I've sent it back under warranty, but lost the content) :(