Тему поднимал недавно, она скатилась.
Linux Slackware 9 + pppd 2.4.1 with cbcp_serv patch + mgetty какой-то. ПРоблема - разрыв связи при перезвоне сервера клиенту. Т.е. если звонишь без колбека, все тип-топ. При callback происходит первичная аунтификация, сервак просит номер, перезванивает, проверяет имя и бросает трубку. Установленый несколько лет назад сервер на слак 7 + рррd 2.3.10 c этим же конфигом работает.
ЛОГИ:
+++++++++--------ppplog----------++++++++
Oct 3 23:15:18 temp pppd[350]: pppd 2.4.1 with CBCPs (ASPLinux) started by /AutoPPP/, uid 0
speed 9 not supported
Oct 3 23:15:18 temp pppd[350]: speed 9 not supported
using channel 6
Oct 3 23:15:18 temp pppd[350]: using channel 6
Oct 3 23:15:18 temp pppd[350]: Using interface ppp0
Using interface ppp0
Oct 3 23:15:18 temp pppd[350]: Connect: ppp0 <--> /dev/ttyS1
Connect: ppp0 <--> /dev/ttyS1
Oct 3 23:15:18 temp pppd[350]: sent [LCP ConfReq id=0x1 <mru 585> <asyncmap 0x0> <auth pap> <magic 0x3be95acd> <pcomp> <accomp>]
sent [LCP ConfReq id=0x1 <mru 585> <asyncmap 0x0> <auth pap> <magic 0x3be95acd> <pcomp> <accomp>]
rcvd [LCP ConfReq id=0x2 <asyncmap 0xa0000> <magic 0x2e3a35> <pcomp> <accomp> <callback CBCP>]
Oct 3 23:15:21 temp pppd[350]: rcvd [LCP ConfReq id=0x2 <asyncmap 0xa0000> <magic 0x2e3a35> <pcomp> <accomp> <callback CBCP>]
sent [LCP ConfAck id=0x2 <asyncmap 0xa0000> <magic 0x2e3a35> <pcomp> <accomp> <callback CBCP>]
Oct 3 23:15:21 temp pppd[350]: sent [LCP ConfAck id=0x2 <asyncmap 0xa0000> <magic 0x2e3a35> <pcomp> <accomp> <callback CBCP>]
sent [LCP ConfReq id=0x1 <mru 585> <asyncmap 0x0> <auth pap> <magic 0x3be95acd> <pcomp> <accomp>]
Oct 3 23:15:21 temp pppd[350]: sent [LCP ConfReq id=0x1 <mru 585> <asyncmap 0x0> <auth pap> <magic 0x3be95acd> <pcomp> <accomp>]
rcvd [LCP ConfAck id=0x1 <mru 585> <asyncmap 0x0> <auth pap> <magic 0x3be95acd> <pcomp> <accomp>]
Oct 3 23:15:22 temp pppd[350]: rcvd [LCP ConfAck id=0x1 <mru 585> <asyncmap 0x0> <auth pap> <magic 0x3be95acd> <pcomp> <accomp>]
Oct 3 23:15:22 temp pppd[350]: cbcp_lowerup
Oct 3 23:15:22 temp pppd[350]: want: 0
rcvd [PAP AuthReq id=0x1 user="vvv" password=<hidden>]
Oct 3 23:15:22 temp pppd[350]: rcvd [PAP AuthReq id=0x1 user="vvv" password=<hidden>]
sent [PAP AuthAck id=0x1 "Login ok"]
Oct 3 23:15:22 temp pppd[350]: sent [PAP AuthAck id=0x1 "Login ok"]
Script /etc/ppp/auth-up started (pid 361)
Oct 3 23:15:22 temp pppd[350]: Script /etc/ppp/auth-up started (pid 361)
Oct 3 23:15:22 temp pppd[350]: cbcp_open
Oct 3 23:15:22 temp pppd[350]: cbcp_sendreq cb_allowed=8
sent [CBCP Request id=0x1 < AdminDefined delay = 5>]
Oct 3 23:15:22 temp pppd[350]: cbcp_sendreq CONF_ADMIN
Oct 3 23:15:22 temp pppd[350]: sent [CBCP Request id=0x1 < AdminDefined delay = 5>]
Script /etc/ppp/auth-up finished (pid 361), status = 0x0
Oct 3 23:15:22 temp pppd[350]: Script /etc/ppp/auth-up finished (pid 361), status = 0x0
rcvd [CBCP Response id=0x1 < AdminDefined delay = 15>]
Oct 3 23:15:23 temp pppd[350]: rcvd [CBCP Response id=0x1 < AdminDefined delay = 15>]
Oct 3 23:15:23 temp pppd[350]: cbcp_sendack cb_type=8
sent [CBCP Ack id=0x1 < AdminDefined delay = 15>]
Oct 3 23:15:23 temp pppd[350]: cbcp_sendack CONF_ADMIN
Oct 3 23:15:23 temp pppd[350]: sent [CBCP Ack id=0x1 < AdminDefined delay = 15>]
rcvd [LCP TermReq id=0x3]
Oct 3 23:15:23 temp pppd[350]: rcvd [LCP TermReq id=0x3]LCP terminated by peer
Oct 3 23:15:23 temp pppd[350]: LCP terminated by peer
Script /etc/ppp/auth-down started (pid 362)
Oct 3 23:15:23 temp pppd[350]: Script /etc/ppp/auth-down started (pid 362)
sent [LCP TermAck id=0x3]
Oct 3 23:15:23 temp pppd[350]: sent [LCP TermAck id=0x3]
Script /etc/ppp/auth-down finished (pid 362), status = 0x0
Oct 3 23:15:23 temp pppd[350]: Script /etc/ppp/auth-down finished (pid 362), status = 0x0
Hangup (SIGHUP)
Modem hangup
Oct 3 23:15:24 temp pppd[350]: Hangup (SIGHUP)
Connection terminated.
Oct 3 23:15:24 temp pppd[350]: Modem hangup
Connect time 0.1 minutes.
Oct 3 23:15:24 temp pppd[350]: Connection terminated.
Sent 0 bytes, received 0 bytes.
Oct 3 23:15:24 temp pppd[350]: Connect time 0.1 minutes.
Oct 3 23:15:24 temp pppd[350]: Sent 0 bytes, received 0 bytes.
Oct 3 23:15:24 temp pppd[350]: cbcp_start_callback running
Oct 3 23:15:24 temp pppd[350]: speed 9 not supported
speed 9 not supported
Oct 3 23:15:24 temp pppd[350]: Callback with </etc/ppp/callback-server 15 282828>
Oct 3 23:15:24 temp pppd[350]: speed 9 not supported
speed 9 not supported
Oct 3 23:15:24 temp chat[368]: send (d+++dc^M)
Oct 3 23:15:24 temp chat[368]: expect (OK)
Oct 3 23:15:24 temp chat[368]: ^M
Oct 3 23:15:24 temp chat[368]: NO CARRIER^M
Oct 3 23:15:26 temp chat[368]: alarm
Oct 3 23:15:26 temp chat[368]: Failed
Oct 3 23:15:44 temp chat[374]: send (ATZ^M)
Oct 3 23:15:44 temp chat[374]: expect (OK)
Oct 3 23:15:44 temp chat[374]: ATZ^M^M
Oct 3 23:15:44 temp chat[374]: OK
Oct 3 23:15:44 temp chat[374]: -- got it
Oct 3 23:15:44 temp chat[374]: send (ATD282828^M)
Oct 3 23:15:44 temp chat[374]: expect (CONNECT)
Oct 3 23:15:44 temp chat[374]: ^M
Oct 3 23:16:02 temp chat[374]: ATD282828^M^M
Oct 3 23:16:02 temp chat[374]: CARRIER 14400^M
Oct 3 23:16:02 temp chat[374]: ^M
Oct 3 23:16:02 temp chat[374]: PROTOCOL: V42^M
Oct 3 23:16:02 temp chat[374]: ^M
Oct 3 23:16:02 temp chat[374]: COMPRESSION: V42b^M
Oct 3 23:16:02 temp chat[374]: ^M
Oct 3 23:16:02 temp chat[374]: CONNECT
Oct 3 23:16:02 temp chat[374]: -- got it
Serial connection established.
Oct 3 23:16:02 temp pppd[350]: Serial connection established.
speed 9 not supported
Oct 3 23:16:02 temp pppd[350]: speed 9 not supported
using channel 7
Oct 3 23:16:02 temp pppd[350]: using channel 7
Using interface ppp0
Connect: ppp0 <--> /dev/ttyS1
sent [LCP ConfReq id=0x2 <mru 585> <asyncmap 0x0> <auth pap> <magic 0x807aab1e> <pcomp> <accomp>]
sent [LCP TermReq id=0x3 "User request"]
Oct 3 23:16:02 temp pppd[350]: Using interface ppp0
Oct 3 23:16:02 temp pppd[350]: Connect: ppp0 <--> /dev/ttyS1
Oct 3 23:16:02 temp pppd[350]: sent [LCP ConfReq id=0x2 <mru 585> <asyncmap 0x0> <auth pap> <magic 0x807aab1e> <pcomp> <accomp>]
Oct 3 23:16:02 temp pppd[350]: sent [LCP TermReq id=0x3 "User request"]
rcvd [LCP ConfReq id=0x1 <asyncmap 0xa0000> <magic 0x2ee81d> <pcomp> <accomp>]
Oct 3 23:16:02 temp pppd[350]: rcvd [LCP ConfReq id=0x1 <asyncmap 0xa0000> <magic 0x2ee81d> <pcomp> <accomp>]
rcvd [LCP ConfAck id=0x2 <mru 585> <asyncmap 0x0> <auth pap> <magic 0x807aab1e> <pcomp> <accomp>]
Oct 3 23:16:03 temp pppd[350]: rcvd [LCP ConfAck id=0x2 <mru 585> <asyncmap 0x0> <auth pap> <magic 0x807aab1e> <pcomp> <accomp>]
rcvd [LCP TermAck id=0x3]
Oct 3 23:16:03 temp pppd[350]: rcvd [LCP TermAck id=0x3]
Connection terminated.
Oct 3 23:16:03 temp pppd[350]: Connection terminated.
speed 9 not supported
Oct 3 23:16:03 temp pppd[350]: speed 9 not supported
disconnect script failed
Oct 3 23:16:48 temp pppd[350]: disconnect script failed
Oct 3 23:16:48 temp pppd[350]: Exit.
++++++++++++++++++++-------------- ppplog end------------+++++++++++++++++
++++++++++++++++++++-------------- messages -------------+++++++++++++++++
Oct 3 23:15:18 temp pppd[350]: pppd 2.4.1 with CBCPs (ASPLinux) started by /AutoPPP/, uid 0
Oct 3 23:15:18 temp pppd[350]: Using interface ppp0
Oct 3 23:15:18 temp pppd[350]: Connect: ppp0 <--> /dev/ttyS1
Oct 3 23:15:18 temp /etc/hotplug/net.agent: assuming ppp0 is already up
Oct 3 23:15:23 temp pppd[350]: LCP terminated by peer
Oct 3 23:15:24 temp pppd[350]: Hangup (SIGHUP)
Oct 3 23:15:24 temp pppd[350]: Modem hangup
Oct 3 23:15:24 temp pppd[350]: Connection terminated.
Oct 3 23:15:24 temp pppd[350]: Connect time 0.1 minutes.
Oct 3 23:15:24 temp pppd[350]: Sent 0 bytes, received 0 bytes.
Oct 3 23:15:24 temp pppd[350]: Callback with </etc/ppp/callback-server 15 282828>
Oct 3 23:15:24 temp chat[368]: send (d+++dc^M)
Oct 3 23:15:24 temp chat[368]: expect (OK)
Oct 3 23:15:24 temp chat[368]: ^M
Oct 3 23:15:24 temp chat[368]: NO CARRIER^M
Oct 3 23:15:26 temp chat[368]: alarm
Oct 3 23:15:26 temp chat[368]: Failed
Oct 3 23:15:44 temp chat[374]: send (ATZ^M)
Oct 3 23:15:44 temp chat[374]: expect (OK)
Oct 3 23:15:44 temp chat[374]: ATZ^M^M
Oct 3 23:15:44 temp chat[374]: OK
Oct 3 23:15:44 temp chat[374]: -- got it
Oct 3 23:15:44 temp chat[374]: send (ATD282828^M)
Oct 3 23:15:44 temp chat[374]: expect (CONNECT)
Oct 3 23:15:44 temp chat[374]: ^M
Oct 3 23:16:02 temp chat[374]: ATD282828^M^M
Oct 3 23:16:02 temp chat[374]: CARRIER 14400^M
Oct 3 23:16:02 temp chat[374]: ^M
Oct 3 23:16:02 temp chat[374]: PROTOCOL: V42^M
Oct 3 23:16:02 temp chat[374]: ^M
Oct 3 23:16:02 temp chat[374]: COMPRESSION: V42b^M
Oct 3 23:16:02 temp chat[374]: ^M
Oct 3 23:16:02 temp chat[374]: CONNECT
Oct 3 23:16:02 temp chat[374]: -- got it
Oct 3 23:16:02 temp pppd[350]: Serial connection established.
Oct 3 23:16:02 temp pppd[350]: Using interface ppp0
Oct 3 23:16:02 temp pppd[350]: Connect: ppp0 <--> /dev/ttyS1
Oct 3 23:16:02 temp /etc/hotplug/net.agent: assuming ppp0 is already up
Oct 3 23:16:03 temp pppd[350]: Connection terminated.
Oct 3 23:16:48 temp pppd[350]: Exit.
+++++++++++++++++-------------------- messages end--------------+++++++++++++
+++++++++++++++++------------------mgetty.ttyS1-----------------+++++++++++++
10/03 23:14:16 yS1 mgetty: experimental test release 1.1.30-Dec16
10/03 23:14:16 yS1 check for lockfiles
10/03 23:14:16 yS1 checklock: no active process has lock, will remove
10/03 23:14:16 yS1 locking the line
10/03 23:14:16 yS1 makelock(ttyS1) called
10/03 23:14:16 yS1 do_makelock: lock='/var/lock/LCK..ttyS1'
10/03 23:14:16 yS1 lock made
10/03 23:14:16 yS1 tio_get_rs232_lines: status: RTS CTS DSR DTR
10/03 23:14:16 yS1 lowering DTR to reset Modem
10/03 23:14:17 yS1 tss: set speed to 115200 (10002)
10/03 23:14:17 yS1 tio_set_flow_control( HARD )
10/03 23:14:17 yS1 waiting for line to clear (VTIME), read:
10/03 23:14:17 yS1 send: AT&K4&N17[0d]
10/03 23:14:17 yS1 waiting for ``OK''
10/03 23:14:17 yS1 got: AT&K4&N17[0d]
10/03 23:14:17 yS1 CND: AT&K4&N17[0d][0a]OK ** found **
10/03 23:14:17 yS1 waiting for line to clear (VTIME), read: [0d][0a]
10/03 23:14:17 yS1 removing lock file
10/03 23:14:17 yS1 waiting...
10/03 23:15:04 yS1 select returned 1
10/03 23:15:04 yS1 checking lockfiles, locking the line
10/03 23:15:04 yS1 makelock(ttyS1) called
10/03 23:15:04 yS1 do_makelock: lock='/var/lock/LCK..ttyS1'
10/03 23:15:04 yS1 lock made
10/03 23:15:04 yS1 wfr: waiting for ``RING''
10/03 23:15:04 yS1 got: [0d][0a]RING[0d]
10/03 23:15:04 yS1 CND: RING
10/03 23:15:04 yS1 wfr: rc=0, drn=0
10/03 23:15:04 yS1 send: ATA[0d]
10/03 23:15:04 yS1 waiting for ``CONNECT''
10/03 23:15:04 yS1 got: ATA[0d]
10/03 23:15:04 yS1 CND: OKATA[0d][0a]CARRIER 14400[0d]
10/03 23:15:17 yS1 CND: CARRIER 14400
10/03 23:15:17 yS1 CND: found: 14400[0a][0d][0a]PROTOCOL: V42[0d]
10/03 23:15:17 yS1 CND: PROTOCOL: V42
10/03 23:15:17 yS1 CND: found: V42[0a][0d][0a]COMPRESSION: V42b[0d]
10/03 23:15:17 yS1 CND: COMPRESSION: V42b[0a][0d][0a]CONNECT ** found **
10/03 23:15:17 yS1 send:
10/03 23:15:17 yS1 waiting for ``_''
10/03 23:15:17 yS1 got: 115200[0d]
10/03 23:15:17 yS1 CND: CONNECT 115200
10/03 23:15:17 yS1 CND: found: 115200/14400 V42[0a] ** found **
10/03 23:15:17 yS1 waiting for line to clear (VTIME), read:
10/03 23:15:18 yS1 looking for utmp entry... (my PID: 350)
10/03 23:15:18 yS1 utmp + wtmp entry made
10/03 23:15:18 yS1 tio_set_flow_control( HARD )
10/03 23:15:18 yS1 print welcome banner (/etc/issue)
10/03 23:15:18 yS1 getlogname (FIDO AUTO_PPP), read:~[ff]}#[c0]!
10/03 23:15:18 yS1 input finished with '\r', setting ICRNL ONLCR
10/03 23:15:18 yS1 tio_get_rs232_lines: status: RTS CTS DSR DTR DCD
10/03 23:15:18 yS1 login: use login config file /usr/local/etc/mgetty+sendfax/login.config
10/03 23:15:18 yS1 match: user='/AutoPPP/', key=''
10/03 23:15:18 yS1 match: user='/AutoPPP/', key=''
10/03 23:15:18 yS1 match: user='/AutoPPP/', key='/AutoPPP/'*** hit!
10/03 23:15:18 yS1 login: utmp entry: /AutoPPP/
10/03 23:15:18 yS1 looking for utmp entry... (my PID: 350)
10/03 23:15:18 yS1 utmp + wtmp entry made
10/03 23:15:18 yS1 calling login: cmd='/usr/sbin/pppd', argv[]='pppd call dial-in'
10/03 23:15:18 yS1 setenv: 'CALLER_ID=none'
10/03 23:15:18 yS1 setenv: 'CONNECT=115200/14400 V42'
10/03 23:15:18 yS1 setenv: 'DEVICE=ttyS1'
10/03 23:15:18 ##### data dev=ttyS1, pid=350, caller='none', conn='115200/14400 V42', name='', cmd='/usr/sbin/pppd', user='/AutoPPP/'
--
10/03 23:16:48 yS1 mgetty: experimental test release 1.1.30-Dec16
10/03 23:16:48 yS1 check for lockfiles
10/03 23:16:48 yS1 checklock: no active process has lock, will remove
10/03 23:16:48 yS1 locking the line
10/03 23:16:48 yS1 makelock(ttyS1) called
10/03 23:16:48 yS1 do_makelock: lock='/var/lock/LCK..ttyS1'
10/03 23:16:48 yS1 lock made
10/03 23:16:49 yS1 tio_get_rs232_lines: status: RTS CTS DSR DTR
10/03 23:16:49 yS1 lowering DTR to reset Modem
10/03 23:16:49 yS1 tss: set speed to 115200 (10002)
10/03 23:16:49 yS1 tio_set_flow_control( HARD )
10/03 23:16:49 yS1 waiting for line to clear (VTIME), read:
10/03 23:16:50 yS1 send: AT&K4&N17[0d]
10/03 23:16:50 yS1 waiting for ``OK''
10/03 23:16:50 yS1 got: AT&K4&N17[0d]
10/03 23:16:50 yS1 CND: AT&K4&N17[0d][0a]OK ** found **
10/03 23:16:50 yS1 waiting for line to clear (VTIME), read: [0d][0a]
10/03 23:16:50 yS1 removing lock file
10/03 23:16:50 yS1 waiting...
++++++++++++++++++++-------------mgetty.ttyS1 end--------+++++++++++++++
|