PPP port being left open?

Wed Mar 22 10:40:49 UTC 2017

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..?)

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

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