Aleksander Morgado <aleksan...@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
_______________________________________________
networkmanager-list mailing list
networkmanager-list@gnome.org
https://mail.gnome.org/mailman/listinfo/networkmanager-list
