Странные проблемы с pppd

Автор: Vladimir Dyakov Дата: 25.09.2003 09:59 Преамбула. Настраивал 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 работает, видимо, проблема не в ней. В этом логе посередине обрыв - я перезапускал mgetty.
---
# cat /var/log/mgetty.log.ttyS0

--
09/22 20:21:19 yS0 mgetty: experimental test release 1.1.30-Dec16
09/22 20:21:19 yS0 mgetty.c compiled at Apr 9 2003, 15:23:09
09/22 20:21:19 yS0 user id: 0, pid: 25009, parent pid: 1
09/22 20:21:19 yS0 reading configuration data for port 'ttyS0'
09/22 20:21:19 yS0 reading /etc/mgetty+sendfax/mgetty.config...
09/22 20:21:19 yS0 conf lib: read: 'debug 5'
09/22 20:21:19 yS0 conf lib: read: 'speed 38400'
09/22 20:21:19 yS0 conf lib: read: 'data-only y'
09/22 20:21:19 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:21:19 yS0 conf lib: read: 'answer-chat "" ATA CONNECT'
09/22 20:21:19 yS0 conf lib: read: 'port ttyS0'
09/22 20:21:19 yS0 section: port ttyS0, **found**
09/22 20:21:19 yS0 conf lib: read: 'debug 5'
09/22 20:21:19 yS0 conf lib: read: 'data-only y'
09/22 20:21:19 yS0 conf lib: read: 'direct n'
09/22 20:21:19 yS0 conf lib: read: 'toggle-dtr y'
09/22 20:21:19 yS0 key: 'speed', type=0, flags=3, data=38400
09/22 20:21:19 yS0 key: 'switchbd', type=0, flags=1, data=0
09/22 20:21:19 yS0 key: 'direct', type=3, flags=3, data=FALSE
09/22 20:21:19 yS0 key: 'blocking', type=3, flags=1, data=FALSE
09/22 20:21:19 yS0 key: 'port-owner', type=1, flags=1, data=uucp
09/22 20:21:19 yS0 key: 'port-group', type=1, flags=1, data=uucp
09/22 20:21:19 yS0 key: 'port-mode', type=0, flags=1, data=432
09/22 20:21:19 yS0 key: 'toggle-dtr', type=3, flags=3, data=TRUE
09/22 20:21:19 yS0 key: 'toggle-dtr-waittime', type=0, flags=1, data=500
09/22 20:21:19 yS0 key: 'need-dsr', type=3, flags=1, data=FALSE
09/22 20:21:19 yS0 key: 'data-only', type=3, flags=3, data=TRUE
09/22 20:21:19 yS0 key: 'fax-only', type=3, flags=1, data=FALSE
09/22 20:21:19 yS0 key: 'modem-type', type=1, flags=1, data=auto
09/22 20:21:19 yS0 key: 'modem-quirks', type=0, flags=0, data=(empty)
09/22 20:21:19 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:21:19 yS0 key: 'force-init-chat', type=2, flags=1, data= \d..\d\d\d+++\d\d\d\dATQ0V1H0 OK
09/22 20:21:19 yS0 key: 'post-init-chat', type=2, flags=0, data=(empty)
09/22 20:21:19 yS0 key: 'data-flow', type=4, flags=1, data=1
09/22 20:21:19 yS0 key: 'fax-send-flow', type=4, flags=1, data=7
09/22 20:21:19 yS0 key: 'fax-rec-flow', type=4, flags=1, data=7
09/22 20:21:19 yS0 key: 'modem-check-time', type=0, flags=1, data=3600
09/22 20:21:19 yS0 key: 'rings', type=0, flags=1, data=1
09/22 20:21:19 yS0 key: 'msn-list', type=2, flags=0, data=(empty)
09/22 20:21:19 yS0 key: 'get-cnd-chat', type=2, flags=0, data=(empty)
09/22 20:21:19 yS0 key: 'cnd-program', type=1, flags=0, data=(empty)
09/22 20:21:19 yS0 key: 'answer-chat', type=2, flags=3, data= ATA CONNECT
09/22 20:21:19 yS0 key: 'answer-chat-timeout', type=0, flags=1, data=80
09/22 20:21:19 yS0 key: 'autobauding', type=3, flags=1, data=FALSE
09/22 20:21:19 yS0 key: 'ringback', type=3, flags=1, data=FALSE
09/22 20:21:19 yS0 key: 'ringback-time', type=0, flags=1, data=30
09/22 20:21:19 yS0 key: 'ignore-carrier', type=3, flags=1, data=FALSE
09/22 20:21:19 yS0 key: 'issue-file', type=1, flags=1, data=/etc/issue
09/22 20:21:19 yS0 key: 'prompt-waittime', type=0, flags=1, data=500
09/22 20:21:19 yS0 key: 'login-prompt', type=1, flags=1, data=@ login:
09/22 20:21:19 yS0 key: 'login-time', type=0, flags=1, data=240
09/22 20:21:19 yS0 key: 'fido-send-emsi', type=3, flags=1, data=TRUE
09/22 20:21:19 yS0 key: 'login-conf-file', type=1, flags=1, data=login.config
09/22 20:21:19 yS0 key: 'fax-id', type=1, flags=1, data=49 115 xxxxxxxx
09/22 20:21:19 yS0 key: 'fax-min-speed', type=0, flags=1, data=0
09/22 20:21:19 yS0 key: 'fax-max-speed', type=0, flags=1, data=14400
09/22 20:21:19 yS0 key: 'fax-server-file', type=1, flags=0, data=(empty)
09/22 20:21:19 yS0 key: 'diskspace', type=0, flags=1, data=1024
09/22 20:21:19 yS0 key: 'notify', type=1, flags=1, data=faxadmin
09/22 20:21:19 yS0 key: 'fax-owner', type=1, flags=1, data=uucp
09/22 20:21:19 yS0 key: 'fax-group', type=1, flags=0, data=(empty)
09/22 20:21:19 yS0 key: 'fax-mode', type=0, flags=1, data=432
09/22 20:21:19 yS0 key: 'fax-spool-in', type=1, flags=1, data=/var/spool/fax/incoming:/tmp
09/22 20:21:19 yS0 key: 'debug', type=0, flags=2, data=5
09/22 20:21:19 yS0 key: 'statistics-chat', type=2, flags=0, data=(empty)
09/22 20:21:19 yS0 key: 'statistics-file', type=1, flags=0, data=(empty)
09/22 20:21:19 yS0 key: 'gettydefs', type=1, flags=1, data=n
09/22 20:21:19 yS0 key: 'term', type=1, flags=0, data=(empty)
09/22 20:21:19 yS0 check for lockfiles
09/22 20:21:19 yS0 checklock: stat failed, no file
09/22 20:21:19 yS0 locking the line
09/22 20:21:19 yS0 makelock(ttyS0) called
09/22 20:21:19 yS0 do_makelock: lock='/var/lock/LCK..ttyS0'
09/22 20:21:19 yS0 lock made
09/22 20:21:19 yS0 tio_get_rs232_lines: status: RTS CTS DSR DTR
09/22 20:21:19 yS0 lowering DTR to reset Modem
09/22 20:21:20 yS0 tss: set speed to 38400 (017)
09/22 20:21:20 yS0 tio_set_flow_control( HARD )
09/22 20:21:20 yS0 waiting for line to clear (VTIME), read:
09/22 20:21:20 yS0 send: ATH0[0d]
09/22 20:21:20 yS0 waiting for ``OK''
09/22 20:21:20 yS0 got: [0d][0a]OK ** found **
09/22 20:21:20 yS0 checking lockfiles, locking the line
09/22 20:21:20 yS0 makelock(ttyS0) called
09/22 20:21:20 yS0 do_makelock: lock='/var/lock/LCK..ttyS0'
09/22 20:21:20 yS0 lock not made: lock file exists (pid=25009)
09/22 20:21:20 yS0 lock file exists (dialout)!
09/22 20:21:20 yS0 lockfile found, pid=25009
09/22 20:21:20 yS0 lockfile found, pid=25009
09/22 20:21:20 yS0 send: ATS2=43[0d]
09/22 20:21:20 yS0 waiting for ``OK''
09/22 20:21:20 yS0 got: [0d][0a][0d][0a]OK ** found **
09/22 20:21:20 yS0 send: ATS3=13[0d]
09/22 20:21:20 yS0 waiting for ``OK''
09/22 20:21:20 yS0 got: [0d][0a][0d][0a]OK ** found **
09/22 20:21:20 yS0 send: ATS7=60[0d]
09/22 20:21:20 yS0 waiting for ``OK''
09/22 20:21:20 yS0 got: [0d][0a][0d][0a]OK ** found **
09/22 20:21:20 yS0 send: ATL0V1E0Q0[0d]
09/22 20:21:20 yS0 waiting for ``OK''
09/22 20:21:20 yS0 got: [0d][0a][0d][0a]OK ** found **
09/22 20:21:20 yS0 send: ATS0=0[0d]
09/22 20:21:20 yS0 waiting for ``OK''
09/22 20:21:20 yS0 got: [0d][0a][0d][0a]OK ** found **
09/22 20:21:20 yS0 waiting for line to clear (VTIME), read: [0d][0a]
09/22 20:21:20 yS0 removing lock file
09/22 20:21:20 yS0 waiting...
09/22 20:21:27 ##### failed dev=ttyS0, pid=25006, got signal 15, exiting

09/22 20:21:36 yS0 checking lockfiles, locking the line
09/22 20:21:36 yS0 makelock(ttyS0) called
09/22 20:21:36 yS0 do_makelock: lock='/var/lock/LCK..ttyS0'
09/22 20:21:36 yS0 lock made
09/22 20:21:36 yS0 wfr: waiting for ``RING''
09/22 20:21:36 yS0 got: [0d][0a]RING[0d]
09/22 20:21:36 yS0 wfr: rc=0, drn=0
09/22 20:21:36 yS0 send: ATA[0d]
09/22 20:21:36 yS0 waiting for ``CONNECT''
09/22 20:21:36 yS0 got: [0d][0a]CONNECT ** found **
09/22 20:21:58 yS0 waiting for line to clear (VTIME), read: 38400[0d][0a]~[ff]}#[c0]!}!} } }7}"}&} } } } }%}&r[e0]h[bf]}'}
"}(}"}-}#}&v ~
09/22 20:21:59 yS0 utmp + wtmp entry made
09/22 20:21:59 yS0 tio_set_flow_control( HARD )
09/22 20:21:59 yS0 print welcome banner (/etc/issue)
09/22 20:21:59 yS0 getlogname (FIDO AUTO_PPP), read:~[ff]}#[c0]!
09/22 20:22:00 yS0 input finished with '\r', setting ICRNL ONLCR
09/22 20:22:00 yS0 tio_get_rs232_lines: status: RTS CTS DSR DTR DCD
09/22 20:22:00 yS0 match: user='/AutoPPP/', key='/AutoPPP/'*** hit!
09/22 20:22:00 yS0 calling login: cmd='/usr/sbin/pppd', argv[]='pppd'
09/22 20:22:00 yS0 setenv: 'CALLER_ID=none'
09/22 20:22:00 yS0 setenv: 'CONNECT='
09/22 20:22:00 yS0 setenv: 'DEVICE=ttyS0'
09/22 20:22:00 ##### data dev=ttyS0, pid=25009, caller='none', conn='', name='', cmd='/usr/sbin/pppd', user='/AutoPPP/'

--
09/22 20:23:16 yS0 mgetty: experimental test release 1.1.30-Dec16
......
---
Re: странные проблемы с pppd 25.09.2003 14:47pahan в /etc/ppp/options
не пробовал noccp закомментировать?
nomagic - тоже зачем здесь?

у меня
это выглядит так:

modem
nodetach
ms-dns XXX.XXX.XXX.XXX
192.168.40.1:192.168.40.10
idle 180

попробуй в таком варианте - у меня виндовые клиенты цепляются без проблем
Re: странные проблемы с pppd 25.09.2003 15:00Vladimir Dyakov Пробовал по-всякому, и с noccp, и без, и с nomagic, и без. nodetach тоже пробовал.

Попробовал с вашими опциями (в конце добавил debug):
---
modem
nodetach
ms-dns 192.168.40.1
192.168.40.1:192.168.40.10
idle 180
debug
---
Тоже самое.
Re: странные проблемы с pppd 25.09.2003 16:39Iron Для конкретного модема лучше использовать собственный файл опций /etc/ppp/options.ttyS0:
115200
crtscts
nodetach
proxyarp
lock
192.168.11.101:192.168.11.102
+pap
ms-dns 192.168.11.57

Возможно проблемы с роутингом, попробуйте
отключить nodefaultroute.
Re: странные проблемы с pppd 25.09.2003 17:21pahan попробуйте вот что:

во-первых присоединяюсь к совету выше
сделайте /etc/ppp/options.ttyS0
его содержание минимально (как у меня ну плюс debug)

(у меня так на каждый прнимающий модем - соответственно при дозвоне на определенный порт получаешь фиксированный известный адрес)

во-вторых попробуйте без использования auto-ppp:
1.
сделайте пользователю дилапщику шелом /usr/sbin/pppd
(не забыть добавить строчку в /etc/shells)
ему в домашний каталог обязательно положите фалик (пустой)
.hushlogin с правами 644 и владельцем соотв. имени пользователя

2.
на виндовом клиенте в подключении укажите сценарий
следующего содержания:

--
proc main

waitfor "ogin:"
transmit "WinUser"
transmit "^M"

waitfor "assword:"
transmit "SecretPassword"
transmit "^M"


endproc
--

если это вин 2000/ХР уберите галочку "Запрашивать имя, пароль, сертификат и т.д."
(пароль у нас теперь передается в скрипте)

3. попробовать со всей этой фигней взлететь
Re: странные проблемы с pppd 26.09.2003 09:11Vladimir Dyakov Iron писал(а):

> Для конкретного модема лучше использовать собственный файл
> опций /etc/ppp/options.ttyS0:
Пробовал, никакой разницы.

> Возможно проблемы с роутингом, попробуйте
> отключить nodefaultroute.
nodefaultroute я включил после настройки, когда начал пытаться решить проблему. И вообще, какие могут быть проблемы в рутинге, если pppd даже в дамп общения по серийной линии ничего не кладёт (опция record)? Улыбка

Я попробовал вашу конфигурацию:
---
# cat /etc/ppp/options.ttyS0
crtscts
nodetach
proxyarp
lock
192.168.11.101:192.168.11.102
ms-dns 192.168.11.57
---
Пришлось убрать 115200, потому что с ней не проходили LCP пакеты, то есть даже до утентификации не доходило - видимо, вообще никакие ppp-пакеты не проходили. Симптомы те же, что и в моём первом сообщении.
Кстати, интересно вот что. При закрытом фаерволе, когда с интерфейса ppp0 выкидываются входящие через линк пакеты, tcpdump -pni ppp0 выдавал icmp echo request'ы. Как только я разрешил общение через ppp0 и послал пинг на 192.168.11.102, всё опять упало.
Злостное подозрение на ядро, pppd или патч к ядру, дающий mppe.
Re: странные проблемы с pppd 26.09.2003 11:10Iron ppp от ASP-7.3 работает нормально.
Попробуйте стандартное ядро и если не поможет,
подключите другой модем.
RSS-материал