search

travelping / upg-vpp

User Plane Gateway (UPG) based on VPP
Apache License 2.0
152 stars 50 forks source link

5G PFCP Error #101

Closed infinitydon closed 3 years ago

infinitydon commented 3 years ago

Hi,

Please I am trying to setup upg-vpp as UPF for open5gs SMF.

The error I get from the open5gs SMF is:

03/20 23:01:14.209: [smf] WARNING: cannot handle PFCP message type[1] (../src/smf/pfcp-sm.c:140)
03/20 23:01:14.729: [pfcp] DEBUG: [3] REMOTE Create  peer [10.0.0.149]:8805 (../lib/pfcp/xact.c:156)
03/20 23:01:14.729: [pfcp] DEBUG: [3] REMOTE Receive peer [10.0.0.149]:8805 (../lib/pfcp/xact.c:699)
03/20 23:01:14.729: [pfcp] DEBUG: [3] REMOTE UPD RX-1  peer [10.0.0.149]:8805 (../lib/pfcp/xact.c:294)
03/20 23:01:14.729: [smf] WARNING: cannot handle PFCP message type[1] (../src/smf/pfcp-sm.c:140)
03/20 23:01:15.207: [smf] WARNING: Retry to association with peer [10.0.0.149]:8805 failed (../src/smf/pfcp-sm.c:107)
03/20 23:01:15.207: [pfcp] DEBUG: Association Setup Request (../lib/pfcp/build.c:64)
03/20 23:01:15.207: [pfcp] DEBUG: [83] LOCAL  UPD TX-5  peer [10.0.0.149]:8805 (../lib/pfcp/xact.c:193)
03/20 23:01:15.207: [pfcp] DEBUG: [83] LOCAL  Create  peer [10.0.0.149]:8805 (../lib/pfcp/xact.c:113)
03/20 23:01:15.207: [pfcp] DEBUG: [83] LOCAL  Commit  peer [10.0.0.149]:8805 (../lib/pfcp/xact.c:473)
03/20 23:01:15.207: [core] ERROR: Unexpected TLV type:32770 (../lib/core/ogs-tlv-msg.c:454)
03/20 23:01:15.207: [smf] ERROR: ogs_pfcp_parse_msg() failed (../src/smf/smf-sm.c:228)

After a while upg-vpp crashes..

DBGvpp# /usr/src/upg-vpp/vpp/src/vlib/counter.h:101 (vlib_decrement_simple_counter) assertion `my_counters[index] >= decrement' fails
Aborted (core dumped)

Following are my config:

ip table add 1
ip table add 2
ip6 table add 1
ip6 table add 2

create host-interface name ens6
set interface mac address host-ens6 02:7e:e1:cc:04:a7
set interface mtu 1500 host-ens6
set interface ip table host-ens6 0
set interface ip address host-ens6 10.0.0.149/24
set interface state host-ens6 up

create host-interface name ens7
set interface mac address host-ens7 02:68:23:7e:1d:bf
set interface mtu 1500 host-ens7
set interface ip table host-ens7 1
set interface ip address host-ens7 10.0.6.133/24
set interface state host-ens7 up

create host-interface name ens8
set interface mac address host-ens8 02:bc:29:ee:b2:63
set interface mtu 1500 host-ens8
set interface ip table host-ens8 2
set interface ip address host-ens8 10.0.4.246/24
set interface state host-ens8 up

ip route add 0.0.0.0/0 table 0 via 10.0.0.1 host-ens6
ip route add 0.0.0.0/0 table 1 via 10.0.6.1 host-ens7
ip route add 0.0.0.0/0 table 2 via 10.0.4.1 host-ens8

upf pfcp endpoint ip 10.0.0.149 vrf 0

upf nwi name cp vrf 0
upf nwi name epc vrf 1
upf nwi name sgi vrf 2

upf gtpu endpoint ip 10.0.0.149 nwi cp teid 0x80000000/2
upf gtpu endpoint ip 10.0.6.133 nwi epc teid 0x80000000/2
unix {
  nodaemon
  log /tmp/vpp.log
  full-coredump
  gid vpp
  interactive
  cli-listen localhost:5002
  exec init.conf
}

api-trace {
  on
}

api-segment {
  gid vpp
}

plugins {
    path /usr/src/upg-vpp/vpp/build-root/install-vpp_debug-native/vpp/lib/vpp_plugins/
    plugin dpdk_plugin.so { disable }
    plugin gtpu_plugin.so { disable }
    plugin upf_plugin.so { enable }
}

Steps that I used in installing upg-vpp:

cd /usr/src
git clone https://github.com/travelping/upg-vpp
cd upg-vpp
make update-vpp
cd vpp
make install-deps
make install-ext-deps
make build

Also it will be great if someone can point me to where the documentation is, I was unable to locate this in this repo.

infinitydon commented 3 years ago

@gantonie - Please do you have an idea why this is failing, maybe you encountered this issue when you used open5gs also?

RoadRunnr commented 3 years ago

@infinitydon - about the SMF problem, we don't use open5gs ourselves and UPG is not part of the open5gs project, you have to go there to ask for that crash.

For the VPP abort, could you capture a PCAP of the PFCP interaction and a gdb backtrace of the VPP crash? @ivan4th could you look into this once we have enough information?

sergeymatov commented 3 years ago

It would be really helpful if we could have core dump generated by vpp

ivan4th commented 3 years ago

Or, even better:

gdb --args /path/to/vpp -c /path/to/startup.conf
r
# after crash:
bt full 30
gantonie commented 3 years ago

I only used the MME and HSS from Open5GS. I replaced the SGWC and the SMF by erGW and the SGWU and the UPF by UPG-VPP.

infinitydon commented 3 years ago

@ivan4th @sergeymatov

gdb output:

DBGvpp# /usr/src/upg-vpp/vpp/src/vlib/counter.h:101 (vlib_decrement_simple_counter) assertion `my_counters[index] >= decrement' fails

Program received signal SIGABRT, Aborted.
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
51      ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.

bt full 30 output:

#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
        set = {__val = {0, 140737309885698, 65568, 142, 142, 7897856, 1, 140736269555952, 140737298297504, 140737294723671, 140737353877200, 0,
            140737353877488, 4218192, 140737488348512, 0}}
        pid = <optimized out>
        tid = <optimized out>
        ret = <optimized out>
#1  0x00007ffff4717921 in __GI_abort () at abort.c:79
        save_stage = 1
        act = {__sigaction_handler = {sa_handler = 0x405d50 <_start>, sa_sigaction = 0x405d50 <_start>}, sa_mask = {__val = {140737349683111,
              140736269509200, 224, 140736220393488, 110450303344, 140737353877568, 3027005456, 7897856, 140737351851288, 7597679427751605295,
              8029178664428990559, 3761130410862802034, 140736220364853, 140736269508996, 140736269508992, 140736269509000}}, sa_flags = -1267961840,
          sa_restorer = 0x0}
        sigs = {__val = {32, 0 <repeats 15 times>}}
        __cnt = <optimized out>
        __set = <optimized out>
        __cnt = <optimized out>
        __set = <optimized out>
#2  0x0000000000407193 in os_panic () at /usr/src/upg-vpp/vpp/src/vpp/vnet/main.c:371
No locals.
#3  0x00007ffff55f6619 in debugger () at /usr/src/upg-vpp/vpp/src/vppinfra/error.c:84
No locals.
#4  0x00007ffff55f6397 in _clib_error (how_to_die=2, function_name=0x0, line_number=0, fmt=0x7fffac0b21f7 "%s:%d (%s) assertion `%s' fails")
    at /usr/src/upg-vpp/vpp/src/vppinfra/error.c:143
        msg = 0x0
        va = {{gp_offset = 48, fp_offset = 48, overflow_arg_area = 0x7ffff7fc0af0, reg_save_area = 0x7ffff7fc09b0}}
#5  0x00007fffac014582 in vlib_decrement_simple_counter (cm=0x7fffb64610b0, thread_index=0, index=0, decrement=1)
    at /usr/src/upg-vpp/vpp/src/vlib/counter.h:101
        my_counters = 0x7fffa7f50600
#6  0x00007fffac013a29 in pfcp_release_association (n=0x7fffb61752c0) at /usr/src/upg-vpp/vpp/src/plugins/upf/upf_pfcp.c:439
        gtm = 0x7fffac2f2248 <upf_main>
        node_id = 2
        idx = 4294967295
#7  0x00007fffac052f66 in request_t1_expired (seq_no=3) at /usr/src/upg-vpp/vpp/src/plugins/upf/upf_pfcp_server.c:434
---Type <return> to continue, or q <return> to quit---
        n = 0x7fffb61752c0
        type = 1 '\001'
        psm = 0x7fffac2f2618 <pfcp_server_main>
        gtm = 0x7fffac2f2248 <upf_main>
        msg = 0x7fffb75dbd80
        p = 0x7fffb5ee84e0
