A Working pppd Connection

The following is the output you should see from various commands while a correctly configured ppp connection is open.

ambceal@anuhost 1> last | head -1
amcbeal     pts/1        h138.anu.uniras. Sat Apr 17 10:50   still logged in

If other people have logged onto the ANU host after you, use
last | less instead.

Your computer at home should show something like the following. With no ppp connection, the lo section would be the only part displayed.

amcbeal [home] 165> ifconfig
lo        Link encap:Local Loopback  
          inet addr:127.0.0.1  Mask:255.0.0.0
          UP LOOPBACK RUNNING  MTU:3924  Metric:1
          RX packets:6 errors:0 dropped:0 overruns:0 frame:0
          TX packets:6 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 

ppp0      Link encap:Point-to-Point Protocol  
          inet addr:203.108.55.138  P-t-P:203.108.192.15  Mask:255.255.255.255
          UP POINTOPOINT RUNNING NOARP MULTICAST  MTU:1500  Metric:1
          RX packets:9 errors:0 dropped:0 overruns:0 frame:0
          TX packets:10 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0

If you are on the slower subnet, the first part of the ppp0 section will show a different subnet for "inet addr"...

ppp0      Link encap:Point-to-Point Protocol  
          inet addr:203.108.192.94  P-t-P:203.108.192.14  Mask:255.255.255.255

The output from route on your computer at home.
Without a ppp connection, only the loopback route (127.0.0.0) is shown.

   
amcbeal [home] 163> route
Kernel IP routing table
Destination     Gateway         Genmask         Flags Metric Ref    Use Iface
termcan2.ozemai *               255.255.255.255 UH    0      0        0 ppp0
127.0.0.0       *               255.0.0.0       U     0      0        0 lo
default         termcan2.ozemai 0.0.0.0         UG    0      0        0 ppp0

Debugging Output Written to /var/log/ppplog

The actual output looks like this...

Apr 20 15:57:58 localhost pppd[479]: pppd 2.3.5 started by root, uid 0

...however I've removed the date and hostname for brevity.

The first part is the output from chat.

pppd[479]: pppd 2.3.5 started by root, uid 0
chat[480]: send (AT^M)
chat[480]: expect (OK)
chat[480]: AT^M^M
chat[480]: OK
chat[480]:  -- got it 
chat[480]: send (ATDT 62578155^M)
chat[480]: expect (CONNECT)
chat[480]: ^M
chat[480]: ATDT 62578155^M^M
pppd[479]: Serial connection established.
chat[480]: CONNECT
chat[480]:  -- got it

Now it switches to ppp. Some of the abreviations it uses are:
LCP Link Control Protocol
PAP Password Authentication Protocol
IPCP Internet Protocol Control Protocol

pppd[479]: Using interface ppp0
pppd[479]: Connect: ppp0 <--> /dev/modem
pppd[479]: sent [LCP ConfReq id=0x1 <magic 0x8c5561c2> <pcomp> <accomp>]
pppd[479]: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <auth pap> <magic 0x3a9e2b78> <pcomp> <accomp>]
pppd[479]: sent [LCP ConfAck id=0x1 <asyncmap 0x0> <auth pap> <magic 0x3a9e2b78> <pcomp> <accomp>]
pppd[479]: sent [LCP ConfReq id=0x1 <magic 0x8c5561c2> <pcomp> <accomp>]
pppd[479]: rcvd [LCP ConfAck id=0x1 <magic 0x8c5561c2> <pcomp> <accomp>]
pppd[479]: sent [PAP AuthReq id=0x1 user="amcbeal" password="ca1op3x"]
pppd[479]: sent [PAP AuthReq id=0x2 user="amcbeal" password="ca1op3x"]
pppd[479]: rcvd [PAP AuthAck id=0x1 ""]
pppd[479]: Remote message: 
pppd[479]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <compress VJ 0f 01>]
pppd[479]: rcvd [IPCP ConfReq id=0x2 <compress VJ 0f 01> <addr 203.108.192.14>]
pppd[479]: sent [IPCP ConfAck id=0x2 <compress VJ 0f 01> <addr 203.108.192.14>]
pppd[479]: rcvd [IPCP ConfNak id=0x1 <addr 203.108.55.26>]
pppd[479]: sent [IPCP ConfReq id=0x2 <addr 203.108.55.26> <compress VJ 0f 01>]
pppd[479]: rcvd [IPCP ConfAck id=0x2 <addr 203.108.55.26> <compress VJ 0f 01>]
pppd[479]: local  IP address 203.108.55.26
pppd[479]: remote IP address 203.108.192.14

The following appears after you close the connection with /etc/ppp/scripts/ppp-off

