Posted on 2008-05-01 08:00:00
Tags: Networking, FreeBsd
Thanks to my job, or cursed by my job sometimes, I have access to a 3G modem of Three Mobile. It works fine in areas where there is Three coverage, outside these areas were we are roaming (and probably on the Telstra 3G network) there are interesting issues with the IPCP phase (IP Confirguration Protocol) of PPP which make the PPP setup fail.
So what works and what doesn't? According to the PPP manual, this is what we should see:
The first two Ps become capitals, but the third one doesn't when we are roaming.ppp ON awfulhak> # No link has been established Ppp ON awfulhak> # We've connected & finished LCP PPp ON awfulhak> # We've authenticated PPP ON awfulhak> # We've agreed IP numbers
What do the logs say? The short version of a successful handshake is:
The full log is at the end of this writeup.IPCP: FSM: Using "deflink" as a transport IPCP: deflink: State change Initial --> Closed IPCP: deflink: LayerStart. IPCP: deflink: SendConfigReq(1) state = Closed IPCP: deflink: State change Closed --> Req-Sent IPCP: deflink: RecvConfigNak(1) state = Req-Sent IPCP: deflink: SendConfigReq(2) state = Req-Sent IPCP: deflink: RecvConfigNak(2) state = Req-Sent IPCP: deflink: SendConfigReq(3) state = Req-Sent IPCP: deflink: RecvConfigReq(0) state = Req-Sent IPCP: deflink: SendConfigNak(0) state = Req-Sent IPCP: deflink: RecvConfigRej(3) state = Req-Sent IPCP: deflink: SendConfigReq(4) state = Req-Sent IPCP: deflink: RecvConfigReq(1) state = Req-Sent IPCP: deflink: SendConfigAck(1) state = Req-Sent IPCP: deflink: State change Req-Sent --> Ack-Sent IPCP: deflink: RecvConfigNak(4) state = Ack-Sent IPCP: deflink: SendConfigReq(5) state = Ack-Sent IPCP: deflink: RecvConfigAck(5) state = Ack-Sent IPCP: deflink: State change Ack-Sent --> Opened
The short version of an unsuccessful handshake is:
The full log is at the end of this writeup.IPCP: FSM: Using "deflink" as a transport IPCP: deflink: State change Initial --> Closed IPCP: deflink: LayerStart. IPCP: deflink: SendConfigReq(1) state = Closed IPCP: deflink: State change Closed --> Req-Sent IPCP: deflink: RecvConfigNak(1) state = Req-Sent IPCP: deflink: SendConfigReq(2) state = Req-Sent IPCP: deflink: RecvConfigNak(2) state = Req-Sent IPCP: deflink: SendConfigReq(3) state = Req-Sent IPCP: deflink: RecvConfigNak(3) state = Req-Sent IPCP: deflink: SendConfigReq(4) state = Req-Sent IPCP: deflink: RecvConfigNak(4) state = Req-Sent IPCP: deflink: SendConfigReq(5) state = Req-Sent IPCP: deflink: RecvConfigNak(5) state = Req-Sent IPCP: deflink: SendConfigReq(6) state = Req-Sent IPCP: deflink: RecvConfigNak(6) state = Req-Sent IPCP: deflink: SendConfigReq(7) state = Req-Sent IPCP: deflink: RecvConfigNak(7) state = Req-Sent IPCP: deflink: SendConfigReq(8) state = Req-Sent IPCP: deflink: RecvConfigNak(8) state = Req-Sent IPCP: deflink: SendConfigReq(9) state = Req-Sent IPCP: deflink: RecvConfigNak(9) state = Req-Sent IPCP: deflink: SendConfigReq(10) state = Req-Sent IPCP: deflink: RecvConfigNak(10) state = Req-Sent IPCP: deflink: SendConfigReq(11) state = Req-Sent IPCP: deflink: SendTerminateReq(11) state = Req-Sent IPCP: deflink: State change Req-Sent --> Closing IPCP: deflink: RecvTerminateAck(11) state = Closing IPCP: deflink: LayerFinish. IPCP: deflink: State change Closing --> Closed IPCP: deflink: RecvConfigNak(11), dropped (expected 12)
If anybody has managed to setup a successful PPP connection on the 3G network of anybody but Three can send me some logs, I would be very happy to see if I can fix things.
Here are the full logs:
This is the IPCP part of a successful handshake
ppp[1098]: tun0: Phase: bundle: Network ppp[1098]: tun0: IPCP: FSM: Using "deflink" as a transport ppp[1098]: tun0: IPCP: deflink: State change Initial --> Closed ppp[1098]: tun0: IPCP: deflink: LayerStart. ppp[1098]: tun0: IPCP: deflink: SendConfigReq(1) state = Closed ppp[1098]: tun0: IPCP: IPADDR[6] 0.0.0.0 ppp[1098]: tun0: IPCP: COMPPROTO[6] 16 VJ slots without slot compression ppp[1098]: tun0: IPCP: PRIDNS[6] 202.124.76.66 ppp[1098]: tun0: IPCP: SECDNS[6] 255.255.255.255 ppp[1098]: tun0: IPCP: deflink: State change Closed --> Req-Sent ppp[1098]: tun0: LCP: deflink: RecvProtocolRej(2) state = Opened ppp[1098]: tun0: LCP: deflink: -- Protocol 0x80fd (Compression Control Protocol) was rejected! ppp[1098]: tun0: CCP: deflink: State change Req-Sent --> Stopped ppp[1098]: tun0: IPCP: deflink: RecvConfigNak(1) state = Req-Sent ppp[1098]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1098]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1098]: tun0: IPCP: PRINBNS[6] 10.11.12.13 ppp[1098]: tun0: IPCP: MS NBNS req 130 - NAK?? ppp[1098]: tun0: IPCP: SECNBNS[6] 10.11.12.14 ppp[1098]: tun0: IPCP: MS NBNS req 132 - NAK?? ppp[1098]: tun0: IPCP: Primary nameserver set to 10.11.12.13 ppp[1098]: tun0: IPCP: Secondary nameserver set to 10.11.12.14 ppp[1098]: tun0: IPCP: deflink: SendConfigReq(2) state = Req-Sent ppp[1098]: tun0: IPCP: IPADDR[6] 0.0.0.0 ppp[1098]: tun0: IPCP: COMPPROTO[6] 16 VJ slots without slot compression ppp[1098]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1098]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1098]: tun0: IPCP: deflink: RecvConfigNak(2) state = Req-Sent ppp[1098]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1098]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1098]: tun0: IPCP: PRINBNS[6] 10.11.12.13 ppp[1098]: tun0: IPCP: MS NBNS req 130 - NAK?? ppp[1098]: tun0: IPCP: SECNBNS[6] 10.11.12.14 ppp[1098]: tun0: IPCP: MS NBNS req 132 - NAK?? ppp[1098]: tun0: IPCP: Primary nameserver set to 10.11.12.13 ppp[1098]: tun0: IPCP: Secondary nameserver set to 10.11.12.14 ppp[1098]: tun0: IPCP: deflink: SendConfigReq(3) state = Req-Sent ppp[1098]: tun0: IPCP: IPADDR[6] 0.0.0.0 ppp[1098]: tun0: IPCP: COMPPROTO[6] 16 VJ slots without slot compression ppp[1098]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1098]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1098]: tun0: IPCP: deflink: RecvConfigReq(0) state = Req-Sent ppp[1098]: tun0: IPCP: [EMPTY] ppp[1098]: tun0: IPCP: deflink: SendConfigNak(0) state = Req-Sent ppp[1098]: tun0: IPCP: IPADDR[6] 10.0.0.2 ppp[1098]: tun0: IPCP: deflink: RecvConfigRej(3) state = Req-Sent ppp[1098]: tun0: IPCP: COMPPROTO[6] 16 VJ slots without slot compression ppp[1098]: tun0: IPCP: deflink: SendConfigReq(4) state = Req-Sent ppp[1098]: tun0: IPCP: IPADDR[6] 0.0.0.0 ppp[1098]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1098]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1098]: tun0: IPCP: deflink: RecvConfigReq(1) state = Req-Sent ppp[1098]: tun0: IPCP: [EMPTY] ppp[1098]: tun0: IPCP: deflink: SendConfigAck(1) state = Req-Sent ppp[1098]: tun0: IPCP: [EMPTY] ppp[1098]: tun0: IPCP: deflink: State change Req-Sent --> Ack-Sent ppp[1098]: tun0: IPCP: deflink: RecvConfigNak(4) state = Ack-Sent ppp[1098]: tun0: IPCP: IPADDR[6] 119.11.8.120 ppp[1098]: tun0: IPCP: IPADDR[6] changing address: 0.0.0.0 --> 119.11.8.120 ppp[1098]: tun0: IPCP: PRIDNS[6] 202.124.68.130 ppp[1098]: tun0: IPCP: SECDNS[6] 202.124.76.66 ppp[1098]: tun0: IPCP: Primary nameserver set to 202.124.68.130 ppp[1098]: tun0: IPCP: Secondary nameserver set to 202.124.76.66 ppp[1098]: tun0: IPCP: deflink: SendConfigReq(5) state = Ack-Sent ppp[1098]: tun0: IPCP: IPADDR[6] 119.11.8.120 ppp[1098]: tun0: IPCP: PRIDNS[6] 202.124.68.130 ppp[1098]: tun0: IPCP: SECDNS[6] 202.124.76.66 ppp[1098]: tun0: IPCP: deflink: RecvConfigAck(5) state = Ack-Sent ppp[1098]: tun0: IPCP: IPADDR[6] 119.11.8.120 ppp[1098]: tun0: IPCP: PRIDNS[6] 202.124.68.130 ppp[1098]: tun0: IPCP: SECDNS[6] 202.124.76.66 ppp[1098]: tun0: IPCP: deflink: State change Ack-Sent --> Opened ppp[1098]: tun0: IPCP: deflink: LayerUp.
This is the IPCP part of a unsuccessful handshake
ppp[1661]: tun0: Phase: bundle: Network ppp[1661]: tun0: IPCP: FSM: Using "deflink" as a transport ppp[1661]: tun0: IPCP: deflink: State change Initial --> Closed ppp[1661]: tun0: IPCP: deflink: LayerStart. ppp[1661]: tun0: IPCP: deflink: SendConfigReq(1) state = Closed ppp[1661]: tun0: IPCP: IPADDR[6] 0.0.0.0 ppp[1661]: tun0: IPCP: COMPPROTO[6] 16 VJ slots with slot compression ppp[1661]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: deflink: State change Closed --> Req-Sent ppp[1661]: tun0: LCP: deflink: RecvProtocolRej(2) state = Opened ppp[1661]: tun0: LCP: deflink: -- Protocol 0x80fd (Compression Control Protocol) was rejected! ppp[1661]: tun0: CCP: deflink: State change Req-Sent --> Stopped ppp[1661]: tun0: IPCP: deflink: RecvConfigNak(1) state = Req-Sent ppp[1661]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: PRINBNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: MS NBNS req 130 - NAK?? ppp[1661]: tun0: IPCP: SECNBNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: MS NBNS req 132 - NAK?? ppp[1661]: tun0: IPCP: Primary nameserver set to 10.11.12.13 ppp[1661]: tun0: IPCP: Secondary nameserver set to 10.11.12.14 ppp[1661]: tun0: IPCP: deflink: SendConfigReq(2) state = Req-Sent ppp[1661]: tun0: IPCP: IPADDR[6] 0.0.0.0 ppp[1661]: tun0: IPCP: COMPPROTO[6] 16 VJ slots with slot compression ppp[1661]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: deflink: RecvConfigNak(2) state = Req-Sent ppp[1661]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: PRINBNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: MS NBNS req 130 - NAK?? ppp[1661]: tun0: IPCP: SECNBNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: MS NBNS req 132 - NAK?? ppp[1661]: tun0: IPCP: Primary nameserver set to 10.11.12.13 ppp[1661]: tun0: IPCP: Secondary nameserver set to 10.11.12.14 ppp[1661]: tun0: IPCP: deflink: SendConfigReq(3) state = Req-Sent ppp[1661]: tun0: IPCP: IPADDR[6] 0.0.0.0 ppp[1661]: tun0: IPCP: COMPPROTO[6] 16 VJ slots with slot compression ppp[1661]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: deflink: RecvConfigNak(3) state = Req-Sent ppp[1661]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: PRINBNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: MS NBNS req 130 - NAK?? ppp[1661]: tun0: IPCP: SECNBNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: MS NBNS req 132 - NAK?? ppp[1661]: tun0: IPCP: Primary nameserver set to 10.11.12.13 ppp[1661]: tun0: IPCP: Secondary nameserver set to 10.11.12.14 ppp[1661]: tun0: IPCP: deflink: SendConfigReq(4) state = Req-Sent ppp[1661]: tun0: IPCP: IPADDR[6] 0.0.0.0 ppp[1661]: tun0: IPCP: COMPPROTO[6] 16 VJ slots with slot compression ppp[1661]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: deflink: RecvConfigNak(4) state = Req-Sent ppp[1661]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: PRINBNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: MS NBNS req 130 - NAK?? ppp[1661]: tun0: IPCP: SECNBNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: MS NBNS req 132 - NAK?? ppp[1661]: tun0: IPCP: Primary nameserver set to 10.11.12.13 ppp[1661]: tun0: IPCP: Secondary nameserver set to 10.11.12.14 ppp[1661]: tun0: IPCP: deflink: SendConfigReq(5) state = Req-Sent ppp[1661]: tun0: IPCP: IPADDR[6] 0.0.0.0 ppp[1661]: tun0: IPCP: COMPPROTO[6] 16 VJ slots with slot compression ppp[1661]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: deflink: RecvConfigNak(5) state = Req-Sent ppp[1661]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: PRINBNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: MS NBNS req 130 - NAK?? ppp[1661]: tun0: IPCP: SECNBNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: MS NBNS req 132 - NAK?? ppp[1661]: tun0: IPCP: Primary nameserver set to 10.11.12.13 ppp[1661]: tun0: IPCP: Secondary nameserver set to 10.11.12.14 ppp[1661]: tun0: IPCP: deflink: SendConfigReq(6) state = Req-Sent ppp[1661]: tun0: IPCP: IPADDR[6] 0.0.0.0 ppp[1661]: tun0: IPCP: COMPPROTO[6] 16 VJ slots with slot compression ppp[1661]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: deflink: RecvConfigNak(6) state = Req-Sent ppp[1661]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: PRINBNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: MS NBNS req 130 - NAK?? ppp[1661]: tun0: IPCP: SECNBNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: MS NBNS req 132 - NAK?? ppp[1661]: tun0: IPCP: Primary nameserver set to 10.11.12.13 ppp[1661]: tun0: IPCP: Secondary nameserver set to 10.11.12.14 ppp[1661]: tun0: IPCP: deflink: SendConfigReq(7) state = Req-Sent ppp[1661]: tun0: IPCP: IPADDR[6] 0.0.0.0 ppp[1661]: tun0: IPCP: COMPPROTO[6] 16 VJ slots with slot compression ppp[1661]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: deflink: RecvConfigNak(7) state = Req-Sent ppp[1661]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: PRINBNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: MS NBNS req 130 - NAK?? ppp[1661]: tun0: IPCP: SECNBNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: MS NBNS req 132 - NAK?? ppp[1661]: tun0: IPCP: Primary nameserver set to 10.11.12.13 ppp[1661]: tun0: IPCP: Secondary nameserver set to 10.11.12.14 ppp[1661]: tun0: IPCP: deflink: SendConfigReq(8) state = Req-Sent ppp[1661]: tun0: IPCP: IPADDR[6] 0.0.0.0 ppp[1661]: tun0: IPCP: COMPPROTO[6] 16 VJ slots with slot compression ppp[1661]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: deflink: RecvConfigNak(8) state = Req-Sent ppp[1661]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: PRINBNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: MS NBNS req 130 - NAK?? ppp[1661]: tun0: IPCP: SECNBNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: MS NBNS req 132 - NAK?? ppp[1661]: tun0: IPCP: Primary nameserver set to 10.11.12.13 ppp[1661]: tun0: IPCP: Secondary nameserver set to 10.11.12.14 ppp[1661]: tun0: IPCP: deflink: SendConfigReq(9) state = Req-Sent ppp[1661]: tun0: IPCP: IPADDR[6] 0.0.0.0 ppp[1661]: tun0: IPCP: COMPPROTO[6] 16 VJ slots with slot compression ppp[1661]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: deflink: RecvConfigNak(9) state = Req-Sent ppp[1661]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: PRINBNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: MS NBNS req 130 - NAK?? ppp[1661]: tun0: IPCP: SECNBNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: MS NBNS req 132 - NAK?? ppp[1661]: tun0: IPCP: Primary nameserver set to 10.11.12.13 ppp[1661]: tun0: IPCP: Secondary nameserver set to 10.11.12.14 ppp[1661]: tun0: IPCP: deflink: SendConfigReq(10) state = Req-Sent ppp[1661]: tun0: IPCP: IPADDR[6] 0.0.0.0 ppp[1661]: tun0: IPCP: COMPPROTO[6] 16 VJ slots with slot compression ppp[1661]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: deflink: RecvConfigNak(10) state = Req-Sent ppp[1661]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: PRINBNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: MS NBNS req 130 - NAK?? ppp[1661]: tun0: IPCP: SECNBNS[6] 10.11.12.14 ppp[1661]: tun0: IPCP: MS NBNS req 132 - NAK?? ppp[1661]: tun0: IPCP: Primary nameserver set to 10.11.12.13 ppp[1661]: tun0: IPCP: Secondary nameserver set to 10.11.12.14 ppp[1661]: tun0: IPCP: deflink: SendConfigReq(11) state = Req-Sent ppp[1661]: tun0: IPCP: IPADDR[6] 0.0.0.0 ppp[1661]: tun0: IPCP: COMPPROTO[6] 16 VJ slots with slot compression ppp[1661]: tun0: IPCP: PRIDNS[6] 10.11.12.13 ppp[1661]: tun0: IPCP: SECDNS[6] 10.11.12.14 ppp[1661]: tun0: Command: /dev/ttyp1: quit ppp[1661]: tun0: IPCP: deflink: SendTerminateReq(11) state = Req-Sent ppp[1661]: tun0: IPCP: deflink: State change Req-Sent --> Closing ppp[1661]: tun0: IPCP: deflink: RecvTerminateAck(11) state = Closing ppp[1661]: tun0: IPCP: deflink: LayerFinish. ppp[1661]: tun0: IPCP: Connect time: 11 secs: 0 octets in, 0 octets out ppp[1661]: tun0: IPCP: 0 packets in, 0 packets out ppp[1661]: tun0: IPCP: total 0 bytes/sec, peak 0 bytes/sec on Thu Apr 24 13:39:49 2008 ppp[1661]: tun0: IPCP: deflink: State change Closing --> Closed ppp[1661]: tun0: IPCP: deflink: RecvConfigNak(11), dropped (expected 12) ppp[1661]: tun0: Phase: bundle: Terminate