Newbie first try – success!

**Phred** · 25-01-2007, 06:03 PM

Originally Posted by petestrash

You are very special.

Something is very wrong, the directory /etc/rc.d has to exist.

Ahhh, ok. In your first post you said rd.d not rc.d and being LinNix illiterate :-) I wouldn't know the difference! So I blindly followed orders (good excuse huh..). So undid all that rd.d junk and put sysinit.local where it was supposed to be - that's the good news. Bad news - same problem and same tivoweb.log contents (without the line "retrying after errTmActiveLockConflict ...").

I'm happy to keep trying to figure out what the problem is and to keep trying all manner of things, don't get me wrong, however, I'm quite happy to telnet and start TWP when I need it.

Any other logs I can send you, or debug type stuff I can gather? Thanks for your time Peter.

Cheers,
Phred

**petestrash** · 26-01-2007, 01:32 AM

rd.d Typo, my bad. I've corrected it now in case someone else follows this thread.

can you clear the tivoweb log using the clear button on TWP.

Then reboot the tivo and repost the new tivoweb log.

Peter.

**Phred** · 26-01-2007, 11:51 AM

Originally Posted by petestrash

can you clear the tivoweb log using the clear button on TWP.
Then reboot the tivo and repost the new tivoweb log.
Peter.

Ok, here ya go:

telnet

--Contents of /var/log/tivoweb.log--
Log cleared on Fri Jan 26, 2007 by TivoWebPlus

--Contents of /var/log/Otivoweb.log--
Log cleared on Fri Jan 26, 2007 by TivoWebPlus

--ls of /etc/rc.d--

[TiVo [p0] /etc/rc.d]# ls
finishInstall.tcl rc.net.cachecard rc.sysinit
rc.arch rc.net.cachecard.static rc.sysinit.author
rc.arch.original rc.net.tivonet rc.sysinit.local
rc.net rc.net.turbonet rc.sysinit.noservices
rc.net.airnet rc.net.turbonet.static rc.sysinit.orig
rc.net.airnet.static rc.ppp

--contents of rc.sysinit.local--

#start TWP
/hack/TivoWebPlus/tivoweb &

--reboot--

-- contents of /var/log/tivoweb.log after reboot--

TivoWebPlus - v1.3.1 (1.3.1 (oztivo-070111))
The program comes with ABSOLUTELY NO WARRANTY.
This program is licensed under the GPL.
See the 'docs/copyright' and 'docs/index.html' files
for copyright and credit information.
PoolSize=2916352
retrying after errTmActiveLockConflict ...
child process exited abnormally
while executing
"exec ifconfig | grep "inet addr" | grep -v "127.0.0.1""
(file "/hack/TivoWebPlus/httpd-tt.tcl" line 997)

--Contents of /var/log/Otivoweb.log--
Log cleared on Fri Jan 26, 2007 by TivoWebPlus

Cheers,
Phred

**petestrash** · 26-01-2007, 12:22 PM

Ok, are you using DHCP to get an IP address?

Peter.

**Phred** · 26-01-2007, 01:39 PM

Originally Posted by petestrash

Ok, are you using DHCP to get an IP address?
Peter.

Good question. I'm using serial ppp via an XP box. I specified the address range (two ip addresses) when I built the direct connect network connection - not sure if via the XP direct connection serial ppp setup if that means dhcp. Somehow Tivo ends up with the two ip address I specified.

On that subject I noticed something sorta strange in the early part of kernel.log (before date and time get set):

Jan 1 00:00:21 (none) kernel: setting ipaddr to 192.168.1.84
Jan 1 00:00:21 (none) kernel: setting macaddr to 0004ace30054
Jan 1 00:00:21 (none) kernel: SIOCSIFHWADDR: Operation not supported by device
Jan 1 00:00:21 (none) kernel: SIOCSIFADDR: Operation not supported by device
Jan 1 00:00:21 (none) kernel: eth0: unknown interface.
Jan 1 00:00:21 (none) kernel: Configuring network...
Jan 1 00:00:21 (none) kernel: Starting PPP over serial
Jan 1 00:00:21 (none) kernel: Enabling local route...
Jan 1 00:00:21 (none) kernel: Setting TCP keepalive parameters...
Jan 1 00:00:21 (none) kernel: Starting logging daemons...
Jan 1 00:00:21 (none) kernel: Check for PROM update ...
Jan 1 00:00:21 (none) kernel: Updating system clock UID=0
Jan 1 00:00:21 (none) kernel: registered device ppp0
Jan 1 00:00:21 (none) kernel: About to check tasks for tty to shutdown
Jan 26 11:45:02 (none) kernel: Time set to: Fri Jan 26 11:45:02 2007
Jan 26 11:45:02 (none) kernel: Have a nice day.

