Modem SORACOM (SC-QGLC4-C1) : Unable to find a usable modem character set

Thu Dec 17 09:59:33 UTC 2020

hello again,

After a sim was inserted in the dongle, no problems have been notices so I it seems that a missing sim prevent modem initialization (which, to my opinion should not be , it should failed only on enable step).

Nevertheless, I open a bug (https://gitlab.freedesktop.org/mobile-broadband/ModemManager/-/issues/289) to track the mmcli segfault on a badly initialized modem and I'll try to come up with a MR to fix this (I don't know yet if the real fix should be to not expose the modem on DBus when it is not initialized or simply add a null-protection somewhere in mmcli)
[https://gitlab.freedesktop.org/uploads/-/system/project/avatar/184/ModemManager-icon.png]<https://gitlab.freedesktop.org/mobile-broadband/ModemManager/-/issues/289>
mmcli coredump when device is not correctly initialized (#289) · Issues · Mobile broadband connectivity / ModemManager<https://gitlab.freedesktop.org/mobile-broadband/ModemManager/-/issues/289>
I have a SORACAOM modem (SC-QGLC4-C1) and when I used it without SIM and with ModemManager , I have the following error:
gitlab.freedesktop.org

________________________________
From: ModemManager-devel <modemmanager-devel-bounces at lists.freedesktop.org> on behalf of Frederic Martinsons <frederic.martinsons at sigfox.com>
Sent: Monday, December 14, 2020 3:15 PM
To: modemmanager-devel at lists.freedesktop.org <modemmanager-devel at lists.freedesktop.org>
Subject: Modem SORACOM (SC-QGLC4-C1) : Unable to find a usable modem character set

Hello ModemManager,

I have an USB LT dongle (SC-QGLC4-C1) which I cannot initialize under ModemManager 1.14.8, I encounter problem setting charset to the modem, below is the debug sequence:

Dec 14 14:12:18.412207 tap-0000A9D8 ModemManager[1275]: <info>  [1607955138.412197] [base-manager] modem for device '/sys/devices/pci0000:00/0000:00:1c.0/0000:01:00.0/usb4/4-1' successfully created
Dec 14 14:12:18.412675 tap-0000A9D8 ModemManager[1275]: <info>  [1607955138.412661] [modem0] loading current capabilities...
Dec 14 14:12:18.412693 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.412683] [modem0/ttyUSB0/qcdm] opening serial port...
Dec 14 14:12:18.413130 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.413122] [modem0/ttyUSB0/qcdm] device open count is 1 (open)
Dec 14 14:12:18.413167 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.413158] [modem0/ttyUSB2/at] --> 'ATE0<CR>'
Dec 14 14:12:18.413251 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.413243] [modem0/ttyUSB0/qcdm] --> 26 0a 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 b2 37 7e
Dec 14 14:12:18.414772 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.414761] [modem0/ttyUSB0/qcdm] <-- 26 0a 00 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 4f 52 7e
Dec 14 14:12:18.414807 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.414797] [modem0/ttyUSB2/at] device open count is 2 (open)
Dec 14 14:12:18.417365 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.417352] [modem0/ttyUSB2/at] <-- 'ATE0'
Dec 14 14:12:18.418255 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.418246] [modem0/ttyUSB2/at] <-- '<CR>'
Dec 14 14:12:18.419382 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.419373] [modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Dec 14 14:12:18.419430 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.419420] [modem0/ttyUSB2/at] --> 'ATV1<CR>'
Dec 14 14:12:18.424486 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.424477] [modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Dec 14 14:12:18.424529 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.424519] [modem0/ttyUSB2/at] --> 'AT+CMEE=1<CR>'
Dec 14 14:12:18.438878 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.438870] [modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Dec 14 14:12:18.438922 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.438912] [modem0/ttyUSB2/at] --> 'ATX4<CR>'
Dec 14 14:12:18.444269 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.444261] [modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Dec 14 14:12:18.444311 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.444301] [modem0/ttyUSB2/at] --> 'AT&C1<CR>'
Dec 14 14:12:18.450309 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.450301] [modem0/ttyUSB2/at] <-- '<CR><LF>OK<CR><LF>'
Dec 14 14:12:18.450351 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.450341] [modem0/ttyUSB2/at] --> 'AT+GCAP<CR>'
Dec 14 14:12:18.458532 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.458482] [modem0/ttyUSB2/at] <-- '<CR><LF>ERROR<CR><LF>'
Dec 14 14:12:18.458662 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.458648] [modem0/ttyUSB2/at] operation failure: 100 (Unknown error)
Dec 14 14:12:18.458710 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.458701] [modem0/ttyUSB2/at] --> 'ATI<CR>'
Dec 14 14:12:18.462664 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.462635] [modem0/ttyUSB2/at] <-- '<CR><LF>Quectel<CR><LF>EG25<CR><LF>Revision: EG25GGBR07A07M2G<CR><LF><CR><LF>OK<CR><LF>'
Dec 14 14:12:18.462758 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.462748] [modem0/ttyUSB2/at] --> 'AT+CPIN?<CR>'
Dec 14 14:12:18.476539 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.476514] [modem0/ttyUSB2/at] <-- '<CR><LF>+CME ERROR: 10<CR><LF>'
Dec 14 14:12:18.476680 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.476666] [modem0/ttyUSB2/at] operation failure: 10 (SIM not inserted)
Dec 14 14:12:18.476732 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.476721] [modem0/ttyUSB2/at] device open count is 3 (open)
Dec 14 14:12:18.476758 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.476749] [modem0/ttyUSB2/at] device open count is 2 (close)
Dec 14 14:12:18.476788 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.476779] [modem0/ttyUSB2/at] --> 'AT+WS46=?<CR>'
Dec 14 14:12:18.489756 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.489704] [modem0/ttyUSB2/at] <-- '<CR><LF>+WS46: (12,22,25,28,29)<CR><LF><CR><LF>OK<CR><LF>'
Dec 14 14:12:18.489938 tap-0000A9D8 ModemManager[1275]: <info>  [1607955138.489923] [modem0] loaded current capabilities: gsm-umts, lte
Dec 14 14:12:18.489947 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.489940] [modem0] setting EPS network as supported
Dec 14 14:12:18.489971 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.489963] [modem0] setting CDMA1x/EVDO networks as unsupported
Dec 14 14:12:18.490049 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.490039] [modem0/ttyUSB2/at] device open count is 3 (open)
Dec 14 14:12:18.490077 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.490067] [modem0/ttyUSB0/qcdm] device open count is 0 (close)
Dec 14 14:12:18.490087 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.490081] [modem0/ttyUSB0/qcdm] closing serial port...
Dec 14 14:12:18.496645 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.496625] [modem0/ttyUSB0/qcdm] serial port closed
Dec 14 14:12:18.496665 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.496657] [modem0/ttyUSB2/at] device open count is 2 (close)
Dec 14 14:12:18.496700 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.496692] [modem0/ttyUSB2/at] --> 'AT+CSCS=?<CR>'
Dec 14 14:12:18.507367 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.507356] [modem0/ttyUSB2/at] <-- '<CR><LF>+CSCS: ("IRA","GSM","UCS2")<CR><LF><CR><LF>OK<CR><LF>'
Dec 14 14:12:18.507471 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.507461] [modem0/ttyUSB2/at] device open count is 3 (open)
Dec 14 14:12:18.507497 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.507488] [modem0/ttyUSB2/at] device open count is 2 (close)
Dec 14 14:12:18.507522 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.507513] [modem0/ttyUSB2/at] --> 'AT+CSCS="UCS2"<CR>'
Dec 14 14:12:18.531246 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.531237] [modem0/ttyUSB2/at] <-- '<CR><LF>ERROR<CR><LF>'
Dec 14 14:12:18.531279 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.531269] [modem0/ttyUSB2/at] operation failure: 100 (Unknown error)
Dec 14 14:12:18.531300 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.531290] [modem0] couldn't set charset 'UCS2': Unknown error
Dec 14 14:12:18.531323 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.531314] [modem0/ttyUSB2/at] device open count is 3 (open)
Dec 14 14:12:18.531347 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.531338] [modem0/ttyUSB2/at] device open count is 2 (close)
Dec 14 14:12:18.531370 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.531361] [modem0/ttyUSB2/at] --> 'AT+CSCS="IRA"<CR>'
Dec 14 14:12:18.545742 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.545734] [modem0/ttyUSB2/at] <-- '<CR><LF>ERROR<CR><LF>'
Dec 14 14:12:18.545773 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.545763] [modem0/ttyUSB2/at] operation failure: 100 (Unknown error)
Dec 14 14:12:18.545792 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.545783] [modem0] couldn't set charset 'IRA': Unknown error
Dec 14 14:12:18.545814 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.545806] [modem0/ttyUSB2/at] device open count is 3 (open)
Dec 14 14:12:18.545836 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.545828] [modem0/ttyUSB2/at] device open count is 2 (close)
Dec 14 14:12:18.545858 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.545850] [modem0/ttyUSB2/at] --> 'AT+CSCS="GSM"<CR>'
Dec 14 14:12:18.560396 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.560365] [modem0/ttyUSB2/at] <-- '<CR><LF>ERROR<CR><LF>'
Dec 14 14:12:18.560444 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.560435] [modem0/ttyUSB2/at] operation failure: 100 (Unknown error)
Dec 14 14:12:18.560479 tap-0000A9D8 ModemManager[1275]: <debug> [1607955138.560470] [modem0] couldn't set charset 'GSM': Unknown error
Dec 14 14:12:18.560492 tap-0000A9D8 ModemManager[1275]: <warn>  [1607955138.560484] [modem0] modem couldn't be initialized: Failed to find a usable modem character set

