NetworkManager not re-connecting modem connection after hangup

[Cezary Manista <cezary manista onet pl>]

Hi Everyone,

I found following issue:

1. GSM connection is Activated .
2. Modem connection ends being hanged up on the operators side
3. NetworkManager tries to auto-activate the connection but it fails 
with error:

Dec 21 13:43:23 6 1 buzby2-tcm NetworkManager[525]:  <info> 
Auto-activating connection 'GSM'.
Dec 21 13:43:23 6 1 buzby2-tcm NetworkManager[525]:  <info> Activation 
(ttyACM0) starting connection 'GSM'
Dec 21 13:43:23 6 1 buzby2-tcm NetworkManager[525]:  <info> (ttyACM0): 
device state change: disconnected -> prepare (reason 'none') [30 40 0]
Dec 21 13:43:23 6 1 buzby2-tcm NetworkManager[525]:  <info> Activation 
(ttyACM0) Stage 1 of 5 (Device Prepare) scheduled...
Dec 21 13:43:24 6 1 buzby2-tcm NetworkManager[525]:  <info> Activation 
(ttyACM0) Stage 1 of 5 (Device Prepare) started...
Dec 21 13:43:24 6 1 buzby2-tcm NetworkManager[525]:  <info> Activation 
(ttyACM0) Stage 1 of 5 (Device Prepare) complete.
Dec 21 13:43:24 4 1 buzby2-tcm NetworkManager[525]:  <warn> GSM 
connection failed: (32) Sending command failed: device is not enabled
Dec 21 13:43:24 6 1 buzby2-tcm NetworkManager[525]:  <info> (ttyACM0): 
device state change: prepare -> failed (reason 'unknown') [40 120 1]
Dec 21 13:43:24 4 1 buzby2-tcm NetworkManager[525]:  <warn> Activation 
(ttyACM0) failed for connection 'GSM'
Dec 21 13:43:24 6 1 buzby2-tcm NetworkManager[525]:  <info> (ttyACM0): 
device state change: failed -> disconnected (reason 'none') [120 30 0]
Dec 21 13:43:24 6 1 buzby2-tcm NetworkManager[525]:  <info> (ttyACM0): 
deactivating device (reason 'none') [0]

4. This error repeats forever as NetworkManager keeps trying.
5. While connection fails, nmcli d reports device "disconnected" and 
DBus org.freedesktop.ModemManager.Modem State property is "Registered"
6. If I send DBus org.freedesktop.ModemManager.Modem.Disable followed by 
Enable connection will be successfully established.


Here is what happens right after connection is terminated. After "Modem 
hangup" NetworkManager fails to acquire the lock in port_connected 
function:

modem-manager[537]:  port_connected: (ttyACM0) could not re-acquire 
serial port lock: (5) Input/output error

and only after that pppd Exit is logged. See below:


Dec 21 13:43:20 5 3 buzby2-tcm pppd[688]:  Modem hangup
Dec 21 13:43:20 6 3 buzby2-tcm NetworkManager[525]:  Modem hangup
Dec 21 13:43:20 5 3 buzby2-tcm pppd[688]:  Connection terminated.
Dec 21 13:43:20 6 3 buzby2-tcm pppd[688]:  Connect time 36.2 minutes.
Dec 21 13:43:20 6 3 buzby2-tcm pppd[688]:  Sent 96 bytes, received 0 bytes.
Dec 21 13:43:20 6 3 buzby2-tcm NetworkManager[525]:  Connection terminated.
Dec 21 13:43:20 6 3 buzby2-tcm NetworkManager[525]:  Connect time 36.2 
minutes.
Dec 21 13:43:20 6 3 buzby2-tcm NetworkManager[525]:  Sent 96 bytes, 
received 0 bytes.
Dec 21 13:43:20 6 1 buzby2-tcm NetworkManager[525]:  <info> (ttyACM0): 
device state change: activated -> failed (reason 
'ip-config-unavailable') [100 120 5]
Dec 21 13:43:20 4 1 buzby2-tcm NetworkManager[525]:  <warn> Activation 
(ttyACM0) failed for connection 'GSM'
Dec 21 13:43:20 6 3 buzby2-tcm modem-manager[537]:  <info> Modem 
/org/freedesktop/ModemManager/Modems/0: state changed (connected -> 
disconnecting)
Dec 21 13:43:20 6 3 buzby2-tcm dbus-daemon[398]: modem-manager[537]: 
<info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed 
(connected -> disconnecting)
Dec 21 13:43:20 6 3 buzby2-tcm dbus-daemon[398]:  dbus[398]: [system] 
Activating service name='org.freedesktop.nm_dispatcher' (using 
servicehelper)
Dec 21 13:43:20 5 3 buzby2-tcm dbus[398]:  [system] Activating service 
name='org.freedesktop.nm_dispatcher' (using servicehelper)
Dec 21 13:43:20 5 1 buzby2-tcm NetworkManager[525]: SCPlugin-Ifupdown: 
devices removed (path: /sys/devices/virtual/net/ppp0, iface: ppp0)
Dec 21 13:43:20 6 1 buzby2-tcm NetworkManager[525]:  <info> (ttyACM0): 
device state change: failed -> disconnected (reason 'none') [120 30 0]
Dec 21 13:43:20 6 1 buzby2-tcm NetworkManager[525]:  <info> (ttyACM0): 
deactivating device (reason 'none') [0]
Dec 21 13:43:20 4 1 buzby2-tcm NetworkManager[525]:  <warn> could not 
read ppp stats: No such device
Dec 21 13:43:20 6 1 buzby2-tcm NetworkManager[525]:  <info> Policy set 
'lan' (lan1) as default for IPv4 routing and DNS.
Dec 21 13:43:20 5 3 buzby2-tcm dbus[398]:  [system] Successfully 
activated service 'org.freedesktop.nm_dispatcher'
Dec 21 13:43:20 6 3 buzby2-tcm dbus-daemon[398]:  dbus[398]: [system] 
Successfully activated service 'org.freedesktop.nm_dispatcher'
Dec 21 13:43:21 4 3 buzby2-tcm modem-manager[537]:  port_connected: 
(ttyACM0) could not re-acquire serial port lock: (5) Input/output error
Dec 21 13:43:21 6 3 buzby2-tcm dbus-daemon[398]: modem-manager[537]: 
port_connected: (ttyACM0) could not re-acquire serial port lock: (5) 
Input/output error
Dec 21 13:43:21 6 3 buzby2-tcm modem-manager[537]:  <info> (ttyACM0) 
closing serial port...
Dec 21 13:43:21 6 3 buzby2-tcm modem-manager[537]:  <info> (ttyACM0) 
serial port closed
Dec 21 13:43:21 6 3 buzby2-tcm dbus-daemon[398]: modem-manager[537]: 
<info>  (ttyACM0) closing serial port...
Dec 21 13:43:21 6 3 buzby2-tcm dbus-daemon[398]: modem-manager[537]: 
<info>  (ttyACM0) serial port closed
Dec 21 13:43:21 6 3 buzby2-tcm modem-manager[537]:  <info> Modem 
/org/freedesktop/ModemManager/Modems/0: state changed (disconnecting -> 
registered)
Dec 21 13:43:21 3 3 buzby2-tcm modem-manager[537]: mm_serial_port_close: 
assertion 'priv->open_count > 0' failed
Dec 21 13:43:21 6 3 buzby2-tcm dbus-daemon[398]: modem-manager[537]: 
<info>  Modem /org/freedesktop/ModemManager/Modems/0: state changed 
(disconnecting -> registered)
Dec 21 13:43:21 6 3 buzby2-tcm dbus-daemon[398]: modem-manager[537]: 
mm_serial_port_close: assertion 'priv->open_count > 0' failed
Dec 21 13:43:21 6 3 buzby2-tcm pppd[688]:  Exit.

Version of NetworkManager is 0.9.8.0, ModemManager 0.6.2.0
Could it be a bug in NetworkManager? If not could you please suggest 
where else I can look to figure out the root cause?

Best Regards,
Cezary.