Преамбула. Настраивал dial-in доступ в интернет через Linux-сервер по модему. Модем MultiTech5600ZDX стоит на первом серийном порту (/dev/ttyS0). Терминальная программа - mgetty+sendfax, демон соединения - pppd. Модем достаточно нестандартный. Пришлось его немного попинать, прежде чем он заработал.
Проблема. Клиент, звонит, аутентифицируется, получает ip, секунд 10 имеет доступ в интернет. После этого соединение как бы живёт (не обрывается), но больше ни одного пакета не проходит ни в одну сторону. Включил опции record и logfile у pppd. Симптомы те же: в какой-то момент, в лог перестают падать сообщения о пакетах. Если оборвать соединение на клиенте, то pppd говорит, что получил SIGHUP: судя по всему, сигнал ему шлёт mgetty. Пробовал сам собрать pppd-2.4.2; ситуация повторилась с теми же симптомами. Опции пробовал, наверное, во всех возможных комбинациях.
Интересно наблюдение. Если сразу после поднятия интерфейса ppp0 на сервере или после договорённости об ip-адресах сделать с него пинг на удалённого клиента, то соединение начнёт молчать сразу же.
Система:
---
# cat /etc/asplinux-release
ASPLinux release 7.3 (Vostok)
# uname -r
2.4.22
# pppd --version
pppd version 2.4.1 with CBCPs (ASPLinux)
# mgetty -V
mgetty+sendfax by Gert Doering
experimental test release 1.1.30-Dec16
log file written to '/var/log/mgetty.log.<ttyX>'
config file read from '/etc/mgetty+sendfax/mgetty.config'
---
Лог опроса модема через minicom:
---
ati
MT5600ZDX
OK
ati1
116
OK
ati2
OK
ati3
V2.300-V90_2M_DLS
OK
ati4
a007840284C6002F
bC60000000
r1005111151012000
r3000111170000000
OK
ati5
099
OK
ati6
RCV56DPF-PLL L8571A Rev 36.00/36.00
OK
---
Конфиги:
---
# cat /etc/ppp/options
192.168.131.1:192.168.131.2
netmask 255.255.255.0
ms-dns 192.168.131.1
asyncmap 0
crtscts
lock
modem
debug
noproxyarp
auth
require-chapms-v2
#nobsdcomp
#nodeflate
#nodetach
#nocrtscts
#noaccomp
#nopcomp
#novjccomp
#nopredictor1
mppe-128
#usehostname
#lcp-echo-interval 30
#lcp-echo-failure 4
nodefaultroute
mtu 552
mru 552
#mtu 1400
#mru 1400
#ipcp-max-configure 30
noccp
nomagic
nomp
receive-all
#record /var/log/pppd/dump
#logfile /var/log/pppd/log
---
---
# cat /etc/ppp/chap-secrets
# Secrets for authentication using CHAP
# client server secret IP addresses
user * password *
---
---
# cat /etc/mgetty+sendfax/login.config
/AutoPPP/ - - /usr/sbin/pppd
---
---
# cat /etc/mgetty+sendfax/mgetty.config
debug 0
speed 38400
#speed 19200
data-only y
init-chat "" ATH0 OK ATS2=43 OK ATS3=13 OK ATS7=60 OK ATL0V1E0Q0 OK ATS0=0 OK
answer-chat "" ATA CONNECT
port ttyS0
debug 0
data-only y
direct n
toggle-dtr n
---
---
# cat /etc/mgetty+sendfax/dialin.config
# No numbers limits
---
Логи:
---
# cat /var/log/pppd/log
using channel 14
Using interface ppp0
Connect: ppp0 <--> /dev/pts/2
sent [LCP ConfReq id=0x1 <mru 552> <asyncmap 0x0> <auth chap 81> <pcomp> <accomp>]
rcvd [LCP ConfNak id=0x1 <mru 1500>]
sent [LCP ConfReq id=0x2 <asyncmap 0x0> <auth chap 81> <pcomp> <accomp>]
rcvd [LCP ConfAck id=0x2 <asyncmap 0x0> <auth chap 81> <pcomp> <accomp>]
rcvd [LCP ConfReq id=0x2 <asyncmap 0x0> <magic 0x17196d48> <pcomp> <accomp> <callback CBCP>]
sent [LCP ConfRej id=0x2 <magic 0x17196d48> <callback CBCP>]
rcvd [LCP ConfReq id=0x3 <asyncmap 0x0> <pcomp> <accomp>]
sent [LCP ConfAck id=0x3 <asyncmap 0x0> <pcomp> <accomp>]
sent [CHAP Challenge id=0x1 <7d971eab3ac097e4e25f76066fe5577b>, name = "kuzya.intersyst.ru"]
rcvd [LCP code=0xc id=0x4 17 19 6d 48 4d 53 52 41 53 56 35 2e 30 30]
sent [LCP CodeRej id=0x3 0c 04 00 12 17 19 6d 48 4d 53 52 41 53 56 35 2e 30 30]
rcvd [LCP code=0xc id=0x5 17 19 6d 48 4d 53 52 41 53 2d 31 2d 41 4e 54 45 59]
sent [LCP CodeRej id=0x4 0c 05 00 15 17 19 6d 48 4d 53 52 41 53 2d 31 2d 41 4e 54 45 59]
rcvd [CHAP Response id=0x1 <bf22d644ef368f6fe8fd9659047c7c7d00000000000000002dabcd73813fb7f92eb1a16dab4b34120b6521afdd7128ac00>, name = "antey"]
sent [CHAP Success id=0x1 "S=839E46311313DA3BB09E5B0366C26BF3EE6D4292"]
sent [IPCP ConfReq id=0x1 <addr 192.168.131.1> <compress VJ 0f 01>]
MSCHAP-v2 peer authentication succeeded for antey
rcvd [CCP ConfReq id=0x6 <mppe 0 0 0 1]
Unsupported protocol 'Compression Control Protocol' (0x80fd) received
sent [LCP ProtRej id=0x5 80 fd 01 06 00 0a 12 06 00 00 00 01]
rcvd [IPCP ConfReq id=0x7 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-wins 0.0.0.0> <ms-dns3 0.0.0.0> <ms-wins 0.0.0.0>]
sent [IPCP ConfRej id=0x7 <ms-wins 0.0.0.0> <ms-wins 0.0.0.0>]
rcvd [IPCP ConfAck id=0x1 <addr 192.168.131.1> <compress VJ 0f 01>]
rcvd [IPCP ConfReq id=0x8 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns3 0.0.0.0>]
sent [IPCP ConfNak id=0x8 <addr 192.168.131.2> <ms-dns1 192.168.131.1> <ms-dns3 192.168.131.1>]
rcvd [IPCP ConfReq id=0x9 <compress VJ 0f 01> <addr 192.168.131.2> <ms-dns1 192.168.131.1> <ms-dns3 192.168.131.1>]
sent [IPCP ConfAck id=0x9 <compress VJ 0f 01> <addr 192.168.131.2> <ms-dns1 192.168.131.1> <ms-dns3 192.168.131.1>]
local IP address 192.168.131.1
remote IP address 192.168.131.2
Hangup (SIGHUP)
ioctl(PPPIOCSASYNCMAP): Inappropriate ioctl for device(25)
tcflush failed: Input/output error
---
---
# grep pppd /var/log/messages
Sep 25 11:02:22 kuzya pppd[4657]: pppd 2.4.1 with CBCPs (ASPLinux) started by LOGIN, uid 0
Sep 25 11:02:22 kuzya pppd[4657]: Using interface ppp0
Sep 25 11:02:22 kuzya pppd[4657]: Connect: ppp0 <--> /dev/pts/2
Sep 25 11:02:25 kuzya pppd[4657]: MSCHAP-v2 peer authentication succeeded for antey
Sep 25 11:02:25 kuzya pppd[4657]: Unsupported protocol 'Compression Control Protocol' (0x80fd) received
Sep 25 11:02:26 kuzya pppd[4657]: local IP address 192.168.131.1
Sep 25 11:02:26 kuzya pppd[4657]: remote IP address 192.168.131.2
Sep 25 11:04:03 kuzya pppd[4657]: Hangup (SIGHUP)
Sep 25 11:04:03 kuzya pppd[4657]: ioctl(PPPIOCSASYNCMAP): Inappropriate ioctl for device(25)
Sep 25 11:04:03 kuzya pppd[4657]: tcflush failed: Input/output error
Sep 25 11:04:03 kuzya pppd[4657]: Exit.
---
Лог mgetty от другой сессии, но он повторяется из раза в раз, поэтому я его и привожу. Кажется, mgetty отрабатывает всё время по крайней мере одинаково вне зависимости от pppd, а поскольку отсоединение клиента она ловит корректно, а также первые несколько секунд pppd работает, видимо, проблема не в ней.
---
# cat /var/log/mgetty.log.ttyS0
09/22 20:23:17 yS0 removing lock file
--
09/22 20:23:17 yS0 mgetty: experimental test release 1.1.30-Dec16
09/22 20:23:17 yS0 mgetty.c compiled at Apr 9 2003, 15:23:09
09/22 20:23:17 yS0 user id: 0, pid: 25036, parent pid: 1
09/22 20:23:17 yS0 reading configuration data for port 'ttyS0'
09/22 20:23:17 yS0 reading /etc/mgetty+sendfax/mgetty.config...
09/22 20:23:17 yS0 conf lib: read: 'debug 5'
09/22 20:23:17 yS0 conf lib: read: 'speed 38400'
09/22 20:23:17 yS0 conf lib: read: 'data-only y'
09/22 20:23:17 yS0 conf lib: read: 'init-chat "" ATH0 OK ATS2=43 OK ATS3=13 OK ATS7=60 OK ATL0V1E0Q0 OK ATS0=0 OK'
09/22 20:23:17 yS0 conf lib: read: 'answer-chat "" ATA CONNECT'
09/22 20:23:17 yS0 conf lib: read: 'port ttyS0'
09/22 20:23:17 yS0 section: port ttyS0, **found**
09/22 20:23:17 yS0 conf lib: read: 'debug 5'
09/22 20:23:17 yS0 conf lib: read: 'data-only y'
09/22 20:23:17 yS0 conf lib: read: 'direct n'
09/22 20:23:17 yS0 conf lib: read: 'toggle-dtr y'
09/22 20:23:17 yS0 key: 'speed', type=0, flags=3, data=38400
09/22 20:23:17 yS0 key: 'switchbd', type=0, flags=1, data=0
09/22 20:23:17 yS0 key: 'direct', type=3, flags=3, data=FALSE
09/22 20:23:17 yS0 key: 'blocking', type=3, flags=1, data=FALSE
09/22 20:23:17 yS0 key: 'port-owner', type=1, flags=1, data=uucp
09/22 20:23:17 yS0 key: 'port-group', type=1, flags=1, data=uucp
09/22 20:23:17 yS0 key: 'port-mode', type=0, flags=1, data=432
09/22 20:23:17 yS0 key: 'toggle-dtr', type=3, flags=3, data=TRUE
09/22 20:23:17 yS0 key: 'toggle-dtr-waittime', type=0, flags=1, data=500
09/22 20:23:17 yS0 key: 'need-dsr', type=3, flags=1, data=FALSE
09/22 20:23:17 yS0 key: 'data-only', type=3, flags=3, data=TRUE
09/22 20:23:17 yS0 key: 'fax-only', type=3, flags=1, data=FALSE
09/22 20:23:17 yS0 key: 'modem-type', type=1, flags=1, data=auto
09/22 20:23:17 yS0 key: 'modem-quirks', type=0, flags=0, data=(empty)
09/22 20:23:17 yS0 key: 'init-chat', type=2, flags=3, data= ATH0 OK ATS2=43 OK ATS3=13 OK ATS7=60 OK ATL0V1E0Q0 OK ATS0=0 O
K
09/22 20:23:17 yS0 key: 'force-init-chat', type=2, flags=1, data= \d..\d\d\d+++\d\d\d\dATQ0V1H0 OK
09/22 20:23:17 yS0 key: 'post-init-chat', type=2, flags=0, data=(empty)
09/22 20:23:17 yS0 key: 'data-flow', type=4, flags=1, data=1
09/22 20:23:17 yS0 key: 'fax-send-flow', type=4, flags=1, data=7
09/22 20:23:17 yS0 key: 'fax-rec-flow', type=4, flags=1, data=7
09/22 20:23:17 yS0 key: 'modem-check-time', type=0, flags=1, data=3600
09/22 20:23:17 yS0 key: 'rings', type=0, flags=1, data=1
09/22 20:23:17 yS0 key: 'msn-list', type=2, flags=0, data=(empty)
09/22 20:23:17 yS0 key: 'get-cnd-chat', type=2, flags=0, data=(empty)
09/22 20:23:17 yS0 key: 'cnd-program', type=1, flags=0, data=(empty)
09/22 20:23:17 yS0 key: 'answer-chat', type=2, flags=3, data= ATA CONNECT
09/22 20:23:17 yS0 key: 'answer-chat-timeout', type=0, flags=1, data=80
09/22 20:23:17 yS0 key: 'autobauding', type=3, flags=1, data=FALSE
09/22 20:23:17 yS0 key: 'ringback', type=3, flags=1, data=FALSE
09/22 20:23:17 yS0 key: 'ringback-time', type=0, flags=1, data=30
09/22 20:23:17 yS0 key: 'ignore-carrier', type=3, flags=1, data=FALSE
09/22 20:23:17 yS0 key: 'issue-file', type=1, flags=1, data=/etc/issue
09/22 20:23:17 yS0 key: 'prompt-waittime', type=0, flags=1, data=500
09/22 20:23:17 yS0 key: 'login-prompt', type=1, flags=1, data=@ login:
09/22 20:23:17 yS0 key: 'login-time', type=0, flags=1, data=240
09/22 20:23:17 yS0 key: 'fido-send-emsi', type=3, flags=1, data=TRUE
09/22 20:23:17 yS0 key: 'login-conf-file', type=1, flags=1, data=login.config
09/22 20:23:17 yS0 key: 'fax-id', type=1, flags=1, data=49 115 xxxxxxxx
09/22 20:23:17 yS0 key: 'fax-min-speed', type=0, flags=1, data=0
09/22 20:23:17 yS0 key: 'fax-max-speed', type=0, flags=1, data=14400
09/22 20:23:17 yS0 key: 'fax-server-file', type=1, flags=0, data=(empty)
09/22 20:23:17 yS0 key: 'diskspace', type=0, flags=1, data=1024
09/22 20:23:17 yS0 key: 'notify', type=1, flags=1, data=faxadmin
09/22 20:23:17 yS0 key: 'fax-owner', type=1, flags=1, data=uucp
09/22 20:23:17 yS0 key: 'fax-group', type=1, flags=0, data=(empty)
09/22 20:23:17 yS0 key: 'fax-mode', type=0, flags=1, data=432
09/22 20:23:17 yS0 key: 'fax-spool-in', type=1, flags=1, data=/var/spool/fax/incoming:/tmp
09/22 20:23:17 yS0 key: 'debug', type=0, flags=2, data=5
09/22 20:23:17 yS0 key: 'statistics-chat', type=2, flags=0, data=(empty)
09/22 20:23:17 yS0 key: 'statistics-file', type=1, flags=0, data=(empty)
09/22 20:23:17 yS0 key: 'gettydefs', type=1, flags=1, data=n
09/22 20:23:17 yS0 key: 'term', type=1, flags=0, data=(empty)
09/22 20:23:17 yS0 check for lockfiles
09/22 20:23:17 yS0 checklock: stat failed, no file
09/22 20:23:17 yS0 locking the line
09/22 20:23:17 yS0 makelock(ttyS0) called
09/22 20:23:17 yS0 do_makelock: lock='/var/lock/LCK..ttyS0'
09/22 20:23:17 yS0 lock made
09/22 20:23:18 yS0 tio_get_rs232_lines: status: RTS CTS DSR DTR
09/22 20:23:18 yS0 lowering DTR to reset Modem
09/22 20:23:18 yS0 tss: set speed to 38400 (017)
09/22 20:23:18 yS0 tio_set_flow_control( HARD )
09/22 20:23:18 yS0 waiting for line to clear (VTIME), read:
09/22 20:23:19 yS0 send: ATH0[0d]
09/22 20:23:19 yS0 waiting for ``OK''
09/22 20:23:19 yS0 got: [0d][0a]OK ** found **
09/22 20:23:19 yS0 send: ATS2=43[0d]
09/22 20:23:19 yS0 waiting for ``OK''
09/22 20:23:19 yS0 got: [0d][0a][0d][0a]OK ** found **
09/22 20:23:19 yS0 send: ATS3=13[0d]
09/22 20:23:19 yS0 waiting for ``OK''
09/22 20:23:19 yS0 got: [0d][0a][0d][0a]OK ** found **
09/22 20:23:19 yS0 send: ATS7=60[0d]
09/22 20:23:19 yS0 waiting for ``OK''
09/22 20:23:19 yS0 got: [0d][0a][0d][0a]OK ** found **
09/22 20:23:19 yS0 send: ATL0V1E0Q0[0d]
09/22 20:23:19 yS0 waiting for ``OK''
09/22 20:23:19 yS0 got: [0d][0a][0d][0a]OK ** found **
09/22 20:23:19 yS0 send: ATS0=0[0d]
09/22 20:23:19 yS0 waiting for ``OK''
09/22 20:23:19 yS0 got: [0d][0a][0d][0a]OK ** found **
09/22 20:23:19 yS0 waiting for line to clear (VTIME), read: [0d][0a]
09/22 20:23:19 yS0 removing lock file
09/22 20:23:19 yS0 waiting...
09/22 20:30:18 ##### failed dev=ttyS0, pid=25036, got signal 15, exiting
---