LTE 信令流程log 之 srsUE

来源:互联网 发布:timepicki.js 编辑:程序博客网 时间:2024/06/06 14:26

最近在研究SDR LTE系统之间的互联互通,成功调通了Amari MME + OAI eNB + srsUE。不知道这些SDR LTE平台的可以参见我的博客http://blog.csdn.net/jxwxg/article/details/53026659。


调通之后,抓取了MME,eNB和UE侧的信令流程log,流程包括了eNB与MME的连接,UE随机接入,UE鉴权等过程。由于UE的Log信息打印较多,本博客只显示了前面的352行,完整的Log信息在附件里面可以下载。下载之后建议使用notepad++ 打开。

Amari MME的信令流程Log信息可以点击 http://blog.csdn.net/jxwxg/article/details/53999138  OAI eNB的信令流程Log信息可以点击 http://blog.csdn.net/jxwxg/article/details/53999085 。


22:02:43.068 [MAC ] Info    [00000] Resetting MAC22:02:43.068 [PHY ] Info    [00000] PHY:   Configuring UL parameters22:02:43.068 [PHY ] Info    [00000] Setting new params worker_id=0, pregen_disabled=022:02:43.068 [MAC ] Info    [00000] Waiting PHY to synchronize with cell22:02:43.068 [PHY ] Info    [00000] Setting new params worker_id=1, pregen_disabled=022:02:43.068 [RRC ] Info    Set MAC main config: harq-MaxReTX=5, bsr-TimerReTX=2560, bsr-TimerPeriodic=-122:02:43.068 [RF  ] Warning Late22:02:43.068 [RF  ] Warning Late22:02:43.265 [RF  ] Warning Late22:02:43.265 [RF  ] Warning Late22:02:43.365 [RF  ] Warning Late22:02:43.365 [RF  ] Warning Late22:02:43.465 [RF  ] Warning Late22:02:43.465 [RF  ] Warning Late22:02:43.465 [RF  ] Warning Late22:02:44.112 [RLC ] Info    BCCH BCH message received.             0000: 43 d4 00 22:02:44.112 [RRC ] Info    BCCH BCH message received.             0000: 43 d4 00 22:02:44.112 [RRC ] Info    BCCH BCH message Stack latency: 20 us22:02:44.112 [RRC ] Info    MIB received BW=5 MHz22:02:44.643 [RF  ] Warning Late22:02:44.899 [RF  ] Warning Late22:02:44.899 [RF  ] Warning Late22:02:45.000 [RF  ] Warning Late22:02:45.000 [RF  ] Warning Late22:02:45.100 [RF  ] Warning Late22:02:45.100 [RF  ] Warning Late22:02:45.101 [PHY ] Info    [00000] SYNC:  Cell found. Synchronizing...22:02:45.113 [RRC ] Info    Detected 1 out-of-sync from PHY. Starting T310 timer22:02:45.121 [PHY ] Info    [00000] SYNC:  Decoding MIB...22:02:45.121 [PHY ] Info    [00000] SYNC:  DONE, TTI=570, sfn_offset=122:02:45.131 [RRC ] Info    Detected 1 in-sync from PHY. Stopping T310 timer22:02:45.169 [MAC ] Info    [00619] BSR:   Configured timer reTX 2560 ms22:02:45.169 [MAC ] Info    [00619] BSR:   QUEUE status: 0 (0), 0 (0), 0 (0), 0 (0), 0 (0), 0 (0), 22:02:45.174 [MAC ] Info    [00624] SCHED: Searching for DL grant for SI-RNTI window_st=645, window_len=122:02:45.196 [PHY ] Info    [00645] PDCCH: DL DCI Format1A cce_index= 0, L=4, n_data_bits=25, hex=[8a c2 15 00 ]22:02:45.196 [PHY ] Info    [00645] PDSCH: l_crb= 4, harq=0, tbs=18, mcs=0, rv=1, crc=OK, snr=10.0 dB, n_iter=2, dec_time=  35 us22:02:45.196 [RLC ] Info    BCCH TXSCH message received.             0000: 40 40 04 03 00 01 00 00 e0 0c 14 60 00 82 80 04              0010: 02 4f 22:02:45.196 [RRC ] Info    BCCH DLSCH message received.             0000: 40 40 04 03 00 01 00 00 e0 0c 14 60 00 82 80 04              0010: 02 4f 22:02:45.196 [RRC ] Info    BCCH DLSCH message Stack latency: 10 us22:02:45.196 [RRC ] Info    SIB1 received, CellID=3584, si_window=20, sib2_period=822:02:45.196 [MAC ] Info    [00646] DL 8:  reTX  tbs=18, rv=1, ack=OK, ndi=0 (0), tti=645 (0)22:02:45.284 [MAC ] Info    [00734] SCHED: Searching for DL grant for SI-RNTI window_st=800, window_len=2022:02:45.366 [PHY ] Info    [00815] PDCCH: DL DCI Format1A cce_index= 0, L=4, n_data_bits=25, hex=[8a c6 15 00 ]22:02:45.366 [PHY ] Info    [00815] PDSCH: l_crb= 4, harq=0, tbs=32, mcs=0, rv=1, crc=OK, snr=10.3 dB, n_iter=1, dec_time=  20 us22:02:45.366 [RLC ] Info    BCCH TXSCH message received.             0000: 00 80 0f 99 bd 64 80 00 02 08 f8 00 20 10 08 04              0010: 02 4f f9 57 96 de c0 0e 11 1f ec 07 c0 20 00 00 22:02:45.366 [RRC ] Info    BCCH DLSCH message received.             0000: 00 80 0f 99 bd 64 80 00 02 08 f8 00 20 10 08 04              0010: 02 4f f9 57 96 de c0 0e 11 1f ec 07 c0 20 00 00 22:02:45.366 [RRC ] Info    BCCH DLSCH message Stack latency: 8 us22:02:45.366 [RRC ] Info    SIB2 received22:02:45.366 [RRC ] Info    Set RACH ConfigCommon: NofPreambles=64, ResponseWindow=10, ContentionResolutionTimer=48 ms22:02:45.366 [PHY ] Info    [00815] PHY:   Configuring UL parameters22:02:45.366 [PHY ] Info    [00815] Setting new params worker_id=0, pregen_disabled=022:02:45.366 [PHY ] Info    [00815] Setting new params worker_id=1, pregen_disabled=022:02:45.366 [RRC ] Info    Set PUSCH ConfigCommon: HopOffset=0, RSGroup=0, RSNcs=1, N_sb=122:02:45.366 [RRC ] Info    Set PUCCH ConfigCommon: DeltaShift=1, CyclicShift=0, N1=32, NRB=122:02:45.366 [RRC ] Info    Set PRACH ConfigCommon: SeqIdx=0, HS=no, FreqOffset=2, ZC=1, ConfigIndex=022:02:45.366 [RRC ] Info    Set SRS ConfigCommon: BW-Configuration=0, SF-Configuration=0, ACKNACK=no22:02:45.366 [RRC ] Info    Set Constants and Timers: N310=20, N311=1, t301=1000, t310=1000, t311=1000022:02:45.366 [RRC ] Info    Sending RRC Connection Request on SRB022:02:45.366 [PDCP] Info    TX SRB0 SDU, do_security = false             0000: 50 00 00 00 3e 86 22:02:45.366 [RLC ] Info    SRB0 Tx SDU             0000: 50 00 00 00 3e 86 22:02:45.366 [MAC ] Info    [00816] DL 8:  reTX  tbs=32, rv=1, ack=OK, ndi=0 (0), tti=815 (0)22:02:45.367 [MAC ] Info    [00817] BSR:   Triggered REGULAR BSR for single LCID=022:02:45.367 [MAC ] Info    [00817] BSR:   Need to send sr: sr_is_sent=true, reset_sr=false, tti=817, next_tx_tti=022:02:45.367 [MAC ] Info    [00817] SR:    PUCCH not configured. Starting RA procedure22:02:45.367 [MAC ] Info    [00817] RA:    INIT:   Starting PRACH by MAC order22:02:45.749 [MAC ] Info    [01199] BSR:   QUEUE status: 6 (6), 0 (0), 0 (0), 0 (0), 0 (0), 0 (0), 22:02:45.768 [PHY ] Info    [01217] PRACH: Transmitted preamble=1, CFO=-0.28 KHz, tx_time=0.43423322:02:45.769 [MAC ] Info    [01218] RA:    PDCCH:  seq=1, ra-rnti=2, ra-tti=122122:02:45.776 [PHY ] Info    [01225] PDCCH: DL DCI Format1A cce_index= 4, L=4, n_data_bits=25, hex=[89 60 11 00 ]22:02:45.776 [PHY ] Info    [01225] PDSCH: l_crb= 4, harq=0, tbs=7, mcs=0, rv=0, crc=OK, snr=9.9 dB, n_iter=1, dec_time=  17 us22:02:45.776 [PHY ] Info    [01225] PHY:   Set TA RAR: ta_cmd: 1, n_ta: 16, ta_usec: 0.522:02:45.776 [MAC ] Info    [01225] RA:    Rx:     RAPID=1, TA=122:02:45.778 [RLC ] Info    SRB0 Complete SDU scheduled for tx. Stack latency: 411636 us22:02:45.778 [RLC ] Info    TX SRB0, Transparent Mode PDU             0000: 50 00 00 00 3e 86 22:02:45.778 [MAC ] Info    [01227] SDU: rlc_buffer=6, allocated=6/17, max_sdu_sz=-1, remaining=1122:02:45.778 [MAC ] Info    [01227] BSR:   Including BSR type Padding, format Long, nof_padding_bytes=1122:02:45.778 [MAC ] Info    [01227] UL 7:  New TX for Msg3, RV=0, TBS=18, RNTI=022:02:45.778 [PHY ] Info    [01227] PUSCH: tti_tx=1231, n_prb=1, rb_start=1, tbs=18, mod=1, mcs=10, rv_idx=0, ack=no, cfo=-270.3 Hz, total_time= 329 us22:02:45.786 [PHY ] Info    [01235] PDCCH: DL DCI Format1A cce_index= 0, L=2, n_data_bits=25, hex=[89 67 11 00 ]22:02:45.786 [MAC ] Info    [01235] Set NDI=1 for Temp-RNTI DL grant22:02:45.786 [PHY ] Info    [01235] PDSCH: l_crb= 4, harq=0, tbs=59, mcs=7, rv=0, crc=OK, snr=11.9 dB, n_iter=1, dec_time=  16 us22:02:45.786 [MAC ] Info    [01235] DL 0:  newTX tbs=59, rv=0, ack=OK, ndi=1 (0), tti=1235 (0)22:02:45.786 [PHY ] Info    [01235] PHICH: hi=1, I_lowest=1, n_dmrs=022:02:45.786 [MAC ] Info    [01235] Delivering PDU for lcid=0, 25 bytes22:02:45.786 [MAC ] Info    [01235] UL 7:  HARQ = ACK for UL transmission. Discarting TB.22:02:45.786 [PDCP] Info    RX SRB0 PDU             0000: 68 10 98 0f 1c ce 01 83 81 fd c0 02 11 c0 44 8d              0010: 01 22 34 04 c8 10 06 0a 00 22:02:45.786 [RRC ] Info    TX SRB0 PDU             0000: 68 10 98 0f 1c ce 01 83 81 fd c0 02 11 c0 44 8d              0010: 01 22 34 04 c8 10 06 0a 00 22:02:45.786 [RRC ] Info    TX PDU Stack latency: 24 us22:02:45.786 [RRC ] Info    SRB0 - Received RRC Connection Setup22:02:45.786 [RRC ] Info    Connection Setup received22:02:45.786 [RRC ] Info    Set cqi-ReportModeAperiodic=rm3022:02:45.786 [RRC ] Info    Set PHY config ded: SR-n_pucch=3, SR-ConfigIndex=5, SR-TransMax=422:02:45.786 [PHY ] Info    [01235] PHY:   Configuring UL parameters22:02:45.786 [PHY ] Info    [01235] Setting new params worker_id=0, pregen_disabled=022:02:45.786 [PHY ] Info    [01235] Setting new params worker_id=1, pregen_disabled=022:02:45.786 [PDCP] Info    Added bearer SRB122:02:45.786 [RLC ] Info    Adding radio bearer SRB1 with mode AM22:02:45.786 [RLC ] Info    SRB1 configured: t_poll_retx=80, poll_pdu=4, poll_byte=-1000, max_retx_thresh=4, t_reordering=35, t_status_prohibit=022:02:45.786 [MAC ] Info    [01235] Logical Channel Setup: LCID=1, LCG=0, priority=1, PBR=-1, BSd=5022:02:45.786 [RRC ] Info    Added radio bearer SRB122:02:45.786 [RRC ] Info    Notifying NAS of connection setup22:02:45.786 [NAS ] Info    Generating PDN Connectivity Request22:02:45.786 [NAS ] Info    Sending attach request22:02:45.786 [RRC ] Info    RX SRB1 SDU             0000: 07 41 01 08 09 10 10 10 32 54 76 11 02 80 e0 00              0010: 04 02 01 d0 11 22:02:45.786 [RRC ] Info    Sending RRC Connection Setup Complete22:02:45.786 [PDCP] Info    TX SRB1 SDU, do_security = false             0000: 22 00 2a 0e 82 02 10 12 20 20 20 64 a8 ec 22 05              0010: 01 c0 00 08 04 03 a0 22 22:02:45.786 [RLC ] Info    SRB1 Tx SDU             0000: 00 22 00 2a 0e 82 02 10 12 20 20 20 64 a8 ec 22              0010: 05 01 c0 00 08 04 03 a0 22 00 00 00 00 22:02:45.786 [PHY ] Info    [01235] PUCCH: power=-91.42 dBm, tti_tx=1239, n_cce=  0, ack=1, sr=no, cfo=-266.0 Hz, enc_time=217, total_time=400 us22:02:45.786 [MAC ] Info    [01236] BSR:   Triggered REGULAR BSR for Max Priority LCID=122:02:45.786 [MAC ] Info    [01236] BSR:   Need to send sr: sr_is_sent=true, reset_sr=false, tti=1236, next_tx_tti=022:02:45.786 [MAC ] Info    [01236] SR:    Signalling PHY sr_counter=122:02:45.787 [MAC ] Info    [01236] RA:    Done:   Random Access Complete.     c-rnti=35953, ta=122:02:45.787 [PHY ] Info    [01236] PUCCH: SR transmission at TTI=1240, I_sr=522:02:45.787 [PHY ] Info    [01236] PUCCH: power=-90.55 dBm, tti_tx=1240, n_cce=  0, ack=no, sr=yes, cfo=-266.0 Hz, enc_time=197, total_time=316 us22:02:45.791 [PHY ] Info    [01240] PDCCH: UL DCI Format0  cce_index=0, L=4, n_data_bits=25, hex=[0f ca 00 00 ]22:02:45.791 [RLC ] Info    SRB1 Complete SDU scheduled for tx. Stack latency: 5133 us22:02:45.791 [RLC ] Info    SRB1 PDU scheduled for tx. SN: 022:02:45.791 [MAC ] Info    [01236] SDU: rlc_buffer=31, allocated=31/126, max_sdu_sz=-1, remaining=9522:02:45.791 [MAC ] Info    [01236] UL 4:  New TX, RV=0, TBS=129, RNTI=3595322:02:45.792 [PHY ] Info    [01240] PUSCH: tti_tx=1244, n_prb=6, rb_start=1, tbs=129, mod=1, mcs=10, rv_idx=0, ack=no, cfo=-263.2 Hz, total_time= 408 us22:02:45.792 [PHY ] Info    [01241] PDCCH: UL DCI Format0  cce_index=0, L=4, n_data_bits=25, hex=[0f ca 20 00 ]22:02:45.792 [MAC ] Info    [01242] BSR:   Including BSR type Padding, format Long, nof_padding_bytes=12922:02:45.792 [MAC ] Info    [01242] UL 5:  New TX, RV=0, TBS=129, RNTI=3595322:02:45.792 [PHY ] Info    [01241] PUSCH: tti_tx=1245, n_prb=6, rb_start=1, tbs=129, mod=1, mcs=10, rv_idx=0, ack=no, cfo=-263.2 Hz, total_time= 383 us22:02:45.793 [PHY ] Info    [01242] PDCCH: UL DCI Format0  cce_index=0, L=4, n_data_bits=25, hex=[0f ca 20 00 ]22:02:45.793 [MAC ] Info    [01242] BSR:   Including BSR type Padding, format Long, nof_padding_bytes=12922:02:45.793 [MAC ] Info    [01242] UL 6:  New TX, RV=0, TBS=129, RNTI=3595322:02:45.793 [PHY ] Info    [01242] PUSCH: tti_tx=1246, n_prb=6, rb_start=1, tbs=129, mod=1, mcs=10, rv_idx=0, ack=no, cfo=-263.2 Hz, total_time= 376 us22:02:45.794 [PHY ] Info    [01243] PDCCH: UL DCI Format0  cce_index=0, L=4, n_data_bits=25, hex=[06 69 a0 00 ]22:02:45.794 [MAC ] Info    [01243] BSR:   Including BSR type Padding, format Long, nof_padding_bytes=5722:02:45.794 [MAC ] Info    [01243] UL 7:  New TX, RV=0, TBS=57, RNTI=3595322:02:45.794 [PHY ] Info    [01243] PUSCH: tti_tx=1247, n_prb=3, rb_start=1, tbs=57, mod=1, mcs=9, rv_idx=0, ack=no, cfo=-263.2 Hz, total_time= 373 us22:02:45.795 [PHY ] Info    [01244] PDCCH: UL DCI Format0  cce_index=0, L=4, n_data_bits=25, hex=[0f ca 20 00 ]22:02:45.795 [MAC ] Info    [01244] BSR:   Including BSR type Padding, format Long, nof_padding_bytes=12922:02:45.795 [MAC ] Info    [01244] UL 0:  New TX, RV=0, TBS=129, RNTI=3595322:02:45.795 [PHY ] Info    [01244] PUSCH: tti_tx=1248, n_prb=6, rb_start=1, tbs=129, mod=1, mcs=10, rv_idx=0, ack=no, cfo=-263.2 Hz, total_time= 367 us22:02:45.797 [PHY ] Info    [01245] PDCCH: UL DCI Format0  cce_index=4, L=4, n_data_bits=25, hex=[0f ca 20 00 ]22:02:45.797 [MAC ] Info    [01245] BSR:   Including BSR type Padding, format Long, nof_padding_bytes=12922:02:45.797 [MAC ] Info    [01245] UL 1:  New TX, RV=0, TBS=129, RNTI=3595322:02:45.797 [PHY ] Info    [01246] PUSCH: tti_tx=1249, n_prb=6, rb_start=1, tbs=129, mod=1, mcs=10, rv_idx=0, ack=no, cfo=-262.2 Hz, total_time= 493 us22:02:45.798 [PHY ] Info    [01247] PDCCH: DL DCI Format1  cce_index= 0, L=2, n_data_bits=27, hex=[7f 00 26 40 ]22:02:45.798 [PHY ] Info    [01247] PDSCH: l_crb=14, harq=1, tbs=61, mcs=1, rv=0, crc=OK, snr=10.5 dB, n_iter=1, dec_time=  32 us22:02:45.798 [PHY ] Info    [01247] PUCCH: power=-91.25 dBm, tti_tx=1251, n_cce=  0, ack=1, sr=no, cfo=-262.2 Hz, enc_time=148, total_time=391 us22:02:45.798 [MAC ] Info    [01247] DL 1:  newTX tbs=61, rv=0, ack=OK, ndi=1 (0), tti=1247 (0)22:02:45.798 [MAC ] Info    [01247] Delivering PDU for lcid=1, 45 bytes22:02:45.798 [RLC ] Info    SRB1 Rx data PDU SN: 0             0000: 00 0c 01 20 3a 90 06 36 d9 0d af 71 77 e7 84 bb              0010: b9 01 23 2f ab 17 78 84 25 16 13 b7 6a 7c 80 09 22:02:45.799 [PHY ] Info    [01248] PDCCH: DL DCI Format1  cce_index= 0, L=2, n_data_bits=27, hex=[60 00 0a 20 ]22:02:45.799 [PHY ] Info    [01248] PDSCH: l_crb= 4, harq=2, tbs=11, mcs=0, rv=0, crc=OK, snr=12.1 dB, n_iter=1, dec_time=  13 us22:02:45.799 [PHY ] Info    [01248] PHICH: hi=1, I_lowest=1, n_dmrs=022:02:45.799 [MAC ] Info    [01248] UL 4:  HARQ = ACK for UL transmission. Discarting TB.22:02:45.799 [PHY ] Info    [01248] PUCCH: power=-89.93 dBm, tti_tx=1252, n_cce=  0, ack=1, sr=no, cfo=-262.2 Hz, enc_time=156, total_time=392 us22:02:45.799 [MAC ] Info    [01248] DL 2:  newTX tbs=11, rv=0, ack=OK, ndi=1 (0), tti=1248 (0)22:02:45.799 [MAC ] Info    [01248] Delivering PDU for lcid=1, 3 bytes22:02:45.799 [RLC ] Info    SRB1 Rx data PDU SN: 1             0000: 00 22:02:45.799 [RLC ] Info    SRB1 Status packet requested through polling bit22:02:45.799 [RLC ] Info    SRB1 Rx SDU             0000: 00 0c 01 20 3a 90 06 36 d9 0d af 71 77 e7 84 bb              0010: b9 01 23 2f ab 17 78 84 25 16 13 b7 6a 7c 80 09 22:02:45.799 [PDCP] Info    RX SRB1 PDU             0000: 00 0c 01 20 3a 90 06 36 d9 0d af 71 77 e7 84 bb              0010: b9 01 23 2f ab 17 78 84 25 16 13 b7 6a 7c 80 09 22:02:45.799 [PDCP] Info    RX SRB1 SDU SN: 0             0000: 0c 01 20 3a 90 06 36 d9 0d af 71 77 e7 84 bb b9              0010: 01 23 2f ab 17 78 84 25 16 13 b7 6a 7c 80 09 53 22:02:45.799 [RRC ] Info    TX SRB1 PDU             0000: 0c 01 20 3a 90 06 36 d9 0d af 71 77 e7 84 bb b9              0010: 01 23 2f ab 17 78 84 25 16 13 b7 6a 7c 80 09 53 22:02:45.799 [RRC ] Info    TX PDU Stack latency: 26 us22:02:45.799 [RRC ] Info    SRB1 - Received DL Information Transfer22:02:45.799 [NAS ] Info    DL SRB1 PDU             0000: 07 52 00 c6 db 21 b5 ee 2e fc f0 97 77 20 24 65              0010: f5 62 ef 10 84 a2 c2 76 ed 4f 90 01 2a 6f 4b 02 22:02:45.799 [NAS ] Info    Received Authentication Request22:02:45.799 [NAS ] Info    MCC=1, MNC=122:02:45.799 [NAS ] Info    Network authentication successful22:02:45.799 [NAS ] Info    Sending Authentication Response22:02:45.799 [RRC ] Info    RX SRB1 SDU             0000: 07 53 08 02 44 d5 59 49 f2 9c 3c 22:02:45.799 [RRC ] Info    Sending RX Info Transfer22:02:45.799 [PDCP] Info    TX SRB1 SDU, do_security = false             0000: 48 01 60 ea 61 00 48 9a ab 29 3e 53 87 80 22:02:45.799 [RLC ] Info    SRB1 Tx SDU             0000: 01 48 01 60 ea 61 00 48 9a ab 29 3e 53 87 80 00              0010: 00 00 00 22:02:45.799 [MAC ] Info    [01249] BSR:   Triggered REGULAR BSR for Max Priority LCID=122:02:45.800 [PHY ] Info    [01249] PHICH: hi=1, I_lowest=1, n_dmrs=022:02:45.800 [MAC ] Info    [01249] UL 5:  HARQ = ACK for UL transmission. Discarting TB.22:02:45.800 [MAC ] Info    [01250] BSR:   Need to send sr: sr_is_sent=true, reset_sr=false, tti=1250, next_tx_tti=124922:02:45.800 [MAC ] Info    [01250] SR:    Signalling PHY sr_counter=122:02:45.801 [PHY ] Info    [01250] PHICH: hi=1, I_lowest=1, n_dmrs=022:02:45.801 [PHY ] Info    [01250] PDCCH: UL DCI Format0  cce_index=0, L=4, n_data_bits=25, hex=[0f ca 82 00 ]22:02:45.801 [PHY ] Info    [01250] PUSCH: Aperiodic CQI=6, SNR=13.7 dB, for 7 subbands22:02:45.801 [MAC ] Info    [01250] UL 6:  HARQ = ACK for UL transmission. Discarting TB.22:02:45.801 [RLC ] Info    SRB1 Tx status PDU - ACK_SN = 2, N_nack = 022:02:45.801 [MAC ] Info    [01250] SDU: rlc_buffer=2, allocated=2/126, max_sdu_sz=-1, remaining=12422:02:45.801 [RLC ] Info    SRB1 Complete SDU scheduled for tx. Stack latency: 1867 us22:02:45.801 [RLC ] Info    SRB1 PDU scheduled for tx. SN: 122:02:45.801 [MAC ] Info    [01250] SDU: rlc_buffer=21, allocated=21/122, max_sdu_sz=-1, remaining=10122:02:45.801 [MAC ] Info    [01250] UL 6:  New TX, RV=0, TBS=129, RNTI=3595322:02:45.802 [PHY ] Info    [01250] PUSCH: tti_tx=1254, n_prb=6, rb_start=1, tbs=129, mod=1, mcs=10, rv_idx=0, ack=no, cfo=-267.5 Hz, total_time= 408 us22:02:45.802 [PHY ] Info    [01251] PHICH: hi=1, I_lowest=1, n_dmrs=022:02:45.802 [PHY ] Info    [01251] PDCCH: UL DCI Format0  cce_index=0, L=4, n_data_bits=25, hex=[0f ca 22 00 ]22:02:45.802 [PHY ] Info    [01251] PUSCH: Aperiodic CQI=6, SNR=13.0 dB, for 7 subbands22:02:45.802 [MAC ] Info    [01251] UL 7:  HARQ = ACK for UL transmission. Discarting TB.22:02:45.802 [MAC ] Info    [01251] BSR:   Including BSR type Padding, format Long, nof_padding_bytes=12922:02:45.802 [MAC ] Info    [01251] UL 7:  New TX, RV=0, TBS=129, RNTI=3595322:02:45.802 [PHY ] Info    [01251] PUSCH: tti_tx=1255, n_prb=6, rb_start=1, tbs=129, mod=1, mcs=10, rv_idx=0, ack=no, cfo=-267.5 Hz, total_time= 364 us22:02:45.803 [PHY ] Info    [01252] PHICH: hi=1, I_lowest=1, n_dmrs=022:02:45.803 [PHY ] Info    [01252] PDCCH: UL DCI Format0  cce_index=0, L=4, n_data_bits=25, hex=[0f ca a2 00 ]22:02:45.803 [PHY ] Info    [01252] PUSCH: Aperiodic CQI=6, SNR=13.5 dB, for 7 subbands22:02:45.803 [MAC ] Info    [01252] UL 0:  HARQ = ACK for UL transmission. Discarting TB.22:02:45.803 [MAC ] Info    [01252] BSR:   Including BSR type Padding, format Long, nof_padding_bytes=12922:02:45.803 [MAC ] Info    [01252] UL 0:  New TX, RV=0, TBS=129, RNTI=3595322:02:45.803 [PHY ] Info    [01252] PUSCH: tti_tx=1256, n_prb=6, rb_start=1, tbs=129, mod=1, mcs=10, rv_idx=0, ack=no, cfo=-267.5 Hz, total_time= 383 us22:02:45.804 [PHY ] Info    [01253] PHICH: hi=1, I_lowest=1, n_dmrs=022:02:45.804 [PHY ] Info    [01253] PDCCH: UL DCI Format0  cce_index=0, L=4, n_data_bits=25, hex=[0f ca a2 00 ]22:02:45.804 [PHY ] Info    [01253] PUSCH: Aperiodic CQI=6, SNR=13.5 dB, for 7 subbands22:02:45.804 [MAC ] Info    [01253] UL 1:  HARQ = ACK for UL transmission. Discarting TB.22:02:45.804 [MAC ] Info    [01253] BSR:   Including BSR type Padding, format Long, nof_padding_bytes=12922:02:45.804 [MAC ] Info    [01253] UL 1:  New TX, RV=0, TBS=129, RNTI=3595322:02:45.804 [PHY ] Info    [01253] PUSCH: tti_tx=1257, n_prb=6, rb_start=1, tbs=129, mod=1, mcs=10, rv_idx=0, ack=no, cfo=-267.5 Hz, total_time= 386 us22:02:45.805 [PHY ] Info    [01254] PDCCH: UL DCI Format0  cce_index=0, L=4, n_data_bits=25, hex=[0f ca 22 00 ]22:02:45.805 [PHY ] Info    [01254] PUSCH: Aperiodic CQI=6, SNR=12.1 dB, for 7 subbands22:02:45.805 [MAC ] Info    [01254] BSR:   Including BSR type Padding, format Long, nof_padding_bytes=12922:02:45.805 [MAC ] Info    [01254] UL 2:  New TX, RV=0, TBS=129, RNTI=3595322:02:45.805 [PHY ] Info    [01254] PUSCH: tti_tx=1258, n_prb=6, rb_start=1, tbs=129, mod=1, mcs=10, rv_idx=0, ack=no, cfo=-267.5 Hz, total_time= 348 us22:02:45.806 [PHY ] Info    [01255] PDCCH: UL DCI Format0  cce_index=0, L=4, n_data_bits=25, hex=[0f ca 22 00 ]22:02:45.806 [PHY ] Info    [01255] PUSCH: Aperiodic CQI=5, SNR=11.6 dB, for 7 subbands22:02:45.806 [MAC ] Info    [01255] BSR:   Including BSR type Padding, format Long, nof_padding_bytes=12922:02:45.806 [MAC ] Info    [01255] UL 3:  New TX, RV=0, TBS=129, RNTI=3595322:02:45.806 [PHY ] Info    [01255] PUSCH: tti_tx=1259, n_prb=6, rb_start=1, tbs=129, mod=1, mcs=10, rv_idx=0, ack=no, cfo=-261.9 Hz, total_time= 354 us22:02:45.807 [PHY ] Info    [01256] PUCCH: SR transmission at TTI=1260, I_sr=522:02:45.807 [PHY ] Info    [01256] PUCCH: power=-91.44 dBm, tti_tx=1260, n_cce=  0, ack=no, sr=yes, cfo=-261.9 Hz, enc_time=156, total_time=252 us22:02:45.808 [PHY ] Info    [01257] PDCCH: DL DCI Format1  cce_index= 0, L=2, n_data_bits=27, hex=[40 00 ee 00 ]22:02:45.808 [PHY ] Info    [01257] PDSCH: l_crb= 2, harq=3, tbs=28, mcs=7, rv=0, crc=OK, snr=13.0 dB, n_iter=2, dec_time=  11 us22:02:45.808 [PHY ] Info    [01257] PUCCH: power=-91.73 dBm, tti_tx=1261, n_cce=  0, ack=1, sr=no, cfo=-261.9 Hz, enc_time=151, total_time=339 us22:02:45.808 [MAC ] Info    [01257] DL 3:  newTX tbs=28, rv=0, ack=OK, ndi=1 (0), tti=1257 (0)22:02:45.808 [MAC ] Info    [01257] Delivering PDU for lcid=1, 24 bytes22:02:45.808 [RLC ] Info    SRB1 Rx data PDU SN: 2             0000: 01 0e 00 71 be b4 87 10 08 00 3a e8 08 00 14 07              0010: 06 08 00 00 00 00 22:02:45.808 [RLC ] Info    SRB1 Status packet requested through polling bit22:02:45.808 [RLC ] Info    SRB1 Rx SDU             0000: 01 0e 00 71 be b4 87 10 08 00 3a e8 08 00 14 07              0010: 06 08 00 00 00 00 22:02:45.808 [PDCP] Info    RX SRB1 PDU             0000: 01 0e 00 71 be b4 87 10 08 00 3a e8 08 00 14 07              0010: 06 08 00 00 00 00 22:02:45.808 [PDCP] Info    RX SRB1 SDU SN: 1             0000: 0e 00 71 be b4 87 10 08 00 3a e8 08 00 14 07 06              0010: 08 22:02:45.808 [RRC ] Info    TX SRB1 PDU             0000: 0e 00 71 be b4 87 10 08 00 3a e8 08 00 14 07 06              0010: 08 22:02:45.808 [RRC ] Info    TX PDU Stack latency: 31 us22:02:45.808 [RRC ] Info    SRB1 - Received DL Information Transfer22:02:45.808 [NAS ] Info    DL SRB1 PDU             0000: 37 d6 90 e2 01 00 07 5d 01 00 02 80 e0 c1 22:02:45.808 [NAS ] Info    Received Security Mode Command22:02:45.808 [NAS ] Info    Sending Security Mode Complete nas_count_ul=0, RB=SRB122:02:45.808 [RRC ] Info    RX SRB1 SDU             0000: 27 54 cb 92 3b 00 07 5e 23 09 83 96 09 07 82 45              0010: 61 56 f3 22:02:45.808 [RRC ] Info    Sending RX Info Transfer22:02:45.808 [PDCP] Info    TX SRB1 SDU, do_security = false             0000: 48 02 64 ea 99 72 47 60 00 eb c4 61 30 72 c1 20              0010: f0 48 ac 2a de 60 22:02:45.808 [RLC ] Info    SRB1 Tx SDU             0000: 02 48 02 64 ea 99 72 47 60 00 eb c4 61 30 72 c1              0010: 20 f0 48 ac 2a de 60 00 00 00 00 22:02:45.808 [MAC ] Info    [01258] BSR:   Triggered REGULAR BSR for Max Priority LCID=122:02:45.809 [PHY ] Info    [01258] PHICH: hi=1, I_lowest=1, n_dmrs=022:02:45.809 [MAC ] Info    [01258] UL 6:  HARQ = ACK for UL transmission. Discarting TB.22:02:45.810 [PHY ] Info    [01259] PHICH: hi=1, I_lowest=1, n_dmrs=022:02:45.810 [MAC ] Info    [01259] UL 7:  HARQ = ACK for UL transmission. Discarting TB.22:02:45.810 [MAC ] Info    [01260] BSR:   Need to send sr: sr_is_sent=true, reset_sr=false, tti=1260, next_tx_tti=125922:02:45.810 [MAC ] Info    [01260] SR:    Signalling PHY sr_counter=122:02:45.811 [PHY ] Info    [01260] PHICH: hi=1, I_lowest=1, n_dmrs=022:02:45.811 [PHY ] Info    [01260] PDCCH: UL DCI Format0  cce_index=0, L=4, n_data_bits=25, hex=[0f ca 02 00 ]22:02:45.811 [PHY ] Info    [01260] PUSCH: Aperiodic CQI=6, SNR=13.6 dB, for 7 subbands22:02:45.811 [MAC ] Info    [01260] UL 0:  HARQ = ACK for UL transmission. Discarting TB.22:02:45.811 [RLC ] Info    SRB1 Tx status PDU - ACK_SN = 3, N_nack = 022:02:45.811 [MAC ] Info    [01260] SDU: rlc_buffer=2, allocated=2/126, max_sdu_sz=-1, remaining=12422:02:45.811 [RLC ] Info    SRB1 Complete SDU scheduled for tx. Stack latency: 3005 us22:02:45.811 [RLC ] Info    SRB1 PDU scheduled for tx. SN: 222:02:45.811 [MAC ] Info    [01260] SDU: rlc_buffer=29, allocated=29/122, max_sdu_sz=-1, remaining=9322:02:45.811 [MAC ] Info    [01260] UL 0:  New TX, RV=0, TBS=129, RNTI=3595322:02:45.811 [PHY ] Info    [01260] PUSCH: tti_tx=1264, n_prb=6, rb_start=1, tbs=129, mod=1, mcs=10, rv_idx=0, ack=no, cfo=-258.5 Hz, total_time= 398 us22:02:45.812 [PHY ] Info    [01261] PHICH: hi=1, I_lowest=1, n_dmrs=022:02:45.812 [PHY ] Info    [01261] PDCCH: UL DCI Format0  cce_index=0, L=4, n_data_bits=25, hex=[0f ca 22 00 ]22:02:45.812 [PHY ] Info    [01261] PUSCH: Aperiodic CQI=6, SNR=12.5 dB, for 7 subbands22:02:45.812 [MAC ] Info    [01261] UL 1:  HARQ = ACK for UL transmission. Discarting TB.22:02:45.812 [MAC ] Info    [01261] BSR:   Including BSR type Padding, format Long, nof_padding_bytes=12922:02:45.812 [MAC ] Info    [01261] UL 1:  New TX, RV=0, TBS=129, RNTI=3595322:02:45.812 [PHY ] Info    [01261] PUSCH: tti_tx=1265, n_prb=6, rb_start=1, tbs=129, mod=1, mcs=10, rv_idx=0, ack=no, cfo=-258.5 Hz, total_time= 372 us22:02:45.813 [PHY ] Info    [01262] PHICH: hi=1, I_lowest=1, n_dmrs=022:02:45.813 [PHY ] Info    [01262] PDCCH: UL DCI Format0  cce_index=0, L=4, n_data_bits=25, hex=[0f ca a2 00 ]22:02:45.813 [PHY ] Info    [01262] PUSCH: Aperiodic CQI=6, SNR=12.7 dB, for 7 subbands22:02:45.813 [MAC ] Info    [01262] UL 2:  HARQ = ACK for UL transmission. Discarting TB.22:02:45.813 [MAC ] Info    [01262] BSR:   Including BSR type Padding, format Long, nof_padding_bytes=12922:02:45.813 [MAC ] Info    [01262] UL 2:  New TX, RV=0, TBS=129, RNTI=3595322:02:45.813 [PHY ] Info    [01262] PUSCH: tti_tx=1266, n_prb=6, rb_start=1, tbs=129, mod=1, mcs=10, rv_idx=0, ack=no, cfo=-258.5 Hz, total_time= 361 us22:02:45.814 [PHY ] Info    [01263] PHICH: hi=1, I_lowest=1, n_dmrs=022:02:45.814 [PHY ] Info    [01263] PDCCH: UL DCI Format0  cce_index=0, L=4, n_data_bits=25, hex=[06 69 a2 00 ]22:02:45.814 [PHY ] Info    [01263] PUSCH: Aperiodic CQI=6, SNR=12.3 dB, for 7 subbands22:02:45.814 [MAC ] Info    [01263] UL 3:  HARQ = ACK for UL transmission. Discarting TB.22:02:45.814 [MAC ] Info    [01263] BSR:   Including BSR type Padding, format Long, nof_padding_bytes=5722:02:45.814 [MAC ] Info    [01263] UL 3:  New TX, RV=0, TBS=57, RNTI=3595322:02:45.814 [PHY ] Info    [01263] PUSCH: tti_tx=1267, n_prb=3, rb_start=1, tbs=57, mod=1, mcs=9, rv_idx=0, ack=no, cfo=-258.5 Hz, total_time= 346 us22:02:45.815 [PHY ] Info    [01264] PDCCH: UL DCI Format0  cce_index=0, L=4, n_data_bits=25, hex=[0f ca a2 00 ]22:02:45.815 [PHY ] Info    [01264] PUSCH: Aperiodic CQI=5, SNR=11.9 dB, for 7 subbands22:02:45.815 [MAC ] Info    [01264] BSR:   Including BSR type Padding, format Long, nof_padding_bytes=12922:02:45.815 [MAC ] Info    [01264] UL 4:  New TX, RV=0, TBS=129, RNTI=3595322:02:45.815 [PHY ] Info    [01264] PUSCH: tti_tx=1268, n_prb=6, rb_start=1, tbs=129, mod=1, mcs=10, rv_idx=0, ack=no, cfo=-258.5 Hz, total_time= 373 us22:02:45.816 [PHY ] Info    [01265] PDCCH: UL DCI Format0  cce_index=4, L=4, n_data_bits=25, hex=[0f ca a2 00 ]22:02:45.816 [PHY ] Info    [01265] PUSCH: Aperiodic CQI=6, SNR=12.2 dB, for 7 subbands22:02:45.816 [MAC ] Info    [01265] BSR:   Including BSR type Padding, format Long, nof_padding_bytes=12922:02:45.816 [MAC ] Info    [01265] UL 5:  New TX, RV=0, TBS=129, RNTI=3595322:02:45.817 [PHY ] Info    [01265] PUSCH: tti_tx=1269, n_prb=6, rb_start=1, tbs=129, mod=1, mcs=10, rv_idx=0, ack=no, cfo=-263.4 Hz, total_time= 484 us22:02:45.817 [PHY ] Info    [01266] PUCCH: SR transmission at TTI=1270, I_sr=522:02:45.817 [PHY ] Info    [01266] PUCCH: power=-89.99 dBm, tti_tx=1270, n_cce=  0, ack=no, sr=yes, cfo=-263.4 Hz, enc_time=155, total_time=282 us22:02:45.818 [PHY ] Info    [01267] PDCCH: DL DCI Format1  cce_index= 0, L=2, n_data_bits=27, hex=[40 00 72 00 ]22:02:45.818 [PHY ] Info    [01267] PDSCH: l_crb= 2, harq=4, tbs=13, mcs=3, rv=0, crc=OK, snr=12.6 dB, n_iter=1, dec_time=   7 us22:02:45.818 [PHY ] Info    [01267] PUCCH: power=-90.80 dBm, tti_tx=1271, n_cce=  0, ack=1, sr=no, cfo=-263.4 Hz, enc_time=147, total_time=361 us22:02:45.818 [MAC ] Info    [01267] DL 4:  newTX tbs=13, rv=0, ack=OK, ndi=1 (0), tti=1267 (0)22:02:45.818 [MAC ] Info    [01267] Delivering PDU for lcid=1, 10 bytes


1 0