search

open5gs / open5gs

Open5GS is a C-language Open Source implementation for 5G Core and EPC, i.e. the core network of LTE/NR network (Release-17)
https://open5gs.org
GNU Affero General Public License v3.0
1.87k stars 770 forks source link

Holding Timeout for step 2 type 33 peer #185

Closed sgww2 closed 5 years ago

sgww2 commented 5 years ago

Hi

I observe GTPU packets back from PGW to SGW, but SGW does not send them to eNodeB. SGW Log contains the following message:

May 22 11:28:41 apu02 nextepc-sgwd[10807]: 05/22 11:28:41.909: [gtp] DEBUG: [1] REMOTE Holding Timeout for step 2 type 33 peer [172.16.0.1]:2123 (gtp_xact.c:566)

What does this message mean and what could be the reason for the issue?

May 22 11:28:38 apu02 nextepc-sgwd[10807]: 05/22 11:28:38.623: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
May 22 11:28:38 apu02 nextepc-sgwd[10807]: 05/22 11:28:38.623: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x6] (sgw_gtp_path.c:129)
May 22 11:28:38 apu02 nextepc-sgwd[10807]: 05/22 11:28:38.943: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
May 22 11:28:38 apu02 nextepc-sgwd[10807]: 05/22 11:28:38.943: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x6] (sgw_gtp_path.c:129)
May 22 11:28:38 apu02 nextepc-sgwd[10807]: 05/22 11:28:38.943: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
May 22 11:28:38 apu02 nextepc-sgwd[10807]: 05/22 11:28:38.944: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x6] (sgw_gtp_path.c:129)
May 22 11:28:40 apu02 nextepc-sgwd[10807]: 05/22 11:28:40.623: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
May 22 11:28:40 apu02 nextepc-sgwd[10807]: 05/22 11:28:40.623: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x6] (sgw_gtp_path.c:129)
May 22 11:28:41 apu02 nextepc-sgwd[10807]: 05/22 11:28:41.665: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
May 22 11:28:41 apu02 nextepc-sgwd[10807]: 05/22 11:28:41.666: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x6] (sgw_gtp_path.c:129)
May 22 11:28:41 apu02 nextepc-sgwd[10807]: 05/22 11:28:41.909: [gtp] DEBUG: [1] REMOTE Holding Timeout for step 2 type 33 peer [172.16.0.1]:2123 (gtp_xact.c:566)
May 22 11:28:41 apu02 nextepc-sgwd[10807]: 05/22 11:28:41.909: [gtp] DEBUG: [1] REMOTE Delete Transaction for step 2 type 33 peer [172.16.0.1]:2123 (gtp_xact.c:581)
May 22 11:28:41 apu02 nextepc-sgwd[10807]: 05/22 11:28:41.909: [gtp] DEBUG: [1] REMOTE Delete  peer [172.16.0.1]:2123 (gtp_xact.c:760)
May 22 11:28:42 apu02 nextepc-sgwd[10807]: 05/22 11:28:42.002: [gtp] DEBUG: [2] REMOTE Holding Timeout for step 2 type 35 peer [172.16.0.1]:2123 (gtp_xact.c:566)
May 22 11:28:42 apu02 nextepc-sgwd[10807]: 05/22 11:28:42.002: [gtp] DEBUG: [2] REMOTE Delete Transaction for step 2 type 35 peer [172.16.0.1]:2123 (gtp_xact.c:581)
May 22 11:28:42 apu02 nextepc-sgwd[10807]: 05/22 11:28:42.002: [gtp] DEBUG: [2] REMOTE Delete  peer [172.16.0.1]:2123 (gtp_xact.c:760)
May 22 11:28:43 apu02 nextepc-sgwd[10807]: 05/22 11:28:43.663: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
May 22 11:28:43 apu02 nextepc-sgwd[10807]: 05/22 11:28:43.664: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x6] (sgw_gtp_path.c:129)
May 22 11:28:43 apu02 nextepc-sgwd[10807]: 05/22 11:28:43.743: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
May 22 11:28:43 apu02 nextepc-sgwd[10807]: 05/22 11:28:43.743: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x6] (sgw_gtp_path.c:129)
May 22 11:28:43 apu02 nextepc-sgwd[10807]: 05/22 11:28:43.983: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
May 22 11:28:43 apu02 nextepc-sgwd[10807]: 05/22 11:28:43.983: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x6] (sgw_gtp_path.c:129)
May 22 11:28:45 apu02 nextepc-sgwd[10807]: 05/22 11:28:45.663: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
May 22 11:28:45 apu02 nextepc-sgwd[10807]: 05/22 11:28:45.663: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x6] (sgw_gtp_path.c:129)
acetcom commented 5 years ago

Hi,

REMOTE Holding Timeout is a GTP-C, not the GTP-U. Because it is a control plane packet, it is not the root cause of your problem. See the lib/gtp/gtp_message.h to find the message type 33 that is Create Session Response GTPv2-C message.

Even if I don't know your network configuration, I assume it as below.

eNodeB GTP-U : 172.16.0.2 PGW GTP-C : 172.16.0.1 PGW GTP-U : 192.168.1.44

If yes, SGW does not receive GTP-U packet from PGW More information is required to resolve the issue such as network configuration.

Thanks!

sgww2 commented 5 years ago

Thank you

I have very similar issue in this case https://github.com/open5gs/nextepc/issues/183#issuecomment-494385534 There u can see all config files and logs. Tomorrow, I will post all data related to my current setup, but it is very similar to what I posted in the issue 183.

acetcom commented 5 years ago

I got your configuration.

Anyway, please check the iptables. See the reference link ==> "Adding a route for UE to have Internet connectivity"

$ sudo sh -c "echo 1 > /proc/sys/net/ipv4/ip_forward"
$ sudo iptables -t nat -A POSTROUTING -o 'interface-name' -j MASQUERADE
$ sudo iptables -I INPUT -i pgwtun -j ACCEPT

You show the result of iptable without 'sudo'. So, I cannot confirm it. If you are running 'iptable' command, use the 'sudo iptable' for reporting proper results.

Thanks!

sgww2 commented 5 years ago

I am running all commands as root user, therefore no need for sudo. You can see this from the command promt invitation root@APU3:~# iptables -L -t nat

sgww2 commented 5 years ago

For me it also looks like a NAT issue, but I have done some test with my laptop attached to PGW and checked that NAT works. Thought, tcpdump has not seen any traffic coming from PGW to Internet Router. Might be the issue is with pgwtun IP wrong configuration as described in https://github.com/open5gs/nextepc/issues/186 Anyway will fully check my setup tomorrow and if no success will put all config, logs and pcap files here.

sgww2 commented 5 years ago

One more test of the mentioned issue today, below is a full spec , configs etc.

172.16.0.2 - eNodeB (both control and user planes, no separation) 172.16.0.1, 192.168.1.122 - host APU2 (SGW, MME, HSS) 172.16.0.20, 192.168.1.144 - host APU3 (PGW, PCRF) 192.168.1.1 - Internet Gateway

MME Ports:

root@apu02:~# netstat -l4pn | grep mme
tcp        0      0 127.0.0.2:5868          0.0.0.0:*               LISTEN      18939/nextepc-mmed
tcp        0      0 127.0.0.2:3868          0.0.0.0:*               LISTEN      18939/nextepc-mmed
sctp                172.16.0.1:36412                                LISTEN      18939/nextepc-mmed
sctp       0      0 172.16.0.1:36412        172.16.0.2:36412        ESTABLISHED 18939/nextepc-mmed
udp        0      0 172.16.0.1:2123         0.0.0.0:*                           18939/nextepc-mmed
root@apu02:~#

SGW ports:

root@apu02:~# netstat -l4pn | grep sgw
udp        0      0 192.168.1.122:2123      0.0.0.0:*                           18984/nextepc-sgwd
udp        0      0 172.16.0.1:2152         0.0.0.0:*                           18984/nextepc-sgwd
root@apu02:~#

HSS ports: 

root@apu02:~# netstat -l4pn | grep hss
tcp        0      0 127.0.0.4:5868          0.0.0.0:*               LISTEN      15050/nextepc-hssd
tcp        0      0 127.0.0.4:3868          0.0.0.0:*               LISTEN      15050/nextepc-hssd
root@apu02:~#

PGW ports:

root@APU3:/etc/nextepc# netstat -l4pn | grep pgw
tcp        0      0 172.16.0.20:5868        0.0.0.0:*               LISTEN      12849/nextepc-pgwd
tcp        0      0 172.16.0.20:3868        0.0.0.0:*               LISTEN      12849/nextepc-pgwd
udp        0      0 192.168.1.144:2123      0.0.0.0:*                           12849/nextepc-pgwd
udp        0      0 192.168.1.144:2152      0.0.0.0:*                           12849/nextepc-pgwd
root@APU3:/etc/nextepc#

PCRF ports:

root@APU3:/etc/nextepc# netstat -l4pn | grep pcrf
tcp        0      0 127.0.0.5:5868          0.0.0.0:*               LISTEN      12671/nextepc-pcrfd
tcp        0      0 127.0.0.5:3868          0.0.0.0:*               LISTEN      12671/nextepc-pcrfd
root@APU3:/etc/nextepc#

Configuration files:

MME config

root@apu02:/etc/nextepc# cat mme.conf
### For reference, see `nextepc.conf`

logger:
    file: /var/log/nextepc/mme.log
    level: debug

parameter:

mme:
    freeDiameter: mme.conf
    s1ap:
      addr: 172.16.0.1
    gtpc:
      addr: 172.16.0.1
    gummei:
      plmn_id:
        mcc: 244
        mnc: 34
      mme_gid: 2
      mme_code: 1
    tai:
      plmn_id:
        mcc: 244
        mnc: 34
      tac: 12594
    security:
        integrity_order : [ EIA1, EIA2, EIA0 ]
        ciphering_order : [ EEA0, EEA1, EEA2 ]
    network_name:
        full: Cumucore

sgw:
    gtpc:
      addr: 192.168.1.122

pgw:
    gtpc:
      - addr: 127.0.0.3
        apn: internet
      - addr: 192.168.1.144
        apn: safenet
root@apu02:/etc/nextepc#

SGW config

root@apu02:/etc/nextepc# cat sgw.conf
### For reference, see `nextepc.conf`