pppd[479]: Terminating on signal 2.
pppd[479]: sent [LCP TermReq id=0x2 "User request"]
pppd[479]: rcvd [LCP TermAck id=0x2]
pppd[479]: Connection terminated.
pppd[479]: Exit.

ppplog Output from a Working pppd Connection using CHAP

pppd[1160]: pppd 2.4.0 started by root, uid 0
chat[1161]: abort on (BUSY)
chat[1161]: abort on (ERROR)
chat[1161]: abort on (NO CARRIER)
chat[1161]: abort on (NO DIALTONE)
chat[1161]: abort on (Invalid Login)
chat[1161]: abort on (Login incorrect)
chat[1161]: send (AT^M)
chat[1161]: expect (OK)
chat[1161]: AT^M^M
chat[1161]: OK
chat[1161]:  -- got it
chat[1161]: send (ATDT62617444^M)
chat[1161]: expect (CONNECT)
chat[1161]: ^M
chat[1161]: ATDT62617444^M^M
chat[1161]: CONNECT
chat[1161]:  -- got it
pppd[1160]: Serial connection established.
pppd[1160]: using channel 1
pppd[1160]: Using interface ppp0
pppd[1160]: Connect: ppp0 <--> /dev/modem
pppd[1160]: sent [LCP ConfReq id=0x1    ]
pppd[1160]: rcvd [LCP ConfReq id=0x1 < 00 04 00 00>       ]
pppd[1160]: sent [LCP ConfRej id=0x1 < 00 04 00 00> ]
pppd[1160]: rcvd [LCP ConfAck id=0x1    ]
pppd[1160]: rcvd [LCP ConfReq id=0x2      ]
pppd[1160]: sent [LCP ConfAck id=0x2      ]
pppd[1160]: rcvd [CHAP Challenge id=0x1 , name = "tnt3.cbr1"]
pppd[1160]: sent [CHAP Response id=0x1 , name = "amcbeal@ozemail.com.au"]
pppd[1160]: rcvd [CHAP Success id=0x1 "\000"]
pppd[1160]: Remote message: ^@
pppd[1160]: sent [IPCP ConfReq id=0x1  ]
pppd[1160]: sent [CCP ConfReq id=0x1   ]
pppd[1160]: rcvd [IPCP ConfReq id=0x1  ]
pppd[1160]: sent [IPCP ConfAck id=0x1  ]
pppd[1160]: rcvd [IPCP ConfNak id=0x1 ]
pppd[1160]: sent [IPCP ConfReq id=0x2  ]
pppd[1160]: rcvd [LCP ProtRej id=0x3 80 fd 01 01 00 0f 1a 04 78 00 18 04 78 00 15 03 2f]
pppd[1160]: rcvd [IPCP ConfAck id=0x2  ]
pppd[1160]: local  IP address 210.84.37.27
pppd[1160]: remote IP address 210.84.63.40
pppd[1160]: Script /etc/ppp/ip-up started (pid 1180)
pppd[1160]: Script /etc/ppp/ip-up finished (pid 1180), status = 0x0

If your chap-secrets file is missing or incorrect, you might see something like this after it switches to ppp:

pppd[3370]: Serial connection established.
pppd[3370]: using channel 1
pppd[3370]: Using interface ppp0
pppd[3370]: Connect: ppp0 <--> /dev/modem
pppd[3370]: sent [LCP ConfReq id=0x1    ]
pppd[3370]: rcvd [LCP ConfReq id=0x1 < 00 04 00 00>       ]
pppd[3370]: sent [LCP ConfRej id=0x1 < 00 04 00 00> ]
pppd[3370]: rcvd [LCP ConfAck id=0x1    ]
pppd[3370]: rcvd [LCP ConfReq id=0x2      ]
pppd[3370]: sent [LCP ConfAck id=0x2      ]
pppd[3370]: rcvd [CHAP Challenge id=0x1 , name = "tnt3.cbr1"]
pppd[3370]: No CHAP secret found for authenticating us to tnt3.cbr1
pppd[3370]: sent [CHAP Response id=0x1 <68937d227c92b8d9b8b7f64d83214a1a>, name = "amcbeal"]
pppd[3370]: rcvd [CHAP Failure id=0x1 "\000"]
pppd[3370]: Remote message: ^@
pppd[3370]: CHAP authentication failed
pppd[3370]: sent [LCP TermReq id=0x2 "Failed to authenticate ourselves to peer"]
pppd[3370]: rcvd [LCP TermAck id=0x2]
pppd[3370]: Connection terminated.
pppd[3370]: Exit.

If you try to connect to a server and the string <auth chap 80> shows up in the ppplog file, it probably means the server is using a Microsoft variation of CHAP called MSCHAP. You will need to recompile pppd to support this. See README.MSCHAP80 in the pppd source. Fortunately OzEmail does not use MSCHAP so I haven't had to deal with it.