On Wed, 2017-03-22 at 10:40 +0000, [email protected] 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 > [email protected] > https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel _______________________________________________ ModemManager-devel mailing list [email protected] https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