logger:
    file: /var/log/nextepc/sgw.log
    level: debug

parameter:
    no_ipv6: true

sgw:
    gtpc:
      addr: 192.168.1.122
    gtpu:
      addr: 172.16.0.1
      addr: 192.168.1.122
root@apu02:/etc/nextepc#

HSS config

root@apu02:/etc/nextepc# cat hss.conf
### For reference, see `nextepc.conf`

db_uri: mongodb://localhost/nextepc

logger:
    file: /var/log/nextepc/hss.log
    level: debug

parameter:

hss:
    freeDiameter: hss.conf
root@apu02:/etc/nextepc#

PGW config

root@APU3:/etc/nextepc# cat pgw.conf
### For reference, see `nextepc.conf`

logger:
    file: /var/log/nextepc/pgw.log
    level: debug

parameter:

pgw:
    freeDiameter: pgw.conf
    gtpc:
      addr:
        - 192.168.1.144
    gtpu:
      - addr: 192.168.1.144
    ue_pool:
      - addr: 45.45.0.1/16
      - addr: cafe::1/64
    dns:
      - 8.8.8.8
      - 8.8.4.4
      - 2001:4860:4860::8888
      - 2001:4860:4860::8844
root@APU3:/etc/nextepc#

PCRF config

root@APU3:/etc/nextepc# cat pcrf.conf
### For reference, see `nextepc.conf`

db_uri: mongodb://172.16.0.1/nextepc

logger:
    file: /var/log/nextepc/pcrf.log
    level: trace
parameter:

pcrf:
    freeDiameter: pcrf.conf
root@APU3:/etc/nextepc#

Log files:

PGW log:

NextEPC daemon v0.4.1.2-fe68

05/24 10:45:25.911: [thread] DEBUG: [0x7f45f6bf4398] worker signal (ogs-thread.c:66)
05/24 10:45:25.911: [pgw] DEBUG: pgw_state_initial(): INIT (pgw_sm.c:15)
05/24 10:45:25.911: [pgw] DEBUG: pgw_state_operational(): ENTRY (pgw_sm.c:33)
05/24 10:45:25.911: [sock] DEBUG: socket create(2:2:17) (ogs-socket.c:82)
05/24 10:45:25.911: [sock] DEBUG: udp socket(2) (ogs-udp.c:32)
05/24 10:45:25.911: [sock] DEBUG: socket bind 192.168.1.144:2123 (ogs-socket.c:107)
05/24 10:45:25.911: [sock] DEBUG: udp_server() [192.168.1.144]:2123 (ogs-udp.c:55)
05/24 10:45:25.911: [gtp] INFO: gtp_server() [192.168.1.144]:2123 (gtp_path.c:35)
05/24 10:45:25.911: [sock] DEBUG: socket create(2:2:17) (ogs-socket.c:82)
05/24 10:45:25.911: [sock] DEBUG: udp socket(2) (ogs-udp.c:32)
05/24 10:45:25.911: [sock] DEBUG: socket bind 192.168.1.144:2152 (ogs-socket.c:107)
05/24 10:45:25.912: [sock] DEBUG: udp_server() [192.168.1.144]:2152 (ogs-udp.c:55)
05/24 10:45:25.912: [gtp] INFO: gtp_server() [192.168.1.144]:2152 (gtp_path.c:35)
05/24 10:45:25.917: [fd] INFO: CONNECTED TO 'pcrf.localdomain' (TCP,soc#10): (fd_logger.c:113)
05/24 10:45:25.920: [pgw] DEBUG: [PGW] PROTO:58 SRC:fe800000 00000000 077ed2c0 bd62099a (pgw_ipfw.c:290)
05/24 10:45:25.920: [pgw] DEBUG: [PGW] HLEN:40  DST:ff020000 00000000 00000000 00000002 (pgw_ipfw.c:293)
05/24 10:45:30.199: [pgw] DEBUG: [PGW] PROTO:58 SRC:fe800000 00000000 077ed2c0 bd62099a (pgw_ipfw.c:290)
05/24 10:45:30.199: [pgw] DEBUG: [PGW] HLEN:40  DST:ff020000 00000000 00000000 00000002 (pgw_ipfw.c:293)
05/24 10:45:38.729: [pgw] DEBUG: [PGW] PROTO:58 SRC:fe800000 00000000 077ed2c0 bd62099a (pgw_ipfw.c:290)
05/24 10:45:38.729: [pgw] DEBUG: [PGW] HLEN:40  DST:ff020000 00000000 00000000 00000002 (pgw_ipfw.c:293)
05/24 10:45:55.399: [pgw] DEBUG: [PGW] PROTO:58 SRC:fe800000 00000000 077ed2c0 bd62099a (pgw_ipfw.c:290)
05/24 10:45:55.399: [pgw] DEBUG: [PGW] HLEN:40  DST:ff020000 00000000 00000000 00000002 (pgw_ipfw.c:293)
05/24 10:46:27.811: [pgw] DEBUG: [PGW] PROTO:58 SRC:fe800000 00000000 077ed2c0 bd62099a (pgw_ipfw.c:290)
05/24 10:46:27.811: [pgw] DEBUG: [PGW] HLEN:40  DST:ff020000 00000000 00000000 00000002 (pgw_ipfw.c:293)
05/24 10:47:34.806: [pgw] DEBUG: [PGW] PROTO:58 SRC:fe800000 00000000 077ed2c0 bd62099a (pgw_ipfw.c:290)
05/24 10:47:34.806: [pgw] DEBUG: [PGW] HLEN:40  DST:ff020000 00000000 00000000 00000002 (pgw_ipfw.c:293)
05/24 10:49:43.057: [pgw] DEBUG: [PGW] PROTO:58 SRC:fe800000 00000000 077ed2c0 bd62099a (pgw_ipfw.c:290)
05/24 10:49:43.057: [pgw] DEBUG: [PGW] HLEN:40  DST:ff020000 00000000 00000000 00000002 (pgw_ipfw.c:293)
05/24 10:50:23.541: [pgw] DEBUG: pgw_state_operational(): PGW_EVT_S5C_MESSAGE (pgw_sm.c:33)
05/24 10:50:23.542: [gtp] INFO: gtp_connect() [192.168.1.122]:2123 (gtp_path.c:77)
05/24 10:50:23.542: [pgw] INFO: UE IMSI:[244341000000001] APN:[safenet] IPv4:[45.45.0.2] IPv6:[] (pgw_context.c:918)
05/24 10:50:23.542: [gtp] DEBUG: [1] REMOTE Create  peer [192.168.1.122]:2123 (gtp_xact.c:151)
05/24 10:50:23.542: [gtp] DEBUG: [1] REMOTE Receive peer [192.168.1.122]:2123 (gtp_xact.c:606)
05/24 10:50:23.542: [gtp] DEBUG: [1] REMOTE UPD RX-32  peer [192.168.1.122]:2123 (gtp_xact.c:258)
05/24 10:50:23.542: [pgw] DEBUG: [PGW] Create Session Reqeust (pgw_s5c_handler.c:29)
05/24 10:50:23.542: [pgw] DEBUG:     SGW_S5C_TEID[0x80000001] PGW_S5C_TEID[0x1] (pgw_s5c_handler.c:77)
05/24 10:50:23.542: [pgw] DEBUG:     SGW_S5U_TEID[2] PGW_S5U_TEID[1] (pgw_s5c_handler.c:79)
05/24 10:50:23.542: [gtp] INFO: gtp_connect() [172.16.0.1]:2152 (gtp_path.c:77)
05/24 10:50:23.543: [pgw] DEBUG: [PGW2] Credit-Control-Request (pgw_fd_path.c:71)
05/24 10:50:23.558: [pgw] DEBUG: [PGW] Credit-Control-Answer (pgw_fd_path.c:450)
05/24 10:50:23.559: [pgw] DEBUG:     Result Code: 2001 (pgw_fd_path.c:490)
05/24 10:50:23.559: [pgw] DEBUG:     From 'pcrf.localdomain' (pgw_fd_path.c:524)
05/24 10:50:23.559: [pgw] DEBUG:          ('localdomain') (pgw_fd_path.c:540)
05/24 10:50:23.559: [pgw] DEBUG: pgw_state_operational(): PGW_EVT_GX_SESSION_MSG (pgw_sm.c:33)
05/24 10:50:23.559: [pgw] DEBUG: [PGW] Create Session Response (pgw_s5c_build.c:29)
05/24 10:50:23.559: [pgw] DEBUG:     SGW_S5C_TEID[0x80000001] PGW_S5C_TEID[0x1] (pgw_s5c_build.c:37)
05/24 10:50:23.559: [pgw] DEBUG:     SGW_S5U_TEID[2] PGW_S5U_TEID[1] (pgw_s5c_build.c:39)
05/24 10:50:23.559: [gtp] DEBUG: [1] REMOTE UPD TX-33  peer [192.168.1.122]:2123 (gtp_xact.c:183)
05/24 10:50:23.559: [gtp] DEBUG: [1] REMOTE Commit  peer [192.168.1.122]:2123 (gtp_xact.c:424)
05/24 10:50:32.547: [gtp] DEBUG: [1] REMOTE Holding Timeout for step 2 type 33 peer [192.168.1.122]:2123 (gtp_xact.c:566)
05/24 10:50:32.547: [gtp] DEBUG: [1] REMOTE Delete Transaction for step 2 type 33 peer [192.168.1.122]:2123 (gtp_xact.c:581)
05/24 10:50:32.547: [gtp] DEBUG: [1] REMOTE Delete  peer [192.168.1.122]:2123 (gtp_xact.c:760)
05/24 10:53:53.644: [pgw] DEBUG: [PGW] PROTO:58 SRC:fe800000 00000000 077ed2c0 bd62099a (pgw_ipfw.c:290)
05/24 10:53:53.644: [pgw] DEBUG: [PGW] HLEN:40  DST:ff020000 00000000 00000000 00000002 (pgw_ipfw.c:293)
05/24 10:53:53.644: [pgw] DEBUG: [PGW] PAA IPv4:45.45.0.2 (pgw_ipfw.c:308)

PCRF log - too bit to post file is attached

SGW log:

File Logging: '/var/log/nextepc/sgw.log'
LOG-LEVEL: 'debug'
Configuration: '/etc/nextepc/sgw.conf'
05/24 10:45:57.608: [thread] DEBUG: [0x7fe9c43e9398] thread started (ogs-thread.c:101)
05/24 10:45:57.608: [thread] DEBUG: [0x7fe9c43e9398] worker signal (ogs-thread.c:66)
05/24 10:45:57.608: [sgw] INFO: SGW initialize...done (sgw.c:25)
05/24 10:45:57.608: [sgw] DEBUG: sgw_state_initial(): INIT
 (sgw_sm.c:12)

NextEPC daemon v0.4.1.2-fe68

05/24 10:45:57.609: [sgw] DEBUG: sgw_state_operational(): ENTRY
 (sgw_sm.c:30)
05/24 10:45:57.609: [sock] DEBUG: socket create(2:2:17) (ogs-socket.c:82)
05/24 10:45:57.609: [sock] DEBUG: udp socket(2) (ogs-udp.c:32)
05/24 10:45:57.609: [sock] DEBUG: socket bind 192.168.1.122:2123 (ogs-socket.c:107)
05/24 10:45:57.609: [sock] DEBUG: udp_server() [192.168.1.122]:2123 (ogs-udp.c:55)
05/24 10:45:57.609: [gtp] INFO: gtp_server() [192.168.1.122]:2123 (gtp_path.c:35)
05/24 10:45:57.609: [sock] DEBUG: socket create(2:2:17) (ogs-socket.c:82)
05/24 10:45:57.609: [sock] DEBUG: udp socket(2) (ogs-udp.c:32)
05/24 10:45:57.609: [sock] DEBUG: socket bind 172.16.0.1:2152 (ogs-socket.c:107)
05/24 10:45:57.609: [sock] DEBUG: udp_server() [172.16.0.1]:2152 (ogs-udp.c:55)
05/24 10:45:57.609: [gtp] INFO: gtp_server() [172.16.0.1]:2152 (gtp_path.c:35)
05/24 10:50:23.539: [sgw] DEBUG: sgw_state_operational(): SGW_EVT_S11_MESSAGE
 (sgw_sm.c:30)
05/24 10:50:23.540: [gtp] INFO: gtp_connect() [172.16.0.1]:2123 (gtp_path.c:77)
05/24 10:50:23.540: [gtp] DEBUG: [1] REMOTE Create  peer [172.16.0.1]:2123 (gtp_xact.c:151)
05/24 10:50:23.540: [gtp] DEBUG: [1] REMOTE Receive peer [172.16.0.1]:2123 (gtp_xact.c:606)
05/24 10:50:23.540: [gtp] DEBUG: [1] REMOTE UPD RX-32  peer [172.16.0.1]:2123 (gtp_xact.c:258)
05/24 10:50:23.540: [sgw] DEBUG: [SGW] Create Session Request (sgw_s11_handler.c:36)
05/24 10:50:23.540: [sgw] DEBUG:     MME_S11_TEID[1] SGW_S11_TEID[1] (sgw_s11_handler.c:106)
05/24 10:50:23.540: [sgw] DEBUG:     SGW_S5C_TEID[0x80000001] PGW_S5C_TEID[0x0] (sgw_s11_handler.c:108)
05/24 10:50:23.540: [sgw] DEBUG:     SGW_S5U_TEID[2] PGW_S5U_TEID[0] (sgw_s11_handler.c:110)
05/24 10:50:23.540: [gtp] INFO: gtp_connect() [192.168.1.144]:2123 (gtp_path.c:77)
05/24 10:50:23.541: [gtp] DEBUG: [1] LOCAL  UPD TX-32  peer [192.168.1.144]:2123 (gtp_xact.c:183)
05/24 10:50:23.541: [gtp] DEBUG: [1] LOCAL  Create  peer [192.168.1.144]:2123 (gtp_xact.c:115)
05/24 10:50:23.541: [gtp] DEBUG: [1] LOCAL  Commit  peer [192.168.1.144]:2123 (gtp_xact.c:424)
05/24 10:50:23.560: [sgw] DEBUG: sgw_state_operational(): SGW_EVT_S5C_MESSAGE
 (sgw_sm.c:30)
05/24 10:50:23.560: [gtp] DEBUG: [1] LOCAL  Find    peer [192.168.1.144]:2123 (gtp_xact.c:717)
05/24 10:50:23.560: [gtp] DEBUG: [1] LOCAL  Receive peer [192.168.1.144]:2123 (gtp_xact.c:606)
05/24 10:50:23.560: [gtp] DEBUG: [1] LOCAL  UPD RX-33  peer [192.168.1.144]:2123 (gtp_xact.c:258)
05/24 10:50:23.560: [sgw] DEBUG: [SGW] Create Session Response (sgw_s5c_handler.c:38)
05/24 10:50:23.560: [sgw] DEBUG:     MME_S11_TEID[1] SGW_S11_TEID[1] (sgw_s5c_handler.c:85)
05/24 10:50:23.561: [sgw] DEBUG:     SGW_S5C_TEID[0x80000001] PGW_S5C_TEID[0x1] (sgw_s5c_handler.c:87)
05/24 10:50:23.561: [sgw] DEBUG:     ENB_S1U_TEID[0] SGW_S1U_TEID[1] (sgw_s5c_handler.c:89)
05/24 10:50:23.561: [sgw] DEBUG:     SGW_S5U_TEID[2] PGW_S5U_TEID[1] (sgw_s5c_handler.c:91)
05/24 10:50:23.561: [gtp] INFO: gtp_connect() [192.168.1.144]:2152 (gtp_path.c:77)
05/24 10:50:23.561: [gtp] DEBUG: [1] LOCAL  Commit  peer [192.168.1.144]:2123 (gtp_xact.c:424)
05/24 10:50:23.561: [gtp] DEBUG: [1] LOCAL  Delete  peer [192.168.1.144]:2123 (gtp_xact.c:760)
05/24 10:50:23.561: [gtp] DEBUG: [1] REMOTE UPD TX-33  peer [172.16.0.1]:2123 (gtp_xact.c:183)
05/24 10:50:23.561: [gtp] DEBUG: [1] REMOTE Commit  peer [172.16.0.1]:2123 (gtp_xact.c:424)
05/24 10:50:23.633: [sgw] DEBUG: sgw_state_operational(): SGW_EVT_S11_MESSAGE
 (sgw_sm.c:30)
05/24 10:50:23.633: [gtp] DEBUG: [2] REMOTE Create  peer [172.16.0.1]:2123 (gtp_xact.c:151)
05/24 10:50:23.633: [gtp] DEBUG: [2] REMOTE Receive peer [172.16.0.1]:2123 (gtp_xact.c:606)
05/24 10:50:23.633: [gtp] DEBUG: [2] REMOTE UPD RX-34  peer [172.16.0.1]:2123 (gtp_xact.c:258)
05/24 10:50:23.633: [sgw] DEBUG: [SGW] Modify Bearer Reqeust (sgw_s11_handler.c:190)
05/24 10:50:23.633: [sgw] DEBUG:     MME_S11_TEID[1] SGW_S11_TEID[1] (sgw_s11_handler.c:218)
05/24 10:50:23.633: [sgw] DEBUG:     ENB_S1U_TEID[1] SGW_S1U_TEID[1] (sgw_s11_handler.c:220)
05/24 10:50:23.634: [gtp] INFO: gtp_connect() [172.16.0.2]:2152 (gtp_path.c:77)
05/24 10:50:23.634: [gtp] DEBUG: [2] REMOTE UPD TX-35  peer [172.16.0.1]:2123 (gtp_xact.c:183)
05/24 10:50:23.634: [gtp] DEBUG: [2] REMOTE Commit  peer [172.16.0.1]:2123 (gtp_xact.c:424)
05/24 10:50:24.409: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:24.409: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:24.489: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:24.489: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:24.649: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:24.649: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:24.656: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:24.656: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:24.709: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:24.709: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:24.969: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:24.969: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:24.976: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:24.976: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:24.976: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:24.976: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:25.129: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:25.129: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:25.376: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:25.376: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:26.356: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:26.356: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:27.556: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:27.556: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:28.358: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:28.358: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:28.496: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:28.496: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:28.529: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:28.529: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:29.376: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:29.376: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:29.529: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:29.529: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:29.689: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:29.689: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:29.709: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:29.709: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:29.729: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:29.729: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:29.736: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:29.736: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:32.418: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:32.418: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:32.541: [gtp] DEBUG: [1] REMOTE Holding Timeout for step 2 type 33 peer [172.16.0.1]:2123 (gtp_xact.c:566)
05/24 10:50:32.541: [gtp] DEBUG: [1] REMOTE Delete Transaction for step 2 type 33 peer [172.16.0.1]:2123 (gtp_xact.c:581)
05/24 10:50:32.541: [gtp] DEBUG: [1] REMOTE Delete  peer [172.16.0.1]:2123 (gtp_xact.c:760)
05/24 10:50:32.634: [gtp] DEBUG: [2] REMOTE Holding Timeout for step 2 type 35 peer [172.16.0.1]:2123 (gtp_xact.c:566)
05/24 10:50:32.634: [gtp] DEBUG: [2] REMOTE Delete Transaction for step 2 type 35 peer [172.16.0.1]:2123 (gtp_xact.c:581)
05/24 10:50:32.634: [gtp] DEBUG: [2] REMOTE Delete  peer [172.16.0.1]:2123 (gtp_xact.c:760)
05/24 10:50:32.736: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:32.736: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:33.536: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:33.536: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:33.537: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:33.537: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:34.416: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:34.416: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:34.496: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:34.496: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:34.656: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:34.656: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:34.976: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:34.976: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:34.977: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:34.977: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)
05/24 10:50:34.978: [sgw] DEBUG: [SGW] RECV GPU-U from [172.16.0.2] : TEID[0x1] (sgw_gtp_path.c:98)
05/24 10:50:34.978: [sgw] DEBUG: [SGW] SEND GPU-U to PGW[192.168.1.144]: TEID[0x1] (sgw_gtp_path.c:129)

MME log

File Logging: '/var/log/nextepc/mme.log'
LOG-LEVEL: 'debug'
Configuration: '/etc/nextepc/mme.conf'
05/24 10:45:48.266: [mme] WARNING: unknown key `apn` (mme_context.c:1503)
05/24 10:45:48.266: [mme] WARNING: unknown key `apn` (mme_context.c:1503)
05/24 10:45:49.386: [thread] DEBUG: [0x7f12ef721618] thread started (ogs-thread.c:101)
05/24 10:45:49.386: [thread] DEBUG: [0x7f12ef721618] worker signal (ogs-thread.c:66)
05/24 10:45:49.387: [mme] INFO: MME initialize...done (mme.c:25)
05/24 10:45:49.387: [mme] DEBUG: mme_state_initial(): INIT
 (mme_sm.c:23)

NextEPC daemon v0.4.1.2-fe68

05/24 10:45:49.387: [mme] DEBUG: mme_state_operational(): ENTRY
 (mme_sm.c:43)
05/24 10:45:49.387: [sock] DEBUG: socket create(2:2:17) (ogs-socket.c:82)
05/24 10:45:49.387: [sock] DEBUG: udp socket(2) (ogs-udp.c:32)
05/24 10:45:49.387: [sock] DEBUG: socket bind 172.16.0.1:2123 (ogs-socket.c:107)
05/24 10:45:49.387: [sock] DEBUG: udp_server() [172.16.0.1]:2123 (ogs-udp.c:55)
05/24 10:45:49.387: [gtp] INFO: gtp_server() [172.16.0.1]:2123 (gtp_path.c:35)
05/24 10:45:49.387: [gtp] INFO: gtp_connect() [192.168.1.122]:2123 (gtp_path.c:77)
05/24 10:45:49.387: [sock] DEBUG: socket create(2:1:132) (ogs-socket.c:82)
05/24 10:45:49.388: [sock] DEBUG: socket bind 172.16.0.1:36412 (ogs-socket.c:107)
05/24 10:45:49.388: [sock] DEBUG: sctp_server() [172.16.0.1]:36412 (ogs-sctp.c:94)
05/24 10:45:49.388: [mme] INFO: s1ap_server() [172.16.0.1]:36412 (s1ap_lksctp.c:34)
05/24 10:45:49.391: [fd] INFO: CONNECTED TO 'hss.localdomain' (TCP,soc#10): (fd_logger.c:113)
05/24 10:49:56.655: [mme] INFO: eNB-S1 accepted[172.16.0.2]:36412 in s1_path module (s1ap_lksctp.c:110)
05/24 10:49:56.655: [mme] DEBUG: mme_state_operational(): MME_EVT_S1AP_LO_ACCEPT
 (mme_sm.c:43)
05/24 10:49:56.655: [mme] INFO: eNB-S1 accepted[172.16.0.2] in master_sm module (mme_sm.c:93)
05/24 10:49:56.655: [mme] DEBUG: s1ap_state_initial(): UNKNOWN_EVENT
 (s1ap_sm.c:14)
05/24 10:49:56.655: [mme] DEBUG: s1ap_state_operational(): ENTRY
 (s1ap_sm.c:34)
05/24 10:49:56.656: [mme] DEBUG: SCTP_ASSOC_CHANGE:[T:32769, F:0x0, S:0, I/O:32/30] (s1ap_lksctp.c:182)
05/24 10:49:56.656: [mme] DEBUG: SCTP_COMM_UP (s1ap_lksctp.c:186)
05/24 10:49:56.656: [mme] DEBUG: mme_state_operational(): MME_EVT_S1AP_LO_SCTP_COMM_UP
 (mme_sm.c:43)
05/24 10:49:56.656: [mme] DEBUG: eNB-S1 SCTP_COMM_UP[172.16.0.2] Outbound Streams[30] (mme_sm.c:140)
05/24 10:49:56.758: [mme] DEBUG: mme_state_operational(): MME_EVT_S1AP_MESSAGE
 (mme_sm.c:43)
05/24 10:49:56.759: [mme] DEBUG: s1ap_state_operational(): MME_EVT_S1AP_MESSAGE
 (s1ap_sm.c:34)
05/24 10:49:56.759: [mme] DEBUG: [MME] S1-Setup request (s1ap_handler.c:43)
05/24 10:49:56.759: [mme] DEBUG:     IP[172.16.0.2] ENB_ID[2] (s1ap_handler.c:67)
05/24 10:49:56.759: [mme] DEBUG:     PagingDRX[0] (s1ap_handler.c:70)
05/24 10:49:56.759: [mme] DEBUG:     PLMN_ID[MCC:244 MNC:34] TAC[12594] (s1ap_handler.c:108)
05/24 10:49:56.759: [mme] DEBUG:     SERVED_TAI_INDEX[0] (s1ap_handler.c:130)
05/24 10:49:56.759: [mme] DEBUG: [MME] S1-Setup response (s1ap_handler.c:146)
05/24 10:49:56.759: [mme] DEBUG:     PLMN_ID[MCC:244 MNC:34] (s1ap_build.c:71)
05/24 10:49:56.759: [mme] DEBUG:     MME Group[2] (s1ap_build.c:83)
05/24 10:49:56.759: [mme] DEBUG:     MME Code[1] (s1ap_build.c:93)
05/24 10:49:56.760: [mme] DEBUG:     IP[172.16.0.2] ENB_ID[2] (s1ap_path.c:70)
05/24 10:50:23.327: [mme] DEBUG: mme_state_operational(): MME_EVT_S1AP_MESSAGE
 (mme_sm.c:43)
05/24 10:50:23.327: [mme] DEBUG: s1ap_state_operational(): MME_EVT_S1AP_MESSAGE
 (s1ap_sm.c:34)
05/24 10:50:23.327: [mme] DEBUG: [MME] Initial UE Message (s1ap_handler.c:191)
05/24 10:50:23.327: [mme] DEBUG:     IP[172.16.0.2] ENB_ID[2] (s1ap_handler.c:219)
05/24 10:50:23.327: [mme] DEBUG:     ENB_UE_S1AP_ID[1] MME_UE_S1AP_ID[1] TAC[12594] (s1ap_handler.c:304)
05/24 10:50:23.327: [mme] DEBUG: mme_state_operational(): MME_EVT_EMM_MESSAGE
 (mme_sm.c:43)
05/24 10:50:23.328: [emm] DEBUG: emm_state_initial(): UNKNOWN_EVENT
 (emm_sm.c:25)
05/24 10:50:23.328: [emm] DEBUG: emm_state_de_registered(): ENTRY
 (emm_sm.c:44)
05/24 10:50:23.328: [emm] DEBUG: emm_state_de_registered(): MME_EVT_EMM_MESSAGE
 (emm_sm.c:44)
05/24 10:50:23.328: [emm] DEBUG: [EMM] Attach request[] (emm_sm.c:157)
05/24 10:50:23.328: [emm] DEBUG:     NAS_EPS TYPE[1] KSI[7] ATTACH[0x72] (emm_handler.c:45)
05/24 10:50:23.328: [emm] DEBUG:     OLD TAI[PLMN_ID:000000,TAC:0] (emm_handler.c:69)
05/24 10:50:23.328: [emm] DEBUG:     OLD E_CGI[PLMN_ID:000000,CELL_ID:0] (emm_handler.c:71)
05/24 10:50:23.328: [emm] DEBUG:     TAI[PLMN_ID:42f443,TAC:12594] (emm_handler.c:73)
05/24 10:50:23.328: [emm] DEBUG:     E_CGI[PLMN_ID:42f443,CELL_ID:513] (emm_handler.c:76)
05/24 10:50:23.328: [emm] DEBUG:     SERVED_TAI_INDEX[0] (emm_handler.c:94)
05/24 10:50:23.328: [emm] DEBUG:     IMSI[244341000000001] (emm_handler.c:136)
05/24 10:50:23.328: [mme] DEBUG: [MME] Authentication-Information-Request (mme_fd_path.c:41)
05/24 10:50:23.329: [emm] DEBUG: emm_state_de_registered(): EXIT
 (emm_sm.c:44)
05/24 10:50:23.329: [emm] DEBUG: emm_state_authentication(): ENTRY
 (emm_sm.c:346)
05/24 10:50:23.340: [mme] DEBUG: [MME] Authentication-Information-Answer (mme_fd_path.c:193)
05/24 10:50:23.340: [mme] DEBUG:     Result Code: 2001 (mme_fd_path.c:233)
05/24 10:50:23.341: [mme] DEBUG:     From 'hss.localdomain' (mme_fd_path.c:267)
05/24 10:50:23.341: [mme] DEBUG:          ('localdomain') (mme_fd_path.c:283)
05/24 10:50:23.341: [mme] DEBUG: mme_state_operational(): MME_EVT_S6A_MESSAGE
 (mme_sm.c:43)
05/24 10:50:23.341: [mme] DEBUG: [EMM] Authentication request (nas_path.c:143)
05/24 10:50:23.341: [mme] DEBUG:     IMSI[244341000000001] (nas_path.c:144)
05/24 10:50:23.341: [mme] DEBUG: [MME] Downlink NAS transport (s1ap_build.c:197)
05/24 10:50:23.341: [mme] DEBUG:     ENB_UE_S1AP_ID[1] MME_UE_S1AP_ID[1] (s1ap_build.c:242)
05/24 10:50:23.341: [mme] DEBUG:     IP[172.16.0.2] ENB_ID[2] (s1ap_path.c:70)
05/24 10:50:23.489: [mme] DEBUG: mme_state_operational(): MME_EVT_S1AP_MESSAGE
 (mme_sm.c:43)
05/24 10:50:23.490: [mme] DEBUG: s1ap_state_operational(): MME_EVT_S1AP_MESSAGE
 (s1ap_sm.c:34)
05/24 10:50:23.490: [mme] DEBUG: [MME] Uplink NAS transport (s1ap_handler.c:334)
05/24 10:50:23.490: [mme] DEBUG:     IP[172.16.0.2] ENB_ID[2] (s1ap_handler.c:353)
05/24 10:50:23.490: [mme] DEBUG:     ENB_UE_S1AP_ID[1] MME_UE_S1AP_ID[1] (s1ap_handler.c:360)
05/24 10:50:23.490: [mme] DEBUG: mme_state_operational(): MME_EVT_EMM_MESSAGE
 (mme_sm.c:43)
05/24 10:50:23.490: [emm] DEBUG: emm_state_authentication(): MME_EVT_EMM_MESSAGE
 (emm_sm.c:346)
05/24 10:50:23.490: [emm] DEBUG: [EMM] Authentication response (emm_sm.c:377)
05/24 10:50:23.490: [emm] DEBUG:     IMSI[244341000000001] (emm_sm.c:378)
05/24 10:50:23.490: [emm] DEBUG: emm_state_authentication(): EXIT
 (emm_sm.c:346)
05/24 10:50:23.490: [emm] DEBUG: emm_state_security_mode(): ENTRY
 (emm_sm.c:505)
05/24 10:50:23.490: [emm] DEBUG: [EMM] Security mode command (emm_build.c:218)
05/24 10:50:23.490: [emm] DEBUG:     IMSI[244341000000001] (emm_build.c:219)
05/24 10:50:23.491: [emm] DEBUG:     Replayed UE SEC[LEN:5 EEA:0xe0 EIA:0x60 UEA:0xc0 UIA:0x40 GEA:0x70] (emm_build.c:288)
05/24 10:50:23.491: [emm] DEBUG:     Selected[Integrity:0x1 Encrypt:0x0] (emm_build.c:290)
05/24 10:50:23.492: [mme] DEBUG: [MME] Downlink NAS transport (s1ap_build.c:197)
05/24 10:50:23.492: [mme] DEBUG:     ENB_UE_S1AP_ID[1] MME_UE_S1AP_ID[1] (s1ap_build.c:242)
05/24 10:50:23.492: [mme] DEBUG:     IP[172.16.0.2] ENB_ID[2] (s1ap_path.c:70)
05/24 10:50:23.509: [mme] DEBUG: mme_state_operational(): MME_EVT_S1AP_MESSAGE
 (mme_sm.c:43)
05/24 10:50:23.509: [mme] DEBUG: s1ap_state_operational(): MME_EVT_S1AP_MESSAGE
 (s1ap_sm.c:34)
05/24 10:50:23.509: [mme] DEBUG: [MME] Uplink NAS transport (s1ap_handler.c:334)
05/24 10:50:23.509: [mme] DEBUG:     IP[172.16.0.2] ENB_ID[2] (s1ap_handler.c:353)
05/24 10:50:23.510: [mme] DEBUG:     ENB_UE_S1AP_ID[1] MME_UE_S1AP_ID[1] (s1ap_handler.c:360)
05/24 10:50:23.510: [mme] DEBUG: mme_state_operational(): MME_EVT_EMM_MESSAGE
 (mme_sm.c:43)
05/24 10:50:23.510: [emm] DEBUG: emm_state_security_mode(): MME_EVT_EMM_MESSAGE
 (emm_sm.c:505)
05/24 10:50:23.510: [emm] DEBUG: [EMM] Security mode complete (emm_sm.c:537)
05/24 10:50:23.511: [emm] DEBUG:     IMSI[244341000000001] (emm_sm.c:538)
05/24 10:50:23.511: [mme] DEBUG: [MME] Update-Location-Request (mme_fd_path.c:462)
05/24 10:50:23.511: [emm] DEBUG: emm_state_security_mode(): EXIT
 (emm_sm.c:505)
05/24 10:50:23.511: [emm] DEBUG: emm_state_initial_context_setup(): ENTRY
 (emm_sm.c:642)
05/24 10:50:23.518: [mme] DEBUG: [MME] Update-Location-Answer (mme_fd_path.c:599)
05/24 10:50:23.518: [mme] DEBUG:     Result Code: 2001 (mme_fd_path.c:639)
05/24 10:50:23.518: [mme] DEBUG:     From 'hss.localdomain' (mme_fd_path.c:673)
05/24 10:50:23.518: [mme] DEBUG:          ('localdomain') (mme_fd_path.c:689)
05/24 10:50:23.518: [mme] DEBUG: mme_state_operational(): MME_EVT_S6A_MESSAGE
 (mme_sm.c:43)
05/24 10:50:23.519: [mme] DEBUG: mme_state_operational(): MME_EVT_ESM_MESSAGE
 (mme_sm.c:43)
05/24 10:50:23.519: [esm] DEBUG: esm_state_initial(): UNKNOWN_EVENT
 (esm_sm.c:20)
05/24 10:50:23.519: [esm] DEBUG: esm_state_inactive(): ENTRY
 (esm_sm.c:42)
05/24 10:50:23.519: [esm] DEBUG: esm_state_inactive(): MME_EVT_ESM_MESSAGE
 (esm_sm.c:42)
05/24 10:50:23.519: [esm] DEBUG: [ESM] PDN Connectivity request (esm_sm.c:70)
05/24 10:50:23.519: [esm] DEBUG:     IMSI[244341000000001] PTI[4] EBI[5] (esm_sm.c:72)
05/24 10:50:23.519: [esm] DEBUG:     EIT(ESM information transfer)[1] (esm_handler.c:43)
05/24 10:50:23.519: [esm] DEBUG: [ESM] ESM information request (esm_build.c:65)
05/24 10:50:23.519: [esm] DEBUG:     IMSI[244341000000001] PTI[4] EBI[5] (esm_build.c:67)
05/24 10:50:23.520: [mme] DEBUG: [MME] Downlink NAS transport (s1ap_build.c:197)
05/24 10:50:23.520: [mme] DEBUG:     ENB_UE_S1AP_ID[1] MME_UE_S1AP_ID[1] (s1ap_build.c:242)
05/24 10:50:23.520: [mme] DEBUG:     IP[172.16.0.2] ENB_ID[2] (s1ap_path.c:70)
05/24 10:50:23.537: [mme] DEBUG: mme_state_operational(): MME_EVT_S1AP_MESSAGE
 (mme_sm.c:43)
05/24 10:50:23.537: [mme] DEBUG: s1ap_state_operational(): MME_EVT_S1AP_MESSAGE
 (s1ap_sm.c:34)
05/24 10:50:23.537: [mme] DEBUG: [MME] Uplink NAS transport (s1ap_handler.c:334)
05/24 10:50:23.538: [mme] DEBUG:     IP[172.16.0.2] ENB_ID[2] (s1ap_handler.c:353)
05/24 10:50:23.538: [mme] DEBUG:     ENB_UE_S1AP_ID[1] MME_UE_S1AP_ID[1] (s1ap_handler.c:360)
05/24 10:50:23.538: [mme] DEBUG: mme_state_operational(): MME_EVT_ESM_MESSAGE
 (mme_sm.c:43)
05/24 10:50:23.539: [esm] DEBUG: esm_state_inactive(): MME_EVT_ESM_MESSAGE
 (esm_sm.c:42)
05/24 10:50:23.539: [esm] DEBUG: [ESM] ESM information response (esm_sm.c:84)
05/24 10:50:23.539: [esm] DEBUG:     IMSI[244341000000001] PTI[4] EBI[5] (esm_sm.c:86)
05/24 10:50:23.539: [esm] DEBUG:     APN[safenet] (esm_handler.c:130)
05/24 10:50:23.539: [mme] DEBUG: [MME] Create Session Request (mme_s11_build.c:40)
05/24 10:50:23.539: [mme] DEBUG:     MME_S11_TEID[1] SGW_S11_TEID[0] (mme_s11_build.c:42)
05/24 10:50:23.539: [gtp] DEBUG: [1] LOCAL  UPD TX-32  peer [192.168.1.122]:2123 (gtp_xact.c:183)
05/24 10:50:23.539: [gtp] DEBUG: [1] LOCAL  Create  peer [192.168.1.122]:2123 (gtp_xact.c:115)
05/24 10:50:23.539: [gtp] DEBUG: [1] LOCAL  Commit  peer [192.168.1.122]:2123 (gtp_xact.c:424)
05/24 10:50:23.561: [mme] DEBUG: mme_state_operational(): MME_EVT_S11_MESSAGE
 (mme_sm.c:43)
05/24 10:50:23.562: [gtp] DEBUG: [1] LOCAL  Find    peer [192.168.1.122]:2123 (gtp_xact.c:717)
05/24 10:50:23.562: [gtp] DEBUG: [1] LOCAL  Receive peer [192.168.1.122]:2123 (gtp_xact.c:606)
05/24 10:50:23.562: [gtp] DEBUG: [1] LOCAL  UPD RX-33  peer [192.168.1.122]:2123 (gtp_xact.c:258)
05/24 10:50:23.562: [mme] DEBUG: [MME] Create Session Response (mme_s11_handler.c:32)
05/24 10:50:23.562: [mme] DEBUG:     MME_S11_TEID[1] SGW_S11_TEID[1] (mme_s11_handler.c:88)
05/24 10:50:23.562: [mme] DEBUG:     ENB_S1U_TEID[0] SGW_S1U_TEID[1] (mme_s11_handler.c:90)
05/24 10:50:23.562: [gtp] DEBUG: [1] LOCAL  Commit  peer [192.168.1.122]:2123 (gtp_xact.c:424)
05/24 10:50:23.562: [gtp] DEBUG: [1] LOCAL  Delete  peer [192.168.1.122]:2123 (gtp_xact.c:760)
05/24 10:50:23.562: [esm] DEBUG: [ESM] Activate default bearer context request (esm_build.c:116)
05/24 10:50:23.562: [esm] DEBUG:     IMSI[244341000000001] PTI[4] EBI[5] (esm_build.c:118)
05/24 10:50:23.562: [esm] DEBUG:     APN[safenet] (esm_build.c:142)
05/24 10:50:23.562: [esm] DEBUG:     IPv4 (esm_build.c:149)
05/24 10:50:23.563: [emm] DEBUG: [EMM] Attach accept (emm_build.c:27)
05/24 10:50:23.563: [emm] DEBUG:     TAI[PLMN_ID:42f443,TAC:12594] (emm_build.c:44)
05/24 10:50:23.563: [emm] DEBUG:     E_CGI[PLMN_ID:42f443,CELL_ID:513] (emm_build.c:47)
05/24 10:50:23.563: [emm] DEBUG:     SERVED_TAI_INDEX[0] (emm_build.c:49)
05/24 10:50:23.563: [emm] DEBUG:     [V] GUTI[G:2,C:1,M_TMSI:0xe90056d0] IMSI:[244341000000001] (emm_build.c:62)
05/24 10:50:23.564: [mme] DEBUG: [MME] Initial context setup request (s1ap_build.c:292)
05/24 10:50:23.564: [mme] DEBUG:     ENB_UE_S1AP_ID[1] MME_UE_S1AP_ID[1] (s1ap_build.c:370)
05/24 10:50:23.564: [mme] DEBUG:     EBI[5] QCI[9] SGW-S1U-TEID[1] (s1ap_build.c:407)
05/24 10:50:23.564: [core] DEBUG:     IPv4[172.16.0.1] (s1ap_conv.c:164)
05/24 10:50:23.564: [mme] DEBUG:     IP[172.16.0.2] ENB_ID[2] (s1ap_path.c:70)
05/24 10:50:23.607: [mme] DEBUG: mme_state_operational(): MME_EVT_S1AP_MESSAGE
 (mme_sm.c:43)
05/24 10:50:23.607: [mme] DEBUG: s1ap_state_operational(): MME_EVT_S1AP_MESSAGE
 (s1ap_sm.c:34)
05/24 10:50:23.607: [mme] DEBUG: [MME] Initial context setup response (s1ap_handler.c:453)
05/24 10:50:23.607: [mme] DEBUG:     IP[172.16.0.2] ENB_ID[2] (s1ap_handler.c:473)
05/24 10:50:23.607: [mme] DEBUG:     ENB_UE_S1AP_ID[1] MME_UE_S1AP_ID[1] (s1ap_handler.c:482)
05/24 10:50:23.607: [core] DEBUG:     IPv4[172.16.0.2] (s1ap_conv.c:128)
05/24 10:50:23.608: [mme] DEBUG:     EBI[5] ENB-S1U-TEID[1] (s1ap_handler.c:512)
05/24 10:50:23.608: [mme] DEBUG: mme_state_operational(): MME_EVT_S1AP_MESSAGE
 (mme_sm.c:43)
05/24 10:50:23.608: [mme] DEBUG: s1ap_state_operational(): MME_EVT_S1AP_MESSAGE
 (s1ap_sm.c:34)
05/24 10:50:23.608: [mme] DEBUG: [MME] UE capability info indication (s1ap_handler.c:391)
05/24 10:50:23.608: [mme] DEBUG:     IP[172.16.0.2] ENB_ID[2] (s1ap_handler.c:410)
05/24 10:50:23.608: [mme] DEBUG:     ENB_UE_S1AP_ID[1] MME_UE_S1AP_ID[1] (s1ap_handler.c:417)
05/24 10:50:23.629: [mme] DEBUG: mme_state_operational(): MME_EVT_S1AP_MESSAGE
 (mme_sm.c:43)
05/24 10:50:23.629: [mme] DEBUG: s1ap_state_operational(): MME_EVT_S1AP_MESSAGE
 (s1ap_sm.c:34)
05/24 10:50:23.630: [mme] DEBUG: [MME] Uplink NAS transport (s1ap_handler.c:334)
05/24 10:50:23.630: [mme] DEBUG:     IP[172.16.0.2] ENB_ID[2] (s1ap_handler.c:353)
05/24 10:50:23.630: [mme] DEBUG:     ENB_UE_S1AP_ID[1] MME_UE_S1AP_ID[1] (s1ap_handler.c:360)
05/24 10:50:23.630: [mme] DEBUG: mme_state_operational(): MME_EVT_EMM_MESSAGE
 (mme_sm.c:43)
05/24 10:50:23.630: [emm] DEBUG: emm_state_initial_context_setup(): MME_EVT_EMM_MESSAGE
 (emm_sm.c:642)
05/24 10:50:23.630: [emm] DEBUG: [EMM] Attach complete (emm_sm.c:666)
05/24 10:50:23.631: [emm] DEBUG:     IMSI[244341000000001] (emm_sm.c:667)
05/24 10:50:23.631: [emm] DEBUG:     GMT Time[Y:M:D H:M:S GMT] - 119:4:24, 7:50:23, 0 (emm_handler.c:196)
05/24 10:50:23.631: [emm] DEBUG:     LOCAL Time[Y:M:D H:M:S GMT] - 119:4:24, 10:50:23, 10800 (emm_handler.c:200)
05/24 10:50:23.631: [emm] DEBUG:     Timezone:0x21 (emm_handler.c:237)
05/24 10:50:23.632: [mme] DEBUG: [MME] Downlink NAS transport (s1ap_build.c:197)
05/24 10:50:23.632: [mme] DEBUG:     ENB_UE_S1AP_ID[1] MME_UE_S1AP_ID[1] (s1ap_build.c:242)
05/24 10:50:23.632: [mme] DEBUG:     IP[172.16.0.2] ENB_ID[2] (s1ap_path.c:70)
05/24 10:50:23.632: [emm] DEBUG: [EMM] EMM information (emm_handler.c:263)
05/24 10:50:23.632: [emm] DEBUG:     IMSI[244341000000001] (emm_handler.c:264)
05/24 10:50:23.632: [emm] DEBUG: emm_state_initial_context_setup(): EXIT
 (emm_sm.c:642)
05/24 10:50:23.632: [emm] DEBUG: emm_state_registered(): ENTRY
 (emm_sm.c:54)
05/24 10:50:23.632: [mme] DEBUG: mme_state_operational(): MME_EVT_ESM_MESSAGE
 (mme_sm.c:43)
05/24 10:50:23.632: [esm] DEBUG: esm_state_inactive(): MME_EVT_ESM_MESSAGE
 (esm_sm.c:42)
05/24 10:50:23.632: [esm] DEBUG: [ESM] Activate default EPS bearer context accept (esm_sm.c:99)
05/24 10:50:23.632: [esm] DEBUG:     IMSI[244341000000001] PTI[4] EBI[5] (esm_sm.c:101)
05/24 10:50:23.632: [mme] DEBUG: [MME] Modifty Bearer Request (mme_s11_build.c:246)
05/24 10:50:23.632: [mme] DEBUG:     MME_S11_TEID[1] SGW_S11_TEID[1] (mme_s11_build.c:248)
05/24 10:50:23.633: [mme] DEBUG:     ENB_S1U_TEID[1] SGW_S1U_TEID[1] (mme_s11_build.c:250)
05/24 10:50:23.633: [gtp] DEBUG: [2] LOCAL  UPD TX-34  peer [192.168.1.122]:2123 (gtp_xact.c:183)
05/24 10:50:23.633: [gtp] DEBUG: [2] LOCAL  Create  peer [192.168.1.122]:2123 (gtp_xact.c:115)
05/24 10:50:23.633: [gtp] DEBUG: [2] LOCAL  Commit  peer [192.168.1.122]:2123 (gtp_xact.c:424)
05/24 10:50:23.633: [esm] DEBUG: esm_state_inactive(): EXIT
 (esm_sm.c:42)
05/24 10:50:23.633: [esm] DEBUG: esm_state_active(): ENTRY
 (esm_sm.c:161)
05/24 10:50:23.634: [mme] DEBUG: mme_state_operational(): MME_EVT_S11_MESSAGE
 (mme_sm.c:43)
05/24 10:50:23.634: [gtp] DEBUG: [2] LOCAL  Find    peer [192.168.1.122]:2123 (gtp_xact.c:717)
05/24 10:50:23.634: [gtp] DEBUG: [2] LOCAL  Receive peer [192.168.1.122]:2123 (gtp_xact.c:606)
05/24 10:50:23.634: [gtp] DEBUG: [2] LOCAL  UPD RX-35  peer [192.168.1.122]:2123 (gtp_xact.c:258)
05/24 10:50:23.634: [mme] DEBUG: [MME] Modify Bearer Response (mme_s11_handler.c:122)
05/24 10:50:23.634: [mme] DEBUG:     MME_S11_TEID[1] SGW_S11_TEID[1] (mme_s11_handler.c:124)
05/24 10:50:23.634: [gtp] DEBUG: [2] LOCAL  Commit  peer [192.168.1.122]:2123 (gtp_xact.c:424)
05/24 10:50:23.634: [gtp] DEBUG: [2] LOCAL  Delete  peer [192.168.1.122]:2123 (gtp_xact.c:760)

All log files attached

Log files show that there is a GPTU trafic coming from SGW to PGW, let see it with tcpdump:

root@apu02:/var/log/nextepc# tcpdump -i enp2s0 udp -n
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on enp2s0, link-type EN10MB (Ethernet), capture size 262144 bytes
11:04:08.349298 IP 192.168.88.1.56009 > 255.255.255.255.5678: UDP, length 111
11:04:16.176267 IP 172.16.0.2.2152 > 172.16.0.1.2152: UDP, length 80
11:04:16.177244 IP 172.16.0.2.2152 > 172.16.0.1.2152: UDP, length 70
11:04:16.177291 IP 172.16.0.2.2152 > 172.16.0.1.2152: UDP, length 83
11:04:17.696425 IP 172.16.0.2.2152 > 172.16.0.1.2152: UDP, length 83
11:04:21.156381 IP 172.16.0.2.2152 > 172.16.0.1.2152: UDP, length 80
11:04:21.157365 IP 172.16.0.2.2152 > 172.16.0.1.2152: UDP, length 83
11:04:21.157407 IP 172.16.0.2.2152 > 172.16.0.1.2152: UDP, length 75
11:04:22.676342 IP 172.16.0.2.2152 > 172.16.0.1.2152: UDP, length 83
11:04:25.716381 IP 172.16.0.2.2152 > 172.16.0.1.2152: UDP, length 73
11:04:26.176316 IP 172.16.0.2.2152 > 172.16.0.1.2152: UDP, length 80
11:04:26.176400 IP 172.16.0.2.2152 > 172.16.0.1.2152: UDP, length 83
11:04:26.176527 IP 172.16.0.2.2152 > 172.16.0.1.2152: UDP, length 75
11:04:26.177285 IP 172.16.0.2.2152 > 172.16.0.1.2152: UDP, length 81
11:04:26.236298 IP 172.16.0.2.2152 > 172.16.0.1.2152: UDP, length 79
11:04:26.349403 IP 172.16.0.2.2152 > 172.16.0.1.2152: UDP, length 72
11:04:27.696370 IP 172.16.0.2.2152 > 172.16.0.1.2152: UDP, length 83
11:04:27.796279 IP 172.16.0.2.2152 > 172.16.0.1.2152: UDP, length 92
11:04:28.816415 IP 172.16.0.2.2152 > 172.16.0.1.2152: UDP, length 92

Than another interface

root@apu02:/var/log/nextepc# tcpdump -i enp1s0 udp -n
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on enp1s0, link-type EN10MB (Ethernet), capture size 262144 bytes
11:05:39.396903 IP 172.16.0.1.2152 > 192.168.1.144.2152: UDP, length 83
11:05:39.776762 IP 172.16.0.1.2152 > 192.168.1.144.2152: UDP, length 83
11:05:40.416923 IP 172.16.0.1.2152 > 192.168.1.144.2152: UDP, length 76
11:05:41.296825 IP 172.16.0.1.2152 > 192.168.1.144.2152: UDP, length 81
11:05:41.297641 IP 172.16.0.1.2152 > 192.168.1.144.2152: UDP, length 81
11:05:41.305610 IP 172.16.0.1.2152 > 192.168.1.144.2152: UDP, length 81
11:05:41.616806 IP 172.16.0.1.2152 > 192.168.1.144.2152: UDP, length 72
11:05:41.617038 IP 172.16.0.1.2152 > 192.168.1.144.2152: UDP, length 72
11:05:42.016795 IP 172.16.0.1.2152 > 192.168.1.144.2152: UDP, length 81
11:05:42.496589 IP 172.16.0.1.2152 > 192.168.1.144.2152: UDP, length 83
^C
10 packets captured

That was SGW, lets check PGW

1 packet dropped by kernel
root@APU3:/etc/nextepc# tcpdump -i enp1s0 udp -n
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on enp1s0, link-type EN10MB (Ethernet), capture size 262144 bytes
11:07:00.492844 IP 172.16.0.1.2152 > 192.168.1.144.2152: UDP, length 73
11:07:00.972479 IP 172.16.0.1.2152 > 192.168.1.144.2152: UDP, length 83
11:07:01.632546 IP 172.16.0.1.2152 > 192.168.1.144.2152: UDP, length 72
11:07:01.633160 IP 172.16.0.1.2152 > 192.168.1.144.2152: UDP, length 72
11:07:01.772406 IP 172.16.0.1.2152 > 192.168.1.144.2152: UDP, length 80
11:07:02.572766 IP 172.16.0.1.2152 > 192.168.1.144.2152: UDP, length 78
11:07:02.652448 IP 172.16.0.1.2152 > 192.168.1.144.2152: UDP, length 83
11:07:05.472693 IP 172.16.0.1.2152 > 192.168.1.144.2152: UDP, length 73
11:07:06.012655 IP 172.16.0.1.2152 > 192.168.1.144.2152: UDP, length 83

Ok, we can see that GTPU traffic is coming from SGW to PGW

lets check tunnel unterface

root@APU3:/etc/nextepc# ifconfig pgwtun
pgwtun: flags=4305<UP,POINTOPOINT,RUNNING,NOARP,MULTICAST>  mtu 1500
        inet 45.45.0.1  netmask 255.255.0.0  destination 45.45.0.1
        inet6 fe80::77e:d2c0:bd62:99a  prefixlen 64  scopeid 0x20<link>
        inet6 cafe::1  prefixlen 64  scopeid 0x0<global>
        unspec 00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00  txqueuelen 500  (UNSPEC)
        RX packets 441  bytes 32994 (32.9 KB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 238  bytes 13328 (13.3 KB)
        TX errors 0  dropped 4 overruns 0  carrier 0  collisions 0

root@APU3:/etc/nextepc#
root@APU3:/etc/nextepc#
root@APU3:/etc/nextepc# tcpdump -i pgwtun udp
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on pgwtun, link-type RAW (Raw IP), capture size 262144 bytes

There is no any traffic coming from tunnel, but it should be Maybe the problem is NAT, let check nat table

root@APU3:/etc/nextepc# conntrack -L
tcp      6 270830 ESTABLISHED src=172.16.0.20 dst=172.16.0.20 sport=36602 dport=3868 src=172.16.0.20 dst=172.16.0.20 sport=3868 dport=36602 [ASSURED] mark=0 use=1
tcp      6 430390 ESTABLISHED src=192.168.1.121 dst=192.168.1.144 sport=27345 dport=22 src=192.168.1.144 dst=192.168.1.121 sport=22 dport=27345 [ASSURED] mark=0 use=1
tcp      6 299 ESTABLISHED src=192.168.1.144 dst=192.168.1.121 sport=22 dport=27397 src=192.168.1.121 dst=192.168.1.144 sport=27397 dport=22 [ASSURED] mark=0 use=1
tcp      6 431998 ESTABLISHED src=127.0.0.1 dst=127.0.0.5 sport=47018 dport=3868 src=127.0.0.5 dst=127.0.0.1 sport=3868 dport=47018 [ASSURED] mark=0 use=1
unknown  2 523 src=192.168.1.1 dst=224.0.0.1 [UNREPLIED] src=224.0.0.1 dst=192.168.1.1 mark=0 use=1
tcp      6 431730 ESTABLISHED src=172.16.0.20 dst=172.16.0.1 sport=55096 dport=27017 src=172.16.0.1 dst=172.16.0.20 sport=27017 dport=55096 [ASSURED] mark=0 use=1
conntrack v1.4.4 (conntrack-tools): 6 flow entries have been shown.

There are some connections, nat is working I attached PGW and SGW pcap files.

Also try to restart all nat functions with the following workaround

WAN=enp1s0 echo 1 > /proc/sys/net/ipv4/ip_forward

iptables -F iptables -F -t nat iptables -t nat -A POSTROUTING -o $WAN -j MASQUERADE iptables -I INPUT -i pgwtun -j ACCEPT -m comment --comment "Accept pgwtun incoming"

systemctl restart systemd-udevd systemctl restart systemd-networkd

sysctl -p /etc/sysctl.d/30-nextepc.conf

ifconfig pgwtun down ifconfig pgwtun up

if trying to restart networkd when pgwd is working got an error

root@APU3:/etc/nextepc# systemctl restart systemd-networkd Job for systemd-networkd.service failed because the control process exited with error code. See "systemctl status systemd-networkd.service" and "journalctl -xe" for details. root@APU3:/etc/nextepc#

Also have the following issues in systemd-networkd.service journal 


root@APU3:/etc/nextepc# journalctl -fn 100 -u systemd-networkd.service
-- Logs begin at Fri 2019-05-17 12:12:09 EEST. --
May 24 10:13:26 APU3 systemd[1]: systemd-networkd.service: Scheduled restart job, restart counter is at 4.
May 24 10:13:26 APU3 systemd[1]: Stopped Network Service.
May 24 10:13:26 APU3 systemd[1]: Starting Network Service...
May 24 10:13:26 APU3 systemd-networkd[12540]: pgwtun: TUNSETIFF failed on tun dev: Device or resource busy
May 24 10:13:26 APU3 systemd-networkd[12540]: Could not load configuration files: Device or resource busy
May 24 10:13:26 APU3 systemd[1]: systemd-networkd.service: Main process exited, code=exited, status=1/FAILURE
May 24 10:13:26 APU3 systemd[1]: systemd-networkd.service: Failed with result 'exit-code'.
May 24 10:13:26 APU3 systemd[1]: Failed to start Network Service.
May 24 10:13:26 APU3 systemd[1]: systemd-networkd.service: Service has no hold-off time, scheduling restart.
May 24 10:13:26 APU3 systemd[1]: systemd-networkd.service: Scheduled restart job, restart counter is at 5.
May 24 10:13:26 APU3 systemd[1]: Stopped Network Service.
May 24 10:13:26 APU3 systemd[1]: systemd-networkd.service: Start request repeated too quickly.
May 24 10:13:26 APU3 systemd[1]: systemd-networkd.service: Failed with result 'exit-code'.
May 24 10:13:26 APU3 systemd[1]: Failed to start Network Service.
May 24 10:13:55 APU3 systemd[1]: Starting Network Service...
May 24 10:13:55 APU3 systemd-networkd[12616]: pgwtun: Gained IPv6LL
May 24 10:13:55 APU3 systemd-networkd[12616]: enp2s0: Gained IPv6LL
May 24 10:13:55 APU3 systemd-networkd[12616]: enp1s0: Gained IPv6LL
May 24 10:13:55 APU3 systemd-networkd[12616]: Enumeration completed
May 24 10:13:55 APU3 systemd[1]: Started Network Service.
May 24 10:13:55 APU3 systemd-networkd[12616]: enp2s0: Link is not managed by us
May 24 10:13:55 APU3 systemd-networkd[12616]: enp1s0: Link is not managed by us
May 24 10:13:55 APU3 systemd-networkd[12616]: lo: Link is not managed by us
May 24 10:13:55 APU3 systemd-networkd[12616]: enp3s0: Link is not managed by us
May 24 10:13:55 APU3 systemd-networkd[12616]: enp1s0: Link is not managed by us
May 24 10:13:55 APU3 systemd-networkd[12616]: lo: Link is not managed by us
May 24 10:13:55 APU3 systemd-networkd[12616]: enp3s0: Link is not managed by us
May 24 10:13:55 APU3 systemd-networkd[12616]: lo: Link is not managed by us
May 24 10:13:55 APU3 systemd-networkd[12616]: enp3s0: Link is not managed by us
May 24 10:13:55 APU3 systemd-networkd[12616]: pgwtun: Configured
May 24 10:13:55 APU3 systemd-networkd[12616]: enp2s0: Configured
May 24 10:13:56 APU3 systemd-networkd[12616]: pgwtun: Lost carrier
May 24 10:13:58 APU3 systemd-networkd[12616]: enp1s0: DHCPv4 address 192.168.1.144/24 via 192.168.1.1
May 24 10:13:58 APU3 systemd-networkd[12616]: enp1s0: Configured
May 24 10:13:58 APU3 systemd-networkd[12616]: Could not set hostname: The name org.freedesktop.PolicyKit1 was not provided by any .service files
May 24 10:14:45 APU3 systemd-networkd[12616]: pgwtun: Gained carrier
May 24 10:14:45 APU3 systemd-networkd[12616]: pgwtun: Gained IPv6LL
May 24 10:14:45 APU3 systemd-networkd[12616]: pgwtun: Configured
May 24 10:20:43 APU3 systemd-networkd[12616]: pgwtun: Lost carrier
May 24 10:20:46 APU3 systemd-networkd[12616]: pgwtun: Gained carrier
May 24 10:20:46 APU3 systemd-networkd[12616]: pgwtun: Configured
May 24 10:20:49 APU3 systemd-networkd[12616]: pgwtun: Lost carrier
May 24 10:20:51 APU3 systemd-networkd[12616]: pgwtun: Gained carrier
May 24 10:20:51 APU3 systemd-networkd[12616]: pgwtun: Configured
May 24 10:24:35 APU3 systemd-networkd[12616]: pgwtun: Lost carrier
May 24 10:24:36 APU3 systemd-networkd[12616]: pgwtun: Gained carrier
May 24 10:24:36 APU3 systemd-networkd[12616]: pgwtun: Configured
May 24 10:44:42 APU3 systemd-networkd[12616]: pgwtun: Lost carrier
May 24 10:45:25 APU3 systemd-networkd[12616]: pgwtun: Gained carrier
May 24 10:45:25 APU3 systemd-networkd[12616]: pgwtun: Configured
May 24 11:19:17 APU3 systemd[1]: Stopping Network Service...
May 24 11:19:17 APU3 systemd[1]: Stopped Network Service.
May 24 11:19:17 APU3 systemd[1]: Starting Network Service...
May 24 11:19:17 APU3 systemd-networkd[13252]: pgwtun: TUNSETIFF failed on tun dev: Device or resource busy
May 24 11:19:17 APU3 systemd-networkd[13252]: Could not load configuration files: Device or resource busy
May 24 11:19:17 APU3 systemd[1]: systemd-networkd.service: Main process exited, code=exited, status=1/FAILURE
May 24 11:19:17 APU3 systemd[1]: systemd-networkd.service: Failed with result 'exit-code'.
May 24 11:19:17 APU3 systemd[1]: Failed to start Network Service.
May 24 11:19:17 APU3 systemd[1]: systemd-networkd.service: Service has no hold-off time, scheduling restart.
May 24 11:19:17 APU3 systemd[1]: systemd-networkd.service: Scheduled restart job, restart counter is at 1.
May 24 11:19:17 APU3 systemd[1]: Stopped Network Service.
May 24 11:19:17 APU3 systemd[1]: Starting Network Service...
May 24 11:19:17 APU3 systemd-networkd[13254]: pgwtun: TUNSETIFF failed on tun dev: Device or resource busy
May 24 11:19:17 APU3 systemd-networkd[13254]: Could not load configuration files: Device or resource busy
May 24 11:19:17 APU3 systemd[1]: systemd-networkd.service: Main process exited, code=exited, status=1/FAILURE
May 24 11:19:17 APU3 systemd[1]: systemd-networkd.service: Failed with result 'exit-code'.
May 24 11:19:17 APU3 systemd[1]: Failed to start Network Service.
May 24 11:19:17 APU3 systemd[1]: systemd-networkd.service: Service has no hold-off time, scheduling restart.
May 24 11:19:17 APU3 systemd[1]: systemd-networkd.service: Scheduled restart job, restart counter is at 2.
May 24 11:19:17 APU3 systemd[1]: Stopped Network Service.
May 24 11:19:17 APU3 systemd[1]: Starting Network Service...
May 24 11:19:17 APU3 systemd-networkd[13255]: pgwtun: TUNSETIFF failed on tun dev: Device or resource busy
May 24 11:19:17 APU3 systemd-networkd[13255]: Could not load configuration files: Device or resource busy
May 24 11:19:17 APU3 systemd[1]: systemd-networkd.service: Main process exited, code=exited, status=1/FAILURE
May 24 11:19:17 APU3 systemd[1]: systemd-networkd.service: Failed with result 'exit-code'.
May 24 11:19:17 APU3 systemd[1]: Failed to start Network Service.
May 24 11:19:17 APU3 systemd[1]: systemd-networkd.service: Service has no hold-off time, scheduling restart.
May 24 11:19:17 APU3 systemd[1]: systemd-networkd.service: Scheduled restart job, restart counter is at 3.
May 24 11:19:17 APU3 systemd[1]: Stopped Network Service.
May 24 11:19:17 APU3 systemd[1]: Starting Network Service...
May 24 11:19:17 APU3 systemd-networkd[13257]: pgwtun: TUNSETIFF failed on tun dev: Device or resource busy
May 24 11:19:17 APU3 systemd-networkd[13257]: Could not load configuration files: Device or resource busy
May 24 11:19:17 APU3 systemd[1]: systemd-networkd.service: Main process exited, code=exited, status=1/FAILURE
May 24 11:19:17 APU3 systemd[1]: systemd-networkd.service: Failed with result 'exit-code'.
May 24 11:19:17 APU3 systemd[1]: Failed to start Network Service.
May 24 11:19:17 APU3 systemd[1]: systemd-networkd.service: Service has no hold-off time, scheduling restart.
May 24 11:19:17 APU3 systemd[1]: systemd-networkd.service: Scheduled restart job, restart counter is at 4.
May 24 11:19:17 APU3 systemd[1]: Stopped Network Service.
May 24 11:19:17 APU3 systemd[1]: Starting Network Service...
May 24 11:19:17 APU3 systemd-networkd[13259]: pgwtun: TUNSETIFF failed on tun dev: Device or resource busy
May 24 11:19:17 APU3 systemd-networkd[13259]: Could not load configuration files: Device or resource busy
May 24 11:19:17 APU3 systemd[1]: systemd-networkd.service: Main process exited, code=exited, status=1/FAILURE
May 24 11:19:17 APU3 systemd[1]: systemd-networkd.service: Failed with result 'exit-code'.
May 24 11:19:17 APU3 systemd[1]: Failed to start Network Service.
May 24 11:19:17 APU3 systemd[1]: systemd-networkd.service: Service has no hold-off time, scheduling restart.
May 24 11:19:17 APU3 systemd[1]: systemd-networkd.service: Scheduled restart job, restart counter is at 5.
May 24 11:19:17 APU3 systemd[1]: Stopped Network Service.
May 24 11:19:17 APU3 systemd[1]: systemd-networkd.service: Start request repeated too quickly.
May 24 11:19:17 APU3 systemd[1]: systemd-networkd.service: Failed with result 'exit-code'.
May 24 11:19:17 APU3 systemd[1]: Failed to start Network Service.

Both hosts are

root@APU3:/etc/nextepc# lsb_release -a No LSB modules are available. Distributor ID: Ubuntu Description: Ubuntu 18.04.2 LTS Release: 18.04 Codename: bionic root@APU3:/etc/nextepc#

Just dont know how to troubleshoot this further ((

logs.zip

acetcom commented 5 years ago

Your PGW daemon did not receive GTP-U packet even though wireshark can capture the packet (172.16.0.1.2152 > 192.168.1.144.2152) in PGW machine.

We need to find out why nextepc-pgwd cannot see the packet.

The correct result might be like the followings.

05/25 20:26:13.987: [pgw] DEBUG: [PGW] RECV GPU-U from SGW : TEID[0x1] (pgw_gtp_path.c:135)

If we succeeded to see the above line, nextepc will forward the packet to the pgwtun. And then pgwtun will receive returned packet like the followings.

05/25 20:26:13.988: [pgw] DEBUG: [PGW] PROTO:1 SRC:2d2d0001 2d2d0002 0000b46d c8da82b7 (pgw_ipfw.c:290)
05/25 20:26:13.988: [pgw] DEBUG: [PGW] HLEN:20  DST:2d2d0002 0000b46d c8da82b7 00000000 (pgw_ipfw.c:293)
05/25 20:26:13.988: [pgw] DEBUG: [PGW] PAA IPv4:45.45.0.2 (pgw_ipfw.c:308)
05/25 20:26:13.989: [pgw] DEBUG: [PGW] Found Session : EBI[5] (pgw_ipfw.c:324)
05/25 20:26:13.989: [pgw] DEBUG: [PGW] SEND GPU-U to SGW[127.0.0.2] : TEID[0x2] (pgw_gtp_path.c:450)
05/25 20:26:13.990: [sgw] DEBUG: [SGW] RECV GPU-U from [127.0.0.3] : TEID[0x2] (sgw_gtp_path.c:98)
05/25 20:26:13.990: [sgw] DEBUG: [SGW] SEND GPU-U to ENB[127.0.0.5]: TEID[0x1] (sgw_gtp_path.c:166)

At this point, I have one questions. Why do you need to set PGW GTP-C/GTP-U Address with 191.168.1.144. Basically, you don't have to this IP with internet connected interface. You can use it with private or loopback IP address. TUN device(pgwtun) can solve all remained part.

How about changing the pgw.conf as below?

pgw:
    freeDiameter: pgw.conf
    gtpc:
      addr: 172.16.0.20
    gtpu:
      addr: 172.16.0.20
    ue_pool:
      - addr: 45.45.0.1/16
      - addr: cafe::1/64

Good luck with you!

sgww2 commented 5 years ago

Thanks acetcom

I followed your advise and configure 172.16.0.20 as PGW GPTU/GPTC.

Once I did this I got the same issue between SGW GPTC (192.168.1.122:2123) and MME GPTC (172.16.0.1:2123). Apparently the problem was in connectivity between 192.168.1.0/24 and 172.16.0.0/24.

To solve this I decided to get rid of 192.168.1.0/24 network at MME and PGW completely. But, here I got a problem, I couldn't use 172.16.0.1:2123 both for MME and SGW. So I decided to add additional interface 172.16.0.11 to SGW/MME server and configure SGW to listen GTPC on this interface.

As a result I have (only GPT):

eNodeB - 172.16.0.2

Server 1 - 172.16.0.1, 172.16.0.10 MME 172.16.0.1:2123 SGW 172.16.0.11:2123 SGW 172.16.0.1:2152

Server 2 - 172.16.0.20, 192.168.1.144 PGW 172.16.0.20: 2123 PGW 172.16.0.20: 2152

As I have all EPC components communicate within one subnet everything is working now. Also I added a second PGW gateway and tested two PGW gateway setup with different APN each.

I still don't understand why there were a communication issue between 172.16.0.0/24 and 192.168.1.0/24, but that is not relevant anymore.

Again thank you for a great piece of software and your magnificent support!