ModemManager crashes when loading timezone (novatel plugins)
Hello, I recently encountered a crash on ModemManager 1.16.6.
The modem is a Novatel Wireless USB551L which use ModemManager novatel plugin.
The stack is the following:
(gdb) bt
#0 0x00005627a55714f9 in load_network_timezone_ready (self=0x5627a5c22350, res=0x7ff3f80095c0) at ../../ModemManager-1.16.6/src/mm-iface-modem-time.c:205
#1 0x00007ff40e1c1712 in g_simple_async_result_complete (simple=0x7ff3f80095c0) at ../glib-2.58.3/gio/gsimpleasyncresult.c:802
#2 0x00005627a5543bbc in at_command_ready (port=<optimized out>, res=<optimized out>, ctx=ctx@entry=0x5627a5bf9a80)
at ../../ModemManager-1.16.6/src/mm-base-modem-at.c:538
#3 0x00007ff40e1c1712 in g_simple_async_result_complete (simple=0x5627a5c56eb0) at ../glib-2.58.3/gio/gsimpleasyncresult.c:802
#4 0x00005627a55a18b4 in serial_command_ready (port=<optimized out>, res=<optimized out>, simple=simple@entry=0x5627a5c56eb0)
at ../../ModemManager-1.16.6/src/mm-port-serial-at.c:378
#5 0x00007ff40e1c1712 in g_simple_async_result_complete (simple=0x7ff3f8009d00) at ../glib-2.58.3/gio/gsimpleasyncresult.c:802
#6 0x00007ff40e1c179c in complete_in_idle_cb (data=0x7ff3f8009d00) at ../glib-2.58.3/gio/gsimpleasyncresult.c:814
#7 0x00007ff40e000ac8 in g_main_dispatch (context=0x5627a5b8e1f0) at ../glib-2.58.3/glib/gmain.c:3182
#8 g_main_context_dispatch (context=context@entry=0x5627a5b8e1f0) at ../glib-2.58.3/glib/gmain.c:3847
#9 0x00007ff40e000eb8 in g_main_context_iterate (context=0x5627a5b8e1f0, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>)
at ../glib-2.58.3/glib/gmain.c:3920
#10 0x00007ff40e0011b2 in g_main_loop_run (loop=0x5627a5ba4f60) at ../glib-2.58.3/glib/gmain.c:4116
#11 0x00005627a552dc9d in main (argc=<optimized out>, argv=<optimized out>) at ../../ModemManager-1.16.6/src/main.c:210
(gdb) p error
$1 = (GError_autoptr) 0x0
(gdb) ModemManager log:
Aug 20 01:30:32.667725 tap-00006604 ModemManager[1384]: <info> [base-manager] port ttyUSB0 released by device '/sys/devices/pci0000:00/0000:00:1c.0/0000:01:00.0/usb4/4-2'
Aug 20 01:30:32.670431 tap-00006604 ModemManager[1384]: <info> [base-manager] port ttyUSB1 released by device '/sys/devices/pci0000:00/0000:00:1c.0/0000:01:00.0/usb4/4-2'
Aug 20 01:30:32.672952 tap-00006604 ModemManager[1384]: <info> [base-manager] port ttyUSB3 released by device '/sys/devices/pci0000:00/0000:00:1c.0/0000:01:00.0/usb4/4-2'
Aug 20 01:30:32.673233 tap-00006604 ModemManager[1384]: <info> [base-manager] port ttyUSB2 released by device '/sys/devices/pci0000:00/0000:00:1c.0/0000:01:00.0/usb4/4-2'
Aug 20 01:31:28.341593 tap-00006604 ModemManager[1384]: <info> [device /sys/devices/pci0000:00/0000:00:1c.0/0000:01:00.0/usb4/4-2] creating modem with plugin 'novatel' and '4' ports
Aug 20 01:31:28.341880 tap-00006604 ModemManager[1384]: <warn> [plugin/novatel] could not grab port ttyUSB3: Cannot add port 'tty/ttyUSB3', unhandled port type
Aug 20 01:31:28.342949 tap-00006604 ModemManager[1384]: <info> [base-manager] modem for device '/sys/devices/pci0000:00/0000:00:1c.0/0000:01:00.0/usb4/4-2' successfully created
Aug 20 01:31:28.351327 tap-00006604 ModemManager[1384]: <info> [modem12] loading current capabilities...
Aug 20 01:31:28.415615 tap-00006604 ModemManager[1384]: <info> [modem12] loaded current capabilities: cdma-evdo, lte
Aug 20 01:31:28.501014 tap-00006604 ModemManager[1384]: <info> [modem12] loaded manufacturer: Novatel Wireless Incorporated
Aug 20 01:31:28.501063 tap-00006604 ModemManager[1384]: <info> [modem12] loading model...
Aug 20 01:31:28.516720 tap-00006604 ModemManager[1384]: <info> [modem12] loaded model: USB551L
Aug 20 01:31:28.516757 tap-00006604 ModemManager[1384]: <info> [modem12] loading revision...
Aug 20 01:31:28.533185 tap-00006604 ModemManager[1384]: <info> [modem12] loaded revision: 1.48 SVN 0 [2012-04-30 18:44:34]
Aug 20 01:31:28.533210 tap-00006604 ModemManager[1384]: <info> [modem12] loading equipment identifier...
Aug 20 01:31:28.550058 tap-00006604 ModemManager[1384]: <info> [modem12] loaded equipment identifier: 990003319664666
Aug 20 01:31:28.550081 tap-00006604 ModemManager[1384]: <info> [modem12] loading device identifier...
Aug 20 01:31:28.558085 tap-00006604 ModemManager[1384]: <info> [modem12] loaded device identifier: 0edfe184b0d72ec93192dd244bea9e7cf11d0103
Aug 20 01:31:28.558118 tap-00006604 ModemManager[1384]: <info> [modem12] loading supported modes...
Aug 20 01:31:31.358959 tap-00006604 ModemManager[1384]: <info> [modem12] loading supported IP families...
Aug 20 01:31:31.375745 tap-00006604 ModemManager[1384]: <info> [modem12] loading power state...
Aug 20 01:31:31.794005 tap-00006604 ModemManager[1384]: <warn> [modem12/sim11] couldn't load operator name: SIM returned empty response 'FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF'
Aug 20 01:31:31.862035 tap-00006604 ModemManager[1384]: <warn> [modem12/sim11] couldn't load list of emergency numbers: Failed to parse CRSM query result '+CRSM: 105,129,""'
Aug 20 01:31:31.899711 tap-00006604 ModemManager[1384]: <info> [modem12] loading IMEI...
Aug 20 01:31:31.899768 tap-00006604 ModemManager[1384]: <info> [modem12] loaded IMEI: 990003319664666
Aug 20 01:31:31.899787 tap-00006604 ModemManager[1384]: <info> [modem12] loading enabled facility locks...
Aug 20 01:31:32.021215 tap-00006604 ModemManager[1384]: <info> [modem12] loading MEID...
Aug 20 01:31:32.030481 tap-00006604 ModemManager[1384]: <info> [modem12] loaded MEID: (null)
Aug 20 01:31:32.030528 tap-00006604 ModemManager[1384]: <info> [modem12] loading ESN...
Aug 20 01:31:32.030603 tap-00006604 ModemManager[1384]: <info> [modem12] loaded ESN: (null)
Aug 20 01:31:32.139697 tap-00006604 ModemManager[1384]: <info> [modem12] state changed (unknown -> disabled)
Aug 20 01:31:32.154559 tap-00006604 ModemManager[1384]: <info> [modem12] state changed (disabled -> enabling)
Aug 20 01:31:32.258354 tap-00006604 ModemManager[1384]: <info> [modem12] loading power state...
Aug 20 01:31:32.268441 tap-00006604 ModemManager[1384]: <info> [modem12] power state updated: on
Aug 20 01:31:32.516099 tap-00006604 ModemManager[1384]: <info> [modem12] running registration checks (CS: 'no', PS: 'no', EPS: 'yes', 5GS: 'no')
Aug 20 01:31:32.527774 tap-00006604 ModemManager[1384]: <info> [modem12] 3GPP registration state changed (unknown -> idle)
Aug 20 01:31:32.761343 tap-00006604 ModemManager[1384]: <info> [modem12] state changed (enabling -> enabled)
Aug 20 01:31:32.761587 tap-00006604 ModemManager[1384]: <info> [modem12] running registration checks (CS: 'no', PS: 'no', EPS: 'yes', 5GS: 'no')
Aug 20 01:31:33.355647 tap-00006604 ModemManager[1384]: <info> [modem12] simple connect started...
Aug 20 01:31:33.355661 tap-00006604 ModemManager[1384]: <info> [modem12] PIN: unspecified
Aug 20 01:31:33.355669 tap-00006604 ModemManager[1384]: <info> [modem12] operator ID: unspecified
Aug 20 01:31:33.355680 tap-00006604 ModemManager[1384]: <info> [modem12] allowed roaming: yes
Aug 20 01:31:33.355690 tap-00006604 ModemManager[1384]: <info> [modem12] APN: data641003
Aug 20 01:31:33.355699 tap-00006604 ModemManager[1384]: <info> [modem12] IP family: ipv4
Aug 20 01:31:33.355715 tap-00006604 ModemManager[1384]: <info> [modem12] allowed authentication: none, pap, chap, mschap, mschapv2, eap
Aug 20 01:31:33.355722 tap-00006604 ModemManager[1384]: <info> [modem12] User: unspecified
Aug 20 01:31:33.355730 tap-00006604 ModemManager[1384]: <info> [modem12] Password: unspecified
Aug 20 01:31:33.355739 tap-00006604 ModemManager[1384]: <info> [modem12] simple connect state (4/8): wait to get fully enabled
Aug 20 01:31:33.355775 tap-00006604 ModemManager[1384]: <info> [modem12] simple connect state (5/8): register
Aug 20 01:31:33.355803 tap-00006604 ModemManager[1384]: <info> [modem12] launching automatic network registration...
Aug 20 01:31:33.391274 tap-00006604 ModemManager[1384]: <info> [modem12] running registration checks (CS: 'no', PS: 'no', EPS: 'yes', 5GS: 'no')
Aug 20 01:31:33.408017 tap-00006604 ModemManager[1384]: <info> [modem12] not yet registered in a 3GPP network... will recheck soon
Aug 20 01:31:36.342051 tap-00006604 ModemManager[1384]: <info> [modem12] running registration checks (CS: 'no', PS: 'no', EPS: 'yes', 5GS: 'no')
Aug 20 01:31:36.380318 tap-00006604 ModemManager[1384]: <info> [modem12] 3GPP registration state changed (idle -> registering)
Aug 20 01:31:36.380354 tap-00006604 ModemManager[1384]: <info> [modem12] loading Operator Code...
Aug 20 01:31:36.380427 tap-00006604 ModemManager[1384]: <info> [modem12] currently registered in a 3GPP network
Aug 20 01:31:36.380440 tap-00006604 ModemManager[1384]: <info> [modem12] simple connect state (6/8): bearer
Aug 20 01:31:36.380826 tap-00006604 ModemManager[1384]: <info> [modem12] simple connect state (7/8): connect
Aug 20 01:31:36.380917 tap-00006604 ModemManager[1384]: <info> [modem12] state changed (enabled -> connecting)
Aug 20 01:31:36.381107 tap-00006604 ModemManager[1384]: <info> [modem12/bearer135] launching 3GPP connection attempt with APN 'data641003'
Aug 20 01:31:36.420501 tap-00006604 ModemManager[1384]: <warn> [modem12] couldn't load operator code: Unknown error
Aug 20 01:31:36.420538 tap-00006604 ModemManager[1384]: <info> [modem12] loading Operator Name...
Aug 20 01:31:36.459419 tap-00006604 ModemManager[1384]: <warn> [modem12] couldn't load operator name: Unknown error
Aug 20 01:31:36.459472 tap-00006604 ModemManager[1384]: <info> [modem12] 3GPP registration state changed (registering -> roaming)
Aug 20 01:31:36.459532 tap-00006604 ModemManager[1384]: <info> [modem12] state changed (connecting -> registered)
Aug 20 01:31:36.490293 tap-00006604 ModemManager[1384]: <info> [modem12/bearer135] found 15 PDP contexts
Aug 20 01:31:36.490304 tap-00006604 ModemManager[1384]: <info> [modem12/bearer135] PDP context [cid=1] [type='ipv4'] [apn='m2m005041.attz']
Aug 20 01:31:36.490310 tap-00006604 ModemManager[1384]: <info> [modem12/bearer135] PDP context [cid=2] [type='ipv4v6'] [apn='vzwadmin']
Aug 20 01:31:36.490315 tap-00006604 ModemManager[1384]: <info> [modem12/bearer135] PDP context [cid=3] [type='ipv4v6'] [apn='VZWINTERNET']
Aug 20 01:31:36.490320 tap-00006604 ModemManager[1384]: <info> [modem12/bearer135] PDP context [cid=4] [type='ipv4v6'] [apn='vzwapp']
Aug 20 01:31:36.490325 tap-00006604 ModemManager[1384]: <info> [modem12/bearer135] PDP context [cid=5] [type='ipv4'] [apn='data641003']
Aug 20 01:31:36.490330 tap-00006604 ModemManager[1384]: <info> [modem12/bearer135] PDP context [cid=6] [type='ipv4'] [apn='orange.m2m.spec']
Aug 20 01:31:36.490334 tap-00006604 ModemManager[1384]: <info> [modem12/bearer135] PDP context [cid=7] [type='ipv4'] [apn='m2m005041.attz']
Aug 20 01:31:36.490339 tap-00006604 ModemManager[1384]: <info> [modem12/bearer135] PDP context [cid=8] [type='ipv4'] [apn='vzwinternet']
Aug 20 01:31:36.490344 tap-00006604 ModemManager[1384]: <info> [modem12/bearer135] PDP context [cid=9] [type='ipv4'] [apn='vzwims']
Aug 20 01:31:36.490349 tap-00006604 ModemManager[1384]: <info> [modem12/bearer135] PDP context [cid=10] [type='ipv4'] [apn='vzwapp']
Aug 20 01:31:36.490353 tap-00006604 ModemManager[1384]: <info> [modem12/bearer135] PDP context [cid=11] [type='ipv4'] [apn='vzwadmin']
Aug 20 01:31:36.490357 tap-00006604 ModemManager[1384]: <info> [modem12/bearer135] PDP context [cid=12] [type='ipv4'] [apn='vzwinternet']
Aug 20 01:31:36.490362 tap-00006604 ModemManager[1384]: <info> [modem12/bearer135] PDP context [cid=13] [type='ipv4'] [apn='wyleslte.gw7.vzwentp']
Aug 20 01:31:36.490367 tap-00006604 ModemManager[1384]: <info> [modem12/bearer135] PDP context [cid=14] [type='ipv4'] [apn='PODSYSTE.VZWENTP']
Aug 20 01:31:36.490372 tap-00006604 ModemManager[1384]: <info> [modem12/bearer135] PDP context [cid=15] [type='ipv4'] [apn='3G38']
Aug 20 01:31:36.505524 tap-00006604 ModemManager[1384]: <info> [modem12] access technology changed (unknown -> 1xrtt)
Aug 20 01:31:51.481234 tap-00006604 ModemManager[1384]: <info> caught signal, shutting down...
Aug 20 01:31:51.481380 tap-00006604 ModemManager[1384]: <info> [modem12] state changed (registered -> disabling)
Aug 20 01:31:51.481489 tap-00006604 ModemManager[1384]: <info> [modem12] access technology changed (1xrtt -> unknown)
Aug 20 01:31:52.368523 tap-00006604 kernel: ModemManager[1384]: segfault at 8 ip 00005635872224f9 sp 00007ffc9e707938 error 4 in ModemManager[5635871b4000+115000]There is a NULL pointer dereference here
From what I saw, the culprit is the object that implement the time interface that should not return a null timezone without setting GError.
The novatel plugin doesn't check the error of at command completion and hence can return a NULL timezone object without any error.
I found 2 other plugins (huawei and icera) which make both different things (but better to my opinion):
- icera ignores also the possible error of at_command_finish but set itself an error before returning a null timezone
- huawei simply gives error object to at_command_finish
I'm thinking about two options here:
- do error NULL check in mm-iface-modem-time.c log
- be sure that the plugins implementation do not return NULL without an error (maybe always give error pointer to at_command_finish)
What are you thought about that ? Please tell me and I'll open a merge request with the modifications.
PS: Note that I enable full debug log and wait for another occurence to happen (to know exactly what make the AT commands fails)