[TeaVoChimp]

ANY advice appreciated!

Got Tivo off ebay,
setup pay monthly account,
wouldnt make calls via Modem....various leads & settings tried.
Opted for LAN/cache card and preloaded drive upgrade.

Installed as per instructions, only one successful test call made, since then I've been in guided setup hell!

I can telnet, ping, web all via the LAN. Have checked nic_config_tivo and option 4 says Network, tried changing and changing back etc no joy.

Can ANYBODY give me ANY suggestions on how to check that my TiVo is actually communicating via my LAN, as modem is not an option (no modem cable attached).

I now cant get out of the on screen Guided Setup, however Bash prompt available and can provide any logs that may tell YOU what my problem is

I'm a complete Tivo novice, very frustrated and disapointed

TIA


ps: sorry for posting in TiVO UK, but looking for UK relevant knowledge

 

[Cainam]

Going through the obvious first, can you do the following:

1) Tell us the IP address of your home router (e.g. 192.168.0.1)

2) in nic_config_tivo, tell us what it says for ip address, subnet mask, and gateway address?

Thanks!

 

[TeaVoChimp]

Going through the obvious first, can you do the following:

1) Tell us the IP address of your home router (e.g. 192.168.0.1)

2) in nic_config_tivo, tell us what it says for ip address, subnet mask, and gateway address?

Thanks!

A1) its exactly that, 192.168.0.1 (good guess

A2) see below:

Current/New Configuration:
mac address = xx:xx:xx:xx:xx:xx (I've masked it out)
ip address = 192.168.0.6
ip subnet mask = 255.255.255.0
ip gateway = 192.168.0.1
debug level = off
daily call = network
cache statistics = 0 seconds

...anything else I can tell you?

cheers

 

[Cainam]

Then the easiest way to me to prove the network card is working is to start telnet, and ping something externally e.g. 'ping 64.233.169.103', which I think is the IP address of google

 

[TeaVoChimp]

yep, can ping 64.233.169.103

can also ping 204.176.49.3
and 204.176.49.31 (which I believe are relevant to the TiVO)


all 3 respond....

 

[Cainam]

OK, so at least you know the network card is working and is configured OK.

Could be a transparent proxy issue then. Have a look at this site, which tells you how to hack the file /tvlib/tcl/tv/Ident.itcl to get round the problem.

 

[TeaVoChimp]

following other threads last night, I ran a test which said i wasnt using a transparent proxy

I use Orange (was Freeserve) broadband as my ISP

 

[Cainam]

Forgot to say, as you have bought a new preconfigured hard drive joe will almost certainly already been on your hard disk, which makes it easier to edit that file!

 

[Cainam]

Can't harm doing the change though, just to make sure

 

[Cainam]

Also, to double check the network settings, type the following, and post the results

cat /etc/rc.d/rc.net

 

[TeaVoChimp]

yes, Joe already loaded....

followed that link and did the following:

Step 2. Hacking the Ident.itcl file

* From the # prompt type:
/var/hack/joe /tvlib/tcl/tv/Ident.itcl
* Look for this line puts $conn "IDB_TIMESTAMP: $now"
* Insert puts $conn "Content-Length: 0" directly after that line
* Save the file:
Ctrl-K-X
* From the # prompt type:
mount -o remount,ro / (Makes the File System Read Only)
sync (Flushes your changes to disk)

Step 3. Suck it and see
Make sure the phone line is unplugged, reboot the TiVo and make a test call - you're there dude.

interestingly when I clicked MAKE TEST CALL NOW, it failed pretty much instantly...
currently says "Settingup" in status, due to me clicking MAKE DAILY CALL NOW...

then typed cat /etc/rc.d/rc.net and got the following:

bash-2.02# cat /etc/rc.d/rc.net
#
#!/bin/sh
#

if /sbin/insmod -f /lib/modules/turbonet2.o macaddr=xx:xx:xx:xx:xx:xx ; then
export DYNAMIC_NET_DEV=eth0
/sbin/ifconfig eth0 192.168.0.6 netmask 255.255.255.0 up
/sbin/route.tivo add default gw 192.168.0.1 netmask 0.0.0.0
fi

 

[Cainam]

rc.net looks fine.

Can you post the http log, and the tvlog files?

 

[TeaVoChimp]

oddly /var/log/http/ gives me the following:

Mon Oct 17 05:32:56 2011: /tvbin/tclient_post invoked
connecting to 204.176.49.3:80
read 1540 bytes from file
writing 1540 bytes to socket
socket 19 ready for writing
wrote 1540 bytes to socket
EOF read from file
select-ing for header
timeout waiting to read

how much tvlog did you want?

Oct 17 08:31:01 (none) Scheduler[151]: Mempool highwater 68
Oct 17 08:31:01 (none) Scheduler[151]: DataChangedROGRAM_GUIDE
Oct 17 08:31:01 (none) Scheduler[151]: Abr-- DataChanged:0x00090009
Oct 17 08:31:11 (none) Recorder[149]: Adding check schedule task
Oct 17 08:31:33 (none) Scheduler[151]: Mempool highwater 68
Oct 17 08:31:33 (none) Scheduler[151]: DataChangedROGRAM_GUIDE
Oct 17 08:31:33 (none) Scheduler[151]: Abr-- DataChanged:0x00090009
Oct 17 08:32:05 (none) Scheduler[151]: Mempool highwater 68
Oct 17 08:32:05 (none) Scheduler[151]: DataChangedROGRAM_GUIDE
Oct 17 08:32:05 (none) Scheduler[151]: Abr-- DataChanged:0x00090009
Oct 17 08:32:10 (none) Recorder[149]: Adding check schedule task
Oct 17 08:32:37 (none) Scheduler[151]: Mempool highwater 68
Oct 17 08:32:37 (none) Scheduler[151]: DataChangedROGRAM_GUIDE
Oct 17 08:32:37 (none) Scheduler[151]: Abr-- DataChanged:0x00090009
Oct 17 08:33:09 (none) Recorder[149]: Adding check schedule task
Oct 17 08:33:09 (none) Scheduler[151]: Mempool highwater 68
Oct 17 08:33:09 (none) Scheduler[151]: DataChangedROGRAM_GUIDE
Oct 17 08:33:09 (none) Scheduler[151]: Abr-- DataChanged:0x00090009
Oct 17 08:33:42 (none) Scheduler[151]: Mempool highwater 68
Oct 17 08:33:42 (none) Scheduler[151]: DataChangedROGRAM_GUIDE
Oct 17 08:33:42 (none) Scheduler[151]: Abr-- DataChanged:0x00090009
Oct 17 08:34:08 (none) Recorder[149]: Adding check schedule task
Oct 17 08:34:13 (none) Scheduler[151]: Mempool highwater 68
Oct 17 08:34:13 (none) Scheduler[151]: DataChangedROGRAM_GUIDE
Oct 17 08:34:13 (none) Scheduler[151]: Abr-- DataChanged:0x00090009
Oct 17 08:34:45 (none) Scheduler[151]: Mempool highwater 68
Oct 17 08:34:45 (none) Scheduler[151]: DataChangedROGRAM_GUIDE
Oct 17 08:34:45 (none) Scheduler[151]: Abr-- DataChanged:0x00090009
Oct 17 08:35:07 (none) Recorder[149]: Adding check schedule task
Oct 17 08:35:17 (none) Scheduler[151]: Mempool highwater 68
Oct 17 08:35:17 (none) Scheduler[151]: DataChangedROGRAM_GUIDE
Oct 17 08:35:17 (none) Scheduler[151]: Abr-- DataChanged:0x00090009
Oct 17 08:36:12 (none) EvtSwitcher[77]: EventSwitcher is starting up
Oct 17 08:36:12 (none) MfsDaemon[78]: MFS Daemon started, id is 78
Oct 17 08:36:12 (none) MfsDaemon[78]: Initializing MFS
Oct 17 08:36:12 (none) MfsDaemon[78]: Found 1 analog, 0 digital tuners: 364544-byte heap
Oct 17 08:36:12 (none) NmCache[78]: Cache at 0x0x7fee0cc4, array of 100 entries at 0x0x7fee0d4c
Oct 17 08:36:14 (none) MfsDaemon[78]: The MfsDaemon is starting up
Oct 17 08:36:14 (none) EvtSwitcher[77]: MFS Daemon started, id is 78
Oct 17 08:36:14 (none) MfsDaemon[78]: Initialization complete
Oct 17 08:36:14 (none) EvtSwitcher[77]: Tmk client 1 (pid=76) has attached
Oct 17 08:36:14 (none) EvtSwitcher[77]: Invalid service attempted to attach?
Oct 17 08:36:14 (none) EvtSwitcher[77]: Group 76 was not an MFS group
Oct 17 08:36:14 (none) EvtSwitcher[77]: Client 1 (pid=76) being removed
Oct 17 08:36:14 (none) EvtSwitcher[77]: Tmk client 2 (pid=78) has attached
Oct 17 08:36:14 (none) EvtSwitcher[77]: Invalid service attempted to attach?
Oct 17 08:36:14 (none) EvtSwitcher[77]: Client 2 (pid=78), thread 78 has activated MFS
Oct 17 08:36:17 (none) DbUpgrader[103]: majorVersionNum:4
Oct 17 08:36:17 (none) DbUpgrader[103]: minorVersionNum:40
Oct 17 08:36:17 (none) DbUpgrader[103]: converted majorVersionNum:4
Oct 17 08:36:17 (none) DbUpgrader[103]: converted minorVersionNum:40
Oct 17 08:36:17 (none) DbUpgrader[103]: Existing version: 4.40
Oct 17 08:36:17 (none) DbUpgrader[103]: Database is already up to date.
Oct 17 08:36:17 (none) convert-db[103]: no pending ZapRequests
Oct 17 08:36:17 (none) convert-db[103]: High water mark:
Oct 17 08:36:17 (none) convert-db[103]: tmk 1348/ 0 bytes ( 19 blocks/ 0 chunks)
Oct 17 08:36:17 (none) convert-db[103]: directory 112/ 1536 bytes ( 2 blocks/ 2 chunks)
Oct 17 08:36:17 (none) convert-db[103]: database 268/ 512 bytes ( 6 blocks/ 1 chunks)
Oct 17 08:36:17 (none) convert-db[103]: executive 44/ 0 bytes ( 2 blocks/ 0 chunks)
Oct 17 08:36:17 (none) convert-db[103]: tmkevent 32/ 0 bytes ( 1 blocks/ 0 chunks)
Oct 17 08:36:17 (none) convert-db[103]: TOTAL 1748/ 2048 bytes ( 29 blocks/ 3 chunks)
Oct 17 08:36:17 (none) tcl[104]: Tcl created pool of 1458176 bytes
Oct 17 08:36:18 (none) EvtSwitcher[77]: Tmk client 3 (pid=104) has attached
Oct 17 08:36:18 (none) EvtSwitcher[77]: Invalid service attempted to attach?
Oct 17 08:36:18 (none) EvtSwitcher[77]: Client 3 (pid=104), thread 104 has activated MFS
Oct 17 08:36:18 (none) EvtSwitcher[77]: Client 3 (pid=104) says he has finished
Oct 17 08:36:18 (none) EvtSwitcher[77]: Client 3 (pid=104) being removed
Oct 17 08:36:19 (none) EvtSwitcher[77]: LaunchPhasedService
Oct 17 08:36:19 (none) EvtService[77]: Launching /tvbin/mcp phase 10
Oct 17 08:36:19 (none) EvtSwitcher[77]: Client 4 being removed
Oct 17 08:36:19 (none) tcl[109]: Tcl created pool of 2916352 bytes
Oct 17 08:36:19 (none) tcl[112]: Tcl created pool of 1458176 bytes
Oct 17 08:36:19 (none) EvtSwitcher[77]: Tmk client 5 (pid=106) has attached
Oct 17 08:36:19 (none) EvtSwitcher[77]: Client 5 (Mcp, pid=106) is service Mcp
Oct 17 08:36:19 (none) EvtSwitcher[77]: Client 5 (Mcp, pid=106) has asked for 42 events
Oct 17 08:36:19 (none) EvtSwitcher[77]: First CLIENT_STARTUP event, current 1, total 1
Oct 17 08:36:19 (none) EvtSwitcher[77]: Service Mcp has finished startup
Oct 17 08:36:19 (none) EvtSwitcher[77]: LaunchPhasedService
Oct 17 08:36:19 (none) EvtService[77]: Launching /tvbin/tcphonehome phase 20
Oct 17 08:36:19 (none) MCPserver[114]: MCP startup complete
Oct 17 08:36:19 (none) EvtSwitcher[77]: Client 5 (Mcp, pid=106) has asked for 19 events
Oct 17 08:36:20 (none) EvtSwitcher[77]: Tmk client 6 (pid=118) has attached
Oct 17 08:36:20 (none) EvtSwitcher[77]: Client 6 (Phone Home, pid=118) is service Phone Home
Oct 17 08:36:21 (none) EvtSwitcher[77]: Client 6 (Phone Home, pid=118), thread 118 has activated MFS
Oct 17 08:36:21 (none) EvtSwitcher[77]: Client 6 (Phone Home, pid=118) has asked for 42 events
Oct 17 08:36:21 (none) EvtSwitcher[77]: Client 6 (Phone Home, pid=118) has asked for 30 events
Oct 17 08:36:21 (none) EvtSwitcher[77]: Client 6 (Phone Home, pid=118) has asked for 69 events
Oct 17 08:36:21 (none) EvtSwitcher[77]: Client 6 (Phone Home, pid=118) has asked for 62 events
Oct 17 08:36:21 (none) EvtSwitcher[77]: Client 6 (Phone Home, pid=118) has asked for 77 events
Oct 17 08:36:21 (none) EvtSwitcher[77]: Client 6 (Phone Home, pid=118) has asked for 76 events
Oct 17 08:36:21 (none) EvtSwitcher[77]: Client 6 (Phone Home, pid=118) has asked for 19 events
Oct 17 08:36:21 (none) tcphonehome[123]: TCphonehome active
Oct 17 08:36:21 (none) tcphonehome[127]: cleaning /Setup
Oct 17 08:36:21 (none) tcphonehome[127]: getting setup
Oct 17 08:36:21 (none) tcphonehome[127]: got setup
Oct 17 08:36:21 (none) tcphonehome[127]: Fetching /SwSystemACTIVE/Name
Oct 17 08:36:21 (none) tcphonehome[127]: Last Call Status Was: 'Failed' (size 6)
Oct 17 08:36:21 (none) tcphonehome[127]: Last Call Status Will Be: Failed
Oct 17 08:36:21 (none) tcphonehome[127]: setCallStatus called with: Failed state 0
Oct 17 08:36:21 (none) tcphonehome[127]: Successfully got /Setup object
Oct 17 08:36:21 (none) tcphonehome[127]: Last call attempt at 1318839025
Oct 17 08:36:21 (none) tcphonehome[127]: setting call status to: Failed
Oct 17 08:36:21 (none) tcphonehome[127]: Successfully got ServiceInfo subobject (first successCount)
Oct 17 08:36:21 (none) tcphonehome[127]: setting call in progress to 0 (second successCount)
Oct 17 08:36:21 (none) tcphonehome[127]: End of transaction, err is 0 0x00000000
Oct 17 08:36:21 (none) tcphonehome[127]: Setting callActive to 0
Oct 17 08:36:22 (none) tcphonehome[127]: PhoneHome: statusValue = <0>, getREsult = <0>
Oct 17 08:36:22 (none) EvtSwitcher[77]: Tmk client 7 (pid=109) has attached
Oct 17 08:36:22 (none) EvtSwitcher[77]: Invalid service attempted to attach?
Oct 17 08:36:22 (none) EvtSwitcher[77]: Client 7 (pid=109), thread 109 has activated MFS
Oct 17 08:36:22 (none) tcphonehome[127]: /State/Avalanche LastStatus was <0> and getResult was <0>, changing to unknown
Oct 17 08:36:22 (none) tcphonehome[127]: finished cleaning /Setup
Oct 17 08:36:23 (none) tcphonehome[127]: Running command: /sbin/ifconfig eth0
Oct 17 08:36:24 (none) tcl[131]: Tcl created pool of 1458176 bytes
Oct 17 08:36:24 (none) tcphonehome[127]: Command output: eth0 Link encap:Ethernet HWaddr 00:0B:AD:8B:AC:C4
Oct 17 08:36:24 (none) tcphonehome[127]: Command output: inet addr:192.168.0.6 Bcast:192.168.0.255 Mask:255.255.255.0
Oct 17 08:36:24 (none) tcphonehome[127]: Command output: UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1
Oct 17 08:36:24 (none) tcphonehome[127]: Command output: RX packets:0 errors:0 dropped:0 overruns:0 frame:0
Oct 17 08:36:24 (none) tcphonehome[127]: Command output: TX packets:0 errors:0 dropped:0 overruns:0 carrier:0 coll:0
Oct 17 08:36:24 (none) tcphonehome[127]: Command output: Interrupt:29
Oct 17 08:36:24 (none) tcphonehome[127]: Command output:
Oct 17 08:36:24 (none) tcphonehome[127]: Command finished status: 0, errno = 2
Oct 17 08:36:24 (none) tcphonehome[127]: USING ethernet. true
Oct 17 08:36:25 (none) tcphonehome[127]: Timesync not found - TIMEWARP!
Oct 17 08:36:25 (none) TmkTime::Warp[127]: warping!
Oct 17 08:36:25 (none) tcphonehome[127]: ReschedCall: reason = 7, secSinceLast = 1, numFails = 0
Oct 17 08:36:25 (none) tcphonehome[127]: Schedule call after timewarp
Oct 17 08:36:25 (none) tcphonehome[127]: setting next attempt at 1318841845 (Mon Oct 17 08:57:25 2011 )
Oct 17 08:36:25 (none) MCPaction[127]: PhoneAction 2 got RegisterComplete. Setting ticcount to 1260
Oct 17 08:36:25 (none) MCPaction[127]: Register Complete: Next call should happen at Mon Oct 17 08:57:25 2011
Oct 17 08:36:25 (none) tcphonehome[127]: called getTZ
Oct 17 08:36:25 (none) EvtSwitcher[77]: First CLIENT_STARTUP event, current 1, total 2
Oct 17 08:36:25 (none) EvtSwitcher[77]: Another CLIENT_STARTUP event, current 2, total 2
Oct 17 08:36:25 (none) EvtSwitcher[77]: Service Phone Home has finished startup
Oct 17 08:36:25 (none) EvtSwitcher[77]: LaunchPhasedService
Oct 17 08:36:25 (none) EvtService[77]: Launching /tvbin/dbgc-mcp phase 40
Oct 17 08:36:25 (none) MCPaction[127]: WatchdogAction register complete
Oct 17 08:36:26 (none) EvtSwitcher[77]: Tmk client 8 (pid=133) has attached
Oct 17 08:36:26 (none) EvtSwitcher[77]: Client 8 (dbgc-mcp, pid=133) is service dbgc-mcp
Oct 17 08:36:26 (none) EvtSwitcher[77]: Client 8 (dbgc-mcp, pid=133), thread 133 has activated MFS
Oct 17 08:36:26 (none) EvtSwitcher[77]: Client 8 (dbgc-mcp, pid=133) has asked for 42 events
Oct 17 08:36:26 (none) EvtSwitcher[77]: Client 8 (dbgc-mcp, pid=133) has asked for 23 events
Oct 17 08:36:26 (none) EvtSwitcher[77]: Client 8 (dbgc-mcp, pid=133) has asked for 55 events
Oct 17 08:36:26 (none) EvtSwitcher[77]: Client 8 (dbgc-mcp, pid=133) has asked for 56 events
Oct 17 08:36:26 (none) EvtSwitcher[77]: Client 8 (dbgc-mcp, pid=133) has asked for 30 events
Oct 17 08:36:26 (none) EvtSwitcher[77]: Client 8 (dbgc-mcp, pid=133) has asked for 19 events
Oct 17 08:36:26 (none) DbGc[134]: DbGc::InitialMarkingTimeout: set timeout to 1 secs
Oct 17 08:36:26 (none) DbGcBaseAction[134]: Background->SetTimeout( 1 )
Oct 17 08:36:26 (none) EvtSwitcher[77]: First CLIENT_STARTUP event, current 1, total 2
Oct 17 08:36:26 (none) EvtSwitcher[77]: Another CLIENT_STARTUP event, current 2, total 2
Oct 17 08:36:26 (none) EvtSwitcher[77]: Service dbgc-mcp has finished startup
Oct 17 08:36:26 (none) EvtSwitcher[77]: LaunchPhasedService
Oct 17 08:36:26 (none) EvtService[77]: Launching /tvbin/myworld phase 50
Oct 17 08:36:27 (none) EvtSwitcher[77]: Tmk client 9 (pid=136) has attached
Oct 17 08:36:27 (none) EvtSwitcher[77]: Client 9 (My World, pid=136) is service My World
Oct 17 08:36:27 (none) EvtSwitcher[77]: Client 9 (My World, pid=136), thread 136 has activated MFS
Oct 17 08:36:27 (none) EvtSwitcher[77]: Tmk client 10 (pid=131) has attached
Oct 17 08:36:27 (none) EvtSwitcher[77]: Invalid service attempted to attach?
Oct 17 08:36:27 (none) EvtSwitcher[77]: Client 10 (pid=131), thread 131 has activated MFS
Oct 17 08:36:27 (none) EvtSwitcher[77]: Client 9 (My World, pid=136) has asked for 19 events
Oct 17 08:36:27 (none) DbGcBaseAction[134]: Background->SetTimeout( 300 )
Oct 17 08:36:27 (none) DbGc[134]: DbGc::HandleTriggerWhileIdle -- clock is warped -- re-marking in 300 seconds
Oct 17 08:36:29 (none) EvtSwitcher[77]: Client 7 (pid=109) has asked for 30 events
Oct 17 08:36:35 (none) MyWorld[137]: MyWorldGlobals: debug board present!
Oct 17 08:36:35 (none) MyWorld[137]: MyWorldGlobals::SetBackdoorsEnabled: Enabling Backdoors!
Oct 17 08:36:35 (none) EventLogger[137]: EventLogger startup complete
Oct 17 08:36:35 (none) MOMGlobals[137]: TMK_DEBUGGER=not sleep
Oct 17 08:36:35 (none) InputState[137]: EnableTuner 0
Oct 17 08:36:35 (none) InputState[137]: IdleTuner 0
Oct 17 08:36:35 (none) TmkSinkMixAud[137]: opened device: /dev/mixaud2
Oct 17 08:36:35 (none) TvSoundPlayer[137]: loading sounds with volume 25
Oct 17 08:36:35 (none) TmkSinkMixAud[137]: Loading sound file from fsid 376
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: sound file size=55668, buf size=6958, nframes=13917
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: Loading sound file from fsid 379
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: sound file size=11196, buf size=1399, nframes=2799
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: Loading sound file from fsid 389
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: sound file size=24196, buf size=3024, nframes=6049
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: Loading sound file from fsid 387
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: sound file size=24416, buf size=3052, nframes=6104
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: Loading sound file from fsid 383
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: sound file size=73176, buf size=9147, nframes=18294
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: Loading sound file from fsid 381
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: sound file size=67612, buf size=8451, nframes=16903
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: Loading sound file from fsid 385
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: sound file size=32944, buf size=4118, nframes=8236
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: Loading sound file from fsid 395
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: sound file size=26532, buf size=3316, nframes=6633
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: Loading sound file from fsid 391
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: sound file size=106508, buf size=13313, nframes=26627
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: Loading sound file from fsid 393
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: sound file size=65268, buf size=8158, nframes=16317
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: Loading sound file from fsid 397
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: sound file size=118512, buf size=14814, nframes=29628
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: Loading sound file from fsid 401
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: sound file size=28744, buf size=3593, nframes=7186
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: Loading sound file from fsid 403
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: sound file size=29700, buf size=3712, nframes=7425
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: Loading sound file from fsid 405
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: sound file size=25720, buf size=3215, nframes=6430
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: Loading sound file from fsid 399
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: sound file size=30372, buf size=3796, nframes=7593
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: Loading sound file from fsid 31198
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: sound file size=94884, buf size=11860, nframes=23721
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: Loading sound file from fsid 31200
Oct 17 08:36:36 (none) TmkSinkMixAud[137]: sound file size=94052, buf size=11756, nframes=23513
Oct 17 08:36:36 (none) VideoGuts[137]: Setting policy to TogglePolicy
Oct 17 08:36:36 (none) Recorder[137]: TvRecorder::Initialize
Oct 17 08:36:37 (none) Recorder[137]: Found recording to clean up: /Recording/InProgress/780269 780269
Oct 17 08:36:37 (none) UiTimer[143]: Heartbeat thread (pid 143) started
Oct 17 08:36:37 (none) VideoGuts[137]: AsociateWithLiveCache 2
Oct 17 08:36:37 (none) TmkSink[137]: Using TvMomMpegSink for output
Oct 17 08:36:37 (none) TmkSink::Trace[137]: Successfully set up sink
Oct 17 08:36:37 (none) TmkSink[137]: Using TvMomMpegSink for output
Oct 17 08:36:37 (none) TmkSink::Trace[137]: Successfully set up sink
Oct 17 08:36:37 (none) TmkSink::Trace[146]: Starting TvMomMpegSink MainLoop in thread 146
Oct 17 08:36:37 (none) TmkSink::Trace[147]: Starting TvMomMpegSink MainLoop in thread 147
Oct 17 08:36:38 (none) TmkMediaswitch::Trace[137]: Auto Board Type Detection:0
Oct 17 08:36:38 (none) TmkMediaswitch::Trace[137]: In mediaswitch contiguous memory addr 0x80154000
Oct 17 08:36:38 (none) TmkMediaswitch::Trace[137]: In mediaswitch contiguous memory length 1179648
Oct 17 08:36:38 (none) TmkMediaswitch::Trace[137]: Mediswitch source contig memory virt addr = 0x30201000
Oct 17 08:36:38 (none) TmkMediaswitch::Trace[137]: Setting Video Buffer 0x80158040 Len: 836096
Oct 17 08:36:38 (none) TmkMediaswitch::Trace[137]: Setting Audio Buffer 0x80224240 Len: 108864
Oct 17 08:36:38 (none) TmkMediaswitch::Trace[137]: Setting Event Buffer 0x80154000 Len: 2048
Oct 17 08:36:38 (none) TmkMediaswitch::Trace[137]: Setting Data Buffer 0x8023eb40 Len: 201888
Oct 17 08:36:38 (none) TunerManager[137]: LoadTunerLocked(): loading 2 signal source(s) on a standalone box
Oct 17 08:36:38 (none) TunerManager[137]: LoadTunerLocked(): adding tuner of type IRTuningSource
Oct 17 08:36:38 (none) TmkMediaswitch::Trace[148]: Mediaswitch Source starting PID:148
Oct 17 08:36:38 (none) TunerManager[137]: LoadTunerLocked(): adding tuner of type InternalTuningSource
Oct 17 08:36:38 (none) EvtSwitcher[77]: Client 9 (My World, pid=136) has asked for 76 events
Oct 17 08:36:38 (none) Scheduler[137]: DISK SPACE: Total: 227390 Live cache: 1277 Overhead: 396
Oct 17 08:36:38 (none) Scheduler[137]: TIVO CLIPS DISK SPACE: Total: 9765 Overhead: 42
Oct 17 08:36:38 (none) EvtSwitcher[77]: Client 9 (My World, pid=136) has asked for 42 events
Oct 17 08:36:38 (none) EvtSwitcher[77]: Client 9 (My World, pid=136) has asked for ALL events
Oct 17 08:36:38 (none) dbcache[153]: DbChannelList::ReloadDerived: Init load done (33 ms), caching nItemM = 0
Oct 17 08:36:38 (none) dbcache[153]: DbChannelList::ReloadDerived: Init cache of callsigns complete (40 ms)
Oct 17 08:36:39 (none) Recorder[149]: Adding check schedule task
Oct 17 08:36:39 (none) RunMyWorld[137]: Running version b-2-5-5 @74190 2002.02.07-1746 release-tivo1 COMPACT_LAYOUT STANDALONE DIRECTV
Oct 17 08:36:39 (none) InputState[153]: StartCaching 0
Oct 17 08:36:39 (none) DbSetupUtil[153]: Setting state 2 to 0
Oct 17 08:36:39 (none) TmkMediaswitch::Trace[148]: using CBR, bitRate=5960000, maxBitrate=5960000
Oct 17 08:36:39 (none) DbSetupUtil[153]: Complete flag set: 0
Oct 17 08:36:39 (none) DbSetupUtil[153]: Setting state 4 to 0
Oct 17 08:36:39 (none) DbSetupUtil[153]: Complete flag set: 0
Oct 17 08:36:40 (none) TmkTransform::Trace[148]: ClipCache 0x30006008 Secondary Reset
Oct 17 08:36:40 (none) ClipCache[144]: 0x30006008 in Entry(), thread 144
Oct 17 08:36:41 (none) TmkMediaswitch::Trace[148]: LOCK LOST ON CHANNEL -3
Oct 17 08:36:46 (none) convertPrefs[152]: Reassociating person perfselements in directory /Preference/a/7
Oct 17 08:36:46 (none) convertPrefs[152]: Reassociating person perfselements in directory /Preference/a/8
Oct 17 08:36:46 (none) convertPrefs[152]: Reassociating person perfselements in directory /Preference/a/9
Oct 17 08:36:46 (none) convertPrefs[152]: Reassociating person perfselements in directory /Preference/a/10
Oct 17 08:36:46 (none) convertPrefs[152]: Reassociating person perfselements in directory /Preference/a/11
Oct 17 08:36:46 (none) convertPrefs[152]: Reassociating person perfselements in directory /Preference/a/12
Oct 17 08:36:46 (none) convertPrefs[152]: Reassociating person perfselements in directory /Preference/a/13
Oct 17 08:36:49 (none) Recorder[149]: Guided setup (1): started, NO RECORDINGS WILL START
Oct 17 08:36:49 (none) Recorder[149]: Adding check schedule task
Oct 17 08:36:57 (none) EvtSwitcher[77]: Client 10 (pid=131) says he has finished
Oct 17 08:36:57 (none) EvtSwitcher[77]: Client 10 (pid=131) being removed
Oct 17 08:37:07 (none) Recorder[149]: Adding allocate task already 59 sec late
Oct 17 08:37:07 (none) Deadline[149]: Creating task already 70000 milliseconds late
Oct 17 08:37:07 (none) Deadline[149]: VERY_LATE:Task AllocateLiveCache started late by 70002ms
Oct 17 08:37:07 (none) Recorder[149]: AllocateFiles for live cache
Oct 17 08:37:07 (none) Recorder[149]: Live cache size 208896
Oct 17 08:37:07 (none) Recorder[149]: User recording 232638848 free 202862976
Oct 17 08:37:07 (none) Recorder[149]: TivoClip total 10000000 free 9686656
Oct 17 08:37:07 (none) Recorder[149]: Allocated stream Id 780281, size 208896
Oct 17 08:37:07 (none) mediamgr[149]: AddLiveFile input#0
Oct 17 08:37:07 (none) Deadline[149]: VERY_LATE:Task AllocateLiveCache ran late by 60175ms
Oct 17 08:37:07 (none) Recorder[149]: Adding check schedule task
Oct 17 08:37:17 (none) Recorder[149]: Adding check schedule task
Oct 17 08:37:21 (none) TvDbUtil[151]: LogRecordings3: Begin (20): 242847744, 232847744, 29775872, 203071872, 29801472, 40480, 5889
Oct 17 08:37:21 (none) TvDbUtil[151]: LogRecordings3: 114470, 25600, 34, 6023, 0x4, 0x10, 0x4
Oct 17 08:37:21 (none) TvDbUtil[151]: LogRecordings3: 377310, 3096576, 4202, 5895, 0x5, 0x3, 0x1
Oct 17 08:37:21 (none) TvDbUtil[151]: LogRecordings3: 377313, 3311616, 4502, 5884, 0x5, 0x3, 0x1
Oct 17 08:37:21 (none) TvDbUtil[151]: LogRecordings3: 478468, 663552, 902, 5885, 0x5, 0x3, 0x1
Oct 17 08:37:21 (none) TvDbUtil[151]: LogRecordings3: 487763, 663552, 902, 5885, 0x5, 0x3, 0x1
Oct 17 08:37:21 (none) TvDbUtil[151]: LogRecordings3: 514274, 884736, 1202, 5888, 0x5, 0x3, 0x1
Oct 17 08:37:21 (none) TvDbUtil[151]: LogRecordings3: 561918, 884736, 1200, 5898, 0x5, 0x3, 0x1
Oct 17 08:37:21 (none) TvDbUtil[151]: LogRecordings3: 561919, 884736, 1202, 5888, 0x5, 0x3, 0x1
Oct 17 08:37:21 (none) TvDbUtil[151]: LogRecordings3: 557126, 3695616, 5024, 5884, 0x5, 0x8, 0x1
Oct 17 08:37:21 (none) TvDbUtil[151]: LogRecordings3: 573161, 663552, 902, 5885, 0x5, 0x3, 0x1
Oct 17 08:37:21 (none) TvDbUtil[151]: LogRecordings3: 585333, 664576, 902, 5894, 0x5, 0x3, 0x1
Oct 17 08:37:21 (none) TvDbUtil[151]: LogRecordings3: 739034, 2207744, 3002, 5883, 0x5, 0x9, 0x1
Oct 17 08:37:21 (none) TvDbUtil[151]: LogRecordings3: 750544, 2207744, 3002, 5883, 0x5, 0x9, 0x1
Oct 17 08:37:21 (none) TvDbUtil[151]: LogRecordings3: 750545, 884736, 1202, 5888, 0x5, 0x9, 0x1
Oct 17 08:37:21 (none) TvDbUtil[151]: LogRecordings3: 750546, 884736, 1202, 5888, 0x5, 0x9, 0x1
Oct 17 08:37:21 (none) TvDbUtil[151]: LogRecordings3: 762923, 2207744, 3002, 5883, 0x5, 0x9, 0x1
Oct 17 08:37:21 (none) TvDbUtil[151]: LogRecordings3: 745075, 2648064, 3602, 5881, 0x5, 0x9, 0x1
Oct 17 08:37:21 (none) TvDbUtil[151]: LogRecordings3: 767402, 2547712, 3455, 5899, 0x5, 0x8, 0x1
Oct 17 08:37:21 (none) TvDbUtil[151]: LogRecordings3: 776996, 196608, 263, 5980, 0x5, 0xb, 0x1
Oct 17 08:37:21 (none) TvDbUtil[151]: LogRecordings3: 778758, 577536, 776, 5953, 0x5, 0x8, 0x1
Oct 17 08:37:21 (none) TvDbUtil[151]: LogRecordings3: End
Oct 17 08:37:21 (none) Scheduler[151]: Mempool highwater 68
Oct 17 08:37:21 (none) Scheduler[151]: DataChangedROGRAM_GUIDE
Oct 17 08:37:21 (none) Scheduler[151]: Abr-- reason changed from 'None' to 'GuideSetup'
Oct 17 08:37:21 (none) Scheduler[151]: Abr-- DataChanged:0x00090009
Oct 17 08:37:53 (none) Scheduler[151]: Mempool highwater 68
Oct 17 08:37:53 (none) Scheduler[151]: DataChangedROGRAM_GUIDE
Oct 17 08:37:53 (none) Scheduler[151]: Abr-- DataChanged:0x00090009

 

[Cainam]

Is that the end of the tvlog?

Can you put in the TClient one as well?

 

[TeaVoChimp]

nope its huge....

here, I've uploaded them so they are easier to get

TVLOG.rtf

TCCLIENT.rtf <spelt wrong, sorry

cheers ears

 

[Cainam]

So it looks like the problem is here...

10/17:05:32:55: /tvbin/TClient: About to connect to 204.176.49.3:80
10/17:05:32:55: /tvbin/TClient: Executing HTTP command: /tvbin/http_post /var/log/svclog http://204.176.49.3:80/tivo-service/mlog.cgi OFF OFF ON
10/17:05:32:56: /tvbin/TClient: about to do HServer Call
10/17:05:32:56: /tvbin/TClient: Executing HTTP command: /tvbin/tclient_post 204.176.49.3:80 /var/tmp/HServer.send /var/tmp/HServer.recv 300 ON
10/17:05:37:56: /tvbin/TClient: http POST command failed: timeout waiting to read
10/17:05:37:56: /tvbin/TClient: doHttpCall returned: 0
10/17:05:37:56: /tvbin/TClient: Connect/POST has failed, we've warned the user, set status to Failed

Can you try pinging that address (204.176.49.3), and see what you get?

 

[Cainam]

Digging around here a bit, this looks an identical problem to the one here

But there seems to be no obvious reply to that one...

Out of interest
1) Is the phone cable still plugged in the back?
2) What do you have plugged into the Scart sockets on the back, a sky box or anything? Can you try unplugging all the scart stuff and trying again?

I am sure I read somewhere that someone could not get their cachecard working and it was due to a problem with what was connected via scart...

If you have nothing plugged in such as a freeview box, can you try plugging something in a turning it on? I cannot remember now which way round the problem was!

 

[TeaVoChimp]

pings fine...10 sent, 10 received
:up:

...and I've found plenty similar, just no solutions
Read that one....didnt have a solution, his just came back to life!

No phone line attached (as it was presumed modem dead/unable to make calls)

SKY and the TV (and do you really think unplugging those will help the LAN connection?)

Digging around here a bit, this looks an identical problem to the one here

But there seems to be no obvious reply to that one...

Out of interest
1) Is the phone cable still plugged in the back?
2) What do you have plugged into the Scart sockets on the back, a sky box or anything? Can you try unplugging all the scart stuff and trying again?

I am sure I read somewhere that someone could not get their cachecard working and it was due to a problem with what was connected via scart...

If you have nothing plugged in such as a freeview box, can you try plugging something in a turning it on? I cannot remember now which way round the problem was!

 

[Cainam]

I edited my post above with some more comments you may have missed!

 

[TeaVoChimp]

I edited my post above with some more comments you may have missed!

hahah me too!

really appreciate your help