The loading order of plugins

Tue Oct 9 09:50:54 UTC 2018

Hi,

matthew stanger <stangerm2 at gmail.com> 於 2018年10月9日 週二 上午2:48寫道：

> Hi Ken,
>
> Given the datasheet Dan linked it seems like that modem family does
> support the 'SWWAN' connection interface type. Given that I'd expect basic
> connection attempts to work. Can you enable MM debugging and post the logs
> of a connection attempt? I'm sure we can get the plugin to support this
> modem properly.
>
> I tried to connect with the Cinterion plugin:
---
$ mmcli -m 0 --simple-connect="apn=internet"
error: couldn't connect the modem:
'GDBus.Error:org.freedesktop.ModemManager1.Error.MobileEquipment.Unknown:
Unknown error'
---

The MM debug log showed below:
---
ModemManager[16877]: <info>  [1539104650.509401] ModemManager (version
1.8.2) starting in system bus...

...

ModemManager[16877]: <info>  [1539104666.882872] [device
/sys/devices/platform/ocp/47400000.usb/47401400.usb/musb-hdrc.0.auto/usb1/1-1]
creating modem with plugin 'Cinterion' and '7' ports

...

ModemManager[16877]: <info>  [1539104726.574932] Simple connect state
(4/8): Wait to get fully enabled
ModemManager[16877]: <info>  [1539104726.575178] Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (enabling -> enabled)
ModemManager[16877]: <info>  [1539104726.581605] Simple connect state
(5/8): Register
ModemManager[16877]: <debug> [1539104726.591762] Launching automatic
network registration...
ModemManager[16877]: <debug> [1539104726.592588] (ttyACM0) device open
count is 2 (open)
ModemManager[16877]: <debug> [1539104726.593468] Running registration
checks (CS: 'yes', PS: 'yes', EPS: 'yes')
ModemManager[16877]: <debug> [1539104726.594093] (ttyACM0) device open
count is 3 (open)
ModemManager[16877]: <debug> [1539104726.599229] (ttyACM0): -->
'AT+COPS=0<CR>'
ModemManager[16877]: <debug> [1539104726.871750] (ttyACM0): <--
'<CR><LF>OK<CR><LF>'
ModemManager[16877]: <debug> [1539104726.872422] Running registration
checks (CS: 'yes', PS: 'yes', EPS: 'yes')
ModemManager[16877]: <debug> [1539104726.872650] (ttyACM0) device open
count is 4 (open)
ModemManager[16877]: <debug> [1539104726.872842] (ttyACM0) device open
count is 3 (close)
ModemManager[16877]: <debug> [1539104726.873058] (ttyACM0): -->
'AT+CREG?<CR>'
ModemManager[16877]: <debug> [1539104726.901797] (ttyACM0): <--
'<CR><LF>+CREG: 2,1,"2817","0275070D",7<CR><LF>'
ModemManager[16877]: <info>  [1539104726.902306] Modem
/org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed
(unknown -> registering)
ModemManager[16877]: <debug> [1539104726.902490] loading Operator Code...
ModemManager[16877]: <debug> [1539104726.902631] (ttyACM0) device open
count is 4 (open)
ModemManager[16877]: <debug> [1539104726.902805] (ttyACM0) device open
count is 5 (open)
ModemManager[16877]: <debug> [1539104726.903010] Modem
/org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0',
MNC: '0', Location area code: '2817', Cell ID: '275070D')
ModemManager[16877]: <debug> [1539104726.912133] (ttyACM0): <--
'<CR><LF>OK<CR><LF>'
ModemManager[16877]: <debug> [1539104726.913176] (ttyACM0) device open
count is 6 (open)
ModemManager[16877]: <debug> [1539104726.913763] (ttyACM0) device open
count is 5 (close)
ModemManager[16877]: <debug> [1539104726.914355] (ttyACM0): -->
'AT+CREG?<CR>'
ModemManager[16877]: <debug> [1539104726.938810] (ttyACM0): <--
'<CR><LF>+CREG: 2,1,"2817","0275070D",7<CR><LF>'
ModemManager[16877]: <debug> [1539104726.946157] (ttyACM0): <--
'<CR><LF>OK<CR><LF>'
ModemManager[16877]: <debug> [1539104726.946686] (ttyACM0) device open
count is 6 (open)
ModemManager[16877]: <debug> [1539104726.946880] (ttyACM0) device open
count is 5 (close)
ModemManager[16877]: <debug> [1539104726.947085] (ttyACM0): -->
'AT+COPS=3,2<CR>'
ModemManager[16877]: <debug> [1539104726.980321] (ttyACM0): <--
'<CR><LF>OK<CR><LF>'
ModemManager[16877]: <debug> [1539104726.980764] (ttyACM0) device open
count is 4 (close)
ModemManager[16877]: <debug> [1539104726.981000] (ttyACM0): -->
'AT+COPS?<CR>'
ModemManager[16877]: <debug> [1539104727.007466] (ttyACM0): <--
'<CR><LF>+COPS: 0,2,"00340036003600390032",7<CR><LF>'
ModemManager[16877]: <debug> [1539104727.013676] (ttyACM0): <--
'<CR><LF>OK<CR><LF>'
ModemManager[16877]: <debug> [1539104727.014463] loaded Operator Code: 46692
ModemManager[16877]: <debug> [1539104727.014866] Modem
/org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '466',
MNC: '92', Location area code: '2817', Cell ID: '275070D')
ModemManager[16877]: <debug> [1539104727.014993] loading Operator Name...
ModemManager[16877]: <debug> [1539104727.015115] (ttyACM0) device open
count is 5 (open)
ModemManager[16877]: <debug> [1539104727.015287] (ttyACM0) device open
count is 6 (open)
ModemManager[16877]: <debug> [1539104727.015418] (ttyACM0) device open
count is 5 (close)
ModemManager[16877]: <debug> [1539104727.024610] (ttyACM0): -->
'AT+CGREG?<CR>'
ModemManager[16877]: <debug> [1539104727.053901] (ttyACM0): <--
'<CR><LF>+CGREG: 2,1,"FFFF","0275070D",7,"FF"<CR><LF>'
ModemManager[16877]: <debug> [1539104727.054411] Modem
/org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '466',
MNC: '92', Location area code: 'FFFF', Cell ID: '275070D')
ModemManager[16877]: <debug> [1539104727.063875] (ttyACM0): <--
'<CR><LF>OK<CR><LF>'
ModemManager[16877]: <debug> [1539104727.064409] (ttyACM0) device open
count is 6 (open)
ModemManager[16877]: <debug> [1539104727.064616] (ttyACM0) device open
count is 5 (close)
ModemManager[16877]: <debug> [1539104727.064818] (ttyACM0): -->
'AT+CGREG?<CR>'
ModemManager[16877]: <debug> [1539104727.089190] (ttyACM0): <--
'<CR><LF>+CGREG: 2,1,"FFFF","0275070D",7,"FF"<CR><LF>'
ModemManager[16877]: <debug> [1539104727.094785] (ttyACM0): <--
'<CR><LF>OK<CR><LF>'
ModemManager[16877]: <debug> [1539104727.095312] (ttyACM0) device open
count is 6 (open)
ModemManager[16877]: <debug> [1539104727.095506] (ttyACM0) device open
count is 5 (close)
ModemManager[16877]: <debug> [1539104727.095706] (ttyACM0): -->
'AT+COPS=3,0<CR>'
ModemManager[16877]: <debug> [1539104727.124460] (ttyACM0): <--
'<CR><LF>OK<CR><LF>'
ModemManager[16877]: <debug> [1539104727.124900] (ttyACM0) device open
count is 4 (close)
ModemManager[16877]: <debug> [1539104727.125127] (ttyACM0): -->
'AT+COPS?<CR>'
ModemManager[16877]: <debug> [1539104727.149321] (ttyACM0): <--
'<CR><LF>+COPS:
0,0,"004300680075006E0067006800770061002000540065006C00650063006F006D",7<CR><LF>'
ModemManager[16877]: <debug> [1539104727.154996] (ttyACM0): <--
'<CR><LF>OK<CR><LF>'
ModemManager[16877]: <debug> [1539104727.155727] loaded Operator Name:
Chunghwa Telecom
ModemManager[16877]: <debug> [1539104727.156115] (ttyACM0) device open
count is 3 (close)
ModemManager[16877]: <info>  [1539104727.164643] Modem
/org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed
(registering -> home)
ModemManager[16877]: <debug> [1539104727.170406] Will start keeping track
of state for subsystem '3gpp'
ModemManager[16877]: <info>  [1539104727.171159] Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (enabled ->
registered)
ModemManager[16877]: <debug> [1539104727.172021] Network timezone polling
started
ModemManager[16877]: <debug> [1539104727.183760] Periodic signal checks
enabled
ModemManager[16877]: <debug> [1539104727.184490] Periodic signal check
refresh requested
ModemManager[16877]: <debug> [1539104727.185003] loading signal quality...
ModemManager[16877]: <debug> [1539104727.185454] (ttyACM0) device open
count is 4 (open)
ModemManager[16877]: <debug> [1539104727.203464] (ttyACM0): -->
'AT+CEREG?<CR>'
ModemManager[16877]: <debug> [1539104727.231681] (ttyACM0): <--
'<CR><LF>+CEREG: 2,1,"3138","0275070D",7<CR><LF>'
ModemManager[16877]: <debug> [1539104727.232235] Modem
/org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '466',
MNC: '92', Location area code: '3138', Cell ID: '275070D')
ModemManager[16877]: <debug> [1539104727.237645] (ttyACM0): <--
'<CR><LF>OK<CR><LF>'
ModemManager[16877]: <debug> [1539104727.238072] Initial 3GPP registration
checks finished
ModemManager[16877]: <debug> [1539104727.238228] (ttyACM0) device open
count is 3 (close)
ModemManager[16877]: <debug> [1539104727.238417] (ttyACM0): -->
'AT+CEREG?<CR>'
ModemManager[16877]: <debug> [1539104727.261499] (ttyACM0): <--
'<CR><LF>+CEREG: 2,1,"3138","0275070D",7<CR><LF>'
ModemManager[16877]: <debug> [1539104727.267221] (ttyACM0): <--
'<CR><LF>OK<CR><LF>'
ModemManager[16877]: <debug> [1539104727.267652] Periodic signal check
refresh ignored: check already running
ModemManager[16877]: <debug> [1539104727.267752] Modem is currently
registered in a 3GPP network
ModemManager[16877]: <info>  [1539104727.267828] Simple connect state
(6/8): Bearer
ModemManager[16877]: <debug> [1539104727.267950] Creating new bearer...
ModemManager[16877]: <debug> [1539104727.268097] checking ^SWWAN support...
ModemManager[16877]: <debug> [1539104727.268221] (ttyACM0) device open
count is 4 (open)
ModemManager[16877]: <debug> [1539104727.268438] (ttyACM0) device open
count is 3 (close)
ModemManager[16877]: <debug> [1539104727.268634] (ttyACM0): --> 'AT+CSQ<CR>'
ModemManager[16877]: <debug> [1539104727.290363] (ttyACM0): <--
'<CR><LF>+CSQ: 6,99<CR><LF>'
ModemManager[16877]: <debug> [1539104727.295940] (ttyACM0): <--
'<CR><LF>OK<CR><LF>'
ModemManager[16877]: <debug> [1539104727.296820] Modem
/org/freedesktop/ModemManager1/Modem/0: signal quality updated (19)
ModemManager[16877]: <debug> [1539104727.297117] (ttyACM0) device open
count is 2 (close)
ModemManager[16877]: <debug> [1539104727.300858] Polling to refresh access
technologies is unsupported
ModemManager[16877]: <debug> [1539104727.301630] Periodic signal quality
checks scheduled in 30s
ModemManager[16877]: <debug> [1539104727.302306] (ttyACM0): -->
'AT^SWWAN=?<CR>'
ModemManager[16877]: <debug> [1539104727.334295] (ttyACM0): <--
'<CR><LF>^SWWAN: (0,1), (1-11), (1,2)<CR><LF>'
ModemManager[16877]: <debug> [1539104727.340078] (ttyACM0): <--
'<CR><LF>OK<CR><LF>'
ModemManager[16877]: <debug> [1539104727.340501] SWWAN supported
ModemManager[16877]: <debug> [1539104727.340596] ^SWWAN supported, creating
cinterion bearer...
ModemManager[16877]: <debug> [1539104727.342751] (ttyACM0) device open
count is 3 (open)
ModemManager[16877]: <debug> [1539104727.342977] (ttyACM0) device open
count is 2 (close)
ModemManager[16877]: <info>  [1539104727.354008] Simple connect state
(7/8): Connect
ModemManager[16877]: <debug> [1539104727.354807] Connecting bearer
'/org/freedesktop/ModemManager1/Bearer/0'
ModemManager[16877]: <info>  [1539104727.355470] Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (registered ->
connecting)
ModemManager[16877]: <debug> [1539104727.361578] Launching 3GPP connection
attempt with APN 'internet'
ModemManager[16877]: <debug> [1539104727.362304] No specific IP family
requested, defaulting to ipv4
ModemManager[16877]: <debug> [1539104727.362860] No specific IP family
requested, defaulting to ipv4
ModemManager[16877]: <debug> [1539104727.363230] Looking for best CID...
ModemManager[16877]: <debug> [1539104727.363747] (ttyACM0) device open
count is 3 (open)
ModemManager[16877]: <debug> [1539104727.364320] (ttyACM0) device open
count is 2 (close)
ModemManager[16877]: <debug> [1539104727.364846] (ttyACM0): -->
'AT+CGDCONT?<CR>'
ModemManager[16877]: <debug> [1539104727.395135] (ttyACM0): <--
'<CR><LF>+CGDCONT:
1,"IP","internet.mnc092.mcc466.gprs","",0,0<CR><LF><CR><LF>+CGDCONT:
2,"IP","internet","",0,0<CR><LF>'
ModemManager[16877]: <debug> [1539104727.400870] (ttyACM0): <--
'<CR><LF>OK<CR><LF>'
ModemManager[16877]: <debug> [1539104727.401635] Found '2' PDP contexts
ModemManager[16877]: <debug> [1539104727.401763]   PDP context [cid=1]
[type='ipv4'] [apn='internet.mnc092.mcc466.gprs']
ModemManager[16877]: <debug> [1539104727.401832]   PDP context [cid=2]
[type='ipv4'] [apn='internet']
ModemManager[16877]: <debug> [1539104727.401920] Found PDP context with CID
1 and PDP type ipv4 for APN 'internet'
ModemManager[16877]: <debug> [1539104727.402175] No specific IP family
requested, defaulting to ipv4
ModemManager[16877]: <debug> [1539104727.402274] cinterion dial step 1/4:
authentication not required
ModemManager[16877]: <debug> [1539104727.402335] cinterion dial step 2/4:
starting SWWAN interface 1 connection...
ModemManager[16877]: <debug> [1539104727.402488] (ttyACM0) device open
count is 3 (open)
ModemManager[16877]: <debug> [1539104727.402693] (ttyACM0) device open
count is 2 (close)
ModemManager[16877]: <debug> [1539104727.402892] (ttyACM0): -->
'AT^SWWAN=1,1,1<CR>'
ModemManager[16877]: <debug> [1539104732.855684] (ttyACM0) device open
count is 3 (open)
ModemManager[16877]: <debug> [1539104752.457754] (ttyACM0): <--
'<CR><LF>+CME ERROR: 100<CR><LF>'
ModemManager[16877]: <debug> [1539104752.458162] Got failure code 100:
Unknown error
ModemManager[16877]: <debug> [1539104752.458391] Couldn't connect bearer
'/org/freedesktop/ModemManager1/Bearer/0': 'Unknown error'
ModemManager[16877]: <info>  [1539104752.458611] Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (connecting ->
registered)
ModemManager[16877]: <debug> [1539104752.473223] Couldn't connect bearer:
'Unknown error'
ModemManager[16877]: <debug> [1539104752.485584] (ttyACM0) device open
count is 2 (close)
ModemManager[16877]: <debug> [1539104752.487708] (ttyACM0): -->
'AT+CCLK?<CR>'
ModemManager[16877]: <debug> [1539104752.516056] (ttyACM0): <--
'<CR><LF>+CCLK: "18/10/09,17:10:02+32"<CR><LF>'
ModemManager[16877]: <debug> [1539104752.525276] (ttyACM0): <--
'<CR><LF>OK<CR><LF>'
ModemManager[16877]: <debug> [1539104752.526335] (ttyACM0) device open
count is 1 (close)
ModemManager[16877]: <debug> [1539104752.666068] (ttyACM0): <--
'<CR><LF>+CREG: 0<CR><LF><CR><LF>+CIEV:
psinfo,16<CR><LF><CR><LF><CR><LF>+CEREG: 0<CR><LF>'
ModemManager[16877]: <debug> [1539104752.667332] (ttyACM1): <--
'<CR><LF>+CREG: 0<CR><LF><CR><LF>+CEREG: 0<CR><LF>'
ModemManager[16877]: <debug> [1539104753.119437] (ttyACM0): <--
'<CR><LF>+CREG: 1,"2817","0275070D",7<CR><LF><CR><LF>+CIEV:
psinfo,17<CR><LF><CR><LF><CR><LF>+CEREG: 1,"3138","0275070D",7<CR><LF>'
ModemManager[16877]: <debug> [1539104753.120096] Modem
/org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '466',
MNC: '92', Location area code: '2817', Cell ID: '275070D')
ModemManager[16877]: <debug> [1539104753.120303] Modem
/org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '466',
MNC: '92', Location area code: '3138', Cell ID: '275070D')
ModemManager[16877]: <debug> [1539104753.121149] (ttyACM1): <--
'<CR><LF>+CREG: 1,"2817","0275070D",7<CR><LF><CR><LF>+CEREG:
1,"3138","0275070D",7<CR><LF>'
ModemManager[16877]: <debug> [1539104753.122105] Modem
/org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '466',
MNC: '92', Location area code: '2817', Cell ID: '275070D')
ModemManager[16877]: <debug> [1539104753.122646] Modem
/org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '466',
MNC: '92', Location area code: '3138', Cell ID: '275070D')
ModemManager[16877]: <debug> [1539104757.852152] loading signal quality...
ModemManager[16877]: <debug> [1539104757.852500] (ttyACM0) device open
count is 2 (open)
ModemManager[16877]: <debug> [1539104757.852766] (ttyACM0): --> 'AT+CSQ<CR>'
ModemManager[16877]: <debug> [1539104757.878920] (ttyACM0): <--
'<CR><LF>+CSQ: 7,99<CR><LF>'
ModemManager[16877]: <debug> [1539104757.888216] (ttyACM0): <--
'<CR><LF>OK<CR><LF>'
ModemManager[16877]: <debug> [1539104757.889018] Modem
/org/freedesktop/ModemManager1/Modem/0: signal quality updated (22)
ModemManager[16877]: <debug> [1539104757.889186] Periodic signal quality
checks scheduled in 30s
ModemManager[16877]: <debug> [1539104757.889316] (ttyACM0) device open
count is 1 (close)
---

> Also what is your hardware interface setup & AT^SSRVSET setup?
>

My AT^SSRVSET setup is value "1" ( ECM ), and I can't switch to value "10"
( NCM ).
The datasheet is here:
https://www.seapraha.cz/wp-content/uploads/2017/08/els61-e_atc_01000.pdf
Slightly different from "els61-e2".

regards,
Ken

On Mon, Oct 8, 2018 at 12:36 PM Dan Williams <dcbw at redhat.com> wrote:
>
>> On Mon, 2018-10-08 at 18:16 +0200, Aleksander Morgado wrote:
>> > Hey,
>> >
>> > > I'm now working on a modem "Cinterion Gemalto ELS61". And I tried
>> > > to use it with ModemManager.
>> > > ModemManager suggests the "Cinterion" plugin. But somehow, the AT
>> > > command set and some response message format of "Cinterion Gemalto
>> > > ELS61" is different from other modems supported by the "Cinterion"
>> > > plugin. So I wrote a plugin named "G-ELS61" especially for it.
>> > >
>> > > The question is, both "Cinterion" plugin and "G-ELS61" plugin
>> > > support modem "Cinterion Gemalto ELS61". ModemManager will select
>> > > the prior loaded plugin as best-plugin.
>> > > While the order of loading plugins is not fixed in ModemManager
>> > > (Since "readdir()" returns entries in the order that files are
>> > > linked in filesystem). That means ModemManager may use different
>> > > plugin for the same modem on different devices.
>> > >
>> > > Currently, I use a simple workaround to solve the issue. I sort the
>> > > loading order by the plugins' filename before loading. So that I
>> > > can control the loading order of my plugin by its filename. The
>> > > diff log is attached below:
>> > >
>> >
>> > Plugins can say "I don't support this specific device", and so in
>> > your
>> > case you could update the Cinterion plugin so that the specific
>> > vid:pid is listed in MM_PLUGIN_FORBIDDEN_PRODUCT_IDS, and then the
>> > order of loading of plugins is irrelevant, see:
>> > https://www.freedesktop.org/software/ModemManager/api/latest/ref-over
>> > view-modem-port-probing.html#id-1.2.5.4.
>> >
>> > BUT, why is it that the modem cannot be supported by the Cinterion
>> > plugin? Which are the commands that are different? Can the Cinterion
>> > plugin not be updated to support this new model as well?
>>
>> If it helps to figure that out:
>>
>> https://developer.gemalto.com/sites/default/files/els61-e2_atc_01000.pdf
>>
>> Dan
>> _______________________________________________
>> ModemManager-devel mailing list
>> ModemManager-devel at lists.freedesktop.org
>> https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20181009/c535c199/attachment-0001.html>