Huawei ME909s-120 registration denied

Tue Mar 27 13:28:06 UTC 2018

On 16 March 2018 at 22:51, Dan Williams <dcbw at redhat.com> wrote:

> On Wed, 2018-03-14 at 16:41 +0000, Hugh Warrington wrote:
> > 1. Is registration denied a recoverable error -- and if so should I
> > expect
> > modemmanager to retry registration?
>
> It's recoverable to the extent that you can attempt to manually
> register with another network, or you could airplane-mode-then-retry
> registration to the same network and see if it works, or you could
> change the preferred access technology.  But usually, if the network
> denies you, that same network will deny you again.
>

I've written a script to repeatedly reset the modem and see if registration
succeeds. After hundreds of trials I've found that registration seems to
succeed or fail at random in this case.

It doesn't make sense to me, and having spoken to the network it makes no
sense to them either. I had a support call in which they performed a 'live
trace'. On the attempts where registration was denied they saw nothing
whatsoever in their logs (not even a connection attempt) and the support
call ended with a big shrug.

What's more, some SIMs from the same provider display this intermittent
failure mode while others work every time. But putting the SIMs in a
different device with a Quectel modem, they work every time. So the problem
seems to be the combination of modem model and SIM (for completeness I also
tested in other identical instances of the same modem/PC, with the same
results).

>From what you say it sounds like registration denied shouldn't be a
'routine' failure mode. But is there any option to have modemmanger
automatically retry? If not then I will just write a cron job to detect
registration denied and reset the modem.

(as an aside, there are tables in the SIM card that control how
> automatic registration works; it could be that your operator is perhaps
> denying registration to the UMTS network but would allow LTE and the
> SIM doesn't distinguish the two.  Or something like that...  but this
> would be odd.)
>

That sounds exactly the kind of mistake they might make. Any idea if/how I
can access that SIM state?

> > Finally, if I try to manually reconnect after the above error I get
> > this
> > every time -- instantly, rather than after a delay, even though the
> > message
> > mentions a timeout:
> >
> >
> > root at host:~# mmcli -m 0 --simple-connect="apn=EEM2M,ip-type=ipv4" --
> > verbose
> > [09 Mar 2018, 16:55:53] [Debug] Forcing request to be run
> > asynchronously
> > [09 Mar 2018, 16:55:53] [Debug] Assuming '0' is the modem index
> > [09 Mar 2018, 16:55:53] [Debug] ModemManager process found at ':1.3'
> > [09 Mar 2018, 16:55:53] [Debug] Modem found at '/org/freedesktop/
> > ModemManager1/Modem/0'
> >
> > [09 Mar 2018, 16:55:53] [Debug] Asynchronously connecting the
> > modem...
> > error: couldn't connect the modem: 'GDBus.Error:org.freedesktop.
> > ModemManager1.Error.MobileEquipment.NetworkTimeout: Network timeout'
>
> That message would be coming directly from the modem in the AT ERROR
> response, I think.  And it may well be that the modem firmware thinks
> there's a timeout or is just returning that error code for the attempt.
>

Here's the mm logs immediately after running the simple-connect command
above:

Mar 20 10:31:15 x ModemManager[919]: <info>  Simple connect started...
Mar 20 10:31:15 x ModemManager[919]: <debug>    PIN: unspecified
Mar 20 10:31:15 x ModemManager[919]: <debug>    Operator ID: unspecified
Mar 20 10:31:15 x ModemManager[919]: <debug>    Allowed roaming: yes
Mar 20 10:31:15 x ModemManager[919]: <debug>    APN: EEM2M
Mar 20 10:31:15 x ModemManager[919]: <debug>    IP family: ipv4
Mar 20 10:31:15 x ModemManager[919]: <debug>    Allowed authentication:
unspecified
Mar 20 10:31:15 x ModemManager[919]: <debug>    User: unspecified
Mar 20 10:31:15 x ModemManager[919]: <debug>    Password: unspecified
Mar 20 10:31:15 x ModemManager[919]: <debug>    Number: unspecified
Mar 20 10:31:15 x ModemManager[919]: <info>  Simple connect state (4/8):
Wait to get fully enabled
Mar 20 10:31:15 x ModemManager[919]: <info>  Simple connect state (5/8):
Register
Mar 20 10:31:15 x ModemManager[919]: <debug> Launching automatic network
registration...
Mar 20 10:31:15 x ModemManager[919]: <debug> (ttyUSB0) device open count is
2 (open)
Mar 20 10:31:15 x ModemManager[919]: <debug> (ttyUSB0): --> 'AT+COPS=0<CR>'
Mar 20 10:31:15 x ModemManager[919]: <debug> (ttyUSB0): <--
'<CR><LF>OK<CR><LF>'
Mar 20 10:31:15 x ModemManager[919]: <debug> Running registration checks
(CS: 'yes', PS: 'yes', EPS: 'no')
Mar 20 10:31:15 x ModemManager[919]: <debug> (ttyUSB0) device open count is
3 (open)
Mar 20 10:31:15 x ModemManager[919]: <debug> (ttyUSB0) device open count is
2 (close)
Mar 20 10:31:15 x ModemManager[919]: <debug> (ttyUSB0): --> 'AT+CREG?<CR>'
Mar 20 10:31:15 x ModemManager[919]: <debug> (ttyUSB0): <-- '<CR><LF>+CREG:
2,3<CR><LF><CR><LF>OK<CR><LF>'
Mar 20 10:31:15 x ModemManager[919]: <debug> (ttyUSB0) device open count is
3 (open)
Mar 20 10:31:15 x ModemManager[919]: <debug> (ttyUSB0) device open count is
2 (close)
Mar 20 10:31:15 x ModemManager[919]: <debug> (ttyUSB0): --> 'AT+CGREG?<CR>'
Mar 20 10:31:15 x ModemManager[919]: <debug> (ttyUSB0): <--
'<CR><LF>+CGREG: 2,3<CR><LF><CR><LF>OK<CR><LF>'
Mar 20 10:31:15 x ModemManager[919]: <debug> (ttyUSB0) device open count is
1 (close)
Mar 20 10:31:15 x ModemManager[919]: <debug> Registration denied
Mar 20 10:31:15 x ModemManager[919]: <info>  Modem
/org/freedesktop/ModemManager1/Modem/13: 3GPP Registration state changed
(denied -> idle)
Mar 20 10:31:15 x ModemManager[919]: <debug> Modem
/org/freedesktop/ModemManager1/Modem/13: access technology changed (umts ->
unknown)

> > However if I do 'mmcli -m 0 --reset', it seems to attempt a new
> > connection
> > from scratch (which succeeds intermittently as on a fresh boot).
>
> --reset doesn't look like it's implemented for Huawei AT-based modems,
> actually.  What do the ModemManager logs look like when you try reset?

Mar 19 18:15:50 x ModemManager[919]: <debug> (ttyUSB0) device open count is
2 (open)
Mar 19 18:15:50 x ModemManager[919]: <debug> (ttyUSB0): --> 'AT^RESET<CR>'
Mar 19 18:15:50 x ModemManager[919]: <debug> (ttyUSB0): <--
'<CR><LF>OK<CR><LF>'
Mar 19 18:15:50 x ModemManager[919]: <debug> (ttyUSB0) device open count is
1 (close)
Mar 19 18:15:50 x ModemManager[919]: <debug> (ttyUSB2): <--
'<CR><LF>+CGREG: 0<CR><LF>'
Mar 19 18:15:50 x ModemManager[919]: <debug> (ttyUSB2): <-- '<CR><LF>+CREG:
0<CR><LF>'
Mar 19 18:15:50 x ModemManager[919]: <info>  Modem
/org/freedesktop/ModemManager1/Modem/11: 3GPP Registration state changed
(denied -> idle)
Mar 19 18:15:50 x ModemManager[919]: <debug> (ttyUSB0): <--
'<CR><LF>+CGREG: 0<CR><LF><CR><LF>+CREG: 0<CR><LF><CR><LF>^SRVST: 0<CR><LF>'
Mar 19 18:15:50 x ModemManager[919]: <debug> (ttyUSB2): <--
'<CR><LF>^SRVST: 0<CR><LF>'
Mar 19 18:15:50 x ModemManager[919]: <debug> (ttyUSB0): <--
'<CR><LF>^SRVST: 1<CR><LF>'
Mar 19 18:15:50 x ModemManager[919]: <debug> (ttyUSB2): <--
'<CR><LF>^SRVST: 1<CR><LF>'
Mar 19 18:15:50 x ModemManager[919]: <debug> (ttyUSB2): <--
'<CR><LF>^SRVST: 0<CR><LF><CR><LF>^MODE: 0,0<CR><LF>'
Mar 19 18:15:50 x ModemManager[919]: <debug> Access Technology: 'unknown'
Mar 19 18:15:50 x ModemManager[919]: <debug> (ttyUSB0): <--
'<CR><LF>^SRVST: 0<CR><LF><CR><LF>^MODE: 0,0<CR><LF>'
Mar 19 18:15:50 x ModemManager[919]: <debug> Access Technology: 'unknown'
Mar 19 18:15:53 x ModemManager[919]: <info>  (net/enp0s21f0u8c2): released
by modem /sys/devices/pci0000:00/0000:00:15.0/usb1/1-8
Mar 19 18:15:53 x ModemManager[919]: <debug> (ttyUSB0) unexpected port
hangup!
Mar 19 18:15:53 x ModemManager[919]: <debug> (ttyUSB0) forced to close port
Mar 19 18:15:53 x ModemManager[919]: <debug> (ttyUSB0) device open count is
0 (close)
Mar 19 18:15:53 x ModemManager[919]: <debug> (ttyUSB0) closing serial
port...
Mar 19 18:15:53 x ModemManager[919]: <debug> (ttyUSB0) serial port closed
Mar 19 18:15:53 x ModemManager[919]: <debug> (ttyUSB2) unexpected port
hangup!
Mar 19 18:15:53 x ModemManager[919]: <debug> (ttyUSB2) forced to close port
Mar 19 18:15:53 x ModemManager[919]: <debug> (ttyUSB2) device open count is
0 (close)
Mar 19 18:15:53 x ModemManager[919]: <debug> (ttyUSB2) closing serial
port...
Mar 19 18:15:53 x ModemManager[919]: <debug> (ttyUSB2) serial port closed
Mar 19 18:15:53 x ModemManager[919]: <info>  (tty/ttyUSB0): released by
modem /sys/devices/pci0000:00/0000:00:15.0/usb1/1-8
Mar 19 18:15:53 x ModemManager[919]: <info>  (tty/ttyUSB1): released by
modem /sys/devices/pci0000:00/0000:00:15.0/usb1/1-8
Mar 19 18:15:53 x ModemManager[919]: <info>  (tty/ttyUSB2): released by
modem /sys/devices/pci0000:00/0000:00:15.0/usb1/1-8
Mar 19 18:15:53 x ModemManager[919]: <info>  (tty/ttyUSB4): released by
modem /sys/devices/pci0000:00/0000:00:15.0/usb1/1-8
Mar 19 18:15:53 x ModemManager[919]: <info>  (tty/ttyUSB3): released by
modem /sys/devices/pci0000:00/0000:00:15.0/usb1/1-8
Mar 19 18:15:53 x ModemManager[919]: <debug> Removing empty device
'/sys/devices/pci0000:00/0000:00:15.0/usb1/1-8'
Mar 19 18:15:53 x ModemManager[919]: <debug> Unexported modem
'/sys/devices/pci0000:00/0000:00:15.0/usb1/1-8' from path
'/org/freedesktop/ModemManager1/Modem/11'
Mar 19 18:15:53 x ModemManager[919]: <debug> (ttyUSB3) forced to close port
Mar 19 18:15:53 x ModemManager[919]: <debug> Modem (Huawei)
'/sys/devices/pci0000:00/0000:00:15.0/usb1/1-8' completely disposed
Mar 19 18:15:58 x ModemManager[919]: <debug> [plugin manager] task 15: new
support task for device: /sys/devices/pci0000:00/0000:00:15.0/usb1/1-8
Mar 19 18:15:58 x ModemManager[919]: <debug> [plugin manager] task 15: port
grabbed: ttyUSB0

Followed by what looks like modem setup.

Many thanks for your help,

Hugh

On 16 March 2018 at 22:51, Dan Williams <dcbw at redhat.com> wrote:

> On Wed, 2018-03-14 at 16:41 +0000, Hugh Warrington wrote:
> > Hello!
> >
> > I am using network-manager 1.2.6-0ubuntu0.16.04.2,
> > modemmanager 1.6.4-1ubuntu0.16.04.1 with a Huawei ME909s-120,
> > firmware 11.617.01.00.00.
> >
> > We're using a SIM card from EE M2M here in the UK.
> >
> > Intermittently when I boot the machine, I get a 3GPP registration
> > denied
> > message in mm logs. Having run mm in debug mode and read through the
> > AT
> > commands going back and forth, I believe mm is correctly reporting
> > the
> > modem state.
> >
> > Here's some mm journald logs from a failed attempt (with many lines
> > of
> > noise removed):
> >
> >
> > ModemManager (version 1.4.12) starting in system bus...
> > Creating modem with plugin 'Huawei' and '6' ports
> > Modem for device at '/sys/devices/pci0000:00/0000:00:15.0/usb1/1-8'
> > successfully created
> > mobile equipment error code: 50
> > Modem: state changed (unknown -> disabled)
> > Modem /org/freedesktop/ModemManager1/Modem/0: state changed (disabled
> > ->
> > enabling)
> > mobile equipment error code: 50
> > Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state
> > changed (unknown -> denied)
> > Modem /org/freedesktop/ModemManager1/Modem/0: state changed (enabling
> > ->
> > enabled)
> >
> >
> > I've contacted the network about why the registration is sometimes
> > denied.
> > But I have a couple of questions:
> >
> > 1. Is registration denied a recoverable error -- and if so should I
> > expect
> > modemmanager to retry registration?
>
> It's recoverable to the extent that you can attempt to manually
> register with another network, or you could airplane-mode-then-retry
> registration to the same network and see if it works, or you could
> change the preferred access technology.  But usually, if the network
> denies you, that same network will deny you again.
>
> (as an aside, there are tables in the SIM card that control how
> automatic registration works; it could be that your operator is perhaps
> denying registration to the UMTS network but would allow LTE and the
> SIM doesn't distinguish the two.  Or something like that...  but this
> would be odd.)
>
> > 2. Does the final line in the logs above indicate a problem? It seems
> > strange that the registration failed but then it reports the modem is
> > 'enabled'.
>
> No, since you can force-register with another operator or change the
> preferred access technology while the modem is enabled.  Just because
> you're denied one operator doesn't mean you're denied all of them.
>
> > Finally, if I try to manually reconnect after the above error I get
> > this
> > every time -- instantly, rather than after a delay, even though the
> > message
> > mentions a timeout:
> >
> >
> > root at host:~# mmcli -m 0 --simple-connect="apn=EEM2M,ip-type=ipv4" --
> > verbose
> > [09 Mar 2018, 16:55:53] [Debug] Forcing request to be run
> > asynchronously
> > [09 Mar 2018, 16:55:53] [Debug] Assuming '0' is the modem index
> > [09 Mar 2018, 16:55:53] [Debug] ModemManager process found at ':1.3'
> > [09 Mar 2018, 16:55:53] [Debug] Modem found at '/org/freedesktop/
> > ModemManager1/Modem/0'
> >
> > [09 Mar 2018, 16:55:53] [Debug] Asynchronously connecting the
> > modem...
> > error: couldn't connect the modem: 'GDBus.Error:org.freedesktop.
> > ModemManager1.Error.MobileEquipment.NetworkTimeout: Network timeout'
>
> That message would be coming directly from the modem in the AT ERROR
> response, I think.  And it may well be that the modem firmware thinks
> there's a timeout or is just returning that error code for the attempt.
>
> >
> > And in the mm journalctl logs:
> >
> >
> > <info>  [1520872097.948148] [mm-iface-modem-simple.c:641]
> > connect_auth_ready(): Simple connect started...
> > <debug> [1520872097.948222] [mm-iface-modem-simple.c:651]
> > connect_auth_ready():    PIN: unspecified
> > <debug> [1520872097.948244] [mm-iface-modem-simple.c:653]
> > connect_auth_ready():    Operator ID: unspecified
> > <debug> [1520872097.948263] [mm-iface-modem-simple.c:655]
> > connect_auth_ready():    Allowed roaming: yes
> > <debug> [1520872097.948282] [mm-iface-modem-simple.c:657]
> > connect_auth_ready():    APN: EEM2M
> > <debug> [1520872097.948302] [mm-iface-modem-simple.c:662]
> > connect_auth_ready():    IP family: ipv4
> > <debug> [1520872097.948320] [mm-iface-modem-simple.c:673]
> > connect_auth_ready():    Allowed authentication: unspecified
> > <debug> [1520872097.948339] [mm-iface-modem-simple.c:675]
> > connect_auth_ready():    User: unspecified
> > <debug> [1520872097.948356] [mm-iface-modem-simple.c:677]
> > connect_auth_ready():    Password: unspecified
> > <debug> [1520872097.948375] [mm-iface-modem-simple.c:679]
> > connect_auth_ready():    Number: unspecified
> > <info>  [1520872097.948392] [mm-iface-modem-simple.c:469]
> > connection_step(): Simple connect state (4/8): Wait to get fully
> > enabled
> > <info>  [1520872097.948472] [mm-iface-modem-simple.c:478]
> > connection_step(): Simple connect state (5/8): Register
> > <debug> [1520872097.948519] [mm-iface-modem-3gpp.c:407]
> > mm_iface_modem_3gpp_register_in_network(): Launching automatic
> > network
> > registration...
> > <debug> [1520872097.948600] [mm-port-serial.c:1288]
> > mm_port_serial_open():
> > (ttyUSB0) device open count is 2 (open)
> > <debug> [1520872097.948679] [mm-port-serial-at.c:459] debug_log():
> > (ttyUSB0): --> 'AT+COPS=0<CR>'
> > <debug> [1520872097.966674] [mm-port-serial-at.c:459] debug_log():
> > (ttyUSB0): <-- '<CR><LF>OK<CR><LF>'
> > <debug> [1520872097.966851] [mm-iface-modem-3gpp.c:761]
> > mm_iface_modem_3gpp_run_registration_checks(): Running registration
> > checks
> > (CS: 'yes', PS: 'yes', EPS: 'no')
> > <debug> [1520872097.966906] [mm-port-serial.c:1288]
> > mm_port_serial_open():
> > (ttyUSB0) device open count is 3 (open)
> > <debug> [1520872097.966954] [mm-port-serial.c:1345]
> > _close_internal():
> > (ttyUSB0) device open count is 2 (close)
> > <debug> [1520872097.967011] [mm-port-serial-at.c:459] debug_log():
> > (ttyUSB0): --> 'AT+CREG?<CR>'
> > <debug> [1520872097.978564] [mm-port-serial-at.c:459] debug_log():
> > (ttyUSB0): <-- '<CR><LF>+CREG: 2,3<CR><LF><CR><LF>OK<CR><LF>'
> > <info>  [1520872097.978719] [mm-iface-modem-3gpp.c:1186]
> > update_registration_state(): Modem
> > /org/freedesktop/ModemManager1/Modem/0:
> > 3GPP Registration state changed (idle -> denied)
> > <debug> [1520872097.978961] [mm-port-serial.c:1288]
> > mm_port_serial_open():
> > (ttyUSB0) device open count is 3 (open)
> > <debug> [1520872097.979022] [mm-port-serial.c:1345]
> > _close_internal():
> > (ttyUSB0) device open count is 2 (close)
> > <debug> [1520872097.979408] [mm-port-serial-at.c:459] debug_log():
> > (ttyUSB0): --> 'AT+CGREG?<CR>'
> > <debug> [1520872097.993673] [mm-port-serial-at.c:459] debug_log():
> > (ttyUSB0): <-- '<CR><LF>+CGREG: 2,3<CR><LF><CR><LF>OK<CR><LF>'
> > <debug> [1520872097.993969] [mm-port-serial.c:1345]
> > _close_internal():
> > (ttyUSB0) device open count is 1 (close)
> > <debug> [1520872097.994049] [mm-iface-modem-3gpp.c:262]
> > run_registration_checks_ready(): Registration denied
> > <info>  [1520872097.994097] [mm-iface-modem-3gpp.c:1186]
> > update_registration_state(): Modem
> > /org/freedesktop/ModemManager1/Modem/0:
> > 3GPP Registration state changed (denied -> idle)
> >
> >
> > However if I do 'mmcli -m 0 --reset', it seems to attempt a new
> > connection
> > from scratch (which succeeds intermittently as on a fresh boot).
>
> --reset doesn't look like it's implemented for Huawei AT-based modems,
> actually.  What do the ModemManager logs look like when you try reset?
>
> Dan
>
> > Question number 3 is a bit more vague: is the difference between a
> > new
> > 'simple connect' and modem reset expected?
> >
> > Many thanks in advance for any insight.
> > Best wishes,
> >
> > Hugh Warrington
> > Engineer
> > Hoxton Analytics
> > _______________________________________________
> > 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/20180327/76234581/attachment-0001.html>