intel: XMM7360: unlocking/enabling RPC timeout fix and location support
I have been testing !1235 (thanks @tuxor1337) on a XMM7360 and seeing quite a bit of modem initialization failures due to RPC command timeout.
This most often happens between uta-ms-sms-init RPC command and AT+XLSRSTOP AT command when the modem is re-initialized after being unlocked, however such timeouts with other combinations of commands and/or in other situation happen occasionally too.
Here's example trace demonstrating the issue:
<dbg> [1736598232.420358] [wwan0at1/at] --> 'AT+CLCC=?<CR><LF>'
<dbg> [1736598232.422182] [wwan0at1/at] <-- '<CR><LF>OK<CR><LF>'
<dbg> [1736598232.422256] [modem3] periodic call list polling will be used if supported
<dbg> [1736598232.422346] [wwan0at1/at] device open count is 1 (close)
<dbg> [1736598232.422400] [modem3] [operation 7] default - initialization: lock released
<wrn> [1736598232.422413] [device /sys/devices/pci0000:00/0000:00:01.2/0000:01:00.0] error initializing: Modem is currently locked, cannot fully initialize
<dbg> [1736598232.423476] [device /sys/devices/pci0000:00/0000:00:01.2/0000:01:00.0] exported modem at path '/org/freedesktop/ModemManager1/Modem/3'
<dbg> [1736598232.423526] [wwan0at1/at] device open count is 0 (close)
<dbg> [1736598232.423551] [wwan0at1/at] closing serial port...
<dbg> [1736598232.428312] [wwan0at1/at] serial port closed
<inf> [1736598242.213948] [modem3/sim3] processing user request to send PIN...
<dbg> [1736598242.214151] [wwan0at1/at] opening serial port...
<dbg> [1736598242.220999] [wwan0at1/at] device open count is 1 (open)
<dbg> [1736598242.221118] [wwan0at1/at] --> 'AT+CPIN="(PIN)"<CR><LF>'
<dbg> [1736598242.251884] [wwan0at1/at] <-- '<CR><LF>OK<CR><LF>'
<dbg> [1736598242.252029] [modem3] checking if unlock required...
<dbg> [1736598242.252059] [wwan0at1/at] device open count is 2 (open)
<dbg> [1736598242.252093] [wwan0at1/at] device open count is 1 (close)
<dbg> [1736598242.252120] [wwan0at1/at] --> 'AT+CPIN?<CR><LF>'
<dbg> [1736598242.254824] [wwan0at1/at] <-- '<CR><LF>+CPIN: READY<CR><LF><CR><LF>OK<CR><LF>'
<inf> [1736598242.254953] [modem3] SIM is ready, and no need for the after SIM unlock step...
<dbg> [1736598242.255051] [wwan0at1/at] device open count is 2 (open)
<dbg> [1736598242.255104] [wwan0at1/at] device open count is 1 (close)
<dbg> [1736598242.255155] [wwan0at1/at] --> 'AT+CSIM=10,"0020000100"<CR><LF>'
<dbg> [1736598242.357811] [wwan0at1/at] <-- '<CR><LF>+CSIM: 4,"63C3"<CR><LF><CR><LF>OK<CR><LF>'
<dbg> [1736598242.358098] [wwan0at1/at] device open count is 2 (open)
<dbg> [1736598242.358125] [wwan0at1/at] device open count is 1 (close)
<dbg> [1736598242.358148] [wwan0at1/at] --> 'AT+CSIM=10,"002C000100"<CR><LF>'
<dbg> [1736598242.463561] [wwan0at1/at] <-- '<CR><LF>+CSIM: 4,"63CA"<CR><LF><CR><LF>OK<CR><LF>'
<dbg> [1736598242.463766] [wwan0at1/at] device open count is 2 (open)
<dbg> [1736598242.463797] [wwan0at1/at] device open count is 1 (close)
<dbg> [1736598242.463824] [wwan0at1/at] --> 'AT+CSIM=10,"0020008100"<CR><LF>'
<dbg> [1736598242.559624] [wwan0at1/at] <-- '<CR><LF>+CSIM: 4,"63C3"<CR><LF><CR><LF>OK<CR><LF>'
<dbg> [1736598242.559798] [wwan0at1/at] device open count is 2 (open)
<dbg> [1736598242.559821] [wwan0at1/at] device open count is 1 (close)
<dbg> [1736598242.559839] [wwan0at1/at] --> 'AT+CSIM=10,"002C008100"<CR><LF>'
<dbg> [1736598242.666037] [wwan0at1/at] <-- '<CR><LF>+CSIM: 4,"63CA"<CR><LF><CR><LF>OK<CR><LF>'
<dbg> [1736598242.666405] [wwan0at1/at] device open count is 0 (close)
<dbg> [1736598242.666421] [wwan0at1/at] closing serial port...
<dbg> [1736598242.668177] [wwan0at1/at] serial port closed
<dbg> [1736598242.668331] [modem3] [operation 8] default - initialization: scheduled
<dbg> [1736598242.668342] [modem3] [operation 8] default - initialization: lock acquired
<msg> [1736598242.668374] [modem3] state changed (locked -> initializing)
<dbg> [1736598242.668555] [modem3] (shared-xmm) setting up ports in XMM modem...
<dbg> [1736598242.668880] [wwan0at1/at] opening serial port...
<dbg> [1736598242.670450] [wwan0at1/at] device open count is 1 (open)
<dbg> [1736598242.670524] [wwan0xmmrpc0/xmmrpc] opening serial port...
<dbg> [1736598242.672178] [wwan0xmmrpc0/xmmrpc] device open count is 1 (open)
<dbg> [1736598242.672201] [modem3] (intel) running init sequence...
<dbg> [1736598242.672214] [wwan0xmmrpc0/xmmrpc] device open count is 2 (open)
<dbg> [1736598242.672235] [wwan0xmmrpc0/xmmrpc] (intel) --> uta-ms-sms-init
<dbg> [1736598242.672251] [wwan0xmmrpc0/xmmrpc] (intel) b'1600000002040000001602040000003011000100020400000000'
<dbg> [1736598242.672310] [wwan0at1/at] --> 'AT+XLSRSTOP<CR><LF>'
<dbg> [1736598242.677553] [wwan0at1/at] <-- '<CR><LF>ERROR<CR><LF>'
<dbg> [1736598242.677642] [wwan0at1/at] operation failure: 100 (Unknown error)
<dbg> [1736598242.677675] [wwan0at1/at] device open count is 0 (close)
<dbg> [1736598242.677686] [wwan0at1/at] closing serial port...
<dbg> [1736598242.679720] [wwan0at1/at] serial port closed
<dbg> [1736598243.131207] [wwan0xmmrpc0/xmmrpc] (intel) <-- (unsolicited) uta-ms-sim-full-access-ind-cb
<dbg> [1736598243.131237] [wwan0xmmrpc0/xmmrpc] (intel) b'020400000000'
<dbg> [1736598243.131245] [wwan0xmmrpc0/xmmrpc] (intel) L(0x00000000)
<dbg> [1736598244.333981] [wwan0xmmrpc0/xmmrpc] (intel) <-- (unsolicited) uta-ms-sms-sim-msg-cache-finished-ind-cb
<dbg> [1736598244.334032] [wwan0xmmrpc0/xmmrpc] (intel) b'020400000000020400000000'
<dbg> [1736598244.334040] [wwan0xmmrpc0/xmmrpc] (intel) L(0x00000000) L(0x00000000)
<wrn> [1736598246.144942] [modem3] couldn't start initialization: Failed to complete init sequence: Serial command timed out
<dbg> [1736598246.145209] [modem3] [operation 8] default - initialization: lock released
<wrn> [1736598246.145228] [modem3] reinitialization failed: Modem in failed state: none
<dbg> [1736598246.145246] [wwan0xmmrpc0/xmmrpc] device open count is 1 (close)
<dbg> [1736598246.145257] [wwan0xmmrpc0/xmmrpc] device open count is 0 (close)
<dbg> [1736598246.145265] [wwan0xmmrpc0/xmmrpc] closing serial port...
<dbg> [1736598246.152267] [wwan0xmmrpc0/xmmrpc] serial port closed
It looks like we have to avoid sending RPC and AT commands at the same time (even thought they are sent via different serial ports) since apparently these modems do not like it.
This draft MR (based on the top of !1235) implements this in the simplest way possible for a PoC: by adding a possibility of having an interlock between two MMPortSerials, where sending queued command will be deferred if the other port is already busy with a command until both serial ports are idle.
I'm open to suggestions how to implement such command collision prevention on two serial ports in a different way, but if significant amount of core ModemManager code changes are necessary then ETA for this may be very long.
This MR also contains a commit to re-enable the location interface for XMM7360 since it seems to work just fine once the port interlocking is present and some other fixes from the third commit in this MR are done (including similar fix as commit d3a2aebf did for the mbm plugin).
The GNSS part even works if the modem is in locked/non-enabled state.
I have been testing all these fixes for more than a week now and with these (and some kernel fixes I am in process of upstreaming) the modem works well for me, including after a few suspend to idle / hibernation + resume cycles.
If @tuxor1337 wants to include these fixes directly in !1235 then I am completely fine with that.