View Single Post
Old 07-09-2008, 02:53 AM   #2 (permalink)
woodyofid
Knows Where the Search Button Is
 
Join Date: Jun 2008
Model: 8900
OS: 5.0.0.592
PIN: a colada
Carrier: tmobile
Posts: 23
Post Thanks: 0
Thanked 0 Times in 0 Posts
Default Follow up diagnostics (debugging a working Windows connection)

I spent a few hours pulling apart the modem and ppp trace from Windows XP to compare to my pppd debug ouput.

Windows sends the following chat sequence before ppp:

Send: AT<cr>
Send: ATE0V1<cr>
Send: AT<cr>
Send: AT+cgdcont=1,"IP","wap.voicestream.com"<cr>
Send: ATS0=0<cr>
Send: AT<cr>
Send: ATE0V1<cr>
Send: AT<cr>
Send: AT+cgdcont=1,"IP","wap.voicestream.com"<cr>
Send: ATDT*99#<cr>

---------------------------------------------------

To close the modem, Windows sends (post ppp)

Send: ATH<cr>
Send: AT<cr>
Send: ATE0V1<cr>
Send: AT<cr>
Send: AT+cgdcont=1,"IP","wap.voicestream.com"<cr>
Send: ATS0=0<cr>

---------------------------------------------------

Now on to the Windows ppp trace (I have interspersed English translations of the LCP, CCP and IPCP packets):

[1188] 19:18:46:625: PPPEMSG_Start recvd, d=, hPort=6,callback=0,mask=83034a,IfType=-1
[3852] 19:18:46:625: Line up event occurred on port 6
[3852] 19:18:46:625: Local identification = MSRAS-0-AMYCOMP
[3852] 19:18:46:625: PortName: COM3
[3852] 19:18:46:625: Starting PPP on link with IfType=0xffffffff,IPIf=0xffffffff,IPXIf=0xffffffff
[3852] 19:18:46:625: RasGetBuffer returned 2f588a0 for SendBuf
[3852] 19:18:46:625: FsmInit called for protocol = c021, port = 6
[3852] 19:18:46:625: ConfigInfo = 83034a
[3852] 19:18:46:625: APs available = 5e
[3852] 19:18:46:625: FsmReset called for protocol = c021, port = 6
[3852] 19:18:46:625: Inserting port in bucket # 6
[3852] 19:18:46:625: Inserting bundle in bucket # 2
[3852] 19:18:46:625: FsmOpen event received for protocol c021 on port 6
[3852] 19:18:46:625: FsmThisLayerStarted called for protocol = c021, port = 6
[3852] 19:18:46:625: FsmUp event received for protocol c021 on port 6
[3852] 19:18:46:625: <PPP packet sent at 07/09/2008 01:18:46:625
[3852] 19:18:46:625: <Protocol = LCP, Type = Configure-Req, Length = 0x19, Id = 0x0, Port = 6
[3852] 19:18:46:625: <C0 21 01 00 00 17 02 06 00 00 00 00 05 06 08 EE |.!..............|
[3852] 19:18:46:625: <1C 62 07 02 08 02 0D 03 06 00 00 00 00 00 00 00 |.b..............|

LCP (sent) -- Link Control Protocol
Conf-Req
02 asyncmap 0
05 magic# 88 EE 1C 62
07 pcomp
08 accomp
0D callback 6


[3852] 19:18:46:625:
[3852] 19:18:46:625: InsertInTimerQ called portid=10,Id=0,Protocol=c021,EventType=0,fAuth=0
[3852] 19:18:46:625: InsertInTimerQ called portid=10,Id=0,Protocol=0,EventType=3,fAuth=0
[3696] 19:18:46:625: Packet received (16 bytes) for hPort 6
[3852] 19:18:46:625: >PPP packet received at 07/09/2008 01:18:46:625
[3852] 19:18:46:625: >Protocol = LCP, Type = Configure-Req, Length = 0x10, Id = 0x0, Port = 6
[3852] 19:18:46:625: >C0 21 01 00 00 0E 02 06 00 00 00 00 03 04 C0 23 |.!.............#|

LCP (recv)
Conf-Req
02 asyncmap 0
03 PAP (proto id: C0 23)


[3852] 19:18:46:625:
[3852] 19:18:46:625: <PPP packet sent at 07/09/2008 01:18:46:625
[3852] 19:18:46:625: <Protocol = LCP, Type = Configure-Ack, Length = 0x10, Id = 0x0, Port = 6
[3852] 19:18:46:625: <C0 21 02 00 00 0E 02 06 00 00 00 00 03 04 C0 23 |.!.............#|

LCP (sent)
Conf-Ack
02 asyncmap 0
03 PAP (C0 23 ?)


[3852] 19:18:46:625:
[3696] 19:18:46:625: Packet received (19 bytes) for hPort 6
[3852] 19:18:46:625: >PPP packet received at 07/09/2008 01:18:46:625
[3852] 19:18:46:625: >Protocol = LCP, Type = Configure-Reject, Length = 0x13, Id = 0x0, Port = 6
[3852] 19:18:46:625: >C0 21 04 00 00 11 05 06 08 EE 1C 62 07 02 08 02 |.!.........b....|
[3852] 19:18:46:625: >0D 03 06 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|

LCP (recv)
Conf-Rej
05 magic#
07 pcomp
08 accomp
0D callback


[3852] 19:18:46:625:
[3852] 19:18:46:625: RemoveFromTimerQ called portid=10,Id=0,Protocol=c021,EventType=0,fAuth=0
[3852] 19:18:46:625: <PPP packet sent at 07/09/2008 01:18:46:625
[3852] 19:18:46:625: <Protocol = LCP, Type = Configure-Req, Length = 0xc, Id = 0x1, Port = 6
[3852] 19:18:46:625: <C0 21 01 01 00 0A 02 06 00 00 00 00 00 00 00 00 |.!..............|

LCP (sent)
Conf-Req
02 asyncmap 0


[3852] 19:18:46:625:
[3852] 19:18:46:625: InsertInTimerQ called portid=10,Id=1,Protocol=c021,EventType=0,fAuth=0
[3696] 19:18:46:625: Packet received (12 bytes) for hPort 6
[3852] 19:18:46:625: >PPP packet received at 07/09/2008 01:18:46:625
[3852] 19:18:46:625: >Protocol = LCP, Type = Configure-Ack, Length = 0xc, Id = 0x1, Port = 6
[3852] 19:18:46:625: >C0 21 02 01 00 0A 02 06 00 00 00 00 00 00 00 00 |.!..............|

LCP (recv)
Conf-Ack
02 asyncmap 0


[3852] 19:18:46:625:
[3852] 19:18:46:625: RemoveFromTimerQ called portid=10,Id=1,Protocol=c021,EventType=0,fAuth=0
[3852] 19:18:46:625: FsmThisLayerUp called for protocol = c021, port = 6
[3852] 19:18:46:625: LCP Local Options-------------
[3852] 19:18:46:625: MRU=1500,ACCM=0,Auth=0,MagicNumber=0,PFC=OFF,ACFC= OFF
[3852] 19:18:46:625: Recv Framing = PPP,SSHF=OFF,MRRU=1500,LinkDiscrim=0,BAP=OFF
[3852] 19:18:46:625: LCP Remote Options-------------
[3852] 19:18:46:625: MRU=1500,ACCM=0,Auth=c023,MagicNumber=0,PFC=OFF,AC FC=OFF
[3852] 19:18:46:625: Send Framing = PPP,SSHF=OFF,MRRU=1500,LinkDiscrim=0
[3852] 19:18:46:625: LCP Configured successfully
[3852] 19:18:46:625: <PPP packet sent at 07/09/2008 01:18:46:625
[3852] 19:18:46:625: <Protocol = LCP, Type = Identification, Length = 0x14, Id = 0x2, Port = 6
[3852] 19:18:46:656: <C0 21 0C 02 00 12 08 EE 1C 62 4D 53 52 41 53 56 |.!.......bMSRASV|
[3852] 19:18:46:656: <35 2E 31 30 00 00 00 00 00 00 00 00 00 00 00 00 |5.10............|

LCP (sent) (byte seq 2)
Ident (MS RAS v5.10)


[3852] 19:18:46:656:
[3852] 19:18:46:656: <PPP packet sent at 07/09/2008 01:18:46:656
[3852] 19:18:46:656: <Protocol = LCP, Type = Identification, Length = 0x19, Id = 0x3, Port = 6
[3852] 19:18:46:656: <C0 21 0C 03 00 17 08 EE 1C 62 4D 53 52 41 53 2D |.!.......bMSRAS-|
[3852] 19:18:46:656: <30 2D 41 4D 59 43 4F 4D 50 00 00 00 00 00 00 00 |0-AMYCOMP.......|

LCP (sent) (byte seq 3)
Ident (MS RAS 0-AMYCOMP) <- machine's name - BlueTooth style? "0-"; this is a BT connection.


[3852] 19:18:46:656:
[3852] 19:18:46:656: Authenticating phase started
[3852] 19:18:46:656: Calling APWork in APStart
[3852] 19:18:46:656: <PPP packet sent at 07/09/2008 01:18:46:656
[3852] 19:18:46:656: <Protocol = PAP, Type = Protocol specific, Length = 0x8, Id = 0x14, Port = 6
[3852] 19:18:46:656:
[3852] 19:18:46:656: InsertInTimerQ called portid=10,Id=20,Protocol=c023,EventType=0,fAuth=0
[3696] 19:18:46:656: Packet received (24 bytes) for hPort 6
[3852] 19:18:46:656: >PPP packet received at 07/09/2008 01:18:46:656
[3852] 19:18:46:656: >Protocol = LCP, Type = Code-Reject, Length = 0x18, Id = 0x1, Port = 6
[3852] 19:18:46:656: >C0 21 07 01 00 16 0C 02 00 12 08 EE 1C 62 4D 53 |.!...........bMS|
[3852] 19:18:46:656: >52 41 53 56 35 2E 31 30 00 00 00 00 00 00 00 00 |RASV5.10........|

LCP (recv)
Code-Rej
Ident (MS RAS v5.10)


[3852] 19:18:46:656:
[3852] 19:18:46:656: PPP Code Reject rcvd, rejected Code = 12
[3696] 19:18:46:656: Packet received (29 bytes) for hPort 6
[3852] 19:18:46:656: >PPP packet received at 07/09/2008 01:18:46:656
[3852] 19:18:46:656: >Protocol = LCP, Type = Code-Reject, Length = 0x1d, Id = 0x2, Port = 6
[3852] 19:18:46:656: >C0 21 07 02 00 1B 0C 03 00 17 08 EE 1C 62 4D 53 |.!...........bMS|
[3852] 19:18:46:656: >52 41 53 2D 30 2D 41 4D 59 43 4F 4D 50 00 00 00 |RAS-0-AMYCOMP...|

LCP (recv)
Code-Rej
Ident (MS RAS 0-AMYCOMP)


[3852] 19:18:46:656:
[3852] 19:18:46:656: PPP Code Reject rcvd, rejected Code = 12
[3696] 19:18:47:078: Packet received (6 bytes) for hPort 6
[3852] 19:18:47:078: >PPP packet received at 07/09/2008 01:18:47:078
[3852] 19:18:47:078: >Protocol = PAP, Type = Protocol specific, Length = 0x6, Id = 0x14, Port = 6
[3852] 19:18:47:078:
[3852] 19:18:47:078: RemoveFromTimerQ called portid=10,Id=20,Protocol=c023,EventType=0,fAuth=0
[3852] 19:18:47:078: FsmThisLayerUp called for protocol = c023, port = 6
[3852] 19:18:47:078: NotifyCaller(hPort=6, dwMsgId=17)
[3852] 19:18:47:078: NotifyCaller(hPort=6, dwMsgId=3)
[3852] 19:18:47:078: Will not initialize CP 8029
[3852] 19:18:47:078: Will not initialize CP 802b
[3852] 19:18:47:078: FsmInit called for protocol = 80fd, port = 6
[3852] 19:18:47:078: FsmReset called for protocol = 80fd, port = 6
[3852] 19:18:47:078: FsmInit called for protocol = 8021, port = 6
[3852] 19:18:47:078: FsmReset called for protocol = 8021, port = 6
[3852] 19:18:47:078: FsmOpen event received for protocol 80fd on port 6
[3852] 19:18:47:078: FsmThisLayerStarted called for protocol = 80fd, port = 6
[3852] 19:18:47:078: FsmUp event received for protocol 80fd on port 6
[3852] 19:18:47:078: <PPP packet sent at 07/09/2008 01:18:47:078
[3852] 19:18:47:078: <Protocol = CCP, Type = Configure-Req, Length = 0xc, Id = 0x4, Port = 6
[3852] 19:18:47:078: <80 FD 01 04 00 0A 12 06 00 00 00 01 00 00 00 00 |................|

CCP (sent) -- Compression Control Protocol
Conf-Req (byte seq 4)
** This is rejected later, so I did not bother looking up CCP bytes)


[3852] 19:18:47:078:
[3852] 19:18:47:078: InsertInTimerQ called portid=10,Id=4,Protocol=80fd,EventType=0,fAuth=0
[3852] 19:18:47:078: FsmOpen event received for protocol 8021 on port 6
[3852] 19:18:47:078: FsmThisLayerStarted called for protocol = 8021, port = 6
[3852] 19:18:47:078: FsmUp event received for protocol 8021 on port 6
[3852] 19:18:47:078: <PPP packet sent at 07/09/2008 01:18:47:078
[3852] 19:18:47:078: <Protocol = IPCP, Type = Configure-Req, Length = 0x24, Id = 0x5, Port = 6
[3852] 19:18:47:078: <80 21 01 05 00 22 03 06 00 00 00 00 81 06 00 00 |.!..."..........|
[3852] 19:18:47:078: <00 00 82 06 00 00 00 00 83 06 00 00 00 00 84 06 |................|
[3852] 19:18:47:078: <00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|

CCP (sent)
Conf-Req (byte seq 5)
** Rejected later...


[3852] 19:18:47:078:
[3852] 19:18:47:078: InsertInTimerQ called portid=10,Id=5,Protocol=8021,EventType=0,fAuth=0
[3696] 19:18:47:093: Packet received (18 bytes) for hPort 6
[3852] 19:18:47:093: >PPP packet received at 07/09/2008 01:18:47:093
[3852] 19:18:47:093: >Protocol = LCP, Type = Protocol-Reject, Length = 0x12, Id = 0x3, Port = 6
[3852] 19:18:47:093: >C0 21 08 03 00 10 80 FD 01 04 00 0A 12 06 00 00 |.!..............|
[3852] 19:18:47:093: >00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|

LCP (recv)
Proto-Rej CCP (See above)


[3852] 19:18:47:093:
[3852] 19:18:47:093: PPP Protocol Reject, Protocol = 80fd
[3852] 19:18:47:093: RemoveFromTimerQ called portid=10,Id=4,Protocol=80fd,EventType=0,fAuth=0
[3852] 19:18:47:093: FsmThisLayerFinished called for protocol = 80fd, port = 6
[3696] 19:18:47:093: Packet received (12 bytes) for hPort 6
[3852] 19:18:47:093: >PPP packet received at 07/09/2008 01:18:47:093
[3852] 19:18:47:093: >Protocol = IPCP, Type = Configure-Req, Length = 0xc, Id = 0x4, Port = 6
[3852] 19:18:47:093: >80 21 01 04 00 0A 03 06 A9 FE 01 01 00 00 00 00 |.!..............|

IPCP (recv)
Conf-Req (byte seq 4)
03 IP Addreess: A9 FE 01 01 (169.254.1.1, I assume the phone want's this address)


[3852] 19:18:47:093:
[3852] 19:18:47:093: <PPP packet sent at 07/09/2008 01:18:47:093
[3852] 19:18:47:093: <Protocol = IPCP, Type = Configure-Ack, Length = 0xc, Id = 0x4, Port = 6
[3852] 19:18:47:093: <80 21 02 04 00 0A 03 06 A9 FE 01 01 00 00 00 00 |.!..............|

IPCP (sent)
Conf-Ack
IP Address A9 FE 01 01


[3852] 19:18:47:093:
[3696] 19:18:47:093: Packet received (18 bytes) for hPort 6
[3852] 19:18:47:093: >PPP packet received at 07/09/2008 01:18:47:093
[3852] 19:18:47:093: >Protocol = IPCP, Type = Configure-Reject, Length = 0x12, Id = 0x5, Port = 6
[3852] 19:18:47:093: >80 21 04 05 00 10 82 06 00 00 00 00 84 06 00 00 |.!..............|
[3852] 19:18:47:093: >00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|

IPCP (recv)
Conf-Rej
82 Primary NBNS Server Address (I cannot find the Conf-Req send for NBNS)
84 Secondary " " " "


[3852] 19:18:47:093:
[3852] 19:18:47:093: RemoveFromTimerQ called portid=10,Id=5,Protocol=8021,EventType=0,fAuth=0
[3852] 19:18:47:093: <PPP packet sent at 07/09/2008 01:18:47:093
[3852] 19:18:47:093: <Protocol = IPCP, Type = Configure-Req, Length = 0x18, Id = 0x6, Port = 6
[3852] 19:18:47:093: <80 21 01 06 00 16 03 06 00 00 00 00 81 06 00 00 |.!..............|
[3852] 19:18:47:093: <00 00 83 06 00 00 00 00 00 00 00 00 00 00 00 00 |................|

IPCP (sent)
Conf-Req
03 IP Address (0.0.0.0)
81 Pri DNS (0.0.0.0)
83 Sec DNS (0.0.0.0)


[3852] 19:18:47:093:
[3852] 19:18:47:093: InsertInTimerQ called portid=10,Id=6,Protocol=8021,EventType=0,fAuth=0
[3696] 19:18:47:093: Packet received (24 bytes) for hPort 6
[3852] 19:18:47:093: >PPP packet received at 07/09/2008 01:18:47:093
[3852] 19:18:47:093: >Protocol = IPCP, Type = Configure-Nak, Length = 0x18, Id = 0x6, Port = 6
[3852] 19:18:47:093: >80 21 03 06 00 16 03 06 0A AB 9E 30 81 06 42 5E |.!.........0..B^|
[3852] 19:18:47:093: >09 78 83 06 42 5E 19 78 00 00 00 00 00 00 00 00 |.x..B^.x........|

IPCP (recv)
Conf-Nak (Rej w/suggested replacement)
03 IP Address: 0A AB 9E 30 (10.171.158.48)
81 Pri DNS: 42 5E 09 78 (66.94.9.120)
83 Sec DNS: 42 5E 19 78 (66.94.25.120)


[3852] 19:18:47:093:
[3852] 19:18:47:093: RemoveFromTimerQ called portid=10,Id=6,Protocol=8021,EventType=0,fAuth=0
[3852] 19:18:47:093: <PPP packet sent at 07/09/2008 01:18:47:093
[3852] 19:18:47:093: <Protocol = IPCP, Type = Configure-Req, Length = 0x18, Id = 0x7, Port = 6
[3852] 19:18:47:093: <80 21 01 07 00 16 03 06 0A AB 9E 30 81 06 42 5E |.!.........0..B^|
[3852] 19:18:47:093: <09 78 83 06 42 5E 19 78 00 00 00 00 00 00 00 00 |.x..B^.x........|

IPCP (sent)
Conf-Req
03 IP Address: 0A AB 9E 30
81 Pri DNS: 42 5E 09 78
83 Sec DNS: 42 5E 19 78


[3852] 19:18:47:093:
[3852] 19:18:47:093: InsertInTimerQ called portid=10,Id=7,Protocol=8021,EventType=0,fAuth=0
[3696] 19:18:47:093: Packet received (24 bytes) for hPort 6
[3852] 19:18:47:093: >PPP packet received at 07/09/2008 01:18:47:093
[3852] 19:18:47:093: >Protocol = IPCP, Type = Configure-Ack, Length = 0x18, Id = 0x7, Port = 6
[3852] 19:18:47:093: >80 21 02 07 00 16 03 06 0A AB 9E 30 81 06 42 5E |.!.........0..B^|
[3852] 19:18:47:093: >09 78 83 06 42 5E 19 78 00 00 00 00 00 00 00 00 |.x..B^.x........|

IPCP (recv)
Conf-Ack
03 IP Address: 0A AB 9E 30
81 Pri DNS: 42 5E 09 78
83 Sec DNS: 42 5E 19 78

-------------------------------------------------------------

Looking closely, Windows does NOT send a PAP auth request (we know authentication is not required), but it also DOES NOT sent a "ConfRej PAP". It is after the conf-rej PAP that pppd sends that the phone responds with a TermReq.

My guess is that T-Mobile's tweaks to BBOS 4.2 have broken the ppp stack on the phone. Sending PAP auth data tail spins the phone's ppp interface (battery removal required), and PAP ConfRej causes the phone to dump the link.

I am going to build a custom pppd that does not send the PAP ConfReq and test the theory.

Last edited by woodyofid : 07-09-2008 at 03:21 AM.
Offline   Reply With Quote