Deal with 'NotOpened' errors?

[Bjørn Mork]

Hello,

I was just doing something I rarel ever do and noticed that MM doesn't
seem to handle NotOpened' errors properly:


ModemManager[18120]: <info>  [1393229894.194487] [mm-iface-modem-simple.c:501] connection_step(): Simple connect state (6/8): Bearer
ModemManager[18120]: <debug> [1393229894.194546] [mm-iface-modem-simple.c:521] connection_step(): Creating new bearer...
ModemManager[18120]: <debug> [1393229894.194596] [mm-iface-modem-simple.c:545] connection_step(): Deleted disconnected bearer at '/org/freedesktop/ModemManager1/Bearer/0'
ModemManager[18120]: <debug> [1393229894.194649] [mm-bearer.c:891] mm_bearer_dbus_unexport(): Removing from DBus bearer at '/org/freedesktop/ModemManager1/Bearer/0'
ModemManager[18120]: <debug> [1393229894.195210] [mm-broadband-modem-mbim.c:1139] modem_create_bearer(): Creating MBIM bearer in MBIM modem
ModemManager[18120]: <debug> [1393229894.195567] [mm-broadband-modem-mbim.c:1053] modem_create_bearer_finish(): New bearer created at DBus path '/org/freedesktop/ModemManager1/Bearer/1'
ModemManager[18120]: <info>  [1393229894.195663] [mm-iface-modem-simple.c:583] connection_step(): Simple connect state (7/8): Connect
ModemManager[18120]: <debug> [1393229894.195730] [mm-bearer.c:586] mm_bearer_connect(): Connecting bearer '/org/freedesktop/ModemManager1/Bearer/1'
ModemManager[18120]: <info>  [1393229894.195804] [mm-iface-modem.c:1203] __iface_modem_update_state_internal(): Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
ModemManager[18120]: <debug> [1393229894.196184] [mm-bearer-mbim.c:834] _connect(): Launching connection with data port (net/wwan0)
ModemManager[18120]: <debug> [1393229894.196840] [mm-bearer-mbim.c:592] connect_context_step(): Activating packet service...
ModemManager[18120]: [/dev/cdc-wdm0] Sent message...
<<<<<< RAW:
<<<<<<   length = 52
<<<<<<   data   = 03:00:00:00:34:00:00:00:1F:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:0A:00:00:00:01:00:00:00:04:00:00:00:00:00:00:00
ModemManager[18120]: [/dev/cdc-wdm0] Sent message (translated)...
<<<<<< Header:
<<<<<<   length      = 52
<<<<<<   type        = command (0x00000003)
<<<<<<   transaction = 31
<<<<<< Fragment header:
<<<<<<   total   = 1
<<<<<<   current = 0
<<<<<< Contents:
<<<<<<   service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
<<<<<<   cid     = 'packet-service' (0x0000000a)
<<<<<<   type    = 'set' (0x00000001)
ModemManager[18120]: [/dev/cdc-wdm0] Received message...
>>>>>> RAW:
>>>>>>   length = 16
>>>>>>   data   = 04:00:00:80:10:00:00:00:1F:00:00:00:05:00:00:00
ModemManager[18120]: [/dev/cdc-wdm0] Received message (translated)...
>>>>>> Header:
>>>>>>   length      = 16
>>>>>>   type        = function-error (0x80000004)
>>>>>>   transaction = 31
>>>>>> Contents:
>>>>>>   error = 'NotOpened' (0x00000005)
ModemManager[18120]: <debug> [1393229924.202840] [mm-bearer.c:461] connect_ready(): Couldn't connect bearer '/org/freedesktop/ModemManager1/Bearer/1': 'Transaction timed out'
ModemManager[18120]: <info>  [1393229924.203077] [mm-iface-modem.c:1203] __iface_modem_update_state_internal(): Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> registered)
ModemManager[18120]: <debug> [1393229924.204387] [mm-iface-modem-simple.c:221] connect_bearer_ready(): Couldn't connect bearer: 'Transaction timed out'


I triggered this by *hibernating* the laptop with MM managing the MC7710
inside.  I have no clue how this actually works, but it seems that the
USB core then restores the USB device to the exact same state on resume
- as seen from the OS.  The only problem is of course that power to the
module was cut, so all internal state in the modem is lost.

I don't blame MM for not catching that the modem was powered off behind
the curtain.  It seems the kernel hides this fact completely for
userspace, which maybe is something we should fix as well?  But I still
think that MM could handle the 'NotOpened' error better....

There doesn't seem to be any other way out of this than restarting MM to
have the modem rediscovered and reinitialized.


This was tested with the Debian experimental/unstable packages so
apoligies if the bug is already fixed in master.  The reported package
versions are:


bjorn at nemi:~$ apt-cache policy libmbim-glib0
libmbim-glib0:
  Installed: 1.6.0-2
  Candidate: 1.6.0-2
  Version table:
 *** 1.6.0-2 0
        600 http://ftp.no.debian.org/debian/ sid/main amd64 Packages
        100 /var/lib/dpkg/status
bjorn at nemi:~$ apt-cache policy modemmanager
modemmanager:
  Installed: 1.0.0-2
  Candidate: 1.0.0-2
  Version table:
 *** 1.0.0-2 0
          1 http://ftp.no.debian.org/debian/ experimental/main amd64 Packages
        100 /var/lib/dpkg/status
     0.5.2.0-2.1 0
        600 http://ftp.no.debian.org/debian/ sid/main amd64 Packages
     0.5.2.0-2 0
        700 http://ftp.no.debian.org/debian/ wheezy/main amd64 Packages




Bjørn