Huawei ME909s-120 registration denied

Wed Mar 14 16:41:43 UTC 2018

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?

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'.

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'

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).

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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20180314/cabee9ab/attachment.html>