#8  0x00007fffac044161 in pfcp_process (vm=0x7ffff6481b80 <vlib_global_main>, rt=0x7fffb5739680, f=0x0)
    at /usr/src/upg-vpp/vpp/src/plugins/upf/upf_pfcp_server.c:1280
        i = 0
        ticks_until_expiration = 1
        timeout = 0.01
        psm = 0x7fffac2f2618 <pfcp_server_main>
        event_type = 18446744073709551615
        event_data = 0x7fffb5e0d2c0
        gtm = 0x7fffac2f2248 <upf_main>
        last_expired = 4294967295
        msg = 0x7fffb75dc180
#9  0x00007ffff61c7efd in vlib_process_bootstrap (_a=140736227657736) at /usr/src/upg-vpp/vpp/src/vlib/main.c:1454
        a = 0x7fffb4db4808
        vm = 0x7ffff6481b80 <vlib_global_main>
        node = 0x7fffb5739680
        f = 0x0
        p = 0x7fffb5739680
        n = 0
#10 0x00007ffff561a7a4 in clib_calljmp () at /usr/src/upg-vpp/vpp/src/vppinfra/longjmp.S:123
No locals.
#11 0x00007fffb4db4800 in ?? ()
No symbol table info available.
#12 0x00007ffff61c793f in vlib_process_startup (vm=0x1affffe560, p=0x1752cfd8cc9fc, f=0xb4db4860) at /usr/src/upg-vpp/vpp/src/vlib/main.c:1479
        a = {vm = 0x7ffff61c8121 <vlib_node_runtime_update_stats+273>, process = 0x0, frame = 0x7ffff7dd0f60}
        r = 0

PCAP trace from smf is attached. smf_upg_vpp.zip

RoadRunnr commented 3 years ago

open5gs problem

The SMF seem to have two problems.

  1. it can not handle the PFCP Heartbeat Request from UPG, that is the warning: 
    03/20 23:01:14.729: [smf] WARNING: cannot handle PFCP message type[1] (../src/smf/pfcp-sm.c:140)

That seems to be no critical. Heartbeats are required to check the liveliness of the PFCP peer. I would consider that a critical feature and the SMF not supporting that is somewhat strange.

  1. the SMF is not ignoring unknown vendor IEs.

This is causing the 

03/20 23:01:15.207: [core] ERROR: Unexpected TLV type:32770 (../lib/core/ogs-tlv-msg.c:454)
03/20 23:01:15.207: [smf] ERROR: ogs_pfcp_parse_msg() failed (../src/smf/smf-sm.c:228)

error. This is in the end preventing the assoziation from working.

UPG uses some vendor IEs to transport diagnostic information. Vendor IEs are not mandatory and unknown IEs of that type should be ignored by the SMF. You need to talk to the open5gs project to fix that in the SMF.

UPG crash

There seems to be a problem with handling the resend timeout of the Heartbeat Request. @ivan4th is looking at that already.

infinitydon commented 3 years ago

@RoadRunnr Thanks for the response..

So I tried to test with another SMF (Free5gc) and the outcome seems the same:

2021-03-23T08:22:59Z [INFO][SMF][App] Send PFCP Association Request to UPF[10.0.0.149] (/go/src/free5gc/src/smf/service/init.go:163 free5gc/src/smf/service.(*SMF).Start)
2021-03-23T08:22:59Z [WARN][SMF][Pfcp] Read PFCP error: Inadequate TLV length: 6 (/go/src/free5gc/src/smf/pfcp/udp/udp.go:37 free5gc/src/smf/pfcp/udp.Run.func1)
2021-03-23T08:23:02Z [WARN][SMF][Pfcp] Read PFCP error: Inadequate TLV length: 6 (/go/src/free5gc/src/smf/pfcp/udp/udp.go:37 free5gc/src/smf/pfcp/udp.Run.func1)
2021-03-23T08:23:05Z [WARN][SMF][Pfcp] Read PFCP error: Inadequate TLV length: 6 (/go/src/free5gc/src/smf/pfcp/udp/udp.go:37 free5gc/src/smf/pfcp/udp.Run.func1)
2021-03-23T08:23:08Z [INFO][LIB][PFCP] Remove Request Transaction [1]
2021-03-23T08:23:09Z [WARN][SMF][Pfcp] PFCP Heartbeat Request handling is not implemented (/go/src/free5gc/src/smf/pfcp/handler/handler.go:17 free5gc/src/smf/pfcp/handler.HandlePfcpHeartbeatRequest)
2021-03-23T08:23:19Z [WARN][SMF][Pfcp] PFCP Heartbeat Request handling is not implemented (/go/src/free5gc/src/smf/pfcp/handler/handler.go:17 free5gc/src/smf/pfcp/handler.HandlePfcpHeartbeatRequest)
2021-03-23T08:23:30Z [WARN][SMF][Pfcp] PFCP Heartbeat Request handling is not implemented (/go/src/free5gc/src/smf/pfcp/handler/handler.go:17 free5gc/src/smf/pfcp/handler.HandlePfcpHeartbeatRequest)

