Need help troubleshooting Quectel EG25 modem in Pine64 Pinephone

Wed Jun 9 08:24:51 UTC 2021

Hello,

> If Roaming is enabled, the modem will check to see if it is able to
> roam on any other carriers.  In your case the O2 network is marked as
> "forbidden" and so it seems that you don't have an O2 SIM ... or it's
> not active or  something strange is going on.

Yes, I find it highly fascinating. I'm pretty sure it's an O2 SIM,
otherwise I've been scammed.

Today I did some more basic tests and I saw that when I repeatedly call
"--3gpp-register-home" the "operator id" in the output of "mmcli -m 0"
will change every now and then. In the course of 2 minutes, the modem
was connected to all the 3 operator networks that "--3gpp-scan"
reports. Is this supposed to happen?

Also I cannot force the modem to connect to any specific operator: 

    $ mmcli -m 0 --3gpp-register-in-operator=26203 --timeout=300
    error: couldn't register the modem:
'GDBus.Error:org.freedesktop.ModemManager1.Error.MobileEquipment.Networ
kTimeout: Network timeout'

26203 is o2 according to a 3GPP scan, my SIM card is from o2 as well,
so why doesn't this work then?

In systemctl I saw the following output after repeatedly issuing the
3gpp-register-home command:

```
Jun 09 09:58:14 fedora ModemManager[411]: <info>  [modem0] state
changed (locked -> initializing)
Jun 09 09:58:14 fedora ModemManager[411]: <warn>  [modem0] couldn't
query SIM slots: QMI protocol error (94): 'NotSupported'
Jun 09 09:58:15 fedora ModemManager[411]: <warn>  [modem0] couldn't
load supported assistance data types: LOC service: general failure
Jun 09 09:58:15 fedora ModemManager[411]: <info>  [modem0] state
changed (initializing -> disabled)
Jun 09 09:58:15 fedora ModemManager[411]: <info>  [modem0] state
changed (disabled -> enabling)
Jun 09 09:58:15 fedora ModemManager[411]: <info>  [modem0] 3GPP
registration state changed (unknown -> idle)
Jun 09 09:58:16 fedora ModemManager[411]: <info>  [modem0] state
changed (enabling -> enabled)
Jun 09 09:58:16 fedora ModemManager[411]: <warn>  [modem0] couldn't
load operator code: Current operator MCC/MNC is still unknown
Jun 09 09:58:16 fedora ModemManager[411]: <warn>  [modem0] couldn't
load operator name: Current operator description is still unknown
Jun 09 09:58:29 fedora ModemManager[411]: <info>  [modem0] simple
connect started...
Jun 09 09:58:29 fedora ModemManager[411]: <info>  [modem0] simple
connect state (4/8): wait to get fully enabled
Jun 09 09:58:29 fedora ModemManager[411]: <info>  [modem0] simple
connect state (5/8): register
Jun 09 10:02:56 fedora ModemManager[411]: <info>  [modem0] 3GPP
registration state changed (idle -> unknown)
Jun 09 10:02:56 fedora ModemManager[411]: <warn>  [modem0] couldn't
load operator code: Current operator MCC/MNC is still unknown
Jun 09 10:02:56 fedora ModemManager[411]: <warn>  [modem0] couldn't
load operator name: Current operator description is still unknown
Jun 09 10:02:56 fedora ModemManager[411]: <info>  [modem0] 3GPP
registration state changed (unknown -> idle)
Jun 09 10:05:48 fedora ModemManager[411]: <info>  [modem0] 3GPP
registration state changed (idle -> unknown)
Jun 09 10:05:48 fedora ModemManager[411]: <warn>  [modem0] couldn't
load operator code: Current operator MCC/MNC is still unknown

```

> Have you tried the Vodafone APN since you seem to be connecting to
> Vodafone?

I have, but the result doesn't change. Also with the current operator
of the modem constantly changing, how should I handle entering the
"correct" APN.

> There might be some real value in seeing what the "More outputs"  are
> ... they might be valuable to see.

Allright, below is the entire output:

```
Jun 04 08:59:02 dhcp-10-132-126-186 ModemManager[6634]: <info>  [base-
manager] couldn't check support for device
'/sys/devices/platform/soc/1c10000.mmc/mmc_host/mmc1/mmc1:0001/mmc1:000
1:1': not supported by any plugin
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: <info>  [device
/sys/devices/platform/soc/1c1b000.usb/usb5/5-1] creating modem with
plugin 'quectel' and '6' ports
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: <warn> 
[plugin/quectel] could not grab port ttyUSB3: Cannot add port
'tty/ttyUSB3', unhandled port type
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: <info>  [base-
manager] modem for device
'/sys/devices/platform/soc/1c1b000.usb/usb5/5-1' successfully created
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Opening device with flags 'version-info, proxy'...
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
created endpoint
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Checking version info (25 retries)...
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
QMI Device supports 30 services:
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
ctl (1.5)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
wds (1.67)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
dms (1.0)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
nas (1.25)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
qos (1.12)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
wms (1.10)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
auth (1.3)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
at (1.2)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
voice (2.1)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
cat2 (2.24)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
uim (1.46)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
pbm (1.4)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
test (1.0)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
loc (2.0)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
sar (1.0)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
ims (1.0)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
ts (1.0)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
tmd (1.0)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
wda (1.16)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
csvt (1.1)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
imsp (1.0)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
imsa (1.0)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
coex (1.0)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
pdc (1.0)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
rfrpe (1.0)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
dsd (1.0)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
unknown [0x2d] (1.0)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
unknown [0x30] (1.0)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
unknown [0x32] (1.0)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
unknown [0x36] (1.0)
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Allocating new client ID...
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Registered 'wda' (version 1.16) client with ID '1'
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Allocating new client ID...
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Releasing 'wda' client with flags 'release-cid'...
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Unregistered 'wda' client with ID '1'
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Registered 'dms' (version 1.0) client with ID '4'
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Allocating new client ID...
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Registered 'nas' (version 1.25) client with ID '4'
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Allocating new client ID...
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Registered 'wds' (version 1.67) client with ID '5'
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Allocating new client ID...
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Registered 'wms' (version 1.10) client with ID '4'
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Allocating new client ID...
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Registered 'uim' (version 1.46) client with ID '4'
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Allocating new client ID...
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Registered 'loc' (version 2.0) client with ID '4'
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Allocating new client ID...
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Registered 'pdc' (version 1.0) client with ID '4'
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Allocating new client ID...
Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Registered 'voice' (version 2.1) client with ID '5'
Jun 04 08:59:10 dhcp-10-132-126-186 ModemManager[6634]: <warn> 
[modem0] couldn't query SIM slots: QMI protocol error (94):
'NotSupported'
Jun 04 08:59:11 dhcp-10-132-126-186 ModemManager[6634]: <warn> 
[modem0] couldn't load supported assistance data types: LOC service:
general failure
Jun 04 08:59:11 dhcp-10-132-126-186 ModemManager[6634]: <info> 
[modem0] state changed (unknown -> disabled)
Jun 04 08:59:11 dhcp-10-132-126-186 ModemManager[6634]: <info> 
[modem0] state changed (disabled -> enabling)
Jun 04 08:59:11 dhcp-10-132-126-186 ModemManager[6634]: <info> 
[modem0] 3GPP registration state changed (unknown -> idle)
Jun 04 08:59:12 dhcp-10-132-126-186 ModemManager[6634]: <info> 
[modem0] state changed (enabling -> enabled)
Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <info> 
[modem0] simple connect started...
Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <info> 
[modem0] simple connect state (4/8): wait to get fully enabled
Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <info> 
[modem0] simple connect state (5/8): register
Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <info> 
[modem0] simple connect state (6/8): bearer
Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <info> 
[modem0] simple connect state (7/8): connect
Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <info> 
[modem0] state changed (enabled -> connecting)
Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Allocating new client ID...
Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-wdm0]
Registered 'wds' (version 1.67) client with ID '6'
Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <info> 
[modem0/bearer0] couldn't start network: QMI protocol error (14):
'CallFailed'
Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <info> 
[modem0/bearer0] call end reason (3): generic-no-service
Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <info> 
[modem0/bearer0] verbose call end reason (3,2001): [cm] no-service
Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <warn> 
[modem0/bearer0] connection attempt #1 failed: QMI protocol error (14):
'CallFailed'
Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <info> 
[modem0] state changed (connecting -> enabled)
Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <info> 
[modem0/bearer0] connection #1 finished: duration 0s, tx: 0 bytes, rx
:0 bytes
```

Thanks for the continued help!

Andreas

