Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

UE Error while Ping another UE #426

Closed
minziran opened this issue Oct 30, 2021 · 6 comments
Closed

UE Error while Ping another UE #426

minziran opened this issue Oct 30, 2021 · 6 comments

Comments

@minziran
Copy link

Hi Ali,
I met the similar problem as the attached issues.
#258
I updated the UERANSIM version(latest) and the problem is solved, which means the gNB works well.
I mirrored the traffic in the UPF side by "iptables -I PREROUTING -t mangle -i eth0 -j TEE --gateway 173.16.1.1"
Howerver, when I ping a UE from a UE, using the following command,

Ping -I uesimtun0 60.60.0.2
4 bytes from 60.60.0.3: icmp_seq=18 ttl=63 time=149 ms (DUP!)
64 bytes from 60.60.0.3: icmp_seq=18 ttl=63 time=149 ms (DUP!)
64 bytes from 60.60.0.3: icmp_seq=18 ttl=63 time=224 ms (DUP!)
^C
--- 60.60.0.3 ping statistics ---
19 packets transmitted, 18 received, +175302 duplicates, 5.26316% packet loss, time 18001ms
rtt min/avg/max/mdev = 16.903/479.145/954.834/208.845 ms
root@1e9f9dab7171:/# ping -I uesimtun0 60.60.0.3
PING 60.60.0.3 (60.60.0.3) from 60.60.0.2 uesimtun0: 56(84) bytes of data.
^C
--- 60.60.0.3 ping statistics ---
50 packets transmitted, 0 received, 100% packet loss, time 50183ms

root@1e9f9dab7171:/# ping -I uesimtun0 60.60.0.1
PING 60.60.0.1 (60.60.0.1) from 60.60.0.2 uesimtun0: 56(84) bytes of data.
^C
--- 60.60.0.1 ping statistics ---
85 packets transmitted, 0 received, 100% packet loss, time 86001ms

