I'm trying to setup a connection over a serial to wifi adapter. I'm using Socat to create a socket to bridge the connection to a PTY for pppd. Data appears to be be flowing both directions, but pppd doesn't seem to be getting the response from the client. The debug output from Socat show incoming/outgoing data, and the client debug output shows it's ACK'ing LCP negotiation packets from the server, but server debug only shows SENT packets and no reply. I've been banging my head against the wall for 2 weeks now trying to figure out what's going on.
The client is a vintage DOS palmtop running dosppp and it works perfectly using a USB cable. My suspicion is that it's related to Socat, but I don't know how to debug if the received data is being passed to pppd.
What am I missing? How can I get this to work?
The Socat command I'm using is:
socat -d -d -v tcp-l:2323,fork,reuseaddr exec:'/usr/sbin/pppd notty',pty,rawer,nonblock=1,iexten=0,b19200
.ppprc
debug
nodetach
default-asyncmap
local
mtu 296
mru 296
noipv6
noauth
notty
Socat output:
root# socat -d -d -v tcp-l:2323,fork,reuseaddr exec:'/usr/sbin/pppd notty',pty,rawer,nonblock=1,iexten=0,b19200
2021/05/08 00:27:04 socat[1082] N listening on AF=2 0.0.0.0:2323
2021/05/08 00:27:20 socat[1082] N accepting connection from AF=2 10.0.10.46:26185 on AF=2 10.0.10.17:2323
2021/05/08 00:27:20 socat[1082] N forked off child process 1083
2021/05/08 00:27:20 socat[1082] N listening on AF=2 0.0.0.0:2323
2021/05/08 00:27:20 socat[1083] N forking off child, using pty for reading and writing
2021/05/08 00:27:20 socat[1083] N forked off child process 1084
2021/05/08 00:27:20 socat[1083] N forked off child process 1084
2021/05/08 00:27:20 socat[1083] N starting data transfer loop with FDs [6,6] and [5,5]
2021/05/08 00:27:20 socat[1084] N execvp'ing "/usr/sbin/pppd"
< 2021/05/08 00:27:20.122440 length=52 from=0 to=51
~.}#.!}!}!} }8}!}$}!(}"}&} } } } }%}&.sr.}'}"}(}">.~< 2021/05/08 00:27:23.117722 length=52 from=52 to=103
~.}#.!}!}!} }8}!}$}!(}"}&} } } } }%}&.sr.}'}"}(}">.~< 2021/05/08 00:27:26.122209 length=52 from=104 to=155
~.}#.!}!}!} }8}!}$}!(}"}&} } } } }%}&.sr.}'}"}(}">.~> 2021/05/08 00:27:26.128144 length=41 from=0 to=40
~.}#.!}!}!} }2}}$}!(}%}&}:}4@}}'}"}(}"%.~ > 2021/05/08 00:27:26.881958 length=50 from=41 to=90
~.}#.!}"}!} }8}}$}!(}"}&} } } }%}&.sr.}'}"}(".} ~ < 2021/05/08 00:27:29.124308 length=52 from=156 to=207
~.}#.!}!}!} }8}!}$}!(}"}&} } } } }%}&.sr.}'}"}(}">.~> 2021/05/08 00:27:29.504403 length=41 from=91 to=131
~.}#.!}!}!} }2}}$}!(}%}&}:}4@}}'}"}(}"%.~ > 2021/05/08 00:27:30.154487 length=50 from=132 to=181
~.}#.!}"}!} }8}}$}!(}"}&} } } }%}&.sr.}'}"}(".} ~ < 2021/05/08 00:27:32.127473 length=52 from=208 to=259
~.}#.!}!}!} }8}!}$}!(}"}&} } } } }%}&.sr.}'}"}(}">.~> 2021/05/08 00:27:33.004495 length=50 from=182 to=231
~.}#.!}"}!} }8}}$}!(}"}&} } } }%}&.sr.}'}"}(".} ~ > 2021/05/08 00:27:33.329502 length=41 from=232 to=272
~.}#.!}!}!} }2}!}}!(}%}&}:}4@} }}"}(}"%.~ < 2021/05/08 00:27:35.130645 length=52 from=260 to=311
~.}#.!}!}!} }8}!}$}!(}"}&} } } } }%}&.sr.}'}"}(}">.~> 2021/05/08 00:27:36.056441 length=50 from=273 to=322
~.}#.!}"}!} }8}}$}!(}"}&} } } }%}&.sr.}'}"}(".} ~ > 2021/05/08 00:27:36.679459 length=41 from=323 to=363
~.}#.!}!}!} }2}}$}!(}%}&}:}4@}}'}"}(}"%.~ < 2021/05/08 00:27:38.133840 length=52 from=312 to=363
~.}#.!}!}!} }8}!}$}!(}"}&} } } } }%}&.sr.}'}"}(}">.~> 2021/05/08 00:27:39.054527 length=50 from=364 to=413
~.}#.!}"}!} }8}}$}!(}"}&} } } }%}&.sr.}'}"}(".} ~ > 2021/05/08 00:27:39.655287 length=41 from=414 to=454
~.}#.!}!}!} }2}}$}!(}%}&}:}4@}}'}"}(}"%.~ < 2021/05/08 00:27:41.137063 length=52 from=364 to=415
~.}#.!}!}!} }8}!}$}!(}"}&} } } } }%}&.sr.}'}"}(}">.~> 2021/05/08 00:27:42.079453 length=50 from=455 to=504
~.}#.!}"}!} }8}}$}!(}"}&} } } }%}&.sr.}'}"}(".} ~ > 2021/05/08 00:27:43.029525 length=41 from=505 to=545
~.}#.!}!}!} }2}}$}!(}%}&}:}4@}}'}"}(}"%.~ < 2021/05/08 00:27:44.140293 length=52 from=416 to=467
~.}#.!}!}!} }8}!}$}!(}"}&} } } } }%}&.sr.}'}"}(}">.~> 2021/05/08 00:27:45.079471 length=50 from=546 to=595
~.}#.!}"}!} }8}}$}!(}"}&} } } }%}&.sr.}'}"}(".} ~ > 2021/05/08 00:27:46.279660 length=41 from=596 to=636
~.}#.!}!}!} }2}}$}!(}%}&}:}4@}}'}"}(}"%.~ < 2021/05/08 00:27:47.143465 length=52 from=468 to=519
~.}#.!}!}!} }8}!}$}!(}"}&} } } } }%}&.sr.}'}"}(}">.~> 2021/05/08 00:27:48.054620 length=50 from=637 to=686
~.}#.!}"}!} }8}}$}!(}"}&} } } }%}&.sr.}'}"}(".} ~ > 2021/05/08 00:27:49.554776 length=41 from=687 to=727
~.}#.!}!}!} }2}}$}!(}%}&}:}4@}}'}"}(}"%.~ 2021/05/08 00:27:50 socat[1083] N read(5, 0x11f15c8, 8192): Input/output error (probably PTY closed)
2021/05/08 00:27:50 socat[1083] N socket 2 (fd 5) is at EOF
2021/05/08 00:27:50 socat[1083] E waitpid(): child 1084 exited with status 16
2021/05/08 00:27:50 socat[1083] N exit(1)
2021/05/08 00:27:50 socat[1082] N childdied(): handling signal 17
2021/05/08 00:27:50 socat[1082] N childdied(): handling signal 17
2021/05/08 00:28:42 socat[1082] N socat_signal(): handling signal 2
2021/05/08 00:28:42 socat[1082] N exiting on signal 2
2021/05/08 00:28:42 socat[1082] N socat_signal(): finishing signal 2
2021/05/08 00:28:42 socat[1082] N exit(130)
Syslog
May 8 00:27:20 pppd[1084]: pppd 2.4.7 started by pi, uid 0
May 8 00:27:20 pppd[1084]: using channel 2
May 8 00:27:20 pppd[1084]: Using interface ppp0
May 8 00:27:20 pppd[1084]: Connect: ppp0 <--> /dev/pts/2
May 8 00:27:20 pppd[1084]: sent [LCP ConfReq id=0x1 <mru 296> <asyncmap 0x0> <magic 0x957372ed> <pcomp> <accomp>]
May 8 00:27:23 pppd[1084]: sent [LCP ConfReq id=0x1 <mru 296> <asyncmap 0x0> <magic 0x957372ed> <pcomp> <accomp>]
May 8 00:27:26 pppd[1084]: sent [LCP ConfReq id=0x1 <mru 296> <asyncmap 0x0> <magic 0x957372ed> <pcomp> <accomp>]
May 8 00:27:29 pppd[1084]: sent [LCP ConfReq id=0x1 <mru 296> <asyncmap 0x0> <magic 0x957372ed> <pcomp> <accomp>]
May 8 00:27:32 pppd[1084]: sent [LCP ConfReq id=0x1 <mru 296> <asyncmap 0x0> <magic 0x957372ed> <pcomp> <accomp>]
May 8 00:27:35 pppd[1084]: sent [LCP ConfReq id=0x1 <mru 296> <asyncmap 0x0> <magic 0x957372ed> <pcomp> <accomp>]
May 8 00:27:38 pppd[1084]: sent [LCP ConfReq id=0x1 <mru 296> <asyncmap 0x0> <magic 0x957372ed> <pcomp> <accomp>]
May 8 00:27:41 pppd[1084]: sent [LCP ConfReq id=0x1 <mru 296> <asyncmap 0x0> <magic 0x957372ed> <pcomp> <accomp>]
May 8 00:27:44 pppd[1084]: sent [LCP ConfReq id=0x1 <mru 296> <asyncmap 0x0> <magic 0x957372ed> <pcomp> <accomp>]
May 8 00:27:47 pppd[1084]: sent [LCP ConfReq id=0x1 <mru 296> <asyncmap 0x0> <magic 0x957372ed> <pcomp> <accomp>]
May 8 00:27:50 pppd[1084]: LCP: timeout sending Config-Requests
May 8 00:27:50 pppd[1084]: Connection terminated.
May 8 00:27:50 pppd[1084]: Modem hangup
May 8 00:27:50 pppd[1084]: Waiting for 1 child processes...
May 8 00:27:50 pppd[1084]: script pppd (charshunt), pid 1085
May 8 00:27:50 pppd[1084]: Script pppd (charshunt) finished (pid 1085), status = 0x0
May 8 00:27:50 pppd[1084]: Exit.
Client debug output:
sent [LCP ConfReq id=0x1 <mru 296> <magic 0x1aed278> <pcomp> <accomp>]
fsm_sdata(LCP): Sent code 1, id 1.
Timeout 53ce:2a06 in 3 seconds.
LCP: sending Configure-Request, id 1
rcvd [LCP ConfReq id=0x1 <mru 296> <magic 0x99ed93e8> <pcomp> <accomp>]
fsm_rconfreq(LCP): Rcvd id 1.
lcp_reqci: rcvd MRU (296) (ACK)
lcp_reqci: rcvd MAGICNUMBER (99ed93e8) (ACK)
lcp_reqci: rcvd PCOMPRESSION (ACK)
lcp_reqci: rcvd ACCOMPRESSION (ACK)
lcp_reqci: returning CONFACK.
sent [LCP ConfAck id=0x1 <mru 296> <magic 0x99ed93e8> <pcomp> <accomp>]
fsm_sdata(LCP): Sent code 2, id 1.
rcvd [LCP ConfReq id=0x1 <mru 296> <magic 0x99ed93e8> <pcomp> <accomp>]
fsm_rconfreq(LCP): Rcvd id 1.
lcp_reqci: rcvd MRU (296) (ACK)
lcp_reqci: rcvd MAGICNUMBER (99ed93e8) (ACK)
lcp_reqci: rcvd PCOMPRESSION (ACK)
lcp_reqci: rcvd ACCOMPRESSION (ACK)
lcp_reqci: returning CONFACK.
sent [LCP ConfAck id=0x1 <mru 296> <magic 0x99ed93e8> <pcomp> <accomp>]
fsm_sdata(LCP): Sent code 2, id 1.
calltimeout, calling 53ce:2a06.
sent [LCP ConfReq id=0x1 <mru 296> <magic 0x1aed278> <pcomp> <accomp>]
fsm_sdata(LCP): Sent code 1, id 1.
Timeout 53ce:2a06 in 3 seconds.
LCP: sending Configure-Request, id 1
rcvd [LCP ConfReq id=0x1 <mru 296> <magic 0x99ed93e8> <pcomp> <accomp>]
fsm_rconfreq(LCP): Rcvd id 1.
lcp_reqci: rcvd MRU (296) (ACK)
lcp_reqci: rcvd MAGICNUMBER (99ed93e8) (ACK)
lcp_reqci: rcvd PCOMPRESSION (ACK)
lcp_reqci: rcvd ACCOMPRESSION (ACK)
lcp_reqci: returning CONFACK.
sent [LCP ConfAck id=0x1 <mru 296> <magic 0x99ed93e8> <pcomp> <accomp>]
fsm_sdata(LCP): Sent code 2, id 1.
calltimeout, calling 53ce:2a06.
sent [LCP ConfReq id=0x1 <mru 296> <magic 0x1aed278> <pcomp> <accomp>]
fsm_sdata(LCP): Sent code 1, id 1.
Timeout 53ce:2a06 in 3 seconds.
LCP: sending Configure-Request, id 1
rcvd [LCP ConfReq id=0x1 <mru 296> <magic 0x99ed93e8> <pcomp> <accomp>]
fsm_rconfreq(LCP): Rcvd id 1.
lcp_reqci: rcvd MRU (296) (ACK)
lcp_reqci: rcvd MAGICNUMBER (99ed93e8) (ACK)
lcp_reqci: rcvd PCOMPRESSION (ACK)
lcp_reqci: rcvd ACCOMPRESSION (ACK)
lcp_reqci: returning CONFACK.
sent [LCP ConfAck id=0x1 <mru 296> <magic 0x99ed93e8> <pcomp> <accomp>]
fsm_sdata(LCP): Sent code 2, id 1.
calltimeout, calling 53ce:2a06.
sent [LCP ConfReq id=0x1 <mru 296> <magic 0x1aed278> <pcomp> <accomp>]
fsm_sdata(LCP): Sent code 1, id 1.
Timeout 53ce:2a06 in 3 seconds.
LCP: sending Configure-Request, id 1
rcvd [LCP ConfReq id=0x1 <mru 296> <magic 0x99ed93e8> <pcomp> <accomp>]
fsm_rconfreq(LCP): Rcvd id 1.
lcp_reqci: rcvd MRU (296) (ACK)
lcp_reqci: rcvd MAGICNUMBER (99ed93e8) (ACK)
lcp_reqci: rcvd PCOMPRESSION (ACK)
lcp_reqci: rcvd ACCOMPRESSION (ACK)
lcp_reqci: returning CONFACK.
sent [LCP ConfAck id=0x1 <mru 296> <magic 0x99ed93e8> <pcomp> <accomp>]
fsm_sdata(LCP): Sent code 2, id 1.
calltimeout, calling 53ce:2a06.
sent [LCP ConfReq id=0x1 <mru 296> <magic 0x1aed278> <pcomp> <accomp>]
fsm_sdata(LCP): Sent code 1, id 1.
Timeout 53ce:2a06 in 3 seconds.
LCP: sending Configure-Request, id 1
rcvd [LCP ConfReq id=0x1 <mru 296> <magic 0x99ed93e8> <pcomp> <accomp>]
fsm_rconfreq(LCP): Rcvd id 1.
lcp_reqci: rcvd MRU (296) (ACK)
lcp_reqci: rcvd MAGICNUMBER (99ed93e8) (ACK)
lcp_reqci: rcvd PCOMPRESSION (ACK)
lcp_reqci: rcvd ACCOMPRESSION (ACK)
lcp_reqci: returning CONFACK.
sent [LCP ConfAck id=0x1 <mru 296> <magic 0x99ed93e8> <pcomp> <accomp>]
fsm_sdata(LCP): Sent code 2, id 1.
calltimeout, calling 53ce:2a06.
sent [LCP ConfReq id=0x1 <mru 296> <magic 0x1aed278> <pcomp> <accomp>]
fsm_sdata(LCP): Sent code 1, id 1.
Timeout 53ce:2a06 in 3 seconds.
LCP: sending Configure-Request, id 1
calltimeout, calling 53ce:2a06.
sent [LCP ConfReq id=0x1 <mru 296> <magic 0x1aed278> <pcomp> <accomp>]
fsm_sdata(LCP): Sent code 1, id 1.
Timeout 53ce:2a06 in 3 seconds.
LCP: sending Configure-Request, id 1
calltimeout, calling 53ce:2a06.
sent [LCP ConfReq id=0x1 <mru 296> <magic 0x1aed278> <pcomp> <accomp>]
fsm_sdata(LCP): Sent code 1, id 1.
Timeout 53ce:2a06 in 3 seconds.
LCP: sending Configure-Request, id 1
calltimeout, calling 53ce:2a06.
sent [LCP ConfReq id=0x1 <mru 296> <magic 0x1aed278> <pcomp> <accomp>]
fsm_sdata(LCP): Sent code 1, id 1.
Timeout 53ce:2a06 in 3 seconds.
LCP: sending Configure-Request, id 1
calltimeout, calling 53ce:2a06.
sent [LCP ConfReq id=0x1 <mru 296> <magic 0x1aed278> <pcomp> <accomp>]
fsm_sdata(LCP): Sent code 1, id 1.
Timeout 53ce:2a06 in 3 seconds.
LCP: sending Configure-Request, id 1
calltimeout, calling 53ce:2a06.
LCP: timeout sending Config-Requests
Update: I've previously already tried wireshark, other than digging into the packets to see the data, the contents are the same as the output of Socat with the -v option. Also have tried
socat PTY,link=/tmp/ptya,rawer,nonblock=1,b19200,waitslave tcp-l:2323,fork,reuseaddr
od -ah `readlink /tmp/ptya`
The LCP packets are correct (per PPP Design-Implementation-Debugging_James-Carlson). The problem still appears like pppd is not getting the client packets, but they are being received by socat. I did this without starting ppp on the server.
root# od -h --endian=big `readlink /tmp/ptya`
# Every 7D XX sequence should be replaced with XX xor 20 (hex)
0000000 7eff 7d23 c021 7d21 7d21 7d20 7d32 7d7d
0000020 227d 287d 2256 6c7e 7eff 7d23 c021 7d21
0000040 7d21 7d20 7d32 7d7d 247d 2128 7d25 7d26
0000060 7d22 6791 2b7d 7d22 7d28 7d22 566c 7e7e
0000100 ff7d 23c0 217d 217d 217d 207d 327d 7d24
0000120 7d21 287d 257d 267d 2267 912b 7d7d 227d
0000140 287d 2256 6c7e 7eff 7d23 c021 7d21 7d21
0000160 7d20 7d32 7d7d 247d 2128 7d25 7d26 7d22
0000200 6791 2b7d 7d22 7d28 7d22 566c 7e7e ff7d
0000220 23c0 217d 217d 217d 207d 327d 7d24 7d21
0000240 287d 257d 267d 2267 912b 7d7d 227d 287d
0000260 2256 6c7e 7eff 7d23 c021 7d21 7d21 7d20
0000300 7d32 7d7d 247d 2128 7d25 7d26 7d22 6791
0000320 2b7d 7d22 7d28 7d22 566c 7e7e ff7d 23c0
0000340 217d 217d 217d 207d 327d 7d24 7d21 287d
0000360 257d 267d 2267 912b 7d7d 227d 287d 2256
0000400 6c7e 7eff 7d23 c021 7d21 7d21 7d20 7d32
0000420 7d7d 247d 2128 7d25 7d26 7d22 6791 2b7d
0000440 7d22 7d28 7d22 566c 7e7e ff7d 23c0 217d
0000460 217d 217d 207d 327d 7d24 7d21 287d 257d
0000500 267d 2267 912b 7d7d 227d 287d 2256 6c7e
0000520 7eff 7d23 c021 7d21 7d21 7d20 7d32 7d7d
0000540 247d 2128 7d25 7d26 7d22 6791 2b7d 7d22
Trying to use the kdebug option, but again syslog is not showing any packets being received by ppp.
UPDATE 2: The problem definitely appears something to do with socat. I can connect directly with a serial cable and very quickly get a ppp connection, BUT, if I link a PTY to the serial port and then try to connect to ppp using the PTY, it fails exactly the same way. PPP server only shows 'sent' messages, nothing received. Socat is preventing PPP server from getting replies from client somehow, or ppp is looking to receive from somewhere else. This also helps explain why kdebug is not showing packets received for ppp, but does not explain why other apps connected thru socat show data being received. Here are the commands I tried that failed:
socat -d -d -v file:/dev/ttyUSB0,nonblock,rawer PTY,rawer,link=/tmp/ptya
pppd `readlink /tmp/ptya`
rawermight be buggy as in one test I found it had cleared thecreadbit of a serial line, so nothing could be read. You could trystty -a -F /dev/...on each of the pty and serial lines to make sure you do not have-cread. Or simply try replacingrawerbyraw,echo=0which was my workaround at the time.rawerwas because the documentation saidrawwas deprecated. Its definitely appearing like a buffering issue.