Hi there, I know this may be a bit unusual these days, but I'm trying to create a dial-in server on my FreeBSD box with 14.2 and MPD5 (version 5.9).
It's working just fine when I use mgetty and ppp - including NAT etc.
My next goal is to play with multilink-PPP (something I never had a chance to do during modem era), and for that I need MPD5.
Now, I tried dialing into BSD from Windows XP, from Linux and from another FreeBSD (with MPD) to get additional debugging info, but it fails during LCP without any clear error.
Here's my config:
And here's the relevant portion of the log, it's clear that the MPD5 answers the call correctly, goes through CONNECT, sends over supported link params including authentication, and then dies...
The "LCP: SendConfigReq" will repeat a few times, and then I get{
I'm also pasting output from another FreeBSD box running MPD5 as a client, the LCP section looks about the same to my untrained eye:
(It's not exactly THE same session which you can see by timestamps or magic numbers, but I hope it helps)
My understanding is that this is about the maximum log level I can get, but still I can't figure out why is it failing.
I can clearly see that the FreeBSD box as a client is showing reception of configreqs and sends acks but fails in the end...
In the meantime, I was able to install wireshark and wincap on the windows box to capture PPP connection.
Comparing mgetty+ppp (good) session with mpd5 (not working) I see that the former has a couple confreq/confack and even a confrej before it succeeds. The mpd5 only has confreq/confack and then it dies.
On the mgetty+ppp session I can see that after the confack/confreq there's Identification where systems exchange version/name of PPP daemon and then it moves onto CHAP.
The MPD5 never reaches the Identification session, so that would indicate it can't agree on the configuration for some reason.
I made sure the ACCMAP is now 0x00000000 (this is what mgetty+ppp does, while mpd5 had 0x000a0000 - the difference was in XON/XOFF but that didn't really help...
I'm attaching wireshark side by side, left is the session from windows to mgetty+ppp and the right is the session to mpd5.
Basically the same request and ack messages repeat themselves for mpd5, as if the sides were ignoring each other and never moving forward.
On the left after a couple requests and asks there's one reject (I don't think it's significant, server basically rejects CBCP), then it moves along to Identification and CHAP.
Any ideas or tips ?
Thanks
It's working just fine when I use mgetty and ppp - including NAT etc.
My next goal is to play with multilink-PPP (something I never had a chance to do during modem era), and for that I need MPD5.
Now, I tried dialing into BSD from Windows XP, from Linux and from another FreeBSD (with MPD) to get additional debugging info, but it fails during LCP without any clear error.
Here's my config:
Code:
default:
log +all
set log +all
load dialin
dialin:
create bundle static B2
set bundle enable compression
set bundle fsm-timeout 2
set iface idle 900
set ipcp ranges 1.1.1.2/32 2.2.2.1/32
create link static L2 modem
set link action bundle B2
set link no pap chap eap
set link enable chap-msv2
set auth authname ppp
log +all
set modem device /dev/cuau4
set modem var $DialPrefix "DT"
set modem idle-script AnswerCall
set link enable incomingAnd here's the relevant portion of the log, it's clear that the MPD5 answers the call correctly, goes through CONNECT, sends over supported link params including authentication, and then dies...
Code:
Aug 18 10:15:44 bsm mpd[34495]: [L2] CHAT: line 1267: log "Incoming call detected..."
Aug 18 10:15:44 bsm mpd[34495]: [L2] CHAT: Incoming call detected...
Aug 18 10:15:44 bsm mpd[34495]: [L2] CHAT: line 1268: print "ATA^M "
Aug 18 10:15:44 bsm mpd[34495]: [L2] CHAT: sending
Aug 18 10:15:44 bsm mpd[34495]: [L2] CHAT: 41 54 41 0d 0a ATA..
Aug 18 10:15:44 bsm mpd[34495]: [L2] CHAT: line 1269: regex "CONNECT *([0-9]*).*$" ModemAnswerConnect
Aug 18 10:15:44 bsm mpd[34495]: [L2] CHAT: line 1270: wait $ConnectTimeout
Aug 18 10:15:44 bsm mpd[34495]: EVENT: Registering event EVENT_TIMEOUT ChatTimeout() at chat.c:971
Aug 18 10:15:44 bsm mpd[34495]: EVENT: Registering event EVENT_TIMEOUT ChatTimeout() done at chat.c:971
Aug 18 10:15:44 bsm mpd[34495]: EVENT: Registering event EVENT_READ ChatRead() at chat.c:584
Aug 18 10:15:44 bsm mpd[34495]: EVENT: Registering event EVENT_READ ChatRead() done at chat.c:584
Aug 18 10:15:44 bsm mpd[34495]: EVENT: Processing event EVENT_READ ChatRead() done
Aug 18 10:15:44 bsm mpd[34495]: EVENT: Processing event EVENT_READ ChatRead()
Aug 18 10:15:44 bsm mpd[34495]: EVENT: Registering event EVENT_READ ChatRead() at chat.c:480
Aug 18 10:15:44 bsm mpd[34495]: EVENT: Registering event EVENT_READ ChatRead() done at chat.c:480
Aug 18 10:15:44 bsm mpd[34495]: EVENT: Processing event EVENT_READ ChatRead() done
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Processing event EVENT_READ ChatRead()
Aug 18 10:15:56 bsm mpd[34495]: [L2] CHAT: read
Aug 18 10:15:56 bsm mpd[34495]: [L2] CHAT: 0a 0d ..
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Registering event EVENT_READ ChatRead() at chat.c:480
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Registering event EVENT_READ ChatRead() done at chat.c:480
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Processing event EVENT_READ ChatRead() done
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Processing event EVENT_READ ChatRead()
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Registering event EVENT_READ ChatRead() at chat.c:480
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Registering event EVENT_READ ChatRead() done at chat.c:480
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Processing event EVENT_READ ChatRead() done
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Processing event EVENT_READ ChatRead()
Aug 18 10:15:56 bsm mpd[34495]: [L2] CHAT: read
Aug 18 10:15:56 bsm mpd[34495]: [L2] CHAT: 0a 43 4f 4e 4e 45 43 54 20 33 33 36 30 30 20 56 .CONNECT 33600 V
Aug 18 10:15:56 bsm mpd[34495]: [L2] CHAT: 34 32 62 69 73 0d 42bis.
Aug 18 10:15:56 bsm mpd[34495]: [L2] CHAT: read
Aug 18 10:15:56 bsm mpd[34495]: [L2] CHAT: 0a .
Aug 18 10:15:56 bsm mpd[34495]: [L2] CHAT: matched set "", goto label "ModemAnswerConnect"
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Unregistering event EVENT_TIMEOUT ChatTimeout() at chat.c:1401
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Unregistering event EVENT_TIMEOUT ChatTimeout() done at chat.c:1401
Aug 18 10:15:56 bsm mpd[34495]: [L2] CHAT: line 1283: set $ConnectionSpeed $matchedString1
Aug 18 10:15:56 bsm mpd[34495]: [L2] CHAT: line 1284: set $answerReturn OK
Aug 18 10:15:56 bsm mpd[34495]: [L2] CHAT: line 1285: return
Aug 18 10:15:56 bsm mpd[34495]: [L2] CHAT: line 195: if $answerReturn == OK goto AnswerCallOK
Aug 18 10:15:56 bsm mpd[34495]: [L2] CHAT: line 195: goto AnswerCallOK
Aug 18 10:15:56 bsm mpd[34495]: [L2] CHAT: line 201: log "Connected at $ConnectionSpeed."
Aug 18 10:15:56 bsm mpd[34495]: [L2] CHAT: Connected at 33600.
Aug 18 10:15:56 bsm mpd[34495]: [L2] CHAT: line 202: set $OptimizeNextTime yes
Aug 18 10:15:56 bsm mpd[34495]: [L2] CHAT: line 203: set $IdleResult answer
Aug 18 10:15:56 bsm mpd[34495]: [L2] CHAT: line 204: success
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Unregistering event EVENT_READ ChatRead() at chat.c:874
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Unregistering event EVENT_READ ChatRead() done at chat.c:874
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Unregistering event (null) at chat.c:875
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Unregistering event (null) done at chat.c:875
Aug 18 10:15:56 bsm mpd[34495]: [L2] MODEM: idle script succeeded, action=answer
Aug 18 10:15:56 bsm mpd[34495]: [L2] MODEM: opening link in answer mode
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Message 1 to LinkMsg() sent
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Processing event EVENT_READ ChatRead() done
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Processing event EVENT_READ MsgEvent()
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Message 1 to LinkMsg() received
Aug 18 10:15:56 bsm mpd[34495]: [L2] Link: OPEN event
Aug 18 10:15:56 bsm mpd[34495]: [L2] LCP: Open event
Aug 18 10:15:56 bsm mpd[34495]: [L2] LCP: state change Initial --> Starting
Aug 18 10:15:56 bsm mpd[34495]: [L2] LCP: LayerStart
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Message 1 to PhysMsg() sent
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Message 1 to LinkMsg() processed
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Message 1 to PhysMsg() received
Aug 18 10:15:56 bsm mpd[34495]: [L2] device: OPEN event in state READY
Aug 18 10:15:56 bsm mpd[34495]: [L2] MODEM: chat script succeeded
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Starting timer "ModemCheck" ModemCheck() for 1000 ms at modem.c:438
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() at timer.c:50
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() done at timer.c:50
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Starting timer "ModemReport" ModemErrorCheck() for 60000 ms at modem.c:442
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() at timer.c:50
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() done at timer.c:50
Aug 18 10:15:56 bsm mpd[34495]: [L2] device: UP event
Aug 18 10:15:56 bsm mpd[34495]: [L2] Link: UP event
Aug 18 10:15:56 bsm mpd[34495]: [L2] Link: origination is remote
Aug 18 10:15:56 bsm mpd[34495]: [L2] LCP: Up event
Aug 18 10:15:56 bsm mpd[34495]: [L2] LCP: state change Starting --> Req-Sent
Aug 18 10:15:56 bsm mpd[34495]: [L2] LCP: phase shift DEAD --> ESTABLISH
Aug 18 10:15:56 bsm mpd[34495]: [L2] LCP: SendConfigReq #11
Aug 18 10:15:56 bsm mpd[34495]: [L2] ACFCOMP
Aug 18 10:15:56 bsm mpd[34495]: [L2] PROTOCOMP
Aug 18 10:15:56 bsm mpd[34495]: [L2] ACCMAP 0x000a0000
Aug 18 10:15:56 bsm mpd[34495]: [L2] MRU 1500
Aug 18 10:15:56 bsm mpd[34495]: [L2] MAGICNUM 0xdf01dd74
Aug 18 10:15:56 bsm mpd[34495]: [L2] AUTHPROTO CHAP MSOFTv2
Aug 18 10:15:56 bsm mpd[34495]: [L2] xmit frame to link proto=0xc021
Aug 18 10:15:56 bsm mpd[34495]: ff 03 c0 21 01 0b 00 1d 08 02 07 02 02 06 00 0a ...!............
Aug 18 10:15:56 bsm mpd[34495]: 00 00 01 04 05 dc 05 06 df 01 dd 74 03 05 c2 23 ...........t...#
Aug 18 10:15:56 bsm mpd[34495]: 81 .
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Starting timer "LCP" FsmTimeout() for 2000 ms at fsm.c:426
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() at timer.c:50
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() done at timer.c:50
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Message 1 to PhysMsg() processed
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Processing event EVENT_READ MsgEvent() done
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Processing event EVENT_READ MsgEvent()
Aug 18 10:15:56 bsm mpd[34495]: EVENT: Processing event EVENT_READ MsgEvent() done
Aug 18 10:15:57 bsm mpd[34495]: EVENT: Processing event EVENT_TIMEOUT TimerExpires()
Aug 18 10:15:57 bsm mpd[34495]: EVENT: Processing timer "ModemCheck" ModemCheck()
Aug 18 10:15:57 bsm mpd[34495]: EVENT: Starting timer "ModemCheck" ModemCheck() for 1000 ms at modem.c:731
Aug 18 10:15:57 bsm mpd[34495]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() at timer.c:50
Aug 18 10:15:57 bsm mpd[34495]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() done at timer.c:50
Aug 18 10:15:57 bsm mpd[34495]: EVENT: Processing timer "ModemCheck" ModemCheck() done
Aug 18 10:15:57 bsm mpd[34495]: EVENT: Processing event EVENT_TIMEOUT TimerExpires() done
Aug 18 10:15:58 bsm mpd[34495]: EVENT: Processing event EVENT_TIMEOUT TimerExpires()
Aug 18 10:15:58 bsm mpd[34495]: EVENT: Processing timer "LCP" FsmTimeout()
Aug 18 10:15:58 bsm mpd[34495]: [L2] LCP: SendConfigReq #12
Aug 18 10:15:58 bsm mpd[34495]: [L2] ACFCOMP
Aug 18 10:15:58 bsm mpd[34495]: [L2] PROTOCOMP
Aug 18 10:15:58 bsm mpd[34495]: [L2] ACCMAP 0x000a0000
Aug 18 10:15:58 bsm mpd[34495]: [L2] MRU 1500
Aug 18 10:15:58 bsm mpd[34495]: [L2] MAGICNUM 0xdf01dd74
Aug 18 10:15:58 bsm mpd[34495]: [L2] AUTHPROTO CHAP MSOFTv2
Aug 18 10:15:58 bsm mpd[34495]: [L2] xmit frame to link proto=0xc021
Aug 18 10:15:58 bsm mpd[34495]: ff 03 c0 21 01 0c 00 1d 08 02 07 02 02 06 00 0a ...!............
Aug 18 10:15:58 bsm mpd[34495]: 00 00 01 04 05 dc 05 06 df 01 dd 74 03 05 c2 23 ...........t...#
Aug 18 10:15:58 bsm mpd[34495]: 81 .The "LCP: SendConfigReq" will repeat a few times, and then I get{
Code:
Aug 18 10:16:14 bsm mpd[34495]: EVENT: Starting timer "LCP" FsmTimeout() for 2000 ms at fsm.c:426
Aug 18 10:16:14 bsm mpd[34495]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() at timer.c:50
Aug 18 10:16:14 bsm mpd[34495]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() done at timer.c:50
Aug 18 10:16:14 bsm mpd[34495]: EVENT: Processing timer "LCP" FsmTimeout() done
Aug 18 10:16:14 bsm mpd[34495]: EVENT: Processing event EVENT_TIMEOUT TimerExpires() done
Aug 18 10:16:14 bsm mpd[34495]: EVENT: Processing event EVENT_TIMEOUT TimerExpires()
Aug 18 10:16:14 bsm mpd[34495]: EVENT: Processing timer "ModemCheck" ModemCheck()
Aug 18 10:16:14 bsm mpd[34495]: EVENT: Starting timer "ModemCheck" ModemCheck() for 1000 ms at modem.c:731
Aug 18 10:16:14 bsm mpd[34495]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() at timer.c:50
Aug 18 10:16:14 bsm mpd[34495]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() done at timer.c:50
Aug 18 10:16:14 bsm mpd[34495]: EVENT: Processing timer "ModemCheck" ModemCheck() done
Aug 18 10:16:14 bsm mpd[34495]: EVENT: Processing event EVENT_TIMEOUT TimerExpires() done
Aug 18 10:16:15 bsm mpd[34495]: EVENT: Processing event EVENT_TIMEOUT TimerExpires()
Aug 18 10:16:15 bsm mpd[34495]: EVENT: Processing timer "ModemCheck" ModemCheck()
Aug 18 10:16:15 bsm mpd[34495]: EVENT: Starting timer "ModemCheck" ModemCheck() for 1000 ms at modem.c:731
Aug 18 10:16:15 bsm mpd[34495]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() at timer.c:50
Aug 18 10:16:15 bsm mpd[34495]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() done at timer.c:50
Aug 18 10:16:15 bsm mpd[34495]: EVENT: Processing timer "ModemCheck" ModemCheck() done
Aug 18 10:16:15 bsm mpd[34495]: EVENT: Processing event EVENT_TIMEOUT TimerExpires() done
Aug 18 10:16:16 bsm mpd[34495]: EVENT: Processing event EVENT_TIMEOUT TimerExpires()
Aug 18 10:16:16 bsm mpd[34495]: EVENT: Processing timer "LCP" FsmTimeout()
Aug 18 10:16:16 bsm mpd[34495]: [L2] LCP: parameter negotiation failed
Aug 18 10:16:16 bsm mpd[34495]: [L2] LCP: state change Req-Sent --> Stopped
Aug 18 10:16:16 bsm mpd[34495]: [L2] LCP: LayerFinish
Aug 18 10:16:16 bsm mpd[34495]: EVENT: Message 2 to PhysMsg() sent
Aug 18 10:16:16 bsm mpd[34495]: EVENT: Processing timer "LCP" FsmTimeout() done
Aug 18 10:16:16 bsm mpd[34495]: EVENT: Processing event EVENT_TIMEOUT TimerExpires() done
Aug 18 10:16:16 bsm mpd[34495]: EVENT: Processing event EVENT_READ MsgEvent()
Aug 18 10:16:16 bsm mpd[34495]: EVENT: Message 2 to PhysMsg() received
Aug 18 10:16:16 bsm mpd[34495]: [L2] device: CLOSE event in state UP
Aug 18 10:16:16 bsm mpd[34495]: EVENT: Unregistering event EVENT_READ ChatRead() at chat.c:874
Aug 18 10:16:16 bsm mpd[34495]: EVENT: Unregistering event EVENT_READ ChatRead() done at chat.c:874
Aug 18 10:16:16 bsm mpd[34495]: EVENT: Unregistering event (null) at chat.c:875
Aug 18 10:16:16 bsm mpd[34495]: EVENT: Unregistering event (null) done at chat.c:875
Aug 18 10:16:16 bsm mpd[34495]: EVENT: Stopping timer "ModemCheck" ModemCheck() at modem.c:351
Aug 18 10:16:16 bsm mpd[34495]: EVENT: Unregistering event EVENT_TIMEOUT TimerExpires() at timer.c:83
Aug 18 10:16:16 bsm mpd[34495]: EVENT: Unregistering event EVENT_TIMEOUT TimerExpires() done at timer.c:83
Aug 18 10:16:16 bsm mpd[34495]: EVENT: Stopping timer "ModemReport" ModemErrorCheck() at modem.c:353
Aug 18 10:16:16 bsm mpd[34495]: EVENT: Unregistering event EVENT_TIMEOUT TimerExpires() at timer.c:83
Aug 18 10:16:16 bsm mpd[34495]: EVENT: Unregistering event EVENT_TIMEOUT TimerExpires() done at timer.c:83
Aug 18 10:16:16 bsm mpd[34495]: EVENT: Starting timer "ModemStart" ModemStart() for 3000 ms at modem.c:256
Aug 18 10:16:16 bsm mpd[34495]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() at timer.c:50
Aug 18 10:16:16 bsm mpd[34495]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() done at timer.c:50
Aug 18 10:16:16 bsm mpd[34495]: [L2] device: DOWN event
Aug 18 10:16:16 bsm mpd[34495]: [L2] Link: DOWN event
Aug 18 10:16:16 bsm mpd[34495]: [L2] LCP: Close event
Aug 18 10:16:16 bsm mpd[34495]: [L2] LCP: state change Stopped --> Closed
Aug 18 10:16:16 bsm mpd[34495]: [L2] LCP: Down event
Aug 18 10:16:16 bsm mpd[34495]: [L2] LCP: state change Closed --> Initial
Aug 18 10:16:16 bsm mpd[34495]: [L2] LCP: phase shift ESTABLISH --> DEADI'm also pasting output from another FreeBSD box running MPD5 as a client, the LCP section looks about the same to my untrained eye:
(It's not exactly THE same session which you can see by timestamps or magic numbers, but I hope it helps)
Code:
Aug 18 09:08:19 whp mpd[11208]: [L1] LCP: SendConfigReq #10
Aug 18 09:08:19 whp mpd[11208]: [L1] ACFCOMP
Aug 18 09:08:19 whp mpd[11208]: [L1] PROTOCOMP
Aug 18 09:08:19 whp mpd[11208]: [L1] ACCMAP 0x000a0000
Aug 18 09:08:19 whp mpd[11208]: [L1] MRU 1500
Aug 18 09:08:19 whp mpd[11208]: [L1] MAGICNUM 0x51aff510
Aug 18 09:08:19 whp mpd[11208]: [L1] xmit frame to link proto=0xc021
Aug 18 09:08:19 whp mpd[11208]: ff 03 c0 21 01 0a 00 18 08 02 07 02 02 06 00 0a ...!............
Aug 18 09:08:19 whp mpd[11208]: 00 00 01 04 05 dc 05 06 51 af f5 10 ........Q...
Aug 18 09:08:19 whp mpd[11208]: EVENT: Starting timer "LCP" FsmTimeout() for 2000 ms at fsm.c:426
Aug 18 09:08:19 whp mpd[11208]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() at timer.c:50
Aug 18 09:08:19 whp mpd[11208]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() done at timer.c:50
Aug 18 09:08:19 whp mpd[11208]: EVENT: Processing timer "LCP" FsmTimeout() done
Aug 18 09:08:19 whp mpd[11208]: EVENT: Processing event EVENT_TIMEOUT TimerExpires() done
Aug 18 09:08:19 whp mpd[11208]: EVENT: Processing event EVENT_READ LinkNgDataEvent()
Aug 18 09:08:19 whp mpd[11208]: [L1] rec'd 31 bytes frame from link proto=0xc021
Aug 18 09:08:19 whp mpd[11208]: c0 21 01 50 00 1d 08 02 07 02 02 06 00 0a 00 00 .!.P............
Aug 18 09:08:19 whp mpd[11208]: 01 04 05 dc 05 06 5f f5 cb 50 03 05 c2 23 81 ......_..P...#.
Aug 18 09:08:19 whp mpd[11208]: [L1] LCP: rec'd Configure Request #80 (Ack-Sent)
Aug 18 09:08:19 whp mpd[11208]: [L1] ACFCOMP
Aug 18 09:08:19 whp mpd[11208]: [L1] PROTOCOMP
Aug 18 09:08:19 whp mpd[11208]: [L1] ACCMAP 0x000a0000
Aug 18 09:08:19 whp mpd[11208]: [L1] MRU 1500
Aug 18 09:08:19 whp mpd[11208]: [L1] MAGICNUM 0x5ff5cb50
Aug 18 09:08:19 whp mpd[11208]: [L1] AUTHPROTO CHAP MSOFTv2
Aug 18 09:08:19 whp mpd[11208]: [L1] LCP: SendConfigAck #80
Aug 18 09:08:19 whp mpd[11208]: [L1] ACFCOMP
Aug 18 09:08:19 whp mpd[11208]: [L1] PROTOCOMP
Aug 18 09:08:19 whp mpd[11208]: [L1] ACCMAP 0x000a0000
Aug 18 09:08:19 whp mpd[11208]: [L1] MRU 1500
Aug 18 09:08:19 whp mpd[11208]: [L1] MAGICNUM 0x5ff5cb50
Aug 18 09:08:19 whp mpd[11208]: [L1] AUTHPROTO CHAP MSOFTv2
Aug 18 09:08:19 whp mpd[11208]: [L1] xmit frame to link proto=0xc021
Aug 18 09:08:19 whp mpd[11208]: ff 03 c0 21 02 50 00 1d 08 02 07 02 02 06 00 0a ...!.P..........
Aug 18 09:08:19 whp mpd[11208]: 00 00 01 04 05 dc 05 06 5f f5 cb 50 03 05 c2 23 ........_..P...#
Aug 18 09:08:19 whp mpd[11208]: 81 .
Aug 18 09:08:19 whp mpd[11208]: EVENT: Processing event EVENT_READ LinkNgDataEvent() done
Aug 18 09:08:20 whp mpd[11208]: EVENT: Processing event EVENT_TIMEOUT TimerExpires()
Aug 18 09:08:20 whp mpd[11208]: EVENT: Processing timer "ModemCheck" ModemCheck()
Aug 18 09:08:20 whp mpd[11208]: EVENT: Starting timer "ModemCheck" ModemCheck() for 1000 ms at modem.c:731
Aug 18 09:08:20 whp mpd[11208]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() at timer.c:50
Aug 18 09:08:20 whp mpd[11208]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() done at timer.c:50
Aug 18 09:08:20 whp mpd[11208]: EVENT: Processing timer "ModemCheck" ModemCheck() done
Aug 18 09:08:20 whp mpd[11208]: EVENT: Processing event EVENT_TIMEOUT TimerExpires() done
Aug 18 09:08:21 whp mpd[11208]: EVENT: Processing event EVENT_TIMEOUT TimerExpires()
Aug 18 09:08:21 whp mpd[11208]: EVENT: Processing timer "ModemCheck" ModemCheck()
Aug 18 09:08:21 whp mpd[11208]: EVENT: Starting timer "ModemCheck" ModemCheck() for 1000 ms at modem.c:731
Aug 18 09:08:21 whp mpd[11208]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() at timer.c:50
Aug 18 09:08:21 whp mpd[11208]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() done at timer.c:50
Aug 18 09:08:21 whp mpd[11208]: EVENT: Processing timer "ModemCheck" ModemCheck() done
Aug 18 09:08:21 whp mpd[11208]: EVENT: Processing event EVENT_TIMEOUT TimerExpires() done
Aug 18 09:08:22 whp mpd[11208]: EVENT: Processing event EVENT_TIMEOUT TimerExpires()
Aug 18 09:08:22 whp mpd[11208]: EVENT: Processing timer "LCP" FsmTimeout()
Aug 18 09:08:22 whp mpd[11208]: [L1] LCP: parameter negotiation failed
Aug 18 09:08:22 whp mpd[11208]: [L1] LCP: state change Ack-Sent --> Stopped
Aug 18 09:08:22 whp mpd[11208]: [L1] LCP: LayerFinishMy understanding is that this is about the maximum log level I can get, but still I can't figure out why is it failing.
I can clearly see that the FreeBSD box as a client is showing reception of configreqs and sends acks but fails in the end...
In the meantime, I was able to install wireshark and wincap on the windows box to capture PPP connection.
Comparing mgetty+ppp (good) session with mpd5 (not working) I see that the former has a couple confreq/confack and even a confrej before it succeeds. The mpd5 only has confreq/confack and then it dies.
On the mgetty+ppp session I can see that after the confack/confreq there's Identification where systems exchange version/name of PPP daemon and then it moves onto CHAP.
The MPD5 never reaches the Identification session, so that would indicate it can't agree on the configuration for some reason.
I made sure the ACCMAP is now 0x00000000 (this is what mgetty+ppp does, while mpd5 had 0x000a0000 - the difference was in XON/XOFF but that didn't really help...
I'm attaching wireshark side by side, left is the session from windows to mgetty+ppp and the right is the session to mpd5.
Basically the same request and ack messages repeat themselves for mpd5, as if the sides were ignoring each other and never moving forward.
On the left after a couple requests and asks there's one reject (I don't think it's significant, server basically rejects CBCP), then it moves along to Identification and CHAP.
Any ideas or tips ?
Thanks
