Race in the SIM hotswap detection logic in MBIM devices
User report for an issue in the SIM hotswap logic:
When plugin out the SIM card and we quickly plugin in the SIM card before ModemManager finished the modem object initialized, during the steps of retrying (6) unlock required check, the Readystate maybe not-initialized instead of sim-not-inserted, so even later modem report the subscriber-ready-status initialized message indicate, ModemManager will not trigger SIM card swap for the last state is not-initialized.
2022-11-15T09:47:35.952833Z DEBUG ModemManager[3988]: <debug> [modem7] retrying (5) unlock required check
2022-11-15T09:47:37.968423Z DEBUG ModemManager[3988]: <debug> [/dev/cdc-wdm0] received message...#012>>>>>> RAW:#012>>>>>> length = 76#012>>>>>> data = 03:00:00:80:4C:00:00:00:13:00:00:00...#012
2022-11-15T09:47:37.968516Z DEBUG ModemManager[3988]: <debug> [/dev/cdc-wdm0] received message (translated)...#012>>>>>> Header:#012>>>>>> length = 76#012>>>>>> type = command-done (0x80000003)#012>>>>>> transaction = 19#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 = 'subscriber-ready-status' (0x00000002)#012>>>>>> Fields:#012>>>>>> ReadyState = 'sim-not-inserted'#012>>>>>> SubscriberId = '###'#012>>>>>> SimIccId = '###'#012>>>>>> ReadyInfo = 'none'#012>>>>>> TelephoneNumbersCount = '0'#012>>>>>> TelephoneNumbers = '###'#012
......
2022-11-15T09:47:37.968587Z DEBUG ModemManager[3988]: <debug> [modem7] couldn't check if unlock required: SIM not ready yet (retry)
2022-11-15T09:47:37.968603Z DEBUG ModemManager[3988]: <debug> [modem7] retrying (6) unlock required check
2022-11-15T09:47:39.952423Z DEBUG ModemManager[3988]: <debug> [/dev/cdc-wdm0] received message (translated)...#012>>>>>> Header:#012>>>>>> length = 116#012>>>>>> type = command-done (0x80000003)#012>>>>>> transaction = 20#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 = 'subscriber-ready-status' (0x00000002)#012>>>>>> Fields:#012>>>>>> ReadyState = 'not-initialized'#012>>>>>> SubscriberId = '###'#012>>>>>> SimIccId = '###'#012>>>>>> ReadyInfo = 'none'#012>>>>>> TelephoneNumbersCount = '0'#012>>>>>> TelephoneNumbers = '###'#012
2022-11-15T09:47:39.952457Z DEBUG ModemManager[3988]: <debug> [modem7] processed subscriber ready status response
2022-11-15T09:47:39.952476Z DEBUG ModemManager[3988]: <debug> [modem7] couldn't check if unlock required: Error waiting for SIM to get initialized
2022-11-15T09:47:39.952547Z INFO ModemManager[3988]: <info> [modem7] state changed (unknown -> locked)
2022-11-15T09:47:39.952715Z WARNING ModemManager[3988]: <warn> [modem7] modem couldn't be initialized: Couldn't check unlock status: Couldn't get SIM lock status after 6 retries
2022-11-15T09:47:39.952735Z INFO ModemManager[3988]: <info> [modem7] state changed (locked -> failed)
......
2022-11-15T09:47:40.144371Z DEBUG ModemManager[3988]: <debug> [modem7] no need to change power state: already 'low'
2022-11-15T09:47:40.144390Z INFO ModemManager[3988]: <info> [modem7] power state updated: low
......
2022-11-15T09:47:55.215739Z DEBUG ModemManager[3988]: <debug> [/dev/cdc-wdm0] received message (translated)...#012>>>>>> Header:#012>>>>>> length = 176#012>>>>>> type = indicate-status (0x80000007)#012>>>>>> transaction = 0#012>>>>>> Fragment header:#012>>>>>> total = 1#012>>>>>> current = 0#012>>>>>> Contents:#012>>>>>> service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)#012>>>>>> cid = 'subscriber-ready-status' (0x00000002)#012>>>>>> Fields:#012>>>>>> ReadyState = 'initialized'#012>>>>>> SubscriberId = '###'#012>>>>>> SimIccId = '###'#012>>>>>> ReadyInfo = 'none'#012>>>>>> TelephoneNumbersCount = '1'#012>>>>>> TelephoneNumbers = '###'#012
2022-11-15T09:47:55.215830Z DEBUG ModemManager[3988]: <debug> [modem7] received notification (service 'basic-connect', command 'subscriber-ready-status')
2022-11-15T09:47:55.215859Z DEBUG ModemManager[3988]: <debug> [modem7] processed subscriber ready status notification
For some reason we're not acting on the subscriber ready status notification, we should have triggered a modem re-probe.