Setup Questions - after a fishy install

[fear7]

Hi Guys,

Tivo newbie here - so be gentle :) I've read a lot of the OzTivo and of course anything related to NZ setups to but still have a few questions, either these questions haven't been answered elsewhere or in some cases I just need a little bit of clarification.

Just to let you know what I've done since.. so I've just installed the lastest 1.4r of the oztivo iso (dated 19/4/05) on a SA 1 tivo with a turbo net card and a 40gig HD. I fixed the ip at the imaging drive stage and then altered the rc.sysinit.author file line that calls 'emuProxy' to point to the NZ emulator rather than the Oz one. But I didn't change the tclient file as it looked like it would be unnecessary.

Currently the box is at the find G/Setup stage when if does that major indexing that people say can take up to 24hrs.

I've been looking in the tvlog and have seen some fishy entries - I'd love to hear some thoughts.

Q1) Is the fact I didn't change the tclient file a mistake? I noticed that their is an entry to "dennis's emulator" but it seemed like the 127:: entry was going to use the emuProxy server setting from rc.sysinit.author.

Q2) How long have people found the final index takes? Is it on the order of 24hrs or closer to the 4hrs mentioned?

Q3) I've read in threads that you can tell when this indexing is finished by the entry "DbGcStats[158]: Outcome: eSucceeded" mean it's done? The tivo also switched itself from the main screen with options to the live t.v picture after about 20mins from when it said it was going to do the big index operation - is this an indication it is done?

Q4) I see the entry "Db[170]: RecList:GetFirstScheduled:DbNotFound" after the eSucceeded entry does this mean the indexing did not really succeed?

Q5) I see the entry "DbGc[158]: DbGc::HandleTriggerWhileIdle -- clock is warped -- re-marking in 300 seconds" also after the successful final indexing. But the time is correct on the box and I thought the ntp program bug had been addressed from what I read. I have seen a number of work arounds and solutions to this. Based upon this image being done with the latest release which is the appropriate solution? or does this go away after a reboot after the big indexing is done?

Q6) I haven't rebooted after the final indexing of the G/Setup as I'm not sure that it has done - the "eSucceeded" entry occured - the eSucceeded happened really quickly so I have doubted the indexing occured successfully. There a number of "time warped" and "dbnotfound" entries in the log.

Q7) I see the message "MwContext[177]: ##### OnHeartbeat(): context 6 said NOT to time out to Live TV. (idle time 15:00) #####" or similar ones refering to the heartbeat with an error type of message. What is this refering to - it is important?

I guess that's it, I'm mainly just wondering how do I tell for sure the tivo is done with the indexing and if the error messages I see in the long are important or will just disappear once I reboot post guided setup.

I also included the log file from the tivo as this might be of some use.

Thanks for your help and time.

- Nic

[thomson]

I can't help much with the questions concerning the emulator, but it seems you will need to "touch /var/timestamp" and do a "force_index.tcl" in order to push things along a little (this will fix the clock warped issue which will be holding up indexing). You can ignore the timeout to TV messages... the menu will try to timeout to LiveTV after 15 minutes (this is configurable via a downloadable TVTimeOut script).

Seems you have most things under control... hopefully somebody with a little more experience with setting up an emulated system will chip in :)

[fear7]

Thanks thomson for the help. But I should have mentioned this isn't the first imaging of the tivo I've done. I used an earlier 1.3 version and had similar error messages in particular the time warping and DBnotfound messages which I tried to correct by a combination of touching the timestamp and then the forcingindexing script but this didn't seem to stop the error messages.

For that reason I decided to get this latest version and try it. There seems to be a lot of solutions put forward regarding time warping given the fact I'm using v1.4 of the ozTivo I'd love to know which is the appropriate one.

I just noticed a further error message seen in the tivoweb interface to the box when I enter the log module, before listing the available logs this error is displayed:

INTERNAL SERVER ERROR
--cut here--
action_logs '/' ''
no files matched glob pattern "/var/log/O*"
while executing
"glob "$TIVO_ROOT/var/log/O*""
(procedure "::action_logs" line 20)
invoked from within
"::action_$action $chan $part $env"
("eval" body line 1)
invoked from within
"eval {::action_$action $chan $part $env}"
--cut here--

Anyone with some thoughts? I haven't done anything to the tivo since the final guide step other than look at logs as I wanted to give it the 24 hours for indexing that is mentioned in some of the installation instructions.

