Failed. Service Unavailable Part 2

[MrGadget]

Like Sadrake, I have noticed that I can not complete a daily call from Tivo...
Unlike Sadrake I have not changed ISP's, and instead connect to the dev emulator (port 80). My ISP assures me that they have not begun using any form of proxy (and provided this rather handy link (http://www.lagado.com/proxy-test) to verify it (which it does)).
Having been away for the last week I know it's not something I have done :) - it was working before and after I left, but failed while I was away... and as is usually the way when you go away, my internet connection dropped early on the 16th and did not come back up until I reset the router on the weekend - therefore the last successful call was August 16 @ 2:20am.
I'm running the 1.3 image and did note the HTTP/1.0 comment in the log (below) which is why I went first to my ISP.
FYI The entry in tclient.conf is:
127::210.48.107.133:80:::

If I try to wget the file from Orac, I get the following:

[TiVo [p1] /tmp]# wget 210.48.107.133/tivo/slice/nzdev.slice
--11:25:39-- http://210.48.107.133/tivo/slice/nzdev.slice
=> `nzdev.slice'
Connecting to 210.48.107.133:80... connected.
HTTP request sent, awaiting response... 404 Not Found
11:25:42 ERROR 404: Not Found.

However I can FTP (from PC) to the IP and find the file in the correct location (and download it to the PC). Tivo can ping internet IP addresses with no issues.

Any idea how to resolve this?
Cheers
Neil

Log file contents:

Aug 22 11:03:15 (none) comm[114]: CallService: Start err 0
Aug 22 11:03:15 (none) comm[114]: CAM_ID not found.
Aug 22 11:03:15 (none) comm[114]: CallStatusReporter: Phase: Dial, Status In Progress
Aug 22 11:03:15 (none) comm[114]: CallStatusReporter: sending message "CL|30"
Aug 22 11:03:15 (none) comm[114]: Backdoor code 4, enable calls via broadband
Aug 22 11:03:15 (none) comm[114]: Using Ethernet. Not starting modem/pppd.
Aug 22 11:03:15 (none) comm[114]: CallStatusReporter: Phase: Start_Auth, Status In Progress
Aug 22 11:03:15 (none) comm[114]: CallStatusReporter: sending message "ST|33"
Aug 22 11:03:17 (none) comm[114]: CommUtil: connection to host 210.48.107.133, port 80, err 0x0
Aug 22 11:03:17 (none) comm[114]: Uploading Header for modLog of /var/log/svclog: POST /tivo-service/mlog.cgi HTTP/1.0^M Content-Length: 9942^M ^M
Aug 22 11:06:14 (none) comm[114]: XferRqst timeout waiting to read
Aug 22 11:06:16 (none) comm[114]: drainGetPostQ: doXfer failed err=65535 (0xffff)
Aug 22 11:06:16 (none) comm[114]: NetAgent: drainPostQ failed, err = 0xffff
Aug 22 11:06:16 (none) comm[114]: CallService: NetAgent Process err 65535
Aug 22 11:06:16 (none) comm[114]: CallService: NetAgent failed, status 0xffff
Aug 22 11:06:16 (none) comm[114]: CallService: EndCall start
Aug 22 11:06:18 (none) comm[114]: CallStatusReporter: Turning off-hook LED off
Aug 22 11:06:18 (none) comm[114]: Recover private logs
Aug 22 11:06:18 (none) comm[114]: Opening old private log files
Aug 22 11:06:18 (none) comm[114]: Reverting private logs
Aug 22 11:07:39 (none) comm[114]: Cleanup: GetAddDiskBasedDirectories returned <70001> "0x70001"...skipping cleanup
Aug 22 11:07:39 (none) tcphonehome[114]: CallService return status 0xffff
Aug 22 11:07:39 (none) tcphonehome[114]: GetPostalCodeVersion - /PostalCode/02113 ServerVersion=27
Aug 22 11:07:39 (none) tcphonehome[114]: debug: sumServerVersion=27
Aug 22 11:07:39 (none) comm[114]: CallStatusReporter: Phase: Start_Auth, Status Failed
Aug 22 11:07:39 (none) comm[114]: CallStatusReporter: sending message "EX|14"
Aug 22 11:07:39 (none) tcphonehome[114]: TClient failed: EX|14
Aug 22 11:07:39 (none) tcphonehome[114]: Sending dialup event, subtype 8, msg EX|14
Aug 22 11:07:39 (none) tcphonehome[114]: setCallStatus called with: Failed state 0
Aug 22 11:08:15 (none) tcphonehome[114]: LastCallAttempt at 1124708190
Aug 22 11:08:15 (none) tcphonehome[114]: setting call status to: Failed
Aug 22 11:08:15 (none) tcphonehome[114]: setting call in progress to 0 (second successCount)
Aug 22 11:08:15 (none) tcphonehome[114]: Setting callActive to 0
Aug 22 11:08:15 (none) comm[114]: CallStatusReporter: sending data changed event 20
Aug 22 11:08:15 (none) tcphonehome[114]: destroying CommGlobals!
Aug 22 11:08:15 (none) tcphonehome[114]: pCommMempool empty
Aug 22 11:09:49 (none) tcphonehome[114]: Setting MCP PhoneHome action: ENABLED

[petestrash]

FWIW:

If I try FTP (using a PC) 210.48.107.133 on port 80 or 8000 it just times out for me also.

Port 21 works fine, except it won't accept my non NZ IP.

Peter.

[Wibble]

On Orac you can get DJC's slices as follows:

Using an Anonymous login via FTP this will show up as
ftp://210.48.107.133/tivo/slice/nzdev.slice

using http:
http://210.48.107.133/slice/nzdev.slice

NOTE: the path are different, one has tivo one hasn't.

To get the original type of slices use:
ftp://210.48.107.133/tivo/slice/nztivo.slice
http://210.48.107.133/slice/nztivo.slice


The loadguide.conf is as follows:
SLICE_URL='http://210.48.107.133/slice/'

For DJC's:
SLICE1=nzdev.slice
and for the other one
SLICE1=nztivo.slice

[MrGadget]

Thanks - that solved the wget issue - that does work with the correct path.
However I still seem unable to make a successful daily call...

Any ideas much appreciated :-)

FYI - Although I do not have any associated network problems with the Tivo, I have just reinstalled the Cachecard drivers and set the network details again - something suggested in this forum (http://archive.tivocommunity.com/tivo-vb/history/topic/103803-1.html) - no change to my issue - still failing on a daily call....

[DJC]

There have been no changes in slice creation mechanisms.

It looks like there are a few tivos on the port 80 orac emulator now, anyone else having problems?

[zollymonsta]

I have my two tivos on the port 8000 emulator. No problem at all, apart from them grizzling only about 7 days of data (which I just ignore) :rolleyes:

[DJC]

I have my two tivos on the port 8000 emulator. No problem at all, apart from them grizzling only about 7 days of data (which I just ignore) :rolleyes:

Check out ... 8am, Ahhhh! Monsters on TV3, time to use the web interface.

[DJC]

I have my two tivos on the port 8000 emulator. No problem at all, apart from them grizzling only about 7 days of data (which I just ignore) :rolleyes:

Port 80 and 8000 emulators use essentially the same slice at present. The development slice has an extra channel in it, which is not visible unless you tweak the headend. So perhaps not a slice issue.

[MrGadget]

Can I change ports from 80 to 8000 easily (ie without clearing data etc as when you change emulators) to try that?

Interesting note - don't think it's relevant - but who knows... as the internet access was down from Tuesday to Sunday, no guide data was downloaded (therefore tivo was mostly out...) - I manually loaded an nzdev.slice on Sunday and only got data fro the following Tuesday onwards... any way this could cause the current issues?

[DJC]

(i) Slices by design have data +3 days, this is normal so that previously set recordings are not lost between slices. [until I get incremental slices working] (altough it should have picked up historic slices to fill in current data)

(ii) Changing from port 80 to 8000 should have little effect... PROVIDED you haven't manually loaded any logos. The key difference with the 8000 emulator is that it has a logo slice.

/DJC

[MrGadget]

Changing from port 80 to 8000 should have little effect... PROVIDED you haven't manually loaded any logos. The key difference with the 8000 emulator is that it has a logo slice.

/DJC


Oh, but I do have manually loaded logos... what would the effect be?

[DJC]

Result is ... "Failed While Loading Data" ... So this is not an option for you.

[catdog]

I believe it is a problem with the orac emulator if you completely run out of data.

A couple of weeks ago telecom ( :mad: ) stuffed up our adsl connection for 4 days, during which one of the two tivos here ran out of data (because it had been disconnected from the network for a couple of days before this occurred). The other one was always on the network, and therefore had data to cover the 4 days of no web connection. When the web was reconnected, the tivo with no data would not connect but the other one was fine.

All the symptoms were exactly the same as your case
- ran out of data
- nothing changed to hardware configuration/files etc
- could wget slices and manually load them
- timed out when trying to connect by itself (service unavailable message)
The tivo which never ran out of data worked fine, with the same setup on the same network.

Not wanting to re-image, I tried changing to the other emulator at 64.151.65.200 - and it downloaded and indexed with out any problems. There were a few holes in the data (not sure if this is normal or not), so changed back to 210.48.107.133 and it then downloaded and indexed successfully!

Something is still slightly broken however, it works fine so long as it is always connected to the network. If it misses a slice (ie network unplugged for more than a day), then instead of getting both the old and new slices it fails (service unavailable) and downloads nothing. Swapping back and forth between emulators rectifys this problem, and it then continues to work as normal again.

I didn't bother posting on here because I just figured the tivo database had randomly become corrupt or something. The similarity with your situation suggests it is a problem with the emulator - which most people never see because they keep the data topped up. I realise this doesn't really give you a proper answer to your problem, but you are not alone. Perhaps someone with knowledge about the emulator workings can have a look at this?

[DJC]

Interesting note - don't think it's relevant - but who knows... as the internet access was down from Tuesday to Sunday, no guide data was downloaded (therefore tivo was mostly out...) - I manually loaded an nzdev.slice on Sunday and only got data fro the following Tuesday onwards... any way this could cause the current issues?

Lets test this...

Can you try a data retrieval from the emulator now, lets see the result with a set of end to end complete slices loaded up.

The nzdev.slice I've just uploaded is a full slice starting now and going forward, so this will (also) eliminate missing days by loading manually. Then we'll see if the issue continues for future slices.

[MrGadget]

I believe it is a problem with the orac emulator if you completely run out of data.

Yay - I'm not alone :-)
I'll clear the data and try again....
As for the wholes in the other emulators guide data - yes, from my experiences quite normal - hense my change to the emulator on orac :)

[catdog]

Yay - I'm not alone :-)
I'll clear the data and try again....

The "clear program data & todo list" didn't help - clear and delete everything might, but I didn't want to lose the recorded shows. Failing that, re-image the drive?

[DJC]

Yay - I'm not alone :-)
I'll clear the data and try again....
As for the wholes in the other emulators guide data - yes, from my experiences quite normal - hense my change to the emulator on orac :)

Whoo! hang up... I've just uploaded completed slices, see previous post... lets test the theory first.

[waynez]

Guys,

Friends TIVO is exhibiting exactly the same problems. He hasn't been connected to the net for a while, and when we last connected he got the Failed. Service unavailable.

I've done a clear and delete, checked and double checked the address, can wget slices, can ping the server, can telnet, can tivoweb, but just wont get data.
Get an error in the tconfig.log XferRqst timeout waiting to read

Running out of ideas, contemplating a re-image, but maybe you guys are on to something.... I'm just trying connecting to the dev emulator and see if that makes a difference.

[MrGadget]

Lets test this...

Can you try a data retrieval from the emulator now, lets see the result with a set of end to end complete slices loaded up.

The nzdev.slice I've just uploaded is a full slice starting now and going forward, so this will (also) eliminate missing days by loading manually. Then we'll see if the issue continues for future slices.

Okay - just tried a connection via Tivoweb - failed as usual - I'll manually download the latest slice and dbload it... I'll advise further....

[MrGadget]

After dbload'ing a slice (and a nice fat one it is too - data thru to Monday sometime), then indexing, a followup daily call gives the same result... failed...
:(

[waynez]

Alrighty then...

That fixed it.

I did a Clear & Delete ALL, it may not have been required in the end, but whats done's done....

I changed back to the emulator on 64.151.65.200, finished guided setup, did the test call, then completed the call.

Waited for the final call to complete and the data to be reindexed.

Once everything was working and data appeared.

Changed back to the emulator on orac 210.48.107.133:80

rebooted, did a daily call, and it's now loading data 8% - 76mins

So that seems to have worked.

DJC, does that mean there was/is a problem with the emulator?

and thanks CATDOG, for your help....

[DJC]

OK. Then based on this its obviously nothing to do with the slices.

So must be some issue tied up with the emulator, might have to disconnect my tivo from the lan to check it out... damn, times like you wish you had two tivos.

Time for this thread to move to the development forum...

[DJC]

I did a Clear & Delete ALL, it may not have been required in the end, but whats done's done....
I changed back to the emulator on 64.151.65.200, finished guided setup, did the test call, then completed the call.
Waited for the final call to complete and the data to be reindexed.
Once everything was working and data appeared.
Changed back to the emulator on orac 210.48.107.133:80
rebooted, did a daily call, and it's now loading data 8% - 76mins
So that seems to have worked.


Crikey, alot of emulator swapping going there...

Waynez, can you do the same thing against the orac emulator...

ie. Same clear and delete all then just run the GS directly against the dev emulator port 80 or 8000 if you want logos.

[MrGadget]

Alrighty then...

That fixed it.

I did a Clear & Delete ALL, it may not have been required in the end, but whats done's done....

Hmnn - I have a 160Gb drive that after being away is 80% full - so a Clear & Delete ALL isn't really an option for me.

I have tried clearing guide data and changing back to the old emulator but it still comes up with a Failed call...
Clear data and dev emulator - failed call

Interestingly, if I run a packet sniffer while making a failed call, I see packets containing things like "Meet The The FockersM€¸ Massive blockbuster hit sequel to 'Meet the Parents' has the Byrne family journeying to Miami to meet Greg's parents only to find alcoholic sex-addicted hippies. Starring: Ben Stiller" & "Angel meets with a swami to try to end his obsession with Darla, while Wesley assumes Angel's identity and plays bodyguard to a businessman's daughter" - seems guide data is actually being downloaded even though the call fails....

Back to attempts...
rerun guided setup on the dev emulator - fails at first call - tried three times - failes each time.
Edit tclient.conf with old emulator IP (64.151.65.200) and tried guided setup again - and success at both first and second calls...

I'm a little loath to go back and try a clear & delete of data and swap back to the dev emulator until the issue is sorted - but if it will help find the problem then I'll give it a go....


*** Update ***
After looking at the guide data on the old emulator - it reminded me of why I changed in the first place - too many gaps - so I have cleared and deleted the guide data, edited the tclient.conf file to point back to the dev emulator and... it works again....

So the short term fix...(at least what worked for me)...
1. Back up your season passes etc
2. Clear & Delete Guide Data
3. Change IP address in tclient.conf to 64.151.65.200
4. Rerun guided setup
5. when completed, change the ip in tclient.conf to 210.48.107.133
6. clear & delete guide data again
7. Make a call
8. restore backup of season passes etc

[DJC]

Right ... I have another emulator at which I can tail logs to check things out.

Who still has the problem and can work the issue through with me?

/DJC

[catdog]

*** Update ***
After looking at the guide data on the old emulator - it reminded me of why I changed in the first place - too many gaps - so I have cleared and deleted the guide data, edited the tclient.conf file to point back to the dev emulator and... it works again....

So the short term fix...(at least what worked for me)...
1. Back up your season passes etc
2. Clear & Delete Guide Data
3. Change IP address in tclient.conf to 64.151.65.200
4. Rerun guided setup
5. when completed, change the ip in tclient.conf to 210.48.107.133
6. clear & delete guide data again
7. Make a call
8. restore backup of season passes etc
I don't think you needed to clear and delete or guided setup or anything, just:
1. Change IP address in tclient.conf to 64.151.65.200
2. Make a call
3. Change the ip in tclient.conf back to 210.48.107.133

well that's what worked for me ;)

[MrGadget]

Who still has the problem and can work the issue through with me?

/DJC

Afraid not me...
My only issue is now being 12 hours behind... I have a feeling I should know how to fix this...
postcodezones file has the entry
02113 Pacific/Auckland
(with the relevant 'auckland' file in the /hack/zoneinfo/pacific folder). Tivo correctly set to GMT...
fixtivotime gives:
Our postcode is 02113. Found matching timezone Pacific/Auckland
Offset 0 for timezone GMT, daylight saving is 0
Connecting to time server 207.126.98.204
t was 3333841323 from server
t is now 1124852523
Time is 2005-08-24 03:02:03
Time set to: Wed Aug 24 03:02:03 2005
Have a nice day.
Time set to: Wed Aug 24 03:02:04 2005
Have a nice day.


Which sets me back 12 hours (as does a daily call when the time is correct...)

What am I missing here ?

[wbeasley]

I have this issue as well, wife redesigned the living room over the weekend :confused: and the cable wouldn't reach the new location. Finally decided I should update the tivo and the update fails.
I'm busy this evening and will try the emulator switch tomorrow evening

[waynez]

Tivo is all up and running fine after the last couple of days issues.

I'm about to Clear and Delete everything and run through Guided setup against the orac emulator 210.48.107.133 - Will report back shortly.

[MrGadget]

My only issue is now being 12 hours behind...

I will forever fail to understand Tivo :p The next day (and another reboot) it's fine - does not reset it's own time back 12 anymore - and I swear I was not still in maint mode (I double checked that!)...

[wbeasley]

Well I am on 64.151.65.200 so that would indicate it isn't an issue only with the orac emulator.

[tonys]

Looks like I've got the same problem! 'failed call, service unavailable' not 100% sure what emulator I'm on, how do I find out?

[tonys]

just checked clientlog thing, I'm on 64.151.65.200 port 80

Hellppp!

[wbeasley]

I cleared the program data and todo list, and tried changing to the orac IP 80 & 8000 (I figured that was just a change of IP in the tclient.conf or is there more to it?)

Nothing worked and have since changed back to 64.151.65.200 a

Some help would be appreciated, what can i try next?

[DJC]

Guys: can you try the following IP as your emulator.

202.36.218.218

This is a one off test emulator so DONT use it premanently.

I have a theory in regard to the number of slices being served simultaneously -leading to a really long slice download response line from the emulator to the tivo.

The theory goes like ~ the tivo buffer length is not long enought to support the long stream of url's.

On this 202.36.218.218 emulator I have removed all slices bar the latest. Other than that its config is the same as orac.

[tonys]

This is going to sound really dumb, but can someone talk me through changing the IP address of the emulator please. If anyone's up and about and willing at this time of day, I'll be up and about till about midnight.
Tony 09 420 9995

[wbeasley]

I tried the IP and no joy, Guided setup spent a long time trying to connect. Looks like it timed out

[tonys]

Me too, if I managed to change the IP correctly that is... does the 127: and :80 bits stay at either end of the 202.36.218.218 bit? Sorry to be dumb!!
If that's correct then mine did the same, tried to connect for a while then timed out. On the original IP 64.151.65.200, the 'failed,service unavailable' message comes up almost instantly after 'housekeeping'

[DJC]

Can you

i) ping the ip?

ii) and point a web browser at it http://202.36.218.218/ and get a forbidden message?

iii) open this file http://202.36.218.218/static/Headend/message-20000000.slice

?

[wbeasley]

I can ping the new IP
I get the forbidden message
When i click on the slice hyperlink I get a box to open it

[tonys]

hang on, just had another go at changing the ip, rebooted, then forced daily call via tenet, it is now downloading data!!! presume after that, I swap the IP back and try again? I was using 64.151.65.200 port 80 which emulator is that? Is it the best, most reliable? if it makes a difference, I'm on OzTivo image 3.0r1.4

[DJC]

I just pointed my tivo at it, and its away downloading the latest slice...

Which is not good; as I was trying to miss a slice or two and see if I can re-create the issue. Guess I have up to date data now tho.

Are you sure nothing else is up with your net/tivo given you can ping and access the emulator?

[DJC]

hang on, just had another go at changing the ip, rebooted, then forced daily call via tenet, it is now downloading data!!! presume after that, I swap the IP back and try again? I was using 64.151.65.200 port 80 which emulator is that? Is it the best, most reliable? if it makes a difference, I'm on OzTivo image 3.0r1.4

The data you now have is from the dev emulator system which serves from orac.

See if you like the slice and make your call. There is plenty of info on the advantages/disavantages of the dev system in the developers forum.

Edit: (Ignore acutually can now) I can't actually see from the log that you have made the connection to the test emulator. Not sure where you are connecting.

* 64.151.65.200 is Ed's emulator, not the dev system.

[tonys]

Well, using 'your' emulator IP, I got a download and up to date guide data, swapped back to 64.151.65.200:80 and got failed, service unavailable again. Problem seems to be with this particular IP. any other suggestions?

[DJC]

Well, using 'your' emulator IP, I got a download and up to date guide data, swapped back to 64.151.65.200:80 and got failed, service unavailable again. Problem seems to be with this particular IP. any other suggestions?

Go orac: 210.48.107.133

port 80 if you have logos loaded manually, otherwise port 8000 to get the logo slice too.

[tonys]

I'm off to bed now! Think I'll give the development emulator a try tomorrow, what is the IP address for it? Thanks for your help.

[wbeasley]

Well, No joy this end.

I wondered if maybe it could be a proxy issue as the tclient log has the HTTP1.0 mentioned in the other thread. So i did the following
(I have an older image)

cd /hack/bin; wget http://202.63.38.134/takm/emuProxy2
chmod +x /hack/bin/emuProxy2
Edit /etc/tclient.conf, modify the line:
127::127.0.0.1:8000:::
added following to rc.sysinit.author to read (mine didn't have line to amend)
emuProxy2 -s 210.48.107.133 -p 8000 & (tried with /hack/bin as well)

nothing worked here, uncertain if i implemented correctly. Possibly off track.

mmm, I'm at work atm but I'm certain I recall that this line is active, thought it a little odd at the time. Could it be that simple?
# Dennis' Emulator
126::66.23.218.193:80:::

Because I cleared all data I have to go through guided setup. I can't even manually use the Tivo atm. Having approx 14 guests around sat evening for the rugby and it would be sad to not have tivo working...
I would do a reinstall but have all but the first 6 legs of the tour de france on Tivo at high quality along with the current season if gilmour gilrs for the wife, and I have yet to move them onto dvd. I can still set up tserver and move them but there is hours and hours of stuff.

Can anyone see a way I can run guided setup without doing a call so at least I can use Tivo manually sat evening?

Thanks

[tonys]

If that line's active and before the IP of the NZ emulator, I'd guess it's trying to connect to this IP first! Would certainly explain all your problems! Although I couldn't get a download from Ed's emulator, and succeded from DJC's 'dummy' one. Going to try the development emulator tonight or tomorrow morning (depends when I'm allowed to 'bugger about with Tivo') funny how possessive they get of the damn things isn't it?

[DJC]

Well, No joy this end.

I wondered if maybe it could be a proxy issue as the tclient log has the HTTP1.0 mentioned in the other thread. So i did the following
(I have an older image)

I have moved the ... lets call it ... bootstrap emulator to port 8888

So the address is 202.36.218.218:8888

That will eliminate any [transparent] proxy issues...

[DJC]

If that line's active and before the IP of the NZ emulator, I'd guess it's trying to connect to this IP first!

It should only connect to the 127 line; which is setup as /State/PhoneConfig DialConfig entry.

Browse MFS to verify from tivoweb.

[Tuatara]

Obviously we're not all having this problem, and it would appear perhaps it's sporadic for some people. I wonder if those of us affected can find something in common that might indicate the cause of the problem.

For me, calls are failing on all three emulators (Ed's, which I've been using up till now, and both port 80 and 8000 on Orac). I don't think I've had a successful call all week.

I've tried it with emuProxy and, for the sake of completeness, without. I can load the Orac home page in a web browser. I haven't, however, tried looking at the traffic when TiVo attempts a daily call.

My ISP (Iconz) promises that nothing has changed with proxies, etc. My own router setup hasn't changed. My TiVo hasn't been tinkered with for several weeks. Although Telecom are apparently about to "grandfather" my particular Jetstream plan, Iconz says that hasn't happened yet.

I'm probably going to reimage anyway, because the beta image I used turned out to have a bug that created only a 64MB swap partition, which is a bit small for my TiVo, which has 240GB of disk space. But before I do that is there any debugging data I can share that might help pin down the problem?

Are others who are having this problem also using the beta image? I know Tony is using a beta image, but doesn't have the small-swapfile problem, because I helped him do the guided setup.

Cheers
Matt

(PS my home router has just dropped off the net so I can't try the new emulator on 8888, but I will when I get home this afternoon.)

[tonys]

Don't think I'll rush home and delete all my current guide data this afternoon then!

[DJC]

(PS my home router has just dropped off the net so I can't try the new emulator on 8888, but I will when I get home this afternoon.)

Excellent, I'm keen to see the result of this. Have deleted yesterdays slice so this emulator is still a one slicer. Which is what the majority who have not had network issues see on a daily basis from the main emulators.

[slangnz]

Hiya.

Mine has now dropped off as well. My ISP is Orcon

/etc/tclient config:
127::64.151.65.200:80:::

Software version: 3.0-01-1-000

Had been working fine until recently - not sure when the daily update started failing, but I've run out of guide info now.

Doing some low level tcp diagnostics yields:

Request going out:

POST /tivo-service/mlog.cgi HTTP/1.0
Content-Length: 2391

tclient_hangup TCD_ID=000134922972058 CALL_ID=1124832459 TIME=1124832566 CODE=0
tclient_ticket TCD_ID=000134922972058 CALL_ID=1124832459 TIME=1124832566 STATUS=None TICKET=None VALUE=None
tclient_result TCD_ID=000134922972058 CALL_ID=1124832459 TIME=1124832575 STATUS=Succeeded CODE=1
ird_id TCD_ID=000134922972058 CALL_ID=1124928792 TIME=1124928819 ID=53972058
tcd_driveid TCD_ID=000134922972058 CALL_ID=1124928792 TIME=1124928819 HDA=3LJ2JHVM HDB=Unknown
tclient_hangup TCD_ID=000134922972058 CALL_ID=1124928792 TIME=1124928822 CODE=65535
tclient_result TCD_ID=000134922972058 CALL_ID=1124928792 TIME=1124928822 STATUS=Failed CODE=14
ird_id TCD_ID=000134922972058 CALL_ID=1124936395 TIME=1124936427 ID=53972058
tcd_driveid TCD_ID=000134922972058 CALL_ID=1124936395 TIME=1124936427 HDA=3LJ2JHVM HDB=Unknown
tclient_hangup TCD_ID=000134922972058 CALL_ID=1124936395 TIME=1124936430 CODE=65535
tclient_result TCD_ID=000134922972058 CALL_ID=1124936395 TIME=1124936430 STATUS=Failed CODE=14
ird_id TCD_ID=000134922972058 CALL_ID=1124982301 TIME=1124982339 ID=53972058
tcd_driveid TCD_ID=000134922972058 CALL_ID=1124982301 TIME=1124982339 HDA=3LJ2JHVM HDB=Unknown
tclient_hangup TCD_ID=000134922972058 CALL_ID=1124982301 TIME=1124982342 CODE=65535
tclient_result TCD_ID=000134922972058 CALL_ID=1124982301 TIME=1124982343 STATUS=Failed CODE=14
ird_id TCD_ID=000134922972058 CALL_ID=1125037424 TIME=1125037444 ID=53972058
tcd_driveid TCD_ID=000134922972058 CALL_ID=1125037424 TIME=1125037444 HDA=3LJ2JHVM HDB=Unknown
tclient_hangup TCD_ID=000134922972058 CALL_ID=1125037424 TIME=1125037447 CODE=65535
tclient_result TCD_ID=000134922972058 CALL_ID=1125037424 TIME=1125037448 STATUS=Failed CODE=14
ird_id TCD_ID=000134922972058 CALL_ID=1125064491 TIME=1125064520 ID=53972058
tcd_driveid TCD_ID=000134922972058 CALL_ID=1125064491 TIME=1125064520 HDA=3LJ2JHVM HDB=Unknown
tclient_hangup TCD_ID=000134922972058 CALL_ID=1125064491 TIME=1125064523 CODE=65535
tclient_result TCD_ID=000134922972058 CALL_ID=1125064491 TIME=1125064524 STATUS=Failed CODE=14
ird_id TCD_ID=000134922972058 CALL_ID=1125064677 TIME=1125064697 ID=53972058
tcd_driveid TCD_ID=000134922972058 CALL_ID=1125064677 TIME=1125064697 HDA=3LJ2JHVM HDB=Unknown
tclient_hangup TCD_ID=000134922972058 CALL_ID=1125064677 TIME=1125064701 CODE=65535
tclient_result TCD_ID=000134922972058 CALL_ID=1125064677 TIME=1125064701 STATUS=Failed CODE=14

Reply:
HTTP/1.1 404 Not Found
Date: Fri, 26 Aug 2005 02:03:24 GMT
Server: Apache/1.3.33 (Unix) (Gentoo/Linux) PHP/4.3.11 mod_gzip/1.3.26.1a
Connection: close
Content-Type: text/html; ch****t=iso-8859-1

<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<HTML><HEAD>
<TITLE>404 Not Found</TITLE>
</HEAD><BODY>
<H1>Not Found</H1>
The requested URL /tivo-service/mlog.cgi was not found on this server.<P>
<P>Additionally, a 404 Not Found
error was encountered while trying to use an ErrorDocument to handle the request.
<HR>
<ADDRESS>Apache/1.3.33 Server at www.pbp.net Port 80</ADDRESS>
</BODY></HTML>

Looks to me like a problem with the webserver?

I've got another tivo that is located in a different city that I look after that is likely to have the same problem, except I can't easily manage/change the config...

Hope this info helps someone track the problem down.

Cheers -

[DJC]

Yep. I'd agree, ed's emulator looks belly up for the moment.

The IP still looks right, his domain resolves to it.

We'll have to wait and see.

[Tuatara]

Yep. I'd agree, ed's emulator looks belly up for the moment.

In turn, pointing a browser at Orac:

http://210.48.107.133/tivo-service/mlog.cgi
http://210.48.107.133:8000/tivo-service/mlog.cgi

both simply return the word "done"

http://210.48.107.133:8888/tivo-service/mlog.cgi

gives no response at all; the browser times out.

Is that what's expected? Does the TiVo request differ in some way?

Cheers
Matt

[Edit: I see from the post below I was using port 8888 on the wrong server ;-). http://202.36.218.218:8888/tivo-service/mlog.cgi in a browser is just like Orac: the word "done".]

[wbeasley]

I have moved the ... lets call it ... bootstrap emulator to port 8888

So the address is 202.36.218.218:8888

That will eliminate any [transparent] proxy issues...

Just to confirm, port 8888 with no emuProxy did not work.

[DJC]

Try 202.36.218.218 for port 8888 (mlog)

[Edit... ok ignore, just saw your edit]

[DJC]

Just to confirm, port 8888 with no emuProxy did not work.

Please post your tclient.conf

[MrGadget]

Obviously we're not all having this problem, and it would appear perhaps it's sporadic for some people. I wonder if those of us affected can find something in common that might indicate the cause of the problem.
For what it's worth (having resolved the issue myself now), my details are as follows:
Emulator with issue: 210.48.107.133 Port 80 (Orac)
Verified no proxy in place (via ISP (Snap) and via http://www.lagado.com/proxy-test )
Image 1.3
My issue occured while I was away when my router dropped the connection on Aug 16 which I reset Aug 21st - all calls thereafter failed with a timeout (even after manually loading data). This apprears to be the theme with everyone - that is, no attemped guide downloads for a period, then failure on first attempt thereafter...

As noted I did resolve the issue (though not identify) with steps previously mentioned.

I post this only in the hope that it helps :-)

[Gazzagazzanz]

My Tivo started failing on data d/l on Wednesday. I read this thread and then decided to just shift to the Orac emulator port 8000, reboot the Tivo and leave it. I checked and it had done a guide data d/l in the middle of the day today and reports success. I did nothing except shift from Ed's to Orac and reboot Tivo.

[wbeasley]

Heres the tclient log - part1-

Aug 26 15:10:21 (none) tcphonehome[119]: TCphonehome active
Aug 26 15:10:21 (none) tcphonehome[122]: cleaning /Setup
Aug 26 15:10:21 (none) tcphonehome[122]: Fetching /SwSystemACTIVE/Name
Aug 26 15:10:21 (none) tcphonehome[122]: Last Call Status Was: 'Failed' (size 6)
Aug 26 15:10:21 (none) tcphonehome[122]: Last Call Status Will Be: Failed
Aug 26 15:10:21 (none) tcphonehome[122]: setCallStatus called with: Failed state 0
Aug 26 15:10:21 (none) tcphonehome[122]: LastCallAttempt at 1125066194
Aug 26 15:10:21 (none) tcphonehome[122]: setting call status to: Failed
Aug 26 15:10:21 (none) tcphonehome[122]: setting call in progress to 0 (second successCount)
Aug 26 15:10:21 (none) tcphonehome[122]: Setting callActive to 0
Aug 26 15:10:21 (none) tcphonehome[122]: PhoneHome: statusValue = <0>, getResult = <0>
Aug 26 15:10:21 (none) tcphonehome[122]: /State/Avalanche LastStatus was <0> and getResult was <0>, changing to unknown
Aug 26 15:10:21 (none) tcphonehome[122]: finished cleaning /Setup
Aug 26 15:10:21 (none) tcphonehome[122]: About to execute: /sbin/ifconfig eth0 2>&1
Aug 26 15:10:21 (none) tcphonehome[122]: Command Output: eth0 Link encap:Ethernet HWaddr 00:0B:AD:69:C6:67
Aug 26 15:10:21 (none) tcphonehome[122]: Command Output: inet addr:0.0.0.0 Bcast:255.255.255.255 Mask:0.0.0.0
Aug 26 15:10:21 (none) tcphonehome[122]: Command Output: UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1
Aug 26 15:10:21 (none) tcphonehome[122]: Command Output: RX packets:0 errors:0 dropped:0 overruns:0 frame:0
Aug 26 15:10:21 (none) tcphonehome[122]: Command Output: TX packets:0 errors:0 dropped:0 overruns:0 carrier:0 coll:0
Aug 26 15:10:21 (none) tcphonehome[122]: Command Output: Interrupt:29
Aug 26 15:10:21 (none) tcphonehome[122]: Command Output:
Aug 26 15:10:21 (none) tcphonehome[122]: Command succeeded
Aug 26 15:10:21 (none) tcphonehome[122]: NOT Using debug ethernet
Aug 26 15:10:21 (none) tcphonehome[122]: Error statting file /var/log/http: No such file or directory (errno=2)
Aug 26 15:10:21 (none) tcphonehome[122]: Error statting file /var/log/Ohttp: No such file or directory (errno=2)
Aug 26 15:10:21 (none) tcphonehome[122]: Timesync is within the past 5 days... all is well
Aug 26 15:10:21 (none) tcphonehome[122]: ReschedCall: reason = 7, secSinceLast = 0, numFails = 0
Aug 26 15:10:21 (none) tcphonehome[122]: Schedule call after failure
Aug 26 15:10:21 (none) tcphonehome[122]: setting next attempt at 1125071181 (Fri Aug 26 15:46:21 2005 )
Aug 26 15:10:21 (none) tcphonehome[122]: ReschedCall(7, 0) in 36 min
Aug 26 15:10:21 (none) PhoneAction[122]: PhoneAction 2 register complete timeout 2160
Aug 26 15:10:21 (none) PhoneAction[122]: Register Complete: Next call should happen at Fri Aug 26 15:46:21 2005
Aug 26 15:10:21 (none) tcphonehome[122]: called getTZ
Aug 26 15:10:21 (none) WatchdogAction[122]: WatchdogAction register complete
Aug 26 15:11:29 (none) tcphonehome[122]: Setting MCP PhoneHome action: RUNNING
Aug 26 15:11:29 (none) tcphonehome[122]: pCommMempool empty
Aug 26 15:11:29 (none) tcphonehome[122]: useBackupTollFree is 1
Aug 26 15:11:29 (none) tcphonehome[122]: phonehome: received message. type = 30 subtype = 2
Aug 26 15:11:29 (none) tcphonehome[122]: creating CommGlobals
Aug 26 15:11:37 (none) tcphonehome[122]: created CommGlobals
Aug 26 15:11:37 (none) tcphonehome[122]: PerformCall, subtype=2 forceTollFree=1 automated=0
Aug 26 15:11:37 (none) tcphonehome[122]: setCallStatus called with: In Progress state 1
Aug 26 15:11:37 (none) tcphonehome[122]: LastCallAttempt at 1125069089
Aug 26 15:11:37 (none) tcphonehome[122]: setting call status to: In Progress
Aug 26 15:11:37 (none) tcphonehome[122]: setting call in progress to 1 (second successCount)
Aug 26 15:11:37 (none) tcphonehome[122]: Setting callActive to 1
Aug 26 15:11:37 (none) tcphonehome[122]: setting call attempt
Aug 26 15:11:37 (none) tcphonehome[122]: Error statting file /var/log/http: No such file or directory (errno=2)
Aug 26 15:11:37 (none) tcphonehome[122]: Error statting file /var/log/Ohttp: No such file or directory (errno=2)
Aug 26 15:11:37 (none) tcphonehome[122]: Calling TClient
Aug 26 15:11:37 (none) comm[122]: CallStatusReporter: Phase: Select_Phone, Status In Progress
Aug 26 15:11:37 (none) comm[122]: CallStatusReporter: sending message "EX|29"
Aug 26 15:11:37 (none) comm[122]: CallService: preprocessing call.
Aug 26 15:11:37 (none) comm[122]: CallStatusReporter: Phase: Prepare_Call, Status In Progress
Aug 26 15:11:37 (none) comm[122]: CallStatusReporter: sending message "EX|29"
Aug 26 15:11:45 (none) comm[122]: LogMgr: start writing to GzPacker(/var/tmp/syslog.gz)
Aug 26 15:11:45 (none) comm[122]: skipping filter line itself!
Aug 26 15:11:58 (none) last message repeated 8490 times
Aug 26 15:11:58 (none) comm[122]: LogMgr: end writing to GzPacker(/var/tmp/syslog.gz)
Aug 26 15:11:58 (none) comm[122]: Starting Private Logs processing; send event to MW
Aug 26 15:11:58 (none) comm[122]: waiting for logs to divert...
Aug 26 15:11:58 (none) comm[121]: Received the LOGMGR WAIT event
Aug 26 15:11:58 (none) comm[122]: logs diverted.
Aug 26 15:11:58 (none) comm[122]: Do actual private logs processing
Aug 26 15:11:59 (none) comm[122]: Error getting demographic info: No Tuner Count
Aug 26 15:11:59 (none) comm[122]: CmdProc: wrote /var/persist/thumbslog.log.gz
Aug 26 15:11:59 (none) comm[122]: encryptFile: infile = /var/persist/thumbslog.log.gz outfile = /var/persist/thumbslog.log.gz.bfg keyname = BACKHAUL_THUMB
Aug 26 15:11:59 (none) comm[122]: About to execute: /tvbin/genkey 128 1 2>&1
Aug 26 15:12:00 (none) comm[122]: Command succeeded
Aug 26 15:12:00 (none) comm[122]: EncryptLog: key was empty for BACKHAUL_THUMB
Aug 26 15:12:04 (none) comm[122]: CmdProc: wrote /var/log/tivoLog.prv.gz
Aug 26 15:12:04 (none) comm[122]: encryptFile: infile = /var/log/tivoLog.prv.gz outfile = /var/log/tivoLog.prv.gz.bfg keyname = BACKHAUL_PRIVATE
Aug 26 15:12:04 (none) comm[122]: About to execute: /tvbin/genkey 128 1 2>&1
Aug 26 15:12:04 (none) comm[122]: Command succeeded
Aug 26 15:12:04 (none) comm[122]: EncryptLog: key was empty for BACKHAUL_PRIVATE
Aug 26 15:12:04 (none) comm[122]: Done with actual private logs processing
Aug 26 15:12:04 (none) comm[122]: About to execute: /tvbin/crypto -gsn 2>&1
Aug 26 15:12:05 (none) comm[122]: Command succeeded
Aug 26 15:12:05 (none) comm[122]: About to execute: /tvbin/crypto -gsv 2>&1
Aug 26 15:12:06 (none) comm[122]: Command succeeded
Aug 26 15:12:07 (none) comm[122]: About to execute: /tvbin/crypto -x -gek 2>&1
Aug 26 15:12:13 (none) comm[122]: Command succeeded
Aug 26 15:12:13 (none) comm[122]: SvcLogRqst: open(/var/log/svclog.tmp)ed (tmpfd = 19)
Aug 26 15:12:13 (none) comm[122]: SvcLogRqst: open(/var/log/svclog.upload)ed (uploadfd = 20)
Aug 26 15:12:13 (none) comm[122]: SvcLogRqst: final (351 bytes)::read() (status = 0)
Aug 26 15:12:13 (none) comm[122]: SvcLogRqst: unlink(/var/log/svclog.tmp)ed (status = 0)
Aug 26 15:12:13 (none) comm[122]: SvcLogRqst: rename failed (/var/log/commlog probably doesn't exist) skipping
Aug 26 15:12:13 (none) comm[122]: Start TCD411 Request ==================
Aug 26 15:12:13 (none) comm[122]: areaCode: 002
Aug 26 15:12:13 (none) comm[122]: prefix: %2C%23401
Aug 26 15:12:13 (none) comm[122]: dialInAreaCode:
Aug 26 15:12:13 (none) comm[122]: curPhNum:
Aug 26 15:12:13 (none) comm[122]: objVer:
Aug 26 15:12:13 (none) comm[122]: tcdId: 0020000202190EF
Aug 26 15:12:13 (none) comm[122]: callId: 1125069097
Aug 26 15:12:13 (none) comm[122]: dialPrefix: %2C%23401
Aug 26 15:12:13 (none) comm[122]: dialToneCheck: 0
Aug 26 15:12:13 (none) comm[122]: offHookDetect: 0
Aug 26 15:12:13 (none) comm[122]: tonePulseDial: T
Aug 26 15:12:13 (none) comm[122]: callWaitPrefix:
Aug 26 15:12:13 (none) comm[122]: tollFreeAuth: 1
Aug 26 15:12:13 (none) comm[122]: callType: TS_SR_ACCEPTED
Aug 26 15:12:13 (none) comm[122]: swVerName: 3.0-01-1-000
Aug 26 15:12:13 (none) comm[122]: End TCD411 Request ==================
Aug 26 15:12:13 (none) comm[122]: sigType=st=2 connector=con=1...
Aug 26 15:12:13 (none) comm[122]: Error getting the Avalanche Disk Directories: errNmNameNotFound
Aug 26 15:12:13 (none) comm[122]: Start Ident ==================
Aug 26 15:12:13 (none) comm[122]: version: 3
Aug 26 15:12:13 (none) comm[122]: centerID: 0020000202190EF
Aug 26 15:12:13 (none) comm[122]: reasonCode: 6
Aug 26 15:12:13 (none) comm[122]: softwareDesc: 6406306-51|6406288-1|6406290-1|6406292-1|6406294-1|6406296-1|6406298-1|6406300-1|6406302-1|6406304-1|6406307-1|6406308-1|6406309-1|6406310-1|6406311-1|6406312-1|6406313-1|6406314-1|6406315-1|6406316-1|6406317-1|6406318-1|6406319-1|6406
Aug 26 15:12:13 (none) comm[122]: 320-1|6406321-1|6406322-1|6406323-1|6406324-1|6406325-1|6406326-1|6406327-1|6406328-1|6406329-1|6406330-1|6406331-1|6406332-1|6406333-1|6406334-1|6406335-1|6406336-1|6406337-1|6406338-1|6406339-1|6406340-1|6406341-1|6406342-1|6406343-1|6406344-1|6406345-1|
Aug 26 15:12:13 (none) comm[122]: 6406346-1|6406347-1|6406348-1|6406349-1|6406350-1|6406351-1|6406352-1|6406353-1|6406354-1|6406355-1|411986-104|412025-19|412046-11|412086-19|412107-19|412149-71|412202-19|412214-6|

[wbeasley]

tclient log - part 2 - and segment from tclient as attachment

Aug 26 15:12:13 (none) comm[122]: locationID: 02113-27
Aug 26 15:12:13 (none) comm[122]: sequenceCookie: 12345678
Aug 26 15:12:13 (none) comm[122]: headendID:
Aug 26 15:12:13 (none) comm[122]: headendHisto:
Aug 26 15:12:13 (none) comm[122]: headendWorst:
Aug 26 15:12:13 (none) comm[122]: showcaseDesc: showcase0-0
Aug 26 15:12:13 (none) comm[122]: inventoryFile:
Aug 26 15:12:13 (none) comm[122]: waitingCount: 0
Aug 26 15:12:13 (none) comm[122]: confInfo: :202.36.218.218:8888::::
Aug 26 15:12:13 (none) comm[122]: dialConfig: 127
Aug 26 15:12:13 (none) comm[122]: messageDesc:
Aug 26 15:12:13 (none) comm[122]: irdbVersion:
Aug 26 15:12:13 (none) comm[122]: genreVersion:
Aug 26 15:12:13 (none) comm[122]: logoVersion:
Aug 26 15:12:13 (none) comm[122]: affiliationVersion:
Aug 26 15:12:13 (none) comm[122]: showcaseVersion:
Aug 26 15:12:13 (none) comm[122]: demoMode:
Aug 26 15:12:13 (none) comm[122]: swVerName: 3.0-01-1-000
Aug 26 15:12:13 (none) comm[122]: apgOnly:
Aug 26 15:12:13 (none) comm[122]: useChksums: TRUE
Aug 26 15:12:13 (none) comm[122]: premiumShowcases:
Aug 26 15:12:13 (none) comm[122]: captureRequests:
Aug 26 15:12:13 (none) comm[122]: menuItems:
Aug 26 15:12:13 (none) comm[122]: collabData:
Aug 26 15:12:13 (none) comm[122]: signedFiles:
Aug 26 15:12:13 (none) comm[122]: otherDatasets:
Aug 26 15:12:13 (none) comm[122]: rbBackgrounds:
Aug 26 15:12:13 (none) comm[122]: dataGroupList:
Aug 26 15:12:13 (none) comm[122]: lastAvalDownload: 0,0 0,0
Aug 26 15:12:13 (none) comm[122]: userInitiated: 1
Aug 26 15:12:13 (none) comm[122]: mfsTotalApp: 785168
Aug 26 15:12:13 (none) comm[122]: mfsAvailApp: 763888
Aug 26 15:12:13 (none) comm[122]: mfsTotalMedia: 388595712
Aug 26 15:12:13 (none) comm[122]: mfsAvailMedia: 66271232
Aug 26 15:12:13 (none) comm[122]: clipsTotalSize: 10000000
Aug 26 15:12:13 (none) comm[122]: clipsAvailSize: 9948800
Aug 26 15:12:13 (none) comm[122]: rbTotalSize: 0
Aug 26 15:12:13 (none) comm[122]: rbAvailSize: 0
Aug 26 15:12:13 (none) comm[122]: tcdId: 0020000202190EF
Aug 26 15:12:13 (none) comm[122]: callId: 1125069097
Aug 26 15:12:13 (none) comm[122]: sourceParameterList: st=2,con=1,drm=,ekr=1,ccn=,brn=,lin=
Aug 26 15:12:13 (none) comm[122]: configParameterList: zip=02113,dar=0,rcq=40,tz=1,as=1,tun=,suc=0,sta=3, exp=0
Aug 26 15:12:13 (none) comm[122]: iceboxinfo:
Aug 26 15:12:13 (none) comm[122]: timeStamp: ...
Aug 26 15:12:13 (none) comm[122]: End Ident ==================
Aug 26 15:12:13 (none) comm[122]: CallService: Start err 0
Aug 26 15:12:13 (none) comm[122]: CAM_ID not found.
Aug 26 15:12:14 (none) comm[122]: CallStatusReporter: Phase: Dial, Status In Progress
Aug 26 15:12:14 (none) comm[122]: CallStatusReporter: sending message "CL|30"
Aug 26 15:12:14 (none) comm[122]: Backdoor code 4, enable calls via broadband
Aug 26 15:12:14 (none) comm[122]: Using Ethernet. Not starting modem/pppd.
Aug 26 15:12:14 (none) comm[122]: CallStatusReporter: Phase: Start_Auth, Status In Progress
Aug 26 15:12:20 (none) comm[122]: CallStatusReporter: sending message "ST|33"
Aug 26 15:12:41 (none) comm[122]: CommUtil: connection to host 202.36.218.218, port 8888, err 0x50005
Aug 26 15:12:41 (none) comm[122]: tmk tcp connect failed, reason = Operation now in progress
Aug 26 15:12:41 (none) comm[122]: drainGetPostQ: doXfer failed err=327685 (0x50005)
Aug 26 15:12:41 (none) comm[122]: NetAgent: drainPostQ failed, err = 0x50005
Aug 26 15:12:41 (none) comm[122]: CallService: NetAgent Process err 327685
Aug 26 15:12:41 (none) comm[122]: CallService: NetAgent failed, status 0x50005
Aug 26 15:12:41 (none) comm[122]: CallService: EndCall start
Aug 26 15:12:43 (none) comm[122]: CallStatusReporter: Turning off-hook LED off
Aug 26 15:12:43 (none) comm[122]: Recover private logs
Aug 26 15:12:43 (none) comm[122]: Opening old private log files
Aug 26 15:12:43 (none) comm[122]: Reverting private logs
Aug 26 15:12:43 (none) tcphonehome[122]: CallService return status 0x50005
Aug 26 15:12:49 (none) comm[122]: CallStatusReporter: Phase: Start_Auth, Status Failed
Aug 26 15:12:49 (none) comm[122]: CallStatusReporter: sending message "EX|14"
Aug 26 15:12:49 (none) tcphonehome[122]: TClient failed: EX|14
Aug 26 15:12:49 (none) tcphonehome[122]: Sending dialup event, subtype 8, msg EX|14
Aug 26 15:12:49 (none) tcphonehome[122]: setCallStatus called with: Failed state 0
Aug 26 15:12:59 (none) tcphonehome[122]: LastCallAttempt at 1125069097
Aug 26 15:12:59 (none) tcphonehome[122]: setting call status to: Failed
Aug 26 15:12:59 (none) tcphonehome[122]: setting call in progress to 0 (second successCount)
Aug 26 15:12:59 (none) tcphonehome[122]: Setting callActive to 0
Aug 26 15:12:59 (none) comm[122]: CallStatusReporter: sending data changed event 20
Aug 26 15:12:59 (none) tcphonehome[122]: destroying CommGlobals!
Aug 26 15:12:59 (none) tcphonehome[122]: pCommMempool empty
Aug 26 15:12:59 (none) tcphonehome[122]: Setting MCP PhoneHome action: ENABLED

[Tuatara]

Excellent, I'm keen to see the result of this.

Tried it, and sorry, it still says "Failed. Service unavailable."

It does spend a long time with the "Connection ..." message (this is in tivoweb, obviously).

I updated tclient.conf; it's not using emuProxy.



[TiVo [p0] ~]# tail -n 15 /etc/tclient.conf
#
000:
# Dennis' Emulator
126::66.23.218.193:80:::
# This is for the server emulator on minnie. Trouble if your ISP blocks HTTP .9
#127::131.244.9.101:80:::

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

# Matt for NZ
#127::64.151.65.200:80:::
#127::210.48.107.133:8000:::
127::202.36.218.218:8888:::

Would any logfiles be helpful? Or is there a glaring error in my config above? ;-)

Cheers
Matt

[ehintz]

All better now...

http://forums.oztivo.net/showthread.php?t=710

[wbeasley]

Thanks, that sorted my problem :)

[DJC]

Thanks, that sorted my problem :)

.. huh? so after all that you never managed to move off the original emulator?

[wbeasley]

I tried the test one you set up first
127::202.36.218.218:8888:::

then the dev emulator 127::210.48.107.133:8000:::
(i don't have logos installed)

then 127::64.151.65.200:80::: and no problems.
(all these with guided setup)

My image is 3.0 version 1

Thanks for your time trying to resolve the issue it was really appreciated.
I will switch to 127::210.48.107.133:8000::: on sunday and see if i can upload data now that guided setup has completed.

[DJC]

Peter: is there a hack that needs to be applied to the emulator for this to work.... or are you talking about the code of emuProxy2 ? cheers/DJC



If the emuproxy2 was working properly the 2nd 'HTTP Header' line should be 1.1 and not 1.0 still. It's ok for the 'Uploading Header' line to show 1.0.

Perhaps the hack has not been implemented on the NZ server.

Peter.

[petestrash]

Peter: is there a hack that needs to be applied to the emulator for this to work.... or are you talking about the code of emuProxy2 ? cheers/DJC

I have not played with emulators since emuProxy2 has been used.

But from my understanding and the comments associated with its use EmuProxy2 works with a hack in the emulator to accept the header "TivoURLBase" which is the base url to give back to the Tivo when specifying data paths.

For the specific changes to the emulator you would be best asking Warren or Ed.

Peter.

[wbeasley]

I switched to 127::210.48.107.133:8000::: this evening and managed to download guide data fine.

Looks like it's only a problem for me when I re-run guided setup.
I did delete guide data and season passes when i was troubleshooting the old emulator, perhaps this was a factor.

[DJC]

Hmmm ... odd.

I think the only way to get to the bottom of this one is to setup a test scenario..

I'm going continue with dropping my tivo of the net for while and see the result when re-connecting.

[Tuatara]

I had the problem and didn't run guided setup at all. I was about to try that, having read MrGadget's post earlier in this thread, when Ed's emulator returned to life.

Since then I've done a fresh install off Orac, using the latest image which creates a correctly-sized swap partition. That went flawlessly.

Thanks for your help. It seems everyone's situation was subtly different so trying to reproduce it might be a fraught process ;-).

Cheers
Matt

[DJC]

It seems everyone's situation was subtly different so trying to reproduce it might be a fraught process ;-).

I'll second that statement!

No luck in reproducing so far.

[slangnz]

Mine has died again.

Haven't re-run GS or anything. Talking to 64.151.65.200

Apologies for the long post, but this is the http communication in it's entirety. Doesn't look like it's actually getting the data to me, although I don't understand the communications in detail anyway. Anyone else have an idea what's gone wrong this time?

Cheers -

First http connection:

POST /tivo-service/mlog.cgi HTTP/1.0
Content-Length: 285

tclient_hangup TCD_ID=000134922972058 CALL_ID=1125378842 TIME=1125378908 CODE=0
tclient_ticket TCD_ID=000134922972058 CALL_ID=1125378842 TIME=1125378908 STATUS=None TICKET=None VALUE=None
tclient_result TCD_ID=000134922972058 CALL_ID=1125378842 TIME=1125378916 STATUS=Succeeded CODE=1

Reply:
HTTP/1.1 200 OK
Date: Tue, 30 Aug 2005 07:10:46 GMT
Server: Apache/1.3.33 (Unix) (Gentoo/Linux) PHP/4.3.11 mod_gzip/1.3.26.1a
Connection: close
Content-Type: text/plain; ch****t=ISO-8859-1

Done.

Second http connection:

POST /tivo-service/TCD411.cgi HTTP/1.0
Content-Length: 231
Content-Type: application/x-www-form-urlencoded
TCD_ID: 000134922972058
CALL_ID: 1125429005

AreaCode=002&Prefix=%2C%23401&DialInAreaCode=&CurPh=&ObjVer=&TcdId=000134922972058&DialPrefix=%2C%23401&CallWaitPrefix=&DialToneCheck=0&OffHookDetect=0&TonePulseDial=T&TollFreeAuth=2&CallType=TS_SR_ACCEPTED&SwVerName=3.0-01-1-000&

Reply:

HTTP/1.1 200 OK
Date: Tue, 30 Aug 2005 07:10:47 GMT
Server: Apache/1.3.33 (Unix) (Gentoo/Linux) PHP/4.3.11 mod_gzip/1.3.26.1a
Connection: close
Content-Type: text/plain; ch****t=ISO-8859-1

ERR_MSG=
AREA_CODE_OBJ=OK
TOLL_FREE_AUTH=0
TOLL_FREE_NUM=

Third http connection:

POST /tivo-service/HServer.cgi HTTP/1.0
Content-Type: text/plain
IDB_VERSION: 3
IDB_CENTERID: 000134922972058
IDB_REASONCODE: 1
IDB_SWDESC: 6406306-51|6406288-1|6406290-1|6406292-1|6406294-1|6406296-1|6406298-1|6406300-1|6406302-1|6406304-1|6406307-1|6406308-1|6406309-1|6406310-1|6406311-1|6406312-1|6406313-1|6406314-1|6406315-1|6406316-1|6406317-1|6406318-1|6406319-1|6406320-1|6406321-1|6406322-1|6406323-1|6406324-1|6406325-1|6406326-1|6406327-1|6406328-1|6406329-1|6406330-1|6406331-1|6406332-1|6406333-1|6406334-1|6406335-1|6406336-1|6406337-1|6406338-1|6406339-1|6406340-1|6406341-1|6406342-1|6406343-1|6406344-1|6406345-1|6406346-1|6406347-1|6406348-1|6406349-1|6406350-1|6406351-1|6406352-1|6406353-1|6406354-1|6406355-1|411986-104|412025-19|412046-11|412086-19|412107-19|412149-71|412202-19|412214-6|
IDB_LOCATIONID: 02113-27
IDB_SEQCOOKIE: 12345678
IDB_HEADEND: AK02113-13025
IDB_ST_HIST: AK02113:13025-81
IDB_ST_WORST: AK02113:7998001,7998002,7998003,7998004,7998005,79 98006,7998007,7998008,7998010,7998011
IDB_SHOWCASES: showcase0-0
IDB_INVFILE:
IDB_WAITCOUNT: 0
IDB_TCINFO: :64.151.65.200:80::::
IDB_CURCODE: 127
IDB_MESSAGE_DESC:
IDB_IRDBVERSION:
IDB_GENREVERSION:
IDB_LOGOVERSION:
IDB_AFFILIATIONVERSION:
IDB_SHOWCASEVERSION:
IDB_DEMOMODE:
IDB_CUR_SWNAME: 3.0-01-1-000
IDB_APG_ONLY:
IDB_USECHKSUMS: TRUE
IDB_PREMIUM_SHOWCASES:
IDB_CAPTURE_REQUESTS:
IDB_MENU_ITEMS:
IDB_COLLAB_DATA:
IDB_SIGNED_FILES:
IDB_OTHER_DATASETS:
IDB_RB_BACKGROUNDS:
IDB_DATAGROUPLIST:
IDB_LAST_AVL_DL: 0,0 0,0
IDB_USER_INITIATED: 1
IDB_MFS_TOTAPP: 785168
IDB_MFS_AVAILAPP: 757784
IDB_MFS_TOTMEDIA: 388333568
IDB_MFS_AVAILMEDIA: 22325248
IDB_MFS_TOTCLIPS: 10000000
IDB_MFS_AVAILCLIPS: 9948800
IDB_MFS_TOTRBACKS: 0
IDB_MFS_AVAILRBACKS: 0
TCD_ID: 000134922972058
CALL_ID: 1125429005
IDB_SOURCEPARAMETERS: st=5,con=3,drm=,ekr=0,ccn=20001,brn=MOTOROLA,lin=1
IDB_CONFIGPARAMETERS: zip=02113,dar=0,rcq=100,tz=7,as=1,tun=,suc=7,sta=3 ,exp=0
IDB_ICEBOXINFO:
IDB_TIMESTAMP: 1125429044
IDB_URL_PARAM_VERS: 1

Reply:

HTTP/1.1 200 OK
Date: Tue, 30 Aug 2005 07:10:48 GMT
Server: Apache/1.3.33 (Unix) (Gentoo/Linux) PHP/4.3.11 mod_gzip/1.3.26.1a
Connection: close
Content-Type: text/plain; ch****t=ISO-8859-1

ERR_MSG=
VERSION=3
CODE=1
SW_LIST=NONE
BACK_CH_PRV=NONE
BACK_CH_PUB=NONE
BACK_CH_LOG=@http://64.151.65.200:80/tivo-service/acceptfile.cgi
TIME_SVC=/bin/ntpdate -b 127.0.0.1
SEQ_COOKIE=12345678
INV_FILE=
NO_PRV_BACKHAUL=1
SERVICE_STATE=3
STATE_EXPIRE=0
SW_SYSTEM_NAME=3.0-01-1-000
INFO_CODE=
TCD_MESSAGE=
GLOBAL_MESSAGES=
KEY_SERVER=
BACK_CH_THUMB=NONE
FORCE_BACKHAUL=0
PUBLIC_LOG_FILTER=
DB_LOAD_ORDER=PG.*
REGEN_TOKEN=0
BACKHAUL_DATA_ON=0
PERSONAL_DATA_ON=0
DATA_GROUP_LIST=
CAPRQST_URL=
TIMEOUT=
SUCCESS_TIME=
FAIL_TIME_LIST=
MERC_URL=
MERC_UDP=
MERC_ENABLED=
TCP_TIME_SVC=204.176.49.2
DATA_GROUP_INT_LIST=

Fourth http connection:

POST /tivo-service/mlog.cgi HTTP/1.0
Content-Length: 259

ird_id TCD_ID=000134922972058 CALL_ID=1125429005 TIME=1125429044 ID=53972058
tcd_driveid TCD_ID=000134922972058 CALL_ID=1125429005 TIME=1125429044 HDA=3LJ2JHVM HDB=Unknown
tclient_cmd TCD_ID=000134922972058 CALL_ID=1125429005 TIME=1125429096 CMD=ntp STATUS=1

Reply:

HTTP/1.1 200 OK
Date: Tue, 30 Aug 2005 07:11:36 GMT
Server: Apache/1.3.33 (Unix) (Gentoo/Linux) PHP/4.3.11 mod_gzip/1.3.26.1a
Connection: close
Content-Type: text/plain; ch****t=ISO-8859-1

Done.

[DJC]

Mine has died again.

Haven't re-run GS or anything. Talking to 64.151.65.200


Have you been on or near the orac emulators??

[slangnz]

Have you been on or near the orac emulators??

Nah man. Haven't screwed with the config at all. Still running the same config since I first installed it.

Cheers -

[DJC]

Nah man. Haven't screwed with the config at all. Still running the same config since I first installed it.
Cheers -

Yeah good, just checking ... since you have connectivity it could have been a slice versioning issue, the develpment emulators have slice numbers > the standard emulator.

...but obviously not the problem...

[bcolloty]

Hi All,

I'm getting a Service Unavailable message when I try and force a daily call from TivoWebPlus.

I've been running quite happily for the last few months since getting my Tivo but have had a few problems in the last week or so.
I've been connecting to the dev server on

I ended up with the "Clock is Warped" issue last week and managed to solve this with the Touch and re-index solution. Along the way I did a refresh of my guide data which seemed to work ok,

However since then I haven't managed to complete a daily call - I get a connection failed message.

I've tried troubleshooting my network settings as per the document on OzTivo but all seems in order - I can ping the server from the Tivo and do a wget and the network is definately up.

I'm at a bit of a loss as to what to try next. Should I try connecting to the standard emulator? do I need to do a reset of the guide data to do this?

Any help would be appreciated

Thanks,

Brendon.

[ehintz]

My emulator's running fine at the moment... AFAIK the port 80 dev emulator and mine are the same thing, though I'd get verification on that. But as far as I know you can swap from dev port 80 to original port 80 with no issues at all.

(btw, if I'm wrong on this let me know; I'll try to ensure that mine is either identical to, or as close as possible, to the dev one, just for consistencies sake)

[ehintz]

(btw, if I'm wrong on this let me know; I'll try to ensure that mine is either identical to, or as close as possible, to the dev one, just for consistencies sake)
Heh. Just read earlier in the thread that the dev numbering scheme is higher... Let me know what it is and I'll modify mine to be the same. At the moment I'm just taking the day the slice is downloaded and using it as the base name of the slice (AK$ZIP_$TODAYEPOCH-$TODAYEPOCH+7). Obviously this is quite easy to change to match the dev emulator if need be.

[ehintz]

Heh. Just read earlier in the thread that the dev numbering scheme is higher... Let me know what it is and I'll modify mine to be the same. At the moment I'm just taking the day the slice is downloaded and using it as the base name of the slice (AK$ZIP_$TODAYEPOCH-$TODAYEPOCH+7). Obviously this is quite easy to change to match the dev emulator if need be.
And in the spirit of full disclosure, I'm also running a cronjob every 6 days which takes the nonag slice, names it AK$ZIP_$TODAYEPOCH, and drops it in the listings directory. The emulator code deletes it after about 5 days, hence the cronjob to regenerate it. Somewhat kludgy but it does ensure that nobody gets the nonag message (it only needs to be loaded once, but keeping it there ensures that newbies get the benefits of nonag as well).

[DJC]

Greets Ed:

The post about the emulator running higher numbers, is in regard to the slice, the slice version numbers in the dev system have a higher number than those jaidev creates.

The slice names are the same at epoch, except dev system is +14, with additional information for TVSN inserted in the database as a permanent NoNag scenario.

Cheers/DJC

[bcolloty]

Hi again,

Just a quick note to let you know that I seemed to have fixed it - still not quite sure how. I re-ran guided setup and made sure that I went into the Phone settings - I didn't actually change anything but obviously whatever was stopping me connecting was reset somehow. Wtatever it was - it's all working fine today.

I did just want to say a big thanks to everyone out there who puts their time and efforts into maintaining and improving the guide info - you've done a great jov and without you my Tivo wiould just be an ugly black box taking up space in my stereo cabinet :)

Just my $0,02

Brendon.

[ehintz]

Greets Ed:

The post about the emulator running higher numbers, is in regard to the slice, the slice version numbers in the dev system have a higher number than those jaidev creates.

Cheers/DJC

And just to clarify; port 80 is jaidev's slices, port 8080 (or whichever it is) runs the dev slices, right?

[DJC]

And just to clarify; port 80 is jaidev's slices, port 8080 (or whichever it is) runs the dev slices, right?

Port 80 and 8000 both run dev slices. Port 8000 is the one for experimenting, has logo slices and a bit of extra stuff. Port 80 is more of a semi-production version of port 8000.

Your emu is the only one running jaidev's slices.

[ehintz]

Port 80 and 8000 both run dev slices. Port 8000 is the one for experimenting, has logo slices and a bit of extra stuff. Port 80 is more of a semi-production version of port 8000.

Your emu is the only one running jaidev's slices.

Ahh, got it. Thanks for the clarification.

[Pastos]

Although much of the technical aspect goes over my head I thought I'd add my bit to this discussion in case it is helpful.
I was originally on the standard emulator with no problems. Then I found that daily calls would suceed but no guide data was downloaded.
Clearing guide data did not help so after reading some of the discussion here I thought I would try the development emulator on port 8000. The first call succeeded but when that data ran out subsequent calls failed with service unavailable. Clearing guide data did not help and changing to port 80 did not work either. However changing back to the standard emulator seems to have done the trick at this stage and I now have guide data. I did not need to re run guided setup. I'm not sure if there is a general conclusion as to what the problem is but I hope this may help in some way. I would also like to add my thanks to all those that make the Tivo service possible. There is no way I could go back to that horrible sky guide :eek:

Cheers

Pastos

[tenty]

Content-Type: text/plain; ch****t=ISO-8859-1


Oh btw, My appologies on why this comes up as stars... I had an incorrect censorship setting which is now fixed that I did not notice before. It should read charset=ISO-8859-1 except it was filtering out the four letters inbetween. I'm sure you can figure it out yourself as I did!

Cheers!

[wbeasley]

I switched to 127::210.48.107.133:8000::: this evening and managed to download guide data fine.

Looks like it's only a problem for me when I re-run guided setup.
I did delete guide data and season passes when i was troubleshooting the old emulator, perhaps this was a factor.

FYI, I have been successfully useing the DEV 8000 daily since this posting but ran out of guide data Wednesday (Tivo was off my network for a week) and when i tried a manual update last night it failed as previous. I switched back to the the old emulator and downloaded guide data fine,

[bikermike]

Hi all

I'm using dialup into Actrix - same problem with 'service not answering' for the past 2 weeks or so. No changes to setup, actrix assure me no change. I'll reset my guide data tonight, change the em to 210.48.107.133 and see what happens. Very weird. 2 other tivos I've set up - dialup into xtra & ihug are both ok at this stage.
Cheers
Mike

[ehintz]

Hi all

I'm using dialup into Actrix - same problem with 'service not answering' for the past 2 weeks or so. No changes to setup, actrix assure me no change. I'll reset my guide data tonight, change the em to 210.48.107.133 and see what happens. Very weird. 2 other tivos I've set up - dialup into xtra & ihug are both ok at this stage.
Cheers
Mike

64.151.65.200 is up fine... I'm downloading a slice from it even as I type. AFAIK it's been fine for several weeks at the least... I'd be suspecting something with the dialup connection. IIRC, the message for a down emulator is "Failed, service unavailable"; not answering could be an issue on the dialup side. Just guessing though.

[petestrash]

Try plugging a phone in parallel to the TiVo and listen when it makes the call.

See if it is dialing out, the ISP is answering, and then comms start.

One of the posibilities with the 'service not answering' message is you might have a fried modem. It may either not dial the number at all or if it does dial it is deaf to the ISP answering the call and will not initiate comms.

Peter

[bikermike]

Sorry - the error is service unavailable - same as everyone else. I can hear the modem dial & connect thru to actrix. This baby was running sweet, no changes for months, then the calls just stopped getting thru...I've just tried changing the ip, deleting guide data and rerunning gs but still no joy.

[bikermike]

ok. so the error is service not answering. Well at least it is now but I'd swear it was unavailable...I saw somewhere theres some info on using an external modem thru the serial port. Let me see how I go with that. Thanks for the tips guys...

Cheers
Bart :)