PPP port being left open?

Wed Mar 22 13:43:10 UTC 2017

 On Wed, 2017-03-22 at 10:40 +0000, colin.helliwell at ln-systems.com
wrote:
> I've noticed a situation where MM seems to not be fully closing the
> PPP
> port. [1.8 Master, updated probably a couple of days ago]
>   mmcli -m 0 --enable 
>   mmcli -m 0 --simple-connect="apn=......"
>   pppd nodetach call provider
> 
> ModemManager[1292]: <debug> [1490177537.285007] [src/mm-port-
> serial.c:1164]
> mm_port_serial_open(): (ttyMux0) opening serial port...
> ModemManager[1292]: <debug> [1490177537.404522] [src/mm-port-
> serial.c:1294]
> mm_port_serial_open(): (ttyMux0) device open count is 1 (open)
> ModemManager[1292]: <debug> [1490177537.404734]
> [src/mm-broadband-bearer.c:222] common_get_at_data_port(): Connection
> through a plain serial AT port (ttyMux0)
> ModemManager[1292]: <debug> [1490177537.404960] [src/mm-port-
> serial.c:1294]
> mm_port_serial_open(): (ttyMux0) device open count is 2 (open)
> ModemManager[1292]: <debug> [1490177537.405274] [src/mm-port-
> serial.c:1351]
> _close_internal(): (ttyMux1) device open count is 1 (close)
> ModemManager[1292]: <debug> [1490177537.405571]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): -->
> 'ATD*99***1#<CR>'
> ModemManager[1292]: <debug> [1490177537.468957]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <--
> '<CR><LF>+CGREG:
> 2<CR><LF>'
> ModemManager[1292]: <debug> [1490177539.745295]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <--
> '<CR><LF>+CGREG:
> 1<CR><LF>'
> ModemManager[1292]: <debug> [1490177540.246733]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <--
> '<CR><LF>CONNECT<CR><LF>~\255}#\192!}!}#} }9}"}&} }*} }
> }'}"}(}"}%}&\210\231\239\225}#}%\194#}%\157\162~'
> ModemManager[1292]: <debug> [1490177540.247277] [src/mm-port-
> serial.c:1351]
> _close_internal(): (ttyMux0) device open count is 1 (close)
> ModemManager[1292]: <debug> [1490177540.247679] [src/mm-port.c:94]
> mm_port_set_connected(): (ttyMux0): port now connected
> ModemManager[1292]: <debug> [1490177540.247944] [src/mm-base-
> bearer.c:699]
> connect_ready(): Connected bearer
> '/org/freedesktop/ModemManager1/Bearer/0'
> ModemManager[1292]: <info>  [1490177540.249230] [src/mm-iface-
> modem.c:1433]
> __iface_modem_update_state_internal(): Modem
> /org/freedesktop/ModemManager1/Modem/0: state changed (connecting ->
> connected)
> ModemManager[1292]: <info>  [1490177540.259389]
> [src/mm-iface-modem-simple.c:602] connection_step(): Simple connect
> state
> (8/8): All done
> ModemManager[1292]: <debug> [1490177540.747212] [src/mm-base-
> manager.c:263]
> device_added(): (net/ppp0): adding device at sysfs path:
> /sys/devices/virtual/net/ppp0
> ModemManager[1292]: <debug> [1490177540.747801]
> [src/kerneldevice/mm-kernel-device-udev.c:464]
> kernel_device_is_candidate():
> (net/ppp0): could not get port's parent device
> ModemManager[1292]: <debug> [1490177540.748003] [src/mm-base-
> manager.c:272]
> device_added(): (net/ppp0): port not candidate
> 
> ppp is now up
> (I notice above that ttyMux0 - my PPP port - has been opened
> twice..?)

The open is a refcount, basically.  Different parts of the code may
need to "open" the TTY at different times, and they don't know about
each other.  So the they all call mm_serial_port_open() individually,
but internally MM will only open the port the first time; the rest
silently succeed.  The log messages are used for debugging so we can
figure out when stuff doesn't get closed correctly.

So short answer; there is actually only one call to open(2).

> Then 'poff':
> 
> ModemManager[1292]: <debug> [1490177545.518934] [src/mm-base-
> bearer.c:172]
> load_connection_status_ready(): connection status loaded:
> disconnected
> ModemManager[1292]: <debug> [1490177545.519724] [src/mm-port.c:94]
> mm_port_set_connected(): (ttyMux0): port now disconnected
> ModemManager[1292]: <info>  [1490177545.520451] [src/mm-iface-
> modem.c:1433]
> __iface_modem_update_state_internal(): Modem
> /org/freedesktop/ModemManager1/Modem/0: state changed (connected ->
> registered)
> ModemManager[1292]: <debug> [1490177549.735048]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- '<CR><LF>NO
> CARRIER<CR><LF>'
> ModemManager[1292]: <debug> [1490177549.735607]
> [src/mm-serial-parsers.c:364] mm_serial_parser_v1_parse(): Got
> failure code
> 1: No carrier
> 
> 
> But ttyMux0 seem to still be open, and not closed even if with a
> '--simple-disconnect' or '--disable'. Only if MM is closed down
> (Ctrl-C)
> does it close it. Which, by the way, reports

