search

aligungr / UERANSIM

Open source 5G UE and RAN (gNodeB) implementation.
GNU General Public License v3.0
792 stars 323 forks source link

UE invalid NAS message type #269

Closed infinitydon closed 3 years ago

infinitydon commented 3 years ago

Hi,

Please I am having issues running ueransim with Free5gc. Any ideas what could be the issue?

UERANSIM v3.1.4
[2021-03-11 08:44:15.017] [sctp] [info] Trying to establish SCTP connection... (172.31.203.7:38412)
[2021-03-11 08:44:15.019] [sctp] [info] SCTP connection established (172.31.203.7:38412)
[2021-03-11 08:44:15.019] [sctp] [debug] SCTP association setup ascId[4]
[2021-03-11 08:44:15.019] [ngap] [debug] Sending NG Setup Request
[2021-03-11 08:44:15.049] [ngap] [debug] NG Setup Response received
[2021-03-11 08:44:15.049] [ngap] [info] NG Setup procedure is successful
[2021-03-11 08:44:36.918] [mr] [info] New UE connected to gNB. Total number of UEs is now: 1
[2021-03-11 08:44:36.918] [rrc] [debug] Sending RRC Setup for UE[3]
[2021-03-11 08:44:36.918] [ngap] [debug] Initial NAS message received from UE 3
[2021-03-11 08:44:42.535] [mr] [error] Radio link failure for UE[3] with cause[RLS-HEARTBEAT-TIMEOUT]
[2021-03-11 08:44:42.535] [mr] [info] A UE disconnected from gNB. Total number of UEs is now: 0
[2021-03-11 08:44:42.535] [ngap] [debug] Sending UE Context release request (NG-RAN node initiated)
[2021-03-11 08:44:42.537] [ngap] [debug] UE Context Release Command received
[2021-03-11 08:44:42.537] [rrc] [debug] Releasing RRC connection for UE[3]
[2021-03-11 08:44:42.537] [rls] [warning] UE connection released or not established
[2021-03-11 08:44:42.975] [ngap] [debug] Sending an error indication with cause: radio-network/unknown-local-UE-NGAP-ID
[2021-03-11 08:44:48.976] [ngap] [debug] Sending an error indication with cause: radio-network/unknown-local-UE-NGAP-ID
[2021-03-11 08:44:54.979] [ngap] [debug] Sending an error indication with cause: radio-network/unknown-local-UE-NGAP-ID
[2021-03-11 08:45:00.981] [ngap] [debug] Sending an error indication with cause: radio-network/unknown-local-UE-NGAP-ID
[2021-03-11 08:47:26.969] [mr] [info] New UE connected to gNB. Total number of UEs is now: 1
[2021-03-11 08:47:26.969] [rrc] [debug] Sending RRC Setup for UE[4]
[2021-03-11 08:47:26.969] [ngap] [debug] Initial NAS message received from UE 4
[2021-03-11 08:47:32.148] [mr] [error] Radio link failure for UE[4] with cause[RLS-HEARTBEAT-TIMEOUT]
[2021-03-11 08:47:32.148] [mr] [info] A UE disconnected from gNB. Total number of UEs is now: 0
[2021-03-11 08:47:32.148] [ngap] [debug] Sending UE Context release request (NG-RAN node initiated)
[2021-03-11 08:47:32.149] [ngap] [debug] UE Context Release Command received
[2021-03-11 08:47:32.149] [rrc] [debug] Releasing RRC connection for UE[4]
[2021-03-11 08:47:32.149] [rls] [warning] UE connection released or not established
[2021-03-11 08:47:33.035] [ngap] [debug] Sending an error indication with cause: radio-network/unknown-local-UE-NGAP-ID
[2021-03-11 08:47:39.038] [ngap] [debug] Sending an error indication with cause: radio-network/unknown-local-UE-NGAP-ID
[2021-03-11 08:47:45.040] [ngap] [debug] Sending an error indication with cause: radio-network/unknown-local-UE-NGAP-ID

UE:

ubuntu@ip-172-31-203-193:~/UERANSIM/build$ sudo ./nr-ue -c free5gc-ue.yaml
UERANSIM v3.1.4
[2021-03-11 08:47:26.968] [nas] [debug] NAS layer started
[2021-03-11 08:47:26.969] [rrc] [debug] RRC layer started
[2021-03-11 08:47:26.969] [nas] [info] UE switches to state [MM-DEREGISTERED/PLMN-SEARCH]
[2021-03-11 08:47:26.969] [nas] [info] UE connected to gNB
[2021-03-11 08:47:26.969] [nas] [info] UE switches to state [MM-DEREGISTERED/NORMAL-SERVICE]
[2021-03-11 08:47:26.969] [nas] [debug] Sending Initial Registration
[2021-03-11 08:47:26.969] [nas] [info] UE switches to state [MM-REGISTER-INITIATED/NA]
[2021-03-11 08:47:26.969] [rrc] [debug] Sending RRC Setup Request
[2021-03-11 08:47:26.969] [rrc] [info] RRC connection established
[2021-03-11 08:47:26.969] [nas] [info] UE switches to state [CM-CONNECTED]
terminate called after throwing an instance of 'std::runtime_error'
  what():  invalid NAS message type
