Huawei ME909s-120 registration denied

Fri Mar 16 22:51:25 UTC 2018

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