[thomson]

INTERNAL SERVER ERROR
--cut here--
action_logs '/' ''
no files matched glob pattern "/var/log/O*"


This error message is occuring because there are no old log files (as when the TiVo starts, some of the log files are moved to O*, eg tivoweb.log->Otivoweb.log). Should be able to ignore this... should not cause problems... if it is, just touch a file (eg Otivoweb.log) in the /var/log directory.

There are actually lots of error messages displayed in the log files (messages, kernel, tverr, tvlog, etc) which can safely be ignored. The clock warped messages need to be fixed... this is done by touching the /var/timestamp file and reindexing.

[petestrash]

Thanks thomson for the help. But I should have mentioned this isn't the first imaging of the tivo I've done. I used an earlier 1.3 version and had similar error messages in particular the time warping and DBnotfound messages which I tried to correct by a combination of touching the timestamp and then the forcingindexing script but this didn't seem to stop the error messages.

For that reason I decided to get this latest version and try it. There seems to be a lot of solutions put forward regarding time warping given the fact I'm using v1.4 of the ozTivo I'd love to know which is the appropriate one.

As thomson had said this is not normal. The correct ntpdate file has been included with all r1.4 releases since april 1st and no workarounds should be needed.

You will have warp message within the 1st 24 hours after GS, but you should not have any after this.

Are you still receiving the warp messages?

What is the timestamp of the timestamp file?

Try this and see what you get
ntpdate 207.126.98.204 207.126.98.204 131.107.1.10

Peter.

[fear7]

Thanks for the clarrification petestrash. I'll have a look at my logs right now and post my findings.

One thing I was wondering pete was last night I tried to follow thomson's advice and touched the file /var/timestamp which didn't previously exist, then i forced an indexing and rebooted and started a manual recording to see what would have happened. i did this at about 11pm and indexing started at about 4pm. would i have screwed things up with the final g/s indexing? would that still have been occuring because i didn't see any log messages that looked to indicate it was still happening on the tivo, is there anyway to tell? or by lack of index related log messages is that indicating the process is over?

thanks,

nic

[fear7]

Hi Guys,

I checked my logs this morning and the "clock is warped" message has not occured since
last night when I did the touch timestamp command. However I still see:

Db[170]: RecList:GetFirstScheduled:DbNotFound

very frequently.

in response to my forceindexing command of last night the following log entries were written:

May 3 23:02:54 (none) DbShowcaseIndexer[158]: Showcase Indexer start
May 3 23:02:54 (none) DbShowcaseIndexer[158]: Showcase Indexer finished
May 3 23:02:54 (none) DbMasterIndexer[158]: Master indexer start.
May 3 23:02:56 (none) Db[170]: RecList:GetFirstScheduled:DbNotFound
May 3 23:04:38 (none) DbGc[158]: Non-linear state transition eMarkingReactive --> eFinished
May 3 23:06:21 (none) DbGc[158]: DbGc::AfterIndexersFSuccessful = 1
May 3 23:06:21 (none) DbGc[158]: DbGc::StoreCompletionInDb: 12906/83181 (0x0)
May 3 23:06:21 (none) DbGc[158]: DbGc::Mark succeeded, sweep soon
May 3 23:06:21 (none) DbGcBaseAction[158]: Background->SetTimeout( 0 )
May 3 23:06:23 (none) Scheduler[172]: Mempool highwater 408
May 3 23:06:23 (none) Scheduler[172]: DataChanged:PROGRAM_GUIDE
May 3 23:06:23 (none) Scheduler[172]: DISK SPACE: Total: 34366 Live cache: 1277 Overhead: 481
May 3 23:06:23 (none) Scheduler[172]: TIVO CLIPS DISK SPACE: Total: 2541 Overhead: 127
May 3 23:06:23 (none) Scheduler[172]: Done Checking high priority Capture Requests
May 3 23:06:23 (none) Scheduler[172]: Done ProcessProgramSources
May 3 23:06:23 (none) Scheduler[172]: Done Checking normal priority Capture Requests
May 3 23:06:23 (none) Scheduler[172]: FUZZY SOURCE
May 3 23:06:23 (none) Scheduler[172]: Start CheckUnwanted
May 3 23:06:23 (none) Scheduler[172]: Done CheckUnwanted
May 3 23:06:23 (none) Scheduler[172]: Start ScheduleOne
May 3 23:06:23 (none) Scheduler[172]: Fuzzy:ScheduleOne
May 3 23:06:23 (none) Scheduler[172]: Fuzzy:GetCandidates
May 3 23:06:23 (none) Scheduler[172]: SimAndSched:18786 [<?>] (Cnd0,Chg0,Unscd0,Scd0)
May 3 23:06:23 (none) Scheduler[172]: Fuzzy:Simulate
May 3 23:06:23 (none) Scheduler[172]: Fuzzy:SaveConflict
May 3 23:06:23 (none) Scheduler[172]: Done ScheduleOne
May 3 23:06:23 (none) Scheduler[172]: Done ProcessSpecialProgramSources
May 3 23:06:23 (none) Scheduler[172]: DataChanged:Completed
May 3 23:06:23 (none) SchedulerPolicy[172]: OtherDataChanged:PROGRAM_GUIDE
May 3 23:06:24 (none) DbGc[158]: Sweep done (eSucceeded) -- rescheduling marking in 61200 sec
May 3 23:06:24 (none) DbGcStats[158]: ---------------
May 3 23:06:24 (none) DbGcStats[158]: DbGC statistics
May 3 23:06:24 (none) DbGcStats[158]: {
May 3 23:06:24 (none) DbGcStats[158]: Type #InMemory #Queued #Collected
May 3 23:06:24 (none) DbGcStats[158]: ~~~~ ~~~~~~~~~ ~~~~~~~~~~ ~~~~~~~~~~
May 3 23:06:24 (none) DbGcStats[158]: Program 13006 0 0
May 3 23:06:24 (none) DbGcStats[158]: Series 2834 0 0
May 3 23:06:24 (none) DbGcStats[158]: Station 84 0 0
May 3 23:06:24 (none) DbGcStats[158]: StationDay 21 388 0
May 3 23:06:24 (none) DbGcStats[158]: PlaceHolder 6 34 0
May 3 23:06:24 (none) DbGcStats[158]: LoopSet 8 0 0
May 3 23:06:24 (none) DbGcStats[158]: SwSystem 0 1 0
May 3 23:06:24 (none) DbGcStats[158]: SwModule 9 0 0
May 3 23:06:24 (none) DbGcStats[158]: Recording 0 1 0
May 3 23:06:24 (none) DbGcStats[158]: Image 305 0 0
May 3 23:06:24 (none) DbGcStats[158]: Headend 0 1 0
May 3 23:06:24 (none) DbGcStats[158]: ResourceGroup 5 44 0
May 3 23:06:24 (none) DbGcStats[158]: Font 2 0 0
May 3 23:06:24 (none) DbGcStats[158]: Setup 0 1 0
May 3 23:06:24 (none) DbGcStats[158]: ComponentCode 660 0 0
May 3 23:06:24 (none) DbGcStats[158]: Component 330 0 0
May 3 23:06:24 (none) DbGcStats[158]: SeasonPass 1 0 0
May 3 23:06:24 (none) DbGcStats[158]: SoundFile 18 0 0
May 3 23:06:24 (none) DbGcStats[158]: PostalCode 1 0 0
May 3 23:06:24 (none) DbGcStats[158]: Genre 148 1 0
May 3 23:06:24 (none) DbGcStats[158]: IrFormat 84 0 0
May 3 23:06:24 (none) DbGcStats[158]: IrBlastData 192 0 0
May 3 23:06:24 (none) DbGcStats[158]: VideoClip 15 0 0
May 3 23:06:24 (none) DbGcStats[158]: IrTivoFormat 1 65 0
May 3 23:06:24 (none) DbGcStats[158]: MessageItem 0 1 0
May 3 23:06:24 (none) DbGcStats[158]: User 1 0 0
May 3 23:06:24 (none) DbGcStats[158]: DatabaseState 1 0 0
May 3 23:06:24 (none) DbGcStats[158]: MyWorldState 1 0 0
May 3 23:06:24 (none) DbGcStats[158]: MediaState 1 0 0
May 3 23:06:24 (none) DbGcStats[158]: AvalancheState 1 0 0
May 3 23:06:24 (none) DbGcStats[158]: AvConfig 1 0 0
May 3 23:06:24 (none) DbGcStats[158]: GeneralConfig 1 0 0
May 3 23:06:24 (none) DbGcStats[158]: PhoneConfig 1 0 0
May 3 23:06:24 (none) DbGcStats[158]: LocationConfig 1 0 0
May 3 23:06:24 (none) DbGcStats[158]: ArmConfig 1 0 0
May 3 23:06:24 (none) DbGcStats[158]: ServiceConfig 1 0 0
May 3 23:06:24 (none) DbGcStats[158]: ~~~~~~~~~ ~~~~~~~~ ~~~~~~~~~~ ~~~~~~~~~~
May 3 23:06:24 (none) DbGcStats[158]: total 17741 537 0
May 3 23:06:24 (none) DbGcStats[158]:
May 3 23:06:24 (none) DbGcStats[158]: State: eFinished
May 3 23:06:24 (none) DbGcStats[158]: Outcome: eSucceeded
May 3 23:06:24 (none) DbGcStats[158]:
May 3 23:06:24 (none) DbGcStats[158]: Attempts To Install GC Mask: 0
May 3 23:06:24 (none) DbGcStats[158]: ActiveLockConflicts during MarkActive: 0
May 3 23:06:24 (none) DbGcStats[158]: ActiveLockConflicts during MarkActive (BurpQueue): 0
May 3 23:06:24 (none) DbGcStats[158]: ActiveLockConflicts during MarkReactive (BurpQueue): 0
May 3 23:06:24 (none) DbGcStats[158]: ActiveLockConflicts while sweeping: 0
May 3 23:06:24 (none) DbGcStats[158]: nNonMaskableFsIdsM while installing GC Mask: 0
May 3 23:06:24 (none) DbGcStats[158]:
May 3 23:06:24 (none) DbGcStats[158]: msec MarkActive: 102926
May 3 23:06:24 (none) DbGcStats[158]: msec MarkReactive: 704
May 3 23:06:24 (none) DbGcStats[158]: msec Indexing: 148635
May 3 23:06:24 (none) DbGcStats[158]: msec InstallGcMask: 0
May 3 23:06:24 (none) DbGcStats[158]: msec SweepOne: 0
May 3 23:06:24 (none) DbGcStats[158]: sec Sweep State: 0
May 3 23:06:24 (none) DbGcStats[158]:
May 3 23:06:24 (none) DbGcStats[158]: before App Blocks 96.3554% free (756552/785168)
May 3 23:06:24 (none) DbGcStats[158]: before Media Blocks 97.0655% free (73568256/75792384)
May 3 23:06:24 (none) DbGcStats[158]: now App Blocks 96.3544% free (756544/785168)
May 3 23:06:24 (none) DbGcStats[158]: now Media Blocks 97.0655% free (73568256/75792384)
May 3 23:06:24 (none) DbGcStats[158]:
May 3 23:06:24 (none) DbGcStats[158]: }
May 3 23:06:24 (none) DbGcStats[158]: ---------------