The ip address set (192.168.1.84) isn't either of the two specified in the serial ppp XP config. Not sure where .84 is coming from. Note, however, that later in the log the correct address (.97 and .98) are there:

Jan 26 11:45:35 (none) kernel: ppp_tty_ioctl: set xasyncmap
Jan 26 11:45:35 (none) kernel: ppp_tty_ioctl: set xmit asyncmap 0
Jan 26 11:45:35 (none) kernel: ppp_tty_ioctl: set flags to f010003
Jan 26 11:45:35 (none) kernel: ppp_tty_ioctl: set mru to 5dc
Jan 26 11:45:35 (none) kernel: ppp_tty_ioctl: set rcv asyncmap 0
Jan 26 11:45:35 (none) kernel: sent [LCP EchoReq id=0x0 magic=0xffff31c9]
Jan 26 11:45:35 (none) kernel: sent [IPCP ConfReq id=0x2 <addr 0.0.0.0> <compress VJ 0f 01>]
Jan 26 11:45:35 (none) kernel: ppp_tty_ioctl: set flags to f010043
Jan 26 11:45:35 (none) kernel: rcvd [CCP ConfReq id=0x2 < 12 06 00 00 00 01>]
Jan 26 11:45:35 (none) kernel: sent [CCP ConfReq id=0x1]
Jan 26 11:45:35 (none) kernel: sent [CCP ConfRej id=0x2 < 12 06 00 00 00 01>]
Jan 26 11:45:35 (none) kernel: rcvd [IPCP ConfReq id=0x3 <compress VJ 0f 01> <addr 192.168.1.97>]
Jan 26 11:45:35 (none) kernel: sent [IPCP ConfAck id=0x3 <compress VJ 0f 01> <addr 192.168.1.97>]
Jan 26 11:45:35 (none) kernel: rcvd [LCP EchoRep id=0x0 magic=0x7f95192a]
Jan 26 11:45:35 (none) kernel: rcvd [IPCP ConfNak id=0x2 <addr 192.168.1.98>]
Jan 26 11:45:35 (none) kernel: sent [IPCP ConfReq id=0x3 <addr 192.168.1.98> <compress VJ 0f 01>]
Jan 26 11:45:35 (none) kernel: rcvd [CCP ConfAck id=0x1]
Jan 26 11:45:35 (none) kernel: rcvd [CCP TermReq id=0x4 7f 95 19 2a 00 3c cd 74 00 00 02 dc]
Jan 26 11:45:35 (none) kernel: sent [CCP TermAck id=0x4]
Jan 26 11:45:35 (none) kernel: rcvd [IPCP ConfAck id=0x3 <addr 192.168.1.98> <compress VJ 0f 01>]
Jan 26 11:45:35 (none) kernel: ppp_tty_ioctl: set maxcid to 16
Jan 26 11:45:35 (none) kernel: ppp_tty_ioctl: set flags to f010047
Jan 26 11:45:35 (none) kernel: ppp: channel ppp0 going up for IP packets!
Jan 26 11:45:35 (none) kernel: local IP address 192.168.1.98
Jan 26 11:45:35 (none) kernel: remote IP address 192.168.1.97

One other thing I noticed in the kernel.log

Jan 26 11:45:24 (none) kernel: /etc/rc.d/rc.sysinit: /etc/rc.d/rc.sysinit.local: Permission denied
Jan 26 11:45:24 (none) kernel: rc.sysinit is complete

Cheers,
Phred

**petestrash** · 26-01-2007, 03:23 PM

Originally Posted by Phred

The ip address set (192.168.1.84) isn't either of the two specified in the serial ppp XP config. Not sure where .84 is coming from.

This is a red herring, the .84 address is set for emergency use by TiVo if no other address is specified. Also the error messages after it are normal.

Originally Posted by Phred

Note, however, that later in the log the correct address (.97 and .98) are there:
Jan 26 11:45:35 (none) kernel: ppp: channel ppp0 going up for IP packets!
Jan 26 11:45:35 (none) kernel: local IP address 192.168.1.98
Jan 26 11:45:35 (none) kernel: remote IP address 192.168.1.97

You do not use DHCP, You have a fixed IP address. But it is being set quite late which appears to be the cause of your problems.

Originally Posted by Phred

One other thing I noticed in the kernel.log