Aborted

AMF logs:

2021-03-11T08:47:39Z [DEBU][AMF][NGAP] Write 41 bytes (/go/src/free5gc/src/amf/ngap/message/send.go:40 free5gc/src/amf/ngap/message.SendToRan)
2021-03-11T08:47:39Z [WARN][AMF][NGAP] Cause RadioNetwork[14] (/go/src/free5gc/src/amf/ngap/handler.go:4113 free5gc/src/amf/ngap.printAndGetCause)
2021-03-11T08:47:45Z [WARN][AMF][Gmm] [NAS] T3560 expires, retransmit Security Mode Command (retry: 3) (/go/src/free5gc/src/amf/gmm/message/send.go:215 free5gc/src/amf/gmm/message.SendSecurityModeCommand.func1)
2021-03-11T08:47:45Z [INFO][AMF][NGAP] [AMF] Send Downlink Nas Transport (/go/src/free5gc/src/amf/ngap/message/send.go:145 free5gc/src/amf/ngap/message.SendDownlinkNasTransport)
2021-03-11T08:47:45Z [WARN][AMF][NGAP] AmfUe is nil (/go/src/free5gc/src/amf/ngap/message/send.go:59 free5gc/src/amf/ngap/message.SendToRanUe)
2021-03-11T08:47:45Z [DEBU][AMF][NGAP] [NGAP] Send To Ran [IP: 172.31.203.193:47389] (/go/src/free5gc/src/amf/ngap/message/send.go:34 free5gc/src/amf/ngap/message.SendToRan)
2021-03-11T08:47:45Z [DEBU][AMF][NGAP] Write 41 bytes (/go/src/free5gc/src/amf/ngap/message/send.go:40 free5gc/src/amf/ngap/message.SendToRan)
2021-03-11T08:47:45Z [WARN][AMF][NGAP] Cause RadioNetwork[14] (/go/src/free5gc/src/amf/ngap/handler.go:4113 free5gc/src/amf/ngap.printAndGetCause)
2021-03-11T08:47:47Z [DEBU][AMF][NGAP] Read EOF from client (/go/src/free5gc/src/amf/ngap/service/service.go:145 free5gc/src/amf/ngap/service.handleConnection)
2021-03-11T08:47:51Z [WARN][AMF][Gmm] [NAS] T3560 expires, retransmit Security Mode Command (retry: 4) (/go/src/free5gc/src/amf/gmm/message/send.go:215 free5gc/src/amf/gmm/message.SendSecurityModeCommand.func1)
2021-03-11T08:47:51Z [INFO][AMF][NGAP] [AMF] Send Downlink Nas Transport (/go/src/free5gc/src/amf/ngap/message/send.go:145 free5gc/src/amf/ngap/message.SendDownlinkNasTransport)
2021-03-11T08:47:51Z [WARN][AMF][NGAP] AmfUe is nil (/go/src/free5gc/src/amf/ngap/message/send.go:59 free5gc/src/amf/ngap/message.SendToRanUe)

Config UE:

# IMSI number of the UE. IMSI = [MCC|MNC|MSISDN] (In total 15 or 16 digits)
supi: 'imsi-208930000000003'
# Mobile Country Code value of HPLMN
mcc: '208'
# Mobile Network Code value of HPLMN (2 or 3 digits)
mnc: '93'

# Permanent subscription key
key: '8baf473f2f8fd09487cccbd7097c6862'
# Operator code (OP or OPC) of the UE
op: '8e27b6af0e692e750f32667a3b14605d'
# This value specifies the OP type and it can be either 'OP' or 'OPC'
opType: 'OP'
# Authentication Management Field (AMF) value
amf: '8000'
# IMEI number of the device. It is used if no SUPI is provided
imei: '356938035643803'
# IMEISV number of the device. It is used if no SUPI and IMEI is provided
imeiSv: '4370816125816151'

# List of gNB IP addresses for Radio Link Simulation
gnbSearchList:
  - 127.0.0.1

# Initial PDU sessions to be established
sessions:
  - type: 'IPv4'
    apn: 'internet'
    slice:
      sst: 0x01
      sd: 0x010203

# Configured NSSAI for this UE by HPLMN
configured-nssai:
  - sst: 0x01
    sd: 0x010203

# Default Configured NSSAI for this UE
default-nssai:
  - sst: 1
    sd: 1

# Supported encryption algorithms by this UE
integrity:
  IA1: true
  IA2: true
  IA3: true

# Supported integrity algorithms by this UE
ciphering:
  EA1: true
  EA2: true
  EA3: true

Config gNB:

mcc: '208'          # Mobile Country Code value
mnc: '93'           # Mobile Network Code value (2 or 3 digits)

