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

[Dan Williams <dcbw redhat com>]

On Wed, 2012-08-29 at 16:22 +0200, Aleksander Morgado wrote:
> 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.

Actually, the decision to go back to "connected" was conscious, since if
we fail to disconnect, we're not entirely sure we're disconnected, and
thus we may still be charging the user $$ because we're actually
connected.  Though if the port disappears due to a firmware crash, then
likely we are disconnected, so that could be considered a bug.
Unfortunately even if we fixed that bug, and reverted to disconnected
state, you wouldn't be able to use the modem again because it has no
data port anymore.

Dan

> 
> 
> > 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]
> 
> 
>