gdb crash log:

DBGvpp# /usr/src/upg-vpp/vpp/src/vlib/counter.h:101 (vlib_decrement_simple_counter) assertion `my_counters[index] >= decrement' fails

Program received signal SIGABRT, Aborted.
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
51      ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt full 30
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
        set = {__val = {0, 140737309885698, 65568, 142, 142, 7897856, 1, 140736269555952, 140737298297504, 140737294723671, 140737353876368, 0,
            140737353876656, 4218192, 140737488348512, 0}}
        pid = <optimized out>
        tid = <optimized out>
        ret = <optimized out>
#1  0x00007ffff4717921 in __GI_abort () at abort.c:79
        save_stage = 1
        act = {__sigaction_handler = {sa_handler = 0x405d50 <_start>, sa_sigaction = 0x405d50 <_start>}, sa_mask = {__val = {140737349683111,
              140736269018944, 224, 140736220393488, 110449813088, 140737353876736, 3027005456, 7897856, 140737351851288, 7597679427751605295,
              8029178664428990559, 3618423697182127218, 140736220364855, 140736269018740, 140736269018736, 140736269018744}}, sa_flags = -1267961840,
          sa_restorer = 0x0}
        sigs = {__val = {32, 0 <repeats 15 times>}}
        __cnt = <optimized out>
        __set = <optimized out>
        __cnt = <optimized out>
        __set = <optimized out>
#2  0x0000000000407193 in os_panic () at /usr/src/upg-vpp/vpp/src/vpp/vnet/main.c:371
No locals.
#3  0x00007ffff55f6619 in debugger () at /usr/src/upg-vpp/vpp/src/vppinfra/error.c:84
No locals.
#4  0x00007ffff55f6397 in _clib_error (how_to_die=2, function_name=0x0, line_number=0, fmt=0x7fffac0b21f7 "%s:%d (%s) assertion `%s' fails")
    at /usr/src/upg-vpp/vpp/src/vppinfra/error.c:143
        msg = 0x0
        va = {{gp_offset = 48, fp_offset = 48, overflow_arg_area = 0x7ffff7fc07b0, reg_save_area = 0x7ffff7fc0670}}
#5  0x00007fffac014582 in vlib_decrement_simple_counter (cm=0x7fffb64610b0, thread_index=0, index=0, decrement=1)
    at /usr/src/upg-vpp/vpp/src/vlib/counter.h:101
        my_counters = 0x7fffa7f50600
#6  0x00007fffac013a29 in pfcp_release_association (n=0x7fffb75da880) at /usr/src/upg-vpp/vpp/src/plugins/upf/upf_pfcp.c:439
        gtm = 0x7fffac2f2248 <upf_main>
        node_id = 8
        idx = 4294967295
#7  0x00007fffac02cc26 in handle_association_setup_request (req=0x7fffb618adc0, msg=0x7ffff7fc09f0)
---Type <return> to continue, or q <return> to quit---
    at /usr/src/upg-vpp/vpp/src/plugins/upf/upf_pfcp_api.c:357
        psm = 0x7fffac2f2618 <pfcp_server_main>
        resp = {grp = {fields = 139, ies = 0x0}, node_id = {type = 0 '\000', {ip = {{pad = {0, 0, 0}, ip4 = {data = "\n\000\000\225",
                    data_u32 = 2499805194, as_u8 = "\n\000\000\225", as_u16 = {10, 38144}, as_u32 = 2499805194}}, ip6 = {
                  as_u8 = '\000' <repeats 12 times>, "\n\000\000\225", as_u16 = {0, 0, 0, 0, 0, 0, 10, 38144}, as_u32 = {0, 0, 0, 2499805194},
                  as_u64 = {0, 10736581554600935424}, as_u128 = {0, 10736581554600935424}, as_uword = {0, 10736581554600935424}},
                as_u8 = '\000' <repeats 12 times>, "\n\000\000\225", as_u64 = {0, 10736581554600935424}}, fqdn = 0x0}}, cause = 64 '@',
          tp_error_report = {grp = {fields = 0, ies = 0x0}, error_message = 0x0, file_name = 0x0, line_number = 0}, recovery_time_stamp = 1616487759,
          cp_function_features = 0 '\000', up_function_features = 0, user_plane_ip_resource_information = 0x0,
          tp_build_id = 0x7fffb75b02c0 "vpp v20.09-rc0~292-g20148fdc1 built by root on ip-10-0-2-92 at 2021-03-20T21:25:19",
          ue_ip_address_pool_identity = 0x0}
        gtm = 0x7fffac2f2248 <upf_main>
        n = 0x7fffb75da880
        r = 0
