Huawei ME909s-120 registration denied
Dan Williams
dcbw at redhat.com
Wed Mar 28 14:43:20 UTC 2018
On Tue, 2018-03-27 at 14:28 +0100, Hugh Warrington wrote:
> 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).
Yeah, sounds plausible. For another example, various Icera chipset
based modems don't work with some SIMs that include ISIS/Softcard
support, which Icera confirmed to me was a firmware issue. Other SIMs
and modems worked fine. So it definitely can happen :)
> 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.
MM doesn't have a way to automatically reset the modem periodically if
registration is denied, because we've never encountered this kind of
situation before. But we could potentially add a timer to retry after
a couple minutes or something.
> (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?
What you can do is access SIM tables and the SIM filesystem with
AT+CRSM and such. The problem is that you then get to decode the SIM
response manually, and that I have no idea which tables might be
interesting to look at. It's fairly easy to get the information out;
figuring out what it means is the time-consuming thing. If you're
interested in doing that, I might be able to point you in a direction.
Dan
>
> > > 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
>
> _______________________________________________
> ModemManager-devel mailing list
> ModemManager-devel at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
More information about the ModemManager-devel
mailing list