Re: [MM] 'qmi-support' branch merged to git master

[Bjørn Mork <bjorn mork no>]

Aleksander Morgado <aleksander lanedo com> writes:

> Thanks for the extended info. I pushed a fix to libqmi, can you test it
> and tell me if that was enough?


Looks good:


ModemManager[5338]: <info>  [1346593697.368688] [mm-manager.c:340] device_removed(): (tty/ttyUSB1): released by modem /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-4
ModemManager[5338]: <info>  [1346593697.373103] [mm-manager.c:340] device_removed(): (net/wwan0): released by modem /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-4
ModemManager[5338]: [/dev/cdc-wdm0] unexpected port hangup!
ModemManager[5338]: <info>  [1346593697.375106] [mm-manager.c:340] device_removed(): (usbmisc/cdc-wdm0): released by modem /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-4
ModemManager[5338]: <info>  [1346593697.377974] [mm-manager.c:340] device_removed(): (tty/ttyUSB0): released by modem /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-4
ModemManager[5338]: <info>  [1346593697.382929] [mm-manager.c:340] device_removed(): (net/wwan1): released by modem /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-4
ModemManager[5338]: <info>  [1346593697.384666] [mm-manager.c:340] device_removed(): (tty/ttyUSB2): released by modem /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-4
ModemManager[5338]: <info>  [1346593697.398750] [mm-manager.c:340] device_removed(): (usbmisc/cdc-wdm1): released by modem /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-4
ModemManager[5338]: <info>  [1346593697.411489] [mm-manager.c:340] device_removed(): (net/wwan2): released by modem /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-4
ModemManager[5338]: <info>  [1346593697.414893] [mm-manager.c:340] device_removed(): (usbmisc/cdc-wdm2): released by modem /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-4
ModemManager[5338]: <debug> [1346593697.414950] [mm-manager.c:345] device_removed(): Removing empty device '/sys/devices/pci0000:00/0000:00:1d.7/usb2/2-4'
ModemManager[5338]: <debug> [1346593697.415299] [mm-device.c:343] unexport_modem(): Unexported modem '/sys/devices/pci0000:00/0000:00:1d.7/usb2/2-4' from path '/org/freedesktop/ModemManager1/Modem/0'
ModemManager[5338]: <info>  [1346593697.415522] [mm-serial-port.c:1074] mm_serial_port_close_force(): (ttyUSB0) forced to close port
ModemManager[5338]: <info>  [1346593697.415558] [mm-serial-port.c:1074] mm_serial_port_close_force(): (ttyUSB2) forced to close port
ModemManager[5338]: [/dev/cdc-wdm0] QMI client for service 'dms' with CID '1' wasn't released
ModemManager[5338]: [/dev/cdc-wdm0] QMI client for service 'nas' with CID '1' wasn't released
ModemManager[5338]: <debug> [1346593697.415684] [mm-base-modem.c:1195] finalize(): Modem (Gobi) '/sys/devices/pci0000:00/0000:00:1d.7/usb2/2-4' completely disposed



But it failed once when re-discovering the modem after reconnecting.
Cannot repeat it, so I don't know exactly how this was triggered...
Possibly related to the non-functional /dev/cdc-wdm2 port? (which is my
fault and as expected - but I assume MM should deal with it anyway):



ModemManager[4941]: KEY: 07:00:00:00:00:00:00:00
ModemManager[4941]:   Service: 00
ModemManager[4941]:   Client ID: 00
ModemManager[4941]:   Transaction ID: 07:00
ModemManager[4941]: [/dev/cdc-wdm2] Sending message...
<<<<<< QMUX:
<<<<<<   length  = 11
<<<<<<   flags   = 0x00
<<<<<<   service = "ctl"
<<<<<<   client  = 0
<<<<<< QMI:
<<<<<<   flags       = "none"
<<<<<<   transaction = 8
<<<<<<   tlv_length  = 0
<<<<<<   message     = "Get Version Info" (0x0021)
ModemManager[4941]: KEY: 08:00:00:00:00:00:00:00
ModemManager[4941]:   Service: 00
ModemManager[4941]:   Client ID: 00
ModemManager[4941]:   Transaction ID: 08:00
ModemManager[4941]: [/dev/cdc-wdm2] Sending message...
<<<<<< QMUX:
<<<<<<   length  = 11
<<<<<<   flags   = 0x00
<<<<<<   service = "ctl"
<<<<<<   client  = 0
<<<<<< QMI:
<<<<<<   flags       = "none"
<<<<<<   transaction = 9
<<<<<<   tlv_length  = 0
<<<<<<   message     = "Get Version Info" (0x0021)
ModemManager[4941]: KEY: 09:00:00:00:00:00:00:00
ModemManager[4941]:   Service: 00
ModemManager[4941]:   Client ID: 00
ModemManager[4941]:   Transaction ID: 09:00
ModemManager[4941]: [/dev/cdc-wdm2] Sending message...
<<<<<< QMUX:
<<<<<<   length  = 11
<<<<<<   flags   = 0x00
<<<<<<   service = "ctl"
<<<<<<   client  = 0
<<<<<< QMI:
<<<<<<   flags       = "none"
<<<<<<   transaction = 10
<<<<<<   tlv_length  = 0
<<<<<<   message     = "Get Version Info" (0x0021)
ModemManager[4941]: KEY: 0A:00:00:00:00:00:00:00
ModemManager[4941]:   Service: 00
ModemManager[4941]:   Client ID: 00
ModemManager[4941]:   Transaction ID: 0A:00
ModemManager[4941]: <warn>  [1346593549.302696] [mm-broadband-modem.c:7095] initialization_started_ready(): Couldn't start initialization: Transaction timed out
ModemManager[4941]: <info>  [1346593549.302828] [mm-iface-modem.c:993] mm_iface_modem_update_state(): Modem: state changed (initializing -> failed)