#8  0x00007fffac02ab35 in node_msg (msg=0x7fffb618adc0) at /usr/src/upg-vpp/vpp/src/plugins/upf/upf_pfcp_api.c:571
        m = {grp = {fields = 11, ies = 0x0}, simple_response = {grp = {fields = 11, ies = 0x0}, response = {node_id = {type = 0 '\000', {ip = {{pad = {
                        0, 0, 0}, ip4 = {data = "\n\000", <incomplete sequence \367>, data_u32 = 4144103434,
                        as_u8 = "\n\000", <incomplete sequence \367>, as_u16 = {10, 63234}, as_u32 = 4144103434}}, ip6 = {
                      as_u8 = '\000' <repeats 12 times>, "\n\000", <incomplete sequence \367>, as_u16 = {0, 0, 0, 0, 0, 0, 10, 63234}, as_u32 = {0, 0,
                        0, 4144103434}, as_u64 = {0, 17798788720271294464}, as_u128 = {0, 17798788720271294464}, as_uword = {0, 17798788720271294464}},
                    as_u8 = '\000' <repeats 12 times>, "\n\000", <incomplete sequence \367>, as_u64 = {0, 17798788720271294464}}, fqdn = 0x0}},
              cause = 52 '4', offending_ie = 0, recovery_time_stamp = 0, tp_error_report = {grp = {fields = 0, ies = 0x0}, error_message = 0x0,
                file_name = 0x0, line_number = 0}}}, heartbeat_request = {grp = {fields = 11, ies = 0x0}, recovery_time_stamp = 0},
          pfd_management_request = {grp = {fields = 11, ies = 0x0}, application_id_pfds = 0x0}, association_setup_request = {grp = {fields = 11,
              ies = 0x0}, request = {node_id = {type = 0 '\000', {ip = {{pad = {0, 0, 0}, ip4 = {data = "\n\000", <incomplete sequence \367>,
                        data_u32 = 4144103434, as_u8 = "\n\000", <incomplete sequence \367>, as_u16 = {10, 63234}, as_u32 = 4144103434}}, ip6 = {
                      as_u8 = '\000' <repeats 12 times>, "\n\000", <incomplete sequence \367>, as_u16 = {0, 0, 0, 0, 0, 0, 10, 63234}, as_u32 = {0, 0,
                        0, 4144103434}, as_u64 = {0, 17798788720271294464}, as_u128 = {0, 17798788720271294464}, as_uword = {0, 17798788720271294464}},
                    as_u8 = '\000' <repeats 12 times>, "\n\000", <incomplete sequence \367>, as_u64 = {0, 17798788720271294464}}, fqdn = 0x0}}},
            recovery_time_stamp = 1616280372, cp_function_features = 0 '\000', up_function_features = 0, user_plane_ip_resource_information = 0x0,
            tp_build_id = 0x0, ue_ip_address_pool_identity = 0x0, alternative_smf_ip_address = 0x0}, association_update_request = {grp = {fields = 11,
              ies = 0x0}, request = {node_id = {type = 0 '\000', {ip = {{pad = {0, 0, 0}, ip4 = {data = "\n\000", <incomplete sequence \367>,
                        data_u32 = 4144103434, as_u8 = "\n\000", <incomplete sequence \367>, as_u16 = {10, 63234}, as_u32 = 4144103434}}, ip6 = {
---Type <return> to continue, or q <return> to quit---
                      as_u8 = '\000' <repeats 12 times>, "\n\000", <incomplete sequence \367>, as_u16 = {0, 0, 0, 0, 0, 0, 10, 63234}, as_u32 = {0, 0,
                        0, 4144103434}, as_u64 = {0, 17798788720271294464}, as_u128 = {0, 17798788720271294464}, as_uword = {0, 17798788720271294464}},
                    as_u8 = '\000' <repeats 12 times>, "\n\000", <incomplete sequence \367>, as_u64 = {0, 17798788720271294464}}, fqdn = 0x0}}},
            cp_function_features = 52 '4', up_function_features = 0, pfcp_association_release_request = {flags = 0 '\000'},
            graceful_release_period = 0, user_plane_ip_resource_information = 0x0, pfcpaureq_flags = 0 '\000', ue_ip_address_pool_identity = 0x0,
            alternative_smf_ip_address = 0x0}, association_release_request = {grp = {fields = 11, ies = 0x0}, request = {node_id = {type = 0 '\000', {
                  ip = {{pad = {0, 0, 0}, ip4 = {data = "\n\000", <incomplete sequence \367>, data_u32 = 4144103434,
                        as_u8 = "\n\000", <incomplete sequence \367>, as_u16 = {10, 63234}, as_u32 = 4144103434}}, ip6 = {
                      as_u8 = '\000' <repeats 12 times>, "\n\000", <incomplete sequence \367>, as_u16 = {0, 0, 0, 0, 0, 0, 10, 63234}, as_u32 = {0, 0,
                        0, 4144103434}, as_u64 = {0, 17798788720271294464}, as_u128 = {0, 17798788720271294464}, as_uword = {0, 17798788720271294464}},
                    as_u8 = '\000' <repeats 12 times>, "\n\000", <incomplete sequence \367>, as_u64 = {0, 17798788720271294464}}, fqdn = 0x0}}}},
          association_procedure_response = {grp = {fields = 11, ies = 0x0}, node_id = {type = 0 '\000', {ip = {{pad = {0, 0, 0}, ip4 = {
                      data = "\n\000", <incomplete sequence \367>, data_u32 = 4144103434, as_u8 = "\n\000", <incomplete sequence \367>, as_u16 = {10,
                        63234}, as_u32 = 4144103434}}, ip6 = {as_u8 = '\000' <repeats 12 times>, "\n\000", <incomplete sequence \367>, as_u16 = {0, 0,
                      0, 0, 0, 0, 10, 63234}, as_u32 = {0, 0, 0, 4144103434}, as_u64 = {0, 17798788720271294464}, as_u128 = {0, 17798788720271294464},
                    as_uword = {0, 17798788720271294464}}, as_u8 = '\000' <repeats 12 times>, "\n\000", <incomplete sequence \367>, as_u64 = {0,
                    17798788720271294464}}, fqdn = 0x0}}, cause = 52 '4', tp_error_report = {grp = {fields = 0, ies = 0x0}, error_message = 0x0,
              file_name = 0x0, line_number = 0}, recovery_time_stamp = 0, cp_function_features = 0 '\000', up_function_features = 0,
            user_plane_ip_resource_information = 0x0, tp_build_id = 0x0, ue_ip_address_pool_identity = 0x0}, node_report_request = {grp = {fields = 11,
              ies = 0x0}, request = {node_id = {type = 0 '\000', {ip = {{pad = {0, 0, 0}, ip4 = {data = "\n\000", <incomplete sequence \367>,
                        data_u32 = 4144103434, as_u8 = "\n\000", <incomplete sequence \367>, as_u16 = {10, 63234}, as_u32 = 4144103434}}, ip6 = {
                      as_u8 = '\000' <repeats 12 times>, "\n\000", <incomplete sequence \367>, as_u16 = {0, 0, 0, 0, 0, 0, 10, 63234}, as_u32 = {0, 0,
                        0, 4144103434}, as_u64 = {0, 17798788720271294464}, as_u128 = {0, 17798788720271294464}, as_uword = {0, 17798788720271294464}},
                    as_u8 = '\000' <repeats 12 times>, "\n\000", <incomplete sequence \367>, as_u64 = {0, 17798788720271294464}}, fqdn = 0x0}}},
            node_report_type = {flags = 52 '4'}, user_plane_path_failure_report = {grp = {fields = 0, ies = 0x0}, remote_gtp_u_peer = 0x0}}}
        err = 0x0
        r = 0
#9  0x00007fffac02a811 in upf_pfcp_handle_msg (msg=0x7fffb618adc0) at /usr/src/upg-vpp/vpp/src/plugins/upf/upf_pfcp_api.c:169
No locals.
#10 0x00007fffac050c99 in upf_pfcp_server_rx_msg (msg=0x7fffb618adc0) at /usr/src/upg-vpp/vpp/src/plugins/upf/upf_pfcp_server.c:265
        p = 0x0
        psm = 0x7fffac2f2618 <pfcp_server_main>
        len = 31
---Type <return> to continue, or q <return> to quit---
        seq_no = 0x7fffb75def54 ""
#11 0x00007fffac043747 in pfcp_process (vm=0x7ffff6481b80 <vlib_global_main>, rt=0x7fffb5739680, f=0x0)
    at /usr/src/upg-vpp/vpp/src/plugins/upf/upf_pfcp_server.c:1180
        msg = 0x7fffb618adc0
        i = 0
        ticks_until_expiration = 100
        timeout = 1
        psm = 0x7fffac2f2618 <pfcp_server_main>
        event_type = 1
        event_data = 0x7fffb5e0d2c0
        gtm = 0x7fffac2f2248 <upf_main>
        last_expired = 4294967295
        msg = 0x7fffb75deb40
#12 0x00007ffff61c7efd in vlib_process_bootstrap (_a=140736227657736) at /usr/src/upg-vpp/vpp/src/vlib/main.c:1454
        a = 0x7fffb4db4808
        vm = 0x7ffff6481b80 <vlib_global_main>
        node = 0x7fffb5739680
        f = 0x0
        p = 0x7fffb5739680
        n = 0
#13 0x00007ffff561a7a4 in clib_calljmp () at /usr/src/upg-vpp/vpp/src/vppinfra/longjmp.S:123
No locals.
#14 0x00007fffb4db4800 in ?? ()
No symbol table info available.
#15 0x00007ffff61c793f in vlib_process_startup (vm=0x1ab75c0168, p=0x1e4c0d24dadb0, f=0xb4db4860) at /usr/src/upg-vpp/vpp/src/vlib/main.c:1479
        a = {vm = 0x511a, process = 0x0, frame = 0x7ffff647dcb8}
        r = 5716601473401
RoadRunnr commented 3 years ago 
2021-03-23T08:23:02Z [WARN][SMF][Pfcp] Read PFCP error: Inadequate TLV length: 6 (/go/src/free5gc/src/smf/pfcp/udp/udp.go:37 free5gc/src/smf/pfcp/udp.Run.func1)

Seems like the handling of PFPC IE UP Function Features in free5gc is broken. That IE is extensible and has been extended in R16. A length of 6 is perfectly legal and the SMF should ignore the bits it doesn't know about.

infinitydon commented 3 years ago

@RoadRunnr @ivan4th Open5gs fixed the bug, PFCP association is now been accepted.

Open5GS daemon v2.2.2-7-gb21dc65

03/24 05:13:27.595: [app] INFO: Configuration: '/open5gs/config-map/smf.yaml' (../lib/app/ogs-init.c:129)
03/24 05:13:27.595: [app] INFO: File Logging: '/var/log/open5gs/smf.log' (../lib/app/ogs-init.c:132)
03/24 05:13:27.603: [smf] WARNING: No diameter configuration (../src/smf/fd-path.c:1067)
03/24 05:13:27.603: [app] INFO: SMF initialize...done (../src/smf/app.c:31)
03/24 05:13:27.603: [gtp] INFO: gtp_server() [10.0.2.44]:2123 (../lib/gtp/path.c:31)
03/24 05:13:27.603: [gtp] INFO: gtp_server() [10.0.2.44]:2152 (../lib/gtp/path.c:31)
03/24 05:13:27.603: [pfcp] INFO: pfcp_server() [10.0.2.44]:8805 (../lib/pfcp/path.c:31)
03/24 05:13:27.603: [pfcp] INFO: ogs_pfcp_connect() [10.0.0.149]:8805 (../lib/pfcp/path.c:59)
03/24 05:13:27.605: [sbi] INFO: nghttp2_server() [0.0.0.0]:80 (../lib/sbi/nghttp2-server.c:144)
03/24 05:13:27.606: [smf] INFO: [aa8bfc4e-8c5f-41eb-a602-419a4c4380df] NF registred [Heartbeat:10s] (../src/smf/nf-sm.c:199)
03/24 05:14:49.627: [core] WARNING: Unknown TLV type [32770] (../lib/core/ogs-tlv-msg.c:454)
03/24 05:14:49.627: [smf] INFO: PFCP associated (../src/smf/pfcp-sm.c:174)

open5gs-vpp-upg.zip

But the upg still crashes.

RoadRunnr commented 3 years ago

I'm a bit at a loss now, I can see anything in the PCAP that could explain the crash.