but I still get the DbNotFound afterwards.

What does DbNotFound in this context mean?
Should I run that ntp command, then force another index and reboot?

[petestrash]

Db[170]: RecList:GetFirstScheduledbNotFound

Have you actually scheduled any recordings ?

some stuff wont be created until recordings have been scheduled.

Peter

[fear7]

Have you actually scheduled any recordings ?


Ahh I see, that's what the message was refering to. After reading this it makes sense now! Is there some documentation that I've missed refering to this sort of thing? I don't remember seeing any of this nature.

After reading this I set up a couple of session pass, some regular recordings from channel data and a manual recording. So far so good! No suspcious log entries and South Park recorded fine tonight.

One question though, I can seem to record a show that has already begun other than do a manual recording. If I got to the guide data for a show that has begun already all I can do is set up a session pass. Surely there must be an option to record what is left of a show? How is this done? (Just point me in the direction of documentation if such exists)

One other thing, I've sucessfully used mfs_ftp to extract a few shows now and they all work except for a very large .ty file that is about 5.6gb. Whenever I open the directory with this file and select it or try and open it windows crashes. This file is really huge I can't help think the size has something to do with it. I looked around google and couldn't see anything related to XP Pro. Has anyone experienced this or something similar?

Cheers and thanks for the help I've been given already.

[petestrash]

Ahh I see, that's what the message was refering to. After reading this it makes sense now! Is there some documentation that I've missed refering to this sort of thing? I don't remember seeing any of this nature.

I don't think it's mentioned, but most people try to record and playback as soon as they can, not watch the logs ;)


