FreeBSD talking to Windows client (with MSCHAPv2 and MPPE) log

ppp.log (text/plain), 14.75 KB, created by Sasha Polonsky on 2006-04-25 12:32:53 UTC

Apr 25 22:18:38 env pptpd[90990]: MGR: Launching /usr/local/sbin/pptpctrl to handle client
Apr 25 22:18:38 env pptpd[90990]: CTRL: pppd options file = /etc/ppp/ppp.conf
Apr 25 22:18:38 env pptpd[90990]: CTRL: Client 195.26.18.9 control connection started
Apr 25 22:18:38 env pptpd[90990]: CTRL: Received PPTP Control Message (type: 1)
Apr 25 22:18:38 env pptpd[90990]: CTRL: Made a START CTRL CONN RPLY packet
Apr 25 22:18:38 env pptpd[90990]: CTRL: I wrote 156 bytes to the client.
Apr 25 22:18:38 env pptpd[90990]: CTRL: Sent packet to client
Apr 25 22:18:38 env pptpd[90990]: CTRL: Received PPTP Control Message (type: 7)
Apr 25 22:18:38 env pptpd[90990]: CTRL: Set parameters to 1525 maxbps, 64 window size
Apr 25 22:18:38 env pptpd[90990]: CTRL: Made a OUT CALL RPLY packet
Apr 25 22:18:38 env pptpd[90990]: CTRL: Starting call (launching pppd, opening GRE)
Apr 25 22:18:38 env pptpd[90990]: CTRL: pty_fd = 6
Apr 25 22:18:38 env pptpd[90990]: CTRL: tty_fd = 5
Apr 25 22:18:38 env pptpd[90990]: CTRL: I wrote 32 bytes to the client.
Apr 25 22:18:38 env pptpd[90990]: CTRL: Sent packet to client
Apr 25 22:18:38 env pptpd[90990]: CTRL: Received PPTP Control Message (type: 15)
Apr 25 22:18:38 env pptpd[90990]: CTRL: Got a SET LINK INFO packet with standard ACCMs
Apr 25 22:18:38 env pptpd[90990]: GRE: Discarding duplicate packet
Apr 25 22:18:39 env ppp[90991]: Phase: Using interface: tun0
Apr 25 22:18:39 env ppp[90991]: Phase: deflink: Created in closed state
Apr 25 22:18:39 env ppp[90991]: IPCP: Selected IP address 10.0.0.105
Apr 25 22:18:39 env ppp[90991]: Phase: PPP Started (direct mode).
Apr 25 22:18:39 env ppp[90991]: Phase: bundle: Establish
Apr 25 22:18:39 env ppp[90991]: Phase: deflink: closed -> opening
Apr 25 22:18:39 env ppp[90991]: Phase: deflink: Connected!
Apr 25 22:18:39 env ppp[90991]: Phase: deflink: opening -> carrier
Apr 25 22:18:39 env ppp[90991]: Phase: deflink: carrier -> lcp
Apr 25 22:18:39 env ppp[90991]: LCP: FSM: Using "deflink" as a transport
Apr 25 22:18:39 env ppp[90991]: LCP: deflink: State change Initial --> Closed
Apr 25 22:18:39 env ppp[90991]: LCP: deflink: State change Closed --> Stopped
Apr 25 22:18:40 env ppp[90991]: LCP: deflink: LayerStart
Apr 25 22:18:40 env ppp[90991]: LCP: deflink: SendConfigReq(1) state = Stopped
Apr 25 22:18:40 env ppp[90991]: LCP:  ACFCOMP[2]
Apr 25 22:18:40 env ppp[90991]: LCP:  PROTOCOMP[2]
Apr 25 22:18:40 env ppp[90991]: LCP:  ACCMAP[6] 0x00000000
Apr 25 22:18:40 env ppp[90991]: LCP:  MRU[4] 1500
Apr 25 22:18:40 env ppp[90991]: LCP:  MAGICNUM[6] 0xe34ae5a6
Apr 25 22:18:40 env ppp[90991]: LCP:  AUTHPROTO[5] 0xc223 (CHAP 0x05)
Apr 25 22:18:40 env ppp[90991]: LCP: deflink: State change Stopped --> Req-Sent
Apr 25 22:18:40 env ppp[90991]: LCP: deflink: RecvConfigNak(1) state = Req-Sent
Apr 25 22:18:40 env ppp[90991]: LCP:  AUTHPROTO[5] 0xc223 (CHAP 0x81)
Apr 25 22:18:40 env ppp[90991]: LCP: deflink: SendConfigReq(2) state = Req-Sent
Apr 25 22:18:40 env ppp[90991]: LCP:  ACFCOMP[2]
Apr 25 22:18:40 env ppp[90991]: LCP:  PROTOCOMP[2]
Apr 25 22:18:40 env ppp[90991]: LCP:  ACCMAP[6] 0x00000000
Apr 25 22:18:40 env ppp[90991]: LCP:  MRU[4] 1500
Apr 25 22:18:40 env ppp[90991]: LCP:  MAGICNUM[6] 0xe34ae5a6
Apr 25 22:18:40 env ppp[90991]: LCP:  AUTHPROTO[5] 0xc223 (CHAP 0x81)
Apr 25 22:18:40 env ppp[90991]: LCP: deflink: RecvConfigAck(2) state = Req-Sent
Apr 25 22:18:40 env ppp[90991]: LCP:  ACFCOMP[2]
Apr 25 22:18:40 env ppp[90991]: LCP:  PROTOCOMP[2]
Apr 25 22:18:40 env ppp[90991]: LCP:  ACCMAP[6] 0x00000000
Apr 25 22:18:40 env ppp[90991]: LCP:  MRU[4] 1500
Apr 25 22:18:40 env ppp[90991]: LCP:  MAGICNUM[6] 0xe34ae5a6
Apr 25 22:18:40 env ppp[90991]: LCP:  AUTHPROTO[5] 0xc223 (CHAP 0x81)
Apr 25 22:18:40 env ppp[90991]: LCP: deflink: State change Req-Sent --> Ack-Rcvd
Apr 25 22:18:41 env ppp[90991]: LCP: deflink: RecvConfigReq(1) state = Ack-Rcvd
Apr 25 22:18:41 env ppp[90991]: LCP:  MRU[4] 1400
Apr 25 22:18:41 env ppp[90991]: LCP:  MAGICNUM[6] 0x26bb5ad4
Apr 25 22:18:41 env ppp[90991]: LCP:  PROTOCOMP[2]
Apr 25 22:18:41 env ppp[90991]: LCP:  ACFCOMP[2]
Apr 25 22:18:41 env ppp[90991]: LCP:  CALLBACK[3] CBCP
Apr 25 22:18:41 env ppp[90991]: LCP: deflink: SendConfigRej(1) state = Ack-Rcvd
Apr 25 22:18:41 env ppp[90991]: LCP:  CALLBACK[3] CBCP
Apr 25 22:18:41 env ppp[90991]: LCP: deflink: RecvConfigReq(2) state = Ack-Rcvd
Apr 25 22:18:41 env ppp[90991]: LCP:  MRU[4] 1400
Apr 25 22:18:41 env ppp[90991]: LCP:  MAGICNUM[6] 0x26bb5ad4
Apr 25 22:18:41 env ppp[90991]: LCP:  PROTOCOMP[2]
Apr 25 22:18:41 env ppp[90991]: LCP:  ACFCOMP[2]
Apr 25 22:18:41 env ppp[90991]: LCP: deflink: SendConfigAck(2) state = Ack-Rcvd
Apr 25 22:18:41 env ppp[90991]: LCP:  MRU[4] 1400
Apr 25 22:18:41 env ppp[90991]: LCP:  MAGICNUM[6] 0x26bb5ad4
Apr 25 22:18:41 env ppp[90991]: LCP:  PROTOCOMP[2]
Apr 25 22:18:41 env ppp[90991]: LCP:  ACFCOMP[2]
Apr 25 22:18:41 env ppp[90991]: LCP: deflink: State change Ack-Rcvd --> Opened
Apr 25 22:18:41 env ppp[90991]: LCP: deflink: LayerUp
Apr 25 22:18:41 env ppp[90991]: Phase: bundle: Authenticate
Apr 25 22:18:41 env ppp[90991]: Phase: deflink: his = none, mine = CHAP 0x81
Apr 25 22:18:41 env ppp[90991]: Phase: Chap Output: CHALLENGE
Apr 25 22:18:41 env pptpd[90990]: CTRL: Received PPTP Control Message (type: 15)
Apr 25 22:18:41 env pptpd[90990]: CTRL: Ignored a SET LINK INFO packet with real ACCMs!
Apr 25 22:18:41 env ppp[90991]: LCP: deflink: RecvIdent(3) state = Opened
Apr 25 22:18:41 env ppp[90991]: LCP:  MAGICNUM 26bb5ad4
Apr 25 22:18:41 env ppp[90991]: LCP:  TEXT MSRA
Apr 25 22:18:41 env ppp[90991]: Phase: Chap Input: RESPONSE (49 bytes from punk)
Apr 25 22:18:41 env ppp[90991]: Phase: Chap Output: SUCCESS
Apr 25 22:18:41 env ppp[90991]: CCP: FSM: Using "deflink" as a transport
Apr 25 22:18:41 env ppp[90991]: CCP: deflink: State change Initial --> Closed
Apr 25 22:18:41 env ppp[90991]: CCP: deflink: LayerStart.
Apr 25 22:18:41 env ppp[90991]: CCP: deflink: SendConfigReq(1) state = Closed
Apr 25 22:18:41 env ppp[90991]: CCP:  DEFLATE[4] win 15
Apr 25 22:18:41 env ppp[90991]: CCP:  PRED1[2] 
Apr 25 22:18:41 env ppp[90991]: CCP:  MPPE[6] value 0x000000e0 (128/56/40 bits, stateful)
Apr 25 22:18:41 env ppp[90991]: CCP: deflink: State change Closed --> Req-Sent
Apr 25 22:18:41 env ppp[90991]: Phase: deflink: lcp -> open
Apr 25 22:18:41 env ppp[90991]: Phase: bundle: Network
Apr 25 22:18:41 env ppp[90991]: IPCP: FSM: Using "deflink" as a transport
Apr 25 22:18:41 env ppp[90991]: IPCP: deflink: State change Initial --> Closed
Apr 25 22:18:41 env ppp[90991]: IPCP: deflink: LayerStart.
Apr 25 22:18:41 env ppp[90991]: IPCP: deflink: SendConfigReq(1) state = Closed
Apr 25 22:18:41 env ppp[90991]: IPCP:  IPADDR[6] 10.0.0.1
Apr 25 22:18:41 env ppp[90991]: IPCP:  COMPPROTO[6] 16 VJ slots with slot compression
Apr 25 22:18:41 env ppp[90991]: IPCP: deflink: State change Closed --> Req-Sent
Apr 25 22:18:41 env ppp[90991]: CCP: deflink: RecvConfigReq(5) state = Req-Sent
Apr 25 22:18:41 env ppp[90991]: CCP:  MPPE[6] value 0x010000e1 (128/56/40 bits, stateless, compressed)
Apr 25 22:18:41 env ppp[90991]: CCP: deflink: SendConfigNak(5) state = Req-Sent
Apr 25 22:18:41 env ppp[90991]: CCP:  MPPE[6] value 0x01000040 (128 bits, stateless)
Apr 25 22:18:41 env ppp[90991]: CCP: deflink: RecvConfigRej(1) state = Req-Sent
Apr 25 22:18:41 env ppp[90991]: CCP:  DEFLATE[4] win 15
Apr 25 22:18:41 env ppp[90991]: CCP:  PRED1[2] 
Apr 25 22:18:41 env ppp[90991]: CCP: deflink: SendConfigReq(2) state = Req-Sent
Apr 25 22:18:41 env ppp[90991]: CCP:  MPPE[6] value 0x000000e0 (128/56/40 bits, stateful)
Apr 25 22:18:41 env ppp[90991]: IPCP: deflink: RecvConfigRej(1) state = Req-Sent
Apr 25 22:18:41 env ppp[90991]: IPCP:  COMPPROTO[6] 16 VJ slots with slot compression
Apr 25 22:18:41 env ppp[90991]: IPCP: deflink: SendConfigReq(2) state = Req-Sent
Apr 25 22:18:41 env ppp[90991]: IPCP:  IPADDR[6] 10.0.0.1
Apr 25 22:18:41 env ppp[90991]: CCP: deflink: RecvConfigReq(7) state = Req-Sent
Apr 25 22:18:41 env ppp[90991]: CCP:  MPPE[6] value 0x01000040 (128 bits, stateless)
Apr 25 22:18:41 env ppp[90991]: CCP: deflink: SendConfigAck(7) state = Req-Sent
Apr 25 22:18:41 env ppp[90991]: CCP:  MPPE[6] value 0x01000040 (128 bits, stateless)
Apr 25 22:18:41 env ppp[90991]: CCP: deflink: State change Req-Sent --> Ack-Sent
Apr 25 22:18:41 env ppp[90991]: CCP: deflink: RecvConfigNak(2) state = Ack-Sent
Apr 25 22:18:41 env ppp[90991]: CCP:  MPPE[6] value 0x00000040 (128 bits, stateful)
Apr 25 22:18:41 env ppp[90991]: CCP: deflink: SendConfigReq(3) state = Ack-Sent
Apr 25 22:18:41 env ppp[90991]: CCP:  MPPE[6] value 0x00000040 (128 bits, stateful)
Apr 25 22:18:41 env ppp[90991]: IPCP: deflink: RecvConfigAck(2) state = Req-Sent
Apr 25 22:18:41 env ppp[90991]: IPCP:  IPADDR[6] 10.0.0.1
Apr 25 22:18:41 env ppp[90991]: IPCP: deflink: State change Req-Sent --> Ack-Rcvd
Apr 25 22:18:41 env ppp[90991]: CCP: deflink: RecvConfigAck(3) state = Ack-Sent
Apr 25 22:18:41 env ppp[90991]: CCP:  MPPE[6] value 0x00000040 (128 bits, stateful)
Apr 25 22:18:41 env ppp[90991]: CCP: deflink: State change Ack-Sent --> Opened
Apr 25 22:18:41 env ppp[90991]: CCP: deflink: LayerUp.
Apr 25 22:18:41 env ppp[90991]: CCP: MPPE: Input channel initiated
Apr 25 22:18:41 env ppp[90991]: CCP: MPPE: Output channel initiated
Apr 25 22:18:41 env ppp[90991]: CCP: deflink: Out = MPPE[18], In = MPPE[18]
Apr 25 22:18:41 env ppp[90991]: LCP: Reducing MTU from 1400 to 1398 (CCP requirement)
Apr 25 22:18:44 env ppp[90991]: IPCP: deflink: RecvConfigReq(8) state = Ack-Rcvd
Apr 25 22:18:44 env ppp[90991]: IPCP:  IPADDR[6] 0.0.0.0
Apr 25 22:18:44 env ppp[90991]: IPCP:  PRIDNS[6] 0.0.0.0
Apr 25 22:18:44 env ppp[90991]: IPCP:  PRINBNS[6] 0.0.0.0
Apr 25 22:18:44 env ppp[90991]: IPCP:  SECDNS[6] 0.0.0.0
Apr 25 22:18:44 env ppp[90991]: IPCP:  SECNBNS[6] 0.0.0.0
Apr 25 22:18:44 env ppp[90991]: IPCP: NBNS REQ - rejected - nbns not set
Apr 25 22:18:44 env ppp[90991]: IPCP: deflink: SendConfigRej(8) state = Ack-Rcvd
Apr 25 22:18:44 env ppp[90991]: IPCP:  SECNBNS[6] 0.0.0.0
Apr 25 22:18:44 env ppp[90991]: IPCP: deflink: RecvConfigReq(9) state = Ack-Rcvd
Apr 25 22:18:44 env ppp[90991]: IPCP:  IPADDR[6] 0.0.0.0
Apr 25 22:18:44 env ppp[90991]: IPCP:  PRIDNS[6] 0.0.0.0
Apr 25 22:18:44 env ppp[90991]: IPCP:  PRINBNS[6] 0.0.0.0
Apr 25 22:18:44 env ppp[90991]: IPCP:  SECDNS[6] 0.0.0.0
Apr 25 22:18:44 env ppp[90991]: IPCP: deflink: SendConfigNak(9) state = Ack-Rcvd
Apr 25 22:18:44 env ppp[90991]: IPCP:  IPADDR[6] 10.0.0.106
Apr 25 22:18:44 env ppp[90991]: IPCP:  PRIDNS[6] 10.0.0.5
Apr 25 22:18:44 env ppp[90991]: IPCP:  PRINBNS[6] 10.0.0.1
Apr 25 22:18:44 env ppp[90991]: IPCP:  SECDNS[6] 255.255.255.255
Apr 25 22:18:45 env ppp[90991]: IPCP: deflink: RecvConfigReq(10) state = Ack-Rcvd
Apr 25 22:18:45 env ppp[90991]: IPCP:  IPADDR[6] 10.0.0.106
Apr 25 22:18:45 env ppp[90991]: IPCP:  PRIDNS[6] 10.0.0.5
Apr 25 22:18:45 env ppp[90991]: IPCP:  PRINBNS[6] 10.0.0.1
Apr 25 22:18:45 env ppp[90991]: IPCP:  SECDNS[6] 255.255.255.255
Apr 25 22:18:45 env ppp[90991]: IPCP: deflink: SendConfigAck(10) state = Ack-Rcvd
Apr 25 22:18:45 env ppp[90991]: IPCP:  IPADDR[6] 10.0.0.106
Apr 25 22:18:45 env ppp[90991]: IPCP:  PRIDNS[6] 10.0.0.5
Apr 25 22:18:45 env ppp[90991]: IPCP:  PRINBNS[6] 10.0.0.1
Apr 25 22:18:45 env ppp[90991]: IPCP:  SECDNS[6] 255.255.255.255
Apr 25 22:18:45 env ppp[90991]: IPCP: deflink: State change Ack-Rcvd --> Opened
Apr 25 22:18:45 env ppp[90991]: IPCP: deflink: LayerUp.
Apr 25 22:18:45 env ppp[90991]: IPCP: myaddr 10.0.0.1 hisaddr = 10.0.0.106
Apr 25 22:18:45 env ppp[90991]: LCP: Reducing MTU from 1400 to 1398 (CCP requirement)
Apr 25 22:19:38 env pptpd[90990]: CTRL: Received PPTP Control Message (type: 5)
Apr 25 22:19:38 env pptpd[90990]: CTRL: Made a ECHO RPLY packet
Apr 25 22:19:38 env pptpd[90990]: CTRL: I wrote 20 bytes to the client.
Apr 25 22:19:38 env pptpd[90990]: CTRL: Sent packet to client
Apr 25 22:19:42 env ppp[90991]: LCP: deflink: RecvTerminateReq(11) state = Opened
Apr 25 22:19:42 env pptpd[90990]: CTRL: Received PPTP Control Message (type: 15)
Apr 25 22:19:42 env ppp[90991]: LCP: deflink: LayerDown
Apr 25 22:19:42 env pptpd[90990]: CTRL: Got a SET LINK INFO packet with standard ACCMs
Apr 25 22:19:42 env ppp[90991]: LCP: deflink: SendTerminateAck(11) state = Opened
Apr 25 22:19:42 env ppp[90991]: LCP: deflink: State change Opened --> Stopping
Apr 25 22:19:42 env ppp[90991]: CCP: deflink: LayerDown.
Apr 25 22:19:42 env ppp[90991]: CCP: deflink: State change Opened --> Starting
Apr 25 22:19:42 env ppp[90991]: CCP: deflink: LayerFinish.
Apr 25 22:19:42 env ppp[90991]: CCP: deflink: State change Starting --> Initial
Apr 25 22:19:42 env ppp[90991]: Phase: deflink: open -> lcp
Apr 25 22:19:42 env ppp[90991]: IPCP: deflink: LayerDown: 10.0.0.1
Apr 25 22:19:42 env ppp[90991]: IPCP: deflink: State change Opened --> Starting
Apr 25 22:19:42 env ppp[90991]: IPCP: deflink: LayerFinish.
Apr 25 22:19:42 env ppp[90991]: IPCP: Connect time: 61 secs: 14597 octets in, 882 octets out
Apr 25 22:19:42 env ppp[90991]: IPCP: 55 packets in, 10 packets out
Apr 25 22:19:42 env ppp[90991]: IPCP:  total 253 bytes/sec, peak 1415 bytes/sec on Tue Apr 25 22:18:50 2006
Apr 25 22:19:42 env ppp[90991]: IPCP: deflink: State change Starting --> Initial
Apr 25 22:19:42 env ppp[90991]: Phase: bundle: Terminate
Apr 25 22:19:42 env pptpd[90990]: CTRL: Received PPTP Control Message (type: 12)
Apr 25 22:19:42 env pptpd[90990]: CTRL: Made a CALL DISCONNECT RPLY packet
Apr 25 22:19:42 env pptpd[90990]: CTRL: Received CALL CLR request (closing call)
Apr 25 22:19:42 env ppp[90991]: Phase: deflink: read (0): Got zero bytes
Apr 25 22:19:42 env pptpd[90990]: CTRL: I wrote 148 bytes to the client.
Apr 25 22:19:42 env ppp[90991]: LCP: deflink: State change Stopping --> Starting
Apr 25 22:19:42 env pptpd[90990]: CTRL: Sent packet to client
Apr 25 22:19:42 env ppp[90991]: LCP: deflink: LayerFinish
Apr 25 22:19:42 env ppp[90991]: LCP: deflink: State change Starting --> Initial
Apr 25 22:19:42 env ppp[90991]: Phase: deflink: Disconnected!
Apr 25 22:19:42 env ppp[90991]: Phase: deflink: Connect time: 63 secs: 17463 octets in, 1733 octets out
Apr 25 22:19:42 env ppp[90991]: Phase: deflink: 72 packets in, 27 packets out
Apr 25 22:19:42 env ppp[90991]: Phase:  total 304 bytes/sec, peak 1642 bytes/sec on Tue Apr 25 22:18:50 2006
Apr 25 22:19:42 env ppp[90991]: Phase: deflink: lcp -> closed
Apr 25 22:19:42 env ppp[90991]: Phase: bundle: Dead
Apr 25 22:19:42 env ppp[90991]: Phase: PPP Terminated (normal).
Apr 25 22:19:42 env pptpd[90990]: CTRL: Received PPTP Control Message (type: 3)
Apr 25 22:19:42 env pptpd[90990]: CTRL: Made a STOP CTRL CONN RPLY packet
Apr 25 22:19:42 env pptpd[90990]: CTRL: Received STOP CTRL CONN request (disconnecting)
Apr 25 22:19:42 env pptpd[90990]: CTRL: I wrote 16 bytes to the client.
Apr 25 22:19:42 env pptpd[90990]: CTRL: Sent packet to client
Apr 25 22:19:42 env pptpd[90990]: CTRL: Closing child ppp with pid 90991
Apr 25 22:19:42 env pptpd[90990]: CTRL: Client 195.26.18.9 control connection finished
Apr 25 22:19:42 env pptpd[90990]: CTRL: Exiting now
Apr 25 22:19:42 env pptpd[55595]: MGR: Reaped child 90990