Build failed in Jenkins: ttcn3-pcu-test #2124

27 Oct 2024

See <https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test/2124/display/redirect>

Changes:


------------------------------------------
[...truncated 2.62 MiB...]
[1;34m20241027042919519 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} Assembling frames: (len=36)
(tbf_ul.cpp:172)[0;m
[1;34m20241027042919519 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} Frame 1 starts at offset 0, length=36,
is_complete=0 (tbf_ul.cpp:185)[0;m
[1;34m20241027042919519 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} No gaps in received block, last block: BSN=20
CV=4 (tbf_ul.cpp:402)[0;m
[1;32m20241027042919520 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=1,ts=7) FN=151 Rx DATA.ind: sapi=5 arfcn=872 cur_fn=151 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919520 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=1,ts=7) FN=151 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919521 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=2,ts=7) FN=151 Rx DATA.ind: sapi=5 arfcn=873 cur_fn=151 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919521 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=2,ts=7) FN=151 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919522 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=3,ts=7) FN=151 Rx DATA.ind: sapi=5 arfcn=874 cur_fn=151 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919522 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=3,ts=7) FN=151 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919523 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=4,ts=7) FN=151 Rx DATA.ind: sapi=5 arfcn=875 cur_fn=151 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919523 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=4,ts=7) FN=151 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919523 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=5,ts=7) FN=151 Rx DATA.ind: sapi=5 arfcn=876 cur_fn=151 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919523 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=5,ts=7) FN=151 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919524 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=6,ts=7) FN=151 Rx DATA.ind: sapi=5 arfcn=877 cur_fn=151 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919524 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=6,ts=7) FN=151 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919525 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=7,ts=7) FN=151 Rx DATA.ind: sapi=5 arfcn=878 cur_fn=151 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919525 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=7,ts=7) FN=151 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919528 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m Time indication
received: 0 (pcu_l1_if.cpp:1048)[0;m
[1;32m20241027042919543 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=0,ts=7) FN=156 Rx DATA.ind: sapi=5 arfcn=871 cur_fn=151 block=0 data=0c 00 2b
1a bc 10 db 89 ef f0 7c a4 4d 9d 45 97 12 9e 6a 41 6a 2b c5 f6 58 ea 0d 68 2e 34 e5 46 48
27 90 fe ff c8 cf 00  (pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919543 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=0,ts=7) FN=156 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 0
(pcu_l1_if.cpp:478)[0;m
[1;36m20241027042919543 [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-3, length: 40 (39))
(pdch.cpp:983)[0;m
[1;36m20241027042919543 [1;34mDRLCMACUL[0;m[1;36m [1;34mDEBUG[0;m[1;36m
PDCH(bts=0,trx=0,ts=7)   UL data: 0c 00 2b 1a bc 10 db 89 ef f0 7c a4 4d 9d 45 97 12 9e 6a
41 6a 2b c5 f6 58 ea 0d 68 2e 34 e5 46 48 27 90 fe ff c8 cf 00  (pdch.cpp:1021)[0;m
[1;36m20241027042919543 [1;32mDRLCMACUL[0;m[1;36m [1;32mINFO[0;m[1;36m
PDCH(bts=0,trx=0,ts=7) Got CS-3 RLC block: R=0, SI=0, TFI=0, CPS=0, RSB=0, rc=312
(pdch.cpp:1032)[0;m
[1;34m20241027042919543 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} UL DATA TFI=0 received (V(Q)=21 .. V(R)=21)
(tbf_ul.cpp:257)[0;m
[1;31m20241027042919543 [1;32mDRLCMACMEAS[0;m[1;31m [1;32mINFO[0;m[1;31m
MS(TLLI-0x00000001:TA-0:MSCLS-0-0:UL) Link quality 0dB (old 0dB) left window [7, 13],
modifying uplink CS level: CS-3 -> CS-2 (gprs_ms.c:816)[0;m
[1;34m20241027042919543 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} Got CS-3 RLC data block: CV=3, BSN=21, SPB=0,
PI=0, E=1, TI=0, bitoffs=24 (tbf_ul.cpp:292)[0;m
[1;34m20241027042919543 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} BSN 21 storing in window (21..84)
(tbf_ul.cpp:314)[0;m
[1;34m20241027042919543 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} data_length=36, data=1a bc 10 db 89 ef f0 7c a4
4d 9d 45 97 12 9e 6a 41 6a 2b c5 f6 58 ea 0d 68 2e 34 e5 46 48 27 90 fe ff c8 cf 
(tbf_ul.cpp:337)[0;m
[1;36m20241027042919543 [1;34mDRLCMACUL[0;m[1;36m [1;34mDEBUG[0;m[1;36m - Mark BSN
85 as INVALID (rlc_window_ul.cpp:42)[0;m
[1;36m20241027042919543 [1;34mDRLCMACUL[0;m[1;36m [1;34mDEBUG[0;m[1;36m - Raising
V(R) to 22 (rlc_window_ul.cpp:50)[0;m
[1;36m20241027042919543 [1;34mDRLCMACUL[0;m[1;36m [1;34mDEBUG[0;m[1;36m - Taking
block 21 out, raising V(Q) to 22 (rlc_window_ul.cpp:65)[0;m
[1;34m20241027042919543 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} Assembling frames: (len=36)
(tbf_ul.cpp:172)[0;m
[1;34m20241027042919543 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} Frame 1 starts at offset 0, length=36,
is_complete=0 (tbf_ul.cpp:185)[0;m
[1;34m20241027042919543 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} No gaps in received block, last block: BSN=21
CV=3 (tbf_ul.cpp:402)[0;m
[1;32m20241027042919544 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=1,ts=7) FN=156 Rx DATA.ind: sapi=5 arfcn=872 cur_fn=156 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919544 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=1,ts=7) FN=156 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919545 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=2,ts=7) FN=156 Rx DATA.ind: sapi=5 arfcn=873 cur_fn=156 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919545 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=2,ts=7) FN=156 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919546 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=3,ts=7) FN=156 Rx DATA.ind: sapi=5 arfcn=874 cur_fn=156 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919546 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=3,ts=7) FN=156 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919548 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=4,ts=7) FN=156 Rx DATA.ind: sapi=5 arfcn=875 cur_fn=156 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919548 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=4,ts=7) FN=156 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919548 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=5,ts=7) FN=156 Rx DATA.ind: sapi=5 arfcn=876 cur_fn=156 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919548 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=5,ts=7) FN=156 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919549 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=6,ts=7) FN=156 Rx DATA.ind: sapi=5 arfcn=877 cur_fn=156 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919549 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=6,ts=7) FN=156 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919550 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=7,ts=7) FN=156 Rx DATA.ind: sapi=5 arfcn=878 cur_fn=156 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919550 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=7,ts=7) FN=156 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919551 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m Time indication
received: 4 (pcu_l1_if.cpp:1048)[0;m
[1;32m20241027042919563 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=0,ts=7) FN=160 Rx DATA.ind: sapi=5 arfcn=871 cur_fn=156 block=1 data=08 00 2d
bd 5b 95 c7 65 6f c8 63 84 5b af 2d a0 2c d4 a6 43 d4 e7 0c 8b b1 1b ba bc d6 d3 dc bb 46
37 74 28 0a f2 50 00  (pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919563 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=0,ts=7) FN=160 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 0
(pcu_l1_if.cpp:478)[0;m
[1;36m20241027042919563 [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-3, length: 40 (39))
(pdch.cpp:983)[0;m
[1;36m20241027042919563 [1;34mDRLCMACUL[0;m[1;36m [1;34mDEBUG[0;m[1;36m
PDCH(bts=0,trx=0,ts=7)   UL data: 08 00 2d bd 5b 95 c7 65 6f c8 63 84 5b af 2d a0 2c d4 a6
43 d4 e7 0c 8b b1 1b ba bc d6 d3 dc bb 46 37 74 28 0a f2 50 00  (pdch.cpp:1021)[0;m
[1;36m20241027042919563 [1;32mDRLCMACUL[0;m[1;36m [1;32mINFO[0;m[1;36m
PDCH(bts=0,trx=0,ts=7) Got CS-3 RLC block: R=0, SI=0, TFI=0, CPS=0, RSB=0, rc=312
(pdch.cpp:1032)[0;m
[1;36m20241027042919563 [1;33mDRLCMACUL[0;m[1;36m [1;33mNOTICE[0;m[1;36m
PDCH(bts=0,trx=0,ts=7) FN=160 Rx UL DATA from unexpected
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} (pdch.cpp:1072)[0;m
[1;34m20241027042919563 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} UL DATA TFI=0 received (V(Q)=22 .. V(R)=22)
(tbf_ul.cpp:257)[0;m
[1;31m20241027042919563 [1;32mDRLCMACMEAS[0;m[1;31m [1;32mINFO[0;m[1;31m
MS(TLLI-0x00000001:TA-0:MSCLS-0-0:UL) Link quality 0dB (old 0dB) left window [5, 8],
modifying uplink CS level: CS-2 -> CS-1 (gprs_ms.c:816)[0;m
[1;34m20241027042919563 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} Got CS-3 RLC data block: CV=2, BSN=22, SPB=0,
PI=0, E=1, TI=0, bitoffs=24 (tbf_ul.cpp:292)[0;m
[1;34m20241027042919563 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} BSN 22 storing in window (22..85)
(tbf_ul.cpp:314)[0;m
[1;34m20241027042919563 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} data_length=36, data=bd 5b 95 c7 65 6f c8 63 84
5b af 2d a0 2c d4 a6 43 d4 e7 0c 8b b1 1b ba bc d6 d3 dc bb 46 37 74 28 0a f2 50 
(tbf_ul.cpp:337)[0;m
[1;36m20241027042919563 [1;34mDRLCMACUL[0;m[1;36m [1;34mDEBUG[0;m[1;36m - Mark BSN
86 as INVALID (rlc_window_ul.cpp:42)[0;m
[1;36m20241027042919563 [1;34mDRLCMACUL[0;m[1;36m [1;34mDEBUG[0;m[1;36m - Raising
V(R) to 23 (rlc_window_ul.cpp:50)[0;m
[1;36m20241027042919563 [1;34mDRLCMACUL[0;m[1;36m [1;34mDEBUG[0;m[1;36m - Taking
block 22 out, raising V(Q) to 23 (rlc_window_ul.cpp:65)[0;m
[1;34m20241027042919563 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} Assembling frames: (len=36)
(tbf_ul.cpp:172)[0;m
[1;34m20241027042919563 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} Frame 1 starts at offset 0, length=36,
is_complete=0 (tbf_ul.cpp:185)[0;m
[1;34m20241027042919563 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} No gaps in received block, last block: BSN=22
CV=2 (tbf_ul.cpp:402)[0;m
[1;32m20241027042919564 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=1,ts=7) FN=160 Rx DATA.ind: sapi=5 arfcn=872 cur_fn=160 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919564 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=1,ts=7) FN=160 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919565 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=2,ts=7) FN=160 Rx DATA.ind: sapi=5 arfcn=873 cur_fn=160 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919565 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=2,ts=7) FN=160 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919566 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=3,ts=7) FN=160 Rx DATA.ind: sapi=5 arfcn=874 cur_fn=160 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919566 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=3,ts=7) FN=160 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919566 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=4,ts=7) FN=160 Rx DATA.ind: sapi=5 arfcn=875 cur_fn=160 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919566 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=4,ts=7) FN=160 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919567 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=5,ts=7) FN=160 Rx DATA.ind: sapi=5 arfcn=876 cur_fn=160 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919567 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=5,ts=7) FN=160 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919568 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=6,ts=7) FN=160 Rx DATA.ind: sapi=5 arfcn=877 cur_fn=160 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919568 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=6,ts=7) FN=160 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919569 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=7,ts=7) FN=160 Rx DATA.ind: sapi=5 arfcn=878 cur_fn=160 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919569 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=7,ts=7) FN=160 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919569 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m Time indication
received: 8 (pcu_l1_if.cpp:1048)[0;m
[1;32m20241027042919582 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=0,ts=7) FN=164 Rx DATA.ind: sapi=5 arfcn=871 cur_fn=160 block=2 data=04 00 2f
fa bb 0b cd 55 f0 40 89 be 9d cf 7b 2f 8b 39 5e 33 1e bc 28 76 31 38 a7 8e ca 0f e0 d9 0d
f5 24 8f 19 de 84 00  (pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919582 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=0,ts=7) FN=164 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 0
(pcu_l1_if.cpp:478)[0;m
[1;36m20241027042919582 [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-3, length: 40 (39))
(pdch.cpp:983)[0;m
[1;36m20241027042919582 [1;34mDRLCMACUL[0;m[1;36m [1;34mDEBUG[0;m[1;36m
PDCH(bts=0,trx=0,ts=7)   UL data: 04 00 2f fa bb 0b cd 55 f0 40 89 be 9d cf 7b 2f 8b 39 5e
33 1e bc 28 76 31 38 a7 8e ca 0f e0 d9 0d f5 24 8f 19 de 84 00  (pdch.cpp:1021)[0;m
[1;36m20241027042919582 [1;32mDRLCMACUL[0;m[1;36m [1;32mINFO[0;m[1;36m
PDCH(bts=0,trx=0,ts=7) Got CS-3 RLC block: R=0, SI=0, TFI=0, CPS=0, RSB=0, rc=312
(pdch.cpp:1032)[0;m
[1;36m20241027042919582 [1;33mDRLCMACUL[0;m[1;36m [1;33mNOTICE[0;m[1;36m
PDCH(bts=0,trx=0,ts=7) FN=164 Rx UL DATA from unexpected
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} (pdch.cpp:1072)[0;m
[1;34m20241027042919582 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} UL DATA TFI=0 received (V(Q)=23 .. V(R)=23)
(tbf_ul.cpp:257)[0;m
[1;34m20241027042919582 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} Got CS-3 RLC data block: CV=1, BSN=23, SPB=0,
PI=0, E=1, TI=0, bitoffs=24 (tbf_ul.cpp:292)[0;m
[1;34m20241027042919582 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} BSN 23 storing in window (23..86)
(tbf_ul.cpp:314)[0;m
[1;34m20241027042919582 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} data_length=36, data=fa bb 0b cd 55 f0 40 89 be
9d cf 7b 2f 8b 39 5e 33 1e bc 28 76 31 38 a7 8e ca 0f e0 d9 0d f5 24 8f 19 de 84 
(tbf_ul.cpp:337)[0;m
[1;36m20241027042919582 [1;34mDRLCMACUL[0;m[1;36m [1;34mDEBUG[0;m[1;36m - Mark BSN
87 as INVALID (rlc_window_ul.cpp:42)[0;m
[1;36m20241027042919582 [1;34mDRLCMACUL[0;m[1;36m [1;34mDEBUG[0;m[1;36m - Raising
V(R) to 24 (rlc_window_ul.cpp:50)[0;m
[1;36m20241027042919582 [1;34mDRLCMACUL[0;m[1;36m [1;34mDEBUG[0;m[1;36m - Taking
block 23 out, raising V(Q) to 24 (rlc_window_ul.cpp:65)[0;m
[1;34m20241027042919582 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} Assembling frames: (len=36)
(tbf_ul.cpp:172)[0;m
[1;34m20241027042919582 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} Frame 1 starts at offset 0, length=36,
is_complete=0 (tbf_ul.cpp:185)[0;m
[1;34m20241027042919582 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} No gaps in received block, last block: BSN=23
CV=1 (tbf_ul.cpp:402)[0;m
[1;32m20241027042919583 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=1,ts=7) FN=164 Rx DATA.ind: sapi=5 arfcn=872 cur_fn=164 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919583 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=1,ts=7) FN=164 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919584 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=2,ts=7) FN=164 Rx DATA.ind: sapi=5 arfcn=873 cur_fn=164 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919584 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=2,ts=7) FN=164 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919585 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=3,ts=7) FN=164 Rx DATA.ind: sapi=5 arfcn=874 cur_fn=164 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919585 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=3,ts=7) FN=164 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919585 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=4,ts=7) FN=164 Rx DATA.ind: sapi=5 arfcn=875 cur_fn=164 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919585 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=4,ts=7) FN=164 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919586 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=5,ts=7) FN=164 Rx DATA.ind: sapi=5 arfcn=876 cur_fn=164 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919586 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=5,ts=7) FN=164 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919587 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=6,ts=7) FN=164 Rx DATA.ind: sapi=5 arfcn=877 cur_fn=164 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919587 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=6,ts=7) FN=164 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919588 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=7,ts=7) FN=164 Rx DATA.ind: sapi=5 arfcn=878 cur_fn=164 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919588 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=7,ts=7) FN=164 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919591 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m Time indication
received: 13 (pcu_l1_if.cpp:1048)[0;m
[1;32m20241027042919605 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=0,ts=7) FN=169 Rx DATA.ind: sapi=5 arfcn=871 cur_fn=164 block=3 data=00 00 31
a1 0d 7c 7d ea 89 de 50 4c 48 04 b6 50 48 11 bf 53 9a 14 59 8e b9 74 59 48 2d b4 78 e4 00
f3 5e 1c dd ad be 00  (pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919606 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=0,ts=7) FN=169 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 0
(pcu_l1_if.cpp:478)[0;m
[1;36m20241027042919606 [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-3, length: 40 (39))
(pdch.cpp:983)[0;m
[1;36m20241027042919606 [1;34mDRLCMACUL[0;m[1;36m [1;34mDEBUG[0;m[1;36m
PDCH(bts=0,trx=0,ts=7)   UL data: 00 00 31 a1 0d 7c 7d ea 89 de 50 4c 48 04 b6 50 48 11 bf
53 9a 14 59 8e b9 74 59 48 2d b4 78 e4 00 f3 5e 1c dd ad be 00  (pdch.cpp:1021)[0;m
[1;36m20241027042919606 [1;32mDRLCMACUL[0;m[1;36m [1;32mINFO[0;m[1;36m
PDCH(bts=0,trx=0,ts=7) Got CS-3 RLC block: R=0, SI=0, TFI=0, CPS=0, RSB=0, rc=312
(pdch.cpp:1032)[0;m
[1;36m20241027042919606 [1;33mDRLCMACUL[0;m[1;36m [1;33mNOTICE[0;m[1;36m
PDCH(bts=0,trx=0,ts=7) FN=169 Rx UL DATA from unexpected
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} (pdch.cpp:1072)[0;m
[1;34m20241027042919606 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} UL DATA TFI=0 received (V(Q)=24 .. V(R)=24)
(tbf_ul.cpp:257)[0;m
[1;34m20241027042919606 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} Got CS-3 RLC data block: CV=0, BSN=24, SPB=0,
PI=0, E=1, TI=0, bitoffs=24 (tbf_ul.cpp:292)[0;m
[1;34m20241027042919606 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} BSN 24 storing in window (24..87)
(tbf_ul.cpp:314)[0;m
[1;34m20241027042919606 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} data_length=36, data=a1 0d 7c 7d ea 89 de 50 4c
48 04 b6 50 48 11 bf 53 9a 14 59 8e b9 74 59 48 2d b4 78 e4 00 f3 5e 1c dd ad be 
(tbf_ul.cpp:337)[0;m
[1;36m20241027042919606 [1;34mDRLCMACUL[0;m[1;36m [1;34mDEBUG[0;m[1;36m - Mark BSN
88 as INVALID (rlc_window_ul.cpp:42)[0;m
[1;36m20241027042919606 [1;34mDRLCMACUL[0;m[1;36m [1;34mDEBUG[0;m[1;36m - Raising
V(R) to 25 (rlc_window_ul.cpp:50)[0;m
[1;36m20241027042919606 [1;34mDRLCMACUL[0;m[1;36m [1;34mDEBUG[0;m[1;36m - Taking
block 24 out, raising V(Q) to 25 (rlc_window_ul.cpp:65)[0;m
[1;34m20241027042919606 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} Assembling frames: (len=36)
(tbf_ul.cpp:172)[0;m
[1;34m20241027042919606 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} Frame 1 starts at offset 0, length=36,
is_complete=1 (tbf_ul.cpp:185)[0;m
[1;34m20241027042919606 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} complete UL frame len=896 (tbf_ul.cpp:197)[0;m
[38;5;59m20241027042919606 [1;32mDLBSSGP[0;m[38;5;59m [1;32mINFO[0;m[38;5;59m LLC
[PCU -> SGSN] TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} len=896 (tbf_ul.cpp:467)[0;m
[1;34m20241027042919606 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} No gaps in received block, last block: BSN=24
CV=0 (tbf_ul.cpp:402)[0;m
[1;34m20241027042919606 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FLOW} Finished with UL TBF (tbf_ul.cpp:406)[0;m
[1;34m20241027042919606 [1;32mDTBFUL[0;m[1;34m [1;32mINFO[0;m[1;34m
UL_TBF(UL:TFI-0-0-0:G){FLOW}: Received Event LAST_UL_DATA_RECVD (tbf_ul.cpp:407)[0;m
[1;34m20241027042919606 [1;32mDTBFUL[0;m[1;34m [1;32mINFO[0;m[1;34m
UL_TBF(UL:TFI-0-0-0:G){FLOW}: state_chg to FINISHED (tbf_ul_fsm.c:210)[0;m
[1;34m20241027042919606 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FINISHED} Scheduling final Ack/Nack, because all data
was received and last block has CV==0. (tbf_ul.cpp:443)[0;m
[1;34m20241027042919606 [1;32mDTBFUL[0;m[1;34m [1;32mINFO[0;m[1;34m
UL_ACK_TBF(UL:TFI-0-0-0:G){NONE}: Received Event SCHED_ACK (tbf_ul.cpp:456)[0;m
[1;34m20241027042919606 [1;32mDTBFUL[0;m[1;34m [1;32mINFO[0;m[1;34m
UL_ACK_TBF(UL:TFI-0-0-0:G){NONE}: state_chg to SCHED_UL_ACK (tbf_ul_ack_fsm.c:102)[0;m
[1;32m20241027042919607 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=1,ts=7) FN=169 Rx DATA.ind: sapi=5 arfcn=872 cur_fn=169 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919607 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=1,ts=7) FN=169 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919607 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=2,ts=7) FN=169 Rx DATA.ind: sapi=5 arfcn=873 cur_fn=169 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919608 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=2,ts=7) FN=169 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919608 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=3,ts=7) FN=169 Rx DATA.ind: sapi=5 arfcn=874 cur_fn=169 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919608 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=3,ts=7) FN=169 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919609 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=4,ts=7) FN=169 Rx DATA.ind: sapi=5 arfcn=875 cur_fn=169 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919609 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=4,ts=7) FN=169 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919610 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=5,ts=7) FN=169 Rx DATA.ind: sapi=5 arfcn=876 cur_fn=169 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919610 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=5,ts=7) FN=169 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919610 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=6,ts=7) FN=169 Rx DATA.ind: sapi=5 arfcn=877 cur_fn=169 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919610 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=6,ts=7) FN=169 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919611 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=7,ts=7) FN=169 Rx DATA.ind: sapi=5 arfcn=878 cur_fn=169 block=0 data=
(pcu_l1_if.cpp:463)[0;m
[1;32m20241027042919611 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=7,ts=7) FN=169 Rx DATA.ind PDTCH: BER10k = 0, BTO = 0, Q = 10
(pcu_l1_if.cpp:478)[0;m
[1;32m20241027042919612 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
PDCH(bts=0,trx=0,ts=7) FN=173 RX RTS.req: sapi=5 arfcn=871 cur_fn=169 block=4
(pcu_l1_if.cpp:576)[0;m
[1;34m20241027042919612 [1;32mDTBFUL[0;m[1;34m [1;32mINFO[0;m[1;34m
UL_ACK_TBF(UL:TFI-0-0-0:G){SCHED_UL_ACK}: Received Event CREATE_RLCMAC_MSG
(tbf_ul_ack_fsm.c:251)[0;m
[0;33m20241027042919612 [1;34mDRLCMAC[0;m[0;33m [1;34mDEBUG[0;m[0;33m
PDCH(bts=0,trx=0,ts=7) POLL scheduled at FN 173 + 13 = 186
(pdch_ul_controller.c:131)[0;m
[1;36m20241027042919612 [1;34mDRLCMACUL[0;m[1;36m [1;34mDEBUG[0;m[1;36m Encoding
Ack/Nack for TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FINISHED} (final=1)
(encoding.cpp:1112)[0;m
[1;36m20241027042919612 [1;34mDRLCMACUL[0;m[1;36m [1;34mDEBUG[0;m[1;36m - V(N):
"IIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIRRRRRRRRRRRRRRRRRRRRRRRRR" R=Received
I=Invalid (encoding.cpp:860)[0;m
[1;36m20241027042919612 [1;34mDRLCMACUL[0;m[1;36m [1;34mDEBUG[0;m[1;36m Uplink
Ack/Nack bit count 147, max 184, message = 48 24 00 26 40 00 00 00 00 7f ff ff e0 00 00 00
38 01 4b 2b 2b 2b 2b  (encoding.cpp:1135)[0;m
[0;33m20241027042919612 [1;34mDRLCMAC[0;m[0;33m [1;34mDEBUG[0;m[0;33m
PDCH(bts=0,trx=0,ts=7) Reserving FN 186 for type POLL (pdch_ul_controller.c:184)[0;m
[1;34m20241027042919612 [1;34mDTBFUL[0;m[1;34m [1;34mDEBUG[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FINISHED} Scheduled UL Acknowledgement polling on
PACCH (FN=186, TS=7) (tbf_ul_ack_fsm.c:90)[0;m
[1;34m20241027042919612 [1;32mDTBFUL[0;m[1;34m [1;32mINFO[0;m[1;34m
UL_ACK_TBF(UL:TFI-0-0-0:G){SCHED_UL_ACK}: state_chg to WAIT_ACK
(tbf_ul_ack_fsm.c:129)[0;m
[0;36m20241027042919612 [1;34mDRLCMACSCHED[0;m[0;36m [1;34mDEBUG[0;m[0;36m
PDCH(bts=0,trx=0,ts=7) FN=173 Scheduling control message at RTS for
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FINISHED} (gprs_rlcmac_sched.cpp:202)[0;m
[1;32m20241027042919612 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m
(bts=0,trx=0,ts=7) FN=173 Sending data request: sapi=5 arfcn=871 cur_fn=169 block=4
data=4f 24 00 26 40 00 00 00 00 7f ff ff e0 00 00 00 38 01 4b 2b 2b 2b 2b 
(pcu_l1_if.cpp:182)[0;m
[1;32m20241027042919613 [1;34mDL1IF[0;m[1;32m [1;34mDEBUG[0;m[1;32m Time indication
received: 17 (pcu_l1_if.cpp:1048)[0;m
BTS(72)@909636ebcb17: Warning: dec_RlcmacDlCtrlBlock(): Data remained at the end of the
stream after successful decoding: '4B2B2B2B2B'O ("K++++")
BTS(72)@909636ebcb17: Shutting down virtual BTS #0...
20241027042919619 [1;32mDLGLOBAL[0;m [1;32mINFO[0;m Closing telnet connection
r=127.0.0.1:48540<->l=127.0.0.1:4240 (telnet_interface.c:138)
20241027042919621 [1;32mDLGLOBAL[0;m [1;32mINFO[0;m Closing telnet connection
r=127.0.0.1:48524<->l=127.0.0.1:4240 (telnet_interface.c:138)
[1;32m20241027042919622 [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;32m20241027042919622 [1;33mDL1IF[0;m[1;32m [1;33mNOTICE[0;m[1;32m PCU socket has
LOST connection (pcuif_sock.c:78)[0;m
[0;33m20241027042919622 [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;34m20241027042919622 [1;32mDTBF[0;m[1;34m [1;32mINFO[0;m[1;34m
TBF(UL:TFI-0-0-0:G:TLLI-0x00000001){FINISHED} free (tbf.cpp:271)[0;m
[0;33m20241027042919622 [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){FINISHED}, 1 TBFs,
USFs = 01, TFIs = 00000001. (pdch.cpp:1202)[0;m
[1;34m20241027042919622 [1;32mDMS[0;m[1;34m [1;32mINFO[0;m[1;34m
MS(TLLI-0x00000001:TA-0:MSCLS-0-0:UL) Detaching TBF: TBF(UL:G:TLLI-0x00000001){FINISHED}
(gprs_ms.c:381)[0;m
[1;34m20241027042919622 [1;32mDMS[0;m[1;34m [1;32mINFO[0;m[1;34m
MS(TLLI-0x00000001:TA-0:MSCLS-0-0): - tbf: now used by 0 (-) (gprs_ms.c:394)[0;m
[1;34m20241027042919622 [1;32mDMS[0;m[1;34m [1;32mINFO[0;m[1;34m
MS(TLLI-0x00000001:TA-0:MSCLS-0-0) Schedule MS release in 60 secs (gprs_ms.c:246)[0;m
[1;34m20241027042919622 [1;34mDTBF[0;m[1;34m [1;34mDEBUG[0;m[1;34m **********
UL-TBF ends here ********** (tbf.cpp:279)[0;m
[1;34m20241027042919622 [1;32mDTBFUL[0;m[1;34m [1;32mINFO[0;m[1;34m
UL_ACK_TBF(UL:TFI-0-0-0:G){WAIT_ACK}: Deallocated (fsm.c:568)[0;m
[1;34m20241027042919622 [1;32mDTBFUL[0;m[1;34m [1;32mINFO[0;m[1;34m
UL_TBF(UL:TFI-0-0-0:G){FINISHED}: Deallocated (fsm.c:568)[0;m
[1;34m20241027042919622 [1;32mDTBF[0;m[1;34m [1;32mINFO[0;m[1;34m
UL_ASS_TBF(UL:TFI-0-0-0:G){NONE}: Deallocated (fsm.c:568)[0;m
[1;34m20241027042919622 [1;32mDTBF[0;m[1;34m [1;32mINFO[0;m[1;34m
DL_ASS_TBF(UL:TFI-0-0-0:G){NONE}: Deallocated (fsm.c:568)[0;m
[0;33m20241027042919622 [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;33m20241027042919622 [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;33m20241027042919622 [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;33m20241027042919622 [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;33m20241027042919622 [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;33m20241027042919622 [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;33m20241027042919622 [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;57m20241027042919622 [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=1, mtu=65523
(gprs_ns2.c:575)[0;m
[1;35m20241027042919622 [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;57m20241027042919622 [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=1,
mtu=65523 (gprs_ns2.c:571)[0;m
[1;35m20241027042919622 [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;57m20241027042919622 [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){RESET}: Terminating (cause =
OSMO_FSM_TERM_REQUEST) (gprs_ns2.c:656)[0;m
[38;5;57m20241027042919622 [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){RESET}: Freeing instance
(gprs_ns2.c:656)[0;m
[38;5;57m20241027042919622 [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){RESET}: Deallocated
(fsm.c:568)[0;m
MTC@909636ebcb17: Test case TC_cs_initial_ul finished. Verdict: pass
MTC@909636ebcb17: Starting external command
`<https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test/ws/_cache/podman/osmo-ttcn3-hacks/ttcn3-tcpdump-stop.sh>
PCU_Tests.TC_cs_initial_ul pass'.
respawn: 8: stopped pid 6571 with status 0
respawn: 9: starting: osmo-pcu
Sun Oct 27 04:29:19 UTC 2024
[1;32m====== PCU_Tests.TC_cs_initial_ul pass ======[0m

Saving talloc report from 127.0.0.1:4240 to PCU_Tests.TC_cs_initial_ul.talloc
20241027042919648 [1;33mDLGLOBAL[0;m [1;33mNOTICE[0;m Setting up GSMTAP Um forwarding
to '127.0.0.1:4729' (pcu_main.cpp:298)
20241027042919649 [1;33mDLGLOBAL[0;m [1;33mNOTICE[0;m Available via telnet 127.0.0.1
4240 (telnet_interface.c:88)
[1;32m20241027042919649 [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;32m20241027042919649 [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
20241027042919660 [1;32mDLGLOBAL[0;m [1;32mINFO[0;m Accept()ed new telnet connection
r=127.0.0.1:48542<->l=127.0.0.1:4240 (telnet_interface.c:192)
20241027042919761 [1;32mDLGLOBAL[0;m [1;32mINFO[0;m Closing telnet connection
r=127.0.0.1:48542<->l=127.0.0.1:4240 (telnet_interface.c:138)
Waiting for packet dumper to finish... 0 (prev_count=-1, count=315648)
Waiting for packet dumper to finish... 1 (prev_count=315648, count=371072)
MTC@909636ebcb17: External command
`<https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test/ws/_cache/podman/osmo-ttcn3-hacks/ttcn3-tcpdump-stop.sh>
PCU_Tests.TC_cs_initial_ul pass' was executed successfully (exit status: 0).
MTC@909636ebcb17: Starting external command
`<https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test/ws/_cache/podman/osmo-ttcn3-hacks/ttcn3-tcpdump-start.sh>
PCU_Tests.TC_cs_max_ul'.
------ PCU_Tests.TC_cs_max_ul ------
Sun Oct 27 04:29:21 UTC 2024
Error: can only start exec sessions when their container is running: container state
improper
[1;91m[testenv] podman container crashed![0m
[0;94m[testenv][generic] Testsuite is done[0m
[1;34m[testenv][generic] Stopping testsuite (1882171)[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/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/ws/_cache/git',>
'-e',
'PATH=<https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test/ws/_testenv/data/scripts>:<https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test/ws/_testenv/data/scripts/qemu>:<https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test/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/2124/artifact/logs/testsuite',>
'testenv-pcu-generic-osmocom-nightly-20241027-0428-fddab15c-0', 'sh',
'-c',
'<https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test/ws/_cache/podman/osmo-ttcn3-hacks/log_merge.sh>
PCU_Tests --rm >/dev/null'][0m
Error: container 909636ebcb1775d78b9b3d220de776f2169b602e25e456da723b8e8455f13065 does not
exist in database: 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/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/ws/_cache/git',>
'-e',
'PATH=<https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test/ws/_testenv/data/scripts>:<https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test/ws/_testenv/data/scripts/qemu>:<https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test/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/2124/artifact/logs/testsuite',>
'testenv-pcu-generic-osmocom-nightly-20241027-0428-fddab15c-0', 'sh',
'-c',
'<https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test/ws/_cache/podman/osmo-ttcn3-hacks/log_merge.sh>
PCU_Tests --rm >/dev/null'][0m
[0;94m[testenv][generic] Returncode: 255[0m
Traceback (most recent call last):
  File
"<https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test/ws/./testenv.py",>
line 110, in <module>
    main()
  File
"<https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test/ws/./testenv.py",>
line 99, in main
    run()
  File
"<https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test/ws/./testenv.py",>
line 58, in run
    testenv.testsuite.run(cfg)
  File
"<https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test/ws/_testenv/testenv/testsuite.py",>
line 204, in run
    merge_log_files(cfg)
  File
"<https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test/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/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/ws/_testenv/testenv/podman.py",>
line 149, in exec_cmd
    return testenv.cmd.run(
           ^^^^^^^^^^^^^^^^
  File
"<https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test/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/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/2124/artifact/logs/ [0m
Build step 'Execute shell' marked build as failure
Recording test results
[Checks API] No suitable checks publisher found.

2025

2024

2023

2022

2021

2020

2019

Build failed in Jenkins: ttcn3-pcu-test #2124