Unable to connect and update EPG: N17 Error

[MHurwood]

G'day all,

So, I got my TiVo back from Adam a couple of weeks ago. (Many thanks for a great and quick job, Adam!) I know he did a at least one guide update while it was with him because when I first plugged it in in had new (OzTivo) program guide data and I was able to set up some new season passes, etc.

I'm also 99% sure I managed to do some more guide updates over the next few days. I then had some unrelated network problems (a router basically going bad on me) which caused problems for the TiVo but also for my Fetch box and a few other devices on the network, so I stopped getting guide updates for a bit.

Today I replaced my router and got most things up and running on the network correctly again, but when I went to force the guide to update I continued to get nothing but "failed to connect" errors, more specifically a "N17" errors, much as had for the previous couple of days, but which I'd put down to my other network issues. I double-checked network settings, and even confirmed I could pick up things like my pyTivo shares on the network, so it looked like the TiVo was defainetlyy connecting correctly to at least the local network, but still no contact to the mothership.

Eventually I did a "Delete Program Guide & Top Do List" and even redid the Guided Setup. During Guided setup it happily did the first connection test/process just fine, but I failed with a N17 error again once I reached the stage of downloading the EPG.

I've tried using DHCP and a static IP. I've also tried assigning the Tivo as the DMZ host on the router, in case some weird port blocking was the issue, but with no luck. I will note that once when I was assigning the IP address manually I had the unit spontaneously reboot on me.

Where do I go from here? Are there other logs I can look at somewhere to see why this might be going wrong?

Cheers,

Michael

[DavidKeegel]

Through the TiVo you can find logs at Messages & Settings > Account & System Information > Backdoors (backdoor-mode) > View Logs.
I would have a look at /var/log/tclient (right about half a dozen times) or if it has been a while since you got the N17 error then /var/log/Otclient (old log).
If you prefer, you could scp or winscp /var/log/tclient from your tivo to a PC (assuming you know the root password set when TivoInstaller 0.6 was run, and you know the local IP address of the tivo).
If you can't work out what is going on, you can post the last 4 digits/letters of your TSN (or PM them to me) and we can check logs on the OzTiVo mothership (although the tclient logs are usually more useful).

As noted on http://hd.oztivo.net/twiki/bin/view/S3FAQ/S3MyTiVoHasWrongGuideData, if you do Clear Program Information and To Do List then you won't be resent guide data which you previously downloaded from the oztivo mothership. I don't think this is your most likely problem, but if it was happening it would fix it self the following day when the oztivo mothership had new guide data to download.

I assume you are using Dial Code 140, let us know if its something different.

[MHurwood]

Hi David,

Alas, I'm now stuck in the Guided Setup, so can't get into the logs through the menus. Because I didn't do the re-imaging myself I didn't set the SCP password, so I don't know if I can get to them that way. Is there a default password or should I ask Adam? I know the IP address no problem.

I'm pretty sure that in my explorations before this though I did see the 140 dial-in code on one of the settings screens. In previous attempts I also got the "command line" style text overlay where it said it was updating the dial code, or words to that effect, which is obviously new behavior for the patched system.

Since my guide was completely empty it had obviously not (successfully) downloaded any data for a few days, so I'm thinking that the server avoiding resending data is probably not the problem.

The last four digits of my TSN are "6543", but if want to hold off on digging that up until I rule out getting SCP access into the unit that's fine.

Thanks,

Michael

[MHurwood]

Hello again,

Ok, I've got into my system using SCP and I've grabbed that log file. Bits of the log file certainly make me think things are configured OK, like:

Dec 21 22:13:31 (none) Ident[1101]: confInfo: :hd.oztivo.net:8000:::::
Dec 21 22:13:31 (none) Ident[1101]: dialConfig: 140


Here's the whole last bit of my log, before it basically gets stuck in an endless loop of retries:


Dec 21 22:13:31 (none) CommGlobals[1101]: --- Rqst Summary Start ---
Dec 21 22:13:31 (none) CommGlobals[1101]: 1 modLog status=none addr=hd.oztivo.net:8000 send=/var/log/svclog.upload.gz
Dec 21 22:13:31 (none) CommGlobals[1101]: 2 commerceLog status=none addr=hd.oztivo.net:8000 send=/var/log/commlog.upload
Dec 21 22:13:31 (none) CommGlobals[1101]: 3 mercuryLog status=none addr=hd.oztivo.net:8000 send=/var/log/merclog.upload.gz
Dec 21 22:13:31 (none) CommGlobals[1101]: 4 elog status=none addr=hd.oztivo.net:8000 send=/var/log/elog.upload.gz recv=/var/log/elog.download
Dec 21 22:13:31 (none) CommGlobals[1101]: 5 HServerRqst status=none addr=hd.oztivo.net:8000 send=/var/tmp/HServer.send recv=/var/tmp/HServer.recv
Dec 21 22:13:31 (none) CommGlobals[1101]: --- Rqst Summary End ---
Dec 21 22:13:31 (none) CommGlobals[1101]: CacheCamState enters......
Dec 21 22:13:31 (none) CommGlobals[1101]: Running simple call to get CA state...
Dec 21 22:13:31 (none) CommGlobals[1101]: CacheCamState found 0 cams
Dec 21 22:13:31 (none) CommGlobals[1101]: Cached cam state as <9>
Dec 21 22:13:31 (none) CommGlobals[1101]: CacheTuningResolverState enters......
Dec 21 22:13:31 (none) CommGlobals[1101]: Cached TR state
Dec 21 22:13:31 (none) CallStatusReporter[1101]: UpdateStatus InProgress phase=3 code=78
Dec 21 22:13:31 (none) RunmeExecutor[1101]: No runmes for phase StartCall
Dec 21 22:13:31 (none) CallService[1101]: Sending Broadband UpRequest
Dec 21 22:13:31 (none) NetworkAccessSession[1625]: received an UP_RESPONSE
Dec 21 22:13:31 (none) CallService[1101]: Result of UpRequest is 1
Dec 21 22:13:31 (none) CallService[1101]: ConnectStart
Dec 21 22:13:31 (none) RunmeExecutor[1101]: No runmes for phase ConnectStart
Dec 21 22:13:31 (none) CallStatusReporter[1101]: UpdateStatus InProgress phase=4 code=33
Dec 21 22:13:31 (none) CallService[1101]: InCall updatesubphase SP_START_AUTH
Dec 21 22:13:31 (none) RunmeExecutor[1101]: No runmes for phase InCall
Dec 21 22:13:31 (none) CallStatusReporter[1101]: UpdateStatus InProgress phase=4 code=51
Dec 21 22:13:31 (none) MlogRqst[1101]: 1 modLog status=open addr=hd.oztivo.net:8000 send=/var/log/svclog.upload.gz
Dec 21 22:13:31 (none) CommUtil[1101]: connect host=hd.oztivo.net port=8000 TvStatus=0x0
Dec 21 22:13:31 (none) MlogRqst[1101]: 1 modLog header: POST /tivo-service/mlog.cgi?gzip HTTP/1.0^M TCD_ID: 663002180206543^M CALL_ID: 1513894230^M SW_VER: 11.3b10.2017.10.11-1506-01-2-Z-663^M Content-Length: 586^M ^M
Dec 21 22:13:32 (none) MlogRqst[1101]: nRecv=178: HTTP/1.1 200 OK^M Date: Thu, 21 Dec 2017 22:13:32 GMT^M Server: Apache/2.4.25 (Debian)^M Content-Length: 6^M Connection: close^M Content-Type: text/plain; charset=ISO-8859-1^M ^M Done.
Dec 21 22:13:32 (none) MlogRqst[1101]: read HTTP Header: HTTP/1.1 200 OK^M Date: Thu, 21 Dec 2017 22:13:32 GMT^M Server: Apache/2.4.25 (Debian)^M Content-Length: 6^M Connection: close^M Content-Type: text/plain; charset=ISO-8859-1
Dec 21 22:13:32 (none) MlogRqst[1101]: 1 modLog status=open,nSend=742,nRecv=178,close
Dec 21 22:13:32 (none) ElogRqst[1101]: 4 elog status=open addr=hd.oztivo.net:8000 send=/var/log/elog.upload.gz recv=/var/log/elog.download
Dec 21 22:13:33 (none) CommUtil[1101]: connect host=hd.oztivo.net port=8000 TvStatus=0x0
Dec 21 22:13:33 (none) ElogRqst[1101]: 4 elog header: POST /tivo-service/elog.cgi?gzip HTTP/1.0^M TCD_ID: 663002180206543^M CALL_ID: 1513894230^M SW_VER: 11.3b10.2017.10.11-1506-01-2-Z-663^M Content-Length: 34551^M ^M
Dec 21 22:13:34 (none) ElogRqst[1101]: nRecv=486: HTTP/1.1 404 Not Found^M Date: Thu, 21 Dec 2017 22:13:33 GMT^M Server: Apache/2.4.25 (Debian)^M Content-Length: 306^M Connection: close^M Content-Type: text/html; charset=iso-8859-1^M ^M <!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN"> <html><head> <title>404 Not Found</title> </head><body> <h1>Not Found</h1> <p>The requested URL /tivo-service/elog.cgi was not found on this s
Dec 21 22:13:34 (none) ElogRqst[1101]: erver.</p> <hr> <address>Apache/2.4.25 (Debian) Server at debian.emulator.local Port 80</address> </body></html>
Dec 21 22:13:34 (none) ElogRqst[1101]: Err: Bad HTTP response: HTTP/1.1 404 Not Found
Dec 21 22:13:34 (none) ElogRqst[1101]: deleteOutputFile: XXX: Deleting output file "/var/log/elog.download"
Dec 21 22:13:34 (none) ElogRqst[1101]: Warn: failed to write all bytes to disk nWrote=-1 bufSize=486 Bad HTTP response
Dec 21 22:13:35 (none) ElogRqst[1101]: 4 elog status=open,nSend=34709,nRecvErr=1,TvStatus=0xffff ,close,TvStatus=0xffff
Dec 21 22:13:35 (none) NetAgent[1101]: Warn: TvStatus=0xffff drainGetPostQ: doXfer 4 elog failed
Dec 21 22:13:35 (none) NetAgent[1101]: after post nRqst=1 TvStatus=0xffff
Dec 21 22:13:35 (none) NetAgent[1101]: Warn: TvStatus=0xffff drainPostQ failed
Dec 21 22:13:35 (none) CallService[1101]: Warn: TvStatus=0xffff NetAgent Process failed
Dec 21 22:13:35 (none) NetAgent[1101]: flushing all queues
Dec 21 22:13:35 (none) CallService[1101]: Dropping Broadband network reservation
Dec 21 22:13:35 (none) NetworkPingSession[1625]: received a PING RESPONSE
Dec 21 22:13:35 (none) CallStatusReporter[1101]: SetOffHookLed=off
Dec 21 22:13:35 (none) CallStatusReporter[1101]: SetOffHookLed=off
Dec 21 22:13:35 (none) comm[1101]: BackhaulStatus: type=1 hserver=0 tried=0 ok=1
Dec 21 22:13:35 (none) LogMgr[1101]: Recover private logs
Dec 21 22:13:35 (none) LogMgr[1101]: Opening old private log files
Dec 21 22:13:35 (none) LogMgr[1101]: Reverting private logs
Dec 21 22:13:35 (none) LineupWatcher[1101]: FChanged fPending=0
Dec 21 22:13:35 (none) CallService[1101]: Cleanup finished
Dec 21 22:13:35 (none) PhoneHome[1101]: TvStatus=0xffff CallService done
Dec 21 22:13:35 (none) CommGlobals[1101]: --- Rqst Summary Start ---
Dec 21 22:13:35 (none) CommGlobals[1101]: 1 modLog status=open,nSend=742,nRecv=178,close addr=hd.oztivo.net:8000 send=/var/log/svclog.upload.gz
Dec 21 22:13:35 (none) CommGlobals[1101]: 2 commerceLog status=none addr=hd.oztivo.net:8000 send=/var/log/commlog.upload
Dec 21 22:13:35 (none) CommGlobals[1101]: 3 mercuryLog status=none addr=hd.oztivo.net:8000 send=/var/log/merclog.upload.gz
Dec 21 22:13:35 (none) CommGlobals[1101]: 4 elog status=open,nSend=34709,nRecvErr=1,TvStatus=0xffff ,close,TvStatus=0xffff addr=hd.oztivo.net:8000 send=/var/log/elog.upload.gz recv=/var/log/elog.download
Dec 21 22:13:35 (none) CommGlobals[1101]: 5 HServerRqst status=none addr=hd.oztivo.net:8000 send=/var/tmp/HServer.send recv=/var/tmp/HServer.recv
Dec 21 22:13:35 (none) CommGlobals[1101]: --- Rqst Summary End ---
Dec 21 22:13:35 (none) LogMgr[299]: Received the revert complete event
Dec 21 22:13:36 (none) PhoneHome[1101]: ReschedCall reason=4 nFail=4
Dec 21 22:13:36 (none) CallBack[1101]: uiFailure no serverCallback value
Dec 21 22:13:36 (none) PhoneHome[1101]: ReschedCall(after ui failure): nMin=56
Dec 21 22:13:36 (none) PhoneHome[1101]: Next call attempt at 1513897776 (12/21/2017 23:09:36)
Dec 21 22:13:36 (none) PhoneHome[1101]: ReschedCall(4) in 56 min (12/21/2017 23:09:36)
Dec 21 22:13:36 (none) PhoneHome[1101]: Setting PHG:NumFails to 4
Dec 21 22:13:36 (none) comm[1101]: BackhaulStatus: type=0 hserver=0 tried=0 ok=1
Dec 21 22:13:36 (none) PhoneHomeActiveCall[1101]: ReleaseModemLock
Dec 21 22:13:36 (none) PhoneHome[1101]: Setting callActive to 0
Dec 21 22:13:36 (none) PhoneHome[1101]: setCallStatus called with: Failed state 0
Dec 21 22:13:36 (none) PhoneHome[1101]: LastCallAttempt at 12/21/2017 22:10:30
Dec 21 22:13:36 (none) PhoneHome[1101]: setting call status to: Failed
Dec 21 22:13:36 (none) CallStatusReporter[1101]: UpdateStatus Failed phase=0 code=71
Dec 21 22:13:36 (none) comm[1101]: Destroy
Dec 21 22:13:36 (none) DataSetCleaner[1101]: Skipping DataSets cleanup
Dec 21 22:13:39 (none) AreaCodeChore[1101]: ReadDbValues: found: 0, lac: , vers: 0 ph#:

Looking through that I get a 404 error for one of my requests, but I don't know how significant that actually is, and whether it means the error is at the OzTivo end or mine?

I can't post the whole log in the message, but I guess I can attach it if it's worth anyone's while?

Cheers,

Michael

[Owen_B_NZ]

Just been there, done that. Was setting up 1TB drive using 113b10 backup off another drive. Got it all updated and hacked but the same thing happened to me. Turned out I wasn't waiting long enough for the hack to operate, so was trying to access the old server. Saw the hack run, then the problems went away, accessed new mothership and spent a loooonnngg time downloading. I can hear it indexing now, it's a WD Blue drive, possible not the best for TiVo.

[MHurwood]

Just been there, done that. Was setting up 1TB drive using 113b10 backup off another drive. Got it all updated and hacked but the same thing happened to me. Turned out I wasn't waiting long enough for the hack to operate, so was trying to access the old server. Saw the hack run, then the problems went away, accessed new mothership and spent a loooonnngg time downloading. I can hear it indexing now, it's a WD Blue drive, possible not the best for TiVo.

Are you suggesting that I reboot, wait for some extra on-screen activity to show the hack has "run", then continue with the guided setup?

The log files suggests to me that the hack has run on my unit, and did so immediately, as it only references the OzTivo website, not the old US "mind" server. But I'll give it another try!