On Mon, 2021-06-07 at 09:07 -0600, Scott Lemon wrote:
> On Sat, Jun 5, 2021 at 8:41 AM Andreas Hartmann <hartan at 7x.de> wrote:
> > Hello,
> > 
> > 
> > >    1. The SIM is sold by a "carrier" (or MNO or MVNO) and contains
> > > a
> > > credential (the IMSI) that will have a prefix that corresponds to
> > the
> > > MCC/MNC.  If you bought the new SIM from O2, then the modem should
> > > register on O2.
> > 
> > Thanks for clarifying. What would make a SIM (or mmcli) decide to try
> > and register in another carriers network, then?
> > 
> 
> 
> If Roaming is enabled, the modem will check to see if it is able to
> roam on any other carriers.  In your case the O2 network is marked as
> "forbidden" and so it seems that you don't have an O2 SIM ... or it's
> not active or  something strange is going on.
>  
> > >    2. Inserting the SIM *should* then show that the registration
> > > has
> > > occurred with that carrier when you do the scan.
> > 
> > Yep, I thought so. That's what pretty much every other PinePhone user
> > I've talked to has reported to me.
> > 
> > >    3. Each SIM/Carrier/MNO/MVNO has their own APN that you must
> > > provide in most cases.
> > 
> > I did do that. I've looked at various places in the internet, they
> > all
> > listed the exact same APN for O2 in this case. But it didn't work
> > regardless.
> > 
> 
> 
> Have you tried the Vodafone APN since you seem to be connecting to
> Vodafone?
>  
> > > There is a "AT Command
> > > Tester" tool for Windows, and they provide a Quectel specific
> > > version, if you want to experiment and learn.
> > 
> > That's good to know, thanks. Unfortunately the modem is baked into an
> > embedded device, and there's no way I will get it out of there or
> > Windows running on that device. I was thinking of entirely killing
> > the
> > ModemManager before attempting to fiddle with AT commands.
> > 
> > On a sidenote I decided to try some more mmcli options at my modem
> > and
> > I got the QMI call error again. Here's an excerpt from systemctl,
> > note
> > that I attempted to perform a simple connect using the O2 APN (which
> > can be seen at the bottom of this output). Maybe anyone can read
> > something from that? Should the "warning" related to the SIM card
> > make
> > me worry?
> > 
> 
> 
> At this point, you'd need a Modem Manager expert to reply.  It does
> seem to say that it's not finding the SIM for some reason?
>  
> > ```
> > Jun 04 08:59:02 dhcp-10-132-126-186 ModemManager[6634]: <info> 
> > [base-
> > manager] couldn't check support for device
> > '/sys/devices/platform/soc/1c10000.mmc/mmc_host/mmc1/mmc1:0001/mmc1:0
> > 00
> > 1:1': not supported by any plugin
> > Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: <info> 
> > [device
> > /sys/devices/platform/soc/1c1b000.usb/usb5/5-1] creating modem with
> > plugin 'quectel' and '6' ports
> > Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: <warn> 
> > [plugin/quectel] could not grab port ttyUSB3: Cannot add port
> > 'tty/ttyUSB3', unhandled port type
> > Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: <info> 
> > [base-
> > manager] modem for device
> > '/sys/devices/platform/soc/1c1b000.usb/usb5/5-1' successfully created
> > Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-
> > wdm0]
> > Opening device with flags 'version-info, proxy'...
> > Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-
> > wdm0]
> > created endpoint
> > Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-
> > wdm0]
> > Checking version info (25 retries)...
> > Jun 04 08:59:08 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-
> > wdm0]
> > QMI Device supports 30 services:
> > 
> > [ ... More outputs here ... ]
> > 
> 
> 
> There might be some real value in seeing what the "More outputs"  are
> ... they might be valuable to see.
>  
> > Jun 04 08:59:10 dhcp-10-132-126-186 ModemManager[6634]: <warn> 
> > [modem0] couldn't query SIM slots: QMI protocol error (94):
> > 'NotSupported'
> > Jun 04 08:59:11 dhcp-10-132-126-186 ModemManager[6634]: <warn> 
> > [modem0] couldn't load supported assistance data types: LOC service:
> > general failure
> > Jun 04 08:59:11 dhcp-10-132-126-186 ModemManager[6634]: <info> 
> > [modem0] state changed (unknown -> disabled)
> > Jun 04 08:59:11 dhcp-10-132-126-186 ModemManager[6634]: <info> 
> > [modem0] state changed (disabled -> enabling)
> > Jun 04 08:59:11 dhcp-10-132-126-186 ModemManager[6634]: <info> 
> > [modem0] 3GPP registration state changed (unknown -> idle)
> > Jun 04 08:59:12 dhcp-10-132-126-186 ModemManager[6634]: <info> 
> > [modem0] state changed (enabling -> enabled)
> > Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <info> 
> > [modem0] simple connect started...
> > Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <info> 
> > [modem0] simple connect state (4/8): wait to get fully enabled
> > Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <info> 
> > [modem0] simple connect state (5/8): register
> > Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <info> 
> > [modem0] simple connect state (6/8): bearer
> > Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <info> 
> > [modem0] simple connect state (7/8): connect
> > Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <info> 
> > [modem0] state changed (enabled -> connecting)
> > Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-
> > wdm0]
> > Allocating new client ID...
> > Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: [/dev/cdc-
> > wdm0]
> > Registered 'wds' (version 1.67) client with ID '6'
> > Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <info> 
> > [modem0/bearer0] couldn't start network: QMI protocol error (14):
> > 'CallFailed'
> > Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <info> 
> > [modem0/bearer0] call end reason (3): generic-no-service
> > Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <info> 
> > [modem0/bearer0] verbose call end reason (3,2001): [cm] no-service
> > Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <warn> 
> > [modem0/bearer0] connection attempt #1 failed: QMI protocol error
> > (14):
> > 'CallFailed'
> > Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <info> 
> > [modem0] state changed (connecting -> enabled)
> > Jun 04 08:59:39 dhcp-10-132-126-186 ModemManager[6634]: <info> 
> > [modem0/bearer0] connection #1 finished: duration 0s, tx: 0 bytes, rx
> > :0 bytes
> > 
> > ```
> > 
> > 
> > Thanks again!
> > 
> > Andreas
> > 
> _______________________________________________
> ModemManager-devel mailing list
> ModemManager-devel at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 228 bytes
Desc: This is a digitally signed message part
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20210609/84932513/attachment-0001.sig>