Could you please check if VPP is still crashing in the same place? It would be very helpful if you could provide a full backtrace (`bt full 30') and a PCAP that matches that backtrace (and please do not filter the PCAP for PFCP, having potential ICMP errors or ARP request in there can help as well). That way it might be possible to pinpoint the message that triggered the problem.

Can you try to first start VPP, ping the PFCP interface IP and after that works, start the SMF? VPP has the annoying "feature" to drop the first packet sent to an IP for which it has no ARP entry yet. That can lead to PFCP responses from UPG being lost which could explain problems.

sergeymatov commented 3 years ago

@infinitydon could you please check UPG build based on this branch https://github.com/travelping/upg-vpp/tree/test/release-accosiation-structure

infinitydon commented 3 years ago

@sergeymatov Before I test the branch you mentioned, I did a fresh installation from the master and the crash is not occurring again but PDU session setup fails with error "Rule creation/modification Failure (73)".

From the specification this error means: This cause shall be used by the UP function if a received Rule failed to be stored and be applied in the UP function.

smf-travel-ping.zip

Let me know if it is necessary to still test with the branch you mentioned.

RoadRunnr commented 3 years ago

The full reason is given in the vendor IE: PDR ID 1, unknown Network Instance

Your request uses network instance internet. The error indicates that you did not configure that network instance in VPP.

infinitydon commented 3 years ago

Ok.. internet is the DNN config on the side of SMF

    upf:
      pfcp:
        - addr: 10.0.0.149
          dnn: internet

Please where exactly should I configure this in the VPP?

infinitydon commented 3 years ago

@RoadRunnr @sergeymatov - Please can you confirm if this is a configuration issue on my side and suggest the right config?

diallama commented 3 years ago

I have the same error as @infinitydon : Rule creation/modification failure. I use free5gc SMF. A reflection track would be welcome test2.zip

infinitydon commented 3 years ago

@RoadRunnr @sergeymatov - I am still trying to get this working, so far from the pcap trace I can see that open5gs is specifying the NWI in the IEs but seems upg is expecting it in a particular order?

image

VPP is complaining that the mandatory IE is missing:

image

open5gs-smf-upg-aug-8.zip

sergeymatov commented 3 years ago

@infinitydon please attach upg-vpp init configuration also, PFCP association request/response pcaps are needed

infinitydon commented 3 years ago

@sergeymatov

VPP Init Config:

ip table add 1
ip table add 2

create host-interface name core
set interface mac address host-core 02:14:bf:ae:e5:55
set interface mtu 1500 host-core
set interface ip table host-core 0
set interface ip address host-core 10.0.4.10/24
set interface state host-core up

create host-interface name sgi
set interface mac address host-sgi 02:28:b9:69:28:45
set interface mtu 1500 host-sgi
set interface ip table host-sgi 1
set interface ip address host-sgi 10.0.8.10/24
set interface state host-sgi up

create host-interface name access
set interface mac address host-access 02:ce:94:f4:ee:7f
set interface mtu 1500 host-access
set interface ip table host-access 2
set interface ip address host-access 10.0.6.10/24
set interface state host-access up

ip route add 0.0.0.0/0 table 0 via 10.0.4.1 host-core
ip route add 0.0.0.0/0 table 1 via 10.0.8.1 host-sgi
ip route add 0.0.0.0/0 table 2 via 10.0.6.1 host-access

upf pfcp endpoint ip 10.0.4.10 vrf 0

upf nwi name core vrf 0
upf nwi name sgi vrf 1
upf nwi name access vrf 2

upf node-id ip4 10.0.4.10

upf specification release 16

trace add af-packet-input 100

upf gtpu endpoint ip 10.0.6.10 nwi access teid 0x000004d2/2

pcap trace with PFCP association request/response and session establishment/request.

smf-upg-aug-11.zip

RoadRunnr commented 3 years ago

two problems:

  1. the PDI specifies the NWI "internet", but you have not configured a NWI of that name
  2. a valid Network Instance IE also needs to be present in the FAR

some more observations:

infinitydon commented 3 years ago

Thanks @RoadRunnr - I agree with you regarding using separate vrf/nwi for the GTP and SGi traffic but seems open5gs developer's focus is to code the SMF with their own UPF.

I want ask for a favor, can you please guide on which part of upg-vpp's code that I can modify so as to skip the SGi FAR IE check and set a default SGi instance value? I know this may not be optimal but am only working on setting up a PoC and currently have limited coding knowledge but I can follow through the code and make the changes quickly if I can get some hints.

infinitydon commented 3 years ago

Have been able to get this working with Free5gc SMF.

raoufkh commented 3 years ago

Hello everyone

I would like to know what is the status of the Free5GC control plane integration with Travelping UPG-VPP? Currently, I am using Free5GC v3.0.6 on top of Kubernetes (I implementand using https://github.com/Orange-OpenSource/towards5gs-helm). Ideally, I would like to deploy UPG-VPP on Kubernetes as well. However, I can't find the necessary instructions to build and run UPG-VPP, nor how to configure it (ideally it would be with configuration files). Would it be possible to provide a link to this information?

Thank you in advance, Abderaouf

prati08 commented 2 years ago

Hi Christopher Adigun

Have been able to get this working with Free5gc SMF.

Hi Christopher Adigun,

can you please help how you run UPG-VPP with free5gc smf

Thanks in Advance

infinitydon commented 2 years ago

@prati08 - Please see the issue below for the workaround:

https://github.com/travelping/upg-vpp/issues/136#issuecomment-903421040