Jan 26 11:45:24 (none) kernel: /etc/rc.d/rc.sysinit: /etc/rc.d/rc.sysinit.local: Permission denied
Jan 26 11:45:24 (none) kernel: rc.sysinit is complete

Ok, we are getting somewhere, this explains why the tivoweb log didn't show 2 attempts at starting up.

Try this:
chmod +x /etc/rc.d/rc.sysinit.local

Then reboot.

If it still didn't work, add a line 'sleep 500' to the start of your rc.sysinit.local file.

Hopefully that should be it.

Peter.

**Phred** · 26-01-2007, 04:57 PM

Originally Posted by petestrash

Try this:
chmod +x /etc/rc.d/rc.sysinit.local

If it still didn't work, add a line 'sleep 500' to the start of your rc.sysinit.local file.
Peter.

Hi Peter,

The chmod fixed the permission denied. Even with the sleep still didn't work. So my rc.sysintit.local now looks like this:

#start TWP
echo "Local - start sleep"
sleep 50
echo "Local - stop sleep"
/hack/TivoWebPlus/tivoweb &

Note the sleep 50 - 500 was too long and wasn't getting to the second echo (stop sleep). Now kernel log looks like this:

Jan 26 16:36:22 (none) kernel: ppp: channel ppp0 going up for IP packets!
Jan 26 16:36:22 (none) kernel: local IP address 192.168.1.98
Jan 26 16:36:22 (none) kernel: remote IP address 192.168.1.97
Jan 26 16:36:25 (none) kernel: sent [CCP ConfReq id=0x1]
Jan 26 16:36:25 (none) kernel: rcvd [CCP TermAck id=0x1]
Jan 26 16:36:25 (none) kernel: ppp_tty_ioctl: set flags to f010007
Jan 26 16:36:25 (none) kernel: sent [CCP TermReq id=0x2"No compression negotiated"]
Jan 26 16:36:25 (none) kernel: rcvd [CCP TermAck id=0x2"No compression negotiated"]
Jan 26 16:36:32 (none) kernel: sent [LCP EchoReq id=0x1 magic=0xffff4301]
Jan 26 16:36:32 (none) kernel: rcvd [LCP EchoRep id=0x1 magic=0x58092cd9]
Jan 26 16:36:42 (none) kernel: sent [LCP EchoReq id=0x2 magic=0xffff4301]
Jan 26 16:36:42 (none) kernel: rcvd [LCP EchoRep id=0x2 magic=0x58092cd9]
Jan 26 16:36:44 (none) kernel: 01/26:16:36:44: /hack/bin/sendtivomesg.tcl: Creating IP Addresses Message...
Jan 26 16:36:44 (none) kernel: 01/26:16:36:44: /hack/bin/sendtivomesg.tcl: Calling event send 23 DATA_MESSAGES 0
Jan 26 16:36:52 (none) kernel: sent [LCP EchoReq id=0x3 magic=0xffff4301]
Jan 26 16:36:52 (none) kernel: rcvd [LCP EchoRep id=0x3 magic=0x58092cd9]
Jan 26 16:36:59 (none) kernel: Local - stop sleep
Jan 26 16:36:59 (none) kernel: rc.sysinit is complete
Jan 26 16:37:00 (none) kernel: Warning: The last few sessions did not complete successfully
Jan 26 16:37:00 (none) kernel: We may be in a reboot loop... aborting

You can see that the second echo is well after the serial ppp ips are assigned. Seeing the "Warning: The last few sessions did not complete - We may be in a reboot loop - aborting" I double checked that I did the :

echo 0 > /hack/TivoWebPlus/.dist/CrashCount

correctly. And CrashCount was/is getting set to 0 and after the crash is 1. Is the "reboot loop" message to do with CrashCount or something else? Maybe I should try a bit longer sleep - maybe 100?

Cheers,
Phred

**petestrash** · 27-01-2007, 03:05 AM

Ok, now I suggest you stop the first try of loading TWP, leaving only the start from rc.sysinit.local. This should then avoid the crashcount issue.

[TiVo [p0] ~]# echo 0 > /hack/TivoWebPlus/.dist/CrashCount
[TiVo [p0] ~]# cd /etc
[TiVo [p0] /etc]# rw
File system is now READ/WRITE.
[TiVo [p0] /etc]# cp dflt_sysinit.conf sysinit.conf

Now edit the line in sysinit.conf which reads:
tivoweb_enable="YES" # Start TivoWeb or TivoWebPlus:

And replace the YES with NO
tivoweb_enable="NO" # Start TivoWeb or TivoWebPlus:

Save the file, then:

[TiVo [p0] /etc]# ro
File system is now READ ONLY.
[TiVo [p0] /etc]#

Cross your fingers and reboot.

Peter.

**Phred** · 27-01-2007, 12:21 PM

Originally Posted by petestrash

Ok, now I suggest you stop the first try of loading TWP, leaving only the start from rc.sysinit.local. This should then avoid the crashcount issue.

Cross your fingers and reboot.

Peter.

Hi Peter,

Yes! Seems like making the dflt_sysinit change is necessary. Thank you! I had sleep set at 50, so thought maybe I could get by without any sleep - nope. Turns out that sleep 4 doesn't work

tivoweb.log at sleep 4

TivoWebPlus - v1.3.1 (1.3.1 (oztivo-070111))
The program comes with ABSOLUTELY NO WARRANTY.
This program is licensed under the GPL.
See the 'docs/copyright' and 'docs/index.html' files
for copyright and credit information.
PoolSize=2916352
child process exited abnormally
while executing
"exec ifconfig | grep "inet addr" | grep -v "127.0.0.1""
(file "/hack/TivoWebPlus/httpd-tt.tcl" line 997)

where sleep 5 does work. My rc.sysinit.local now looks like this (7 just to give a bit of buffer):

echo "**Local rc.sysinit.local - start"
echo "**Local - begin sleep 7"
sleep 7
echo "**Local - end sleep 7"
#start TWP
echo "**Local - starting TWP"
/hack/TivoWebPlus/tivoweb &
echo "**Local rc.sysinit.local - end"

Sleep 4 kernel.log - doesn't work

Jan 27 11:44:57 (none) kernel: /dev/hdb: Device not configured
Jan 27 11:44:57 (none) kernel:
Jan 27 11:44:57 (none) kernel: /dev/hda:
Jan 27 11:44:57 (none) kernel: setting multcount to 16
Jan 27 11:44:57 (none) kernel: multcount = 16 (on)
Jan 27 11:44:57 (none) kernel: /dev/hdb: Device not configured
Jan 27 11:44:57 (none) kernel: **Local rc.sysinit.local - start
Jan 27 11:44:57 (none) kernel: **Local - begin sleep 4
Jan 27 11:44:57 (none) kernel: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <compress VJ 0f 01>]
Jan 27 11:44:57 (none) kernel: No response to 2 echo-requests
Jan 27 11:44:57 (none) kernel: Serial link appears to be disconnected.
Jan 27 11:44:57 (none) kernel: ppp_tty_ioctl: set flags to f010003
Jan 27 11:44:57 (none) kernel: ppp_tty_ioctl: set xasyncmap
Jan 27 11:44:57 (none) kernel: ppp_tty_ioctl: set xmit asyncmap ffffffff
Jan 27 11:44:57 (none) kernel: ppp_tty_ioctl: set flags to f010000
Jan 27 11:44:57 (none) kernel: ppp_tty_ioctl: set mru to 5dc
Jan 27 11:44:57 (none) kernel: ppp_tty_ioctl: set rcv asyncmap 0
Jan 27 11:44:57 (none) kernel: sent [LCP TermReq id=0x2 "Peer not responding"]
Jan 27 11:44:57 (none) kernel: rcvd [LCP TermAck id=0x2 "Peer not responding"]
Jan 27 11:44:57 (none) kernel: Connection terminated.
Jan 27 11:44:57 (none) kernel: ppp_tty_ioctl: invalid ioctl: 2000741f, addr 2
Jan 27 11:44:57 (none) kernel: tcflush failed: Invalid argument
Jan 27 11:44:57 (none) kernel: ppp: channel ppp0 closing.
Jan 27 11:45:01 (none) kernel: Initialize with 1 live caches
Jan 27 11:45:01 (none) kernel: mediaswitch: resetting adjustments
Jan 27 11:45:01 (none) kernel: **Local - end sleep 4
Jan 27 11:45:01 (none) kernel: **Local - starting TWP
Jan 27 11:45:01 (none) kernel: **Local rc.sysinit.local - end
Jan 27 11:45:01 (none) kernel: rc.sysinit is complete
Jan 27 11:45:01 (none) kernel: Microcode version 00034
Jan 27 11:45:01 (none) kernel: osd buffer size = 1080000
Jan 27 11:45:01 (none) kernel: Bus services started.
Jan 27 11:45:01 (none) kernel: Couldn't restrict write permissions to /dev/ttyS3: Read-only file system
Jan 27 11:45:01 (none) kernel: ppp_tty_ioctl: set flags to 10000
Jan 27 11:45:01 (none) kernel: ppp_tty_ioctl: set flags to 10000
Jan 27 11:45:01 (none) kernel: Using interface ppp0