Program received signal SIGSEGV, Segmentation fault.
ports_context_unref (ctx=0x0) at mm-broadband-modem.c:6113
6113        if (g_atomic_int_dec_and_test (&ctx->ref_count)) {
(gdb) bt full
#0  ports_context_unref (ctx=0x0) at mm-broadband-modem.c:6113
No locals.
#1  0x0000000000457abc in initialization_stopped (self=<optimized out>, user_data=<optimized out>, error=<optimized out>) at mm-broadband-modem.c:6143
        ctx = <optimized out>
#2  0x000000000044f627 in initialize_context_complete_and_free (ctx=0x753820) at mm-broadband-modem.c:7049
        error = 0x0
        __PRETTY_FUNCTION__ = "initialize_context_complete_and_free"
#3  0x000000000045915c in initialization_started_ready (self=0x726280, result=<optimized out>, ctx=0x753820) at mm-broadband-modem.c:7104
        error = 0x72ccb0
        ports_ctx = <optimized out>
        __PRETTY_FUNCTION__ = "initialization_started_ready"
#4  0x00007ffff6f7d3f7 in g_simple_async_result_complete (simple=0x710990) at /tmp/buildd/glib2.0-2.32.3/./gio/gsimpleasyncresult.c:767
        current_source = 0x757b20
        current_context = 0x457ab0
        __PRETTY_FUNCTION__ = "g_simple_async_result_complete"
#5  0x00007ffff6f7d4f9 in complete_in_idle_cb (data=<optimized out>) at /tmp/buildd/glib2.0-2.32.3/./gio/gsimpleasyncresult.c:779
        simple = <optimized out>
#6  0x00007ffff6a10205 in g_main_dispatch (context=0x6bf4f0) at /tmp/buildd/glib2.0-2.32.3/./glib/gmain.c:2539
        dispatch = 0x7ffff6a0df20 <g_idle_dispatch>
        was_in_call = 0
        user_data = 0x710990
        callback = 0x7ffff6f7d4f0 <complete_in_idle_cb>
        cb_funcs = 0x7ffff6cbb980
        cb_data = 0x749860
        current_source_link = {data = 0x757b20, next = 0x0}
        need_destroy = <optimized out>
        source = 0x757b20
        current = 0x6c7400
        i = <optimized out>
#7  g_main_context_dispatch (context=context@entry=0x6bf4f0) at /tmp/buildd/glib2.0-2.32.3/./glib/gmain.c:3075
No locals.
#8  0x00007ffff6a10538 in g_main_context_iterate (context=0x6bf4f0, block=block@entry=1, dispatch=dispatch@entry=1, self=<error reading variable: Unhandled dwarf expression opcode 0xfa>)
    at /tmp/buildd/glib2.0-2.32.3/./glib/gmain.c:3146
        max_priority = 0
        timeout = 0
        some_ready = 1
        nfds = <optimized out>
        allocated_nfds = <optimized out>
        fds = 0x71f5f0
#9  0x00007ffff6a10932 in g_main_loop_run (loop=0x6c9f30) at /tmp/buildd/glib2.0-2.32.3/./glib/gmain.c:3340
        __PRETTY_FUNCTION__ = "g_main_loop_run"
#10 0x0000000000420cf7 in main (argc=<optimized out>, argv=<optimized out>) at main.c:150
        bus = 0x6bf810
        err = 0x0
        name_id = 1
        __PRETTY_FUNCTION__ = "main"





OK, I managed to repeat the crash once more by disconnecting before the
modem was full discovered.  Backtrace is identical:



ModemManager[5338]: <info>  [1346593994.354608] [mm-iface-modem.c:993] mm_iface_modem_update_state(): Modem: state changed (unknown -> initializing)
ModemManager[5338]: <info>  [1346593994.357028] [mm-manager.c:149] find_device_support_ready(): Modem for device at '/sys/devices/pci0000:00/0000:00:1d.7/usb2/2-4' successfully created
ModemManager[5338]: <warn>  [1346593994.357579] [mm-broadband-modem.c:7095] initialization_started_ready(): Couldn't start initialization: Cannot open QMI device: Cannot open device file '/dev/cdc-wdm0': No such device
ModemManager[5338]: <info>  [1346593994.357850] [mm-iface-modem.c:993] mm_iface_modem_update_state(): Modem: state changed (initializing -> failed)

Program received signal SIGSEGV, Segmentation fault.
ports_context_unref (ctx=0x0) at mm-broadband-modem.c:6113
6113        if (g_atomic_int_dec_and_test (&ctx->ref_count)) {
(gdb) 
(gdb) bt full
#0  ports_context_unref (ctx=0x0) at mm-broadband-modem.c:6113
No locals.
#1  0x0000000000457abc in initialization_stopped (self=<optimized out>, user_data=<optimized out>, error=<optimized out>) at mm-broadband-modem.c:6143
        ctx = <optimized out>
#2  0x000000000044f627 in initialize_context_complete_and_free (ctx=0x7ffff006e630) at mm-broadband-modem.c:7049
        error = 0x0
        __PRETTY_FUNCTION__ = "initialize_context_complete_and_free"
#3  0x000000000045915c in initialization_started_ready (self=0x7266e0, result=<optimized out>, ctx=0x7ffff006e630) at mm-broadband-modem.c:7104
        error = 0x7ffff0052400
        ports_ctx = <optimized out>
        __PRETTY_FUNCTION__ = "initialization_started_ready"
#4  0x00007ffff6f7d3f7 in g_simple_async_result_complete (simple=0x7109c0) at /tmp/buildd/glib2.0-2.32.3/./gio/gsimpleasyncresult.c:767
        current_source = 0x7ffff00650f0
        current_context = 0x457ab0
        __PRETTY_FUNCTION__ = "g_simple_async_result_complete"
#5  0x00007ffff6f7d4f9 in complete_in_idle_cb (data=<optimized out>) at /tmp/buildd/glib2.0-2.32.3/./gio/gsimpleasyncresult.c:779
        simple = <optimized out>
#6  0x00007ffff6a10205 in g_main_dispatch (context=0x6bf4f0) at /tmp/buildd/glib2.0-2.32.3/./glib/gmain.c:2539
        dispatch = 0x7ffff6a0df20 <g_idle_dispatch>
        was_in_call = 0
        user_data = 0x7109c0
        callback = 0x7ffff6f7d4f0 <complete_in_idle_cb>
        cb_funcs = 0x7ffff6cbb980
        cb_data = 0x7ffff0064fe0
        current_source_link = {data = 0x7ffff00650f0, next = 0x0}
        need_destroy = <optimized out>
        source = 0x7ffff00650f0
        current = 0x6c7400
        i = <optimized out>
#7  g_main_context_dispatch (context=context@entry=0x6bf4f0) at /tmp/buildd/glib2.0-2.32.3/./glib/gmain.c:3075
No locals.
#8  0x00007ffff6a10538 in g_main_context_iterate (context=0x6bf4f0, block=block@entry=1, dispatch=dispatch@entry=1, self=<error reading variable: Unhandled dwarf expression opcode 0xfa>)
    at /tmp/buildd/glib2.0-2.32.3/./glib/gmain.c:3146
        max_priority = 0
        timeout = 0
        some_ready = 1
        nfds = <optimized out>
        allocated_nfds = <optimized out>
        fds = 0x7203b0
#9  0x00007ffff6a10932 in g_main_loop_run (loop=0x6c9d10) at /tmp/buildd/glib2.0-2.32.3/./glib/gmain.c:3340
        __PRETTY_FUNCTION__ = "g_main_loop_run"
#10 0x0000000000420cf7 in main (argc=<optimized out>, argv=<optimized out>) at main.c:150
        bus = 0x6bf810
        err = 0x0
        name_id = 1
        __PRETTY_FUNCTION__ = "main"





Bjørn