Nz Tivo!!

**David Stott** · 11-09-2008, 07:10 AM

Possible progress!!

David's suggestion (offline) that my ISP may be the problem may be right on the money. Working back now, and as near as I can tell, my last successful connect was on my last day with Telecom (never thought I'd have a good word to say about them). I'm now with Vodafone and proxy issues may well be why I'm failing to connect.

So that suggests that Wibble's fix re setting up 127.0.0.1 in tclient.conf and adding in the emuproxy2 call into rc.sysinit.author is also bang on the money. The only problem here is that I appear to be missing emuproxy2!! Have searched the forum (and Google) in vain and closest I come is a link to emuproxyZA. So does anyone know where I can find emuproxy2?

Also possibly crucial is the lack of the postcode in the postcodes file as posted earlier. But have tried that fix on its own (ie without proxy changes) and still failing, so that's not sufficient.

David

**David Stott** · 11-09-2008, 07:12 AM

Catdog - our posts have crossed in the mail :-)

However, we are obviously zeroing in on the same solution. I need the right emu file before going much further.

(And yes, I have been rebooting like crazy.)

David

**David Stott** · 11-09-2008, 10:02 AM

Right still no joy. Found emuProxy2, copied to TiVo, set GS = 1, rebooted and ran GS twice (with Satellite and Cable). Still failing in exact same place (Failed. Service unavailable.) after 6 or so seconds of Connecting... Log looks a bit long to post the lot but here are what look like relevant bits to me.

Sep 10 23:24:13 (none) comm[113]: Start TCD411 Request ==================
Sep 10 23:24:13 (none) comm[113]: areaCode: 002
Sep 10 23:24:13 (none) comm[113]: prefix: %2C%23401
Sep 10 23:24:13 (none) comm[113]: dialInAreaCode:
Sep 10 23:24:13 (none) comm[113]: curPhNum:
Sep 10 23:24:13 (none) comm[113]: objVer:
Sep 10 23:24:13 (none) comm[113]: tcdId: 002000020347DC8
Sep 10 23:24:13 (none) comm[113]: callId: 1221088996
Sep 10 23:24:13 (none) comm[113]: dialPrefix: %2C%23401
Sep 10 23:24:13 (none) comm[113]: dialToneCheck: 0
Sep 10 23:24:13 (none) comm[113]: offHookDetect: 0
Sep 10 23:24:13 (none) comm[113]: tonePulseDial: T
Sep 10 23:24:13 (none) comm[113]: callWaitPrefix:
Sep 10 23:24:13 (none) comm[113]: tollFreeAuth: 1
Sep 10 23:24:13 (none) comm[113]: callType: TS_SR_ACCEPTED
Sep 10 23:24:13 (none) comm[113]: swVerName: 3.0-01-1-000
Sep 10 23:24:13 (none) comm[113]: End TCD411 Request ==================
Sep 10 23:24:13 (none) comm[113]: sigType=st=2 connector=con=1...
Sep 10 23:24:13 (none) comm[113]: Error getting the Avalanche Disk Directories: errNmNameNotFound
Sep 10 23:24:13 (none) comm[113]: Start Ident ==================

and