Sleep 5 kernel.log - does work

Jan 27 11:50:13 (none) kernel: /dev/hda:
Jan 27 11:50:13 (none) kernel: setting multcount to 16
Jan 27 11:50:13 (none) kernel: multcount = 16 (on)
Jan 27 11:50:13 (none) kernel: /dev/hdb: Device not configured
Jan 27 11:50:13 (none) kernel: **Local rc.sysinit.local - start
Jan 27 11:50:13 (none) kernel: **Local - begin sleep 5
Jan 27 11:50:14 (none) kernel: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <compress VJ 0f 01>]
Jan 27 11:50:14 (none) kernel: No response to 2 echo-requests
Jan 27 11:50:14 (none) kernel: Serial link appears to be disconnected.
Jan 27 11:50:14 (none) kernel: ppp_tty_ioctl: set flags to f010003
Jan 27 11:50:14 (none) kernel: ppp_tty_ioctl: set xasyncmap
Jan 27 11:50:14 (none) kernel: ppp_tty_ioctl: set xmit asyncmap ffffffff
Jan 27 11:50:14 (none) kernel: ppp_tty_ioctl: set flags to f010000
Jan 27 11:50:14 (none) kernel: ppp_tty_ioctl: set mru to 5dc
Jan 27 11:50:14 (none) kernel: ppp_tty_ioctl: set rcv asyncmap 0
Jan 27 11:50:14 (none) kernel: sent [LCP TermReq id=0x2 "Peer not responding"]
Jan 27 11:50:16 (none) kernel: rcvd [LCP TermAck id=0x2 "Peer not responding"]
Jan 27 11:50:16 (none) kernel: Connection terminated.
Jan 27 11:50:16 (none) kernel: ppp_tty_ioctl: invalid ioctl: 2000741f, addr 2
Jan 27 11:50:16 (none) kernel: tcflush failed: Invalid argument
Jan 27 11:50:16 (none) kernel: ppp: channel ppp0 closing.
Jan 27 11:50:16 (none) kernel: Couldn't restrict write permissions to /dev/ttyS3: Read-only file system
Jan 27 11:50:16 (none) kernel: ppp_tty_ioctl: set flags to 10000
Jan 27 11:50:16 (none) kernel: ppp_tty_ioctl: set flags to 10000
Jan 27 11:50:16 (none) kernel: Using interface ppp0
Jan 27 11:50:16 (none) kernel: Connect: ppp0 <--> /dev/ttyS3
Jan 27 11:50:16 (none) kernel: ppp_tty_ioctl: set xasyncmap
Jan 27 11:50:16 (none) kernel: ppp_tty_ioctl: set xmit asyncmap ffffffff
Jan 27 11:50:16 (none) kernel: ppp_tty_ioctl: set flags to 10000
Jan 27 11:50:16 (none) kernel: ppp_tty_ioctl: set mru to 5dc
Jan 27 11:50:16 (none) kernel: ppp_tty_ioctl: set rcv asyncmap ffffffff
Jan 27 11:50:16 (none) kernel: sent [LCP ConfReq id=0x3 <asyncmap 0x0> <magic 0xfbbb> <pcomp> <accomp>]
Jan 27 11:50:17 (none) kernel: **Local - end sleep 5
Jan 27 11:50:17 (none) kernel: **Local - starting TWP
Jan 27 11:50:17 (none) kernel: **Local rc.sysinit.local - end
Jan 27 11:50:17 (none) kernel: rc.sysinit is complete
Jan 27 11:50:19 (none) kernel: sent [LCP ConfReq id=0x3 <asyncmap 0x0> <magic 0xfbbb> <pcomp> <accomp>]
Jan 27 11:50:22 (none) kernel: Initialize with 1 live caches
Jan 27 11:50:22 (none) kernel: mediaswitch: resetting adjustments
Jan 27 11:50:22 (none) kernel: sent [LCP ConfReq id=0x3 <asyncmap 0x0> <magic 0xfbbb> <pcomp> <accomp>]
Jan 27 11:50:23 (none) kernel: Microcode version 00034
Jan 27 11:50:23 (none) kernel: osd buffer size = 1080000
Jan 27 11:50:23 (none) kernel: Bus services started.

Thanks Peter!

Cheers,
Phred