PPP Logging

PPP Log Updated 27-Apr-04

In addition to Windows' Modem Log, it's possible to get a PPP log with most versions of Windows. PPP - point-to-point protocol - is used with dial-up connections to the Internet.

In order to establish a successful dial-up connection to the Internet, after the handshake completes there is an authentication and registration on the network. It's possible to authenticate using plain text (terminal mode) and then start a PPP session; however, some ISPs authentication takes place under PPP.

Without getting too technical, what can PPP logging tell you? It can give you an idea of where a connection is failing: no PPP log entries are made if a PPP session isn't started. The lack of log entries indicates the connection fails at or before plain-text log in. If the PPP log exists, it may offer some clue as to what's going on (explored further down).

HOW TO ENABLE PPP Logging:

The process differs among versions of Windows.

Windows 95, 98 & Me:
Start->Settings->Control Panel -> Network; Click Dial-up Adapter -> Properties -> Advanced. Click Record a log file so that it is checked.

When logging is enabled, the file ppplog.txt will be created in the Windows system folder. (Also see: MS KB 140791)

Windows NT:
The registry key: SYSTEM\CurrentControlSet\Services\RasMan\PPP in the HKEY_LOCAL_MACHINE subtree needs a dword LOGGING value of 1 or 2. (A value of 0 disables PPP logging; 1 is standard logging; 2 is verbose mode. The LOGGING value may need to be added if it does not exist.

When logging is enabled, the file ppp.log will be created in the Windows\System32\RAS folder. (Also see: MS KB 115929)

Windows 2000 and XP:
Win2k Pro and all versions of XP require using a command prompt to enable logging. Open a command prompt with Start->Run and type in cmd

From the command prompt, type:

netsh
ras
set tracing PPP enable
exit

After you enable logging, all PPP activity is logged to a file named ppp.log in the folder Tracing located in the Windows folder.

To disable PPP logging, use the command sequence above, except replace enable with disable.

What the logs look like & what they reveal:

Here's a portion of a PPP log from WinMe calling a network (AOL/ANS) doing authentication in PPP:

04-20-2002 08:27:56.17 - Microsoft Dial Up Adapter log opened.
04-20-2002 08:27:56.17 - Server type is PPP (Point to Point Protocol).
04-20-2002 08:27:56.17 - FSA : Adding Control Protocol 80fd (CCP) to control protocol chain.
04-20-2002 08:27:56.17 - FSA : Protocol not bound - skipping control protocol 803f (NBFCP).
04-20-2002 08:27:56.17 - FSA : Adding Control Protocol 8021 (IPCP) to control protocol chain.
04-20-2002 08:27:56.17 - FSA : Protocol not bound - skipping control protocol 802b (IPXCP).
04-20-2002 08:27:56.17 - FSA : Adding Control Protocol c029 (CallbackCP) to control protocol chain.
04-20-2002 08:27:56.17 - FSA : Adding Control Protocol c027 (no description) to control protocol chain.
04-20-2002 08:27:56.17 - FSA : Adding Control Protocol c023 (PAP) to control protocol chain.
04-20-2002 08:27:56.17 - FSA : Adding Control Protocol c223 (CHAP) to control protocol chain.
04-20-2002 08:27:56.17 - FSA : Adding Control Protocol c021 (LCP) to control protocol chain.
04-20-2002 08:27:56.17 - LCP : Callback negotiation enabled.
04-20-2002 08:27:56.17 - LCP : Layer started.
04-20-2002 08:27:56.17 - PPP : Transmitting Control Packet of length: 25
04-20-2002 08:27:56.17 - Data 0000: c0 20 01 01 00 14 02 06 | .!.....
...
04-20-2002 08:27:56.32 - PPP : Received Control Packet of length: 25
...
04-20-2002 08:27:56.32 - LCP : Received and accepted ACCM of a0000.
04-20-2002 08:27:56.32 - LCP : Naking possibly loopback magic number.
04-20-2002 08:27:56.32 - PPP : Transmitting Control Packet of length: 12
...
04-20-2002 08:27:56.44 - LCP : Loopback! Peer nak'd with our nak of peer's magic number!
04-20-2002 08:27:56.44 - LCP : Peer requests use of magic number xxxx0b.
04-20-2002 08:27:56.44 - PPP : Transmitting Control Packet of length: 25
...
04-20-2002 08:27:56.58 - LCP : Received and accepted ACCM of a0000.
04-20-2002 08:27:56.58 - LCP : Naking possibly loopback magic number.
04-20-2002 08:27:56.58 - PPP : Transmitting Control Packet of length: 12
...
04-20-2002 08:27:58.94 - LCP : Received and accepted ACCM of a0000.
04-20-2002 08:27:58.94 - LCP : Received and accepted authentication protocol c223 (CHAP).
04-20-2002 08:27:58.94 - LCP : Received and accepted magic number xxxxxxx0.
04-20-2002 08:27:58.94 - LCP : Received and accepted protocol field compression option.
04-20-2002 08:27:58.94 - LCP : Received and accepted address+control field compression option.
...
04-20-2002 08:28:00.68 - LCP : Received configure reject for callback control protocol option.
...
04-20-2002 08:28:00.94 - LCP : Received and accepted protocol field compression option.
04-20-2002 08:28:00.94 - LCP : Received and accepted address+control field compression option.
...
04-20-2002 08:28:00.94 - LCP : Layer up.
04-20-2002 08:28:00.94 - CHAP : Layer started.
04-20-2002 08:28:03.58 - PPP : Received Control Packet of length: 31
...
04-20-2002 08:28:03.58 - PPP : Transmitting Control Packet of length: 48
04-20-2002 08:28:03.58 - Data 0000: xx xx xx xx xx xx xx xx | .#.....~
(you may see your UserID in data during authentication here)
...
04-20-2002 08:28:03.90 - CHAP : Login was successful.
04-20-2002 08:28:03.90 - CHAP : Layer up.
04-20-2002 08:28:03.90 - IPCP : Layer started.
04-20-2002 08:28:03.90 - IPCP : IP address is 0.
04-20-2002 08:28:03.90 - CCP : Layer started.
04-20-2002 08:28:03.90 - PPP : Transmitting Control Packet of length: 42
...
04-20-2002 08:28:04.18 - FSA : Received protocol reject for control protocol 80fd.
04-20-2002 08:28:04.18 - CCP : Layer finished.
04-20-2002 08:28:04.42 - PPP : Received Control Packet of length: 24
...
04-20-2002 08:28:04.42 - IPCP : Changing IP address from 0 to xxxxxxxx.
04-20-2002 08:28:04.42 - IPCP : Accepting primary DNS xxxxxx21.
04-20-2002 08:28:04.42 - IPCP : Accepting backup DNS xxxxxx22.
04-20-2002 08:28:04.42 - PPP : Transmitting Control Packet of length: 24
...
04-20-2002 08:28:05.85 - IPCP : Layer up.
04-20-2002 08:28:05.85 - FSA : Last control protocol is up.
04-20-2002 08:29:52.36 - Remote access driver is shutting down.
04-20-2002 08:29:52.36 - CRC Errors 0
04-20-2002 08:29:52.36 - Timeout Errors 0
04-20-2002 08:29:52.36 - Alignment Errors 0
04-20-2002 08:29:52.36 - Overrun Errors 0
04-20-2002 08:29:52.36 - Framing Errors 0
04-20-2002 08:29:52.36 - Buffer Overrun Errors 0
04-20-2002 08:29:52.36 - Incomplete Packets 0
04-20-2002 08:29:52.36 - Bytes Received 69017
04-20-2002 08:29:52.36 - Bytes Transmittted 13862
04-20-2002 08:29:52.36 - Frames Received 163
04-20-2002 08:29:52.36 - Frames Transmitted 175
04-20-2002 08:29:52.36 - LCP : Layer down.
04-20-2002 08:29:52.36 - CHAP : Layer down.
04-20-2002 08:29:52.36 - IPCP : Layer down.
04-20-2002 08:29:52.37 - CCP : Layer started.
04-20-2002 08:29:52.37 - PPP : Transmitting Control Packet of length: 6
...
04-20-2002 08:29:52.62 - LCP : Received terminate acknowledgement.
04-20-2002 08:29:52.62 - LCP : Layer finished.
04-20-2002 08:29:52.62 - Microsoft Dial Up Adapter log closed.

Here's a portion of a PPP log from WindowsXP calling the same number, and failing with a DUNS ERROR 737:

[2584] 10:23:06:809: PPPEMSG_Start recvd, d=, hPort=6,callback=0,mask=11111a,IfType=-1
[1160] 10:23:06:809: Line up event occurred on port 6
[1160] 10:23:06:809: Local identification = MSRAS-1-NAME
...
[1160] 10:23:07:390: The control protocol for c021, returned error 737
[1160] 10:23:07:390: while making a configure result on port 6
[1160] 10:23:07:390: FsmClose event received for protocol c021 on port 6
[1160] 10:23:07:390: RemoveFromTimerQ called portid=6,Id=2,Protocol=c021,EventType=0,fAuth=0
[1160] 10:23:07:390: FsmThisLayerDown called for protocol = c021, port = 6
[1160] 10:23:07:390: RemoveFromTimerQ called portid=6,Id=0,Protocol=c029,EventType=0,fAuth=0
[1160] 10:23:07:390: <PPP packet sent at 04/20/2002 20:23:07:390
[1160] 10:23:07:390: <Protocol = LCP, Type = Terminate-Req, Length = 0x12, Id = 0x3, Port = 6
...
[2584] 10:23:07:500: PppStop

[2584] 10:23:07:500: PPPEMSG_Stop recvd

[1160] 10:23:07:500: FsmClose event received for protocol c021 on port 6
[1160] 10:23:07:500: RemoveFromTimerQ called portid=6,Id=3,Protocol=c021,EventType=0,fAuth=0
[1160] 10:23:07:500: FsmThisLayerFinished called for protocol = c021, port = 6
[1160] 10:23:07:500: NotifyCaller(hPort=6, dwMsgId=10)
[1036] 10:23:08:481: PPPEMSG_LineDown recvd, hPort=6

[1160] 10:23:08:511: Line down event occurred on port 6
[1160] 10:23:08:792: FsmDown event received for protocol c021 on port 6
[1160] 10:23:08:792: RemoveFromTimerQ called portid=6,Id=3,Protocol=c021,EventType=0,fAuth=0
[1160] 10:23:08:792: FsmReset called for protocol = c021, port = 6
[1160] 10:23:08:792: RemoveFromTimerQ called portid=6,Id=0,Protocol=0,EventType=3,fAuth=0
[1160] 10:23:08:792: RemoveFromTimerQ called portid=6,Id=0,Protocol=0,EventType=7,fAuth=0
[1160] 10:23:08:792: RemoveFromTimerQ called portid=6,Id=0,Protocol=0,EventType=2,fAuth=0
[1160] 10:23:08:792: RemoveFromTimerQ called portid=6,Id=0,Protocol=0,EventType=1,fAuth=0
[1160] 10:23:08:792: RemoveFromTimerQ called portid=6,Id=0,Protocol=c029,EventType=0,fAuth=0
[1160] 10:23:08:792: LcpEnd
[1160] 10:23:08:792: Post line down event occurred on port 6
[1160] 10:23:08:792: NotifyCaller(hPort=6, dwMsgId=23)