GNOME.org
 

Re: NetworkManager not re-connecting modem connection after hangup

Hey,

On 22/12/15 15:45, Cezary Manista wrote:

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?


This looks like an issue in ModemManager/NM/pppd interaction; I believe
I fixed some issue which was giving results like those in NetworkManager
some time ago. You're using a very old version of both components,
though, latest stable release of ModemManager is 1.4.12 and we don't
really support 0.6.x any more...

-- 
Aleksander
https://aleksander.es
[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]