search

srsran / srsRAN_4G

Open source SDR 4G software suite from Software Radio Systems (SRS) https://docs.srsran.com/projects/4g
https://www.srsran.com
GNU Affero General Public License v3.0
3.42k stars 1.13k forks source link

srsENB does not reestablish the connection when using OAI EPC #113

Closed ismagom closed 6 years ago

ismagom commented 6 years ago

1) UE looses connection 2) UE does PRACH + ConnectionReestablishment 3) srsENB rejects (not implemented) 4) UE does PRACH + ConnectionRequest 5) IP traffic is restored in Amarisoft EPC but not in OAI EPC

This is issue identified in the list message: http://www.softwareradiosystems.com/pipermail/srslte-users/2017-October/001170.html

14:41:59.463204 [PHY0] Info    [09500] PRACH: 0/1, preamble=41, offset=0.0 us, peak2avg=706.4, max_offset=30.0 us
14:41:59.463388 [MAC ] Info    [09501] SCHED: Added user rnti=0x48
14:41:59.463406 [MAC ] Info    [09501] SCHED: Set bearer config lc_id=0, direction=3
14:41:59.463462 [RRC ] Info    Added new user rnti=0x48
14:41:59.463475 [MAC ] Info    [09501] RACH:  tti=9501, preamble=41, offset=0, temp_crnti=0x48
14:41:59.464005 [MAC ] Info    [09506] SCHED: RAR, ra_id=0, rnti=0x48, rarnti_idx=2, start_rb=0, n_rb=3, rar_grant_rba=52, rar_grant_mcs=0
14:41:59.464043 [PHY0] Info    [09502] PDCCH: DL DCI Format1A rnti=0x2, cce_index=0, L=4, tti_tx=9506
14:41:59.464058 [PHY0] Info    [09502] PDSCH: rnti=0x2, l_crb= 3, rb_start=0, harq=0, tbs=7, mcs=0, rv=0, tti_tx=9506
             0000: 69 00 00 68 0c 00 48 
14:41:59.465781 [MAC ] Info    [09512] SCHED: RAR tx rnti=0x48, pid=0, dci=0,0, grant=(2,5), n_rtx=0, tbs=7, bsr=0 (0-7)
14:41:59.473980 [PHY0] Info    [09512] PUSCH: rnti=0x48, prb=(2,5), tbs=7, mcs=0, rv=0, snr=21.9 dB, n_iter=1, crc=OK, dec_time=  33 us
             0000: 00 40 10 00 00 00 58 
14:41:59.474021 [PHY0] Info    [09512] PHICH: rnti=0x48, hi=1, I_lowest=2, n_dmrs=0, tti_tx=9516
14:41:59.474024 [PDCP] Info    RX SRB0 PDU
             0000: 40 10 00 00 00 58 
14:41:59.476610 [RRC ] Info    Removed user rnti=0x47
14:41:59.476629 [RRC ] Info    Rx SRB0 PDU
             0000: 40 10 00 00 00 58 
14:41:59.476651 [RRC ] Info    SRB0 - Rx: RRC Connection Request
             0000: 40 10 00 00 00 58 
14:41:59.476667 [RRC ] Info    Allocated SR resources for time-frequency slot (0, 0), N_pucch_sr=0, I_sr=16
14:41:59.476678 [RRC ] Info    Allocated CQI resources for time-frequency slot (0, 0), n_pucch_2=0, pmi_cfg_idx=37
14:41:59.476688 [MAC ] Info    [09522] Registering rnti=0x48 to PHY...
14:41:59.483686 [MAC ] Info    [09529] Done registering rnti=0x48 to PHY...
14:41:59.483708 [MAC ] Info    [09529] SCHED: Added user rnti=0x48
14:41:59.483720 [MAC ] Info    [09529] SCHED: Set bearer config lc_id=0, direction=3
14:41:59.483731 [MAC ] Info    [09529] SCHED: Set bearer config lc_id=1, direction=3
14:41:59.483757 [RLC ] Info    Adding radio bearer SRB1 with mode AM
14:41:59.483773 [RLC ] Info    SRB1 configured: t_poll_retx=45, poll_pdu=-1, poll_byte=-1000, max_retx_thresh=4, t_reordering=35, t_status_prohibit=0
14:41:59.483784 [PDCP] Info    Added bearer SRB1
14:41:59.483805 [RRC ] Info    SRB0 - rnti=0x48, Sending: RRC Connection Setup
             0000: 60 12 9b 2e 6a 1e 82 b2 65 2d 21 83 4c 00 02 56 
             0010: 00 04 20 
14:41:59.483821 [PDCP] Info    TX SRB0 SDU, do_security = false
             0000: 60 12 9b 2e 6a 1e 82 b2 65 2d 21 83 4c 00 02 56 
             0010: 00 04 20 
14:41:59.483835 [RLC ] Info    SRB0 Tx SDU
             0000: 60 12 9b 2e 6a 1e 82 b2 65 2d 21 83 4c 00 02 56 
             0010: 00 04 20 
14:41:59.483850 [RLC ] Info    Buffer state: rnti=0x48, lcid=0, tx_queue=19
14:41:59.483890 [MAC ] Info    [09526] SCHED: Added MAC Contention Resolution CE for rnti=0x48
14:41:59.483919 [MAC ] Info    [09526] SCHED: DL tx rnti=0x48, pid=0, mask=0x1fc0, dci=3,8, n_rtx=0, tbs=47, buffer=0
14:41:59.483932 [MAC ] Info    [09526] CE:    Added Contention Resolution ID=0x401000000058
14:41:59.483944 [RLC ] Info    SRB0 Complete SDU scheduled for tx. Stack latency: 0 us
14:41:59.483955 [RLC ] Info    TX SRB0, Transparent Mode PDU
             0000: 60 12 9b 2e 6a 1e 82 b2 65 2d 21 83 4c 00 02 56 
             0010: 00 04 20 
14:41:59.483992 [PHY0] Info    [09522] PDCCH: DL DCI Format1  rnti=0x48, cce_index=8, L=8, tti_tx=9526
14:41:59.484005 [PHY0] Info    [09522] PDSCH: rnti=0x48, l_crb=14, mask=0x1fc0, harq=0, tbs=47, mcs=0, rv=0, tti_tx=9526
             0000: 3c 20 13 1f 40 10 00 00 00 58 60 12 9b 2e 6a 1e 
             0010: 82 b2 65 2d 21 83 4c 00 02 56 00 04 20 00 00 00 
14:41:59.492080 [PHY0] Info    [09530] PUCCH: rnti=0x48, corr=0.99, n_pucch=20, n_prb=1, ack=1
14:41:59.503066 [PHY1] Info    [09541] PUCCH: rnti=0x48, corr=0.99, n_pucch=0, n_prb=23, sr=yes
14:41:59.503110 [MAC ] Info    [09549] SCHED: UL tx rnti=0x48, pid=5, dci=3,8, grant=(0,25), n_rtx=0, tbs=85, bsr=0 (512-85)
14:41:59.503149 [PHY1] Info    [09541] PDCCH: UL DCI Format0  rnti=0x48, cce_index=8, L=8, tti_tx=9545
14:41:59.510989 [PHY1] Info    [09549] PUSCH: rnti=0x48, prb=(0,25), tbs=85, mcs=0, rv=0, snr=13.0 dB, n_iter=1, crc=OK, dec_time= 141 us
             0000: 3d 3a 21 0f 1f 00 22 a0 00 00 20 10 09 8e 05 86 
             0010: 92 a0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
14:41:59.511037 [PHY1] Info    [09549] PHICH: rnti=0x48, hi=1, I_lowest=0, n_dmrs=0, tti_tx=9553
14:41:59.511038 [RLC ] Info    SRB1 Rx data PDU SN: 0
             0000: 00 20 10 09 8e 05 86 92 a0 00 00 00 00 
14:41:59.511080 [RLC ] Info    SRB1 Status packet requested through polling bit
14:41:59.511093 [RLC ] Info    SRB1 Rx SDU
             0000: 00 20 10 09 8e 05 86 92 a0 00 00 00 00 
14:41:59.511110 [PDCP] Info    RX SRB1 SDU SN: 0
             0000: 20 10 09 8e 05 86 92 a0 
14:41:59.511136 [MAC ] Info    [09557] CE:    Received Short BSR rnti=0x48, lcg=0, value=0
14:41:59.511138 [RRC ] Info    Rx SRB1 PDU
             0000: 20 10 09 8e 05 86 92 a0 
14:41:59.511152 [MAC ] Info    [09557] CE:    Received PHR from rnti=0x48, value=11
14:41:59.511177 [RRC ] Info    SRB1 - Rx RRC Connection Setup Complete
             0000: 20 10 09 8e 05 86 92 a0 
14:41:59.511195 [RRC ] Info    RRCConnectionSetupComplete transaction ID: 0
14:41:59.511254 [S1AP] Info    Sending InitialUEMessage for RNTI:0x48
             0000: 00 0c 40 37 00 00 06 00 08 00 02 00 02 00 1a 00 
             0010: 05 04 c7 02 c3 49 00 43 00 06 00 09 f1 07 00 01 
14:41:59.511926 [MAC ] Info    [09554] SCHED: DL tx rnti=0x48, pid=0, mask=0x1c00, dci=3,0, n_rtx=0, tbs=19, buffer=0
14:41:59.511951 [RLC ] Info    SRB1 Tx status PDU - ACK_SN = 1, N_nack = 0
14:41:59.511966 [RLC ] Info    No data available to be sent
14:41:59.511996 [PHY0] Info    [09550] PDCCH: DL DCI Format1  rnti=0x48, cce_index=0, L=8, tti_tx=9554
14:41:59.512011 [PHY0] Info    [09550] PDSCH: rnti=0x48, l_crb= 6, mask=0x1c00, harq=0, tbs=19, mcs=0, rv=0, tti_tx=9554
             0000: 21 02 1f 00 04 00 00 00 00 00 00 00 00 00 00 00 
             0010: 00 00 00 
14:41:59.512619 [S1AP] Info    Received S1AP PDU
             0000: 00 09 00 61 00 00 06 00 00 00 02 00 05 00 08 00 
             0010: 02 00 01 00 42 00 0a 18 0b eb c2 00 60 05 f5 e1 
14:41:59.512658 [S1AP] Info    Received InitialContextSetupRequest
14:41:59.512671 [RRC ] Info    Adding initial context for 0x46
14:41:59.512680 [RRC ] Warning Unrecognised rnti: 0x46
14:41:59.520107 [PHY0] Info    [09558] PUCCH: rnti=0x48, corr=0.99, n_pucch=12, n_prb=23, ack=1
14:41:59.521874 [PHY0] Info    [09560] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:41:59.522953 [PHY1] Info    [09561] PUCCH: rnti=0x48, corr=-0.06, n_pucch=0, n_prb=23, sr=no
14:41:59.542812 [PHY1] Info    [09581] PUCCH: rnti=0x48, corr=0.06, n_pucch=0, n_prb=23, sr=no
14:41:59.561984 [PHY0] Info    [09600] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:41:59.563043 [PHY1] Info    [09601] PUCCH: rnti=0x48, corr=0.10, n_pucch=0, n_prb=23, sr=no
14:41:59.582918 [PHY1] Info    [09621] PUCCH: rnti=0x48, corr=0.00, n_pucch=0, n_prb=23, sr=no
14:41:59.602075 [PHY0] Info    [09640] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:41:59.603143 [PHY1] Info    [09641] PUCCH: rnti=0x48, corr=0.03, n_pucch=0, n_prb=23, sr=no
14:41:59.623010 [PHY1] Info    [09661] PUCCH: rnti=0x48, corr=-0.02, n_pucch=0, n_prb=23, sr=no
14:41:59.636825 [GTPU] Error   Unrecognized RNTI for DL PDU: 0x46 - dropping packet
14:41:59.641813 [PHY0] Info    [09680] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:41:59.642880 [PHY1] Info    [09681] PUCCH: rnti=0x48, corr=-0.04, n_pucch=0, n_prb=23, sr=no
14:41:59.663110 [PHY1] Info    [09701] PUCCH: rnti=0x48, corr=0.02, n_pucch=0, n_prb=23, sr=no
14:41:59.681921 [PHY0] Info    [09720] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:41:59.682985 [PHY1] Info    [09721] PUCCH: rnti=0x48, corr=0.07, n_pucch=0, n_prb=23, sr=no
14:41:59.702852 [PHY1] Info    [09741] PUCCH: rnti=0x48, corr=-0.10, n_pucch=0, n_prb=23, sr=no
14:41:59.722015 [PHY0] Info    [09760] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:41:59.723080 [PHY1] Info    [09761] PUCCH: rnti=0x48, corr=0.11, n_pucch=0, n_prb=23, sr=no
14:41:59.742961 [PHY1] Info    [09781] PUCCH: rnti=0x48, corr=-0.00, n_pucch=0, n_prb=23, sr=no
14:41:59.762112 [PHY0] Info    [09800] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:41:59.762825 [PHY1] Info    [09801] PUCCH: rnti=0x48, corr=-0.10, n_pucch=0, n_prb=23, sr=no
14:41:59.783052 [PHY1] Info    [09821] PUCCH: rnti=0x48, corr=-0.11, n_pucch=0, n_prb=23, sr=no
14:41:59.801859 [PHY0] Info    [09840] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:41:59.802932 [PHY1] Info    [09841] PUCCH: rnti=0x48, corr=0.16, n_pucch=0, n_prb=23, sr=no
14:41:59.823153 [PHY1] Info    [09861] PUCCH: rnti=0x48, corr=-0.12, n_pucch=0, n_prb=23, sr=no
14:41:59.841961 [PHY0] Info    [09880] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:41:59.843021 [PHY1] Info    [09881] PUCCH: rnti=0x48, corr=0.02, n_pucch=0, n_prb=23, sr=no
14:41:59.862910 [PHY1] Info    [09901] PUCCH: rnti=0x48, corr=-0.05, n_pucch=0, n_prb=23, sr=no
14:41:59.882057 [PHY0] Info    [09920] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:41:59.883126 [PHY1] Info    [09921] PUCCH: rnti=0x48, corr=-0.03, n_pucch=0, n_prb=23, sr=no
14:41:59.902997 [PHY1] Info    [09941] PUCCH: rnti=0x48, corr=-0.01, n_pucch=0, n_prb=23, sr=no
14:41:59.921802 [PHY0] Info    [09960] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:41:59.922870 [PHY1] Info    [09961] PUCCH: rnti=0x48, corr=-0.03, n_pucch=0, n_prb=23, sr=no
14:41:59.943094 [PHY1] Info    [09981] PUCCH: rnti=0x48, corr=-0.09, n_pucch=0, n_prb=23, sr=no
14:41:59.961905 [PHY0] Info    [10000] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:41:59.962983 [PHY1] Info    [10001] PUCCH: rnti=0x48, corr=-0.07, n_pucch=0, n_prb=23, sr=no
14:41:59.982842 [PHY1] Info    [10021] PUCCH: rnti=0x48, corr=-0.04, n_pucch=0, n_prb=23, sr=no
14:42:00.002008 [PHY0] Info    [10040] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.003069 [PHY1] Info    [10041] PUCCH: rnti=0x48, corr=-0.09, n_pucch=0, n_prb=23, sr=no
14:42:00.022946 [PHY1] Info    [10061] PUCCH: rnti=0x48, corr=0.08, n_pucch=0, n_prb=23, sr=no
14:42:00.042105 [PHY0] Info    [10080] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.042810 [PHY1] Info    [10081] PUCCH: rnti=0x48, corr=0.04, n_pucch=0, n_prb=23, sr=no
14:42:00.063033 [PHY1] Info    [10101] PUCCH: rnti=0x48, corr=-0.03, n_pucch=0, n_prb=23, sr=no
14:42:00.081852 [PHY0] Info    [10120] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.082919 [PHY1] Info    [10121] PUCCH: rnti=0x48, corr=-0.01, n_pucch=0, n_prb=23, sr=no
14:42:00.103132 [PHY1] Info    [10141] PUCCH: rnti=0x48, corr=-0.07, n_pucch=0, n_prb=23, sr=no
14:42:00.121958 [PHY0] Info    [10160] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.123007 [PHY1] Info    [10161] PUCCH: rnti=0x48, corr=-0.05, n_pucch=0, n_prb=23, sr=no
14:42:00.142921 [PHY1] Info    [10181] PUCCH: rnti=0x48, corr=-0.00, n_pucch=0, n_prb=23, sr=no
14:42:00.162065 [PHY0] Info    [10200] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.163113 [PHY1] Info    [10201] PUCCH: rnti=0x48, corr=0.14, n_pucch=0, n_prb=23, sr=no
14:42:00.182984 [PHY1] Info    [10221] PUCCH: rnti=0x48, corr=-0.04, n_pucch=0, n_prb=23, sr=no
14:42:00.202141 [PHY0] Info    [00000] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.202851 [PHY1] Info    [00001] PUCCH: rnti=0x48, corr=0.11, n_pucch=0, n_prb=23, sr=no
14:42:00.223081 [PHY1] Info    [00021] PUCCH: rnti=0x48, corr=0.06, n_pucch=0, n_prb=23, sr=no
14:42:00.241888 [PHY0] Info    [00040] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.242960 [PHY1] Info    [00041] PUCCH: rnti=0x48, corr=-0.08, n_pucch=0, n_prb=23, sr=no
14:42:00.262826 [PHY1] Info    [00061] PUCCH: rnti=0x48, corr=-0.01, n_pucch=0, n_prb=23, sr=no
14:42:00.281990 [PHY0] Info    [00080] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.283051 [PHY1] Info    [00081] PUCCH: rnti=0x48, corr=0.05, n_pucch=0, n_prb=23, sr=no
14:42:00.302932 [PHY1] Info    [00101] PUCCH: rnti=0x48, corr=0.07, n_pucch=0, n_prb=23, sr=no
14:42:00.322086 [PHY0] Info    [00120] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.323150 [PHY1] Info    [00121] PUCCH: rnti=0x48, corr=0.04, n_pucch=0, n_prb=23, sr=no
14:42:00.343024 [PHY1] Info    [00141] PUCCH: rnti=0x48, corr=0.07, n_pucch=0, n_prb=23, sr=no
14:42:00.350725 [GTPU] Error   Unrecognized RNTI for DL PDU: 0x46 - dropping packet
14:42:00.361830 [PHY0] Info    [00160] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.362895 [PHY1] Info    [00161] PUCCH: rnti=0x48, corr=-0.05, n_pucch=0, n_prb=23, sr=no
14:42:00.383123 [PHY1] Info    [00181] PUCCH: rnti=0x48, corr=0.00, n_pucch=0, n_prb=23, sr=no
14:42:00.401934 [PHY0] Info    [00200] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.403000 [PHY1] Info    [00201] PUCCH: rnti=0x48, corr=-0.11, n_pucch=0, n_prb=23, sr=no
14:42:00.422869 [PHY1] Info    [00221] PUCCH: rnti=0x48, corr=0.10, n_pucch=0, n_prb=23, sr=no
14:42:00.442030 [PHY0] Info    [00240] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.443097 [PHY1] Info    [00241] PUCCH: rnti=0x48, corr=0.07, n_pucch=0, n_prb=23, sr=no
14:42:00.462971 [PHY1] Info    [00261] PUCCH: rnti=0x48, corr=-0.03, n_pucch=0, n_prb=23, sr=no
14:42:00.482125 [PHY0] Info    [00280] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.482839 [PHY1] Info    [00281] PUCCH: rnti=0x48, corr=-0.09, n_pucch=0, n_prb=23, sr=no
14:42:00.503066 [PHY1] Info    [00301] PUCCH: rnti=0x48, corr=-0.08, n_pucch=0, n_prb=23, sr=no
14:42:00.521871 [PHY0] Info    [00320] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.522948 [PHY1] Info    [00321] PUCCH: rnti=0x48, corr=-0.07, n_pucch=0, n_prb=23, sr=no
14:42:00.542808 [PHY1] Info    [00341] PUCCH: rnti=0x48, corr=-0.03, n_pucch=0, n_prb=23, sr=no
14:42:00.561978 [PHY0] Info    [00360] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.563037 [PHY1] Info    [00361] PUCCH: rnti=0x48, corr=0.01, n_pucch=0, n_prb=23, sr=no
14:42:00.582916 [PHY1] Info    [00381] PUCCH: rnti=0x48, corr=-0.01, n_pucch=0, n_prb=23, sr=no
14:42:00.589372 [GTPU] Error   Unrecognized RNTI for DL PDU: 0x46 - dropping packet
14:42:00.602077 [PHY0] Info    [00400] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.603136 [PHY1] Info    [00401] PUCCH: rnti=0x48, corr=-0.07, n_pucch=0, n_prb=23, sr=no
14:42:00.623009 [PHY1] Info    [00421] PUCCH: rnti=0x48, corr=-0.19, n_pucch=0, n_prb=23, sr=no
14:42:00.641814 [PHY0] Info    [00440] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.642886 [PHY1] Info    [00441] PUCCH: rnti=0x48, corr=0.01, n_pucch=0, n_prb=23, sr=no
14:42:00.663108 [PHY1] Info    [00461] PUCCH: rnti=0x48, corr=-0.01, n_pucch=0, n_prb=23, sr=no
14:42:00.681922 [PHY0] Info    [00480] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.682982 [PHY1] Info    [00481] PUCCH: rnti=0x48, corr=0.02, n_pucch=0, n_prb=23, sr=no
14:42:00.702854 [PHY1] Info    [00501] PUCCH: rnti=0x48, corr=0.04, n_pucch=0, n_prb=23, sr=no
14:42:00.722022 [PHY0] Info    [00520] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.723082 [PHY1] Info    [00521] PUCCH: rnti=0x48, corr=-0.06, n_pucch=0, n_prb=23, sr=no
14:42:00.742962 [PHY1] Info    [00541] PUCCH: rnti=0x48, corr=-0.03, n_pucch=0, n_prb=23, sr=no
14:42:00.762121 [PHY0] Info    [00560] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.762826 [PHY1] Info    [00561] PUCCH: rnti=0x48, corr=0.09, n_pucch=0, n_prb=23, sr=no
14:42:00.783054 [PHY1] Info    [00581] PUCCH: rnti=0x48, corr=0.08, n_pucch=0, n_prb=23, sr=no
14:42:00.801863 [PHY0] Info    [00600] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.802931 [PHY1] Info    [00601] PUCCH: rnti=0x48, corr=0.01, n_pucch=0, n_prb=23, sr=no
14:42:00.823150 [PHY1] Info    [00621] PUCCH: rnti=0x48, corr=0.03, n_pucch=0, n_prb=23, sr=no
14:42:00.828380 [GTPU] Error   Unrecognized RNTI for DL PDU: 0x46 - dropping packet
14:42:00.841969 [PHY0] Info    [00640] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.843022 [PHY1] Info    [00641] PUCCH: rnti=0x48, corr=0.06, n_pucch=0, n_prb=23, sr=no
14:42:00.862897 [PHY1] Info    [00661] PUCCH: rnti=0x48, corr=0.02, n_pucch=0, n_prb=23, sr=no
14:42:00.882063 [PHY0] Info    [00680] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.883121 [PHY1] Info    [00681] PUCCH: rnti=0x48, corr=-0.00, n_pucch=0, n_prb=23, sr=no
14:42:00.888655 [GTPU] Error   Unrecognized RNTI for DL PDU: 0x46 - dropping packet
14:42:00.903019 [PHY1] Info    [00701] PUCCH: rnti=0x48, corr=0.06, n_pucch=0, n_prb=23, sr=no
14:42:00.921808 [PHY0] Info    [00720] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.922864 [PHY1] Info    [00721] PUCCH: rnti=0x48, corr=-0.04, n_pucch=0, n_prb=23, sr=no
14:42:00.943091 [PHY1] Info    [00741] PUCCH: rnti=0x48, corr=0.04, n_pucch=0, n_prb=23, sr=no
14:42:00.961914 [PHY0] Info    [00760] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:00.962970 [PHY1] Info    [00761] PUCCH: rnti=0x48, corr=0.14, n_pucch=0, n_prb=23, sr=no
14:42:00.982836 [PHY1] Info    [00781] PUCCH: rnti=0x48, corr=-0.05, n_pucch=0, n_prb=23, sr=no
14:42:01.002009 [PHY0] Info    [00800] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:01.003064 [PHY1] Info    [00801] PUCCH: rnti=0x48, corr=0.04, n_pucch=0, n_prb=23, sr=no
14:42:01.022943 [PHY1] Info    [00821] PUCCH: rnti=0x48, corr=-0.01, n_pucch=0, n_prb=23, sr=no
14:42:01.042103 [PHY0] Info    [00840] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:01.042808 [PHY1] Info    [00841] PUCCH: rnti=0x48, corr=0.06, n_pucch=0, n_prb=23, sr=no
14:42:01.063040 [PHY1] Info    [00861] PUCCH: rnti=0x48, corr=-0.05, n_pucch=0, n_prb=23, sr=no
14:42:01.064364 [GTPU] Error   Unrecognized RNTI for DL PDU: 0x46 - dropping packet
14:42:01.081857 [PHY0] Info    [00880] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:01.082916 [PHY1] Info    [00881] PUCCH: rnti=0x48, corr=0.08, n_pucch=0, n_prb=23, sr=no
14:42:01.103133 [PHY1] Info    [00901] PUCCH: rnti=0x48, corr=-0.07, n_pucch=0, n_prb=23, sr=no
14:42:01.121955 [PHY0] Info    [00920] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:01.123007 [PHY1] Info    [00921] PUCCH: rnti=0x48, corr=0.03, n_pucch=0, n_prb=23, sr=no
14:42:01.142879 [PHY1] Info    [00941] PUCCH: rnti=0x48, corr=0.00, n_pucch=0, n_prb=23, sr=no
14:42:01.162051 [PHY0] Info    [00960] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:01.163106 [PHY1] Info    [00961] PUCCH: rnti=0x48, corr=-0.02, n_pucch=0, n_prb=23, sr=no
14:42:01.182979 [PHY1] Info    [00981] PUCCH: rnti=0x48, corr=0.09, n_pucch=0, n_prb=23, sr=no
14:42:01.202147 [PHY0] Info    [01000] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:01.202852 [PHY1] Info    [01001] PUCCH: rnti=0x48, corr=0.08, n_pucch=0, n_prb=23, sr=no
14:42:01.223075 [PHY1] Info    [01021] PUCCH: rnti=0x48, corr=0.03, n_pucch=0, n_prb=23, sr=no
14:42:01.241893 [PHY0] Info    [01040] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:01.242955 [PHY1] Info    [01041] PUCCH: rnti=0x48, corr=-0.09, n_pucch=0, n_prb=23, sr=no
14:42:01.262820 [PHY1] Info    [01061] PUCCH: rnti=0x48, corr=0.01, n_pucch=0, n_prb=23, sr=no
14:42:01.282003 [PHY0] Info    [01080] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:01.283047 [PHY1] Info    [01081] PUCCH: rnti=0x48, corr=-0.06, n_pucch=0, n_prb=23, sr=no
14:42:01.302930 [PHY1] Info    [01101] PUCCH: rnti=0x48, corr=-0.03, n_pucch=0, n_prb=23, sr=no
14:42:01.303215 [GTPU] Error   Unrecognized RNTI for DL PDU: 0x46 - dropping packet
14:42:01.306355 [GTPU] Error   Unrecognized RNTI for DL PDU: 0x46 - dropping packet
14:42:01.322093 [PHY0] Info    [01120] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:01.323146 [PHY1] Info    [01121] PUCCH: rnti=0x48, corr=0.03, n_pucch=0, n_prb=23, sr=no
14:42:01.343017 [PHY1] Info    [01141] PUCCH: rnti=0x48, corr=-0.05, n_pucch=0, n_prb=23, sr=no
14:42:01.361837 [PHY0] Info    [01160] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:01.362890 [PHY1] Info    [01161] PUCCH: rnti=0x48, corr=-0.09, n_pucch=0, n_prb=23, sr=no
14:42:01.383120 [PHY1] Info    [01181] PUCCH: rnti=0x48, corr=0.00, n_pucch=0, n_prb=23, sr=no
14:42:01.401942 [PHY0] Info    [01200] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:01.402994 [PHY1] Info    [01201] PUCCH: rnti=0x48, corr=-0.09, n_pucch=0, n_prb=23, sr=no
14:42:01.422861 [PHY1] Info    [01221] PUCCH: rnti=0x48, corr=-0.16, n_pucch=0, n_prb=23, sr=no
14:42:01.442036 [PHY0] Info    [01240] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:01.443089 [PHY1] Info    [01241] PUCCH: rnti=0x48, corr=0.09, n_pucch=0, n_prb=23, sr=no
14:42:01.462968 [PHY1] Info    [01261] PUCCH: rnti=0x48, corr=-0.10, n_pucch=0, n_prb=23, sr=no
14:42:01.482134 [PHY0] Info    [01280] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:01.482834 [PHY1] Info    [01281] PUCCH: rnti=0x48, corr=0.09, n_pucch=0, n_prb=23, sr=no
14:42:01.503063 [PHY1] Info    [01301] PUCCH: rnti=0x48, corr=0.12, n_pucch=0, n_prb=23, sr=no
14:42:01.515670 [S1AP] Info    Received S1AP PDU
             0000: 00 17 00 11 00 00 02 00 63 00 04 00 05 00 01 00 
             0010: 02 40 02 00 00 
14:42:01.515710 [S1AP] Info    Received UEContextReleaseCommand
14:42:01.515726 [RRC ] Info    Releasing E-RABs for 0x46
14:42:01.515736 [RRC ] Warning Unrecognised rnti: 0x46
14:42:01.515752 [S1AP] Info    Sending UEContextReleaseComplete for RNTI:0x46
             0000: 20 17 00 0f 00 00 02 00 00 40 02 00 05 00 08 40 
             0010: 02 00 01 
14:42:01.515827 [S1AP] Info    UE context for RNTI:0x46 released
14:42:01.515849 [RRC ] Info    Received Release Complete rnti=0x46
14:42:01.515859 [RRC ] Error   Received ReleaseComplete for unknown rnti=0x46
14:42:01.521879 [PHY0] Info    [01320] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:01.522941 [PHY1] Info    [01321] PUCCH: rnti=0x48, corr=0.06, n_pucch=0, n_prb=23, sr=no
14:42:01.542228 [GTPU] Error   Unrecognized RNTI for DL PDU: 0x46 - dropping packet
14:42:01.542811 [PHY1] Info    [01341] PUCCH: rnti=0x48, corr=0.04, n_pucch=0, n_prb=23, sr=no
14:42:01.561991 [PHY0] Info    [01360] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:01.563040 [PHY1] Info    [01361] PUCCH: rnti=0x48, corr=0.01, n_pucch=0, n_prb=23, sr=no
14:42:01.582927 [PHY1] Info    [01381] PUCCH: rnti=0x48, corr=-0.04, n_pucch=0, n_prb=23, sr=no
14:42:01.602109 [PHY0] Info    [01400] PUCCH: rnti=0x48, corr=1.01, n_pucch=0, n_prb=24, cqi=15
14:42:01.603143 [PHY1] Info    [01401] PUCCH: rnti=0x48, corr=0.05, n_pucch=0, n_prb=23, sr=no
nicolabui commented 6 years ago

In the log attached the following sequence of events happens:

kewinrausch commented 6 years ago

I tried this configuration with OAI EPC, develop branch.

To resume:

Results are that the UE eventually (Nexus is slow in this process) reconnects again with eNB, and connection with EPC is re-established, but something within the EPC went wrong, since I can see the MME but can't establish internet connection (or maybe the new GTP connection id to go out of SPGW is lost).

So UE reconnects again, but no Internet traffic. I suppose this is a problem with OAI EPC, rather than with srsENB.

Log file is: https://drive.google.com/open?id=16KE94GvvSktY-UF4bfiGwkdQUbKr2cfn

spencersevilla commented 6 years ago

Hi Ismael and Kewin,

I'm also seeing the exact same pattern/bug with the OAI EPC (I'm using master branch) after idle disconnect/reconnect. I collected some logs and at a first glance, they look quite similar to yours. I share your suspicions that this is an OAI bug, because I've been able to recreate this pattern with two different eNBs (srsENB and a commercial product) as well as three different commercial UEs. I was wondering if either of you got any further on this, or figured out what was going on? Any hints or other ideas you could suggest? Just figured I'd check if there was any help you provide. Thank you!!!

spencersevilla commented 6 years ago

Just in case anyone else finds this and/or is interested, I figured out the problem in the OAI EPC, and have a fix. When the UE goes idle, the MME tells the SPGW to release the context (relevant function is sgw_handle_release_access_bearers_request in sgw_handlers.c) but the SPGW forgets to tear down the old GTP tunnel. This means that when the UE wakes up, the MME tells the SPGW to create a new GTP tunnel, creation fails (because there already exists a tunnel), but the old tunnel has the wrong RNTI value. You can fix this by adding the line gtp_mod_kernel_tunnel_del(eps_bearer_entry_p->s_gw_teid_S1u_S12_S4_up, eps_bearer_entry_p->enb_teid_S1u); to the function sgw_release_all_enb_related_information in sgw_handlers.c right above the memset line. I am trying to push this to openair-cn soon, but hope this helps in the meantime!

ismagom commented 6 years ago

Thanks for the feedback. Closing since it's not an srsUE bug