Corruption in guide data?

**chis** · 02-09-2009, 07:36 PM

For the last few days my Tivo has got part way through the Phone process and failed.

It downloads the latest data and starts processing, but sometime after 5% or so it fails with the message "Failed while preparing data". I've tried a reboot with no change.

Something up with the guide data?

**catdog** · 03-09-2009, 05:47 AM

I have not noticed any problems here. Which postcode are you using? (Sky/Freeview?).

**chis** · 03-09-2009, 07:28 AM

Just using Sky. It's been working for years without change.

**petestrash** · 03-09-2009, 10:12 AM

Check the tclient log to see why it is failing.

Peter.

**chis** · 03-09-2009, 06:51 PM

Of course as soon as I left home I realised that logs were central to any resolution!

Otclient
Sep 3 20:37:05 (none) comm[153]: Starting DB Loading
Sep 3 20:37:05 (none) comm[153]: No snowball for /var/packages/NZ02113_14492-14505.slice.gz
Sep 3 20:37:05 (none) comm[153]: No snowball for /var/packages/NZ02113_14489-14502.slice.gz
Sep 3 20:37:05 (none) comm[153]: No snowball for /var/packages/NZ02113_14490-14503.slice.gz
Sep 3 20:37:05 (none) comm[153]: No snowball for /var/packages/NZ02113_14489-14503.slice.gz
Sep 3 20:37:05 (none) comm[153]: No snowball for /var/packages/NZ02113_14491-14504.slice.gz
Sep 3 20:37:05 (none) comm[153]: Here comes Avalanche->SetDirectory! (pADirM = 0x7f85ae64)
Sep 3 20:37:05 (none) comm[153]: There went Avalanche->SetDirectory! (err = 0x0)
Sep 3 20:37:05 (none) comm[153]: Here comes Avalanche->Start!
Sep 3 20:37:05 (none) avalPP[153]: DIR <0x7f85ae64>: id=PHONE_DATA path=NOT USED recordingId=0/0 mfsStreamId=3735928559 dirType=1 verified=T alreadyProcessed=F active=T dataFormat=3
Sep 3 20:37:05 (none) avalPP[153]: DIR <0x7f85ae64>: Load Order = 2 4 3 5 1
Sep 3 20:37:05 (none) avalPP[153]: DIR <0x7f85ae64>: BEGIN SECTION TABLE
Sep 3 20:37:05 (none) avalPP[153]: FILE 0: ordinal=0 type=0 compress=0 encryp=0 sign=0 origSize=0 finalSize=0 startEventId=0/0 succEventId=0/0 failEventId=0/0 checksum= filename= serverId=0 version=0 alreadyProcessed=1 required=0 verified=1 errTolerant=0
Sep 3 20:37:05 (none) avalPP[153]: FILE 1: ordinal=1 type=1 compress=1 encryp=0 sign=0 origSize=644083 finalSize=0 startEventId=0/0 succEventId=0/0 failEventId=0/0 checksum=0x249C47F3C2B109336D48AAEF01BF8BB350FF6E0 5 filename=/var/packages/NZ02113_14492-14505.slice.gz serverId=0 version=0 alreadyProcessed=0 required=1 verified=1 errTolerant=0
Sep 3 20:37:05 (none) avalPP[153]: FILE 2: ordinal=2 type=1 compress=1 encryp=0 sign=0 origSize=540888 finalSize=0 startEventId=0/0 succEventId=0/0 failEventId=0/0 checksum=0x42607B53EA593F9E60D57060B5CA382057FABBF 0 filename=/var/packages/NZ02113_14489-14502.slice.gz serverId=0 version=0 alreadyProcessed=0 required=1 verified=1 errTolerant=0
Sep 3 20:37:05 (none) avalPP[153]: FILE 3: ordinal=3 type=1 compress=1 encryp=0 sign=0 origSize=628481 finalSize=0 startEventId=0/0 succEventId=0/0 failEventId=0/0 checksum=0xA08ACBC5FF5711407FB7CEECDCD35FDE5540F18 3 filename=/var/packages/NZ02113_14490-14503.slice.gz serverId=0 version=0 alreadyProcessed=0 required=1 verified=1 errTolerant=0
Sep 3 20:37:05 (none) avalPP[153]: FILE 4: ordinal=4 type=1 compress=1 encryp=0 sign=0 origSize=710365 finalSize=0 startEventId=0/0 succEventId=0/0 failEventId=0/0 checksum=0x8FE3F5CB1997E0A03E8C6F723105025240240BF 9 filename=/var/packages/NZ02113_14489-14503.slice.gz serverId=0 version=0 alreadyProcessed=0 required=1 verified=1 errTolerant=0
Sep 3 20:37:05 (none) avalPP[153]: FILE 5: ordinal=5 type=1 compress=1 encryp=0 sign=0 origSize=627239 finalSize=0 startEventId=0/0 succEventId=0/0 failEventId=0/0 checksum=0x16182F83D6933F6DD412B4870DCA7D03C4E77B0 3 filename=/var/packages/NZ02113_14491-14504.slice.gz serverId=0 version=0 alreadyProcessed=0 required=1 verified=1 errTolerant=0
Sep 3 20:37:05 (none) avalPP[153]: DIR <0x7f85ae64>: END SECTION TABLE
Sep 3 20:37:05 (none) avalPP[153]: ServerID=0: file can't be skipped
Sep 3 20:37:05 (none) last message repeated 4 times
Sep 3 20:37:05 (none) avalPP[153]: NotSkippable: 1 2 3 4 5
Sep 3 20:37:05 (none) avalPP[153]: Processing file 2
Sep 3 20:37:05 (none) avalPP[153]: Processing file 2 (/var/packages/NZ02113_14489-14502.slice.gz)
Sep 3 20:37:05 (none) avalPP[153]: POST PROCESSING FILE 2
Sep 3 20:37:05 (none) avalPP[153]: ::PlayFile: Playing file ID = 2<2>, index 2<2>
Sep 3 20:37:05 (none) avalPP[153]: BuildChainFromIndex(2) returned <0>
Sep 3 20:37:05 (none) db[153]: Loader Processing ProcessUnpacker(/var/packages/NZ02113_14489-14502.slice.gz)
Sep 3 20:37:07 (none) db[153]: Loader ProcessUnpacker(/var/packages/NZ02113_14489-14502.slice.gz): Error Processing = 0x3001d
Sep 3 20:37:07 (none) db[153]: Loader FinishedLoading(ProcessUnpacker(/var/packages/NZ02113_14489-14502.slice.gz)) nAction=0/0 batch=0 batchtrans=0 badbatch=0
Sep 3 20:37:07 (none) db[153]: loadgeneric nProcessed=0 (ty=0 subty=57005 svrid=(null) vers=0): nNotLoaded=0 nSnow=0 nComplete=0 nIncomplete=0 nerr=0
Sep 3 20:37:07 (none) avalPP[153]: DBLoad Failed with errcode <3001d>!!!!!
Sep 3 20:37:07 (none) avalPP[153]: post processing of file /var/packages/NZ02113_14489-14502.slice.gz (2) returns FAILURE_0003001D (3001d)
Sep 3 20:37:07 (none) avalPP[153]: Result of processing file 2 (/var/packages/NZ02113_14489-14502.slice.gz) is <3001d>
Sep 3 20:37:07 (none) avalPP[153]: File is required, and so we puke!
Sep 3 20:37:07 (none) avalPP[153]: AvalancheManager::StartDirectory returns <1e0011>
Sep 3 20:37:07 (none) avalPP[153]: StartDirectory puked, returned <0x1e0011>
Sep 3 20:37:07 (none) avalPP[153]: CLEARING OUT ANY DIRECTORIES THAT CAUSED US TROUBLE
Sep 3 20:37:07 (none) avalPP[153]: Nuking dead directory <0x7f875628>
Sep 3 20:37:07 (none) avalPP[153]: NukeFromDisk returns <0>
Sep 3 20:37:07 (none) avalPP[153]: DONE CLEARING OUT TROUBLED DIRECTORIES
Sep 3 20:37:07 (none) avalPP[153]: Returning boolean value false
Sep 3 20:37:07 (none) comm[153]: There went Avalanche->Start! (err = 0x1e0011)
Sep 3 20:37:08 (none) comm[153]: Call: ProcessQueue failed, status 0xffff
Sep 3 20:37:08 (none) comm[153]: checking for new software
Sep 3 20:37:08 (none) comm[153]: NewSoftware: getting SwSystem name
Sep 3 20:37:08 (none) comm[153]: NewSoftware: SwSystem 3.0-01-1-000 is already active.
Sep 3 20:37:08 (none) comm[153]: CallService: Postprocessing failed, status 0xffff
Sep 3 20:37:08 (none) comm[153]: Reverting private logs
Sep 3 20:37:08 (none) comm[153]: Cleanup: GetAddDiskBasedDirectories returned <70001> "0x70001"...skipping cleanup
Sep 3 20:37:08 (none) tcphonehome[153]: CallService return status 0xffff
Sep 3 20:37:08 (none) tcphonehome[153]: GetPostalCodeVersion - /PostalCode/02113 ServerVersion=198
Sep 3 20:37:08 (none) tcphonehome[153]: debug: sumServerVersion=198
Sep 3 20:37:08 (none) tcphonehome[153]: Rotating log files

