Build failed in Jenkins: ttcn3-pcu-test-latest #1440

See <https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-latest/1440/display/redirect?page=changes> Changes: [Oliver Smith] ttcn3-*/jenkins*.sh: use $SUBNET everywhere [Oliver Smith] network_create: find free subnet automatically ------------------------------------------ [...truncated 31.58 KB...] MTC@b3f56d9298a2: Start timer T: 2 s PCUIF(17)@b3f56d9298a2: "Init PCU interface on '/data/unix/pcu_bts', waiting for connection..." PCUIF(17)@b3f56d9298a2: Start timer T: 5 s PCUIF(17)@b3f56d9298a2: Start timer T_Conn: 10 s TC_pcuif_suspend_active_tbf-STATS(19)@b3f56d9298a2: Start timer T: 2 s TC_pcuif_suspend_active_tbf-STATS(19)@b3f56d9298a2: Start timer T: 2 s PCUIF(17)@b3f56d9298a2: OsmoPCU is now connected BTS(18)@b3f56d9298a2: Rx TXT.ind from the PCU, version is "1.1.0" MTC@b3f56d9298a2: Start timer T: 10 s BTS(18)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX0/TS7" -NSVCI1234(16)@b3f56d9298a2: NSVC 1234 State Transition: NSVC_S_DEAD_BLOCKED (1) -> NSVC_S_ALIVE_BLOCKED (3) -NSVCI1234(16)@b3f56d9298a2: Rx NS-RESET: Sending NS-ALIVE -NSVCI1234(16)@b3f56d9298a2: Start timer Tns_alive: 3 s -NSVCI1234(16)@b3f56d9298a2: Start timer Tns_test: 10 s BTS(18)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX1/TS7" BTS(18)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX2/TS7" -NSVCI1234(16)@b3f56d9298a2: Warning: Stopping inactive timer Tns_block. -NSVCI1234(16)@b3f56d9298a2: NSVC 1234 State Transition: NSVC_S_ALIVE_BLOCKED (3) -> NSVC_S_ALIVE_UNBLOCKED (4) BTS(18)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX3/TS7" BTS(18)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX4/TS7" -NSVCI1234(16)@b3f56d9298a2: Rx NS-ALIVE-ACK: stopping Tns-alive; starting Tns-test -NSVCI1234(16)@b3f56d9298a2: Warning: Re-starting timer Tns_test, which is already active (running or expired). -NSVCI1234(16)@b3f56d9298a2: Start timer Tns_test: 10 s BTS(18)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX5/TS7" BTS(18)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX6/TS7" BTS(18)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX7/TS7" 13@b3f56d9298a2: Rx BVC-RESET for Signaling BVCI=0 13@b3f56d9298a2: BVCI(0) State Transition: BVC_S_WAIT_RESET (0) -> BVC_S_UNBLOCKED (3) TC_pcuif_suspend_active_tbf-BVCI1234(14)@b3f56d9298a2: Rx BVC-RESET from BVCI=1234 TC_pcuif_suspend_active_tbf-BVCI1234(14)@b3f56d9298a2: BVCI(1234) State Transition: BVC_S_BLOCKED (2) -> BVC_S_UNBLOCKED (3) MTC@b3f56d9298a2: BSSGP successfully initialized MTC@b3f56d9298a2: Sending RACH.ind on fn=1337 with RA=120, TA=0 MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Rx Immediate Assignment: { header := { l2_plen := { l2_plen := 11, zero_one := '01'B }, skip_indicator := 0, rr_protocol_discriminator := 6, message_type := IMMEDIATE_ASSIGNMENT (63) }, payload := { imm_ass := { ded_or_tbf := { spare := '0'B, tma := false, downlink := false, tbf := true }, page_mode := PAGE_MODE_NORMAL (0), chan_desc := omit, pkt_chan_desc := { channel_Type_spare := 1, tn := 7, tsc := 7, presence := '0'B, zero := { hopping := '0'B, spare := '0'B, arfcn := 871, indirect := omit }, one := omit }, req_ref := { ra := '01111000'B, t1p := 1, t3 := 11, t2 := 11 }, timing_advance := 0, mobile_allocation := { len := 0, ma := ''B }, rest_octets := { presence := '11'B, ll := omit, lh := omit, hl := omit, hh := { pa_disc := '0'B, pa := { uldl := { ass_disc := '0'B, ass := { ul := { presence := '1'B, dynamic := { tfi_assignment := 0, polling := '0'B, spare := '0'B, usf := 0, usf_granularity := '0'B, p0_present := '0'B, p0 := omit, pr_mode := omit, ch_coding_cmd := CH_CODING_CS2 (1), tlli_block_chan_coding := '1'B, alpha_present := '0'B, alpha := omit, gamma := 0, ta_index_present := '0'B, ta_index := omit, tbf_starting_time_present := '0'B, tbf_starting_time := omit }, single := omit } } } } } } } } } MTC@b3f56d9298a2: Rx Uplink TBF GPRS assignment: { presence := '1'B, dynamic := { tfi_assignment := 0, polling := '0'B, spare := '0'B, usf := 0, usf_granularity := '0'B, p0_present := '0'B, p0 := omit, pr_mode := omit, ch_coding_cmd := CH_CODING_CS2 (1), tlli_block_chan_coding := '1'B, alpha_present := '0'B, alpha := omit, gamma := 0, ta_index_present := '0'B, ta_index := omit, tbf_starting_time_present := '0'B, tbf_starting_time := omit }, single := omit } BTS(18)@b3f56d9298a2: Warning: dec_RlcmacDlCtrlBlock(): Data remained at the end of the stream after successful decoding: '4B2B2B2B2B'O ("K++++") MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Rx Immediate Assignment: { header := { l2_plen := { l2_plen := 11, zero_one := '01'B }, skip_indicator := 0, rr_protocol_discriminator := 6, message_type := IMMEDIATE_ASSIGNMENT (63) }, payload := { imm_ass := { ded_or_tbf := { spare := '0'B, tma := false, downlink := true, tbf := true }, page_mode := PAGE_MODE_NORMAL (0), chan_desc := omit, pkt_chan_desc := { channel_Type_spare := 1, tn := 7, tsc := 7, presence := '0'B, zero := { hopping := '0'B, spare := '0'B, arfcn := 871, indirect := omit }, one := omit }, req_ref := { ra := '01111101'B, t1p := 16, t3 := 8, t2 := 8 }, timing_advance := 0, mobile_allocation := { len := 0, ma := ''B }, rest_octets := { presence := '11'B, ll := omit, lh := omit, hl := omit, hh := { pa_disc := '0'B, pa := { uldl := { ass_disc := '1'B, ass := { dl := { tlli := '00000001'O, group1_present := '1'B, group1 := { tfi_assignment := 0, rlc_mode := '0'B, alpha_present := '0'B, alpha := 0, gamma := 4, polling := '0'B, ta_valid := '1'B }, ta_index_present := '1'B, ta_index := 2, tbf_starting_time_present := '1'B, tbf_starting_time := { t1 := 12, t3 := 43, t2 := 5 }, p0_present := '0'B, p0 := omit, pr_mode := omit } } } } } } } } } MTC@b3f56d9298a2: Rx Downlink TBF assignment: { ccch := { tlli := '00000001'O, group1_present := '1'B, group1 := { tfi_assignment := 0, rlc_mode := '0'B, alpha_present := '0'B, alpha := 0, gamma := 4, polling := '0'B, ta_valid := '1'B }, ta_index_present := '1'B, ta_index := 2, tbf_starting_time_present := '1'B, tbf_starting_time := { t1 := 12, t3 := 43, t2 := 5 }, p0_present := '0'B, p0 := omit, pr_mode := omit } } MTC@b3f56d9298a2: Start timer T: 0.2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Rx Immediate Assignment: { header := { l2_plen := { l2_plen := 11, zero_one := '01'B }, skip_indicator := 0, rr_protocol_discriminator := 6, message_type := IMMEDIATE_ASSIGNMENT (63) }, payload := { imm_ass := { ded_or_tbf := { spare := '0'B, tma := false, downlink := true, tbf := true }, page_mode := PAGE_MODE_NORMAL (0), chan_desc := omit, pkt_chan_desc := { channel_Type_spare := 1, tn := 7, tsc := 7, presence := '0'B, zero := { hopping := '0'B, spare := '0'B, arfcn := 871, indirect := omit }, one := omit }, req_ref := { ra := '01111101'B, t1p := 16, t3 := 22, t2 := 21 }, timing_advance := 0, mobile_allocation := { len := 0, ma := ''B }, rest_octets := { presence := '11'B, ll := omit, lh := omit, hl := omit, hh := { pa_disc := '0'B, pa := { uldl := { ass_disc := '1'B, ass := { dl := { tlli := '00000001'O, group1_present := '1'B, group1 := { tfi_assignment := 0, rlc_mode := '0'B, alpha_present := '0'B, alpha := 0, gamma := 4, polling := '0'B, ta_valid := '1'B }, ta_index_present := '1'B, ta_index := 2, tbf_starting_time_present := '1'B, tbf_starting_time := { t1 := 12, t3 := 43, t2 := 5 }, p0_present := '0'B, p0 := omit, pr_mode := omit } } } } } } } } } MTC@b3f56d9298a2: Rx Downlink TBF assignment: { ccch := { tlli := '00000001'O, group1_present := '1'B, group1 := { tfi_assignment := 0, rlc_mode := '0'B, alpha_present := '0'B, alpha := 0, gamma := 4, polling := '0'B, ta_valid := '1'B }, ta_index_present := '1'B, ta_index := 2, tbf_starting_time_present := '1'B, tbf_starting_time := { t1 := 12, t3 := 43, t2 := 5 }, p0_present := '0'B, p0 := omit, pr_mode := omit } } BTS(18)@b3f56d9298a2: Shutting down virtual BTS #0... MTC@b3f56d9298a2: Test case TC_pcuif_suspend_active_tbf finished. Verdict: pass MTC@b3f56d9298a2: Starting external command `../ttcn3-tcpdump-stop.sh PCU_Tests.TC_pcuif_suspend_active_tbf pass'. Tue Jan 17 05:00:18 UTC 2023 ====== PCU_Tests.TC_pcuif_suspend_active_tbf pass ====== Waiting for packet dumper to finish... 0 (prev_count=-1, count=70951) Waiting for packet dumper to finish... 1 (prev_count=70951, count=170421) MTC@b3f56d9298a2: External command `../ttcn3-tcpdump-stop.sh PCU_Tests.TC_pcuif_suspend_active_tbf pass' was executed successfully (exit status: 0). MTC@b3f56d9298a2: Starting external command `../ttcn3-tcpdump-start.sh PCU_Tests.TC_ta_ptcch_idle'. ------ PCU_Tests.TC_ta_ptcch_idle ------ Tue Jan 17 05:00:20 UTC 2023 NOTE: unable to use dumpcap due to missing capabilities or suid bit Waiting for packet dumper to start... 0 MTC@b3f56d9298a2: External command `../ttcn3-tcpdump-start.sh PCU_Tests.TC_ta_ptcch_idle' was executed successfully (exit status: 0). MTC@b3f56d9298a2: Test case TC_ta_ptcch_idle started. MTC@b3f56d9298a2: Start timer g_T_guard: 60 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s PCUIF(21)@b3f56d9298a2: "Init PCU interface on '/data/unix/pcu_bts', waiting for connection..." PCUIF(21)@b3f56d9298a2: Start timer T: 5 s PCUIF(21)@b3f56d9298a2: Start timer T_Conn: 10 s TC_ta_ptcch_idle-STATS(23)@b3f56d9298a2: Start timer T: 2 s TC_ta_ptcch_idle-STATS(23)@b3f56d9298a2: Start timer T: 2 s PCUIF(21)@b3f56d9298a2: OsmoPCU is now connected BTS(22)@b3f56d9298a2: Rx TXT.ind from the PCU, version is "1.1.0" MTC@b3f56d9298a2: Start timer T: 5 s BTS(22)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX0/TS7" BTS(22)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX1/TS7" BTS(22)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX2/TS7" BTS(22)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX3/TS7" BTS(22)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX4/TS7" BTS(22)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX5/TS7" BTS(22)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX6/TS7" BTS(22)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX7/TS7" MTC@b3f56d9298a2: Decoded PTCCH/D message: <unbound> BTS(22)@b3f56d9298a2: Shutting down virtual BTS #0... MTC@b3f56d9298a2: Test case TC_ta_ptcch_idle finished. Verdict: pass MTC@b3f56d9298a2: Starting external command `../ttcn3-tcpdump-stop.sh PCU_Tests.TC_ta_ptcch_idle pass'. Tue Jan 17 05:00:24 UTC 2023 ====== PCU_Tests.TC_ta_ptcch_idle pass ====== Waiting for packet dumper to finish... 0 (prev_count=-1, count=43290) Waiting for packet dumper to finish... 1 (prev_count=43290, count=114346) MTC@b3f56d9298a2: External command `../ttcn3-tcpdump-stop.sh PCU_Tests.TC_ta_ptcch_idle pass' was executed successfully (exit status: 0). MTC@b3f56d9298a2: Starting external command `../ttcn3-tcpdump-start.sh PCU_Tests.TC_ta_rach_imm_ass'. ------ PCU_Tests.TC_ta_rach_imm_ass ------ Tue Jan 17 05:00:26 UTC 2023 NOTE: unable to use dumpcap due to missing capabilities or suid bit Waiting for packet dumper to start... 0 MTC@b3f56d9298a2: External command `../ttcn3-tcpdump-start.sh PCU_Tests.TC_ta_rach_imm_ass' was executed successfully (exit status: 0). MTC@b3f56d9298a2: Test case TC_ta_rach_imm_ass started. MTC@b3f56d9298a2: Start timer g_T_guard: 60 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s PCUIF(25)@b3f56d9298a2: "Init PCU interface on '/data/unix/pcu_bts', waiting for connection..." PCUIF(25)@b3f56d9298a2: Start timer T: 5 s PCUIF(25)@b3f56d9298a2: Start timer T_Conn: 10 s TC_ta_rach_imm_ass-STATS(27)@b3f56d9298a2: Start timer T: 2 s TC_ta_rach_imm_ass-STATS(27)@b3f56d9298a2: Start timer T: 2 s PCUIF(25)@b3f56d9298a2: OsmoPCU is now connected BTS(26)@b3f56d9298a2: Rx TXT.ind from the PCU, version is "1.1.0" MTC@b3f56d9298a2: Sending RACH.ind on fn=1337 with RA=120, TA=0 MTC@b3f56d9298a2: Start timer T: 2 s BTS(26)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX0/TS7" BTS(26)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX1/TS7" BTS(26)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX2/TS7" BTS(26)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX3/TS7" BTS(26)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX4/TS7" BTS(26)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX5/TS7" BTS(26)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX6/TS7" BTS(26)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX7/TS7" MTC@b3f56d9298a2: Rx Immediate Assignment: { header := { l2_plen := { l2_plen := 11, zero_one := '01'B }, skip_indicator := 0, rr_protocol_discriminator := 6, message_type := IMMEDIATE_ASSIGNMENT (63) }, payload := { imm_ass := { ded_or_tbf := { spare := '0'B, tma := false, downlink := false, tbf := true }, page_mode := PAGE_MODE_NORMAL (0), chan_desc := omit, pkt_chan_desc := { channel_Type_spare := 1, tn := 7, tsc := 7, presence := '0'B, zero := { hopping := '0'B, spare := '0'B, arfcn := 871, indirect := omit }, one := omit }, req_ref := { ra := '01111000'B, t1p := 1, t3 := 11, t2 := 11 }, timing_advance := 0, mobile_allocation := { len := 0, ma := ''B }, rest_octets := { presence := '11'B, ll := omit, lh := omit, hl := omit, hh := { pa_disc := '0'B, pa := { uldl := { ass_disc := '0'B, ass := { ul := { presence := '1'B, dynamic := { tfi_assignment := 0, polling := '0'B, spare := '0'B, usf := 0, usf_granularity := '0'B, p0_present := '0'B, p0 := omit, pr_mode := omit, ch_coding_cmd := CH_CODING_CS2 (1), tlli_block_chan_coding := '1'B, alpha_present := '0'B, alpha := omit, gamma := 0, ta_index_present := '0'B, ta_index := omit, tbf_starting_time_present := '0'B, tbf_starting_time := omit }, single := omit } } } } } } } } } MTC@b3f56d9298a2: Rx Uplink TBF GPRS assignment: { presence := '1'B, dynamic := { tfi_assignment := 0, polling := '0'B, spare := '0'B, usf := 0, usf_granularity := '0'B, p0_present := '0'B, p0 := omit, pr_mode := omit, ch_coding_cmd := CH_CODING_CS2 (1), tlli_block_chan_coding := '1'B, alpha_present := '0'B, alpha := omit, gamma := 0, ta_index_present := '0'B, ta_index := omit, tbf_starting_time_present := '0'B, tbf_starting_time := omit }, single := omit } MTC@b3f56d9298a2: Sending RACH.ind on fn=1353 with RA=120, TA=16 MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Rx Immediate Assignment: { header := { l2_plen := { l2_plen := 11, zero_one := '01'B }, skip_indicator := 0, rr_protocol_discriminator := 6, message_type := IMMEDIATE_ASSIGNMENT (63) }, payload := { imm_ass := { ded_or_tbf := { spare := '0'B, tma := false, downlink := false, tbf := true }, page_mode := PAGE_MODE_NORMAL (0), chan_desc := omit, pkt_chan_desc := { channel_Type_spare := 1, tn := 7, tsc := 7, presence := '0'B, zero := { hopping := '0'B, spare := '0'B, arfcn := 872, indirect := omit }, one := omit }, req_ref := { ra := '01111000'B, t1p := 1, t3 := 27, t2 := 1 }, timing_advance := 16, mobile_allocation := { len := 0, ma := ''B }, rest_octets := { presence := '11'B, ll := omit, lh := omit, hl := omit, hh := { pa_disc := '0'B, pa := { uldl := { ass_disc := '0'B, ass := { ul := { presence := '1'B, dynamic := { tfi_assignment := 0, polling := '0'B, spare := '0'B, usf := 0, usf_granularity := '0'B, p0_present := '0'B, p0 := omit, pr_mode := omit, ch_coding_cmd := CH_CODING_CS2 (1), tlli_block_chan_coding := '1'B, alpha_present := '0'B, alpha := omit, gamma := 0, ta_index_present := '0'B, ta_index := omit, tbf_starting_time_present := '0'B, tbf_starting_time := omit }, single := omit } } } } } } } } } MTC@b3f56d9298a2: Rx Uplink TBF GPRS assignment: { presence := '1'B, dynamic := { tfi_assignment := 0, polling := '0'B, spare := '0'B, usf := 0, usf_granularity := '0'B, p0_present := '0'B, p0 := omit, pr_mode := omit, ch_coding_cmd := CH_CODING_CS2 (1), tlli_block_chan_coding := '1'B, alpha_present := '0'B, alpha := omit, gamma := 0, ta_index_present := '0'B, ta_index := omit, tbf_starting_time_present := '0'B, tbf_starting_time := omit }, single := omit } MTC@b3f56d9298a2: Sending RACH.ind on fn=1369 with RA=120, TA=32 MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Rx Immediate Assignment: { header := { l2_plen := { l2_plen := 11, zero_one := '01'B }, skip_indicator := 0, rr_protocol_discriminator := 6, message_type := IMMEDIATE_ASSIGNMENT (63) }, payload := { imm_ass := { ded_or_tbf := { spare := '0'B, tma := false, downlink := false, tbf := true }, page_mode := PAGE_MODE_NORMAL (0), chan_desc := omit, pkt_chan_desc := { channel_Type_spare := 1, tn := 7, tsc := 7, presence := '0'B, zero := { hopping := '0'B, spare := '0'B, arfcn := 873, indirect := omit }, one := omit }, req_ref := { ra := '01111000'B, t1p := 1, t3 := 43, t2 := 17 }, timing_advance := 32, mobile_allocation := { len := 0, ma := ''B }, rest_octets := { presence := '11'B, ll := omit, lh := omit, hl := omit, hh := { pa_disc := '0'B, pa := { uldl := { ass_disc := '0'B, ass := { ul := { presence := '1'B, dynamic := { tfi_assignment := 0, polling := '0'B, spare := '0'B, usf := 0, usf_granularity := '0'B, p0_present := '0'B, p0 := omit, pr_mode := omit, ch_coding_cmd := CH_CODING_CS2 (1), tlli_block_chan_coding := '1'B, alpha_present := '0'B, alpha := omit, gamma := 0, ta_index_present := '0'B, ta_index := omit, tbf_starting_time_present := '0'B, tbf_starting_time := omit }, single := omit } } } } } } } } } MTC@b3f56d9298a2: Rx Uplink TBF GPRS assignment: { presence := '1'B, dynamic := { tfi_assignment := 0, polling := '0'B, spare := '0'B, usf := 0, usf_granularity := '0'B, p0_present := '0'B, p0 := omit, pr_mode := omit, ch_coding_cmd := CH_CODING_CS2 (1), tlli_block_chan_coding := '1'B, alpha_present := '0'B, alpha := omit, gamma := 0, ta_index_present := '0'B, ta_index := omit, tbf_starting_time_present := '0'B, tbf_starting_time := omit }, single := omit } MTC@b3f56d9298a2: Sending RACH.ind on fn=1385 with RA=120, TA=48 MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Rx Immediate Assignment: { header := { l2_plen := { l2_plen := 11, zero_one := '01'B }, skip_indicator := 0, rr_protocol_discriminator := 6, message_type := IMMEDIATE_ASSIGNMENT (63) }, payload := { imm_ass := { ded_or_tbf := { spare := '0'B, tma := false, downlink := false, tbf := true }, page_mode := PAGE_MODE_NORMAL (0), chan_desc := omit, pkt_chan_desc := { channel_Type_spare := 1, tn := 7, tsc := 7, presence := '0'B, zero := { hopping := '0'B, spare := '0'B, arfcn := 874, indirect := omit }, one := omit }, req_ref := { ra := '01111000'B, t1p := 1, t3 := 8, t2 := 7 }, timing_advance := 48, mobile_allocation := { len := 0, ma := ''B }, rest_octets := { presence := '11'B, ll := omit, lh := omit, hl := omit, hh := { pa_disc := '0'B, pa := { uldl := { ass_disc := '0'B, ass := { ul := { presence := '1'B, dynamic := { tfi_assignment := 0, polling := '0'B, spare := '0'B, usf := 0, usf_granularity := '0'B, p0_present := '0'B, p0 := omit, pr_mode := omit, ch_coding_cmd := CH_CODING_CS2 (1), tlli_block_chan_coding := '1'B, alpha_present := '0'B, alpha := omit, gamma := 0, ta_index_present := '0'B, ta_index := omit, tbf_starting_time_present := '0'B, tbf_starting_time := omit }, single := omit } } } } } } } } } MTC@b3f56d9298a2: Rx Uplink TBF GPRS assignment: { presence := '1'B, dynamic := { tfi_assignment := 0, polling := '0'B, spare := '0'B, usf := 0, usf_granularity := '0'B, p0_present := '0'B, p0 := omit, pr_mode := omit, ch_coding_cmd := CH_CODING_CS2 (1), tlli_block_chan_coding := '1'B, alpha_present := '0'B, alpha := omit, gamma := 0, ta_index_present := '0'B, ta_index := omit, tbf_starting_time_present := '0'B, tbf_starting_time := omit }, single := omit } BTS(26)@b3f56d9298a2: Shutting down virtual BTS #0... MTC@b3f56d9298a2: Test case TC_ta_rach_imm_ass finished. Verdict: pass MTC@b3f56d9298a2: Starting external command `../ttcn3-tcpdump-stop.sh PCU_Tests.TC_ta_rach_imm_ass pass'. Tue Jan 17 05:00:29 UTC 2023 ====== PCU_Tests.TC_ta_rach_imm_ass pass ====== Waiting for packet dumper to finish... 0 (prev_count=-1, count=6298) Waiting for packet dumper to finish... 1 (prev_count=6298, count=77643) MTC@b3f56d9298a2: External command `../ttcn3-tcpdump-stop.sh PCU_Tests.TC_ta_rach_imm_ass pass' was executed successfully (exit status: 0). MTC@b3f56d9298a2: Starting external command `../ttcn3-tcpdump-start.sh PCU_Tests.TC_ta_ul_ack_nack_first_block'. ------ PCU_Tests.TC_ta_ul_ack_nack_first_block ------ Tue Jan 17 05:00:31 UTC 2023 NOTE: unable to use dumpcap due to missing capabilities or suid bit Waiting for packet dumper to start... 0 MTC@b3f56d9298a2: External command `../ttcn3-tcpdump-start.sh PCU_Tests.TC_ta_ul_ack_nack_first_block' was executed successfully (exit status: 0). MTC@b3f56d9298a2: Test case TC_ta_ul_ack_nack_first_block started. 29@b3f56d9298a2: Creating NSIP provider for "172.18.105.10":23000 TC_ta_ul_ack_nack_first_block-BVCI1234(31)@b3f56d9298a2: Adding Client=mtc, IMSI='262420000000001'H, TLLI='FFFFFFFF'O, index=0 MTC@b3f56d9298a2: Start timer g_T_guard: 60 s 29@b3f56d9298a2: Starting NSVC component for { provider := { ip := { address_family := AF_INET (2), local_udp_port := 23000, local_ip := "172.18.105.10", remote_udp_port := 23000, remote_ip := "172.18.105.101", data_weight := 1, signalling_weight := 1 } }, nsvci := 1234 } -NSVCI1234(33)@b3f56d9298a2: NSVC 1234 State Transition: NSVC_S_DEAD_BLOCKED (1) -> NSVC_S_DEAD_BLOCKED (1) -NSVCI1234(33)@b3f56d9298a2: Provider Link came up: waiting for NS-RESET MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Start timer T: 2 s PCUIF(34)@b3f56d9298a2: "Init PCU interface on '/data/unix/pcu_bts', waiting for connection..." PCUIF(34)@b3f56d9298a2: Start timer T: 5 s PCUIF(34)@b3f56d9298a2: Start timer T_Conn: 10 s TC_ta_ul_ack_nack_first_block-STATS(36)@b3f56d9298a2: Start timer T: 2 s TC_ta_ul_ack_nack_first_block-STATS(36)@b3f56d9298a2: Start timer T: 2 s PCUIF(34)@b3f56d9298a2: OsmoPCU is now connected BTS(35)@b3f56d9298a2: Rx TXT.ind from the PCU, version is "1.1.0" MTC@b3f56d9298a2: Start timer T: 10 s -NSVCI1234(33)@b3f56d9298a2: NSVC 1234 State Transition: NSVC_S_DEAD_BLOCKED (1) -> NSVC_S_ALIVE_BLOCKED (3) BTS(35)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX0/TS7" -NSVCI1234(33)@b3f56d9298a2: Rx NS-RESET: Sending NS-ALIVE -NSVCI1234(33)@b3f56d9298a2: Start timer Tns_alive: 3 s -NSVCI1234(33)@b3f56d9298a2: Start timer Tns_test: 10 s BTS(35)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX1/TS7" BTS(35)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX2/TS7" -NSVCI1234(33)@b3f56d9298a2: Warning: Stopping inactive timer Tns_block. -NSVCI1234(33)@b3f56d9298a2: NSVC 1234 State Transition: NSVC_S_ALIVE_BLOCKED (3) -> NSVC_S_ALIVE_UNBLOCKED (4) BTS(35)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX3/TS7" BTS(35)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX4/TS7" -NSVCI1234(33)@b3f56d9298a2: Rx NS-ALIVE-ACK: stopping Tns-alive; starting Tns-test -NSVCI1234(33)@b3f56d9298a2: Warning: Re-starting timer Tns_test, which is already active (running or expired). -NSVCI1234(33)@b3f56d9298a2: Start timer Tns_test: 10 s BTS(35)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX5/TS7" BTS(35)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX6/TS7" BTS(35)@b3f56d9298a2: "Rx ACT.req from the PCU: TRX7/TS7" 30@b3f56d9298a2: Rx BVC-RESET for Signaling BVCI=0 30@b3f56d9298a2: BVCI(0) State Transition: BVC_S_WAIT_RESET (0) -> BVC_S_UNBLOCKED (3) TC_ta_ul_ack_nack_first_block-BVCI1234(31)@b3f56d9298a2: Rx BVC-RESET from BVCI=1234 TC_ta_ul_ack_nack_first_block-BVCI1234(31)@b3f56d9298a2: BVCI(1234) State Transition: BVC_S_BLOCKED (2) -> BVC_S_UNBLOCKED (3) MTC@b3f56d9298a2: BSSGP successfully initialized MTC@b3f56d9298a2: Sending RACH.ind on fn=1337 with RA=120, TA=0 MTC@b3f56d9298a2: Start timer T: 2 s MTC@b3f56d9298a2: Rx Immediate Assignment: { header := { l2_plen := { l2_plen := 11, zero_one := '01'B }, skip_indicator := 0, rr_protocol_discriminator := 6, message_type := IMMEDIATE_ASSIGNMENT (63) }, payload := { imm_ass := { ded_or_tbf := { spare := '0'B, tma := false, downlink := false, tbf := true }, page_mode := PAGE_MODE_NORMAL (0), chan_desc := omit, pkt_chan_desc := { channel_Type_spare := 1, tn := 7, tsc := 7, presence := '0'B, zero := { hopping := '0'B, spare := '0'B, arfcn := 871, indirect := omit }, one := omit }, req_ref := { ra := '01111000'B, t1p := 1, t3 := 11, t2 := 11 }, timing_advance := 0, mobile_allocation := { len := 0, ma := ''B }, rest_octets := { presence := '11'B, ll := omit, lh := omit, hl := omit, hh := { pa_disc := '0'B, pa := { uldl := { ass_disc := '0'B, ass := { ul := { presence := '1'B, dynamic := { tfi_assignment := 0, polling := '0'B, spare := '0'B, usf := 0, usf_granularity := '0'B, p0_present := '0'B, p0 := omit, pr_mode := omit, ch_coding_cmd := CH_CODING_CS2 (1), tlli_block_chan_coding := '1'B, alpha_present := '0'B, alpha := omit, gamma := 0, ta_index_present := '0'B, ta_index := omit, tbf_starting_time_present := '0'B, tbf_starting_time := omit }, single := omit } } } } } } } } } MTC@b3f56d9298a2: Rx Uplink TBF GPRS assignment: { presence := '1'B, dynamic := { tfi_assignment := 0, polling := '0'B, spare := '0'B, usf := 0, usf_granularity := '0'B, p0_present := '0'B, p0 := omit, pr_mode := omit, ch_coding_cmd := CH_CODING_CS2 (1), tlli_block_chan_coding := '1'B, alpha_present := '0'B, alpha := omit, gamma := 0, ta_index_present := '0'B, ta_index := omit, tbf_starting_time_present := '0'B, tbf_starting_time := omit }, single := omit } BTS(35)@b3f56d9298a2: Warning: dec_RlcmacDlCtrlBlock(): Data remained at the end of the stream after successful decoding: '4B2B2B2B2B'O ("K++++") MTC@b3f56d9298a2: Test case "TC_ta_ul_ack_nack_first_block" aborted at "PCU_Tests.ttcn":561 BTS(35)@b3f56d9298a2: Shutting down virtual BTS #0... MTC@b3f56d9298a2: Test case TC_ta_ul_ack_nack_first_block finished. Verdict: fail reason: Timing Advance mismatch: expected 2, but received 0 MTC@b3f56d9298a2: Starting external command `../ttcn3-tcpdump-stop.sh PCU_Tests.TC_ta_ul_ack_nack_first_block fail'. Tue Jan 17 05:00:34 UTC 2023 ------ PCU_Tests.TC_ta_ul_ack_nack_first_block fail ------ Waiting for packet dumper to finish... 0 (prev_count=-1, count=7835) Waiting for packet dumper to finish... 1 (prev_count=7835, count=71972) + clean_up_common + set +e + set +x ### Clean up ### + trap - EXIT INT TERM 0 + type clean_up + network_clean + docker network inspect ttcn3-pcu-test + grep Name + cut -d : -f2 + awk -F" NR>1{print $2} + xargs -rn1 docker kill jenkins-ttcn3-pcu-test-latest-1440-pcu + network_remove + set +x Removing network ttcn3-pcu-test + docker network remove ttcn3-pcu-test Error: No such network: ttcn3-pcu-test + rm -rf <https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-latest/1440/artifact/logs/unix> + fix_perms + set +x Fixing permissions + docker run --rm -v <https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-latest/ws/logs>:/data -v <https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-latest/ws/_cache>:/cache --name jenkins-ttcn3-pcu-test-latest-1440-cleaner debian:bullseye chmod -R a+rX /data/ /cache/ + collect_logs + cat <https://jenkins.osmocom.org/jenkins/job/ttcn3-pcu-test-latest/1440/artifact/logs/pcu-tester/junit-xml-21.log> Build step 'Execute shell' marked build as failure Recording test results [Checks API] No suitable checks publisher found.