Hello All,
I have m0n0wall (1.233) running a PPTP VPN which uses a radius server for authentication, and a remote DD-WRT based client that connects. At the remote location there are a few IP phones that connect to an Asterisk server via SIP.
For months this setup was working fine, but now the connection goes up and down. I'm hoping that someone can help me narrow down the problem. Here are the logs showing some of the problem:
Last 500 system log entries
Aug 28 12:30:25 mpd: [pt0] IFACE: Up event
Aug 28 12:30:25 mpd: [pt0] exec: /usr/local/sbin/vpn-linkup ng1 inet 192.168.1.2 192.168.1.176 g3home-vpn
Aug 28 12:30:25 mpd: [pt0] exec: /sbin/route add 192.168.1.2 -iface lo0
Aug 28 12:30:24 mpd: [pt0] exec: /usr/sbin/arp -s 192.168.1.176 0:0:24:c4:37:b1 pub
Aug 28 12:30:24 mpd: [pt0] exec: /sbin/ifconfig ng1 192.168.1.2 192.168.1.176 netmask 0xffffffff -link0
Aug 28 12:30:24 mpd: [pt0] setting interface ng1 MTU to 1446 bytes
Aug 28 12:30:24 mpd: [pt0] IFACE: Up event
Aug 28 12:30:24 mpd: 192.168.1.2 -> 192.168.1.176
Aug 28 12:30:24 mpd: [pt0] IPCP: LayerUp
Aug 28 12:30:24 mpd: [pt0] IPCP: state change Ack-Sent --> Opened
Aug 28 12:30:24 mpd: COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 28 12:30:24 mpd: IPADDR 192.168.1.2
Aug 28 12:30:24 mpd: [pt0] IPCP: rec'd Configure Ack #140 link 0 (Ack-Sent)
Aug 28 12:30:24 mpd: COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 28 12:30:24 mpd: IPADDR 192.168.1.2
Aug 28 12:30:24 mpd: [pt0] IPCP: SendConfigReq #140
Aug 28 12:30:23 mpd: [pt0] IPCP: state change Req-Sent --> Ack-Sent
Aug 28 12:30:23 mpd: SECDNS 208.67.220.220
Aug 28 12:30:23 mpd: PRIDNS 208.67.222.222
Aug 28 12:30:23 mpd: IPADDR 192.168.1.176
Aug 28 12:30:23 mpd: COMPPROTO VJCOMP, 16 comp. channels, allow comp-cid
Aug 28 12:30:23 mpd: [pt0] IPCP: SendConfigAck #2
Aug 28 12:30:23 mpd: SECDNS 208.67.220.220
Aug 28 12:30:23 mpd: PRIDNS 208.67.222.222
Aug 28 12:30:23 mpd: 192.168.1.176 is OK
Aug 28 12:30:23 mpd: IPADDR 192.168.1.176
Aug 28 12:30:23 mpd: COMPPROTO VJCOMP, 16 comp. channels, allow comp-cid
Aug 28 12:30:23 mpd: [pt0] IPCP: rec'd Configure Request #2 link 0 (Req-Sent)
Aug 28 12:30:23 mpd: SECDNS 208.67.220.220
Aug 28 12:30:23 mpd: PRIDNS 208.67.222.222
Aug 28 12:30:23 mpd: IPADDR 192.168.1.176
Aug 28 12:30:23 mpd: [pt0] IPCP: SendConfigNak #1
Aug 28 12:30:23 mpd: NAKing with 208.67.220.220
Aug 28 12:30:23 mpd: SECDNS 0.0.0.0
Aug 28 12:30:23 mpd: NAKing with 208.67.222.222
Aug 28 12:30:23 mpd: PRIDNS 0.0.0.0
Aug 28 12:30:23 mpd: NAKing with 192.168.1.176
Aug 28 12:30:23 mpd: IPADDR 10.1.1.1
Aug 28 12:30:23 mpd: COMPPROTO VJCOMP, 16 comp. channels, allow comp-cid
Aug 28 12:30:23 mpd: [pt0] IPCP: rec'd Configure Request #1 link 0 (Req-Sent)
Aug 28 12:30:23 mpd: [pt0] setting interface ng1 MTU to 1446 bytes
Aug 28 12:30:23 mpd: Decompress using: MPPE, 128 bit
Aug 28 12:30:23 mpd: Compress using: MPPE, 128 bit
Aug 28 12:30:23 mpd: [pt0] CCP: LayerUp
Aug 28 12:30:23 mpd: [pt0] CCP: state change Ack-Sent --> Opened
Aug 28 12:30:23 mpd: 0x00000040: MPPE, 128 bit
Aug 28 12:30:23 mpd: MPPC
Aug 28 12:30:23 mpd: [pt0] CCP: rec'd Configure Ack #51 link 0 (Ack-Sent)
Aug 28 12:30:23 mpd: [pt0] CCP: state change Req-Sent --> Ack-Sent
Aug 28 12:30:23 mpd: 0x00000040: MPPE, 128 bit
Aug 28 12:30:23 mpd: MPPC
Aug 28 12:30:23 mpd: [pt0] CCP: SendConfigAck #2
Aug 28 12:30:23 mpd: [pt0] CCP: Checking whether 128 bits are acceptable -> yes
Aug 28 12:30:23 mpd: 0x00000040: MPPE, 128 bit
Aug 28 12:30:23 mpd: MPPC
Aug 28 12:30:23 mpd: [pt0] CCP: rec'd Configure Request #2 link 0 (Req-Sent)
Aug 28 12:30:23 mpd: 0x00000040: MPPE, 128 bit
Aug 28 12:30:23 mpd: MPPC
Aug 28 12:30:23 mpd: [pt0] CCP: Checking whether 128 bits are enabled -> yes
Aug 28 12:30:23 mpd: [pt0] CCP: Checking whether 56 bits are enabled -> no
Aug 28 12:30:22 mpd: [pt0] CCP: Checking whether 40 bits are enabled -> no
Aug 28 12:30:22 mpd: [pt0] CCP: SendConfigReq #51
Aug 28 12:30:22 mpd: 0x00000040: MPPE, 128 bit
Aug 28 12:30:22 mpd: MPPC
Aug 28 12:30:22 mpd: [pt0] CCP: rec'd Configure Nak #50 link 0 (Req-Sent)
Aug 28 12:30:22 mpd: [pt0] IPCP: rec'd Terminate Ack #139 link 0 (Req-Sent)
Aug 28 12:30:22 mpd: 0x00000040: MPPE, 128 bit
Aug 28 12:30:22 mpd: MPPC
Aug 28 12:30:22 mpd: [pt0] CCP: SendConfigNak #1
Aug 28 12:30:22 mpd: [pt0] CCP: Checking whether 128 bits are acceptable -> yes
Aug 28 12:30:22 mpd: [pt0] CCP: Checking whether 56 bits are acceptable -> no
Aug 28 12:30:22 mpd: [pt0] CCP: Checking whether 40 bits are acceptable -> no
Aug 28 12:30:22 mpd: 0x000000e1: MPPC MPPE, 40 bit, 56 bit, 128 bit
Aug 28 12:30:22 mpd: MPPC
Aug 28 12:30:22 mpd: [pt0] CCP: rec'd Configure Request #1 link 0 (Req-Sent)
Aug 28 12:30:22 mpd: [pt0] RADIUS: RadiusSendRequest: RAD_ACCOUNTING_RESPONSE for user g3home-vpn
Aug 28 12:30:22 mpd: [pt0] RADIUS: RadiusAccount: Sending accounting data (Type: 1)
Aug 28 12:30:22 mpd: [pt0] RADIUS: RadiusAddServer Adding 192.168.1.10
Aug 28 12:30:22 mpd: [pt0] RADIUS: RadiusAccount for: g3home-vpn
Aug 28 12:30:22 mpd: 0x01000040: MPPE, 128 bit, stateless
Aug 28 12:30:22 mpd: MPPC
Aug 28 12:30:22 mpd: [pt0] CCP: Checking whether 128 bits are enabled -> yes
Aug 28 12:30:22 mpd: [pt0] CCP: Checking whether 56 bits are enabled -> no
Aug 28 12:30:22 mpd: [pt0] CCP: Checking whether 40 bits are enabled -> no
Aug 28 12:30:22 mpd: [pt0] CCP: SendConfigReq #50
Aug 28 12:30:22 mpd: [pt0] CCP: state change Starting --> Req-Sent
Aug 28 12:30:22 mpd: [pt0] CCP: Up event
Aug 28 12:30:22 mpd: [pt0] CCP: LayerStart
Aug 28 12:30:22 mpd: [pt0] CCP: state change Initial --> Starting
Aug 28 12:30:22 mpd: [pt0] CCP: Open event
Aug 28 12:30:22 mpd: COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 28 12:30:22 mpd: IPADDR 192.168.1.2
Aug 28 12:30:22 mpd: [pt0] IPCP: SendConfigReq #139
Aug 28 12:30:22 mpd: [pt0] IPCP: state change Starting --> Req-Sent
Aug 28 12:30:22 mpd: [pt0] IPCP: Up event
Aug 28 12:30:22 mpd: [pt0] up: 1 link, total bandwidth 64000 bps
Aug 28 12:30:22 mpd: [pt0] setting interface ng1 MTU to 1450 bytes
Aug 28 12:30:22 mpd: [pt0] LCP: phase shift AUTHENTICATE --> NETWORK
Aug 28 12:30:22 mpd: [pt0] LCP: authorization successful
Aug 28 12:30:22 mpd: [pt0] CHAP: sending SUCCESS
Aug 28 12:30:22 mpd: Response is valid
Aug 28 12:30:22 mpd: [pt0] RADIUS: RadiusGetParams: Dropping MPD vendor specific attribute: 8
Aug 28 12:30:22 mpd: [pt0] RADIUS: RadiusGetParams: RAD_MICROSOFT_MS_MPPE_ENCRYPTION_TYPES: 4 (128 bit)
Aug 28 12:30:22 mpd: [pt0] RADIUS: RadiusGetParams: Dropping MPD vendor specific attribute: 7
Aug 28 12:30:22 mpd: [pt0] RADIUS: RadiusGetParams: RAD_MICROSOFT_MS_MPPE_ENCRYPTION_POLICY: 2 (Required)
Aug 28 12:30:22 mpd: [pt0] RADIUS: RadiusGetParams: Dropping MPD vendor specific attribute: 10
Aug 28 12:30:22 mpd: [pt0] RADIUS: RadiusGetParams: RAD_MICROSOFT_MS_CHAP_DOMAIN: ^AFIRM
Aug 28 12:30:22 mpd: [pt0] RADIUS: RadiusGetParams: Dropping MPD vendor specific attribute: 26
Aug 28 12:30:22 mpd: [pt0] RADIUS: RadiusGetParams: RAD_MICROSOFT_MS_CHAP2_SUCCESS: S=5C67811AB229DC0C70F283047E959226F56F7642
Aug 28 12:30:22 mpd: [pt0] RADIUS: RadiusGetParams: Dropping MPD vendor specific attribute: 16
Aug 28 12:30:22 mpd: [pt0] RADIUS: RadiusGetParams: RAD_MICROSOFT_MS_MPPE_SEND_KEY
Aug 28 12:30:22 mpd: [pt0] RADIUS: RadiusGetParams: Dropping MPD vendor specific attribute: 17
Aug 28 12:30:22 mpd: [pt0] RADIUS: RadiusGetParams: RAD_MICROSOFT_MS_MPPE_RECV_KEY
Aug 28 12:30:22 mpd: [pt0] RADIUS: RadiusGetParams: RAD_CLASS: 1571424108
Aug 28 12:30:22 mpd: [pt0] RADIUS: RadiusGetParams: RAD_FRAMED_PROTOCOL: 2
Aug 28 12:30:22 mpd: [pt0] RADIUS: RadiusGetParams: RAD_FRAMED_PROTOCOL: 1
Aug 28 12:30:22 mpd: [pt0] RADIUS: RadiusSendRequest: RAD_ACCESS_ACCEPT for user g3home-vpn
Aug 28 12:30:22 mpd: [pt0] RADIUS: RadiusPutAuth: RADIUS_CHAP (MSOFTv2) peer name: g3home-vpn
Aug 28 12:30:22 mpd: [pt0] RADIUS: RadiusAddServer Adding 192.168.1.10
Aug 28 12:30:22 mpd: Name: "g3home-vpn"
Aug 28 12:30:22 mpd: [pt0] CHAP: rec'd RESPONSE #1
Aug 28 12:30:22 mpd: [pt0] LCP: LayerUp
Aug 28 12:30:22 mpd: [pt0] CHAP: sending CHALLENGE
Aug 28 12:30:22 mpd: [pt0] LCP: auth: peer wants nothing, I want CHAP
Aug 28 12:30:22 mpd: [pt0] LCP: phase shift ESTABLISH --> AUTHENTICATE
Aug 28 12:30:22 mpd: [pt0] LCP: state change Ack-Sent --> Opened
Aug 28 12:30:22 mpd: AUTHPROTO CHAP MSOFTv2
Aug 28 12:30:22 mpd: MAGICNUM 7b896db8
Aug 28 12:30:22 mpd: MRU 1500
Aug 28 12:30:22 mpd: PROTOCOMP
Aug 28 12:30:22 mpd: ACFCOMP
Aug 28 12:30:22 mpd: [pt0] LCP: rec'd Configure Ack #39 link 0 (Ack-Sent)
Aug 28 12:30:22 mpd: AUTHPROTO CHAP MSOFTv2
Aug 28 12:30:22 mpd: MAGICNUM 7b896db8
Aug 28 12:30:22 mpd: MRU 1500
Aug 28 12:30:22 mpd: PROTOCOMP
Aug 28 12:30:22 mpd: ACFCOMP
Aug 28 12:30:22 mpd: [pt0] LCP: SendConfigReq #39
Aug 28 12:30:22 mpd: MP SHORTSEQ
Aug 28 12:30:22 mpd: MP MRRU 1600
Aug 28 12:30:22 mpd: [pt0] LCP: rec'd Configure Reject #38 link 0 (Ack-Sent)
Aug 28 12:30:22 mpd: Wrong id#, expecting 38
Aug 28 12:30:22 mpd: [pt0] LCP: rec'd Configure Reject #37 link 0 (Ack-Sent)
Aug 28 12:30:22 mpd: [pt0] LCP: state change Req-Sent --> Ack-Sent
Aug 28 12:30:22 mpd: ACFCOMP
Aug 28 12:30:22 mpd: PROTOCOMP
Aug 28 12:30:22 mpd: MAGICNUM 300e8ce6
Aug 28 12:30:22 mpd: ACCMAP 0x00000000
Aug 28 12:30:22 mpd: MRU 1450
Aug 28 12:30:22 mpd: [pt0] LCP: SendConfigAck #1
Aug 28 12:30:22 mpd: ACFCOMP
Aug 28 12:30:22 mpd: PROTOCOMP
Aug 28 12:30:22 mpd: MAGICNUM 300e8ce6
Aug 28 12:30:22 mpd: ACCMAP 0x00000000
Aug 28 12:30:22 mpd: MRU 1450
Aug 28 12:30:22 mpd: [pt0] LCP: rec'd Configure Request #1 link 0 (Req-Sent)
Aug 28 12:30:22 mpd: ENDPOINTDISC [802.1] 00 20 78 db 1d cc
Aug 28 12:30:22 mpd: MP SHORTSEQ
Aug 28 12:30:22 mpd: MP MRRU 1600
Aug 28 12:30:22 mpd: AUTHPROTO CHAP MSOFTv2
Aug 28 12:30:22 mpd: MAGICNUM 7b896db8
Aug 28 12:30:22 mpd: MRU 1500
Aug 28 12:30:22 mpd: PROTOCOMP
Aug 28 12:30:22 mpd: ACFCOMP
Aug 28 12:30:22 mpd: [pt0] LCP: SendConfigReq #38
Aug 28 12:30:20 mpd: ENDPOINTDISC [802.1] 00 20 78 db 1d cc
Aug 28 12:30:20 mpd: MP SHORTSEQ
Aug 28 12:30:20 mpd: MP MRRU 1600
Aug 28 12:30:20 mpd: AUTHPROTO CHAP MSOFTv2
Aug 28 12:30:20 mpd: MAGICNUM 7b896db8
Aug 28 12:30:20 mpd: MRU 1500
Aug 28 12:30:20 mpd: PROTOCOMP
Aug 28 12:30:20 mpd: ACFCOMP
Aug 28 12:30:20 mpd: [pt0] LCP: SendConfigReq #37
Aug 28 12:30:20 mpd: [pt0] LCP: phase shift DEAD --> ESTABLISH
Aug 28 12:30:20 mpd: [pt0] LCP: state change Starting --> Req-Sent
Aug 28 12:30:20 mpd: [pt0] LCP: Up event
Aug 28 12:30:20 mpd: [pt0] link: origination is remote
Aug 28 12:30:20 mpd: [pt0] link: UP event
Aug 28 12:30:20 mpd: [pt0] device is now in state UP
Aug 28 12:30:20 mpd: [pt0] device: UP event in state OPENING
Aug 28 12:30:20 mpd: [pt0] device is now in state OPENING
Aug 28 12:30:20 mpd: [pt0] attaching to peer's outgoing call
Aug 28 12:30:20 mpd: [pt0] device: OPEN event in state DOWN
Aug 28 12:30:20 mpd: [pt0] LCP: LayerStart
Aug 28 12:30:20 mpd: [pt0] LCP: state change Initial --> Starting
Aug 28 12:30:20 mpd: [pt0] LCP: Open event
Aug 28 12:30:20 mpd: [pt0] link: OPEN event
Aug 28 12:30:20 mpd: [pt0] opening link "pt0"...
Aug 28 12:30:20 mpd: [pt0] bundle: OPEN event in state CLOSED
Aug 28 12:30:20 mpd: [pt0] IPCP: Open event
Aug 28 12:30:20 mpd: [pt0] IPCP: LayerStart
Aug 28 12:30:20 mpd: [pt0] IPCP: state change Initial --> Starting
Aug 28 12:30:20 mpd: [pt0] IPCP: Open event
Aug 28 12:30:20 mpd: [pt0] IFACE: Open event
Aug 28 12:30:19 mpd: pptp0: attached to connection with 70.220.64.144:2053
Aug 28 12:30:19 mpd: mpd: PPTP connection from 70.220.64.144:2053
Aug 28 12:30:09 mpd: pptp0: killing connection with 70.220.64.144:2052
Aug 28 12:30:09 mpd: [pt0] LCP: Down event
Aug 28 12:30:09 mpd: [pt0] link: DOWN event
Aug 28 12:30:09 mpd: [pt0] LCP: phase shift ESTABLISH --> DEAD
Aug 28 12:30:09 mpd: [pt0] LCP: state change Closed --> Initial
Aug 28 12:30:09 mpd: [pt0] LCP: Down event
Aug 28 12:30:09 mpd: [pt0] link: DOWN event
Aug 28 12:30:09 mpd: [pt0] device is now in state DOWN
Aug 28 12:30:09 mpd: [pt0] device: DOWN event in state DOWN
Aug 28 12:30:09 mpd: [pt0] LCP: state change Stopped --> Closed
Aug 28 12:30:09 mpd: [pt0] LCP: Close event
Aug 28 12:30:09 mpd: [pt0] link: CLOSE event
Aug 28 12:30:09 mpd: [pt0] device is now in state DOWN
Aug 28 12:30:09 mpd: [pt0] device: DOWN event in state CLOSING
Aug 28 12:30:09 mpd: [pt0] closing link "pt0"...
Aug 28 12:30:09 mpd: [pt0] bundle: CLOSE event in state OPENED
Aug 28 12:30:09 mpd: [pt0] device is now in state CLOSING
Aug 28 12:30:09 mpd: [pt0] IFACE: Close event
Aug 28 12:30:09 mpd: pptp0: closing connection with 70.220.64.144:2052
Aug 28 12:30:09 mpd: [pt0] IFACE: Close event
Aug 28 12:30:09 mpd: [pt0] IPCP: LayerFinish
Aug 28 12:30:09 mpd: [pt0] IPCP: state change Starting --> Initial
Aug 28 12:30:09 mpd: [pt0] IPCP: Close event
Aug 28 12:30:09 mpd: [pt0] IFACE: Close event
Aug 28 12:30:09 mpd: [pt0] PPTP call terminated
Aug 28 12:30:09 mpd: pptp0-0: killing channel
Aug 28 12:30:09 mpd: pptp0-0: clearing call
Aug 28 12:30:09 mpd: [pt0] device: CLOSE event in state UP
Aug 28 12:30:09 mpd: [pt0] LCP: LayerFinish
Aug 28 12:30:09 mpd: [pt0] LCP: phase shift TERMINATE --> ESTABLISH
Aug 28 12:30:09 mpd: [pt0] LCP: state change Stopping --> Stopped
Aug 28 12:30:09 mpd: [pt0] LCP: rec'd Configure Request #6 link 0 (Stopping)
Aug 28 12:30:08 mpd: [pt0] LCP: LayerDown
Aug 28 12:30:08 mpd: [pt0] LCP: SendTerminateAck #36
Aug 28 12:30:08 mpd: [pt0] CCP: LayerFinish
Aug 28 12:30:08 mpd: [pt0] CCP: state change Starting --> Initial
Aug 28 12:30:08 mpd: [pt0] CCP: Close event
Aug 28 12:30:08 mpd: [pt0] CCP: LayerDown
Aug 28 12:30:08 mpd: [pt0] CCP: state change Opened --> Starting
Aug 28 12:30:08 mpd: [pt0] CCP: Down event
Aug 28 12:30:07 mpd: [pt0] exec: /sbin/ifconfig ng1 down delete -link0
Aug 28 12:30:07 mpd: [pt0] exec: /usr/sbin/arp -d 192.168.1.176
Aug 28 12:30:07 mpd: [pt0] exec: /sbin/route delete 192.168.1.2 -iface lo0
Aug 28 12:30:07 mpd: [pt0] exec: /usr/local/sbin/vpn-linkdown ng1 inet g3home-vpn
Aug 28 12:30:07 mpd: [pt0] IFACE: Down event
Aug 28 12:30:07 mpd: [pt0] IPCP: LayerDown
Aug 28 12:30:07 mpd: [pt0] IPCP: state change Opened --> Starting
Aug 28 12:30:07 mpd: [pt0] IPCP: Down event
Aug 28 12:30:07 mpd: [pt0] RADIUS: Down Event
Aug 28 12:30:07 mpd: [pt0] up: 0 links, total bandwidth 9600 bps
Aug 28 12:30:07 mpd: [pt0] setting interface ng1 MTU to 1500 bytes
Aug 28 12:30:07 mpd: [pt0] RADIUS: RadiusSendRequest: RAD_ACCOUNTING_RESPONSE for user g3home-vpn
Aug 28 12:30:07 mpd: [pt0] RADIUS: RadiusAccount: Sending accounting data (Type: 2)
Aug 28 12:30:07 mpd: [pt0] RADIUS: Termination cause: Peer disconnect:The remote server initiated a disconnection for unknown reasons., RADIUS: 1
Aug 28 12:30:07 mpd: [pt0] RADIUS: RadiusAddServer Adding 192.168.1.10
Aug 28 12:30:07 mpd: [pt0] RADIUS: RadiusAccount for: g3home-vpn
Aug 28 12:30:07 mpd: [pt0] LCP: phase shift NETWORK --> TERMINATE
Aug 28 12:30:07 mpd: [pt0] LCP: state change Opened --> Stopping
Aug 28 12:30:07 mpd: [pt0] LCP: rec'd Terminate Request #5 link 0 (Opened)
Topic: PPTP VPN unstable with DD-WRT client