Incorrect modem state transition due to previous initial registration check

[Ben Chan]

Hi Aleksander,

I observed the following issue when trying to disable the modem shortly
after it was enabled by ModemManager. In the last step of enabling the
Modem3gpp interface, the code scheduled an initial registration state check
and then proceeded to completion. While the initial registration check was
executing asynchronously, the modem was going through the disabling
sequence. If the initial registration check completed during or after the
disabling sequence, the modem and registration state were incorrectly
transitioned to a wrong state.  Assuming it may not always be possible to
cancel an ongoing registration checks, one solution is to ignore the
registration check result if modem state < ENABLING. Does it sound
reasonable?

Thanks,
Ben

---

Here's an example log that demonstrates the issue:

### modem was being disabled

2018-01-10T13:14:25.071293+08:00 INFO ModemManager[1485]: <info>  Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (registered ->
disabling)
2018-01-10T13:14:25.071565+08:00 DEBUG ModemManager[1485]: <debug> Modem
has messaging capabilities, disabling the Messaging interface...
2018-01-10T13:14:25.073144+08:00 DEBUG ModemManager[1485]: <debug> Modem
has 3GPP capabilities, disabling the Modem 3GPP interface...
2018-01-10T13:14:25.073170+08:00 DEBUG ModemManager[1485]: <debug> Periodic
3GPP registration checks disabled
...

### modem registration state was set to unknown

2018-01-10T13:14:25.075148+08:00 INFO ModemManager[1485]: <info>  Modem
/org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed
(home -> unknown)
2018-01-10T13:14:25.075269+08:00 DEBUG ModemManager[1485]: <debug> Bearer
not allowed to connect, not registered in 3GPP network
2018-01-10T13:14:25.075315+08:00 DEBUG ModemManager[1485]: <debug> Modem
/org/freedesktop/ModemManager1/Modem/0: access technology changed (lte ->
unknown)

### modem state was transitioned to 'disabled'

2018-01-10T13:14:25.075654+08:00 INFO ModemManager[1485]: <info>  Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (disabling ->
disabled)

### Previously scheduled initial registration check completed and returned
the registration state

2018-01-10T13:14:25.078755+08:00 DEBUG ModemManager[1485]: [/dev/cdc-wdm0]
Received message...#012>>>>>> RAW:#012>>>>>>   length = 120#012>>>>>>
data   =
03:00:00:80:78:00:00:00:7C:2D:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:09:00:00:00:00:00:00:00:48:00:00:00:00:00:00:00:03:00:00:00:01:00:00:00:20:00:00:00:01:00:00:00:30:00:00:00:0A:00:00:00:3C:00:00:00:0C:00:00:00:00:00:00:00:00:00:00:00:02:00:00:00:34:00:36:00:30:00:30:00:31:00:00:00:30:00:30:00:30:00:30:00:30:00:30:00
2018-01-10T13:14:25.078796+08:00 DEBUG ModemManager[1485]: [/dev/cdc-wdm0]
Received message (translated)...#012>>>>>> Header:#012>>>>>>   length
  = 120#012>>>>>>   type        = command-done (0x80000003)#012>>>>>>
transaction = 11644#012>>>>>> Fragment header:#012>>>>>>   total   =
1#012>>>>>>   current = 0#012>>>>>> Contents:#012>>>>>>   status error =
'None' (0x00000000)#012>>>>>>   service      = 'basic-connect'
(a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)#012>>>>>>   cid          =
'register-state' (0x00000009)

### modem registration was (potentially incorrectly) transitioned from
'unknown' to 'registering'

2018-01-10T13:14:25.078877+08:00 INFO ModemManager[1485]: <info>  Modem
/org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed
(unknown -> registering)
2018-01-10T13:14:25.078967+08:00 DEBUG ModemManager[1485]: <debug> Modem
/org/freedesktop/ModemManager1/Modem/0: access technology changed (unknown
-> lte)
2018-01-10T13:14:25.078988+08:00 DEBUG ModemManager[1485]: <debug> Initial
3GPP registration checks finished
2018-01-10T13:14:25.079392+08:00 INFO ModemManager[1485]: <info>  Modem
/org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed
(registering -> home)

### modem state was incorrectly transitioned from 'disabled' back to
'registered'

2018-01-10T13:14:25.079456+08:00 INFO ModemManager[1485]: <info>  Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (disabled ->
registered)