AMF remains in the ContextSetup state after UE has sent SecurityModeReject and new InitialRegistration

[sysarch-repo]

According to 3GPP TS 24.501 the AMF should guard the NAS Security Mode procedure using the timer T3560.

Upon receipt of the SECURITY MODE REJECT message, the AMF shall stop timer T3560. The AMF shall also abort the ongoing procedure that triggered the initiation of the NAS security mode control procedure. Both the UE and the AMF shall apply the 5G NAS security context in use before the initiation of the security mode control procedure, if any.

On the first expiry of the timer T3560, the AMF shall retransmit the SECURITY MODE COMMAND message and shall reset and start timer T3560. This retransmission is repeated four times, i.e. on the fifth expiry of timer T3560, the procedure shall be aborted.

So the AMF shall - at some point - exit the ContextSetup state and be ready to process the next Registration Request sent by the UE. Instead, the UE is sending Registration Request all the time that remains unanswered by the AMF in the ContextSetup state for the UE.

The AMF:

2022-01-19T10:34:30Z [INFO][AMF][App] amf
2022-01-19T10:34:30Z [INFO][AMF][App] AMF version:
        free5GC version: v3.0.6
        build time:      2021-11-16T15:25:18Z
        commit hash:     b3e99f97
        commit time:     2021-09-24T09:44:32Z
        go version:      go1.14.4 linux/amd64

The N2 interface:

2022-01-20T00:31:02Z [INFO][AMF][NGAP] Create a new NG connection for: 10.10.20.204:38412
2022-01-20T00:31:02Z [INFO][AMF][NGAP][10.10.20.204:38412] Handle NG Setup request
2022-01-20T00:31:02Z [INFO][AMF][NGAP][10.10.20.204:38412] Send NG-Setup response
2022-01-20T00:31:02Z [INFO][AMF][NGAP][10.10.20.204:38412] Handle Initial UE Message
2022-01-20T00:31:02Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:750] Handle Registration Request
2022-01-20T00:31:02Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:750] Authentication procedure
2022-01-20T00:31:02Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:750] Send Authentication Request
2022-01-20T00:31:02Z [INFO][AMF][NGAP][10.10.20.204:38412][AMF_UE_NGAP_ID:750] Send Downlink Nas Transport
2022-01-20T00:31:02Z [INFO][AMF][NGAP][10.10.20.204:38412] Handle Uplink Nas Transport
2022-01-20T00:31:02Z [INFO][AMF][NGAP][10.10.20.204:38412][AMF_UE_NGAP_ID:750] Uplink NAS Transport (RAN UE NGAP ID: 1)
2022-01-20T00:31:02Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:750] Handle Authentication Response
2022-01-20T00:31:02Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:750][SUPI:imsi-999990000000091] Send Security Mode Command
2022-01-20T00:31:02Z [INFO][AMF][NGAP][10.10.20.204:38412][AMF_UE_NGAP_ID:750] Send Downlink Nas Transport
2022-01-20T00:31:02Z [INFO][AMF][NGAP][10.10.20.204:38412] Handle Uplink Nas Transport
2022-01-20T00:31:02Z [INFO][AMF][NGAP][10.10.20.204:38412][AMF_UE_NGAP_ID:750] Uplink NAS Transport (RAN UE NGAP ID: 1)
2022-01-20T00:31:02Z [WARN][AMF][NAS][AMF_UE_NGAP_ID:750][SUPI:imsi-999990000000091] Received Plain NAS message
2022-01-20T00:31:02Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:750][SUPI:imsi-999990000000091] Handle Security Mode Reject
2022-01-20T00:31:02Z [WARN][AMF][GMM][AMF_UE_NGAP_ID:750][SUPI:imsi-999990000000091] Reject Cause: Security mode rejected, upspecified (24)
2022-01-20T00:31:02Z [ERRO][AMF][GMM][AMF_UE_NGAP_ID:750][SUPI:imsi-999990000000091] UE reject the security mode command, abort the ongoing procedure
2022-01-20T00:31:27Z [INFO][AMF][NGAP][10.10.20.204:38412] Handle Uplink Nas Transport
2022-01-20T00:31:27Z [INFO][AMF][NGAP][10.10.20.204:38412][AMF_UE_NGAP_ID:750] Uplink NAS Transport (RAN UE NGAP ID: 1)
2022-01-20T00:31:27Z [WARN][AMF][NAS][AMF_UE_NGAP_ID:750][SUPI:imsi-999990000000091] Received Plain NAS message
2022-01-20T00:31:27Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:750][SUPI:imsi-999990000000091] Handle Registration Request
2022-01-20T00:31:27Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:750][SUPI:imsi-999990000000091] Authentication procedure
2022-01-20T00:31:27Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:750][SUPI:imsi-999990000000091] Handle InitialRegistration
2022-01-20T00:31:27Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:750][SUPI:imsi-999990000000091] Send Registration Reject
2022-01-20T00:31:27Z [INFO][AMF][NGAP][10.10.20.204:38412][AMF_UE_NGAP_ID:750] Send Downlink Nas Transport
2022-01-20T00:31:27Z [ERRO][AMF][GMM] Capability5GMM is nil
2022-01-20T01:01:27Z [INFO][AMF][NGAP][10.10.20.204:38412] Handle Initial UE Message
2022-01-20T01:01:27Z [INFO][AMF][NGAP][10.10.20.204:38412][AMF_UE_NGAP_ID:750] Implicit Deregistration - RanUeNgapID[1]
2022-01-20T01:01:27Z [WARN][AMF][NAS][AMF_UE_NGAP_ID:750] Received Plain NAS message
2022-01-20T01:01:27Z [ERRO][AMF][GMM][AMF_UE_NGAP_ID:750] state mismatch: receieve gmm message[message type 0x41] at ContextSetup state
2022-01-20T01:01:52Z [INFO][AMF][NGAP][10.10.20.204:38412] Handle Initial UE Message
2022-01-20T01:01:52Z [INFO][AMF][NGAP][10.10.20.204:38412][AMF_UE_NGAP_ID:750] Implicit Deregistration - RanUeNgapID[1]
2022-01-20T01:01:52Z [WARN][AMF][NAS][AMF_UE_NGAP_ID:750] Received Plain NAS message
2022-01-20T01:01:52Z [ERRO][AMF][GMM][AMF_UE_NGAP_ID:750] state mismatch: receieve gmm message[message type 0x41] at ContextSetup state
...

Note, the GNB simulator is re-using the RAN UE NGAP ID all the time. If this seems to be the issue, please indicate when the GNB shall assign a new RAN UE NGAP ID. But then the AMF may pile up orphan data?

Also, there seems to be a Registration Reject (cause 111 - protocol error) to the first Registration attempt after the Security Mode Reject was processed by the AMF. The Capability5GMM is nil because the UE has no security context established. And because Capability5GMM is a non-cleartext IE, it would be included in the NAS Registration Request sent inside the NAS Security Mode Complete message. This did not happen due to the Security Mode Reject. Is this the reason for the protocol error?

After the Registration Reject, the AMF no longer responds to any Registration Request sent with the RAN UE NGAP ID. The Registration Request (the same content all the time - cleartext IEs only):

{"time":"2022-01-20T18:28:17Z","level":"debug","msg":"Ngap PDU [000f006c00000500550002000100260042417e00417900350199f999f0ff0101e7f676c1cb924e2bcca7e75f6ae2265460156b2d1bbea93003a83d046ad99f368a43fdbf67a008c54cb1d272762e0480a000000079000f4099f9990000e0001099f999000001005a4001180070400100]"}
{"time":"2022-01-20T18:28:17Z","level":"debug","msg":"Handler [cucpNgc] is sending NGAP [InitiatingMessage] message [15:initialUeMessage]"}