PPP port being left open?

[Aleksander Morgado]

On Wed, Mar 22, 2017 at 11:40 AM,  <colin.helliwell at ln-systems.com> wrote:
> 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..?)
>

MM opens it once, pppd opens it again, I assume?

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

Ok, so it looks like the connection monitoring logic detects that it
has been disconnected (through the 'poff', I assume) and flags the
modem as disconnected. BUT, the ttyMux0 isn't closed explicitly at
that moment, which is a bug. If the connection monitoring logic wasn't
in place, MM would have required an explicit bearer disconnect (e.g.
through --simple-disconnect) and in that case, it's very likely that
the data port would have been closed (although we'll have to validate
that as well).

So, yes, we need to fix this.

-- 
Aleksander
https://aleksander.es