Sep 10 23:24:13 (none) comm[113]: End Ident ==================
Sep 10 23:24:13 (none) comm[113]: CallService: Start err 0
Sep 10 23:24:13 (none) comm[113]: CAM_ID not found.
Sep 10 23:24:13 (none) comm[113]: CallStatusReporter: Phase: Dial, Status In Progress
Sep 10 23:24:13 (none) comm[113]: CallStatusReporter: sending message "CL|30"
Sep 10 23:24:13 (none) comm[113]: Backdoor code 4, enable calls via broadband
Sep 10 23:24:13 (none) comm[113]: Using Ethernet. Not starting modem/pppd.
Sep 10 23:24:13 (none) comm[113]: CallStatusReporter: Phase: Start_Auth, Status In Progress
Sep 10 23:24:13 (none) comm[113]: CallStatusReporter: sending message "ST|33"
Sep 10 23:24:14 (none) comm[113]: CommUtil: connection to host 127.0.0.1, port 8000, err 0x50005
Sep 10 23:24:14 (none) comm[113]: tmk tcp connect failed, reason = Operation now in progress
Sep 10 23:24:14 (none) comm[113]: drainGetPostQ: doXfer failed err=327685 (0x50005)
Sep 10 23:24:14 (none) comm[113]: NetAgent: drainPostQ failed, err = 0x50005
Sep 10 23:24:14 (none) comm[113]: CallService: NetAgent Process err 327685
Sep 10 23:24:14 (none) comm[113]: CallService: NetAgent failed, status 0x50005
Sep 10 23:24:14 (none) comm[113]: CallService: EndCall start
Sep 10 23:24:16 (none) comm[113]: CallStatusReporter: Turning off-hook LED off
Sep 10 23:24:16 (none) comm[113]: Recover private logs
Sep 10 23:24:16 (none) comm[113]: Opening old private log files
Sep 10 23:24:16 (none) comm[113]: Reverting private logs
Sep 10 23:24:16 (none) tcphonehome[113]: CallService return status 0x50005
Sep 10 23:24:21 (none) comm[113]: CallStatusReporter: Phase: Start_Auth, Status Failed
Sep 10 23:24:21 (none) comm[113]: CallStatusReporter: sending message "EX|14"
Sep 10 23:24:21 (none) tcphonehome[113]: TClient failed: EX|14
Sep 10 23:24:21 (none) tcphonehome[113]: Sending dialup event, subtype 8, msg EX|14
Sep 10 23:24:21 (none) tcphonehome[113]: setCallStatus called with: Failed state 0
Sep 10 23:24:29 (none) tcphonehome[113]: LastCallAttempt at 1221088996
Sep 10 23:24:29 (none) tcphonehome[113]: setting call status to: Failed
Sep 10 23:24:29 (none) tcphonehome[113]: setting call in progress to 0 (second successCount)
Sep 10 23:24:29 (none) tcphonehome[113]: Setting callActive to 0
Sep 10 23:24:30 (none) comm[113]: CallStatusReporter: sending data changed event 20
Sep 10 23:24:30 (none) tcphonehome[113]: destroying CommGlobals!
Sep 10 23:24:30 (none) tcphonehome[113]: pCommMempool empty
Sep 10 23:24:30 (none) tcphonehome[113]: Setting MCP PhoneHome action: ENABLED

David

**Wibble** · 11-09-2008, 12:24 PM

BTW, which version are you using?
This is what I get
cat /etc/oztivo_version
1.5-20051128 (NZ-TWP-20060815)

Unless you have already fixed it, you have 127 configured twice:
both
127::210.48.107.133:8000:::
and
127::127.0.0.1:8000:::

See:
# This is the default port, it's values come from Addr.itcl not here
#
000:
# Dennis' Emulator
#126::66.23.218.193:8000:::
# This is for the server emulator on minnie.
#127::66.92.222.38:8000:::
#127::64.151.65.200:8000:::
127::210.48.107.133:8000:::
#127::127.0.0.1:8000:::

# This uses emuProxy2 to avoid problems with transparent proxy. Thanks Tim!
127::127.0.0.1:8000:::

**David Stott** · 11-09-2008, 01:20 PM

Wibble, that copy I posted earlier had both configured (as I pointed out). I've hashed out the first occurence so that all that is left operational is the code you gave me. This is the only option where it fails straight away instead of waiting 16 minutes to time out. Ie if 127::210.48.107.133:8000::: occurs first or only, then I end up with a 16 minute wait before failure. If 127::127.0.0.1:8000::: occurs as the only operational line, then the connection fails straight away.

I suspect my version is (from the log): swVerName: 3.0-01-1-000. Probably a very good reason for re-imaging in itself!

One thing I wasn't sure of from your earlier posting was whether the line in rc.sysinit.author should be preceded by the directory location or not, eg /hack/bin/emuProxy2 -s 210.48.107.133 -p 8000 &. I have tried running the GS with this as shown here and also as shown in your original post without the directory prefix. Neither worked. Sigh!

My hope now is that someone will recognise the errors in the log below and intuit the real problem from those. In order (because the first is likely to cause the later ones):

1. What are the Avalanche Disk Directories?

2. What might cause CAM_ID to not be found?

3. What is an "err 0x50005"?

David

**Wibble** · 11-09-2008, 02:39 PM

Originally Posted by David Stott

I suspect my version is (from the log): swVerName: 3.0-01-1-000. Probably a very good reason for re-imaging in itself!

That version is the same as mine, it won't change. That's not the version to look at.

Your current problem is that you are pointing to the emuproxy but it's not working.

Here my log:

Sep 10 23:21:52 (none) comm[153]: End Ident ==================
Sep 10 23:21:52 (none) comm[153]: CallService: Start err 0
Sep 10 23:21:52 (none) comm[153]: CAM_ID not found.
Sep 10 23:21:52 (none) comm[153]: CallStatusReporter: Phase: Dial, Status In Progress
Sep 10 23:21:52 (none) comm[153]: CallStatusReporter: sending message "CL|30"
Sep 10 23:21:52 (none) comm[153]: Backdoor code 4, enable calls via broadband
Sep 10 23:21:52 (none) comm[153]: Using Ethernet. Not starting modem/pppd.
Sep 10 23:21:52 (none) comm[153]: CallStatusReporter: Phase: Start_Auth, Status In Progress
Sep 10 23:21:52 (none) comm[153]: CallStatusReporter: sending message "ST|33"
Sep 10 23:21:52 (none) comm[153]: CommUtil: connection to host 127.0.0.1, port 8000, err 0x0
Sep 10 23:21:52 (none) comm[153]: Uploading HTTP Header for modLog of /var/log/svclog: POST /tivo-service/mlog.cgi HTTP/1.0^M Content-Length: 929^M ^M
Sep 10 23:21:53 (none) comm[153]: read HTTP Header: HTTP/1.1 200 OK^M Date: Wed, 10 Sep 2008 11:21:56 GMT^M Server: Apache/2.0.54 (Mandriva Linux/PREFORK-13.3.20060mdk) mod_
ssl/2.0.54 OpenSSL/0.9.7g PHP/5.0.4 mod_perl/2.0.1 Perl/v5.8.7^M Connection: close^M Content-Type: text/plain; charset=IS
Sep 10 23:21:53 (none) comm[153]: O-8859-1
Sep 10 23:21:53 (none) comm[153]: SvcLogRqst::verify: enter
Sep 10 23:21:53 (none) comm[153]: SvcLogRqst::verify: unlink(/var/log/svclog.upload)ed (status = 0)
Sep 10 23:21:53 (none) comm[153]: couldn't stat input file, reason = No such file or directory
Sep 10 23:21:53 (none) comm[153]: NetAgent::doXfer: open failed on Rqst : No such file or directory
Sep 10 23:21:53 (none) comm[153]: drainGetPostQ: doXfer failed err=65535 (0xffff)
Sep 10 23:21:53 (none) comm[153]: Xfer Performance Log says errors are Ok!
Sep 10 23:21:53 (none) comm[153]: CommUtil: connection to host 127.0.0.1, port 8000, err 0x0
Sep 10 23:21:53 (none) comm[153]: read 384 bytes of upload data for FourOneOneRqst
Sep 10 23:21:53 (none) comm[153]: CommUtil: connection to host 127.0.0.1, port 8000, err 0x0
Sep 10 23:21:53 (none) comm[153]: read 2103 bytes of upload data for HServerRqst
Sep 10 23:21:53 (none) comm[153]: HTTP header: HTTP/1.1 200 OK^M
Sep 10 23:21:53 (none) comm[153]: HTTP header: Date: Wed, 10 Sep 2008 11:21:56 GMT^M

Yours starts going wrong here:
Sep 10 23:24:14 (none) comm[113]: CommUtil: connection to host 127.0.0.1, port 8000, err 0x50005
where mine is:
Sep 10 23:21:53 (none) comm[153]: CommUtil: connection to host 127.0.0.1, port 8000, err 0x0

Run the following and post the output:
cat /etc/oztivo_version

This will tell you which version you are running

It sounds like you have an old version if it's missing the emuProxy2 (which should be at /hack/bin/emuProxy2 )

**Wibble** · 11-09-2008, 02:46 PM

And to test you connectivity from you tivo,
run the following:
wget http://210.48.107.133:8000

This is what you should get:

[TiVo [p0] ~]# wget http://210.48.107.133:8000
--16:44:55-- http://210.48.107.133:8000/
=> `index.html.1'
Connecting to 210.48.107.133:8000... connected.
HTTP request sent, awaiting response... 200 OK
Length: 1,858 [text/html]

0% [ ] 1,858 0.00B/s ETA 00:00

Last-modified header invalid -- time-stamp ignored.
16:44:55 (0.00 GB/s) - `index.html.1' saved [1858/1858]

If that doesn't work, then the daily call wont' work either,

**David Stott** · 11-09-2008, 02:52 PM

Wibble

Tried the cat from within Putty (is that right?), and got:

[TiVo [p0] ~]# cat /etc/oztivo_version
cat: /etc/oztivo_version: No such file or directory
[TiVo [p0] ~]#

However, I got upgraded software and 250GB disk in October 2004, so probably safe to say an old version. That's why I'll probably end up reimaging, even if we do get a solution to current position.

The wget response looks good:

[TiVo [p0] ~]# wget http://210.48.107.133:8000
--16:51:37-- http://210.48.107.133:8000/
=> `index.html'
Connecting to 210.48.107.133:8000... connected.
HTTP request sent, awaiting response... 200 OK
Length: 1,858 [text/html]

100%[====================================>] 1,858 95.50K/s

16:51:37 (95.50 KB/s) - `index.html' saved [1858/1858]

[TiVo [p0] ~]#

David