Problems with dialing in on HR10-250...

[charlestwaters]

Just curious about something...

I have a hacked HR10-250, and recently moved from CA to WA. I am changing the local dialin number, and when I put in the new area code, it dials, connects, then when it gets to "Negotiating...", it hangs up...

Is this because I have a hacked TiVo!? I am using a landling phone from QWest!

[puffdaddy]

I have a hacked HR10-250, and recently moved from CA to WA. I am changing the local dialin number, and when I put in the new area code, it dials, connects, then when it gets to "Negotiating...", it hangs up...I know the answer to your question, and it lies in your HR10-250's log files.

[charlestwaters]

Here's what the log says for this specific call....

I edited out the toll free # that it dials to find the local #, since I saw a post awhile back ago that says that shouldn't be given out!

Log cleared on Thu Sep 14, 2006 by TivoWebPlus
Sep 14 19:18:23 (none) tcphonehome[138]: Setting MCP PhoneHome action: RUNNING
Sep 14 19:18:23 (none) tcphonehome[138]: pCommMempool empty
Sep 14 19:18:23 (none) tcphonehome[138]: forceTollFree is unset
Sep 14 19:18:23 (none) tcphonehome[138]: useBackupTollFree is 1
Sep 14 19:18:23 (none) tcphonehome[138]: phonehome: received message. type = 30 subtype = 3
Sep 14 19:18:23 (none) tcphonehome[138]: creating CommGlobals
Sep 14 19:18:24 (none) tcphonehome[138]: created CommGlobals
Sep 14 19:18:24 (none) tcphonehome[138]: PerformCall, subtype=3 forceTollFree=0 automated=0
Sep 14 19:18:24 (none) tcphonehome[138]: setCallStatus called with: In Progress state 1
Sep 14 19:18:24 (none) tcphonehome[138]: LastCallAttempt at 1158261399
Sep 14 19:18:24 (none) tcphonehome[138]: setting call status to: In Progress
Sep 14 19:18:24 (none) tcphonehome[138]: setting call in progress to 1 (second successCount)
Sep 14 19:18:24 (none) tcphonehome[138]: Setting callActive to 1
Sep 14 19:18:24 (none) tcphonehome[138]: setting call attempt
Sep 14 19:18:24 (none) tcphonehome[138]: Error statting file /var/log/http: No such file or directory (errno=2)
Sep 14 19:18:24 (none) tcphonehome[138]: Error statting file /var/log/edidlog: No such file or directory (errno=2)
Sep 14 19:18:24 (none) tcphonehome[138]: Error statting file /var/log/Omessages: No such file or directory (errno=2)
Sep 14 19:18:24 (none) tcphonehome[138]: Error statting file /var/log/Okernel: No such file or directory (errno=2)
Sep 14 19:18:24 (none) tcphonehome[138]: Error statting file /var/log/Otverr: No such file or directory (errno=2)
Sep 14 19:18:24 (none) tcphonehome[138]: Error statting file /var/log/Okdebug: No such file or directory (errno=2)
Sep 14 19:18:24 (none) tcphonehome[138]: Error statting file /var/log/Otvdebuglog: No such file or directory (errno=2)
Sep 14 19:18:24 (none) tcphonehome[138]: Error statting file /var/log/Otvlog: No such file or directory (errno=2)
Sep 14 19:18:24 (none) tcphonehome[138]: Error statting file /var/log/Otclient: No such file or directory (errno=2)
Sep 14 19:18:24 (none) tcphonehome[138]: Error statting file /var/log/Otcdebuglog: No such file or directory (errno=2)
Sep 14 19:18:24 (none) tcphonehome[138]: Error statting file /var/log/Ohttp: No such file or directory (errno=2)
Sep 14 19:18:24 (none) tcphonehome[138]: Error statting file /var/log/Oedidlog: No such file or directory (errno=2)
Sep 14 19:18:25 (none) tcphonehome[138]: Calling TClient
Sep 14 19:18:25 (none) comm[138]: CallStatusReporter: Phase: Select_Phone, Status In Progress
Sep 14 19:18:25 (none) comm[138]: CallStatusReporter: sending message "EX|29"
Sep 14 19:18:25 (none) comm[138]: CallService: preprocessing call.
Sep 14 19:18:25 (none) comm[138]: CallStatusReporter: Phase: Prepare_Call, Status In Progress
Sep 14 19:18:25 (none) comm[138]: CallStatusReporter: sending message "EX|29"
Sep 14 19:18:25 (none) comm[138]: SvcLogRqst: open(/var/log/svclog.tmp)ed (tmpfd = 16)
Sep 14 19:18:25 (none) comm[138]: SvcLogRqst: open(/var/log/svclog.upload)ed (uploadfd = 17)
Sep 14 19:18:25 (none) comm[138]: SvcLogRqst: final (730 bytes)::read() (status = 0)
Sep 14 19:18:25 (none) comm[138]: SvcLogRqst: unlink(/var/log/svclog.tmp)ed (status = 0)
Sep 14 19:18:25 (none) comm[138]: Start Ident ==================
Sep 14 19:18:25 (none) comm[138]: version: 3
Sep 14 19:18:25 (none) comm[138]: centerID: 3570000A0E3FC4E
Sep 14 19:18:25 (none) comm[138]: reasonCode: 4
Sep 14 19:18:25 (none) comm[138]: softwareDesc: NONE
Sep 14 19:18:25 (none) comm[138]: locationID: NONE
Sep 14 19:18:25 (none) comm[138]: sequenceCookie: NONE
Sep 14 19:18:25 (none) comm[138]: headendID: NONE
Sep 14 19:18:25 (none) comm[138]: headendHisto:
Sep 14 19:18:25 (none) comm[138]: headendWorst:
Sep 14 19:18:25 (none) comm[138]: showcaseDesc: NONE
Sep 14 19:18:25 (none) comm[138]: inventoryFile:
Sep 14 19:18:25 (none) comm[138]: waitingCount:
Sep 14 19:18:25 (none) comm[138]: confInfo:
Sep 14 19:18:25 (none) comm[138]: dialConfig:
Sep 14 19:18:25 (none) comm[138]: messageDesc:
Sep 14 19:18:25 (none) comm[138]: irdbVersion:
Sep 14 19:18:25 (none) comm[138]: genreVersion:
Sep 14 19:18:25 (none) comm[138]: logoVersion:
Sep 14 19:18:25 (none) comm[138]: affiliationVersion:
Sep 14 19:18:25 (none) comm[138]: showcaseVersion:
Sep 14 19:18:25 (none) comm[138]: demoMode:
Sep 14 19:18:25 (none) comm[138]: swVerName: 3.1.5f-01-2-357
Sep 14 19:18:25 (none) comm[138]: apgOnly:
Sep 14 19:18:25 (none) comm[138]: useChksums: TRUE
Sep 14 19:18:25 (none) comm[138]: premiumShowcases:
Sep 14 19:18:25 (none) comm[138]: captureRequests:
Sep 14 19:18:25 (none) comm[138]: menuItems:
Sep 14 19:18:25 (none) comm[138]: collabData:
Sep 14 19:18:25 (none) comm[138]: signedFiles:
Sep 14 19:18:25 (none) comm[138]: otherDatasets:
Sep 14 19:18:25 (none) comm[138]: rbBackgrounds:
Sep 14 19:18:25 (none) comm[138]: dataGroupList:
Sep 14 19:18:25 (none) comm[138]: lastAvalDownload:
Sep 14 19:18:25 (none) comm[138]: userInitiated:
Sep 14 19:18:25 (none) comm[138]: mfsTotalApp:
Sep 14 19:18:25 (none) comm[138]: mfsAvailApp:
Sep 14 19:18:25 (none) comm[138]: mfsTotalMedia:
Sep 14 19:18:25 (none) comm[138]: mfsAvailMedia:
Sep 14 19:18:25 (none) comm[138]: clipsTotalSize:
Sep 14 19:18:25 (none) comm[138]: clipsAvailSize:
Sep 14 19:18:25 (none) comm[138]: rbTotalSize:
Sep 14 19:18:25 (none) comm[138]: rbAvailSize:
Sep 14 19:18:25 (none) comm[138]: tcdId: 3570000A0E3FC4E
Sep 14 19:18:25 (none) comm[138]: callId: 1158261505
Sep 14 19:18:25 (none) comm[138]: sourceParameterList:
Sep 14 19:18:25 (none) comm[138]: configParameterList:
Sep 14 19:18:25 (none) comm[138]: iceboxinfo:
Sep 14 19:18:25 (none) comm[138]: modemState: V34,V34,4,14,33,13419
Sep 14 19:18:25 (none) comm[138]: localSw: 222
Sep 14 19:18:25 (none) comm[138]: timeStamp: ...
Sep 14 19:18:25 (none) comm[138]: End Ident ==================
Sep 14 19:18:25 (none) comm[138]: CallService: Start err 0
Sep 14 19:18:25 (none) comm[138]: CallStatusReporter: Phase: Dial, Status In Progress
Sep 14 19:18:25 (none) comm[138]: CallStatusReporter: sending message "CL|30"
Sep 14 19:18:25 (none) comm[138]: ##### Initial dial prefix = '18xxxxxxxx'
Sep 14 19:18:25 (none) comm[138]: After ,# final dialstring is '18xxxxxxx'
Sep 14 19:18:25 (none) comm[138]: CallStatusReporter: Turning off-hook LED on
Sep 14 19:18:25 (none) comm[138]: Opening device
Sep 14 19:18:25 (none) comm[138]: Initializing modem
Sep 14 19:18:27 (none) comm[138]: ATZ
Sep 14 19:18:27 (none) comm[138]: OK
Sep 14 19:18:28 (none) comm[138]: Set up modem and check for availability
Sep 14 19:18:28 (none) comm[138]: AT\Q3\T12
Sep 14 19:18:28 (none) comm[138]: OK
Sep 14 19:18:28 (none) comm[138]: AT:U70,A100
Sep 14 19:18:28 (none) comm[138]: ATQ0S0=0
Sep 14 19:18:28 (none) comm[138]: OK
Sep 14 19:18:28 (none) comm[138]: SETTING MODEM TO V34 MODE
Sep 14 19:18:28 (none) comm[138]: OK
Sep 14 19:18:28 (none) comm[138]: Modem set up and onhook.
Sep 14 19:18:28 (none) comm[138]: Turning off dial tone detection
Sep 14 19:18:28 (none) comm[138]: ATV1S6=8S7=50%C0&H2X4
Sep 14 19:18:28 (none) comm[138]: ATX3
Sep 14 19:18:28 (none) comm[138]: OK
Sep 14 19:18:28 (none) comm[138]: Setting extension pickup detection
Sep 14 19:18:28 (none) comm[138]: AT:U76,3240
Sep 14 19:18:28 (none) comm[138]: OK
Sep 14 19:18:28 (none) comm[138]: Trying to connect
Sep 14 19:19:00 (none) comm[138]: AT:U77,8D10,8050
Sep 14 19:19:00 (none) comm[138]: ATDT18xxxxxxxxx,,#019,,6341305
Sep 14 19:19:00 (none) comm[138]: OK
Sep 14 19:19:00 (none) comm[138]: CONNECT 12000
Sep 14 19:19:02 (none) comm[138]: PROTOCOL:V42
Sep 14 19:19:02 (none) comm[138]: Got a connection.
Sep 14 19:19:02 (none) comm[138]: Trying to login
Sep 14 19:19:02 (none) comm[138]: UQKT2
Sep 14 19:19:02 (none) comm[138]: User Access Verification
Sep 14 19:19:02 (none) comm[138]: Username:
Sep 14 19:19:03 (none) comm[138]:
Sep 14 19:19:03 (none) comm[138]: Username: 357xxxxxxxxxxxxxxx.xxxxxx@tivo.net
Sep 14 19:19:03 (none) comm[138]: Password:
Sep 14 19:19:03 (none) comm[138]:
Sep 14 19:19:03 (none) comm[138]: Entering PPP mode.
Sep 14 19:19:03 (none) comm[138]: Async interface address is unnumbered (Loopback0)
Sep 14 19:19:03 (none) comm[138]: Your IP address is 0.0.0.0. MTU is 1500 bytes
Sep 14 19:19:03 (none) comm[138]: Login is complete.
Sep 14 19:19:03 (none) comm[138]: Modem dialcode is 1
Sep 14 19:19:03 (none) comm[138]: CallStatusReporter: Phase: Calling, Status In Progress
Sep 14 19:19:03 (none) comm[138]: CallStatusReporter: sending message "CL|31"
Sep 14 19:19:03 (none) comm[138]: CallStatusReporter: Phase: Start_PPP, Status In Progress
Sep 14 19:19:04 (none) comm[138]: CallStatusReporter: sending message "ST|33"
Sep 14 19:19:04 (none) comm[138]: Going to start pppd.
Sep 14 19:19:04 (none) comm[138]: Pppd:Start: enter
Sep 14 19:19:04 (none) comm[138]: Pppd::Start: fork()ed (pid = 489)
Sep 14 19:19:04 (none) comm[138]: Pppd::Start: storing child pid as 489
Sep 14 19:19:04 (none) comm[138]: Pppd::Start: waiting for PPP - 1
Sep 14 19:19:04 (none) comm[489]: Pppd::Start: fork()ed (pid = 0)
Sep 14 19:19:04 (none) comm[489]: Pppd::Start: spawning pppd
Sep 14 19:19:07 (none) comm[138]: Pppd::Start: waiting for PPP - 2
Sep 14 19:19:10 (none) comm[138]: Pppd::Start: waiting for PPP - 3
Sep 14 19:19:10 (none) comm[138]: Pppd::Start: exit (succeeded)
Sep 14 19:19:10 (none) comm[138]: CallStatusReporter: Phase: Start_Auth, Status In Progress
Sep 14 19:19:10 (none) comm[138]: CallStatusReporter: sending message "ST|33"
Sep 14 19:19:10 (none) comm[138]: CallStatusReporter: Phase: Start_Negotiating, Status In Progress
Sep 14 19:19:10 (none) comm[138]: CallStatusReporter: sending message "ST|51"
Sep 14 19:19:19 (none) WatchdogAction[137]: WatchdogAction::Trigger: callActive for 900 interval-secs
Sep 14 19:22:10 (none) comm[138]: CommUtil: connection to host 204.176.49.2, port 80, err 0x50005
Sep 14 19:22:10 (none) comm[138]: tmk tcp connect failed, reason = Operation now in progress
Sep 14 19:22:10 (none) comm[138]: drainGetPostQ: doXfer failed err=327685 (0x50005)
Sep 14 19:22:10 (none) comm[138]: NetAgent: drainPostQ failed, err = 0x50005
Sep 14 19:22:10 (none) comm[138]: CallService: NetAgent Process err 327685
Sep 14 19:22:10 (none) comm[138]: CallService: NetAgent failed, status 0x50005
Sep 14 19:22:10 (none) comm[138]: CallService: EndCall start
Sep 14 19:22:10 (none) comm[138]: Stopping pppd.
Sep 14 19:22:10 (none) comm[138]: Pppd::Stop: enter
Sep 14 19:22:10 (none) comm[138]: Pppd::Stop: killed (pid = 489, status = 0)
Sep 14 19:22:14 (none) comm[138]: Pppd::Stop: waited (pid = 489, status = 489)
Sep 14 19:22:14 (none) comm[138]: Pppd::Stop: exit
Sep 14 19:22:15 (none) comm[138]: OK
Sep 14 19:22:15 (none) comm[138]: AT
Sep 14 19:22:15 (none) comm[138]: OK
Sep 14 19:22:15 (none) comm[138]: ATH0
Sep 14 19:22:15 (none) comm[138]: OK
Sep 14 19:22:15 (none) comm[138]: ATI7
Sep 14 19:22:15 (none) comm[138]: RX 9600 TX 9600
Sep 14 19:22:15 (none) comm[138]: PROTOCOL :V42
Sep 14 19:22:15 (none) comm[138]: LOCAL NAK 00000
Sep 14 19:22:15 (none) comm[138]: REMOTE NAK 00000
Sep 14 19:22:15 (none) comm[138]: RETRN/RR 00001
Sep 14 19:22:15 (none) comm[138]: DISC REASON 8017
Sep 14 19:22:15 (none) comm[138]: OK
Sep 14 19:22:15 (none) comm[138]: ATI8
Sep 14 19:22:15 (none) comm[138]: RX LEVEL -16db
Sep 14 19:22:15 (none) comm[138]: TX LEVEL -10db
Sep 14 19:22:15 (none) comm[138]: EFFECTIVE S/N 99db
Sep 14 19:22:15 (none) comm[138]: RESIDUAL ECHO -65db
Sep 14 19:22:15 (none) comm[138]: OK
Sep 14 19:22:15 (none) comm[138]: 0001 8017 0000 0006
Sep 14 19:22:15 (none) comm[138]: OK
Sep 14 19:22:15 (none) comm[138]: Disconnect Reason = Remote_Disconnect
Sep 14 19:22:15 (none) comm[138]: Number of Retrains = 1
Sep 14 19:22:15 (none) comm[138]: Last Retrain reason = UNKNOWN
Sep 14 19:22:16 (none) comm[138]: ATZ
Sep 14 19:22:16 (none) comm[138]: 0001 8017 0000 000AT\Q3\T12
Sep 14 19:22:16 (none) comm[138]: OK
Sep 14 19:22:20 (none) comm[138]: CallStatusReporter: Turning off-hook LED off
Sep 14 19:22:20 (none) tcphonehome[138]: CallService return status 0x50005
Sep 14 19:22:21 (none) comm[138]: CallStatusReporter: Phase: Start_Negotiating, Status Failed
Sep 14 19:22:21 (none) comm[138]: CallStatusReporter: sending message "EX|53"
Sep 14 19:22:21 (none) tcphonehome[138]: TClient failed: EX|53
Sep 14 19:22:21 (none) tcphonehome[138]: Sending dialup event, subtype 8, msg EX|53
Sep 14 19:22:21 (none) tcphonehome[138]: setCallStatus called with: Failed state 0
Sep 14 19:22:21 (none) tcphonehome[138]: LastCallAttempt at 1158261504
Sep 14 19:22:21 (none) tcphonehome[138]: setting call status to: Failed
Sep 14 19:22:21 (none) tcphonehome[138]: setting call in progress to 0 (second successCount)
Sep 14 19:22:21 (none) tcphonehome[138]: Setting callActive to 0
Sep 14 19:22:21 (none) comm[138]: CallStatusReporter: sending data changed event 20
Sep 14 19:22:21 (none) tcphonehome[138]: destroying CommGlobals!
Sep 14 19:22:22 (none) tcphonehome[138]: pCommMempool empty
Sep 14 19:22:22 (none) tcphonehome[138]: Setting MCP PhoneHome action: ENABLED


Can someome help me out on this!? As you can see, I even added the toll free # as the dialing string as well, with no prevail!

Also, is there a way to erase the Number dialed that the system has stored!? For Vonage, when you dial something like *99,123456123456, the system gives you an error message. With that "Set Dial In Number" populated, I can't get just a 7 digit dial, which sux!

[puffdaddy]

Attachments..... they're underrated.

I retract my earlier statement, and state now, I might know what your problem is. This is the interesting part.
Sep 14 19:22:10 (none) comm[138]: CommUtil: connection to host 204.176.49.2, port 80, err 0x50005How did you hack your unit? Did you block ports to the mothership?

Also, is there a way to erase the Number dialed that the system has stored!? For Vonage, when you dial something like *99,123456123456, the system gives you an error message. With that "Set Dial In Number" populated, I can't get just a 7 digit dial, which sux!Are you using Vonage to make these calls. That can create a lot of problems as well.

[charlestwaters]

Attachments..... they're underrated.

I retract my earlier statement, and state now, I might know what your problem is. This is the interesting part.

How did you hack your unit? Did you block ports to the mothership?

Are you using Vonage to make these calls. That can create a lot of problems as well.

First off, sorry about not using an attachment! Forgot about that option! :)

As for hacking, I used rbautch's Zipper procedure to hack both TiVo's!

As for blocking ports, not that I know of! I looked in my router's setup, and I don't have port 80 blocked on anything, and in fact, I don't have port 80 blocked for anything!

I have one HR10 that is on Vonage, and the other is on Qwest landline, and both of them stop at the same exact spot!

[pdawg17]

I have the same problem and had used the Zipper too...I did option 1 in the 6.3 prep thread...does fakecall have to be removed as well or does that have nothing to do with it?

[puffdaddy]

I used rbautch's Zipper procedure to hack both TiVo's!
As for blocking ports, not that I know of!Pdawg17 has answered your question (http://www.tivocommunity.com/tivo-vb/showthread.php?t=315245), and though I laud your efforts to ween yourself from the sweet teat of the script, in this case, you're better off continuing to suckle. ;)
I have the same problem and had used the Zipper too...I did option 1 in the 6.3 prep thread...does fakecall have to be removed as well or does that have nothing to do with it?It should not be removed, and it has nothing to do with the "Failed with Negotiating" error.

[charlestwaters]

I got this fixed! Problem was in the /etc/rc.d/sysinit.author file, I didn't comment out the gateway and IP lines!