One question though, I can seem to record a show that has already begun other than do a manual recording. If I got to the guide data for a show that has begun already all I can do is set up a session pass. Surely there must be an option to record what is left of a show? How is this done? (Just point me in the direction of documentation if such exists)

the best way is just to press the record button on the remote whilst watching live tv :D. This also has the benefit of including all of the show currently in the buffer as well.


One other thing, I've sucessfully used mfs_ftp to extract a few shows now and they all work except for a very large .ty file that is about 5.6gb. Whenever I open the directory with this file and select it or try and open it windows crashes. This file is really huge I can't help think the size has something to do with it. I looked around google and couldn't see anything related to XP Pro. Has anyone experienced this or something similar?

Which version of mfs_ftp are you using 1.2.9p works ok for me, 2 hour movies are around 6gb. what are you using to play them back.

Peter.

[fear7]

True, true Pete regarding the logs :). I was guarded since I read about weird behaviour happening to tivos that do a improper final indexing.


the best way is just to press the record button on the remote whilst watching live tv . This also has the benefit of including all of the show currently in the buffer as well.


Ah, but the tivo I'm setting up is intended for principly to be controlled remotely.But I guess I could just use the web interface for the remote which would work just as you say. But this (should) be rare as the programs recorded should all be set before they occur.


Which version of mfs_ftp are you using 1.2.9p works ok for me, 2 hour movies are around 6gb. what are you using to play them back.

Yep I'm using 1.2.9 as well. I did notice some error messages when I untared the package on the tivo but it seemed to function so I just ignored them. Windows Media Encoder, Windows Media Player and Windows Explorer will all crash as soon as they touch it, I was just wondering if it's massive size was an OS issue. But if you are using files of 6gb then this 5.6 one should be fine. Maybe it is corrupt.

The errors I got from the tivo during the install of mfs_ftp were:

[TiVo [p0] /var]# tar -xvf mfs_ftp.tar
mfs_ftp/
mfs_ftp/fifo
mfs_ftp/scramble_utils/
mfs_ftp/scramble_utils/get_DC_key.tcl
mfs_ftp/scramble_utils/set_DC_key.tcl
mfs_ftp/scramble_utils/nuke_DC_key.tcl
mfs_ftp/scramble_utils/readme.txt
mfs_ftp/mfs_export
mfs_ftp/mfs_ftp.tcl
mfs_ftp/mfs_stdinsert
mfs_ftp/mfs_stream
mfs_ftp/mfs_tarstream
mfs_ftp/ftpf.sh
mfs_ftp/cache/
mfs_ftp/tzoffset.tcl
mfs_ftp/setpri
mfs_ftp/log
tar: mfs_ftp/log: Cannot lchown to uid 0 gid 0: Function not implemented
mfs_ftp/abort_toggle.sh
mfs_ftp/ftpf21.sh
mfs_ftp/seasonpass/
mfs_ftp/readme.txt
mfs_ftp/ftp
tar: mfs_ftp/ftp: Cannot lchown to uid 0 gid 0: Function not implemented
mfs_ftp/abort.doc
mfs_ftp/license.txt
mfs_ftp/settings.tcl
mfs_ftp/set
tar: mfs_ftp/set: Cannot lchown to uid 0 gid 0: Function not implemented
tar: Error exit delayed from previous errors

[Tuatara]

tar: mfs_ftp/log: Cannot lchown to uid 0 gid 0: Function not implemented
tar: Error exit delayed from previous errors

I've had those errors, but they just seem to be a permissions thing which you can ignore as TiVo runs everything as root anyway.

mfs_ftp seems to work better with some clients than others. I've had the best luck with ncftp, a command-line tool (which is available for ye Windows users). If you have a bunch of files to move use its background mode -- just remember the server is single-threaded.

Cheers
Matt

[fear7]

Hi,

Thought I'd just let everyone know I resolved that problem with large .ty files. I found someone who had exactly the same problem and they said by updating to 0.15 of tyshow together with a patch of two of the files that was put up on the tyshow thread that the issue cleared up.

So if anyone else has this problem just remove any earlier versions of tyshow, grab the 0.15 version from the tyshow project at sourceforge patch two of the files from the posting on the tyshow thread (about page 43 i think)
that is available at:

http://www.dealdatabase.com/forum/showthread.php?t=27399

So the problem wasn't with mfs_ftp or the tivo box, just with TyShow.

- Nic