Re: [MM 07] Huawei plugin: "Failed to find primary port"
- From: Bjørn Mork <bjorn mork no>
- To: Aleksander Morgado <aleksander lanedo com>
- Cc: networkmanager-list gnome org
- Subject: Re: [MM 07] Huawei plugin: "Failed to find primary port"
- Date: Tue, 04 Sep 2012 13:09:31 +0200
Aleksander Morgado <aleksander lanedo com> writes:
>> ModemManager[5165]: KEY: 09:00:01:02:00:00:00:00
>> ModemManager[5165]: Service: 02
>> ModemManager[5165]: Client ID: 01
>> ModemManager[5165]: Transaction ID: 09:00
>> ModemManager[5165]: <debug> [1346741345.079565] [mm-sim-qmi.c:133] load_sim_identifier(): loading SIM identifier...
>> ModemManager[5165]: <debug> [1346741345.079755] [mm-sim-qmi.c:133] load_sim_identifier(): loading SIM identifier...
>> ModemManager[5165]: <warn> [1346741345.079854] [mm-sim.c:1465] load_sim_identifier_ready(): couldn't load SIM identifier: 'QMI operation failed: Cannot send message: QMI service 'dms' version '1.3' required, got version '1.2''
>> ModemManager[5165]: <debug> [1346741345.079930] [mm-sim-qmi.c:209] load_imsi(): loading IMSI...
>> ModemManager[5165]: <warn> [1346741345.080055] [mm-sim.c:1501] load_imsi_ready(): couldn't load IMSI: 'QMI operation failed: Cannot send message: QMI service 'dms' version '1.3' required, got version '1.2''
>> ModemManager[5165]: <debug> [1346741345.080354] [mm-broadband-modem-qmi.c:1295] modem_load_supported_bands(): loading band capabilities...
>> ModemManager[5165]: <warn> [1346741345.080486] [mm-iface-modem.c:3143] load_supported_bands_ready(): couldn't load Supported Bands: 'QMI operation failed: Cannot send message: QMI service 'dms' version '1.3' required, got version '1.2''
>> ModemManager[5165]: <debug> [1346741345.081158] [mm-serial-port.c:969] mm_serial_port_close(): (ttyUSB2) device open count is 0 (close)
>> ModemManager[5165]: <info> [1346741345.081217] [mm-serial-port.c:984] mm_serial_port_close(): (ttyUSB2) closing serial port...
>> ModemManager[5165]: <info> [1346741345.082242] [mm-serial-port.c:1005] mm_serial_port_close(): (ttyUSB2) serial port closed
>> ModemManager[5165]: <debug> [1346741345.082376] [mm-base-modem.c:755] initialize_ready(): Couldn't finish initialization in the current state: 'Modem is currently locked, cannot fully initialize'
>>
>> (ModemManager:5165): GLib-CRITICAL **: g_variant_new_string: assertion `g_utf8_validate (string, -1, NULL)' failed
>>
>> (ModemManager:5165): GLib-CRITICAL **: g_variant_ref_sink: assertion `value != NULL' failed
>
> This is weird; can you run it like this, and get a backtrace of where
> this happened?
>
> sudo G_DEBUG=fatal-criticals gdb --args /usr/sbin/ModemManager --debug
>
> That should run gdb and halt when the first critical is issued.
backtrace follows below. But first, this may be related to a firmware
bug in the IMEI code. Looking at:
ModemManager[11662]: KEY: 06:00:03:02:00:00:00:00
ModemManager[11662]: Service: 02
ModemManager[11662]: Client ID: 03
ModemManager[11662]: Transaction ID: 06:00
ModemManager[11662]: [/dev/cdc-wdm0] Received message...
>>>>>> QMUX:
>>>>>> length = 47
>>>>>> flags = 0x80
>>>>>> service = "dms"
>>>>>> client = 3
>>>>>> QMI:
>>>>>> flags = "response"
>>>>>> transaction = 6
>>>>>> tlv_length = 35
>>>>>> message = "Get IDs" (0x0025)
>>>>>> TLV:
>>>>>> type = "Result" (0x02)
>>>>>> length = 4
>>>>>> value = 00:00:00:00
>>>>>> translated = SUCCESS
>>>>>> TLV:
>>>>>> type = "Imei" (0x11)
>>>>>> length = 25
>>>>>> value = 33:35:33:36:31:33:30:34:38:38:30:35:31:39:39:02:B0:1C:0E:02:84:E3:A6:01:3D
>>>>>> translated = 353613048805199���=
ModemManager[11662]: KEY: 06:00:03:02:00:00:00:00
ModemManager[11662]: Service: 02
ModemManager[11662]: Client ID: 03
ModemManager[11662]: Transaction ID: 06:00
ModemManager[11662]: <debug> [1346755251.079194] [mm-broadband-modem-qmi.c:797] modem_load_equipment_identifier_finish(): loaded equipment identifier: 353613048805199���=
ModemManager[11662]: <debug> [1346755251.079349] [mm-broadband-modem-qmi.c:924] modem_load_device_identifier(): loading device identifier...
ModemManager[11662]: <debug> [1346755251.079495] [mm-modem-helpers.c:129] mm_create_device_identifier(): Device ID source '000012d100001506353613048805199=8200C-FACPACZQ-103801[Oct14201014:00:00]8QUALCOMMINCORPORATED'
ModemManager[11662]: <debug> [1346755251.079590] [mm-modem-helpers.c:130] mm_create_device_identifier(): Device ID 'acf85b48ca4510376b6ca51f7cc9ba99f07e4bbf'
ModemManager[11662]: <debug> [1346755251.079703] [mm-broadband-modem-qmi.c:912] modem_load_device_identifier_finish(): loaded device identifier: acf85b48ca4510376b6ca51f7cc9ba99f07e4bbf
Which is very odd. Attempting to run
qmicli -d /dev/cdc-wdm0 -v --dms-get-ids
consistenly result in:
[04 Sep 2012, 13:01:55] [Debug] [/dev/cdc-wdm0] Received message...
>>>>>> QMUX:
>>>>>> length = 38
>>>>>> flags = 0x80
>>>>>> service = "dms"
>>>>>> client = 10
>>>>>> QMI:
>>>>>> flags = "response"
>>>>>> transaction = 1
>>>>>> tlv_length = 26
>>>>>> message = "Get IDs" (0x0025)
>>>>>> TLV:
>>>>>> type = "Result" (0x02)
>>>>>> length = 4
>>>>>> value = 00:00:00:00
>>>>>> translated = SUCCESS
>>>>>> TLV:
>>>>>> type = "Imei" (0x11)
>>>>>> length = 16
>>>>>> value = 33:35:33:36:31:33:30:34:38:38:30:35:31:39:39:02
>>>>>> translated = 353613048805199
So you still got a bogus 0x02 byte there, but why did MM see 9 more
bytes? Anyway, it is safe to consider any firmware response as
potentionally buggy, and never trust any of it to fit into any expected
pattern...
Yes, I know that's easy to say ;-)
Anyway, here is a full backtrace after the assertion:
ms' version '1.3' required, got version '1.2''
ModemManager[11662]: <debug> [1346755251.095901] [mm-sim-qmi.c:209] load_imsi(): loading IMSI...
ModemManager[11662]: <warn> [1346755251.096002] [mm-sim.c:1501] load_imsi_ready(): couldn't load IMSI: 'QMI operation failed: Cannot send message: QMI service 'dms' version '1.3' required, got version '1.2''
ModemManager[11662]: <debug> [1346755251.096203] [mm-broadband-modem-qmi.c:1295] modem_load_supported_bands(): loading band capabilities...
ModemManager[11662]: <warn> [1346755251.096300] [mm-iface-modem.c:3143] load_supported_bands_ready(): couldn't load Supported Bands: 'QMI operation failed: Cannot send message: QMI service 'dms' version '1.3' required, got version '1.2''
ModemManager[11662]: <debug> [1346755251.096776] [mm-broadband-modem-qmi.c:2342] modem_3gpp_load_imei_finish(): loaded IMEI: 353613048805199���=
ModemManager[11662]: <debug> [1346755251.096897] [mm-broadband-modem-qmi.c:2421] dms_uim_get_ck_status_ready(): Couldn't query facility 'ph-sim' status, assuming disabled
ModemManager[11662]: <debug> [1346755251.096976] [mm-broadband-modem-qmi.c:2421] dms_uim_get_ck_status_ready(): Couldn't query facility 'net-pers' status, assuming disabled
ModemManager[11662]: <debug> [1346755251.097053] [mm-broadband-modem-qmi.c:2421] dms_uim_get_ck_status_ready(): Couldn't query facility 'net-sub-pers' status, assuming disabled
ModemManager[11662]: <debug> [1346755251.097134] [mm-broadband-modem-qmi.c:2421] dms_uim_get_ck_status_ready(): Couldn't query facility 'provider-pers' status, assuming disabled
ModemManager[11662]: <debug> [1346755251.097205] [mm-broadband-modem-qmi.c:2421] dms_uim_get_ck_status_ready(): Couldn't query facility 'corp-pers' status, assuming disabled
ModemManager[11662]: <debug> [1346755251.097556] [mm-broadband-modem.c:7297] iface_modem_3gpp_ussd_initialize_ready(): Couldn't initialize interface: 'USSD not supported'
ModemManager[11662]: <debug> [1346755251.097971] [mm-broadband-modem.c:7300] iface_modem_messaging_initialize_ready(): Couldn't initialize interface: 'Messaging not supported'
ModemManager[11662]: <debug> [1346755251.098143] [mm-broadband-modem.c:7301] iface_modem_time_initialize_ready(): Couldn't initialize interface: 'Time not supported'
ModemManager[11662]: <info> [1346755251.098316] [mm-iface-modem.c:995] mm_iface_modem_update_state(): Modem: state changed (initializing -> disabled)
ModemManager[11662]: <debug> [1346755251.098458] [mm-serial-port.c:969] mm_serial_port_close(): (ttyUSB2) device open count is 0 (close)
ModemManager[11662]: <info> [1346755251.098504] [mm-serial-port.c:984] mm_serial_port_close(): (ttyUSB2) closing serial port...
ModemManager[11662]: <info> [1346755251.099788] [mm-serial-port.c:1005] mm_serial_port_close(): (ttyUSB2) serial port closed
ModemManager[11662]: <debug> [1346755251.099847] [mm-base-modem.c:760] initialize_ready(): modem properly initialized
(ModemManager:11662): GLib-CRITICAL **: g_variant_new_string: assertion `g_utf8_validate (string, -1, NULL)' failed
Program received signal SIGTRAP, Trace/breakpoint trap.
g_logv (log_domain=0x7ffff6a4f32e "GLib", log_level=G_LOG_LEVEL_CRITICAL, format=0x7ffff6a586e2 "%s: assertion `%s' failed", args1=args1@entry=0x7fffffffd7a8)
at /tmp/buildd/glib2.0-2.32.3/./glib/gmessages.h:101
101 /tmp/buildd/glib2.0-2.32.3/./glib/gmessages.h: No such file or directory.
(gdb) bt full
#0 g_logv (log_domain=0x7ffff6a4f32e "GLib", log_level=G_LOG_LEVEL_CRITICAL, format=0x7ffff6a586e2 "%s: assertion `%s' failed", args1=args1@entry=0x7fffffffd7a8)
at /tmp/buildd/glib2.0-2.32.3/./glib/gmessages.h:101
domain = 0x0
data = <optimized out>
depth = <optimized out>
log_func = <optimized out>
domain_fatal_mask = <optimized out>
masquerade_fatal = <optimized out>
test_level = <optimized out>
was_fatal = <optimized out>
was_recursion = <optimized out>
i = <optimized out>
#1 0x00007ffff6a174d2 in g_log (log_domain=log_domain@entry=0x7ffff6a4f32e "GLib", log_level=log_level@entry=G_LOG_LEVEL_CRITICAL,
format=format@entry=0x7ffff6a586e2 "%s: assertion `%s' failed") at /tmp/buildd/glib2.0-2.32.3/./glib/gmessages.c:792
args = {{gp_offset = 24, fp_offset = 48, overflow_arg_area = 0x7fffffffd880, reg_save_area = 0x7fffffffd7c0}}
#2 0x00007ffff6a174f9 in g_return_if_fail_warning (log_domain=log_domain@entry=0x7ffff6a4f32e "GLib", pretty_function=pretty_function@entry=0x7ffff6a9eb70 "g_variant_new_string",
expression=expression@entry=0x7ffff6a9cd80 "g_utf8_validate (string, -1, NULL)") at /tmp/buildd/glib2.0-2.32.3/./glib/gmessages.c:801
No locals.
#3 0x00007ffff6a3d785 in g_variant_new_string (string=<optimized out>) at /tmp/buildd/glib2.0-2.32.3/./glib/gvariant.c:1267
No locals.
#4 g_variant_new_string (string=0x6dda80 "353613048805199\002\260\034\016\002\204\343\246\001=") at /tmp/buildd/glib2.0-2.32.3/./glib/gvariant.c:1264
No locals.
#5 0x00007ffff6fbcc0e in g_dbus_gvalue_to_gvariant (gvalue=gvalue@entry=0x7fffffffd8d0, type=0x7ffff79b41d1) at /tmp/buildd/glib2.0-2.32.3/./gio/gdbusutils.c:647
ret = 0x0
s = <optimized out>
as = <optimized out>
empty_strv = {0x0}
__PRETTY_FUNCTION__ = "g_dbus_gvalue_to_gvariant"
#6 0x00007ffff799df34 in _mm_gdbus_modem_skeleton_handle_get_property (connection=<optimized out>, sender=sender@entry=0x0,
object_path=object_path@entry=0x736fa0 "/org/freedesktop/ModemManager1/Modem/0", interface_name=interface_name@entry=0x7ffff79bb2e0 "org.freedesktop.ModemManager1.Modem",
property_name=<optimized out>, error=error@entry=0x0, user_data=user_data@entry=0x6f4100) at mm-gdbus-modem.c:4445
skeleton = 0x6f4100
value = {g_type = 64, data = {{v_int = 7199360, v_uint = 7199360, v_long = 7199360, v_ulong = 7199360, v_int64 = 7199360, v_uint64 = 7199360, v_float = 1.00884521e-38,
v_double = 3.5569564480436367e-317, v_pointer = 0x6dda80}, {v_int = 0, v_uint = 0, v_long = 0, v_ulong = 0, v_int64 = 0, v_uint64 = 0, v_float = 0, v_double = 0,
v_pointer = 0x0}}}
pspec = <optimized out>
info = 0x7ffff7bcf600
ret = 0x0
__PRETTY_FUNCTION__ = "_mm_gdbus_modem_skeleton_handle_get_property"
#7 0x00007ffff799e5eb in mm_gdbus_modem_skeleton_dbus_interface_get_properties (_skeleton=<optimized out>) at mm-gdbus-modem.c:4523
value = <optimized out>
info = 0x7ffff7bcf600
skeleton = 0x6f4100
builder = {x = {0, 7571424, 7571425, 7571248, 0, 18446744073709551615, 7578112, 16, 12, 3, 1033660112, 0, 0, 0, 0, 0}}
n = <optimized out>
#8 0x00007ffff6fe2431 in g_dbus_interface_skeleton_get_properties (interface_=0x6f4100) at /tmp/buildd/glib2.0-2.32.3/./gio/gdbusinterfaceskeleton.c:372
ret = <optimized out>
__PRETTY_FUNCTION__ = "g_dbus_interface_skeleton_get_properties"
#9 0x00007ffff6fe7c13 in g_dbus_object_manager_server_emit_interfaces_added (manager=manager@entry=0x6c3e30, interfaces=0x737800,
object_path=object_path@entry=0x722550 "/org/freedesktop/ModemManager1/Modem/0", data=<error reading variable: Unhandled dwarf expression opcode 0xfa>,
data=<error reading variable: Unhandled dwarf expression opcode 0xfa>) at /tmp/buildd/glib2.0-2.32.3/./gio/gdbusobjectmanagerserver.c:887
iface = <optimized out>
properties = <optimized out>
array_builder = {x = {0, 7570960, 7570961, 7572688, 0, 18446744073709551615, 7570992, 8, 1, 3, 1033660112, 0, 0, 0, 0, 0}}
error = 0x0
n = <optimized out>
#10 0x00007ffff6fe8427 in g_dbus_object_manager_server_export_unlocked (manager=0x6c3e30, object=<optimized out>, object_path=0x722550 "/org/freedesktop/ModemManager1/Modem/0")
at /tmp/buildd/glib2.0-2.32.3/./gio/gdbusobjectmanagerserver.c:506
data = 0x72fb80
existing_interfaces = 0x707360
l = 0x0
interface_names = 0x707540
__PRETTY_FUNCTION__ = "g_dbus_object_manager_server_export_unlocked"
#11 0x00007ffff6fe8897 in g_dbus_object_manager_server_export (manager=0x6c3e30, object=0x71c020) at /tmp/buildd/glib2.0-2.32.3/./gio/gdbusobjectmanagerserver.c:538
__PRETTY_FUNCTION__ = "g_dbus_object_manager_server_export"
#12 0x0000000000424770 in export_modem (self=0x6bea30) at mm-device.c:390
---Type <return> to continue, or q <return> to quit---
connection = 0x6bf810
path = 0x736270 "/org/freedesktop/ModemManager1/Modem/0"
id = 1
#13 modem_valid (modem=<optimized out>, pspec=<optimized out>, self=0x6bea30) at mm-device.c:437
No locals.
#14 0x00007ffff6cce724 in g_closure_invoke (closure=0x721bd0, return_value=0x0, n_param_values=2, param_values=0x7fffffffddb0, invocation_hint=0x7fffffffdd50)
at /tmp/buildd/glib2.0-2.32.3/./gobject/gclosure.c:777
marshal = 0x7ffff6cd15d0 <g_cclosure_marshal_VOID__PARAM>
marshal_data = 0x0
in_marshal = <optimized out>
real_closure = 0x721bb0
__PRETTY_FUNCTION__ = "g_closure_invoke"
#15 0x00007ffff6cdf7b0 in signal_emit_unlocked_R (node=node@entry=0x6bc460, detail=detail@entry=375, instance=instance@entry=0x71c020, emission_return=emission_return@entry=0x0,
instance_and_params=instance_and_params@entry=0x7fffffffddb0) at /tmp/buildd/glib2.0-2.32.3/./gobject/gsignal.c:3547
tmp = <optimized out>
handler = 0x6cd190
accumulator = 0x0
emission = {next = 0x0, instance = 0x71c020, ihint = {signal_id = 1, detail = 375, run_type = G_SIGNAL_RUN_FIRST}, state = EMISSION_RUN, chain_type = 4}
class_closure = 0x6bbdd0
hlist = 0x6cd190
handler_list = 0x6cd190
return_accu = 0x0
accu = {g_type = 0, data = {{v_int = 0, v_uint = 0, v_long = 0, v_ulong = 0, v_int64 = 0, v_uint64 = 0, v_float = 0, v_double = 0, v_pointer = 0x0}, {v_int = 0, v_uint = 0,
v_long = 0, v_ulong = 0, v_int64 = 0, v_uint64 = 0, v_float = 0, v_double = 0, v_pointer = 0x0}}}
signal_id = 1
max_sequential_handler_number = 67
return_value_altered = 1
#16 0x00007ffff6ce772c in g_signal_emit_valist (instance=0x71c020, signal_id=<optimized out>, detail=375, var_args=var_args@entry=0x7fffffffe008)
at /tmp/buildd/glib2.0-2.32.3/./gobject/gsignal.c:3296
instance_and_params = 0x7fffffffddb0
signal_return_type = 4
param_values = 0x7fffffffddc8
node = 0x6bc460
i = <optimized out>
n_params = 1
__PRETTY_FUNCTION__ = "g_signal_emit_valist"
#17 0x00007ffff6ce78c2 in g_signal_emit (instance=<optimized out>, signal_id=<optimized out>, detail=<optimized out>) at /tmp/buildd/glib2.0-2.32.3/./gobject/gsignal.c:3352
var_args = {{gp_offset = 32, fp_offset = 48, overflow_arg_area = 0x7fffffffe0e0, reg_save_area = 0x7fffffffe020}}
#18 0x00007ffff6cd30e5 in g_object_dispatch_properties_changed (object=0x71c020, n_pspecs=0, pspecs=0x5) at /tmp/buildd/glib2.0-2.32.3/./gobject/gobject.c:1041
No locals.
#19 0x00007ffff6cd4ae3 in g_object_notify_by_spec_internal (pspec=<optimized out>, object=0x71c020) at /tmp/buildd/glib2.0-2.32.3/./gobject/gobject.c:1133
nqueue = 0x0
notify_pspec = 0x6f9e30
#20 g_object_notify_by_pspec (object=0x71c020, pspec=<optimized out>) at /tmp/buildd/glib2.0-2.32.3/./gobject/gobject.c:1234
__PRETTY_FUNCTION__ = "g_object_notify_by_pspec"
#21 0x0000000000433288 in initialize_ready (self=0x71c020, res=<optimized out>) at mm-base-modem.c:765
error = 0x0
__PRETTY_FUNCTION__ = "initialize_ready"
#22 0x00007ffff6f7d3f7 in g_simple_async_result_complete (simple=0x6be800) at /tmp/buildd/glib2.0-2.32.3/./gio/gsimpleasyncresult.c:767
current_source = 0x736dd0
current_context = 0x0
__PRETTY_FUNCTION__ = "g_simple_async_result_complete"
#23 0x00007ffff6f7d4f9 in complete_in_idle_cb (data=<optimized out>) at /tmp/buildd/glib2.0-2.32.3/./gio/gsimpleasyncresult.c:779
simple = <optimized out>
#24 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 = 0x6be800
callback = 0x7ffff6f7d4f0 <complete_in_idle_cb>
cb_funcs = 0x7ffff6cbb980
cb_data = 0x736750
current_source_link = {data = 0x736dd0, next = 0x0}
need_destroy = <optimized out>
source = 0x736dd0
current = 0x6c7400
i = <optimized out>
---Type <return> to continue, or q <return> to quit---
#25 g_main_context_dispatch (context=context@entry=0x6bf4f0) at /tmp/buildd/glib2.0-2.32.3/./glib/gmain.c:3075
No locals.
#26 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 = 0x713980
#27 0x00007ffff6a10932 in g_main_loop_run (loop=0x6cd600) at /tmp/buildd/glib2.0-2.32.3/./glib/gmain.c:3340
__PRETTY_FUNCTION__ = "g_main_loop_run"
#28 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
[
Date Prev][
Date Next] [
Thread Prev][
Thread Next]
[
Thread Index]
[
Date Index]
[
Author Index]
