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 _______________________________________________ networkmanager-list mailing list networkmanager-list@gnome.org https://mail.gnome.org/mailman/listinfo/networkmanager-list