After that sequence, mmcli gone wild and coredump:

root at tap-0000A9D8:~# mmcli -L

** (mmcli:822): WARNING **: 14:14:41.388: (../../ModemManager-1.14.8/libmm-glib/mm-object.c:135):mm_object_peek_modem: runtime check failed: (MM_IS_MODEM (modem))

** (mmcli:822): CRITICAL **: 14:14:41.388: mm_modem_get_manufacturer: assertion 'MM_IS_MODEM (self)' failed

** (mmcli:822): WARNING **: 14:14:41.388: (../../ModemManager-1.14.8/libmm-glib/mm-object.c:135):mm_object_peek_modem: runtime check failed: (MM_IS_MODEM (modem))

** (mmcli:822): CRITICAL **: 14:14:41.388: mm_modem_get_model: assertion 'MM_IS_MODEM (self)' failed
    /org/freedesktop/ModemManager1/Modem/0 [manufacturer unknown] model unknown
root at tap-0000A9D8:~# mmcli -m 0

** (mmcli:880): WARNING **: 14:14:44.804: (../../ModemManager-1.14.8/libmm-glib/mm-object.c:108):mm_object_get_modem: runtime check failed: (MM_IS_MODEM (modem))

** (mmcli:880): WARNING **: 14:14:44.804: (../../ModemManager-1.14.8/libmm-glib/mm-object.c:108):mm_object_get_modem: runtime check failed: (MM_IS_MODEM (modem))

** (mmcli:880): CRITICAL **: 14:14:44.804: mm_modem_get_supported_capabilities: assertion 'MM_IS_MODEM (self)' failed

** (mmcli:880): CRITICAL **: 14:14:44.804: mm_modem_get_current_capabilities: assertion 'MM_IS_MODEM (self)' failed

** (mmcli:880): CRITICAL **: 14:14:44.804: mm_modem_get_access_technologies: assertion 'MM_IS_MODEM (self)' failed

** (mmcli:880): CRITICAL **: 14:14:44.804: mm_modem_get_supported_modes: assertion 'MM_IS_MODEM (self)' failed

** (mmcli:880): CRITICAL **: 14:14:44.804: mm_modem_get_current_bands: assertion 'MM_IS_MODEM (self)' failed

** (mmcli:880): CRITICAL **: 14:14:44.804: mm_modem_get_supported_bands: assertion 'MM_IS_MODEM (self)' failed

** (mmcli:880): CRITICAL **: 14:14:44.804: mm_modem_get_ports: assertion 'MM_IS_MODEM (self)' failed

** (mmcli:880): CRITICAL **: 14:14:44.804: mm_modem_get_current_modes: assertion 'MM_IS_MODEM (self)' failed

** (mmcli:880): CRITICAL **: 14:14:44.804: mm_modem_get_supported_ip_families: assertion 'MM_IS_MODEM (self)' failed

** (mmcli:880): CRITICAL **: 14:14:44.804: mm_modem_get_unlock_retries: assertion 'MM_IS_MODEM (self)' failed
Segmentation fault (core dumped)

