Failed. Service unavailable when attempting test daily call please help!

[goldendel]

Hello,

I have a Tivo S1 in NSW. I've recently rebuilt it with the latest image after I was unable to communicate with it to get daily updates (no serial cable, one is on the way now). After rebuilding I directly connected to my router (I was using a Netgear WGE111 wireless game adaptor to connect to my Turbonet card). I had no problem with the intial daily call when connected to the router. I then moved the tivo and my TV back into my lounge so my family could watch it whilst I waited for a replacement for the Netgear WGE111 to arrive (I've bought an Netgear HDX101 to connect ethernet over power). This is working well, but I'm unable to do daily calls, even when I connect directly to the router. Can someone please help me diagnose what is wrong?

Attached are the last few hundred lines of my tclient.conf (I think this is the right file for diagnosis, but I'm not sure how much is needed). The TiVo is currently set on DHCP with an IP of 192.168.0.4 and the router is 192.168.0.1.

Many thanks in advance for your help.

Tim

[petestrash]

This is where your problem is:
Feb 19 21:36:35 (none) comm[163]: Uploading HTTP Header for modLog of /var/log/svclog: POST /tivo-service/mlog.cgi HTTP/1.0^M Content-Length: 14234^M ^M
Feb 19 21:39:32 (none) comm[163]: XferRqst timeout waiting to read

So to clarify, even if you move it back directly to the router it now still does not work?

Also run though these (http://www.oztivo.net/twiki/bin/view/Network/NetworkingHowto#Configuration_and_Diagnostics) tests and let us know what you get.

Peter.

[goldendel]

Hi Peter,

Thank you for your response. I can confirm I have the Tivo connected via LAN cable to my router (Netcomm NB12WD) and I've just received the same message when performing a test daily update:

"Feb 20 19:06:02 (none) comm[172]: XferRqst timeout waiting to read"

Here are the results of the tests: I hope they prove useful!


[TiVo [p0] ~]# ifconfig
lo Link encap:Local Loopback
inet addr:127.0.0.1 Bcast:127.255.255.255 Mask:255.0.0.0
UP BROADCAST LOOPBACK RUNNING MTU:3584 Metric:1
RX packets:22 errors:0 dropped:0 overruns:0 frame:0
TX packets:22 errors:0 dropped:0 overruns:0 carrier:0 coll:0

eth0 Link encap:Ethernet HWaddr 00:0B:AD:84:78:90
inet addr:192.168.0.4 Bcast:192.168.0.255 Mask:255.255.255.0
UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1
RX packets:1381 errors:0 dropped:0 overruns:0 frame:0
TX packets:1808 errors:0 dropped:0 overruns:0 carrier:0 coll:0
Interrupt:29

[TiVo [p0] ~]#
[TiVo [p0] ~]# route
route_info, afname=inet, options=33
Kernel IP routing table
Destination Gateway Genmask Flags Metric Ref Use Iface
192.168.0.0 * 255.255.255.0 U 0 0 0 eth0
default 192.168.0.1 0.0.0.0 UG 0 0 0 eth0
[TiVo [p0] ~]#
[TiVo [p0] ~]# ping -c 5 192.168.0.1
PING 192.168.0.1 (192.168.0.1): 56 data bytes
64 bytes from 192.168.0.1: icmp_seq=0 ttl=64 time=2.7 ms
64 bytes from 192.168.0.1: icmp_seq=1 ttl=64 time=1.1 ms
64 bytes from 192.168.0.1: icmp_seq=2 ttl=64 time=1.0 ms
64 bytes from 192.168.0.1: icmp_seq=3 ttl=64 time=1.0 ms
64 bytes from 192.168.0.1: icmp_seq=4 ttl=64 time=1.1 ms

--- 192.168.0.1 ping statistics ---
5 packets transmitted, 5 packets received, 0% packet loss
round-trip min/avg/max = 1.0/1.3/2.7 ms
[TiVo [p0] ~]#
[TiVo [p0] ~]# ping -c 5 65.49.60.197
PING 65.49.60.197 (65.49.60.197): 56 data bytes
64 bytes from 65.49.60.197: icmp_seq=0 ttl=51 time=192.8 ms
64 bytes from 65.49.60.197: icmp_seq=1 ttl=51 time=190.8 ms
64 bytes from 65.49.60.197: icmp_seq=2 ttl=51 time=190.7 ms
64 bytes from 65.49.60.197: icmp_seq=3 ttl=51 time=190.7 ms
64 bytes from 65.49.60.197: icmp_seq=4 ttl=51 time=193.0 ms

--- 65.49.60.197 ping statistics ---
5 packets transmitted, 5 packets received, 0% packet loss
round-trip min/avg/max = 190.7/191.6/193.0 ms
[TiVo [p0] ~]#
[TiVo [p0] ~]# wget http://65.49.60.197/index.html
--19:14:11-- http://65.49.60.197/index.html
=> `index.html'
Connecting to 65.49.60.197:80... connected.
HTTP request sent, awaiting response... 301 Moved Permanently
Location: http://www.oztivo.net/twiki/bin/view [following]
--19:14:11-- http://www.oztivo.net/twiki/bin/view
=> `view.1'
Resolving www.oztivo.net... done.
Connecting to www.oztivo.net[65.49.60.197]:80... connected.
HTTP request sent, awaiting response... 200 OK
Length: 21,528 [text/html]

0% [ ] 21,528 0.00G/s ETA 00:00

19:14:13 (0.00 GB/s) - `view.1' saved [21528/21528]

[TiVo [p0] ~]#
[TiVo [p0] ~]# dbget /State/PhoneConfig DialPrefix
,#401
[TiVo [p0] ~]#
[TiVo [p0] ~]#

Tim

[petestrash]

Ok, well the good news is, that it does appear to be connecting to the network.

Have you made any changes to the /etc/oztivo.conf file?

Can you please list it's contents.

Peter

[goldendel]

No...I think that was how I lost comms before the last rebuild though! Here are the contents:


OzTiVo menu configuration settings file
# Please do not edit this file
# Run the nic_config_tivo tool to reconfigure
nic=TurboNet
ip=DHCP
mac=00:0B:AD:84:78:90
timing=16
hostname=TiVo
emulator=www.oztivo.net
emulatorport=80
netmask=
gateway=
ssid=
wep=
wepkey=

Tim

[petestrash]

From your previous post it appears you ISP is running your service through a proxy.

To fix this, please change the line emulatorport=80 to emulatorport=9090 in /etc/oztivo.conf

Then reboot and try a call.

Peter.

[goldendel]

I had checked with the guidelines to see if I was using a proxy, and it appeared I was not. However, after making the change and rebooting, I was able to make a successful call. My ISP is Exetel (not listed in the known ISPs using a proxy).

When I try to do a normal call via TivoWebPlus, it's been stuck on "Preparing to call" for over 30mins. How long should this stage take?

Tim

[petestrash]

Please add Exetel to the list of proxied ISP's.

Chances are the TiVo is/was still busy processing the data from the last call. There is not much spare processing power in a TiVo.

If it has not finished by now, just reboot. then leave it alone for an hour to do it's housekeeping, then try again.

Peter.

[goldendel]

I rebooted and successfully got an update using trickey.

I've added Exetel to the list.

Thanks for your help resolving this Peter

[petestrash]

Your welcome.

Peter

[goldendel]

Hi Peter,

I've been getting "Failed. Service unavailable" again for the past few days.

Attached are the networking howto test results, listing of my oztivo.conf and my tclient.log

My Tivo is directly connected to a Netcomm NB12WD via a Netgear ethernet over power adapter. Can you check if there is anything obvious I am doing wrong?

Many thanks in advance for your help,

Tim

[petestrash]

Your networking and settings seem to fine.

Looking at the log it appears you may have some data corruption on your disk.

How old is the Drive you are using, and have you noticed any Audio or Video Glitches during playback?

Peter.

[goldendel]

Hi Peter,

I bought the disk on 5/08/2006 according to my records. I haven't seen any audio\video glitches so far. I think the disk is 34% full. I can delete some stuff, would that help?

Many thanks,

Tim

[petestrash]

Deleting shows should not make any difference.

We can try and have the TiVo fix any database and file system issues. If it does not work, re-imaging may be the only alternative.

Also running the commands may stop your TiVo from working if there is a lot of corruption, which means that you will have no choice but to re-image. This only happens in a small number of cases, but it can happen.

So I suggest you watch or transfer your important shows first.

There are 2 area to check. These commands first try to fix the internal database.

[TiVo [p0] ~]# chmod 777 /var/tmp//fsmem.mpkey
[TiVo [p0] ~]# rm /var/tmp//fsmem.mpkey
[TiVo [p0] ~]# mfscheck -fix

This can take many hours to complete.

Let me know the results if any, then we will move to the filesystem check.

Peter.

[goldendel]

It took a while to backup shows\settings. I ran the commands, but the scan failed, so I re-ran it with only 1 trailing slash and got the following:


[TiVo [p1] /var/tmp]# chmod 777 /var/tmp/fsmem.mpkey
[TiVo [p1] /var/tmp]#
[TiVo [p1] /var/tmp]# rm /var/tmp/fsmem.mpkey
[TiVo [p1] /var/tmp]#
[TiVo [p1] /var/tmp]# mfscheck -fix
mfscheck scan begins
Checking reference counts
All reference counts are OK.
mfscheck scan ends
mfscheck: 0 fatal errors, 0 severe errors, 0 warnings.

You must manually restart the EventSwitcher
[TiVo [p1] /var/tmp]#

It ran in under a couple of minutes.

Tim

[petestrash]

Ok, reboot the TiVo and now try

[TiVo [p0] ~]# fsfix

Peter.

[goldendel]

Hi Peter,

I ran fsfix twice (1st time my PC crashed due to an unrelated event, taking the telnet with it). Here is the output:

fsfix
fsfix: mounted MFS volume, starting consistency checks.
I-Nodes:
I-Node table size is 131072 entries for 102400 active nodes max.
FsId high-water mark is 0xf8ba
Pass 1 - scan and analyze
reconstructing zone buddymaps
synchronizing...
volume marked as OK
scanned 8272 files, covering 3163 extents
29072 application pages in use
599031808 media pages in use
Inode table collision details
0 hash collisions in node table.
Allocation Details
6224/7575 application inline files, 82.16%
25.50% wasted space (0 bytes) in normal application region
48.7% wasted space (0 bytes) in inlined application region
697 media files
1.54% wasted space (0 bytes) in media region
Fragmentation:
average extents/file is 0.38
worst extents/file is 9
expected extents/file (approx) is 3
Application region:
zone contains 785168 pages: 29072 allocated; 756096 free
inode allocations match allocated page count
buddy-map is internally consistent, 756096 pages marked free
Media region:
zone contains 2097152 pages: 2064384 allocated; 32768 free
inode allocations match allocated page count
buddy-map is internally consistent, 32768 pages marked free
zone contains 620625920 pages: 596967424 allocated; 23658496 free
inode allocations match allocated page count
buddy-map is internally consistent, 23658496 pages marked free
fsfix: 0 fatal errors, 0 warnings.

I'm not sure if it is related, but if I try to start ms_ftp, I get the error:

[TiVo [p2] ~]# /hack/mfs_ftp/mfs_ftp.tcl
No EventSwitcher active
while executing
"dbopen"
(file "/hack/mfs_ftp/mfs_ftp.tcl" line 1531)

Tim

[goldendel]

Hi Peter,

I noticed the Tivo was frozen, and realised it did not get a reboot after the mfscheck. I rebooted, re-ran mfs check:

[TiVo [p0] ~]# chmod 777 /var/tmp//fsmem.mpkey
[TiVo [p0] ~]#
[TiVo [p0] ~]# rm /var/tmp//fsmem.mpkey
[TiVo [p0] ~]#
[TiVo [p0] ~]# mfscheck -fix
mfscheck scan begins
Checking reference counts
All reference counts are OK.
mfscheck scan ends
mfscheck: 0 fatal errors, 0 severe errors, 0 warnings.

You must manually restart the EventSwitcher

The Tivo again froze, so I rebooted it and ran fsfix:

[TiVo [p0] ~]# fsfix
Couldn't CreateSharedMemoryFile() /var/tmp//fsmem.mpkey -- check permissions
Error in FsInit: 0x11001
[TiVo [p0] ~]#
[TiVo [p0] ~]# chmod 777 /var/tmp//fsmem.mpkey
[TiVo [p0] ~]#
[TiVo [p0] ~]# rm /var/tmp//fsmem.mpkey
[TiVo [p0] ~]#
[TiVo [p0] ~]# fsfix
fsfix: mounted MFS volume, starting consistency checks.
I-Nodes:
I-Node table size is 131072 entries for 102400 active nodes max.
FsId high-water mark is 0xf8f2
Pass 1 - scan and analyze
reconstructing zone buddymaps
synchronizing...
volume marked as OK
scanned 8060 files, covering 3116 extents
28944 application pages in use
596475904 media pages in use
Inode table collision details
0 hash collisions in node table.
Allocation Details
6033/7369 application inline files, 81.86%
25.32% wasted space (0 bytes) in normal application region
48.25% wasted space (0 bytes) in inlined application region
691 media files
1.12% wasted space (0 bytes) in media region
Fragmentation:
average extents/file is 0.38
worst extents/file is 9
expected extents/file (approx) is 3
Application region:
zone contains 785168 pages: 28944 allocated; 756224 free
inode allocations match allocated page count
buddy-map is internally consistent, 756224 pages marked free
Media region:
zone contains 2097152 pages: 2064384 allocated; 32768 free
inode allocations match allocated page count
buddy-map is internally consistent, 32768 pages marked free
zone contains 620625920 pages: 594411520 allocated; 26214400 free
inode allocations match allocated page count
buddy-map is internally consistent, 26214400 pages marked free
fsfix: 0 fatal errors, 0 warnings.

I hope this helps. By the way, after another reboot I can now start ms_ftp.

Tim

[Darren King]

If it was me I would now be pulling the drive and checking it on a PC with Seatools (available from www.seagate.com under "support" then "downloads") running the full drive scan.


I bought the disk on 5/08/2006 according to my records.
That's almost three years. In a TiVo that gets constant use I usually expect to see problems after 18-24 months.

[petestrash]

Both of these processes kill the event switcher and require a reboot to get the system running again.

But they did not find anything wrong in the structure.

If you have a spare drive I would suggested loading the latest image onto it and see if the problem goes away.

Peter.

[goldendel]

Thanks Fellas.

Unfortunately I don't have a spare drive. I'll download seatools and run it against the drive then re-image it depending on what it finds. This may take a while (I'd do it this weekend, but it's my son's 1st birthday). I'll let you know how I get on.

Thanks again for your help.

Tim

[goldendel]

Hi Peter\Darren,

A quick update on this issue. The Tivo powered off a couple of days after. I pulled the plug, left it for a few minutes and turned it back on. It powered up and has been getting guide data ever since. NOt sure what the issue was, but I'm happy to provide the logs if you're intregued and care to tell me which logs you need.

Many thanks for all your help.

Tim

PS Is there a recommended way to turn off the TiVo safely to avoid disk corruption?

[petestrash]

You won't get any corruption by pulling the plug under any normal circumstances.

The only time you might cause corruption is if you were manually doing something using telnet and left the drive in read/write when it rebooted.

Peter.