Re: 3G Modem disconnect goes to unavailable rather than disconnected

[Aleksander Morgado <aleksander lanedo com>]

On 08/28/2012 07:36 PM, Tristan Stevens wrote:
> I'm now running 0.5.999 as downloaded
> from https://launchpad.net/ubuntu/quantal/amd64/modemmanager however am
> still seeing the same problem. Logs below:
> 


> Aug 28 18:27:33 hostname-1 modem-manager[1065]: <debug>
> [mm-modem-huawei-gsm.c:712] handle_status_change(): Duration: 422 Up: 0
> Kbps Down: 0 Kbps Total: 340 Total: 2102#012
> Aug 28 18:27:34 hostname-1 modem-manager[1065]: <debug>
> [mm-at-serial-port.c:334] debug_log(): (ttyUSB2): <--
> '<CR><LF>^RSSI:0<CR><LF>'
> Aug 28 18:27:34 hostname-1 pppd[2624]: LCP terminated by peer
> Aug 28 18:27:34 hostname-1 pppd[2624]: Connect time 7.1 minutes.
> Aug 28 18:27:34 hostname-1 pppd[2624]: Sent 352002 bytes, received
> 2152602 bytes.
> Aug 28 18:27:34 hostname-1 NetworkManager[1093]: <debug>
> [1346174854.889072] [nm-netlink-monitor.c:163] link_msg_handler():
> netlink link message: iface idx 4 flags 0x1090
> Aug 28 18:27:34 hostname-1 pppd[2624]: Modem hangup
> Aug 28 18:27:34 hostname-1 pppd[2624]: Connection terminated.
> Aug 28 18:27:34 hostname-1 avahi-daemon[1059]: Withdrawing workstation
> service for ppp0.
> Aug 28 18:27:34 hostname-1 NetworkManager[1093]: <debug>
> [1346174854.898506] [nm-netlink-monitor.c:163] link_msg_handler():
> netlink link message: iface idx 4 flags 0x1090
> Aug 28 18:27:34 hostname-1 NetworkManager[1093]: <info> (ttyUSB0):
> device state change: activated -> failed (reason
> 'ip-config-unavailable') [100 120 5]
> Aug 28 18:27:34 hostname-1 modem-manager[1065]: <debug>
> [mm-serial-port.c:697] data_available(): (ttyUSB0) unexpected port hangup!

When we get a HUP in the port we mark it as disconnected and fully
closed (open count == 0). This is as if ttyUSB0 disappeared when you get
the disconnection, but it doesn't really disappear, we may just need to
re-open the port again.



> Aug 28 18:27:34 hostname-1 modem-manager[1065]: <debug>
> [mm-serial-port.c:908] mm_serial_port_close(): (ttyUSB0) device open
> count is 0 (close)
> Aug 28 18:27:34 hostname-1 modem-manager[1065]: <info>
>  [mm-serial-port.c:923] mm_serial_port_close(): (ttyUSB0) closing serial
> port...
> Aug 28 18:27:34 hostname-1 modem-manager[1065]: <debug> [mm-port.c:181]
> mm_port_set_connected(): (ttyUSB0): port now disconnected
> Aug 28 18:27:34 hostname-1 modem-manager[1065]: <info>
>  [mm-serial-port.c:944] mm_serial_port_close(): (ttyUSB0) serial port closed
> Aug 28 18:27:34 hostname-1 NetworkManager[1093]: <warn> Activation
> (ttyUSB0) failed.
> Aug 28 18:27:34 hostname-1 NetworkManager[1093]: <debug>
> [1346174854.916596] [nm-device.c:4406] nm_device_queue_state():
> (ttyUSB0): queued state change to disconnected (id 146)
> Aug 28 18:27:34 hostname-1 modem-manager[1065]: <info>  [mm-modem.c:759]
> mm_modem_set_state(): Modem /org/freedesktop/ModemManager/Modems/0:
> state changed (connected -> disconnecting)
> Aug 28 18:27:34 hostname-1 NetworkManager[1093]:    SCPlugin-Ifupdown:
> devices removed (path: /sys/devices/virtual/net/ppp0, iface: ppp0)
> Aug 28 18:27:34 hostname-1 modem-manager[1065]: <info>  [mm-modem.c:759]
> mm_modem_set_state(): Modem /org/freedesktop/ModemManager/Modems/0:
> state changed (disconnecting -> connected)

When the disconnection sequence fails the state goes back to connected;
which is wrong in this case. It should really go to 'disconnected' at least.



> Aug 28 18:27:34 hostname-1 NetworkManager[1093]: <debug>
> [1346174854.918252] [nm-udev-manager.c:476] handle_uevent(): UDEV event:
> action 'remove' subsys 'net' device 'ppp0'
> Aug 28 18:27:34 hostname-1 modem-manager[1065]: mm_serial_port_close:
> assertion `priv->open_count > 0' failed

This error is due to the forced close after the HUP.


> Aug 28 18:27:34 hostname-1 NetworkManager[1093]: <info> (ttyUSB0): now
> unmanaged
> Aug 28 18:27:34 hostname-1 NetworkManager[1093]: <info> (ttyUSB0):
> device state change: failed -> unmanaged (reason 'removed') [120 10 36]
> Aug 28 18:27:34 hostname-1 NetworkManager[1093]: <debug>
> [1346174854.918386] [nm-device.c:2891] queued_state_clear(): (ttyUSB0):
> clearing queued state transition (id 146)
> Aug 28 18:27:34 hostname-1 NetworkManager[1093]: <info> (ttyUSB0):
> deactivating device (reason 'removed') [36]
> Aug 28 18:27:34 hostname-1 dbus[1007]: [system] Activating service
> name='org.freedesktop.nm_dispatcher' (using servicehelper)
> Aug 28 18:27:34 hostname-1 NetworkManager[1093]: <debug>
> [1346174854.918432] [nm-firewall-manager.c:157]



-- 
Aleksander