search

edgecomllc / eupf

5G User Plane Function (UPF) based on eBPF
Apache License 2.0
107 stars 20 forks source link

Multiple UEs data stopping suddenly #494

Closed Sabreu closed 11 months ago

Sabreu commented 12 months ago

Hello again,

I spotted issue with two UEs: I have two UEs attached, first UE IP 10.25.0.219, second UE IP 10.25.0.220. Second UE makes detach and attach while 1st. UE is running Iperf3 -> Data halts on UE1. One thing that seems a bit odd to me from logs is that the Second UE Session remove seems to delete wrong FAR and QER internalIDs which in fact belong to UE1. Then the next Session request is reusing these internalIDs again.

Am I looking correctly this or what could be the cause for this kind of data freeze?

12:58:41 epc14900k eupf[28945]: Session Establishment Request:
12:58:41 epc14900k eupf[28945]:   CreatePDR ID: 1
12:58:41 epc14900k eupf[28945]:     FAR ID: 1
12:58:41 epc14900k eupf[28945]:     QER ID: 1
12:58:41 epc14900k eupf[28945]:     URR ID: 1
12:58:41 epc14900k eupf[28945]:     Source Interface: 1
12:58:41 epc14900k eupf[28945]:     UE IPv4 Address: 10.25.0.220
12:58:41 epc14900k eupf[28945]:   CreatePDR ID: 2
12:58:41 epc14900k eupf[28945]:     Outer Header Removal: 0
12:58:41 epc14900k eupf[28945]:     FAR ID: 2
12:58:41 epc14900k eupf[28945]:     QER ID: 1
12:58:41 epc14900k eupf[28945]:     Source Interface: 0
12:58:41 epc14900k eupf[28945]:     TEID: 141321
12:58:41 epc14900k eupf[28945]:     Ipv4: 10.10.4.1
12:58:41 epc14900k eupf[28945]:     Ipv6: <nil>
12:58:41 epc14900k eupf[28945]:     UE IPv4 Address: 10.25.0.220
12:58:41 epc14900k eupf[28945]:   CreatePDR ID: 3
12:58:41 epc14900k eupf[28945]:     Outer Header Removal: 0
12:58:41 epc14900k eupf[28945]:     FAR ID: 1
12:58:41 epc14900k eupf[28945]:     QER ID: 1
12:58:41 epc14900k eupf[28945]:     Source Interface: 3
12:58:41 epc14900k eupf[28945]:     TEID: 211376
12:58:41 epc14900k eupf[28945]:     Ipv4: 10.10.4.1
12:58:41 epc14900k eupf[28945]:     Ipv6: <nil>
12:58:41 epc14900k eupf[28945]:   CreatePDR ID: 4
12:58:41 epc14900k eupf[28945]:     Outer Header Removal: 0
12:58:41 epc14900k eupf[28945]:     FAR ID: 3
12:58:41 epc14900k eupf[28945]:     Source Interface: 0
12:58:41 epc14900k eupf[28945]:     TEID: 141321
12:58:41 epc14900k eupf[28945]:     Ipv4: 10.10.4.1
12:58:41 epc14900k eupf[28945]:     Ipv6: <nil>
12:58:41 epc14900k eupf[28945]:     SDF Filter: permit out 58 from ff02::2/128 to assigned
12:58:41 epc14900k eupf[28945]:   CreateFAR ID: 1
12:58:41 epc14900k eupf[28945]:     Apply Action: [12 0]
12:58:41 epc14900k eupf[28945]:     BAR ID: 1
12:58:41 epc14900k eupf[28945]:   CreateFAR ID: 2
12:58:41 epc14900k eupf[28945]:     Apply Action: [2 0]
12:58:41 epc14900k eupf[28945]:     Forwarding Parameters:
12:58:41 epc14900k eupf[28945]: [32B blob data]
12:58:41 epc14900k eupf[28945]:   CreateFAR ID: 3
12:58:41 epc14900k eupf[28945]:     Apply Action: [2 0]
12:58:41 epc14900k eupf[28945]:     Forwarding Parameters:
12:58:41 epc14900k eupf[28945]: [32B blob data]
12:58:41 epc14900k eupf[28945]:       Outer Header Creation: &{OuterHeaderCreationDescription:256 TEID:219 IPv4Address:10.10.1.3 IPv6Address:<nil> PortNumber:0 CTag:0 STag:0}
12:58:41 epc14900k eupf[28945]:   CreateQER ID: 1
12:58:41 epc14900k eupf[28945]:     Gate Status DL: 0
12:58:41 epc14900k eupf[28945]:     Gate Status UL: 0
12:58:41 epc14900k eupf[28945]:     Max Bitrate DL: 10000000
12:58:41 epc14900k eupf[28945]:     Max Bitrate UL: 10000000
12:58:41 epc14900k eupf[28945]:     QFI: 1
12:58:41 epc14900k eupf[28945]:   CreateURR ID: 1
12:58:41 epc14900k eupf[28945]:     Measurement Method: 2
12:58:41 epc14900k eupf[28945]:     Volume Threshold: &{Flags:1 TotalVolume:104857600 UplinkVolume:0 DownlinkVolume:0}
12:58:41 epc14900k eupf[28945]:   CreateBAR ID: 1
12:58:41 epc14900k eupf[28945]: 2023/11/24 12:58:41 INF Saving FAR info to session: 1, {Action:12 OuterHeaderCreation:0 Teid:0 RemoteIP:0 LocalIP:33819146 TransportLevelMarking:0}
12:58:41 epc14900k eupf[28945]: 2023/11/24 12:58:41 TRC EBPF: Put FAR: internalId=15, qerInfo={Action:12 OuterHeaderCreation:0 Teid:0 RemoteIP:0 LocalIP:33819146 TransportLevelMarking:0}
12:58:41 epc14900k eupf[28945]: 2023/11/24 12:58:41 INF WARN: No OuterHeaderCreation
12:58:41 epc14900k eupf[28945]: 2023/11/24 12:58:41 INF Saving FAR info to session: 2, {Action:2 OuterHeaderCreation:0 Teid:0 RemoteIP:0 LocalIP:33819146 TransportLevelMarking:0}
12:58:41 epc14900k eupf[28945]: 2023/11/24 12:58:41 TRC EBPF: Put FAR: internalId=16, qerInfo={Action:2 OuterHeaderCreation:0 Teid:0 RemoteIP:0 LocalIP:33819146 TransportLevelMarking:0}
12:58:41 epc14900k eupf[28945]: 2023/11/24 12:58:41 INF Saving FAR info to session: 3, {Action:2 OuterHeaderCreation:1 Teid:219 RemoteIP:50399754 LocalIP:33819146 TransportLevelMarking:0}
12:58:41 epc14900k eupf[28945]: 2023/11/24 12:58:41 TRC EBPF: Put FAR: internalId=17, qerInfo={Action:2 OuterHeaderCreation:1 Teid:219 RemoteIP:50399754 LocalIP:33819146 TransportLevelMarking:0}
12:58:41 epc14900k eupf[28945]: 2023/11/24 12:58:41 INF Saving QER info to session: 1, {GateStatusUL:0 GateStatusDL:0 Qfi:1 MaxBitrateUL:1410065408 MaxBitrateDL:1410065408 StartUL:0 StartDL:0}
12:58:41 epc14900k eupf[28945]: 2023/11/24 12:58:41 TRC EBPF: Put QER: internalId=5, qerInfo={GateStatusUL:0 GateStatusDL:0 Qfi:1 MaxBitrateUL:1410065408 MaxBitrateDL:1410065408 StartUL:0 StartDL:0}
12:58:41 epc14900k eupf[28945]: 2023/11/24 12:58:41 TRC EBPF: Put PDR Downlink: ipv4=10.25.0.220, pdrInfo={OuterHeaderRemoval:0 FarId:15 QerId:5 SdfFilter:<nil>}
12:58:41 epc14900k eupf[28945]: 2023/11/24 12:58:41 TRC EBPF: Put PDR Uplink: teid=141321, pdrInfo={OuterHeaderRemoval:0 FarId:16 QerId:5 SdfFilter:<nil>}
12:58:41 epc14900k eupf[28945]: 2023/11/24 12:58:41 TRC EBPF: Put PDR Uplink: teid=211376, pdrInfo={OuterHeaderRemoval:0 FarId:15 QerId:5 SdfFilter:<nil>}
12:58:41 epc14900k eupf[28945]: 2023/11/24 12:58:41 DBG Error extracting PDR info: SDF Filter: bad formatting. Should be compatible with regexp: ^permit out (icmp|ip|tcp|udp) from (any|[\d.]+|[\da-fA-F:]+)(?:/(\d+))?(?: (\d+|\d+-\d+))? to ([\d.]+|[\da-fA-F:]+)(?:/(\d+))?(?: (\d+|\d+-\d+))?$
12:58:41 epc14900k eupf[28945]: 2023/11/24 12:58:41 INF Session Establishment Request from 10.10.1.3 accepted.
12:58:42 epc14900k eupf[28945]: 2023/11/24 12:58:42 INF Received 69 bytes from 10.10.1.3:8805
12:58:42 epc14900k eupf[28945]: 2023/11/24 12:58:42 INF Handling PFCP message from 10.10.1.3:8805
12:58:42 epc14900k eupf[28945]: 2023/11/24 12:58:42 INF Got Session Modification Request from: 10.10.1.3.
12:58:42 epc14900k eupf[28945]: 2023/11/24 12:58:42 INF Finding association for 10.10.1.3
12:58:42 epc14900k eupf[28945]: 2023/11/24 12:58:42 INF Finding session 8
12:58:42 epc14900k eupf[28945]: 2023/11/24 12:58:42 INF
12:58:42 epc14900k eupf[28945]: Session Modification Request:
12:58:42 epc14900k eupf[28945]:   UpdateFAR ID: 1
12:58:42 epc14900k eupf[28945]:     Apply Action: [2 0]
12:58:42 epc14900k eupf[28945]:     Update forwarding Parameters:
12:58:42 epc14900k eupf[28945]: [32B blob data]
12:58:42 epc14900k eupf[28945]:       Outer Header Creation: &{OuterHeaderCreationDescription:256 TEID:3221225763 IPv4Address:10.10.10.41 IPv6Address:<nil> PortNumber:0 CTag:0 STag:0}
12:58:42 epc14900k eupf[28945]: 2023/11/24 12:58:42 INF Updating FAR info: 1, {FarInfo:{Action:2 OuterHeaderCreation:1 Teid:3221225763 RemoteIP:688523786 LocalIP:33819146 TransportLevelMarking:0} GlobalId:15}
12:58:42 epc14900k eupf[28945]: 2023/11/24 12:58:42 TRC EBPF: Update FAR: internalId=15, farInfo={Action:2 OuterHeaderCreation:1 Teid:3221225763 RemoteIP:688523786 LocalIP:33819146 TransportLevelM

13:03:32 epc14900k eupf[28945]: 2023/11/24 13:03:32 INF Got Session Deletion Request from: 10.10.1.3.
13:03:32 epc14900k eupf[28945]: 2023/11/24 13:03:32 TRC EBPF: Delete PDR Downlink: ipv4=10.25.0.220
13:03:32 epc14900k eupf[28945]: 2023/11/24 13:03:32 TRC EBPF: Delete PDR Uplink: teid=141321
13:03:32 epc14900k eupf[28945]: 2023/11/24 13:03:32 TRC EBPF: Delete PDR Uplink: teid=211376
13:03:32 epc14900k eupf[28945]: 2023/11/24 13:03:32 TRC EBPF: Delete FAR(release): intenalId=1
13:03:32 epc14900k eupf[28945]: 2023/11/24 13:03:32 TRC EBPF: Delete FAR(release): intenalId=2
13:03:32 epc14900k eupf[28945]: 2023/11/24 13:03:32 TRC EBPF: Delete FAR(release): intenalId=3
13:03:32 epc14900k eupf[28945]: 2023/11/24 13:03:32 TRC EBPF: Delete QER: internalId=1
13:03:32 epc14900k eupf[28945]: 2023/11/24 13:03:32 INF Deleting session: 8
pirog-spb commented 12 months ago

Hi @Sabreu

Seems like a bug. I confirm. During deletion request prcessing FARs and QERs are released by wrong id.

pirog-spb commented 12 months ago

@Sabreu FYI I've added a fix in the linked branch

Sabreu commented 11 months ago

@pirog-spb

cannot build anymore (was warning before I think, I have installed all updates so maybe build tools are newer or something):

/home/14900k/git/eupf/cmd/ebpf/xdp/qer_program.c:39:16: error: call to undeclared function 'max'; ISO C99 and later do not support implicit function declarations [-Wimplicit-function-declaration] __u64 ts = max(now - BURST, t_next); ^ 1 error generated. Error: can't execute clang: exit status 1

Edit: Also getting this kind of error later: cmd/core/api.go:13:2: no required module provides package github.com/edgecomllc/eupf/cmd/docs; to add it: go get github.com/edgecomllc/eupf/cmd/docs

$ go get github.com/edgecomllc/eupf/docs go: github.com/edgecomllc/eupf/docs: no matching versions for query "upgrade"

Edit 2: I was able to build after copying from my own installation the docs folder...

thanks

pirog-spb commented 11 months ago

@Sabreu The old warning turned into an error. I've fixed and pushed it.

Considering the second error. Please verify that you have installed swag utility. See build manual or Dockerfile commands for details.

Sabreu commented 11 months ago

@pirog-spb

I have installed swag earlier, I just pulled the new codes to different folder and tried to generate /cmd and build after that.

EDIT: I tried to install swag also again and still seeing the same issues with cmd/docs

Sabreu commented 11 months ago

@pirog-spb

Correct FAR & QER deleted now and no data stopping. Thanks

2023/11/27 10:16:07 INF Saving FAR info to session: 1, {Action:12 OuterHeaderCreation:0 Teid:0 RemoteIP:0 LocalIP:33819146 TransportLevelMarking:0}
2023/11/27 10:16:07 DBG EBPF: Put FAR: internalId=9, qerInfo={Action:12 OuterHeaderCreation:0 Teid:0 RemoteIP:0 LocalIP:33819146 TransportLevelMarking:0}
2023/11/27 10:16:07 INF WARN: No OuterHeaderCreation
2023/11/27 10:16:07 INF Saving FAR info to session: 2, {Action:2 OuterHeaderCreation:0 Teid:0 RemoteIP:0 LocalIP:33819146 TransportLevelMarking:0}
2023/11/27 10:16:07 DBG EBPF: Put FAR: internalId=10, qerInfo={Action:2 OuterHeaderCreation:0 Teid:0 RemoteIP:0 LocalIP:33819146 TransportLevelMarking:0}
2023/11/27 10:16:07 INF Saving FAR info to session: 3, {Action:2 OuterHeaderCreation:1 Teid:4751 RemoteIP:50399754 LocalIP:33819146 TransportLevelMarking:0}
2023/11/27 10:16:07 DBG EBPF: Put FAR: internalId=11, qerInfo={Action:2 OuterHeaderCreation:1 Teid:4751 RemoteIP:50399754 LocalIP:33819146 TransportLevelMarking:0}
2023/11/27 10:16:07 INF Saving QER info to session: 1, {GateStatusUL:0 GateStatusDL:0 Qfi:1 MaxBitrateUL:1410065408 MaxBitrateDL:1410065408 StartUL:0 StartDL:0}
2023/11/27 10:16:07 DBG EBPF: Put QER: internalId=3, qerInfo={GateStatusUL:0 GateStatusDL:0 Qfi:1 MaxBitrateUL:1410065408 MaxBitrateDL:1410065408 StartUL:0 StartDL:0}
2023/11/27 10:16:07 DBG EBPF: Put PDR Downlink: ipv4=10.25.0.216, pdrInfo={OuterHeaderRemoval:0 FarId:9 QerId:3 SdfFilter:<nil>}
2023/11/27 10:16:07 DBG EBPF: Put PDR Uplink: teid=255776, pdrInfo={OuterHeaderRemoval:0 FarId:10 QerId:3 SdfFilter:<nil>}
2023/11/27 10:16:07 DBG EBPF: Put PDR Uplink: teid=164640, pdrInfo={OuterHeaderRemoval:0 FarId:9 QerId:3 SdfFilter:<nil>}
2023/11/27 10:16:07 DBG Error extracting PDR info: SDF Filter: bad formatting. Should be compatible with regexp: ^permit out (icmp|ip|tcp|udp) from (any|[\d.]+|[\da-fA-F:]+)(?:/(\d+))?(?: (\d+|\d+-\d+))? to ([\d.]+|[\da-fA-F:]+)(?:/(\d+))?(?: (\d+|\d+-\d+))?$
2023/11/27 10:16:07 INF Session Establishment Request from 10.10.1.3 accepted.
2023/11/27 10:16:07 DBG Received 69 bytes from 10.10.1.3:8805
2023/11/27 10:16:07 DBG Handling PFCP message from 10.10.1.3:8805
2023/11/27 10:16:07 INF Got Session Modification Request from: 10.10.1.3.

2023/11/27 10:16:07 INF Finding association for 10.10.1.3
2023/11/27 10:16:07 INF Finding session 5
2023/11/27 10:16:07 INF
Session Modification Request:
  UpdateFAR ID: 1
    Apply Action: [2 0]
    Update forwarding Parameters:
      Network Instance: 5gapn3
      Outer Header Creation: &{OuterHeaderCreationDescription:256 TEID:3221618979 IPv4Address:10.10.10.41 IPv6Address:<nil> PortNumber:0 CTag:0 STag:0}

2023/11/27 10:16:07 INF Updating FAR info: 1, {FarInfo:{Action:2 OuterHeaderCreation:1 Teid:3221618979 RemoteIP:688523786 LocalIP:33819146 TransportLevelMarking:0} GlobalId:9}
2023/11/27 10:16:07 DBG EBPF: Update FAR: internalId=9, farInfo={Action:2 OuterHeaderCreation:1 Teid:3221618979 RemoteIP:688523786 LocalIP:33819146 TransportLevelMarking:0}
2023/11/27 10:16:12 DBG Received 16 bytes from 10.10.1.3:8805
2023/11/27 10:16:12 DBG Handling PFCP message from 10.10.1.3:8805
2023/11/27 10:16:12 DBG Got Heartbeat Request with TS: 2023-11-24 13:15:18 +0200 EET, from: 10.10.1.3
2023/11/27 10:16:12 DBG Sent Heartbeat Response to: 10.10.1.3
[GIN] 2023/11/27 - 10:16:12 | 200 |    1.910357ms |       10.10.5.1 | GET      "/metrics"
2023/11/27 10:16:17 DBG Sent Heartbeat Request to: 10.10.1.3
2023/11/27 10:16:17 DBG Received 16 bytes from 10.10.1.3:8805
2023/11/27 10:16:17 DBG Handling PFCP message from 10.10.1.3:8805
2023/11/27 10:16:17 DBG Got Heartbeat Response with TS: 2023-11-24 13:15:18 +0200 EET, from: 10.10.1.3
[GIN] 2023/11/27 - 10:16:22 | 200 |    1.778472ms |       10.10.5.1 | GET      "/metrics"
2023/11/27 10:16:23 DBG Received 16 bytes from 10.10.1.3:8805
2023/11/27 10:16:23 DBG Handling PFCP message from 10.10.1.3:8805
2023/11/27 10:16:23 DBG Got Heartbeat Request with TS: 2023-11-24 13:15:18 +0200 EET, from: 10.10.1.3
2023/11/27 10:16:23 DBG Sent Heartbeat Response to: 10.10.1.3
2023/11/27 10:16:27 DBG Sent Heartbeat Request to: 10.10.1.3
2023/11/27 10:16:27 DBG Received 16 bytes from 10.10.1.3:8805
2023/11/27 10:16:27 DBG Handling PFCP message from 10.10.1.3:8805
2023/11/27 10:16:27 DBG Got Heartbeat Response with TS: 2023-11-24 13:15:18 +0200 EET, from: 10.10.1.3
2023/11/27 10:16:30 DBG Received 16 bytes from 10.10.1.3:8805
2023/11/27 10:16:30 DBG Handling PFCP message from 10.10.1.3:8805
2023/11/27 10:16:30 INF Got Session Deletion Request from: 10.10.1.3.

2023/11/27 10:16:30 DBG EBPF: Delete PDR Downlink: ipv4=10.25.0.216
2023/11/27 10:16:30 DBG EBPF: Delete PDR Uplink: teid=255776
2023/11/27 10:16:30 DBG EBPF: Delete PDR Uplink: teid=164640
2023/11/27 10:16:30 DBG EBPF: Delete FAR: intenalId=9
2023/11/27 10:16:30 DBG EBPF: Delete FAR: intenalId=10
2023/11/27 10:16:30 DBG EBPF: Delete FAR: intenalId=11
2023/11/27 10:16:30 DBG EBPF: Delete QER: internalId=3
2023/11/27 10:16:30 INF Deleting session: 5