tclient
Sep 3 20:37:17 (none) tcphonehome[153]: Log file rotation complete.
Sep 3 20:37:17 (none) comm[153]: CallStatusReporter: Phase: Prepare_Data, Status Failed
Sep 3 20:37:17 (none) comm[153]: CallStatusReporter: sending message "EX|18"
Sep 3 20:37:17 (none) tcphonehome[153]: TClient failed: EX|18
Sep 3 20:37:17 (none) tcphonehome[153]: Sending dialup event, subtype 8, msg EX|18
Sep 3 20:37:17 (none) tcphonehome[153]: setCallStatus called with: Failed state 0
Sep 3 20:37:24 (none) tcphonehome[153]: LastCallAttempt at 1252010161
Sep 3 20:37:24 (none) tcphonehome[153]: setting call status to: Failed
Sep 3 20:37:24 (none) tcphonehome[153]: setting call in progress to 0 (second successCount)
Sep 3 20:37:24 (none) tcphonehome[153]: Setting callActive to 0
Sep 3 20:37:24 (none) comm[153]: CallStatusReporter: sending data changed event 20
Sep 3 20:37:24 (none) tcphonehome[153]: destroying CommGlobals!
Sep 3 20:37:24 (none) tcphonehome[153]: pCommMempool empty
Sep 3 20:37:29 (none) tcphonehome[153]: Setting MCP PhoneHome action: ENABLED

tvlog had nothing that seemed interesting

svclog
tclient_hangup TCD_ID=0020000201F48AD CALL_ID=1252010161 TIME=1252010224 CODE=0
tclient_ticket TCD_ID=0020000201F48AD CALL_ID=1252010161 TIME=1252010224 STATUS=None TICKET=None VALUE=None
aval_file TCD_ID=0020000201F48AD CALL_ID=1252010161 TIME=1252010227 AVAL_ID=0000389A000121F1 FILE_NAME=/var/packages/NZ02113_14489-14502.slice.gz FILE_STATUS=FAILURE_0003001D SRC=phone
aval_pp TCD_ID=0020000201F48AD CALL_ID=1252010161 TIME=1252010227 AVAL_ID=0000389A000121F1 STATUS=FAIL_001E0011 SRC=phone
tclient_result TCD_ID=0020000201F48AD CALL_ID=1252010161 TIME=1252010237 STATUS=Failed CODE=18

**petestrash** · 04-09-2009, 09:54 AM

So it looks like there is an issue with either the NZ02113_14492-14505 slice or it was corrupted on your TiVo.

Does anyone else around here postcode 02113, are you having issues?

You can download the slice and try manually loading it. The instructions are on the OzTiVo Website.

Peter.

**Wibble** · 04-09-2009, 02:56 PM

Originally Posted by petestrash

So it looks like there is an issue with either the NZ02113_14492-14505 slice or it was corrupted on your TiVo.

Does anyone else around here postcode 02113, are you having issues?
Peter.

I'm on 02113, and everything's fine.

Though something's wacky about Cris' tivo.

Here hare the latest slices for 02113
-rw-rw-r-- 1 tivo tivo 710365 Sep 1 23:49 NZ02113_14489-14503.slice.gz
-rw-r--r-- 1 tivo tivo 628481 Sep 1 14:32 NZ02113_14490-14503.slice.gz
-rw-r--r-- 1 tivo tivo 627239 Sep 2 15:09 NZ02113_14491-14504.slice.gz
-rw-r--r-- 1 tivo tivo 644083 Sep 3 14:47 NZ02113_14492-14505.slice.gz
-rw-r--r-- 1 tivo tivo 631258 Sep 4 14:50 NZ02113_14493-14506.slice.gz

Note that there is no NZ02113_14489-14502.slice.gz, and the time on NZ02113_14489-14503.slice.gz is unsual, it's not the normal build time.

I'm guessing there was an issue with the slice on the 1st but it's recovred.

**chis** · 06-09-2009, 05:03 PM

Issue Resolved!

It was some sort of corruption on my Tivo.

The issue:
All my Phone calls failed with message "Failed while preparing data". In the Otclient the processing started going wrong with error 3001d.

To fix:
1. I backed up all my season passes using TivoWebPlus.
2. Did a "Clear Program Data & To Do List" from the Tivo interface.
3. Once it came back up I did a Phone call to update the guide data. It all loaded correctly.
4. Restored my season passes.
5. After some time (hours) my ToDo list was still empty so I did a force_index30.tcl. Not sure this was required, but soon after my ToDo list started filling up.

Thanks for all the help and suggestions.

Perhaps the "Clear Program Data & To Do List" should be tried as a possible first resolution for guide data problems?

**petestrash** · 06-09-2009, 11:47 PM

Originally Posted by chis

Perhaps the "Clear Program Data & To Do List" should be tried as a possible first resolution for guide data problems?

I'm glad it worked for you , but I would not recommend others run the clear data command from the menu as a first step as you have suggested.

People have ended up with their TiVo's stuck in a reboot loop and unable to easily recover stored programs. It does depends on what damage the corruption may have done (if any).

Peter.