PPP port being left open?

Wed Mar 22 14:31:18 UTC 2017

> On 22 March 2017 at 13:43 Dan Williams <dcbw at redhat.com> wrote:
> 
> 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
> > 
...
> > 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':
...
> > 
> > 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.
> 

Ok, though I also have the 'primary' port available for such things (and, indeed, still continuing to be correctly used to refresh signal quality prior to the --disable)

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

Not the same run, but should be equivalent - certainly the same symptoms.
(The reason I spot it is that my mux driver powers-down the modem when its last file handle is closed. That happens with just a enable/disable, but not if the ppp is fired up in between)

ModemManager[1812]: <info>  [1490192786.992418] [src/mm-iface-modem.c:1433] __iface_modem_update_state_internal(): Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> disabling)
ModemManager[1812]: <debug> [1490192786.994668] [src/mm-iface-modem.c:1206] update_signal_quality(): Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (0)
ModemManager[1812]: <debug> [1490192786.994871] [src/mm-iface-modem.c:1323] periodic_signal_quality_check_disable(): Periodic signal quality checks disabled
ModemManager[1812]: <debug> [1490192786.995236] [src/mm-iface-modem.c:935] mm_iface_modem_update_access_technologies(): Modem /org/freedesktop/ModemManager1/Modem/0: access technology changed (hsdpa, hsupa -> unknown)
ModemManager[1812]: <debug> [1490192786.995413] [src/mm-iface-modem.c:1049] periodic_access_technologies_check_disable(): Periodic access technology checks disabled
ModemManager[1812]: <debug> [1490192786.996454] [src/mm-broadband-modem.c:9153] disabling_step(): Modem has time capabilities, disabling the Time interface...
ModemManager[1812]: <debug> [1490192786.996780] [src/mm-broadband-modem.c:9165] disabling_step(): Modem has messaging capabilities, disabling the Messaging interface...
ModemManager[1812]: <debug> [1490192786.997119] [src/mm-broadband-modem.c:5949] set_messaging_unsolicited_events_handlers(): (ttyMux1) Removing messaging unsolicited events handlers
ModemManager[1812]: <debug> [1490192786.997924] [src/mm-broadband-modem.c:9177] disabling_step(): Modem has voice capabilities, disabling the Voice interface...
ModemManager[1812]: <debug> [1490192786.998304] [src/mm-broadband-modem.c:6586] set_voice_unsolicited_events_handlers(): (ttyMux1) Removing voice unsolicited events handlers
ModemManager[1812]: <debug> [1490192786.998814] [src/mm-broadband-modem.c:9189] disabling_step(): Modem has location capabilities, disabling the Location interface...
ModemManager[1812]: <debug> [1490192786.999044] [src/mm-iface-modem-location.c:768] setup_gathering(): Need to disable the following location sources: '3gpp-lac-ci'
ModemManager[1812]: <debug> [1490192787.019756] [src/mm-broadband-modem.c:9217] disabling_step(): Modem has 3GPP/USSD capabilities, disabling the Modem 3GPP/USSD interface...
ModemManager[1812]: <debug> [1490192787.020794] [src/mm-port-serial.c:1294] mm_port_serial_open(): (ttyMux1) device open count is 2 (open)
ModemManager[1812]: <debug> [1490192787.021779] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): --> 'AT+CUSD=0<CR>'
ModemManager[1812]: <debug> [1490192787.058624] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- '<CR><LF>OK<CR><LF>'
ModemManager[1812]: <debug> [1490192787.059210] [src/mm-broadband-modem.c:4981] set_unsolicited_result_code_handlers(): (ttyMux1) Removing unsolicited result code handlers
ModemManager[1812]: <debug> [1490192787.059454] [src/mm-port-serial.c:1351] _close_internal(): (ttyMux1) device open count is 1 (close)
ModemManager[1812]: <debug> [1490192787.063545] [src/mm-broadband-modem.c:9229] disabling_step(): Modem has 3GPP capabilities, disabling the Modem 3GPP interface...
ModemManager[1812]: <debug> [1490192787.064360] [src/mm-iface-modem-3gpp.c:1353] periodic_registration_check_disable(): Periodic 3GPP registration checks disabled
ModemManager[1812]: <debug> [1490192787.065240] [src/mm-port-serial.c:1294] mm_port_serial_open(): (ttyMux1) device open count is 2 (open)
ModemManager[1812]: <debug> [1490192787.069309] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): --> 'AT+CREG=0<CR>'
ModemManager[1812]: <debug> [1490192787.093379] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- '<CR><LF>OK<CR><LF>'
ModemManager[1812]: <debug> [1490192787.093942] [src/mm-port-serial.c:1294] mm_port_serial_open(): (ttyMux1) device open count is 3 (open)
ModemManager[1812]: <debug> [1490192787.094241] [src/mm-port-serial.c:1351] _close_internal(): (ttyMux1) device open count is 2 (close)
ModemManager[1812]: <debug> [1490192787.094509] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): --> 'AT+CGREG=0<CR>'
ModemManager[1812]: <debug> [1490192787.124256] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- '<CR><LF>OK<CR><LF>'
ModemManager[1812]: <debug> [1490192787.124784] [src/mm-port-serial.c:1351] _close_internal(): (ttyMux1) device open count is 1 (close)
ModemManager[1812]: <debug> [1490192787.126310] [src/mm-broadband-modem.c:3721] modem_3gpp_cleanup_unsolicited_registration_events(): (ttyMux1) cleaning up unsolicited registration messages handlers
ModemManager[1812]: <debug> [1490192787.126777] [src/mm-broadband-modem.c:2591] set_unsolicited_events_handlers(): (ttyMux1) Removing 3GPP unsolicited events handlers
ModemManager[1812]: <debug> [1490192787.127148] [src/mm-port-serial.c:1294] mm_port_serial_open(): (ttyMux1) device open count is 2 (open)
ModemManager[1812]: <debug> [1490192787.127491] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): --> 'AT+CMER=0<CR>'
ModemManager[1812]: <debug> [1490192787.156726] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux1): <-- '<CR><LF>OK<CR><LF>'
ModemManager[1812]: <info>  [1490192787.157256] [src/mm-iface-modem-3gpp.c:1212] update_registration_state(): Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (home -> unknown)
ModemManager[1812]: <debug> [1490192787.158205] [src/mm-base-bearer.c:471] modem_3gpp_registration_state_changed(): Bearer not allowed to connect, not registered in 3GPP network
ModemManager[1812]: <debug> [1490192787.158529] [src/mm-port-serial.c:1351] _close_internal(): (ttyMux1) device open count is 1 (close)
ModemManager[1812]: <debug> [1490192787.163083] [src/mm-port-serial.c:1351] _close_internal(): (ttyMux1) device open count is 0 (close)
ModemManager[1812]: <debug> [1490192787.165971] [src/mm-port-serial.c:1367] _close_internal(): (ttyMux1) closing serial port...
ModemManager[1812]: <warn>  [1490192787.166609] [src/mm-port-serial.c:1380] _close_internal(): (ttyMux1): serial port closing_wait was reset!
ModemManager[1812]: <debug> [1490192787.171512] [src/mm-port-serial.c:1415] _close_internal(): (ttyMux1) serial port closed
ModemManager[1812]: <info>  [1490192787.171796] [src/mm-iface-modem.c:1433] __iface_modem_update_state_internal(): Modem /org/freedesktop/ModemManager1/Modem/0: state changed (disabling -> disabled)