'port forced close' after failed ppp
Colin Helliwell
colin.helliwell at ln-systems.com
Tue Mar 7 12:26:49 UTC 2017
Is it right that MM should be showing the ppp port as going disconnected part way through the ppp negotiation....? [see below]
> On 07 March 2017 at 10:13 Colin Helliwell <colin.helliwell at ln-systems.com> wrote:
>
> ...
> In case it's of use, here's the log of MM+pppd when trying (after a --enable) the --simple-connect followed by 'pon'
>
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.022821] [src/mm-iface-modem-simple.c:641] connect_auth_ready(): Simple connect started...
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.023123] [src/mm-iface-modem-simple.c:651] connect_auth_ready(): PIN: unspecified
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.023257] [src/mm-iface-modem-simple.c:653] connect_auth_ready(): Operator ID: unspecified
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.023392] [src/mm-iface-modem-simple.c:655] connect_auth_ready(): Allowed roaming: yes
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.023525] [src/mm-iface-modem-simple.c:657] connect_auth_ready(): APN: mobile.o2.co.uk
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.023660] [src/mm-iface-modem-simple.c:665] connect_auth_ready(): IP family: unspecified
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.023786] [src/mm-iface-modem-simple.c:673] connect_auth_ready(): Allowed authentication: unspecified
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.023916] [src/mm-iface-modem-simple.c:675] connect_auth_ready(): User: unspecified
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.024039] [src/mm-iface-modem-simple.c:677] connect_auth_ready(): Password: unspecified
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.024171] [src/mm-iface-modem-simple.c:679] connect_auth_ready(): Number: unspecified
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.024281] [src/mm-iface-modem-simple.c:469] connection_step(): Simple connect state (4/8): Wait to get fully enabled
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.024578] [src/mm-iface-modem-simple.c:478] connection_step(): Simple connect state (5/8): Register
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.026843] [src/mm-iface-modem-3gpp.c:437] mm_iface_modem_3gpp_register_in_network(): Already registered in network '23410', automatic registration not launched...
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.028145] [src/mm-iface-modem-simple.c:501] connection_step(): Simple connect state (6/8): Bearer
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.029406] [src/mm-iface-modem-simple.c:521] connection_step(): Creating new bearer...
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.030410] [plugins/cinterion/mm-broadband-modem-cinterion.c:1733] cinterion_modem_create_bearer(): skipping ^SWWAN check as no data port is available
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.031342] [plugins/cinterion/mm-broadband-modem-cinterion.c:1671] common_create_bearer(): ^SWWAN not supported, creating default bearer...
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.034868] [src/mm-port-serial.c:1294] mm_port_serial_open(): (ttyMux0) device open count is 2 (open)
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.036067] [src/mm-port-serial.c:1351] _close_internal(): (ttyMux0) device open count is 1 (close)
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.037489] [plugins/cinterion/mm-broadband-modem-cinterion.c:1630] cinterion_modem_create_bearer_finish(): New bearer created at DBus path '/org/freedesktop/ModemManager1/Bearer/0'
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.042393] [src/mm-iface-modem-simple.c:583] connection_step(): Simple connect state (7/8): Connect
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.043586] [src/mm-base-bearer.c:801] mm_base_bearer_connect(): Connecting bearer '/org/freedesktop/ModemManager1/Bearer/0'
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.044690] [src/mm-iface-modem.c:1431] __iface_modem_update_state_internal(): Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.052266] [src/mm-broadband-bearer.c:1342] connect(): Launching 3GPP connection attempt with APN 'mobile.o2.co.uk'
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.054094] [src/mm-broadband-bearer.c:84] select_bearer_ip_family(): No specific IP family requested, defaulting to ipv4
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.055072] [src/mm-broadband-bearer.c:84] select_bearer_ip_family(): No specific IP family requested, defaulting to ipv4
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.056028] [src/mm-broadband-bearer.c:951] cid_selection_3gpp(): Looking for best CID...
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.057001] [src/mm-port-serial.c:1294] mm_port_serial_open(): (ttyMux0) device open count is 2 (open)
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.058199] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): --> 'AT+CGDCONT?'
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.111839] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- '+CGDCONT: 1,"IP","mobile.o2.co.uk","",0,0OK'
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.113404] [src/mm-broadband-bearer.c:867] parse_pdp_list(): Found '1' PDP contexts
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.114400] [src/mm-broadband-bearer.c:876] parse_pdp_list(): PDP context [cid=1] [type='ipv4'] [apn='mobile.o2.co.uk']
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.115352] [src/mm-broadband-bearer.c:901] parse_pdp_list(): Found PDP context with CID 1 and PDP type ipv4 for APN 'mobile.o2.co.uk'
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.116265] [src/mm-port-serial.c:1164] mm_port_serial_open(): (ttyMux1) opening serial port...
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.228678] [src/mm-port-serial.c:1294] mm_port_serial_open(): (ttyMux1) device open count is 1 (open)
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.229838] [src/mm-broadband-bearer.c:222] common_get_at_data_port(): Connection through a plain serial AT port (ttyMux1)
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.230881] [src/mm-port-serial.c:1294] mm_port_serial_open(): (ttyMux1) device open count is 2 (open)
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.232005] [src/mm-port-serial.c:1351] _close_internal(): (ttyMux0) device open count is 1 (close)
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.233118] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): --> 'ATD*99***1#'
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.261200] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- 'ATD*99***1#'
> Mar 7 10:05:16 wg2 daemon.info ModemManager[896]: [1488881116.274786] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- '+CGREG: 2'
> Mar 7 10:05:19 wg2 daemon.info ModemManager[896]: [1488881119.270515] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- '+CGREG: 1'
> Mar 7 10:05:19 wg2 daemon.info ModemManager[896]: [1488881119.778895] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- 'CONNECT~\255}#\192!}!}#} }9}"}&} }*} } }'}"}(}"}%}&_\173\129q}#}%\194#}%},M~'
> Mar 7 10:05:19 wg2 daemon.info ModemManager[896]: [1488881119.780328] [src/mm-port-serial.c:1351] _close_internal(): (ttyMux1) device open count is 1 (close)
> Mar 7 10:05:19 wg2 daemon.info ModemManager[896]: [1488881119.781645] [src/mm-port.c:94] mm_port_set_connected(): (ttyMux1): port now connected
> Mar 7 10:05:19 wg2 daemon.info ModemManager[896]: [1488881119.782764] [src/mm-base-bearer.c:699] connect_ready(): Connected bearer '/org/freedesktop/ModemManager1/Bearer/0'
> Mar 7 10:05:19 wg2 daemon.info ModemManager[896]: [1488881119.784955] [src/mm-iface-modem.c:1431] __iface_modem_update_state_internal(): Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected)
> Mar 7 10:05:19 wg2 daemon.info ModemManager[896]: [1488881119.792374] [src/mm-iface-modem-simple.c:602] connection_step(): Simple connect state (8/8): All done
> Mar 7 10:05:19 wg2 user.info kernel: PPP generic driver version 2.4.2
> Mar 7 10:05:19 wg2 daemon.notice pppd[944]: pppd 2.4.7 started by root, uid 0
> Mar 7 10:05:19 wg2 daemon.debug pppd[944]: using channel 1
> Mar 7 10:05:19 wg2 daemon.info ModemManager[896]: [1488881119.961557] [src/mm-base-manager.c:256] device_added(): (net/ppp0): adding device at sysfs path: /sys/devices/virtual/net/ppp0
> Mar 7 10:05:19 wg2 daemon.info ModemManager[896]: [1488881119.961950] [src/kerneldevice/mm-kernel-device-udev.c:466] kernel_device_is_candidate(): (net/ppp0): could not get port's parent device
> Mar 7 10:05:19 wg2 daemon.info ModemManager[896]: [1488881119.962129] [src/mm-base-manager.c:265] device_added(): (net/ppp0): port not candidate
> Mar 7 10:05:19 wg2 daemon.info pppd[944]: Using interface ppp0
> Mar 7 10:05:19 wg2 daemon.notice pppd[944]: Connect: ppp0 <--> /dev/ttyMux1
> Mar 7 10:05:19 wg2 daemon.debug pppd[944]: sent [LCP ConfReq id=0x1 ]
> Mar 7 10:05:19 wg2 daemon.debug pppd[944]: rcvd [LCP ConfNak id=0x1 ]
> Mar 7 10:05:19 wg2 daemon.debug pppd[944]: sent [LCP ConfReq id=0x2 ]
> Mar 7 10:05:20 wg2 daemon.debug pppd[944]: rcvd [LCP ConfAck id=0x2 ]
> Mar 7 10:05:22 wg2 daemon.debug pppd[944]: rcvd [LCP ConfReq id=0x3 ]
> Mar 7 10:05:22 wg2 daemon.debug pppd[944]: No auth is possible
> Mar 7 10:05:22 wg2 daemon.debug pppd[944]: sent [LCP ConfRej id=0x3 ]
> Mar 7 10:05:22 wg2 daemon.debug pppd[944]: rcvd [LCP ConfReq id=0x5 ]
> Mar 7 10:05:22 wg2 daemon.debug pppd[944]: No auth is possible
> Mar 7 10:05:22 wg2 daemon.debug pppd[944]: sent [LCP ConfRej id=0x5 ]
> Mar 7 10:05:22 wg2 daemon.debug pppd[944]: rcvd [LCP ConfReq id=0x7 ]
> Mar 7 10:05:22 wg2 daemon.debug pppd[944]: sent [LCP ConfAck id=0x7 ]
> Mar 7 10:05:22 wg2 daemon.warn pppd[944]: kernel does not support PPP filtering
> Mar 7 10:05:22 wg2 user.info kernel: PPP BSD Compression module registered
> Mar 7 10:05:22 wg2 daemon.debug pppd[944]: sent [CCP ConfReq id=0x1 <deflate(old#) 15> ]
> Mar 7 10:05:22 wg2 daemon.debug pppd[944]: sent [IPCP ConfReq id=0x1 <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
> Mar 7 10:05:22 wg2 user.info kernel: PPP Deflate Compression module registered
> Mar 7 10:05:22 wg2 daemon.debug pppd[944]: rcvd [LCP ProtRej id=0x8 80 fd 01 01 00 0f 1a 04]
> Mar 7 10:05:22 wg2 daemon.debug pppd[944]: Protocol-Reject for 'Compression Control Protocol' (0x80fd) received
> Mar 7 10:05:25 wg2 daemon.debug pppd[944]: sent [IPCP ConfReq id=0x1 <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
> Mar 7 10:05:25 wg2 daemon.info ModemManager[896]: [1488881125.484324] [src/mm-port-serial.c:1294] mm_port_serial_open(): (ttyMux0) device open count is 2 (open)
> Mar 7 10:05:25 wg2 daemon.info ModemManager[896]: [1488881125.484745] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): --> 'AT+CGACT?'
> Mar 7 10:05:25 wg2 daemon.info ModemManager[896]: [1488881125.513270] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- '+CGACT: 1,0OK'
*HERE*
> Mar 7 10:05:25 wg2 daemon.info ModemManager[896]: [1488881125.514773] [src/mm-base-bearer.c:172] load_connection_status_ready(): connection status loaded: disconnected
> Mar 7 10:05:25 wg2 daemon.info ModemManager[896]: [1488881125.515912] [src/mm-port.c:94] mm_port_set_connected(): (ttyMux1): port now disconnected
> Mar 7 10:05:25 wg2 daemon.info ModemManager[896]: [1488881125.516973] [src/mm-iface-modem.c:1431] __iface_modem_update_state_internal(): Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connected -> registered)
> Mar 7 10:05:25 wg2 daemon.info ModemManager[896]: [1488881125.521936] [src/mm-port-serial.c:1351] _close_internal(): (ttyMux0) device open count is 1 (close)
> Mar 7 10:05:28 wg2 daemon.debug pppd[944]: sent [IPCP ConfReq id=0x1 <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
> Mar 7 10:05:31 wg2 daemon.debug pppd[944]: sent [IPCP ConfReq id=0x1 <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
> Mar 7 10:05:34 wg2 daemon.debug pppd[944]: sent [IPCP ConfReq id=0x1 <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
> Mar 7 10:05:37 wg2 daemon.debug pppd[944]: sent [IPCP ConfReq id=0x1 <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
> Mar 7 10:05:40 wg2 daemon.debug pppd[944]: sent [IPCP ConfReq id=0x1 <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
> Mar 7 10:05:43 wg2 daemon.debug pppd[944]: sent [IPCP ConfReq id=0x1 <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
> Mar 7 10:05:43 wg2 daemon.info ModemManager[896]: [1488881143.488654] [src/mm-port-serial.c:1294] mm_port_serial_open(): (ttyMux0) device open count is 2 (open)
> Mar 7 10:05:43 wg2 daemon.info ModemManager[896]: [1488881143.489017] [src/mm-broadband-modem.c:2077] modem_load_signal_quality(): loading signal quality...
> Mar 7 10:05:43 wg2 daemon.info ModemManager[896]: [1488881143.489234] [src/mm-port-serial.c:1294] mm_port_serial_open(): (ttyMux0) device open count is 3 (open)
> Mar 7 10:05:43 wg2 daemon.info ModemManager[896]: [1488881143.489520] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): --> 'AT^SMONG'
> Mar 7 10:05:43 wg2 daemon.info ModemManager[896]: [1488881143.536387] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- 'GPRS MonitorBCCH G PBC'
> Mar 7 10:05:43 wg2 daemon.info ModemManager[896]: [1488881143.554117] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- 'CH PAT MCC MNC NOM TA RAC # Cell # 40 2 - 4 234 10 2 - 92
> Mar 7 10:05:43 wg2 daemon.info ModemManager[896]: [1488881143.555862] [src/mm-port-serial.c:1351] _close_internal(): (ttyMux0) device open count is 2 (close)
> Mar 7 10:05:43 wg2 daemon.info ModemManager[896]: [1488881143.557052] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): --> 'AT+CIND?'
> Mar 7 10:05:43 wg2 daemon.info ModemManager[896]: [1488881143.585853] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- '+CIND: 5,99,1,0,0,0,0,0,3OK'
> Mar 7 10:05:43 wg2 daemon.info ModemManager[896]: [1488881143.587382] [src/mm-port-serial.c:1294] mm_port_serial_open(): (ttyMux0) device open count is 3 (open)
> Mar 7 10:05:43 wg2 daemon.info ModemManager[896]: [1488881143.588580] [src/mm-port-serial.c:1351] _close_internal(): (ttyMux0) device open count is 2 (close)
> Mar 7 10:05:43 wg2 daemon.info ModemManager[896]: [1488881143.589679] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): --> 'AT+CSQ'
> Mar 7 10:05:43 wg2 daemon.info ModemManager[896]: [1488881143.614250] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- '+CSQ: 22,99OK'
> Mar 7 10:05:43 wg2 daemon.info ModemManager[896]: [1488881143.615634] [src/mm-port-serial.c:1351] _close_internal(): (ttyMux0) device open count is 1 (close)
> Mar 7 10:05:43 wg2 daemon.info ModemManager[896]: [1488881143.617096] [src/mm-iface-modem.c:1204] update_signal_quality(): Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (70)
> Mar 7 10:05:46 wg2 daemon.debug pppd[944]: sent [IPCP ConfReq id=0x1 <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
> Mar 7 10:05:49 wg2 daemon.debug pppd[944]: sent [IPCP ConfReq id=0x1 <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
> Mar 7 10:05:52 wg2 daemon.warn pppd[944]: IPCP: timeout sending Config-Requests
> Mar 7 10:05:52 wg2 daemon.debug pppd[944]: sent [LCP TermReq id=0x3 "No network protocols running"]
> Mar 7 10:05:52 wg2 daemon.debug pppd[944]: rcvd [LCP TermAck id=0x3 "No network protocols running"]
> Mar 7 10:05:52 wg2 daemon.notice pppd[944]: Connection terminated.
> Mar 7 10:05:52 wg2 daemon.info avahi-daemon[865]: Withdrawing workstation service for ppp0.
> Mar 7 10:05:53 wg2 daemon.info pppd[944]: Exit.
> Mar 7 10:05:53 wg2 daemon.info ModemManager[896]: [1488881153.411592] [src/mm-port-serial.c:942] common_input_available(): (ttyMux1) unexpected port hangup!
> Mar 7 10:05:53 wg2 daemon.info ModemManager[896]: [1488881153.411812] [src/mm-port-serial.c:1477] port_serial_close_force(): (ttyMux1) forced to close port
> Mar 7 10:05:53 wg2 daemon.info ModemManager[896]: [1488881153.411933] [src/mm-port-serial.c:1351] _close_internal(): (ttyMux1) device open count is 0 (close)
> Mar 7 10:05:53 wg2 daemon.info ModemManager[896]: [1488881153.412072] [src/mm-port-serial.c:1367] _close_internal(): (ttyMux1) closing serial port...
> Mar 7 10:05:53 wg2 daemon.info ModemManager[896]: [1488881153.423341] [src/mm-port-serial.c:1415] _close_internal(): (ttyMux1) serial port closed
>
> The ppp 'provider' file is
> ttyMux1
> 115200
> lock
> crtscts
> modem
> passive
> novj
> defaultroute
> noipdefault
> usepeerdns
> noauth
> hide-password
> persist
> holdoff 10
> maxfail 1
> debug
>
> _______________________________________________
> ModemManager-devel mailing list
> ModemManager-devel at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
More information about the ModemManager-devel
mailing list