Open RomainBeurdouche opened 2 years ago
Here is the SPGWU log in case you can learn something from it:
[2022-04-13T14:05:34.364141] [spgwu] [itti ] [start] Starting...
[2022-04-13T14:05:34.364214] [spgwu] [itti ] [start] Started
[2022-04-13T14:05:34.364227] [spgwu] [async_c ] [start] Starting...
[2022-04-13T14:05:34.364322] [spgwu] [itti ] [info ] Starting timer_manager_task
[2022-04-13T14:05:34.365342] [spgwu] [async_c ] [start] Started
[2022-04-13T14:05:34.365364] [spgwu] [spgwu_app] [start] Starting...
[2022-04-13T14:05:34.366486] [spgwu] [udp ] [debug] Creating new listen socket on address 127.5.4.131 and port 8805
[2022-04-13T14:05:34.366511] [spgwu] [udp ] [debug] udp_server::udp_server(127.5.4.131:8805)
[2022-04-13T14:05:34.366524] [spgwu] [udp ] [debug] Creating new listen socket on address 127.5.4.131 and port 0
[2022-04-13T14:05:34.366534] [spgwu] [udp ] [debug] udp_server::udp_server(127.5.4.131:0)
[2022-04-13T14:05:34.366555] [spgwu] [pfcp ] [info ] pfcp_l4_stack created listening to 127.5.4.131:8805
[2022-04-13T14:05:34.366565] [spgwu] [udp ] [trace] udp_server::start_receive
[2022-04-13T14:05:34.366689] [spgwu] [udp ] [trace] udp_server::start_receive
[2022-04-13T14:05:34.366795] [spgwu] [spgwu_sx ] [start] Starting...
[2022-04-13T14:05:34.367975] [spgwu] [pfcp ] [trace] Sending PFCP_ASSOCIATION_SETUP_REQUEST, seq 14243678
[2022-04-13T14:05:34.368089] [spgwu] [pfcp ] [trace] Sending PFCP_ASSOCIATION_SETUP_REQUEST, seq 14243679
[2022-04-13T14:05:34.368140] [spgwu] [spgwu_sx ] [start] Started
[2022-04-13T14:05:34.368168] [spgwu] [udp ] [debug] Creating new listen socket on address 127.4.21.2 and port 2152
[2022-04-13T14:05:34.368180] [spgwu] [udp ] [debug] udp_server::udp_server(127.4.21.2:2152)
[2022-04-13T14:05:34.368196] [spgwu] [gtpv1_u ] [info ] gtpu_l4_stack created listening to 127.4.21.2:2152
[2022-04-13T14:05:34.368208] [spgwu] [udp ] [trace] udp_server::start_receive
[2022-04-13T14:05:34.368313] [spgwu] [spgwu_s1u] [start] Starting...
[2022-04-13T14:05:34.368451] [spgwu] [spgwu_sx ] [info ] handle_receive(35 bytes)
[2022-04-13T14:05:34.368511] [spgwu] [spgwu_sx ] [info ] Received SX ASSOCIATION SETUP RESPONSE
[2022-04-13T14:05:34.369471] [spgwu] [spgwu_s1u] [start] Started
[2022-04-13T14:05:34.371991] [spgwu] [spgwu_app] [start] Started
[2022-04-13T14:05:35.368099] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 1
[2022-04-13T14:05:39.368097] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 2
[2022-04-13T14:05:39.368182] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 4
[2022-04-13T14:05:39.368709] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 5
[2022-04-13T14:05:39.368735] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:05:39.368785] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243680
[2022-04-13T14:05:39.369131] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:05:39.369160] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:05:44.368790] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:05:44.368892] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT REQUEST
[2022-04-13T14:05:44.368926] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_RESPONSE, seq 11129268
[2022-04-13T14:05:44.369005] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 8
[2022-04-13T14:05:44.369243] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 9
[2022-04-13T14:05:44.369260] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:05:44.369306] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243681
[2022-04-13T14:05:44.369544] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:05:44.369575] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:05:49.369445] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 13
[2022-04-13T14:05:49.369650] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 14
[2022-04-13T14:05:49.369663] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:05:49.369707] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243682
[2022-04-13T14:05:49.370005] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:05:49.370036] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:05:54.369504] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:05:54.369567] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT REQUEST
[2022-04-13T14:05:54.369590] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_RESPONSE, seq 11129269
[2022-04-13T14:05:54.369809] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 17
[2022-04-13T14:05:54.370107] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 18
[2022-04-13T14:05:54.370117] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:05:54.370146] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243683
[2022-04-13T14:05:54.370367] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:05:54.370393] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:05:59.370271] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 22
[2022-04-13T14:05:59.370465] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 23
[2022-04-13T14:05:59.370477] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:05:59.370521] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243684
[2022-04-13T14:05:59.370838] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:05:59.370868] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:06:04.370049] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:06:04.370118] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT REQUEST
[2022-04-13T14:06:04.370149] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_RESPONSE, seq 11129270
[2022-04-13T14:06:04.370626] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 26
[2022-04-13T14:06:04.370947] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 27
[2022-04-13T14:06:04.370963] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:06:04.370999] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243685
[2022-04-13T14:06:04.371222] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:06:04.371250] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:06:09.371123] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 31
[2022-04-13T14:06:09.371337] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 32
[2022-04-13T14:06:09.371358] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:06:09.371421] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243686
[2022-04-13T14:06:09.371708] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:06:09.371741] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:06:14.370664] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:06:14.370732] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT REQUEST
[2022-04-13T14:06:14.370758] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_RESPONSE, seq 11129271
[2022-04-13T14:06:14.371540] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 35
[2022-04-13T14:06:14.371820] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 36
[2022-04-13T14:06:14.371834] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:06:14.371874] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243687
[2022-04-13T14:06:14.372111] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:06:14.372140] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:06:19.371997] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 40
[2022-04-13T14:06:19.372214] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 41
[2022-04-13T14:06:19.372225] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:06:19.372269] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243688
[2022-04-13T14:06:19.372582] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:06:19.372610] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:06:24.371270] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:06:24.371334] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT REQUEST
[2022-04-13T14:06:24.371357] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_RESPONSE, seq 11129272
[2022-04-13T14:06:24.372378] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 44
[2022-04-13T14:06:24.372687] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 45
[2022-04-13T14:06:24.372703] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:06:24.372734] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243689
[2022-04-13T14:06:24.372975] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:06:24.373002] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:06:29.372836] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 49
[2022-04-13T14:06:29.373074] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 50
[2022-04-13T14:06:29.373086] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:06:29.373128] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243690
[2022-04-13T14:06:29.373421] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:06:29.373450] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:06:34.371838] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:06:34.371904] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT REQUEST
[2022-04-13T14:06:34.371931] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_RESPONSE, seq 11129273
[2022-04-13T14:06:34.373231] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 53
[2022-04-13T14:06:34.373531] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 54
[2022-04-13T14:06:34.373550] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:06:34.373583] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243691
[2022-04-13T14:06:34.373793] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:06:34.373816] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:06:39.373694] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 58
[2022-04-13T14:06:39.373886] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 59
[2022-04-13T14:06:39.373897] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:06:39.373938] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243692
[2022-04-13T14:06:39.374234] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:06:39.374261] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:06:44.372547] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:06:44.372621] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT REQUEST
[2022-04-13T14:06:44.372653] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_RESPONSE, seq 11129274
[2022-04-13T14:06:44.374042] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 62
[2022-04-13T14:06:44.374349] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 63
[2022-04-13T14:06:44.374370] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:06:44.374407] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243693
[2022-04-13T14:06:44.374621] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:06:44.374649] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:06:49.374520] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 67
[2022-04-13T14:06:49.374728] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 68
[2022-04-13T14:06:49.374745] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:06:49.374795] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243694
[2022-04-13T14:06:49.375100] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:06:49.375133] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:06:54.257958] [spgwu] [spgwu_sx ] [info ] handle_receive(127 bytes)
[2022-04-13T14:06:54.258138] [spgwu] [spgwu_app] [info ] Received SXAB_SESSION_ESTABLISHMENT_REQUEST seid 0x0
[2022-04-13T14:06:54.258185] [spgwu] [spgwu_sx ] [info ] pfcp_session::add(far) seid 0x1
[2022-04-13T14:06:54.258226] [spgwu] [spgwu_sx ] [info ] pfcp_session::add(pdr) seid 0x1
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| PFCP switch Packet Detection Rule list ordered by established sessions: |
+----------------+----+--------+--------+------------+---------------------------------------+----------------------+----------------+-------------------------------------------------------------+
| SEID |pdr | far |predence| action | create outer hdr tun id| rmv outer hdr tun id| UE IPv4 | |
+----------------+----+--------+--------+------------+---------------------------------------+----------------------+----------------+-------------------------------------------------------------+
|0000000000000001|0001|00000001|00000000|ACC>---->COR|none |GTPU_UDP_IPV4:00000001|12.1.1.2 |
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
[2022-04-13T14:06:54.258400] [spgwu] [pfcp ] [trace] Sending PFCP_SESSION_ESTABLISHMENT_RESPONSE, seq 11129275 seid 0x13
[2022-04-13T14:06:54.352326] [spgwu] [spgwu_sx ] [info ] handle_receive(100 bytes)
[2022-04-13T14:06:54.352523] [spgwu] [spgwu_app] [info ] Received SXAB_SESSION_MODIFICATION_REQUEST seid 0x1
[2022-04-13T14:06:54.352554] [spgwu] [spgwu_sx ] [info ] pfcp_session::add(far) seid 0x1
[2022-04-13T14:06:54.352587] [spgwu] [spgwu_sx ] [info ] pfcp_session::add(pdr) seid 0x1
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| PFCP switch Packet Detection Rule list ordered by established sessions: |
+----------------+----+--------+--------+------------+---------------------------------------+----------------------+----------------+-------------------------------------------------------------+
| SEID |pdr | far |predence| action | create outer hdr tun id| rmv outer hdr tun id| UE IPv4 | |
+----------------+----+--------+--------+------------+---------------------------------------+----------------------+----------------+-------------------------------------------------------------+
|0000000000000001|0001|00000001|00000000|ACC>---->COR|none |GTPU_UDP_IPV4:00000001|12.1.1.2 |
|0000000000000001|0002|00000002|00000000|COR>---->ACC|GTPU_UDP_IPV4:127.5.3.130 :7ca324a8|none |12.1.1.2 |
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
[2022-04-13T14:06:54.352698] [spgwu] [pfcp ] [trace] Sending PFCP_SESSION_MODIFICATION_RESPONSE, seq 11129276 seid 0x13
[2022-04-13T14:06:54.373231] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:06:54.373305] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT REQUEST
[2022-04-13T14:06:54.373335] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_RESPONSE, seq 11129277
[2022-04-13T14:06:54.374902] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 71
[2022-04-13T14:06:54.375211] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 72
[2022-04-13T14:06:54.375227] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:06:54.375259] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243695
[2022-04-13T14:06:54.375479] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:06:54.375504] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:06:59.153535] [spgwu] [spgwu_sx ] [info ] handle_receive(50 bytes)
[2022-04-13T14:06:59.153691] [spgwu] [spgwu_app] [info ] Received SXAB_SESSION_MODIFICATION_REQUEST seid 0x1
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| PFCP switch Packet Detection Rule list ordered by established sessions: |
+----------------+----+--------+--------+------------+---------------------------------------+----------------------+----------------+-------------------------------------------------------------+
| SEID |pdr | far |predence| action | create outer hdr tun id| rmv outer hdr tun id| UE IPv4 | |
+----------------+----+--------+--------+------------+---------------------------------------+----------------------+----------------+-------------------------------------------------------------+
|0000000000000001|0001|00000001|00000000|ACC>---X> ? |none |GTPU_UDP_IPV4:00000001|12.1.1.2 |
|0000000000000001|0002|00000002|00000000|COR>-N--> ? |GTPU_UDP_IPV4:127.5.3.130 :7ca324a8|none |12.1.1.2 |
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
[2022-04-13T14:06:59.153824] [spgwu] [pfcp ] [trace] Sending PFCP_SESSION_MODIFICATION_RESPONSE, seq 11129278 seid 0x13
[2022-04-13T14:06:59.375374] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 78
[2022-04-13T14:06:59.375576] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 79
[2022-04-13T14:06:59.375587] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:06:59.375631] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243696
[2022-04-13T14:06:59.375940] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:06:59.375977] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:07:04.373970] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:07:04.374039] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT REQUEST
[2022-04-13T14:07:04.374063] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_RESPONSE, seq 11129279
[2022-04-13T14:07:04.375734] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 83
[2022-04-13T14:07:04.376059] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 84
[2022-04-13T14:07:04.376075] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:07:04.376106] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243697
[2022-04-13T14:07:04.376312] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:07:04.376341] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:07:09.376218] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 88
[2022-04-13T14:07:09.376417] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 89
[2022-04-13T14:07:09.376429] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:07:09.376477] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243698
[2022-04-13T14:07:09.376780] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:07:09.376817] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:07:14.374665] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:07:14.374740] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT REQUEST
[2022-04-13T14:07:14.374765] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_RESPONSE, seq 11129280
[2022-04-13T14:07:14.376591] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 92
[2022-04-13T14:07:14.376897] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 93
[2022-04-13T14:07:14.376913] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:07:14.376946] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243699
[2022-04-13T14:07:14.377167] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:07:14.377200] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:07:19.377067] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 97
[2022-04-13T14:07:19.377284] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 98
[2022-04-13T14:07:19.377302] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:07:19.377350] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243700
[2022-04-13T14:07:19.377642] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:07:19.377675] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:07:24.375380] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:07:24.375451] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT REQUEST
[2022-04-13T14:07:24.375479] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_RESPONSE, seq 11129281
[2022-04-13T14:07:24.377463] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 101
[2022-04-13T14:07:24.377757] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 102
[2022-04-13T14:07:24.377774] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:07:24.377813] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243701
[2022-04-13T14:07:24.378022] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:07:24.378048] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:07:29.377935] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 106
[2022-04-13T14:07:29.378125] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 107
[2022-04-13T14:07:29.378138] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:07:29.378185] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243702
[2022-04-13T14:07:29.378510] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:07:29.378541] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:07:34.376069] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:07:34.376137] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT REQUEST
[2022-04-13T14:07:34.376163] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_RESPONSE, seq 11129282
[2022-04-13T14:07:34.378296] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 110
[2022-04-13T14:07:34.378622] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 111
[2022-04-13T14:07:34.378637] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:07:34.378672] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243703
[2022-04-13T14:07:34.378899] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:07:34.378932] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:07:39.378793] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 115
[2022-04-13T14:07:39.379021] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 116
[2022-04-13T14:07:39.379043] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:07:39.379093] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243704
[2022-04-13T14:07:39.379361] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:07:39.379392] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:07:44.376724] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:07:44.376791] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT REQUEST
[2022-04-13T14:07:44.376825] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_RESPONSE, seq 11129283
[2022-04-13T14:07:44.379207] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 119
[2022-04-13T14:07:44.379469] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 120
[2022-04-13T14:07:44.379484] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:07:44.379519] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243705
[2022-04-13T14:07:44.379737] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:07:44.379766] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:07:49.379639] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 124
[2022-04-13T14:07:49.379848] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 125
[2022-04-13T14:07:49.379867] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:07:49.379915] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243706
[2022-04-13T14:07:49.380188] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:07:49.380219] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:07:54.377408] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:07:54.377479] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT REQUEST
[2022-04-13T14:07:54.377508] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_RESPONSE, seq 11129284
[2022-04-13T14:07:54.380025] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 128
[2022-04-13T14:07:54.380298] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 129
[2022-04-13T14:07:54.380313] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:07:54.380353] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243707
[2022-04-13T14:07:54.380562] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:07:54.380588] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
[2022-04-13T14:07:55.732595] [spgwu] [spgwu_sx ] [info ] handle_receive(127 bytes)
[2022-04-13T14:07:55.732801] [spgwu] [spgwu_app] [info ] Received SXAB_SESSION_ESTABLISHMENT_REQUEST seid 0x0
[2022-04-13T14:07:55.732841] [spgwu] [spgwu_sx ] [info ] pfcp_session::add(far) seid 0x2
[2022-04-13T14:07:55.732878] [spgwu] [spgwu_sx ] [info ] pfcp_session::add(pdr) seid 0x2
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| PFCP switch Packet Detection Rule list ordered by established sessions: |
+----------------+----+--------+--------+------------+---------------------------------------+----------------------+----------------+-------------------------------------------------------------+
| SEID |pdr | far |predence| action | create outer hdr tun id| rmv outer hdr tun id| UE IPv4 | |
+----------------+----+--------+--------+------------+---------------------------------------+----------------------+----------------+-------------------------------------------------------------+
|0000000000000001|0001|00000001|00000000|ACC>---X> ? |none |GTPU_UDP_IPV4:00000001|12.1.1.2 |
|0000000000000001|0002|00000002|00000000|COR>-N--> ? |GTPU_UDP_IPV4:127.5.3.130 :7ca324a8|none |12.1.1.2 |
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|0000000000000002|0001|00000001|00000000|ACC>---->COR|none |GTPU_UDP_IPV4:00000002|12.1.1.2 |
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
[2022-04-13T14:07:55.733056] [spgwu] [pfcp ] [trace] Sending PFCP_SESSION_ESTABLISHMENT_RESPONSE, seq 11129285 seid 0x16
[2022-04-13T14:07:55.827313] [spgwu] [spgwu_sx ] [info ] handle_receive(100 bytes)
[2022-04-13T14:07:55.827512] [spgwu] [spgwu_app] [info ] Received SXAB_SESSION_MODIFICATION_REQUEST seid 0x2
[2022-04-13T14:07:55.827542] [spgwu] [spgwu_sx ] [info ] pfcp_session::add(far) seid 0x2
[2022-04-13T14:07:55.827569] [spgwu] [spgwu_sx ] [info ] pfcp_session::add(pdr) seid 0x2
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| PFCP switch Packet Detection Rule list ordered by established sessions: |
+----------------+----+--------+--------+------------+---------------------------------------+----------------------+----------------+-------------------------------------------------------------+
| SEID |pdr | far |predence| action | create outer hdr tun id| rmv outer hdr tun id| UE IPv4 | |
+----------------+----+--------+--------+------------+---------------------------------------+----------------------+----------------+-------------------------------------------------------------+
|0000000000000001|0001|00000001|00000000|ACC>---X> ? |none |GTPU_UDP_IPV4:00000001|12.1.1.2 |
|0000000000000001|0002|00000002|00000000|COR>-N--> ? |GTPU_UDP_IPV4:127.5.3.130 :7ca324a8|none |12.1.1.2 |
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|0000000000000002|0001|00000001|00000000|ACC>---->COR|none |GTPU_UDP_IPV4:00000002|12.1.1.2 |
|0000000000000002|0002|00000002|00000000|COR>---->ACC|GTPU_UDP_IPV4:127.5.3.130 :e46d849d|none |12.1.1.2 |
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
[2022-04-13T14:07:55.827726] [spgwu] [pfcp ] [trace] Sending PFCP_SESSION_MODIFICATION_RESPONSE, seq 11129286 seid 0x16
[2022-04-13T14:07:57.629101] [spgwu] [spgwu_sx ] [info ] handle_receive(50 bytes)
[2022-04-13T14:07:57.629281] [spgwu] [spgwu_app] [info ] Received SXAB_SESSION_MODIFICATION_REQUEST seid 0x2
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| PFCP switch Packet Detection Rule list ordered by established sessions: |
+----------------+----+--------+--------+------------+---------------------------------------+----------------------+----------------+-------------------------------------------------------------+
| SEID |pdr | far |predence| action | create outer hdr tun id| rmv outer hdr tun id| UE IPv4 | |
+----------------+----+--------+--------+------------+---------------------------------------+----------------------+----------------+-------------------------------------------------------------+
|0000000000000001|0001|00000001|00000000|ACC>---X> ? |none |GTPU_UDP_IPV4:00000001|12.1.1.2 |
|0000000000000001|0002|00000002|00000000|COR>-N--> ? |GTPU_UDP_IPV4:127.5.3.130 :7ca324a8|none |12.1.1.2 |
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|0000000000000002|0001|00000001|00000000|ACC>---X> ? |none |GTPU_UDP_IPV4:00000002|12.1.1.2 |
|0000000000000002|0002|00000002|00000000|COR>-N--> ? |GTPU_UDP_IPV4:127.5.3.130 :e46d849d|none |12.1.1.2 |
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
[2022-04-13T14:07:57.629462] [spgwu] [pfcp ] [trace] Sending PFCP_SESSION_MODIFICATION_RESPONSE, seq 11129287 seid 0x16
[2022-04-13T14:07:59.380477] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 133
[2022-04-13T14:07:59.380669] [spgwu] [spgwu_sx ] [info ] TIME-OUT event timer id 134
[2022-04-13T14:07:59.380688] [spgwu] [spgwu_sx ] [info ] PFCP HEARTBEAT PROCEDURE hash 33817983 starting
[2022-04-13T14:07:59.380740] [spgwu] [pfcp ] [trace] Sending HEARTBEAT_REQUEST, seq 14243708
[2022-04-13T14:07:59.381052] [spgwu] [spgwu_sx ] [info ] handle_receive(16 bytes)
[2022-04-13T14:07:59.381083] [spgwu] [spgwu_sx ] [info ] Received SX HEARTBEAT RESPONSE
^CCaught signal 2
[2022-04-13T14:08:03.946884] [spgwu] [system ] [start] exiting
[2022-04-13T14:08:03.946932] [spgwu] [itti ] [info ] Waiting ITTI tasks closed
[2022-04-13T14:08:03.946941] [spgwu] [async_c ] [info ] Received terminate message
[2022-04-13T14:08:03.947030] [spgwu] [spgwu_app] [info ] Received terminate message
[2022-04-13T14:08:03.947071] [spgwu] [spgwu_sx ] [info ] Received terminate message
[2022-04-13T14:08:03.947103] [spgwu] [spgwu_s1u] [info ] Received terminate message
/snap/oai-spgwu/x1/run: line 25: 10005 Terminated $SPGWU_EXEC -c "$SPGWU_CONFIG" -o "$@"
context/reproducible experiment
The issue was encountered when connecting twice a UE to the OAI network without restarting any function neither core network functions, neither the gNB. All the core network and RAN were running on the same machine.
When running the UE for the first time, the user traffic was flowing normally as shows this capture of a icmp ping request and response in the core network:
Then after stopping and restarting the UE making sure that it disconnects from the network properly and connects again with the same ip address, the user data does not flow anymore in the downlink direction:
Capture of ping from the core network to the UE were also performed and confirmed that the problem was about the downlink traffic.
Important points noticed
Idea on the issue
From what we observed, we believe that this is probably happening because some structure or object that describe the PDU Session created at first UE connection is partially but not entirely cleaned at UE disconnection so that at second connection the SPGWU does believes it already has some PDU Session ready for this UE and does not setup again properly the downlink channel for the UE. If such structure are indexed by ip addresses, it would explain why changing the ip address solves the issue for one more connection.
Details on our setup
We have bee using the core network, RAN and UE as Snap packages developed in the Mosaic5G project. The core network and RAN were running on only one machine. Only one UE was used and connected to the network. The UE was modified in a way that makes sure it disconnects properly from the network so that it get the same ip address at each connection since this address was properly released.
For more info
This issue was reported by Romain Beurdouche. You can contact me by mail at romain.beurdouche@eurecom.fr for more information on the issue.