PPP 使用 Socat 与串行到 WiFi 连接的 LCP 协商失败

PPP 使用 Socat 与串行到 WiFi 连接的 LCP 协商失败

我正在尝试通过串口到 WiFi 适配器建立连接。我正在使用 Socat 创建一个套接字来桥接 pppd 到 PTY 的连接。数据似乎是双向流动的,但 pppd 似乎没有得到客户端的响应。 Socat 的调试输出显示传入/传出数据,客户端调试输出显示它正在确认来自服务器的 LCP 协商数据包,但服务器调试仅显示 SENT 数据包而没有回复。我已经用头撞墙两周了,试图弄清楚到底发生了什么。

客户端是一个运行 dosppp 的老式 DOS 掌上电脑,使用 USB 电缆可以完美运行。我怀疑它与 Socat 有关,但我不知道如何调试接收到的数据是否传递给 pppd。

我缺少什么?我怎样才能让它发挥作用?

我使用的 Socat 命令是:

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

索卡特输出:

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)

系统日志

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.

客户端调试输出:

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

更新:我之前已经尝试过wireshark,除了深入数据包查看数据之外,内容与带有-v选项的Socat的输出相同。也曾尝试过

socat PTY,link=/tmp/ptya,rawer,nonblock=1,b19200,waitslave tcp-l:2323,fork,reuseaddr

od -ah `readlink /tmp/ptya`

LCP 数据包正确(根据 PPP Design-Implementation-Debugging_James-Carlson)。问题仍然出现,就像 pppd 没有获取客户端数据包,但 socat 正在接收它们。我这样做时没有在服务器上启动 ppp。

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

尝试使用 kdebug 选项,但 syslog 再次没有显示 ppp 接收到的任何数据包。

更新2: 这个问题肯定与 socat 有关。我可以直接使用串行电缆连接并很快获得 ppp 连接,但是,如果我将 PTY 连接到串行端口,然后尝试使用 PTY 连接到 ppp,则会失败确切地一样的方法。 PPP 服务器仅显示“已发送”消息,未收到任何消息。 Socat 正在阻止 PPP 服务器从客户端获取回复不知何故,或者 ppp 正在寻求从其他地方接收。这也有助于解释为什么 kdebug 不显示为 ppp 接收的数据包,但不能解释为什么通过 socat 连接的其他应用程序显示正在接收的数据。以下是我尝试过但失败的命令:

socat -d -d -v file:/dev/ttyUSB0,nonblock,rawer PTY,rawer,link=/tmp/ptya
pppd `readlink /tmp/ptya`

答案1

不是实际问题的答案,但也许有帮助:

如果您只想pppd使用 PTY,为什么不在pppd命令中直接指定它呢?例如,当我玩弄时,以下内容对我有用pppd

socat PTY,link=/tmp/ptya PTY,link=/tmp/ptyb
sudo pppd `readlink /tmp/ptya` noauth nocrtscts xonxoff local maxfail 0 10.0.3.1:10.0.3.2 persist
sudo pppd `readlink /tmp/ptyb` noauth nocrtscts xonxoff local maxfail 0 10.0.3.2:10.0.3.1 persist

如果不查看细节,我会怀疑这pppd notty与它无法正常工作有关。

需要 PTY 将 Socat 套接字链接到 ppp 终端设备

是的。也是如此,例如

socat -d -d -v tcp-l:2323,fork,reuseaddr PTY,link=/tmp/ptya
/usr/sbin/pppd `readlink /tmp/ptya` ...

看看是否效果更好。

使用此选项,pppd 将为自己分配一个伪 tty 主/从对,并使用从设备作为其终端设备。

那么,如果socat分配一个PTY,并且pppd还分配一个不同的PTY,如果socat使用第一个PTY,同时pppd使用第二个PTY,它们应该如何相互通信?他们需要使用相同的PTY(嗯,它的不同方面)。


我正在使用 Socat 创建一个套接字来桥接 pppd 到 PTY 的连接。

客户端是一个运行 dosppp 的老式 DOS 掌上电脑,使用 USB 电缆可以完美运行

我之前已经尝试过wireshark,除了深入数据包查看数据之外,内容与带有-v选项的Socat的输出相同

现在你真的必须解释谁连接到端口 2323,这端是什么,以及它与老式 DOS 掌上电脑有何关系,因为我真的不明白那部分。

从你的描述来看,听起来 pppd 正在工作,socat 正在工作,他们的共享 PTY 正在工作,并且某个东西(无论是什么)连接到 2323,并且 socat 正在向该东西发送数据,但没有接收任何数据。

它是否正确? (如果不了解细节,远程调试真的很困难)。

相关内容