It works well at the very beginning, then the UE(60.60.0.3) crashed. The error is attached
[2021-10-29 20:52:30.072] [nas] [info] UE switches to state [MM-DEREGISTERED/PLMN-SEARCH]
[2021-10-29 20:52:30.073] [rrc] [debug] New signal detected for cell[1], total [1] cells in coverage
[2021-10-29 20:52:30.073] [nas] [info] Selected plmn[208/93]
[2021-10-29 20:52:30.073] [rrc] [info] Selected cell plmn[208/93] tac[1] category[SUITABLE]
[2021-10-29 20:52:30.073] [nas] [info] UE switches to state [MM-DEREGISTERED/PS]
[2021-10-29 20:52:30.073] [nas] [info] UE switches to state [MM-DEREGISTERED/NORMAL-SERVICE]
[2021-10-29 20:52:30.073] [nas] [debug] Initial registration required due to [MM-DEREG-NORMAL-SERVICE]
[2021-10-29 20:52:30.073] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-10-29 20:52:30.073] [nas] [debug] Sending Initial Registration
[2021-10-29 20:52:30.073] [rrc] [debug] Sending RRC Setup Request
[2021-10-29 20:52:30.073] [nas] [info] UE switches to state [MM-REGISTER-INITIATED]
[2021-10-29 20:52:30.074] [rrc] [info] RRC connection established
[2021-10-29 20:52:30.074] [rrc] [info] UE switches to state [RRC-CONNECTED]
[2021-10-29 20:52:30.074] [nas] [info] UE switches to state [CM-CONNECTED]
[2021-10-29 20:52:30.143] [nas] [debug] Authentication Request received
[2021-10-29 20:52:30.143] [nas] [debug] Sending Authentication Failure due to SQN out of range
[2021-10-29 20:52:30.203] [nas] [debug] Authentication Request received
[2021-10-29 20:52:30.234] [nas] [debug] Security Mode Command received
[2021-10-29 20:52:30.234] [nas] [debug] Selected integrity[2] ciphering[0]
[2021-10-29 20:52:30.434] [nas] [debug] Registration accept received
[2021-10-29 20:52:30.434] [nas] [info] UE switches to state [MM-REGISTERED/NORMAL-SERVICE]
[2021-10-29 20:52:30.434] [nas] [debug] Sending Registration Complete
[2021-10-29 20:52:30.435] [nas] [info] Initial Registration is successful
[2021-10-29 20:52:30.435] [nas] [debug] Sending PDU Session Establishment Request
[2021-10-29 20:52:30.435] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-10-29 20:52:30.699] [nas] [debug] PDU Session Establishment Accept received
[2021-10-29 20:52:30.699] [nas] [warning] SM cause received in PduSessionEstablishmentAccept [PDU_SESSION_TYPE_IPV4_ONLY_ALLOWED]
[2021-10-29 20:52:30.699] [nas] [info] PDU Session establishment is successful PSI[1]
[2021-10-29 20:52:30.727] [app] [info] Connection setup for PDU session[1] is successful, TUN interface[uesimtun0, 60.60.0.1] is up.
[2021-10-29 21:52:30.704] [nas] [debug] NAS timer[3512] expired [1]
[2021-10-29 21:52:30.704] [nas] [debug] Mobility registration updating required due to [T3512-EXPIRY]
[2021-10-29 21:52:30.704] [nas] [debug] Sending Periodic Registration with update cause [T3512-EXPIRY]
[2021-10-29 21:52:30.704] [nas] [info] UE switches to state [MM-REGISTER-INITIATED]
[2021-10-29 21:52:30.709] [nas] [debug] Registration accept received
[2021-10-29 21:52:30.709] [nas] [info] UE switches to state [MM-REGISTERED/NORMAL-SERVICE]
[2021-10-29 21:52:30.709] [nas] [info] Periodic Registration is successful
[2021-10-29 22:52:31.301] [nas] [debug] NAS timer[3512] expired [1]
[2021-10-29 22:52:31.301] [nas] [debug] Mobility registration updating required due to [T3512-EXPIRY]
[2021-10-29 22:52:31.301] [nas] [debug] Sending Periodic Registration with update cause [T3512-EXPIRY]
[2021-10-29 22:52:31.301] [nas] [info] UE switches to state [MM-REGISTER-INITIATED]
[2021-10-29 22:52:31.306] [nas] [debug] Registration accept received
[2021-10-29 22:52:31.306] [nas] [info] UE switches to state [MM-REGISTERED/NORMAL-SERVICE]
[2021-10-29 22:52:31.306] [nas] [info] Periodic Registration is successful
[2021-10-29 23:52:31.898] [nas] [debug] NAS timer[3512] expired [1]
[2021-10-29 23:52:31.898] [nas] [debug] Mobility registration updating required due to [T3512-EXPIRY]
[2021-10-29 23:52:31.898] [nas] [debug] Sending Periodic Registration with update cause [T3512-EXPIRY]
[2021-10-29 23:52:31.898] [nas] [info] UE switches to state [MM-REGISTER-INITIATED]
[2021-10-29 23:52:31.903] [nas] [debug] Registration accept received
[2021-10-29 23:52:31.903] [nas] [info] UE switches to state [MM-REGISTERED/NORMAL-SERVICE]
[2021-10-29 23:52:31.903] [nas] [info] Periodic Registration is successful

I would appreciate any help!

Best regards,
Ziran

@minziran
Copy link
Author

The log from anther UE is attached
Thanks!

UERANSIM v3.2.4
[2021-10-29 20:52:30.264] [nas] [info] UE switches to state [MM-DEREGISTERED/PLMN-SEARCH]
[2021-10-29 20:52:30.267] [rrc] [debug] New signal detected for cell[1], total [1] cells in coverage
[2021-10-29 20:52:30.268] [nas] [info] Selected plmn[208/93]
[2021-10-29 20:52:30.268] [rrc] [info] Selected cell plmn[208/93] tac[1] category[SUITABLE]
[2021-10-29 20:52:30.268] [nas] [info] UE switches to state [MM-DEREGISTERED/PS]
[2021-10-29 20:52:30.268] [nas] [info] UE switches to state [MM-DEREGISTERED/NORMAL-SERVICE]
[2021-10-29 20:52:30.268] [nas] [debug] Initial registration required due to [MM-DEREG-NORMAL-SERVICE]
[2021-10-29 20:52:30.274] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-10-29 20:52:30.274] [nas] [debug] Sending Initial Registration
[2021-10-29 20:52:30.274] [nas] [info] UE switches to state [MM-REGISTER-INITIATED]
[2021-10-29 20:52:30.274] [rrc] [debug] Sending RRC Setup Request
[2021-10-29 20:52:30.275] [rrc] [info] RRC connection established
[2021-10-29 20:52:30.275] [rrc] [info] UE switches to state [RRC-CONNECTED]
[2021-10-29 20:52:30.275] [nas] [info] UE switches to state [CM-CONNECTED]
[2021-10-29 20:52:30.543] [nas] [debug] Authentication Request received
[2021-10-29 20:52:30.740] [nas] [debug] Security Mode Command received
[2021-10-29 20:52:30.740] [nas] [debug] Selected integrity[2] ciphering[0]
[2021-10-29 20:52:30.908] [nas] [debug] Registration accept received
[2021-10-29 20:52:30.908] [nas] [info] UE switches to state [MM-REGISTERED/NORMAL-SERVICE]
[2021-10-29 20:52:30.908] [nas] [debug] Sending Registration Complete
[2021-10-29 20:52:30.908] [nas] [info] Initial Registration is successful
[2021-10-29 20:52:30.908] [nas] [debug] Sending PDU Session Establishment Request
[2021-10-29 20:52:30.908] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2021-10-29 20:52:31.197] [nas] [debug] PDU Session Establishment Accept received
[2021-10-29 20:52:31.197] [nas] [warning] SM cause received in PduSessionEstablishmentAccept [PDU_SESSION_TYPE_IPV4_ONLY_ALLOWED]
[2021-10-29 20:52:31.197] [nas] [info] PDU Session establishment is successful PSI[1]
[2021-10-29 20:52:31.215] [app] [info] Connection setup for PDU session[1] is successful, TUN interface[uesimtun0, 60.60.0.2] is up.
[2021-10-29 20:55:43.121] [rrc] [debug] Signal lost for cell[1], total [0] cells in coverage
[2021-10-29 20:55:43.121] [nas] [error] Radio link failure detected
[2021-10-29 20:55:43.121] [nas] [info] UE switches to state [CM-IDLE]
[2021-10-29 20:55:43.121] [nas] [info] UE switches to state [MM-REGISTERED/PS]
[2021-10-29 20:55:43.121] [nas] [info] UE switches to state [MM-REGISTERED/PLMN-SEARCH]
[2021-10-29 20:55:43.121] [nas] [error] PLMN selection failure, no cells in coverage
[2021-10-29 20:55:43.122] [rrc] [debug] New signal detected for cell[2], total [1] cells in coverage
[2021-10-29 20:55:45.153] [nas] [error] PLMN selection failure, no cells in coverage
[2021-10-29 20:55:45.345] [rrc] [warning] Acceptable cell selection failed in [1] cells. [1] no SI, [0] reserved, [0] barred, ftai [0]
[2021-10-29 20:55:45.345] [rrc] [error] Cell selection failure, no suitable or acceptable cell found
[2021-10-29 20:55:47.355] [nas] [error] PLMN selection failure, no cells in coverage
[2021-10-29 20:55:48.456] [nas] [info] UE switches to state [MM-REGISTERED/NO-CELL-AVAILABLE]
[2021-10-29 20:55:49.280] [nas] [info] Selected plmn[208/93]
[2021-10-29 20:55:49.281] [rrc] [info] Selected cell plmn[208/93] tac[1] category[SUITABLE]
[2021-10-29 20:55:49.281] [nas] [info] UE switches to state [MM-REGISTERED/PS]
[2021-10-29 20:55:49.281] [nas] [info] UE switches to state [MM-REGISTERED/NORMAL-SERVICE]
[2021-10-29 21:10:51.295] [nas] [debug] Uplink data status changed PSI[1] pending[true]
[2021-10-29 21:10:51.295] [nas] [debug] Service request required due to [IDLE-UPLINK-DATA-PENDING]
[2021-10-29 21:10:51.295] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_data]
[2021-10-29 21:10:51.295] [nas] [debug] Sending Service Request due to [IDLE-UPLINK-DATA-PENDING]
[2021-10-29 21:10:51.295] [nas] [info] UE switches to state [MM-SERVICE-REQUEST-INITIATED]
[2021-10-29 21:10:51.295] [rrc] [debug] Sending RRC Setup Request
[2021-10-29 21:11:06.408] [nas] [debug] NAS timer[3517] expired [1]
[2021-10-29 21:11:06.408] [nas] [info] UE switches to state [MM-REGISTERED/PS]
[2021-10-29 21:11:06.408] [nas] [info] UE switches to state [MM-REGISTERED/NORMAL-SERVICE]

@aligungr
Copy link
Owner

aligungr commented Nov 1, 2021

Hi Ziran

Unfortunately I could not help you about this problem. Because it's beyond to scope of UE and gNodeB, and is highly dependent on the core network's behavior. I mean everything seems OK from UE and gNodeB perspective.

Perhaps these threads may help you.

@minziran
Copy link
Author

minziran commented Nov 6, 2021

Thank you very much!
When I run the Iperf3 on both UEs. It worked well at the very beginning, after that

In the UE side, the new error message is like:
It says "Radio link failure detected"
2021-11-06 01:19:09.702] [rrc] [debug] Signal lost for cell[1], total [0] cells in coverage
[2021-11-06 01:19:09.702] [rrc] [debug] New signal detected for cell[2], total [1] cells in coverage
[2021-11-06 01:19:09.703] [nas] [error] Radio link failure detected
[2021-11-06 01:19:09.703] [nas] [info] UE switches to state [CM-IDLE]
[2021-11-06 01:19:09.703] [nas] [info] UE switches to state [MM-REGISTERED/PS]
[2021-11-06 01:19:09.703] [nas] [info] UE switches to state [MM-REGISTERED/PLMN-SEARCH]
[2021-11-06 01:19:09.704] [nas] [error] PLMN selection failure, no cells in coverage
[2021-11-06 01:19:09.890] [rrc] [warning] Acceptable cell selection failed in [1] cells. [1] no SI, [0] reserved, [0] barred, ftai [0]
[2021-11-06 01:19:09.890] [rrc] [error] Cell selection failure, no suitable or acceptable cell found
[2021-11-06 01:19:12.507] [nas] [error] PLMN selection failure, no cells in coverage
[2021-11-06 01:19:14.709] [nas] [info] UE switches to state [MM-REGISTERED/NO-CELL-AVAILABLE]
[2021-11-06 01:19:19.342] [nas] [info] Selected plmn[208/93]
[2021-11-06 01:19:19.342] [rrc] [info] Selected cell plmn[208/93] tac[1] category[SUITABLE]
[2021-11-06 01:19:19.342] [nas] [info] UE switches to state [MM-REGISTERED/PS]
[2021-11-06 01:19:19.343] [nas] [info] UE switches to state [MM-REGISTERED/NORMAL-SERVICE]
[2021-11-06 01:19:23.426] [nas] [debug] Uplink data status changed PSI[1] pending[true]
[2021-11-06 01:19:23.426] [nas] [debug] Service request required due to [IDLE-UPLINK-DATA-PENDING]
[2021-11-06 01:19:23.426] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_data]
[2021-11-06 01:19:23.426] [nas] [debug] Sending Service Request due to [IDLE-UPLINK-DATA-PENDING]
[2021-11-06 01:19:23.426] [nas] [info] UE switches to state [MM-SERVICE-REQUEST-INITIATED]
[2021-11-06 01:19:23.426] [rrc] [debug] Sending RRC Setup Request
[2021-11-06 01:19:39.171] [nas] [debug] NAS timer[3517] expired [1]
[2021-11-06 01:19:39.171] [nas] [info] UE switches to state [MM-REGISTERED/PS]
[2021-11-06 01:19:39.171] [nas] [info] UE switches to state [MM-REGIST

The gNB side says:
Discarding RRC Setup Request, UE context already exists

[2021-11-06 01:36:27.405] [sctp] [info] Trying to establish SCTP connection... (10.100.200.102:38412)
[2021-11-06 01:36:27.407] [sctp] [info] SCTP connection established (10.100.200.102:38412)
[2021-11-06 01:36:27.407] [sctp] [debug] SCTP association setup ascId[121]
[2021-11-06 01:36:27.408] [ngap] [debug] Sending NG Setup Request
[2021-11-06 01:36:27.415] [ngap] [debug] NG Setup Response received
[2021-11-06 01:36:27.415] [ngap] [info] NG Setup procedure is successful
[2021-11-06 01:36:27.656] [rrc] [debug] UE[1] new signal detected
[2021-11-06 01:36:27.910] [rrc] [debug] UE[2] new signal detected
[2021-11-06 01:36:27.912] [rrc] [info] RRC Setup for UE[2]
[2021-11-06 01:36:27.912] [ngap] [debug] Initial NAS message received from UE[2]
[2021-11-06 01:36:27.984] [ngap] [debug] Initial Context Setup Request received
[2021-11-06 01:36:28.222] [ngap] [info] PDU session resource(s) setup for UE[2] count[1]
[2021-11-06 01:36:30.157] [rrc] [info] RRC Setup for UE[1]
[2021-11-06 01:36:30.157] [ngap] [debug] Initial NAS message received from UE[1]
[2021-11-06 01:36:30.328] [ngap] [debug] Initial Context Setup Request received
[2021-11-06 01:36:30.649] [ngap] [info] PDU session resource(s) setup for UE[1] count[1]
[2021-11-06 01:43:45.674] [rrc] [warning] Discarding RRC Setup Request, UE context already exists

Best,
Ziran

@aligungr
Copy link
Owner

aligungr commented Nov 8, 2021

@minziran Radio link failure detected may be caused because of the under heavy internet traffic load of UE. But it's uncertain from the logs. And also, please make sure that both of the UEs have different 5G mobile identities. (imsi etc.)

@jiangxukun
Copy link

jiangxukun commented Nov 11, 2021

Thank you very much! When I run the Iperf3 on both UEs. It worked well at the very beginning, after that

In the UE side, the new error message is like: It says "Radio link failure detected" 2021-11-06 01:19:09.702] [rrc] [debug] Signal lost for cell[1], total [0] cells in coverage [2021-11-06 01:19:09.702] [rrc] [debug] New signal detected for cell[2], total [1] cells in coverage [2021-11-06 01:19:09.703] [nas] [error] Radio link failure detected [2021-11-06 01:19:09.703] [nas] [info] UE switches to state [CM-IDLE] [2021-11-06 01:19:09.703] [nas] [info] UE switches to state [MM-REGISTERED/PS] [2021-11-06 01:19:09.703] [nas] [info] UE switches to state [MM-REGISTERED/PLMN-SEARCH] [2021-11-06 01:19:09.704] [nas] [error] PLMN selection failure, no cells in coverage [2021-11-06 01:19:09.890] [rrc] [warning] Acceptable cell selection failed in [1] cells. [1] no SI, [0] reserved, [0] barred, ftai [0] [2021-11-06 01:19:09.890] [rrc] [error] Cell selection failure, no suitable or acceptable cell found [2021-11-06 01:19:12.507] [nas] [error] PLMN selection failure, no cells in coverage [2021-11-06 01:19:14.709] [nas] [info] UE switches to state [MM-REGISTERED/NO-CELL-AVAILABLE] [2021-11-06 01:19:19.342] [nas] [info] Selected plmn[208/93] [2021-11-06 01:19:19.342] [rrc] [info] Selected cell plmn[208/93] tac[1] category[SUITABLE] [2021-11-06 01:19:19.342] [nas] [info] UE switches to state [MM-REGISTERED/PS] [2021-11-06 01:19:19.343] [nas] [info] UE switches to state [MM-REGISTERED/NORMAL-SERVICE] [2021-11-06 01:19:23.426] [nas] [debug] Uplink data status changed PSI[1] pending[true] [2021-11-06 01:19:23.426] [nas] [debug] Service request required due to [IDLE-UPLINK-DATA-PENDING] [2021-11-06 01:19:23.426] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_data] [2021-11-06 01:19:23.426] [nas] [debug] Sending Service Request due to [IDLE-UPLINK-DATA-PENDING] [2021-11-06 01:19:23.426] [nas] [info] UE switches to state [MM-SERVICE-REQUEST-INITIATED] [2021-11-06 01:19:23.426] [rrc] [debug] Sending RRC Setup Request [2021-11-06 01:19:39.171] [nas] [debug] NAS timer[3517] expired [1] [2021-11-06 01:19:39.171] [nas] [info] UE switches to state [MM-REGISTERED/PS] [2021-11-06 01:19:39.171] [nas] [info] UE switches to state [MM-REGIST

The gNB side says: Discarding RRC Setup Request, UE context already exists

[2021-11-06 01:36:27.405] [sctp] [info] Trying to establish SCTP connection... (10.100.200.102:38412) [2021-11-06 01:36:27.407] [sctp] [info] SCTP connection established (10.100.200.102:38412) [2021-11-06 01:36:27.407] [sctp] [debug] SCTP association setup ascId[121] [2021-11-06 01:36:27.408] [ngap] [debug] Sending NG Setup Request [2021-11-06 01:36:27.415] [ngap] [debug] NG Setup Response received [2021-11-06 01:36:27.415] [ngap] [info] NG Setup procedure is successful [2021-11-06 01:36:27.656] [rrc] [debug] UE[1] new signal detected [2021-11-06 01:36:27.910] [rrc] [debug] UE[2] new signal detected [2021-11-06 01:36:27.912] [rrc] [info] RRC Setup for UE[2] [2021-11-06 01:36:27.912] [ngap] [debug] Initial NAS message received from UE[2] [2021-11-06 01:36:27.984] [ngap] [debug] Initial Context Setup Request received [2021-11-06 01:36:28.222] [ngap] [info] PDU session resource(s) setup for UE[2] count[1] [2021-11-06 01:36:30.157] [rrc] [info] RRC Setup for UE[1] [2021-11-06 01:36:30.157] [ngap] [debug] Initial NAS message received from UE[1] [2021-11-06 01:36:30.328] [ngap] [debug] Initial Context Setup Request received [2021-11-06 01:36:30.649] [ngap] [info] PDU session resource(s) setup for UE[1] count[1] [2021-11-06 01:43:45.674] [rrc] [warning] Discarding RRC Setup Request, UE context already exists

Best, Ziran

I have the same problem.When the UE goes offline, the gNB refuses to re-access the UE due to the presence of the UE context

@aligungr
Copy link
Owner

@jiangxukun This should be fixed with the latest versions of UERANSIM, but please clarify more the issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants