search

aligungr / UERANSIM

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

UE not registering in new version #349

Open pragnyakiri opened 3 years ago

pragnyakiri commented 3 years ago

Hi @aligungr

In the latest version of UERANSIM (v3.2.1), the UE when run, is not getting registered to the network. Is this a bug ? Because I did not find any option to Register the UE in ./nr-cli also.

Thanks, Pradnya

aligungr commented 3 years ago

Hi @pragnyakiri

Please make sure that you successfully configured and run the UE, gNB, and the core network.

Regards

pragnyakiri commented 3 years ago

The gNB is connected to the Core. And it is also detecting the UE signal.

gNB logs: ubuntu@ueransim-gnb:~/UERANSIM/build$ ./nr-gnb -c ../config/free5gc-gnb.yaml UERANSIM v3.2.1 [2021-06-16 04:11:04.444] [sctp] [info] Trying to establish SCTP connection... (192.168.1.247:38412) [2021-06-16 04:11:04.458] [sctp] [info] SCTP connection established (192.168.1.247:38412) [2021-06-16 04:11:04.459] [sctp] [debug] SCTP association setup ascId[5] [2021-06-16 04:11:04.459] [ngap] [debug] Sending NG Setup Request [2021-06-16 04:11:04.469] [ngap] [debug] NG Setup Response received [2021-06-16 04:11:04.469] [ngap] [info] NG Setup procedure is successful [2021-06-16 04:11:40.892] [rrc] [debug] UE[1] new signal detected

UE logs: ubuntu@ueransim-ue:~/UERANSIM/build$ sudo ./nr-ue -c ../config/free5gc-ue.yaml [sudo] password for ubuntu: UERANSIM v3.2.1 [2021-06-16 04:11:40.890] [nas] [info] UE switches to state [MM-DEREGISTERED/PLMN-SEARCH] [2021-06-16 04:11:40.892] [rrc] [debug] New signal detected for cell[1], total [1] cells in coverage [2021-06-16 04:11:40.892] [nas] [info] Selected plmn[208/93] [2021-06-16 04:11:40.892] [rrc] [info] Selected cell plmn[208/93] tac[1] category[ACCEPTABLE] [2021-06-16 04:11:40.893] [nas] [info] UE switches to state [MM-DEREGISTERED/PS] [2021-06-16 04:11:40.893] [nas] [info] UE switches to state [MM-DEREGISTERED/LIMITED-SERVICE]

What is wrong here ?

PallaviTharigonda commented 3 years ago

The gNB is connected to the Core. And it is also detecting the UE signal.

gNB logs: ubuntu@ueransim-gnb:~/UERANSIM/build$ ./nr-gnb -c ../config/free5gc-gnb.yaml UERANSIM v3.2.1 Duplicate of # [2021-06-16 04:11:04.444] [sctp] [info] Trying to establish SCTP connection... (192.168.1.247:38412) [2021-06-16 04:11:04.458] [sctp] [info] SCTP connection established (192.168.1.247:38412) [2021-06-16 04:11:04.459] [sctp] [debug] SCTP association setup ascId[5] [2021-06-16 04:11:04.459] [ngap] [debug] Sending NG Setup Request [2021-06-16 04:11:04.469] [ngap] [debug] NG Setup Response received [2021-06-16 04:11:04.469] [ngap] [info] NG Setup procedure is successful [2021-06-16 04:11:40.892] [rrc] [debug] UE[1] new signal detected

UE logs: ubuntu@ueransim-ue:~/UERANSIM/build$ sudo ./nr-ue -c ../config/free5gc-ue.yaml [sudo] password for ubuntu: UERANSIM v3.2.1 [2021-06-16 04:11:40.890] [nas] [info] UE switches to state [MM-DEREGISTERED/PLMN-SEARCH] [2021-06-16 04:11:40.892] [rrc] [debug] New signal detected for cell[1], total [1] cells in coverage [2021-06-16 04:11:40.892] [nas] [info] Selected plmn[208/93] [2021-06-16 04:11:40.892] [rrc] [info] Selected cell plmn[208/93] tac[1] category[ACCEPTABLE] [2021-06-16 04:11:40.893] [nas] [info] UE switches to state [MM-DEREGISTERED/PS] [2021-06-16 04:11:40.893] [nas] [info] UE switches to state [MM-DEREGISTERED/LIMITED-SERVICE]

What is wrong here ?

I'm also facing same issue

aligungr commented 3 years ago

@pragnyakiri @PallaviTharigonda

I'll try to check this today

aligungr commented 3 years ago

@pragnyakiri @PallaviTharigonda

I detected a bug related to cell selection mechanism. Sometimes the UE was trying to select a cell before selecting a PLMN.

This issue should be fixed now, please try again with the latest code, and let me know if it works for you.

Thanks

PallaviTharigonda commented 3 years ago

Now i'm getting like this

ubuntu@ip-192-168-28-153:~/UERANSIM/build$ ./nr-gnb -c open5gs-gnb.yaml
UERANSIM v3.2.1
[2021-06-21 13:05:27.349] [sctp] [info] Trying to establish SCTP connection... (192.168.76.86:38412)
[2021-06-21 13:05:27.353] [sctp] [info] SCTP connection established (192.168.76.86:38412)
[2021-06-21 13:05:27.354] [sctp] [debug] SCTP association setup ascId[4]
[2021-06-21 13:05:27.354] [ngap] [debug] Sending NG Setup Request
[2021-06-21 13:05:27.355] [ngap] [debug] NG Setup Response received
[2021-06-21 13:05:27.355] [ngap] [info] NG Setup procedure is successful
ubuntu@ip-192-168-28-153:~/UERANSIM/build$ sudo ./nr-ue -c open5gs-ue.yaml -n 4 -i 208930000000000
UERANSIM v3.2.1
[2021-06-21 13:05:53.257] [208930000000003|nas] [info] UE switches to state [MM-DEREGISTERED/PLMN-SEARCH]
[2021-06-21 13:05:53.258] [208930000000001|nas] [info] UE switches to state [MM-DEREGISTERED/PLMN-SEARCH]
[2021-06-21 13:05:53.258] [208930000000000|nas] [info] UE switches to state [MM-DEREGISTERED/PLMN-SEARCH]
[2021-06-21 13:05:53.259] [208930000000000|rrc] [debug] New signal detected for cell[1], total [1] cells in coverage
[2021-06-21 13:05:53.258] [208930000000002|rrc] [debug] New signal detected for cell[1], total [1] cells in coverage
[2021-06-21 13:05:53.258] [208930000000002|nas] [info] UE switches to state [MM-DEREGISTERED/PLMN-SEARCH]
[2021-06-21 13:05:53.259] [208930000000002|nas] [info] Selected plmn[208/93]
[2021-06-21 13:05:53.258] [208930000000003|rrc] [debug] New signal detected for cell[1], total [1] cells in coverage
[2021-06-21 13:05:53.259] [208930000000002|rrc] [info] Selected cell plmn[208/93] tac[7] category[SUITABLE]
[2021-06-21 13:05:53.258] [208930000000001|rrc] [debug] New signal detected for cell[1], total [1] cells in coverage
[2021-06-21 13:05:53.259] [208930000000002|nas] [info] UE switches to state [MM-DEREGISTERED/PS]
[2021-06-21 13:05:53.259] [208930000000001|nas] [info] Selected plmn[208/93]
[2021-06-21 13:05:53.259] [208930000000001|rrc] [info] Selected cell plmn[208/93] tac[7] category[SUITABLE]
[2021-06-21 13:05:53.259] [208930000000001|nas] [info] UE switches to state [MM-DEREGISTERED/PS]
[2021-06-21 13:05:53.259] [208930000000001|nas] [info] UE switches to state [MM-DEREGISTERED/NORMAL-SERVICE]
[2021-06-21 13:05:53.259] [208930000000001|nas] [debug] Initial registration required due to [MM-DEREG-NORMAL-SERVICE]
[2021-06-21 13:05:53.259] [208930000000001|nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-06-21 13:05:53.260] [208930000000001|nas] [debug] Sending Initial Registration
[2021-06-21 13:05:53.260] [208930000000001|nas] [info] UE switches to state [MM-REGISTER-INITIATED]
[2021-06-21 13:05:53.259] [208930000000000|nas] [info] Selected plmn[208/93]
[2021-06-21 13:05:53.259] [208930000000002|nas] [info] UE switches to state [MM-DEREGISTERED/NORMAL-SERVICE]
[2021-06-21 13:05:53.259] [208930000000003|nas] [info] Selected plmn[208/93]
[2021-06-21 13:05:53.260] [208930000000002|nas] [debug] Initial registration required due to [MM-DEREG-NORMAL-SERVICE]
[2021-06-21 13:05:53.260] [208930000000002|nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-06-21 13:05:53.260] [208930000000002|nas] [debug] Sending Initial Registration
[2021-06-21 13:05:53.260] [208930000000002|nas] [info] UE switches to state [MM-REGISTER-INITIATED]
[2021-06-21 13:05:53.260] [208930000000003|rrc] [info] Selected cell plmn[208/93] tac[7] category[SUITABLE]
[2021-06-21 13:05:53.260] [208930000000003|nas] [info] UE switches to state [MM-DEREGISTERED/PS]
[2021-06-21 13:05:53.260] [208930000000003|nas] [info] UE switches to state [MM-DEREGISTERED/NORMAL-SERVICE]
[2021-06-21 13:05:53.260] [208930000000003|nas] [debug] Initial registration required due to [MM-DEREG-NORMAL-SERVICE]
[2021-06-21 13:05:53.260] [208930000000002|rrc] [debug] Sending RRC Setup Request
[2021-06-21 13:05:53.260] [208930000000002|rrc] [info] RRC connection established
[2021-06-21 13:05:53.260] [208930000000002|rrc] [info] UE switches to state [RRC-CONNECTED]
[2021-06-21 13:05:53.260] [208930000000002|nas] [info] UE switches to state [CM-CONNECTED]
[2021-06-21 13:05:53.262] [208930000000003|nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-06-21 13:05:53.262] [208930000000003|nas] [debug] Sending Initial Registration
[2021-06-21 13:05:53.262] [208930000000003|nas] [info] UE switches to state [MM-REGISTER-INITIATED]
[2021-06-21 13:05:53.262] [208930000000003|rrc] [debug] Sending RRC Setup Request
[2021-06-21 13:05:53.262] [208930000000001|rrc] [debug] Sending RRC Setup Request
[2021-06-21 13:05:53.262] [208930000000001|rrc] [info] RRC connection established
[2021-06-21 13:05:53.262] [208930000000001|rrc] [info] UE switches to state [RRC-CONNECTED]
[2021-06-21 13:05:53.262] [208930000000003|rrc] [info] RRC connection established
[2021-06-21 13:05:53.262] [208930000000003|rrc] [info] UE switches to state [RRC-CONNECTED]
[2021-06-21 13:05:53.262] [208930000000001|nas] [info] UE switches to state [CM-CONNECTED]
[2021-06-21 13:05:53.262] [208930000000003|nas] [info] UE switches to state [CM-CONNECTED]
[2021-06-21 13:05:53.275] [208930000000002|nas] [debug] Authentication Request received
[2021-06-21 13:05:53.283] [208930000000003|nas] [debug] Authentication Request received
[2021-06-21 13:05:53.283] [208930000000001|nas] [debug] Authentication Request received
[2021-06-21 13:05:53.291] [208930000000002|nas] [debug] Security Mode Command received
[2021-06-21 13:05:53.291] [208930000000002|nas] [debug] Selected integrity[2] ciphering[0]
[2021-06-21 13:05:53.303] [208930000000003|nas] [debug] Security Mode Command received
[2021-06-21 13:05:53.303] [208930000000003|nas] [debug] Selected integrity[2] ciphering[0]
[2021-06-21 13:05:53.314] [208930000000001|nas] [debug] Security Mode Command received
[2021-06-21 13:05:53.314] [208930000000001|nas] [debug] Selected integrity[2] ciphering[0]
[2021-06-21 13:05:53.330] [208930000000002|nas] [debug] Registration accept received
[2021-06-21 13:05:53.330] [208930000000002|nas] [info] UE switches to state [MM-REGISTERED/NORMAL-SERVICE]
[2021-06-21 13:05:53.330] [208930000000002|nas] [debug] Sending Registration Complete
[2021-06-21 13:05:53.330] [208930000000002|nas] [info] Initial Registration is successful
[2021-06-21 13:05:53.330] [208930000000002|nas] [debug] Sending PDU Session Establishment Request
[2021-06-21 13:05:53.330] [208930000000002|nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-06-21 13:05:53.330] [208930000000003|nas] [debug] Registration accept received
[2021-06-21 13:05:53.330] [208930000000003|nas] [info] UE switches to state [MM-REGISTERED/NORMAL-SERVICE]
[2021-06-21 13:05:53.330] [208930000000003|nas] [debug] Sending Registration Complete
[2021-06-21 13:05:53.330] [208930000000003|nas] [info] Initial Registration is successful
[2021-06-21 13:05:53.330] [208930000000003|nas] [debug] Sending PDU Session Establishment Request
[2021-06-21 13:05:53.334] [208930000000003|nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-06-21 13:05:53.343] [208930000000001|nas] [debug] Registration accept received
[2021-06-21 13:05:53.343] [208930000000001|nas] [info] UE switches to state [MM-REGISTERED/NORMAL-SERVICE]
[2021-06-21 13:05:53.343] [208930000000001|nas] [debug] Sending Registration Complete
[2021-06-21 13:05:53.343] [208930000000001|nas] [info] Initial Registration is successful
[2021-06-21 13:05:53.343] [208930000000001|nas] [debug] Sending PDU Session Establishment Request
[2021-06-21 13:05:53.344] [208930000000001|nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-06-21 13:05:53.345] [208930000000002|nas] [debug] Configuration Update Command received
[2021-06-21 13:05:53.345] [208930000000003|nas] [debug] Configuration Update Command received
[2021-06-21 13:05:53.346] [208930000000001|nas] [debug] Configuration Update Command received
[2021-06-21 13:05:55.759] [208930000000000|rrc] [info] Selected cell plmn[208/93] tac[7] category[SUITABLE]
[2021-06-21 13:05:55.759] [208930000000000|nas] [info] UE switches to state [MM-DEREGISTERED/PS]
[2021-06-21 13:05:55.759] [208930000000000|nas] [info] UE switches to state [MM-DEREGISTERED/NORMAL-SERVICE]
[2021-06-21 13:05:55.759] [208930000000000|nas] [debug] Initial registration required due to [MM-DEREG-NORMAL-SERVICE]
[2021-06-21 13:05:55.759] [208930000000000|nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-06-21 13:05:55.759] [208930000000000|nas] [debug] Sending Initial Registration
[2021-06-21 13:05:55.759] [208930000000000|rrc] [debug] Sending RRC Setup Request
[2021-06-21 13:05:55.759] [208930000000000|nas] [info] UE switches to state [MM-REGISTER-INITIATED]
[2021-06-21 13:05:55.759] [208930000000000|rrc] [info] RRC connection established
[2021-06-21 13:05:55.759] [208930000000000|rrc] [info] UE switches to state [RRC-CONNECTED]
[2021-06-21 13:05:55.759] [208930000000000|nas] [info] UE switches to state [CM-CONNECTED]
[2021-06-21 13:05:55.767] [208930000000000|nas] [debug] Authentication Request received
[2021-06-21 13:05:55.778] [208930000000000|nas] [debug] Security Mode Command received
[2021-06-21 13:05:55.778] [208930000000000|nas] [debug] Selected integrity[2] ciphering[0]
[2021-06-21 13:05:55.791] [208930000000000|nas] [debug] Registration accept received
[2021-06-21 13:05:55.791] [208930000000000|nas] [info] UE switches to state [MM-REGISTERED/NORMAL-SERVICE]
[2021-06-21 13:05:55.791] [208930000000000|nas] [debug] Sending Registration Complete
[2021-06-21 13:05:55.791] [208930000000000|nas] [info] Initial Registration is successful
[2021-06-21 13:05:55.791] [208930000000000|nas] [debug] Sending PDU Session Establishment Request
[2021-06-21 13:05:55.792] [208930000000000|nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-06-21 13:05:55.997] [208930000000000|nas] [debug] Configuration Update Command received
[2021-06-21 13:06:05.999] [208930000000000|nas] [error] SM forwarding failure for message type[193] with cause[PAYLOAD_NOT_FORWARDED]
[2021-06-21 13:06:05.999] [208930000000000|nas] [debug] Aborting SM procedure for PTI[1], PSI[1]
[2021-06-21 13:06:06.470] [208930000000000|nas] [debug] Sending PDU Session Establishment Request
[2021-06-21 13:06:06.470] [208930000000000|nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-06-21 13:06:10.274] [208930000000003|nas] [warning] Retransmitting PDU Session Establishment Request due to T3580 expiry
[2021-06-21 13:06:10.274] [208930000000001|nas] [warning] Retransmitting PDU Session Establishment Request due to T3580 expiry
[2021-06-21 13:06:10.274] [208930000000001|nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-06-21 13:06:10.274] [208930000000003|nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-06-21 13:06:10.274] [208930000000002|nas] [warning] Retransmitting PDU Session Establishment Request due to T3580 expiry
[2021-06-21 13:06:10.274] [208930000000002|nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-06-21 13:06:16.475] [208930000000000|nas] [error] SM forwarding failure for message type[193] with cause[PAYLOAD_NOT_FORWARDED]
[2021-06-21 13:06:16.475] [208930000000000|nas] [debug] Aborting SM procedure for PTI[1], PSI[1]
[2021-06-21 13:06:17.354] [208930000000000|nas] [debug] Sending PDU Session Establishment Request
[2021-06-21 13:06:17.354] [208930000000000|nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-06-21 13:06:20.278] [208930000000001|nas] [error] SM forwarding failure for message type[193] with cause[PAYLOAD_NOT_FORWARDED]
[2021-06-21 13:06:20.278] [208930000000001|nas] [debug] Aborting SM procedure for PTI[1], PSI[1]
[2021-06-21 13:06:20.478] [208930000000003|nas] [error] SM forwarding failure for message type[193] with cause[PAYLOAD_NOT_FORWARDED]
[2021-06-21 13:06:20.478] [208930000000003|nas] [debug] Aborting SM procedure for PTI[1], PSI[1]
[2021-06-21 13:06:20.478] [208930000000002|nas] [error] SM forwarding failure for message type[193] with cause[PAYLOAD_NOT_FORWARDED]
[2021-06-21 13:06:20.478] [208930000000002|nas] [debug] Aborting SM procedure for PTI[1], PSI[1]
[2021-06-21 13:06:20.782] [208930000000001|nas] [debug] Sending PDU Session Establishment Request
[2021-06-21 13:06:20.782] [208930000000002|nas] [debug] Sending PDU Session Establishment Request
[2021-06-21 13:06:20.782] [208930000000002|nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-06-21 13:06:20.782] [208930000000003|nas] [debug] Sending PDU Session Establishment Request
[2021-06-21 13:06:20.782] [208930000000003|nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-06-21 13:06:20.782] [208930000000001|nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-06-21 13:06:27.358] [208930000000000|nas] [error] SM forwarding failure for message type[193] with cause[PAYLOAD_NOT_FORWARDED]
[2021-06-21 13:06:27.358] [208930000000000|nas] [debug] Aborting SM procedure for PTI[1], PSI[1]
[2021-06-21 13:06:27.389] [208930000000000|nas] [debug] Sending PDU Session Establishment Request
[2021-06-21 13:06:27.389] [208930000000000|nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-06-21 13:06:30.788] [208930000000002|nas] [error] SM forwarding failure for message type[193] with cause[PAYLOAD_NOT_FORWARDED]
[2021-06-21 13:06:30.789] [208930000000002|nas] [debug] Aborting SM procedure for PTI[1], PSI[1]
[2021-06-21 13:06:30.990] [208930000000003|nas] [error] SM forwarding failure for message type[193] with cause[PAYLOAD_NOT_FORWARDED]
[2021-06-21 13:06:30.990] [208930000000003|nas] [debug] Aborting SM procedure for PTI[1], PSI[1]
[2021-06-21 13:06:30.990] [208930000000001|nas] [error] SM forwarding failure for message type[193] with cause[PAYLOAD_NOT_FORWARDED]
[2021-06-21 13:06:30.990] [208930000000001|nas] [debug] Aborting SM procedure for PTI[1], PSI[1]
[2021-06-21 13:06:31.792] [208930000000001|nas] [debug] Sending PDU Session Establishment Request
[2021-06-21 13:06:31.792] [208930000000001|nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-06-21 13:06:31.792] [208930000000003|nas] [debug] Sending PDU Session Establishment Request
[2021-06-21 13:06:31.792] [208930000000002|nas] [debug] Sending PDU Session Establishment Request
[2021-06-21 13:06:31.792] [208930000000003|nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-06-21 13:06:31.792] [208930000000002|nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-06-21 13:06:37.392] [208930000000000|nas] [error] SM forwarding failure for message type[193] with cause[PAYLOAD_NOT_FORWARDED]
[2021-06-21 13:06:37.392] [208930000000000|nas] [debug] Aborting SM procedure for PTI[1], PSI[1]
[2021-06-21 13:06:38.399] [208930000000000|nas] [debug] Sending PDU Session Establishment Request
[2021-06-21 13:06:38.399] [208930000000000|nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
aligungr commented 3 years ago

@PallaviTharigonda

"SM forwarding failure" errors are usually caused by AMF or SMF. Please check the core network logs, if an error is visible. You can also share the logs here.

dongzx666 commented 3 years ago

@PallaviTharigonda Have you solved it? I updated Open5GS to the latest version yesterday. The error log of UERANSIM is the same as yours...

PallaviTharigonda commented 3 years ago

@dongzx666 No it's not solved . I've broken the connection between UPF and SMF through eth0 and have added new interface to it.I think that's the reason it's failed for me. Can u send the logs of yours ,so that I can cross verify with mine.

dongzx666 commented 3 years ago

@PallaviTharigonda Thank you very much. I just found out the reason. The situation is completely different from yours (the port number of the new BSF NF added by Open5GS conflicts with the port number of NRF), but the error log of UERANSIM is surprisingly similar to yours. Thanks again.

pragnyakiri commented 3 years ago

@pragnyakiri @PallaviTharigonda

I detected a bug related to cell selection mechanism. Sometimes the UE was trying to select a cell before selecting a PLMN.

This issue should be fixed now, please try again with the latest code, and let me know if it works for you.

Thanks

Thanks @aligungr, It is working with the latest code.

jamjad333 commented 6 months ago

@dongzx666 did you solve the issue after changing BSF port?