For information I try with ModemManager 1.12.12, the sequence go futher but since I have not yet a usable SIM card , I don't go until charset initialization (I noticed this step was moved to initalization in 1.14.0 , in 1.12.12 , it was in enable steps):

Dec 13 06:22:58.678123 tap ModemManager[1275]: <info>  ModemManager (version 1.12.12) starting in system bus...
Dec 13 06:23:01.237651 tap ModemManager[1275]: <info>  Couldn't check support for device '/sys/devices/pci0000:00/0000:00:1c.3/0000:02:00.0': not supported by any plugin
Dec 13 06:23:29.363958 tap-0000A9D8 ModemManager[1275]: <warn>  (tty/ttyUSB0) failed to parse QCDM version info command result: -7
Dec 13 06:23:30.351456 tap-0000A9D8 ModemManager[1275]: <info>  [device /sys/devices/pci0000:00/0000:00:1c.0/0000:01:00.0/usb4/4-1] creating modem with plugin 'Quectel' and '4' ports
Dec 13 06:23:30.354006 tap-0000A9D8 ModemManager[1275]: <info>  Modem for device '/sys/devices/pci0000:00/0000:00:1c.0/0000:01:00.0/usb4/4-1' successfully created
Dec 13 06:23:30.354451 tap-0000A9D8 ModemManager[1275]: <info>  loading current capabilities...
Dec 13 06:23:30.422541 tap-0000A9D8 ModemManager[1275]: <info>  loaded current capabilities: gsm-umts, lte
Dec 13 06:23:30.437371 tap-0000A9D8 ModemManager[1275]: <info>  loaded manufacturer: Quectel
Dec 13 06:23:30.448234 tap-0000A9D8 ModemManager[1275]: <info>  loaded model: EG25
Dec 13 06:23:30.456844 tap-0000A9D8 ModemManager[1275]: <info>  loaded revision: EG25GGBR07A07M2G
Dec 13 06:23:30.464985 tap-0000A9D8 ModemManager[1275]: <info>  loaded equipment identifier: 867698042725088
Dec 13 06:23:30.465005 tap-0000A9D8 ModemManager[1275]: <info>  loading device identifier...
Dec 13 06:23:30.465059 tap-0000A9D8 ModemManager[1275]: <info>  loaded device identifier: 3183ac7d745cf9d539968c1d1ed6b150e94493e0
Dec 13 06:23:30.465082 tap-0000A9D8 ModemManager[1275]: <info>  loading supported modes...
Dec 13 06:23:30.475545 tap-0000A9D8 ModemManager[1275]: <info>  loading supported IP families...
Dec 13 06:23:30.489929 tap-0000A9D8 ModemManager[1275]: <info>  loading power state...
Dec 13 06:23:30.516050 tap-0000A9D8 ModemManager[1275]: <warn>  Modem couldn't be initialized: Couldn't check unlock status: SIM not inserted
Dec 13 06:23:30.516068 tap-0000A9D8 ModemManager[1275]: <info>  Modem: state changed (unknown -> failed)

Do you already experienced such a behavior (or better, do you have the same model which is working) ? Do you think it is because I have no SIM inserted which make the modem refused to set charset ?

Frédéric Martinsons
Embedded software craftsman
[http://www.sigfox.com/static/media/signature_sigfox_logo_nov16.png]<http://www.sigfox.com>     Bâtiment E-volution - 425, rue Jean Rostand
31670 Labège, France
T: +33 (0)5 82 08 07 41
M: +33 (0)6 72 93 52 01
frederic.martinsons at sigfox.com<mailto:frederic.martinsons at gmail.com>
sigfox.com<http://www.sigfox.com>
[http://www.sigfox.com/static/media/T.png] <https://twitter.com/sigfox> [http://www.sigfox.com/static/media/F.png]  <http://www.facebook.com/sigfox> [http://www.sigfox.com/static/media/L.png]  <http://www.linkedin.com/company/2731408> [http://www.sigfox.com/static/media/Y.png]  <https://www.youtube.com/sigfox>

[cid:429784ca-35a9-42bc-8c36-530b415f1e79]<https://live.sigfoxconnect.com/>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20201217/103086c5/attachment-0001.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: Outlook-x1mfbqo4.png
Type: image/png
Size: 408475 bytes
Desc: Outlook-x1mfbqo4.png
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20201217/103086c5/attachment-0001.png>