MM won't close the port on disconnect because that's just a packet
data/PPP disconnect, it's not terminating all communication with the
modem.  MM still needs to listen for registration changes, incoming
SMS, etc.

But I think NM should be closing the port on --disable.  Happen to have
logs of when you send --disable?  I don't think the logs below show
that...

Dan

> ModemManager[1292]: <info>  [1490177673.004923] [src/main.c:46]
> quit_cb():
> Caught signal, shutting down...
> ModemManager[1292]: <debug> [1490177673.005207] [src/mm-base-
> manager.c:964]
> set_property(): Stopping connection in object manager server
> ModemManager[1292]: <debug> [1490177673.006949] [src/mm-base-
> bearer.c:1107]
> base_bearer_dbus_unexport(): Removing from DBus bearer at
> '/org/freedesktop/ModemManager1/Bearer/0'
> ModemManager[1292]: <debug> [1490177673.007789] [src/mm-device.c:235]
> unexport_modem(): [device LinMux] unexported modem from path
> '/org/freedesktop/ModemManager1/Modem/0'
> ModemManager[1292]: <debug> [1490177673.011121] [src/mm-port-
> serial.c:1477]
> port_serial_close_force(): (ttyMux0) forced to close port
> ModemManager[1292]: <debug> [1490177673.014613] [src/mm-port-
> serial.c:1351]
> _close_internal(): (ttyMux0) device open count is 0 (close)
> 
> (ModemManager:1292): GLib-GObject-WARNING **:
> /home/colin/fsl-community-bsp/build/tmp/work/cortexa9hf-vfp-neon-
> poky-linux-
> gnueabi/glib-2.0/1_2.44.1-r0/glib-2.44.1/gobject/gsignal.c:2569:
> instance
> '0x8dfb10' has no handler with id '179'
> ModemManager[1292]: <debug> [1490177673.018149] [src/mm-port-
> serial.c:1367]
> _close_internal(): (ttyMux0) closing serial port...
> ModemManager[1292]: <warn>  [1490177673.018964] [src/mm-port-
> serial.c:1380]
> _close_internal(): (ttyMux0): serial port closing_wait was reset!
> ModemManager[1292]: <debug> [1490177684.225739] [src/mm-port-
> serial.c:1415]
> _close_internal(): (ttyMux0) serial port closed
> ModemManager[1292]: <debug> [1490177684.226156] [src/mm-port-
> serial.c:1477]
> port_serial_close_force(): (ttyMux1) forced to close port
> ModemManager[1292]: <info>  [1490177684.233961] [src/main.c:217]
> main():
> ModemManager is shut down
> ModemManager[1292]: <debug> [1490177684.235282] [src/mm-sleep-
> monitor.c:245]
> _singleton_instance_weak_ref_cb(): disposing MMSleepMonitor singleton
> (0x88f6a8)
> ModemManager[1292]: <debug> [1490177684.237513] [src/mm-sleep-
> monitor.c:68]
> drop_inhibitor(): [sleep-monitor] dropping systemd sleep inhibitor
> 
> 
> The glib warning might be relevant/symptomatic to this too?
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> 
> ModemManager[1378]: <debug> [1490178148.379828] [src/mm-port-
> serial.c:1164]
> mm_port_serial_open(): (ttyMux0) opening serial port...
> ModemManager[1378]: <debug> [1490178148.493362] [src/mm-port-
> serial.c:1294]
> mm_port_serial_open(): (ttyMux0) device open count is 1 (open)
> ModemManager[1378]: <debug> [1490178148.493579]
> [src/mm-broadband-bearer.c:222] common_get_at_data_port(): Connection
> through a plain serial AT port (ttyMux0)
> ModemManager[1378]: <debug> [1490178148.493811] [src/mm-port-
> serial.c:1294]
> mm_port_serial_open(): (ttyMux0) device open count is 2 (open)
> ModemManager[1378]: <debug> [1490178148.494127] [src/mm-port-
> serial.c:1351]
> _close_internal(): (ttyMux1) device open count is 1 (close)
> ModemManager[1378]: <debug> [1490178148.494446]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <--
> '<CR><LF>^SYSSTART<CR><LF>'
> ModemManager[1378]: <debug> [1490178148.494773]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): -->
> 'ATD*99***1#<CR>'
> ModemManager[1378]: <debug> [1490178148.519129]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <--
> 'ATD*99***1#'
> ModemManager[1378]: <debug> [1490178148.520406]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- '<CR>'
> ModemManager[1378]: <debug> [1490178148.535255]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <--
> '<CR><LF>CONNECT<CR><LF>'
> ModemManager[1378]: <debug> [1490178148.535791] [src/mm-port-
> serial.c:1351]
> _close_internal(): (ttyMux0) device open count is 1 (close)
> ModemManager[1378]: <debug> [1490178148.536220] [src/mm-port.c:94]
> mm_port_set_connected(): (ttyMux0): port now connected
> ModemManager[1378]: <debug> [1490178148.536493] [src/mm-base-
> bearer.c:699]
> connect_ready(): Connected bearer
> '/org/freedesktop/ModemManager1/Bearer/0'
> ModemManager[1378]: <info>  [1490178148.537799] [src/mm-iface-
> modem.c:1433]
> __iface_modem_update_state_internal(): Modem
> /org/freedesktop/ModemManager1/Modem/0: state changed (connecting ->
> connected)
> ModemManager[1378]: <info>  [1490178148.548068]
> [src/mm-iface-modem-simple.c:602] connection_step(): Simple connect
> state
> (8/8): All done
> ModemManager[1378]: <debug> [1490178149.105414] [src/mm-base-
> manager.c:263]
> device_added(): (net/ppp0): adding device at sysfs path:
> /sys/devices/virtual/net/ppp0
> ModemManager[1378]: <debug> [1490178149.106003]
> [src/kerneldevice/mm-kernel-device-udev.c:464]
> kernel_device_is_candidate():
> (net/ppp0): could not get port's parent device
> ModemManager[1378]: <debug> [1490178149.106213] [src/mm-base-
> manager.c:272]
> device_added(): (net/ppp0): port not candidate
> ModemManager[1378]: <debug> [1490178153.778547] [src/mm-port-
> serial.c:1294]
> mm_port_serial_open(): (ttyMux1) device open count is 2 (open)
> ModemManager[1378]: <debug> [1490178153.778994]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): -->
> 'AT+CGACT?<CR>'
> ModemManager[1378]: <debug> [1490178153.809025]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <--
> '<CR><LF>+CGACT:
> 1,1<CR><LF><CR><LF>+CGACT: 2,0<CR><LF>'
> ModemManager[1378]: <debug> [1490178153.814649]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <--
> '<CR><LF>OK<CR><LF>'
> ModemManager[1378]: <debug> [1490178153.815402] [src/mm-base-
> bearer.c:172]
> load_connection_status_ready(): connection status loaded: connected
> ModemManager[1378]: <debug> [1490178153.815620] [src/mm-port-
> serial.c:1351]
> _close_internal(): (ttyMux1) device open count is 1 (close)
> ModemManager[1378]: <debug> [1490178156.236715]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <--
> '<CR><LF>+CREG:
> 1,"037C","0288FCD5",6<CR><LF>'
> ModemManager[1378]: <debug> [1490178156.237256]
> [src/mm-iface-modem-location.c:297] notify_3gpp_location_update():
> Modem
> /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC:
> '0',
> MNC: '0', Location area code: '37C', Cell ID: '288FCD5')
> ModemManager[1378]: <debug> [1490178158.776575] [src/mm-port-
> serial.c:1294]
> mm_port_serial_open(): (ttyMux1) device open count is 2 (open)
> ModemManager[1378]: <debug> [1490178158.777012]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): -->
> 'AT+CGACT?<CR>'
> ModemManager[1378]: <debug> [1490178158.807114]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <--
> '<CR><LF>+CGACT:
> 1,1<CR><LF><CR><LF>+CGACT: 2,0<CR><LF>'
> ModemManager[1378]: <debug> [1490178158.812919]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <--
> '<CR><LF>OK<CR><LF>'
> ModemManager[1378]: <debug> [1490178158.813765] [src/mm-base-
> bearer.c:172]
> load_connection_status_ready(): connection status loaded: connected
> ModemManager[1378]: <debug> [1490178158.813989] [src/mm-port-
> serial.c:1351]
> _close_internal(): (ttyMux1) device open count is 1 (close)
> ModemManager[1378]: <debug> [1490178163.776023] [src/mm-port-
> serial.c:1294]
> mm_port_serial_open(): (ttyMux1) device open count is 2 (open)
> ModemManager[1378]: <debug> [1490178163.776471]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): -->
> 'AT+CGACT?<CR>'
> ModemManager[1378]: <debug> [1490178163.804787]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <--
> '<CR><LF>+CGACT:
> 1,0<CR><LF><CR><LF>+CGACT: 2,0<CR><LF>'
> ModemManager[1378]: <debug> [1490178163.809051]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <--
> '<CR><LF>OK<CR><LF>'
> ModemManager[1378]: <debug> [1490178163.809793] [src/mm-base-
> bearer.c:172]
> load_connection_status_ready(): connection status loaded:
> disconnected
> ModemManager[1378]: <debug> [1490178163.810074] [src/mm-port.c:94]
> mm_port_set_connected(): (ttyMux0): port now disconnected
> ModemManager[1378]: <info>  [1490178163.810338] [src/mm-iface-
> modem.c:1433]
> __iface_modem_update_state_internal(): Modem
> /org/freedesktop/ModemManager1/Modem/0: state changed (connected ->
> registered)
> ModemManager[1378]: <debug> [1490178163.817504] [src/mm-port-
> serial.c:1351]
> _close_internal(): (ttyMux1) device open count is 1 (close)
> ModemManager[1378]: <debug> [1490178163.818451]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- '<CR><LF>NO
> CARRIER<CR><LF>'
> ModemManager[1378]: <debug> [1490178163.819389]
> [src/mm-serial-parsers.c:364] mm_serial_parser_v1_parse(): Got
> failure code
> 1: No carrier
> ModemManager[1378]: <debug> [1490178168.778530]
> [src/mm-broadband-modem.c:2077] modem_load_signal_quality(): loading
> signal
> quality...
> ModemManager[1378]: <debug> [1490178168.778898] [src/mm-port-
> serial.c:1294]
> mm_port_serial_open(): (ttyMux1) device open count is 2 (open)
> ModemManager[1378]: <debug> [1490178168.779241]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): -->
> 'AT+CSQ<CR>'
> ModemManager[1378]: <debug> [1490178168.801311]
> [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <--
> '<CR><LF>+CSQ:
> 11,99<CR><LF>'
> 
> 
> ModemManager[1378]: <info>  [1490178254.243613] [src/main.c:46]
> quit_cb():
> Caught signal, shutting down...
> ModemManager[1378]: <debug> [1490178254.243893] [src/mm-base-
> manager.c:964]
> set_property(): Stopping connection in object manager server
> ModemManager[1378]: <debug> [1490178254.245667] [src/mm-base-
> bearer.c:1107]
> base_bearer_dbus_unexport(): Removing from DBus bearer at
> '/org/freedesktop/ModemManager1/Bearer/0'
> ModemManager[1378]: <debug> [1490178254.246502] [src/mm-device.c:235]
> unexport_modem(): [device LinMux] unexported modem from path
> '/org/freedesktop/ModemManager1/Modem/0'
> ModemManager[1378]: <debug> [1490178254.250091] [src/mm-port-
> serial.c:1477]
> port_serial_close_force(): (ttyMux0) forced to close port
> ModemManager[1378]: <debug> [1490178254.255331] [src/mm-port-
> serial.c:1351]
> _close_internal(): (ttyMux0) device open count is 0 (close)
> 
> (ModemManager:1378): GLib-GObject-WARNING **:
> /home/colin/100051-karo/fsl-community-bsp/build/tmp/work/cortexa9hf-
> vfp-neon
> -poky-linux-gnueabi/glib-2.0/1_2.44.1-r0/glib-
> 2.44.1/gobject/gsignal.c:2569:
> instance '0xb80b10' has no handler with id '198'
> ModemManager[1378]: <debug> [1490178254.257000] [src/mm-port-
> serial.c:1367]
> _close_internal(): (ttyMux0) closing serial port...
> ModemManager[1378]: <warn>  [1490178254.257799] [src/mm-port-
> serial.c:1380]
> _close_internal(): (ttyMux0): serial port closing_wait was reset!
> ModemManager[1378]: <debug> [1490178271.796882] [src/mm-port-
> serial.c:1415]
> _close_internal(): (ttyMux0) serial port closed
> ModemManager[1378]: <debug> [1490178271.797305] [src/mm-port-
> serial.c:1477]
> port_serial_close_force(): (ttyMux1) forced to close port
> ModemManager[1378]: <info>  [1490178271.807524] [src/main.c:217]
> main():
> ModemManager is shut down
> ModemManager[1378]: <debug> [1490178271.810965] [src/mm-sleep-
> monitor.c:245]
> _singleton_instance_weak_ref_cb(): disposing MMSleepMonitor singleton
> (0xaee6a8)
> ModemManager[1378]: <debug> [1490178271.811707] [src/mm-sleep-
> monitor.c:68]
> drop_inhibitor(): [sleep-monitor] dropping systemd sleep inhibitor
> 
> _______________________________________________
> ModemManager-devel mailing list
> ModemManager-devel at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel