See https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/137/display/redirect
Changes:
------------------------------------------ [...truncated 45.14 MiB...] [1;32m20241024140021714 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=7,ts=7) FN=91 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021715 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=0,ts=7) FN=95 RX RTS.req: sapi=5 arfcn=871 cur_fn=91 block=10 (pcu_l1_if.cpp:576)[0;m [0;36m20241024140021715 [1;34mDRLCMACSCHED[0;m[0;36m [1;34mDEBUG[0;m[0;36m PDCH(bts=0,trx=0,ts=7) Received RTS for PDCH: FN=95 block_nr=10 scheduling USF=0 for TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW}, expect answer on UL FN=99 (gprs_rlcmac_sched.cpp:454)[0;m [0;33m20241024140021715 [1;34mDRLCMAC[0;m[0;33m [1;34mDEBUG[0;m[0;33m PDCH(bts=0,trx=0,ts=7) Reserving FN 99 for type USF (pdch_ul_controller.c:184)[0;m [1;37m20241024140021715 [1;32mDNACC[0;m[1;37m [1;32mINFO[0;m[1;37m NACC(TLLI-0x00000001){TX_NEIGHBOUR_DATA}: Received Event CREATE_RLCMAC_MSG (gprs_ms.c:1078)[0;m [1;37m20241024140021715 [1;34mDNACC[0;m[1;37m [1;34mDEBUG[0;m[1;37m +++++++++++++++++++++++++ TX : Packet Neighbour Cell Data +++++++++++++++++++++++++ (nacc_fsm.c:139)[0;m [1;31m20241024140021715 [1;32mDCSN1[0;m[1;31m [1;32mINFO[0;m[1;31m csnStreamEncoder (type: Pkt Neightbour Cell Data (12)): [0;m[1;31mMESSAGE_TYPE = 12 | [0;m[1;31mPAGE_MODE = 0 | [0;m[1;31m0x00 = 0 | [0;m[1;31m : Global_TFI | [0;m[1;31mu.UPLINK_TFI = 0 | [0;m[1;31mu.UPLINK_TFI = 0 | [0;m[1;31m : End Global_TFI | [0;m[1;31mCONTAINER_ID = 0 | [0;m[1;31mspare = 0 | [0;m[1;31mCONTAINER_INDEX = 3 | [0;m[1;31m : Container | [0;m[1;31mu.PNCD_Container_Without_ID = 0 | [0;m[1;31m : u.PNCD_Container_Without_ID | [0;m[1;31mCONTAINER = 11 | [0;m[1;31mCONTAINER = 171 | [0;m[1;31mCONTAINER = 43 | [0;m[1;31mCONTAINER = 43 | [0;m[1;31mCONTAINER = 43 | [0;m[1;31mCONTAINER = 43 | [0;m[1;31mCONTAINER = 43 | [0;m[1;31mCONTAINER = 43 | [0;m[1;31mCONTAINER = 43 | [0;m[1;31mCONTAINER = 43 | [0;m[1;31mCONTAINER = 43 | [0;m[1;31mCONTAINER = 43 | [0;m[1;31mCONTAINER = 0 | [0;m[1;31mCONTAINER = 0 | [0;m[1;31mCONTAINER = 0 | [0;m[1;31mCONTAINER = 0 | [0;m[1;31mCONTAINER = 0 | [0;m[1;31mCONTAINER = 0 | [0;m[1;31mCONTAINER = 0 | [0;m[1;31m : End u.PNCD_Container_Without_ID | [0;m[1;31m : End Container | [0;m[1;31mPadding = [0;m[1;31m (gsm_rlcmac.c:6009)[0;m [1;37m20241024140021716 [1;34mDNACC[0;m[1;37m [1;34mDEBUG[0;m[1;37m ------------------------- TX : Packet Neighbour Cell Data ------------------------- (nacc_fsm.c:145)[0;m [1;37m20241024140021716 [1;32mDNACC[0;m[1;37m [1;32mINFO[0;m[1;37m NACC(TLLI-0x00000001){TX_NEIGHBOUR_DATA}: state_chg to TX_CELL_CHG_CONTINUE (nacc_fsm.c:620)[0;m [0;36m20241024140021716 [1;34mDRLCMACSCHED[0;m[0;36m [1;34mDEBUG[0;m[0;36m PDCH(bts=0,trx=0,ts=7) FN=95 Scheduling control message at RTS for TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} (gprs_rlcmac_sched.cpp:202)[0;m [1;32m20241024140021716 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=0,ts=7) FN=95 Sending data request: sapi=5 arfcn=871 cur_fn=91 block=10 data=40 30 00 06 0b ab 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 00 00 00 00 00 00 (pcu_l1_if.cpp:182)[0;m [1;32m20241024140021716 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m Time indication received: 43 (pcu_l1_if.cpp:1048)[0;m [1;32m20241024140021727 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=0,ts=7) FN=95 Rx DATA.ind: sapi=5 arfcn=871 cur_fn=91 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021727 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=0,ts=7) FN=95 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [0;33m20241024140021727 [1;32mDRLCMAC[0;m[0;33m [1;32mINFO[0;m[0;33m PDCH(bts=0,trx=0,ts=7) Timeout for registered USF (FN=95): TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} (pdch_ul_controller.c:309)[0;m [1;34m20241024140021727 [1;34mDTBF[0;m[1;34m [1;34mDEBUG[0;m[1;34m TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} N3101 2 => 3 (< MAX 10) (tbf.cpp:362)[0;m [1;32m20241024140021729 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=1,ts=7) FN=95 Rx DATA.ind: sapi=5 arfcn=872 cur_fn=95 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021729 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=1,ts=7) FN=95 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021730 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=2,ts=7) FN=95 Rx DATA.ind: sapi=5 arfcn=873 cur_fn=95 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021730 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=2,ts=7) FN=95 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021731 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=3,ts=7) FN=95 Rx DATA.ind: sapi=5 arfcn=874 cur_fn=95 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021731 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=3,ts=7) FN=95 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021732 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=4,ts=7) FN=95 Rx DATA.ind: sapi=5 arfcn=875 cur_fn=95 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021732 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=4,ts=7) FN=95 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021733 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=5,ts=7) FN=95 Rx DATA.ind: sapi=5 arfcn=876 cur_fn=95 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021733 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=5,ts=7) FN=95 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021733 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=6,ts=7) FN=95 Rx DATA.ind: sapi=5 arfcn=877 cur_fn=95 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021733 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=6,ts=7) FN=95 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021734 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=7,ts=7) FN=95 Rx DATA.ind: sapi=5 arfcn=878 cur_fn=95 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021734 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=7,ts=7) FN=95 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021735 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=0,ts=7) FN=99 RX RTS.req: sapi=5 arfcn=871 cur_fn=95 block=11 (pcu_l1_if.cpp:576)[0;m [0;36m20241024140021735 [1;34mDRLCMACSCHED[0;m[0;36m [1;34mDEBUG[0;m[0;36m PDCH(bts=0,trx=0,ts=7) Received RTS for PDCH: FN=99 block_nr=11 scheduling USF=0 for TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW}, expect answer on UL FN=104 (gprs_rlcmac_sched.cpp:454)[0;m [0;33m20241024140021735 [1;34mDRLCMAC[0;m[0;33m [1;34mDEBUG[0;m[0;33m PDCH(bts=0,trx=0,ts=7) Reserving FN 104 for type USF (pdch_ul_controller.c:184)[0;m [1;37m20241024140021735 [1;32mDNACC[0;m[1;37m [1;32mINFO[0;m[1;37m NACC(TLLI-0x00000001){TX_CELL_CHG_CONTINUE}: Received Event CREATE_RLCMAC_MSG (gprs_ms.c:1078)[0;m [0;33m20241024140021735 [1;34mDRLCMAC[0;m[0;33m [1;34mDEBUG[0;m[0;33m PDCH(bts=0,trx=0,ts=7) POLL scheduled at FN 99 + 13 = 112 (pdch_ul_controller.c:131)[0;m [1;37m20241024140021735 [1;34mDNACC[0;m[1;37m [1;34mDEBUG[0;m[1;37m +++++++++++++++++++++++++ TX : Packet Cell Change Continue +++++++++++++++++++++++++ (nacc_fsm.c:196)[0;m [1;31m20241024140021735 [1;32mDCSN1[0;m[1;31m [1;32mINFO[0;m[1;31m csnStreamEncoder (type: Pkt Cell Change Continue (11)): [0;m[1;31mMESSAGE_TYPE = 11 | [0;m[1;31mPAGE_MODE = 0 | [0;m[1;31m0x00 = 0 | [0;m[1;31m : Global_TFI | [0;m[1;31mu.UPLINK_TFI = 0 | [0;m[1;31mu.UPLINK_TFI = 0 | [0;m[1;31m : End Global_TFI | [0;m[1;31mExist_ID = 1 | [0;m[1;31mARFCN = 862 | [0;m[1;31mBSIC = 43 | [0;m[1;31mCONTAINER_ID = 0 | [0;m[1;31mPadding = [0;m[1;31m11|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m (gsm_rlcmac.c:6009)[0;m [1;37m20241024140021736 [1;34mDNACC[0;m[1;37m [1;34mDEBUG[0;m[1;37m ------------------------- TX : Packet Cell Change Continue ------------------------- (nacc_fsm.c:202)[0;m [0;33m20241024140021736 [1;34mDRLCMAC[0;m[0;33m [1;34mDEBUG[0;m[0;33m PDCH(bts=0,trx=0,ts=7) Reserving FN 112 for type POLL (pdch_ul_controller.c:184)[0;m [1;34m20241024140021736 [1;34mDTBF[0;m[1;34m [1;34mDEBUG[0;m[1;34m TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} Scheduled 'Packet Cell Change Continue' polling on PACCH (FN=112, TS=7) (nacc_fsm.c:206)[0;m [1;37m20241024140021736 [1;32mDNACC[0;m[1;37m [1;32mINFO[0;m[1;37m NACC(TLLI-0x00000001){TX_CELL_CHG_CONTINUE}: state_chg to WAIT_CELL_CHG_CONTINUE_ACK (nacc_fsm.c:649)[0;m [0;36m20241024140021736 [1;34mDRLCMACSCHED[0;m[0;36m [1;34mDEBUG[0;m[0;36m PDCH(bts=0,trx=0,ts=7) FN=99 Scheduling control message at RTS for TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} (gprs_rlcmac_sched.cpp:202)[0;m [1;32m20241024140021736 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=0,ts=7) FN=99 Sending data request: sapi=5 arfcn=871 cur_fn=95 block=11 data=48 2c 01 d7 ab 0b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b (pcu_l1_if.cpp:182)[0;m [1;32m20241024140021736 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m Time indication received: 47 (pcu_l1_if.cpp:1048)[0;m BTS(1073)@9541a9c1d226: Warning: dec_RlcmacDlCtrlBlock(): Data remained at the end of the stream after successful decoding: '0B2B2B2B2B2B2B2B2B2B2B2B2B2B2B2B2B2B'O ("\v+++++++++++++++++") [1;32m20241024140021747 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=0,ts=7) FN=99 Rx DATA.ind: sapi=5 arfcn=871 cur_fn=95 block=11 data=40 30 06 bd 58 00 00 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021747 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=0,ts=7) FN=99 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 0 (pcu_l1_if.cpp:478)[0;m [1;36m20241024140021747 [1;34mDRLCMACUL[0;m[1;36m [1;34mDEBUG[0;m[1;36m PDCH(bts=0,trx=0,ts=7) Got RLC block, coding scheme: CS-1, length: 23 (23)) (pdch.cpp:983)[0;m [0;33m20241024140021747 [1;34mDRLCMAC[0;m[0;33m [1;34mDEBUG[0;m[0;33m PDCH(bts=0,trx=0,ts=7) FN=99 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ (pdch.cpp:914)[0;m [1;31m20241024140021747 [1;32mDCSN1[0;m[1;31m [1;32mINFO[0;m[1;31m csnStreamDecoder (type: Pkt Cell Change Notification (12)): [0;m[1;31mPayloadType = 1 | [0;m[1;31mspare = 0 | [0;m[1;31mR = 0 | [0;m[1;31mMESSAGE_TYPE = 12 | [0;m[1;31m : Global_TFI | [0;m[1;31mu.UPLINK_TFI = 0 | [0;m[1;31mu.UPLINK_TFI = 0 | [0;m[1;31m: End Global_TFI | [0;m[1;31m : Target_Cell | [0;m[1;31mu.Target_Cell_GSM_Notif = 0 | [0;m[1;31m : u.Target_Cell_GSM_Notif | [0;m[1;31mARFCN = 862 | [0;m[1;31mBSIC = 43 | [0;m[1;31m : End u.Target_Cell_GSM_Notif | [0;m[1;31m: End Target_Cell | [0;m[1;31mu.BA_IND = 0 | [0;m[1;31mu.BA_IND = 0 | [0;m[1;31mPMO_USED = 0 | [0;m[1;31mPCCN_SENDING = 0 | [0;m[1;31m : CCN_Measurement_Report | [0;m[1;31mRXLEV_SERVING_CELL = 0 | [0;m[1;31m0 = 0 | [0;m[1;31mNUMBER_OF_NC_MEASUREMENTS = 0 | [0;m[1;31m: End CCN_Measurement_Report | [0;m[1;31mExist_AdditionsR6 = 0 | [0;m[1;31mPadding = [0;m[1;31m0|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m (gsm_rlcmac.c:5476)[0;m [0;33m20241024140021748 [1;34mDRLCMAC[0;m[0;33m [1;34mDEBUG[0;m[0;33m PDCH(bts=0,trx=0,ts=7) FN=99 ------------------------- RX : Uplink Control Block ------------------------- (pdch.cpp:927)[0;m [1;37m20241024140021748 [1;32mDNACC[0;m[1;37m [1;32mINFO[0;m[1;37m NACC(TLLI-0x00000001){WAIT_CELL_CHG_CONTINUE_ACK}: Received Event RX_CELL_CHG_NOTIFICATION (gprs_ms.c:1052)[0;m [1;37m20241024140021748 [1;33mDNACC[0;m[1;37m [1;33mNOTICE[0;m[1;37m NACC(TLLI-0x00000001){WAIT_CELL_CHG_CONTINUE_ACK}: TargetCell: RAT=GSM, ARFCN=862, BSIC=43 (nacc_fsm.c:291)[0;m [1;32m20241024140021750 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=1,ts=7) FN=99 Rx DATA.ind: sapi=5 arfcn=872 cur_fn=99 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021750 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=1,ts=7) FN=99 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021752 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=2,ts=7) FN=99 Rx DATA.ind: sapi=5 arfcn=873 cur_fn=99 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021752 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=2,ts=7) FN=99 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021753 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=3,ts=7) FN=99 Rx DATA.ind: sapi=5 arfcn=874 cur_fn=99 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021753 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=3,ts=7) FN=99 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021754 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=4,ts=7) FN=99 Rx DATA.ind: sapi=5 arfcn=875 cur_fn=99 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021754 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=4,ts=7) FN=99 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021754 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=5,ts=7) FN=99 Rx DATA.ind: sapi=5 arfcn=876 cur_fn=99 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021754 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=5,ts=7) FN=99 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021754 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=6,ts=7) FN=99 Rx DATA.ind: sapi=5 arfcn=877 cur_fn=99 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021755 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=6,ts=7) FN=99 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021755 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=7,ts=7) FN=99 Rx DATA.ind: sapi=5 arfcn=878 cur_fn=99 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021755 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=7,ts=7) FN=99 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021756 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m Time indication received: 0 (pcu_l1_if.cpp:1048)[0;m [1;32m20241024140021771 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=0,ts=7) FN=104 Rx DATA.ind: sapi=5 arfcn=871 cur_fn=99 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021771 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=0,ts=7) FN=104 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [0;33m20241024140021772 [1;32mDRLCMAC[0;m[0;33m [1;32mINFO[0;m[0;33m PDCH(bts=0,trx=0,ts=7) Timeout for registered USF (FN=104): TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} (pdch_ul_controller.c:309)[0;m [1;34m20241024140021772 [1;34mDTBF[0;m[1;34m [1;34mDEBUG[0;m[1;34m TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} N3101 3 => 4 (< MAX 10) (tbf.cpp:362)[0;m [1;32m20241024140021773 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=1,ts=7) FN=104 Rx DATA.ind: sapi=5 arfcn=872 cur_fn=104 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021773 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=1,ts=7) FN=104 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021774 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=2,ts=7) FN=104 Rx DATA.ind: sapi=5 arfcn=873 cur_fn=104 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021774 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=2,ts=7) FN=104 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021775 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=3,ts=7) FN=104 Rx DATA.ind: sapi=5 arfcn=874 cur_fn=104 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021775 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=3,ts=7) FN=104 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021775 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=4,ts=7) FN=104 Rx DATA.ind: sapi=5 arfcn=875 cur_fn=104 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021775 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=4,ts=7) FN=104 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021776 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=5,ts=7) FN=104 Rx DATA.ind: sapi=5 arfcn=876 cur_fn=104 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021776 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=5,ts=7) FN=104 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021777 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=6,ts=7) FN=104 Rx DATA.ind: sapi=5 arfcn=877 cur_fn=104 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021777 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=6,ts=7) FN=104 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021778 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=7,ts=7) FN=104 Rx DATA.ind: sapi=5 arfcn=878 cur_fn=104 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021778 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=7,ts=7) FN=104 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021779 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m Time indication received: 4 (pcu_l1_if.cpp:1048)[0;m [1;32m20241024140021790 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=0,ts=7) FN=108 Rx DATA.ind: sapi=5 arfcn=871 cur_fn=104 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021790 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=0,ts=7) FN=108 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021791 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=1,ts=7) FN=108 Rx DATA.ind: sapi=5 arfcn=872 cur_fn=108 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021791 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=1,ts=7) FN=108 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021792 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=2,ts=7) FN=108 Rx DATA.ind: sapi=5 arfcn=873 cur_fn=108 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021792 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=2,ts=7) FN=108 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021792 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=3,ts=7) FN=108 Rx DATA.ind: sapi=5 arfcn=874 cur_fn=108 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021792 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=3,ts=7) FN=108 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021793 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=4,ts=7) FN=108 Rx DATA.ind: sapi=5 arfcn=875 cur_fn=108 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021793 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=4,ts=7) FN=108 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021794 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=5,ts=7) FN=108 Rx DATA.ind: sapi=5 arfcn=876 cur_fn=108 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021794 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=5,ts=7) FN=108 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021795 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=6,ts=7) FN=108 Rx DATA.ind: sapi=5 arfcn=877 cur_fn=108 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021795 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=6,ts=7) FN=108 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021795 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=7,ts=7) FN=108 Rx DATA.ind: sapi=5 arfcn=878 cur_fn=108 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021795 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=7,ts=7) FN=108 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021796 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m Time indication received: 8 (pcu_l1_if.cpp:1048)[0;m [1;32m20241024140021809 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=0,ts=7) FN=112 Rx DATA.ind: sapi=5 arfcn=871 cur_fn=108 block=2 data=40 04 00 00 00 07 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021809 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=0,ts=7) FN=112 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 0 (pcu_l1_if.cpp:478)[0;m [1;36m20241024140021809 [1;34mDRLCMACUL[0;m[1;36m [1;34mDEBUG[0;m[1;36m PDCH(bts=0,trx=0,ts=7) Got RLC block, coding scheme: CS-1, length: 23 (23)) (pdch.cpp:983)[0;m [0;33m20241024140021809 [1;34mDRLCMAC[0;m[0;33m [1;34mDEBUG[0;m[0;33m PDCH(bts=0,trx=0,ts=7) FN=112 +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ (pdch.cpp:914)[0;m [1;31m20241024140021809 [1;32mDCSN1[0;m[1;31m [1;32mINFO[0;m[1;31m csnStreamDecoder (type: Pkt Control Ack (1)): [0;m[1;31mPayloadType = 1 | [0;m[1;31mspare = 0 | [0;m[1;31mR = 0 | [0;m[1;31mMESSAGE_TYPE = 1 | [0;m[1;31mTLLI = 0x00000001 | [0;mBTS(1073)@9541a9c1d226: Shutting down virtual BTS #0... [1;31mCTRL_ACK = 3 | [0;m[1;31mExist_AdditionsR5 = 0 | [0;m[1;31mPadding = [0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m43|[0;m[1;31m (gsm_rlcmac.c:5476)[0;m [0;33m20241024140021809 [1;34mDRLCMAC[0;m[0;33m [1;34mDEBUG[0;m[0;33m PDCH(bts=0,trx=0,ts=7) FN=112 ------------------------- RX : Uplink Control Block ------------------------- (pdch.cpp:927)[0;m [1;34m20241024140021810 [1;34mDTBF[0;m[1;34m [1;34mDEBUG[0;m[1;34m TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} FN=112 Rx Packet Control Ack (reason=CELL_CHG_CONTINUE) (pdch.cpp:363)[0;m [1;37m20241024140021810 [1;32mDNACC[0;m[1;37m [1;32mINFO[0;m[1;37m NACC(TLLI-0x00000001){WAIT_CELL_CHG_CONTINUE_ACK}: Received Event RX_CELL_CHG_CONTINUE_ACK (pdch.cpp:449)[0;m [1;37m20241024140021810 [1;32mDNACC[0;m[1;37m [1;32mINFO[0;m[1;37m NACC(TLLI-0x00000001){WAIT_CELL_CHG_CONTINUE_ACK}: state_chg to DONE (nacc_fsm.c:671)[0;m [1;37m20241024140021810 [1;32mDNACC[0;m[1;37m [1;32mINFO[0;m[1;37m NACC(TLLI-0x00000001){DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) (nacc_fsm.c:681)[0;m [1;37m20241024140021810 [1;32mDNACC[0;m[1;37m [1;32mINFO[0;m[1;37m NACC(TLLI-0x00000001){DONE}: Freeing instance (nacc_fsm.c:681)[0;m [1;37m20241024140021810 [1;32mDNACC[0;m[1;37m [1;32mINFO[0;m[1;37m NACC(TLLI-0x00000001){DONE}: Deallocated (fsm.c:568)[0;m [1;32m20241024140021811 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=1,ts=7) FN=112 Rx DATA.ind: sapi=5 arfcn=872 cur_fn=112 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021811 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=1,ts=7) FN=112 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021812 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=2,ts=7) FN=112 Rx DATA.ind: sapi=5 arfcn=873 cur_fn=112 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021812 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=2,ts=7) FN=112 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021814 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=3,ts=7) FN=112 Rx DATA.ind: sapi=5 arfcn=874 cur_fn=112 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021814 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=3,ts=7) FN=112 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m 20241024140021814 [1;32mDLGLOBAL[0;m [1;32mINFO[0;m Closing telnet connection r=127.0.0.1:44156<->l=127.0.0.1:4240 (telnet_interface.c:138) [1;32m20241024140021815 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=4,ts=7) FN=112 Rx DATA.ind: sapi=5 arfcn=875 cur_fn=112 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021815 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=4,ts=7) FN=112 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021816 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=5,ts=7) FN=112 Rx DATA.ind: sapi=5 arfcn=876 cur_fn=112 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021816 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=5,ts=7) FN=112 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021817 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=6,ts=7) FN=112 Rx DATA.ind: sapi=5 arfcn=877 cur_fn=112 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021817 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=6,ts=7) FN=112 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m [1;32m20241024140021819 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m (bts=0,trx=7,ts=7) FN=112 Rx DATA.ind: sapi=5 arfcn=878 cur_fn=112 block=0 data= (pcu_l1_if.cpp:463)[0;m [1;32m20241024140021819 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m PDCH(bts=0,trx=7,ts=7) FN=112 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10 (pcu_l1_if.cpp:478)[0;m 20241024140021823 [1;32mDLGLOBAL[0;m [1;32mINFO[0;m Closing telnet connection r=127.0.0.1:44152<->l=127.0.0.1:4240 (telnet_interface.c:138) [1;32m20241024140021825 [1;31mDL1IF[0;m[1;32m [1;31mERROR[0;m[1;32m pcu_sock_read: recv() failed with rc=0 errno=9 (pcuif_sock.c:123)[0;m [1;32m20241024140021825 [1;33mDL1IF[0;m[1;32m [1;33mNOTICE[0;m[1;32m PCU socket has LOST connection (pcuif_sock.c:78)[0;m [0;33m20241024140021825 [1;32mDRLCMAC[0;m[0;33m [1;32mINFO[0;m[0;33m PDCH(bts=0,trx=0,ts=7) PDCH state: enabled => disabled (pdch.cpp:184)[0;m [1;34m20241024140021825 [1;32mDTBF[0;m[1;34m [1;32mINFO[0;m[1;34m TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} free (tbf.cpp:271)[0;m [0;33m20241024140021825 [1;32mDRLCMAC[0;m[0;33m [1;32mINFO[0;m[0;33m PDCH(bts=0,trx=0,ts=7) Detaching TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW}, 1 TBFs, USFs = 01, TFIs = 00000001. (pdch.cpp:1202)[0;m [1;34m20241024140021825 [1;32mDMS[0;m[1;34m [1;32mINFO[0;m[1;34m MS(TLLI-0x00000001:TA-0:MSCLS-3-0:UL) Detaching TBF: TBF(UL:G:TLLI-0x00000001){FLOW} (gprs_ms.c:381)[0;m [1;34m20241024140021825 [1;32mDMS[0;m[1;34m [1;32mINFO[0;m[1;34m MS(TLLI-0x00000001:TA-0:MSCLS-3-0): - tbf: now used by 0 (-) (gprs_ms.c:394)[0;m [1;34m20241024140021826 [1;32mDMS[0;m[1;34m [1;32mINFO[0;m[1;34m MS(TLLI-0x00000001:TA-0:MSCLS-3-0) Schedule MS release in 60 secs (gprs_ms.c:246)[0;m [1;34m20241024140021826 [1;34mDTBF[0;m[1;34m [1;34mDEBUG[0;m[1;34m ********** UL-TBF ends here ********** (tbf.cpp:279)[0;m [1;34m20241024140021826 [1;32mDTBFUL[0;m[1;34m [1;32mINFO[0;m[1;34m UL_ACK_TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){NONE}: Deallocated (fsm.c:568)[0;m [1;34m20241024140021826 [1;32mDTBFUL[0;m[1;34m [1;32mINFO[0;m[1;34m UL_TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW}: Deallocated (fsm.c:568)[0;m [1;34m20241024140021826 [1;32mDTBF[0;m[1;34m [1;32mINFO[0;m[1;34m UL_ASS_TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){NONE}: Deallocated (fsm.c:568)[0;m [1;34m20241024140021826 [1;32mDTBF[0;m[1;34m [1;32mINFO[0;m[1;34m DL_ASS_TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){NONE}: Deallocated (fsm.c:568)[0;m [0;33m20241024140021826 [1;32mDRLCMAC[0;m[0;33m [1;32mINFO[0;m[0;33m PDCH(bts=0,trx=1,ts=7) PDCH state: enabled => disabled (pdch.cpp:184)[0;m [0;33m20241024140021826 [1;32mDRLCMAC[0;m[0;33m [1;32mINFO[0;m[0;33m PDCH(bts=0,trx=2,ts=7) PDCH state: enabled => disabled (pdch.cpp:184)[0;m [0;33m20241024140021826 [1;32mDRLCMAC[0;m[0;33m [1;32mINFO[0;m[0;33m PDCH(bts=0,trx=3,ts=7) PDCH state: enabled => disabled (pdch.cpp:184)[0;m [0;33m20241024140021826 [1;32mDRLCMAC[0;m[0;33m [1;32mINFO[0;m[0;33m PDCH(bts=0,trx=4,ts=7) PDCH state: enabled => disabled (pdch.cpp:184)[0;m [0;33m20241024140021826 [1;32mDRLCMAC[0;m[0;33m [1;32mINFO[0;m[0;33m PDCH(bts=0,trx=5,ts=7) PDCH state: enabled => disabled (pdch.cpp:184)[0;m [0;33m20241024140021827 [1;32mDRLCMAC[0;m[0;33m [1;32mINFO[0;m[0;33m PDCH(bts=0,trx=6,ts=7) PDCH state: enabled => disabled (pdch.cpp:184)[0;m [0;33m20241024140021827 [1;32mDRLCMAC[0;m[0;33m [1;32mINFO[0;m[0;33m PDCH(bts=0,trx=7,ts=7) PDCH state: enabled => disabled (pdch.cpp:184)[0;m [38;5;57m20241024140021827 [1;33mDLNS[0;m[38;5;57m [1;33mNOTICE[0;m[38;5;57m NSE(01234) NS-STATUS.ind(bvci=00000): cause=NSE failure, transfer=0, first=0, mtu=65523 (gprs_ns2.c:575)[0;m [1;35m20241024140021827 [1;33mDPCU[0;m[1;35m [1;33mNOTICE[0;m[1;35m NS-NSE 1234 became unavailable (gprs_bssgp_pcu.c:690)[0;m [38;5;57m20241024140021827 [1;33mDLNS[0;m[38;5;57m [1;33mNOTICE[0;m[38;5;57m NSE(01234)-NSVC(01234) NS-STATUS.ind(bvci=00000): cause=NSVC failure, transfer=0, first=0, mtu=65523 (gprs_ns2.c:571)[0;m [1;35m20241024140021827 [1;34mDPCU[0;m[1;35m [1;34mDEBUG[0;m[1;35m NS: indication Unknown affecting cause NSVC failure / 0 from NS (gprs_bssgp_pcu.c:702)[0;m [38;5;57m20241024140021827 [1;34mDLNS[0;m[38;5;57m [1;34mDEBUG[0;m[38;5;57m GPRS-NS2-VC(NSE01234-NSVC-UDP-0_0_0_0:22000-127_0_0_1:23000){UNBLOCKED}: Terminating (cause = OSMO_FSM_TERM_REQUEST) (gprs_ns2.c:656)[0;m [38;5;57m20241024140021827 [1;34mDLNS[0;m[38;5;57m [1;34mDEBUG[0;m[38;5;57m GPRS-NS2-VC(NSE01234-NSVC-UDP-0_0_0_0:22000-127_0_0_1:23000){UNBLOCKED}: Freeing instance (gprs_ns2.c:656)[0;m [38;5;57m20241024140021827 [1;34mDLNS[0;m[38;5;57m [1;34mDEBUG[0;m[38;5;57m GPRS-NS2-VC(NSE01234-NSVC-UDP-0_0_0_0:22000-127_0_0_1:23000){UNBLOCKED}: Deallocated (fsm.c:568)[0;m MTC@9541a9c1d226: Test case TC_nacc_outbound_pkt_cell_chg_notif_dup5 finished. Verdict: pass MTC@9541a9c1d226: Starting external command `https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/_cache/podman/osmo-ttcn3-hacks/ttcn3-tcpdump-stop.sh PCU_Tests.TC_nacc_outbound_pkt_cell_chg_notif_dup5 pass'. Thu Oct 24 14:00:21 UTC 2024 [1;32m====== PCU_Tests.TC_nacc_outbound_pkt_cell_chg_notif_dup5 pass ======[0m
Saving talloc report from 127.0.0.1:4240 to PCU_Tests.TC_nacc_outbound_pkt_cell_chg_notif_dup5.talloc respawn: 95: stopped pid 13908 with status 0 respawn: 96: starting: osmo-pcu 20241024140021907 [1;33mDLGLOBAL[0;m [1;33mNOTICE[0;m Setting up GSMTAP Um forwarding to '127.0.0.1:4729' (pcu_main.cpp:298) 20241024140021907 [1;33mDLGLOBAL[0;m [1;33mNOTICE[0;m Available via telnet 127.0.0.1 4240 (telnet_interface.c:88) [1;32m20241024140021907 [1;32mDL1IF[0;m[1;32m [1;32mINFO[0;m[1;32m Opening OsmoPCU L1 interface v12 to OsmoBTS/OsmoBSC (pcuif_sock.c:202)[0;m [1;32m20241024140021907 [1;31mDL1IF[0;m[1;32m [1;31mERROR[0;m[1;32m Failed to connect to the BTS (/tmp/pcu_bts). Retrying... (pcuif_sock.c:210)[0;m 20241024140021908 [1;32mDLGLOBAL[0;m [1;32mINFO[0;m Accept()ed new telnet connection r=127.0.0.1:60948<->l=127.0.0.1:4240 (telnet_interface.c:192) 20241024140022009 [1;32mDLGLOBAL[0;m [1;32mINFO[0;m Closing telnet connection r=127.0.0.1:60948<->l=127.0.0.1:4240 (telnet_interface.c:138) Waiting for packet dumper to finish... 0 (prev_count=-1, count=302736) Waiting for packet dumper to finish... 1 (prev_count=302736, count=312328) MTC@9541a9c1d226: External command `https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/_cache/podman/osmo-ttcn3-hacks/ttcn3-tcpdump-stop.sh PCU_Tests.TC_nacc_outbound_pkt_cell_chg_notif_dup5 pass' was executed successfully (exit status: 0). MTC@9541a9c1d226: Starting external command `https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/_cache/podman/osmo-ttcn3-hacks/ttcn3-tcpdump-start.sh PCU_Tests.TC_nacc_outbound_pkt_cell_chg_notif_twice'. ------ PCU_Tests.TC_nacc_outbound_pkt_cell_chg_notif_twice ------ Thu Oct 24 14:00:24 UTC 2024 /usr/bin/dumpcap -q -s 1520 -n -i any -w "https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/137/artifact/logs/testsuite/PCU_Tests.TC_nacc_outbound_pkt_cell_chg_notif_twice.pcap" >https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/137/artifact/logs/testsuite/PCU_Tests.TC_nacc_outbound_pkt_cell_chg_notif_twice.pcap.stdout 2>/tmp/cmderr & Waiting for packet dumper to start... 0 MTC@9541a9c1d226: External command `https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/_cache/podman/osmo-ttcn3-hacks/ttcn3-tcpdump-start.sh PCU_Tests.TC_nacc_outbound_pkt_cell_chg_notif_twice' was executed successfully (exit status: 0). MTC@9541a9c1d226: Test case TC_nacc_outbound_pkt_cell_chg_notif_twice started. 1080@9541a9c1d226: Creating NSIP provider for "127.0.0.1":23000 1080@9541a9c1d226: Starting NSVC component for { provider := { ip := { address_family := AF_INET (2), local_udp_port := 23000, local_ip := "127.0.0.1", remote_udp_port := 22000, remote_ip := "127.0.0.1", data_weight := 1, signalling_weight := 1 } }, nsvci := 1234 } -NSVCI1234(1084)@9541a9c1d226: NSVC 1234 State Transition: NSVC_S_DEAD_BLOCKED (1) -> NSVC_S_DEAD_BLOCKED (1) TC_nacc_outbound_pkt_cell_chg_notif_twice-BVCI1234(1083)@9541a9c1d226: Adding Client=mtc, IMSI='262420000000001'H, TLLI='FFFFFFFF'O, index=0 1080@9541a9c1d226: Creating NSIP provider for "127.0.0.1":23001 -NSVCI1234(1084)@9541a9c1d226: Provider Link came up: waiting for NS-RESET MTC@9541a9c1d226: Start timer g_T_guard: 60 s 1080@9541a9c1d226: Starting NSVC component for { provider := { ip := { address_family := AF_INET (2), local_udp_port := 23001, local_ip := "127.0.0.1", remote_udp_port := 22000, remote_ip := "127.0.0.1", data_weight := 1, signalling_weight := 1 } }, nsvci := 1234 } -NSVCI1234(1087)@9541a9c1d226: NSVC 1234 State Transition: NSVC_S_DEAD_BLOCKED (1) -> NSVC_S_DEAD_BLOCKED (1) 1080@9541a9c1d226: Creating NSIP provider for "127.0.0.1":23002 -NSVCI1234(1087)@9541a9c1d226: Provider Link came up: waiting for NS-RESET 20241024140025930 [1;32mDLGLOBAL[0;m [1;32mINFO[0;m Accept()ed new telnet connection r=127.0.0.1:60962<->l=127.0.0.1:4240 (telnet_interface.c:192) MTC@9541a9c1d226: Start timer T: 2 s MTC@9541a9c1d226: Start timer T: 2 s MTC@9541a9c1d226: Start timer T: 2 s MTC@9541a9c1d226: Start timer T: 2 s MTC@9541a9c1d226: Start timer T: 2 s MTC@9541a9c1d226: Start timer T: 2 s MTC@9541a9c1d226: Start timer T: 2 s MTC@9541a9c1d226: Start timer T: 2 s MTC@9541a9c1d226: Start timer T: 2 s 1080@9541a9c1d226: Starting NSVC component for { provider := { ip := { address_family := AF_INET (2), local_udp_port := 23002, local_ip := "127.0.0.1", remote_udp_port := 22000, remote_ip := "127.0.0.1", data_weight := 1, signalling_weight := 1 } }, nsvci := 1234 } -NSVCI1234(1090)@9541a9c1d226: NSVC 1234 State Transition: NSVC_S_DEAD_BLOCKED (1) -> NSVC_S_DEAD_BLOCKED (1) -NSVCI1234(1090)@9541a9c1d226: Provider Link came up: waiting for NS-RESET PCUIF(1086)@9541a9c1d226: "Init PCU interface on '/tmp/pcu_bts', waiting for connection..." PCUIF(1086)@9541a9c1d226: Start timer T: 5 s 20241024140025937 [1;32mDLGLOBAL[0;m [1;32mINFO[0;m Accept()ed new telnet connection r=127.0.0.1:60964<->l=127.0.0.1:4240 (telnet_interface.c:192) PCUIF(1086)@9541a9c1d226: Start timer T_Conn: 10 s TC_nacc_outbound_pkt_cell_chg_notif_twice-STATS(1091)@9541a9c1d226: Start timer T: 2 s TC_nacc_outbound_pkt_cell_chg_notif_twice-STATS(1091)@9541a9c1d226: Start timer T: 2 s Error: OCI runtime error: crun: the container `9541a9c1d22616963ded87dae5e9d742098d2372ae18d2ab19bff3bad2a3b196` is not running [1;91m[testenv] podman container crashed![0m [0;94m[testenv][generic] Testsuite is done[0m [1;34m[testenv][generic] Stopping testsuite (1828055)[0m [1;34m[testenv][generic] Merging log files[0m [0;94m[testenv][generic] + ['podman', 'exec', '-e', 'CCACHE_DIR=/home/osmocom-build/ccache/testenv', '-e', 'TESTENV_CACHE_DIR=https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/_cache', '-e', 'TESTENV_SRC_DIR=/home/osmocom-build/jenkins/workspace', '-e', 'TERM=dumb', '-e', 'TESTENV_GIT_DIR=https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/_cache/git', '-e', 'PATH=https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/_testenv/data/scripts:https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/_testenv/data/scripts/qemu:https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/_cache/podman/osmo-ttcn3-hacks/pcu:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin', '-e', 'HOME=/home/osmocom-build', '-t', '-w', 'https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/137/artifact/logs/testsuite', 'testenv-pcu-generic-osmocom-nightly-asan-20241024-1348-d17cee9a-0', 'sh', '-c', 'https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/_cache/podman/osmo-ttcn3-hacks/log_merge.sh PCU_Tests --rm >/dev/null'][0m Error: no container with name or ID "testenv-pcu-generic-osmocom-nightly-asan-20241024-1348-d17cee9a-0" found: no such container [1;91m[testenv][generic] Command failed unexpectedly[0m [0;94m[testenv][generic] Command: ['podman', 'exec', '-e', 'CCACHE_DIR=/home/osmocom-build/ccache/testenv', '-e', 'TESTENV_CACHE_DIR=https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/_cache', '-e', 'TESTENV_SRC_DIR=/home/osmocom-build/jenkins/workspace', '-e', 'TERM=dumb', '-e', 'TESTENV_GIT_DIR=https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/_cache/git', '-e', 'PATH=https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/_testenv/data/scripts:https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/_testenv/data/scripts/qemu:https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/_cache/podman/osmo-ttcn3-hacks/pcu:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin', '-e', 'HOME=/home/osmocom-build', '-t', '-w', 'https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/137/artifact/logs/testsuite', 'testenv-pcu-generic-osmocom-nightly-asan-20241024-1348-d17cee9a-0', 'sh', '-c', 'https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/_cache/podman/osmo-ttcn3-hacks/log_merge.sh PCU_Tests --rm >/dev/null'][0m [0;94m[testenv][generic] Returncode: 125[0m Traceback (most recent call last): File "https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/./testenv.py", line 115, in <module> main() File "https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/./testenv.py", line 104, in main run() File "https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/./testenv.py", line 63, in run testenv.testsuite.run(cfg) File "https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/_testenv/testenv/testsuite.py", line 204, in run merge_log_files(cfg) File "https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/_testenv/testenv/testsuite.py", line 130, in merge_log_files testenv.cmd.run(cmd, cwd=cwd) File "https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/_testenv/testenv/cmd.py", line 101, in run return testenv.podman.exec_cmd(cmd, check=check, env=env, *args, **kwargs) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/_testenv/testenv/podman.py", line 149, in exec_cmd testenv.cmd.run( File "https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/_testenv/testenv/cmd.py", line 118, in run exit_error_cmd(p, "Command failed unexpectedly") File "https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/ws/_testenv/testenv/cmd.py", line 66, in exit_error_cmd raise RuntimeError("shell command related error, find details right above this python trace") RuntimeError: shell command related error, find details right above this python trace [1;34m[testenv][generic] Logs saved to: https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-asan/137/artifact/log... [0m Build step 'Execute shell' marked build as failure Recording test results [Checks API] No suitable checks publisher found.