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
[1;32m====== PCU_Tests.TC_pcuif_suspend_active_tbf pass ======[0m
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
[1;32m====== PCU_Tests.TC_ta_ptcch_idle pass ======[0m
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
[1;32m====== PCU_Tests.TC_ta_rach_imm_ass pass ======[0m
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
[1;31m------ PCU_Tests.TC_ta_ul_ack_nack_first_block fail ------[0m
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.