nci: '0x000000010'  # NR Cell Identity (36-bit)
idLength: 32        # NR gNB ID length in bits [22...32]
tac: 1              # Tracking Area Code

linkIp: 127.0.0.1   # gNB's local IP address for Radio Link Simulation (Usually same with local IP)
ngapIp: 172.31.203.193   # gNB's local IP address for N2 Interface (Usually same with local IP)
gtpIp: 172.31.203.193    # gNB's local IP address for N3 Interface (Usually same with local IP)

# List of AMF address information
amfConfigs:
  - address: 172.31.203.7
    port: 38412

# List of supported S-NSSAIs by this gNB
slices:
  - sst: 0x1
    sd: 0x010203

# Indicates whether or not SCTP stream number errors should be ignored.
ignoreStreamIds: true
aligungr commented 3 years ago

@infinitydon

PCAP file will be very helpful to solve this. Please attach if you have one. (ngap/nas packets will be sufficient).

Thanks for reporting this issue.

infinitydon commented 3 years ago

@aligungr

Kindly see attached.

ueransim-free5gc.zip

aligungr commented 3 years ago

@infinitydon

In the packet 160, AMF sends a packet with security header type "integrity protected with new 5GS security context". And it means that the packet is a SecurityModeCommand, but the packet itself is either encrypted or corrupted. (And SecurityModeCommand should not be encrypted)

Therefore we can say that there is a bug on AMF side.

And it can be related to this issue: https://github.com/free5gc/free5gc/issues/104

Btw, which free5gc version are you using?

infinitydon commented 3 years ago

I am using Freegc v3.0.4:

[ec2-user@ip-172-31-38-94 istio-injection]$ kubectl -n free5gc logs free5gc-amf-deployment-86ddbdf69d-b9bbf | more
2021-03-11T08:48:02Z [INFO][AMF][App] amf
2021-03-11T08:48:02Z [INFO][AMF][App] AMF version:
        version: v3.0.4-5-g797c046
        build time: 2020-10-23T14:50:06Z
        commit hash: 1b92f8cf
        commit time: 2020-09-28T21:02:22Z
        go version: go1.14.4 linux/amd64
aligungr commented 3 years ago

In the past, they said that the issue was fixed in release v3.0.4, but perhaps there is another bug. I think free5gc should look at this issue, because clearly there is a bug on AMF side.

infinitydon commented 3 years ago

I was able to get this working by using the following AMF security config:

      security:
        integrityOrder:
       #  - NIA0
          - NIA2
        cipheringOrder:
      #   - NEA0
          - NEA2
ubuntu@ip-172-31-203-193:~/UERANSIM/build$ sudo ./nr-ue -c free5gc-ue.yaml
UERANSIM v3.1.4
[2021-03-11 14:04:13.380] [nas] [debug] NAS layer started
[2021-03-11 14:04:13.381] [rrc] [debug] RRC layer started
[2021-03-11 14:04:13.381] [nas] [info] UE switches to state [MM-DEREGISTERED/PLMN-SEARCH]
[2021-03-11 14:04:13.381] [nas] [info] UE connected to gNB
[2021-03-11 14:04:13.381] [nas] [info] UE switches to state [MM-DEREGISTERED/NORMAL-SERVICE]
[2021-03-11 14:04:13.381] [nas] [debug] Sending Initial Registration
[2021-03-11 14:04:13.381] [nas] [info] UE switches to state [MM-REGISTER-INITIATED/NA]
[2021-03-11 14:04:13.381] [rrc] [debug] Sending RRC Setup Request
[2021-03-11 14:04:13.382] [rrc] [info] RRC connection established
[2021-03-11 14:04:13.382] [nas] [info] UE switches to state [CM-CONNECTED]
[2021-03-11 14:04:13.468] [nas] [debug] Security Mode Command received
[2021-03-11 14:04:13.468] [nas] [debug] Derived NAS keys integrity[48497A93CC85318C59DEF6634378BFA2] ciphering[E67A0C93F8293575A1ACAB5202CABB04]
[2021-03-11 14:04:13.468] [nas] [debug] Selected integrity[2] ciphering[2]
[2021-03-11 14:04:13.680] [nas] [debug] Registration accept received
[2021-03-11 14:04:13.680] [nas] [info] UE switches to state [MM-REGISTERED/NORMAL-SERVICE]
[2021-03-11 14:04:13.680] [nas] [info] Initial Registration is successful
[2021-03-11 14:04:13.680] [nas] [info] Initial PDU sessions are establishing [1#]
[2021-03-11 14:04:13.680] [nas] [debug] Sending PDU session establishment request
[2021-03-11 14:04:14.211] [nas] [warning] SM cause received in PduSessionEstablishmentAccept: PDU_SESSION_TYPE_IPV4_ONLY_ALLOWED
[2021-03-11 14:04:14.211] [nas] [info] PDU Session establishment is successful PSI[1]
[2021-03-11 14:04:14.232] [app] [info] Connection setup for PDU session[1] is successful, TUN interface[uesimtun0, 60.60.0.1] is up.