Project

General

Profile

Bug #4780

ttcn3-pcu-test: regression: PCU_Tests.TC_ul_all_sizes fails due to "Timeout of T_guard"

Added by fixeria 21 days ago. Updated 10 days ago.

Status:
Resolved
Priority:
High
Assignee:
Target version:
-
Start date:
10/06/2020
Due date:
% Done:

20%

Spec Reference:
Tags:

Description

Starting from build 610 in 'master' and 597 in 'latest', PCU_Tests.TC_ul_all_sizes fails due to "Timeout of T_guard". Not only in Jenkins, but also on my machine.

History

#1 Updated by fixeria 10 days ago

Interestingly enough, since build#622 in ttcn3-pcu-test and build#142 in TTCN3-centos-pcu-test this test case magically started to pass.

#2 Updated by fixeria 10 days ago

  • Status changed from New to In Progress
  • Assignee set to fixeria

#3 Updated by fixeria 10 days ago

  • % Done changed from 0 to 20

I manually compared both capture files from the build artifacts:

https://jenkins.osmocom.org/jenkins/view/TTCN3-centos/job/TTCN3-centos-pcu-test/141/artifact/logs/pcu-tester/PCU_Tests.TC_ul_all_sizes.pcap.gz (failing)

vs

https://jenkins.osmocom.org/jenkins/view/TTCN3-centos/job/TTCN3-centos-pcu-test/143/artifact/logs/pcu-tester/PCU_Tests.TC_ul_all_sizes.pcap.gz (passing)

in Wireshark side by side. The idea of PCU_Tests.TC_ul_all_sizes (as its name states) is to send random Uplink blocks of all possible size values in range 1 .. 49 (inclusive), and in the failing case something really odd happens when sending a block with 40 random octets:

Packet # Description Comment
1367 GPRS RLC/MAC UL: CV=15 BSN=40 The tester sends an Uplink block with 40 random octets over the PCUIF
1365 NS-UD BVCI=1234 / BSSGP-UD TLLI=0x01 The PCU sends that block towards the tester over the NS
1368 NS-STATUS Cause: PDU not compatible with the protocol state (0x0a) The tester responds with an error?

Why would ttcn3-pcu-test respond with such an error?

The seems to be originated from NS_Emulation.as_allstate():

/* default case of handling unknown PDUs */
[] NSCP.receive(PDU_NS: ?) -> value rf {
    log("Rx Unexpected NS PDU ", rf," in state ", g_state);
    NSCP.send(ts_NS_STATUS(NS_CAUSE_PDU_NOT_COMPATIBLE_WITH_PROTOCOL_STATE, rf));
}

#4 Updated by fixeria 10 days ago

  • Priority changed from Normal to High

Huh, I wanted to run this test case on my own machine, and... it does not even start due to the same error:

$ tshark -i lo -Y udp
Capturing on 'Loopback: lo'
  184 1.058662350    127.0.0.1 → 127.0.0.1    GPRS-NS 43 NS_ALIVE
  185 1.058677290    127.0.0.1 → 127.0.0.1    ICMP 71 Destination unreachable (Port unreachable)
  453 4.195866700    127.0.0.1 → 127.0.0.1    GPRS-NS 54 NS_RESET, Cause: O&M intervention, NS VCI: 0x4d2, NSEI 1234
  498 4.202726524    127.0.0.1 → 127.0.0.1    GPRS-NS 60 NS_STATUS, Cause: PDU not compatible with the protocol state, NS_RESET, Cause: O&M intervention, NS VCI: 0x4d2, NSEI 1234
 1118 7.195989949    127.0.0.1 → 127.0.0.1    GPRS-NS 54 NS_RESET, Cause: O&M intervention, NS VCI: 0x4d2, NSEI 1234
 1133 7.197844509    127.0.0.1 → 127.0.0.1    GPRS-NS 60 NS_STATUS, Cause: PDU not compatible with the protocol state, NS_RESET, Cause: O&M intervention, NS VCI: 0x4d2, NSEI 1234
 1721 10.196096774   127.0.0.1 → 127.0.0.1    GPRS-NS 54 NS_RESET, Cause: O&M intervention, NS VCI: 0x4d2, NSEI 1234
 1736 10.198077305   127.0.0.1 → 127.0.0.1    GPRS-NS 60 NS_STATUS, Cause: PDU not compatible with the protocol state, NS_RESET, Cause: O&M intervention, NS VCI: 0x4d2, NSEI 1234
 2325 13.196244470   127.0.0.1 → 127.0.0.1    GPRS-NS 54 NS_RESET, Cause: O&M intervention, NS VCI: 0x4d2, NSEI 1234
 2340 13.199208419   127.0.0.1 → 127.0.0.1    GPRS-NS 60 NS_STATUS, Cause: PDU not compatible with the protocol state, NS_RESET, Cause: O&M intervention, NS VCI: 0x4d2, NSEI 1234

#5 Updated by laforge 10 days ago

12:18 < fixeria> LaF0rge: would be nice to get your feedback: https://osmocom.org/issues/4780#note-4 
                 thanks!
12:58 <@LaF0rge> fixeria: the question is: Which dialect of NS are you trying to use here?
12:59 <@LaF0rge> fixeria: a non-standard combination pre-release-4 NS over IP (like nanoBTS)?  Or a 3PP 
                 Gb-over-IP compliant interface?
13:00 <@LaF0rge> in the former case (R97/R99 used over IP which was never specified) you would need 
                 NS-RESET/NS-UNBLOCK
13:00 <@LaF0rge> fixeria: in the latter case (Rel-4 or later), the use of NS-RESET/UNBLOCK/BLOCK is 
                 forbidden
13:00 <@LaF0rge> fixeria: now if one side implementa one dialect and the other another, it will have 
                 effects like this: One side waits for a RESET while the other side never sends one

#6 Updated by fixeria 10 days ago

From https://jenkins.osmocom.org/jenkins/view/TTCN3-centos/job/TTCN3-centos-pcu-test/141/artifact/logs/pcu-tester/PCU_Tests.TC_ul_all_sizes.merged:

02:44:24.188796 67 NS_Emulation.ttcnpp:265 Rx Unexpected NS PDU { pDU_NS_Unitdata := { nsPduType := '00'O, nS_SDU_ControlBits := { rBit := '0'B, cBit := '0'B, spare := '000000'B }, bVCI := '04D2'O, nS_SDU := '0100000001000004088862F224334F0051E000800E0028902DEFACBAA3F0B852D24A4566891B9C1A25CA181B71E6ADF41A41DE0FDFC3E1C032B74DF56368D5'O } } in state NSE_S_DEAD_BLOCKED (0)
02:44:33.119129 67 NS_Emulation.ttcnpp:265 Rx Unexpected NS PDU { pDU_NS_Unitdata := { nsPduType := '00'O, nS_SDU_ControlBits := { rBit := '0'B, cBit := '0'B, spare := '000000'B }, bVCI := '04D2'O, nS_SDU := '261E8102058207D003820640018203E81C82032006820000'O } } in state NSE_S_DEAD_BLOCKED (0)
02:44:43.119259 67 NS_Emulation.ttcnpp:265 Rx Unexpected NS PDU { pDU_NS_Unitdata := { nsPduType := '00'O, nS_SDU_ControlBits := { rBit := '0'B, cBit := '0'B, spare := '000000'B }, bVCI := '04D2'O, nS_SDU := '261E8103058207D003820640018203E81C82032006820000'O } } in state NSE_S_DEAD_BLOCKED (0)
02:44:53.119442 67 NS_Emulation.ttcnpp:265 Rx Unexpected NS PDU { pDU_NS_Unitdata := { nsPduType := '00'O, nS_SDU_ControlBits := { rBit := '0'B, cBit := '0'B, spare := '000000'B }, bVCI := '04D2'O, nS_SDU := '261E8104058207D003820640018203E81C82032006820000'O } } in state NSE_S_DEAD_BLOCKED (0)
02:45:03.119560 67 NS_Emulation.ttcnpp:265 Rx Unexpected NS PDU { pDU_NS_Unitdata := { nsPduType := '00'O, nS_SDU_ControlBits := { rBit := '0'B, cBit := '0'B, spare := '000000'B }, bVCI := '04D2'O, nS_SDU := '261E8105058207D003820640018203E81C82032006820000'O } } in state NSE_S_DEAD_BLOCKED (0)
02:45:13.119812 67 NS_Emulation.ttcnpp:265 Rx Unexpected NS PDU { pDU_NS_Unitdata := { nsPduType := '00'O, nS_SDU_ControlBits := { rBit := '0'B, cBit := '0'B, spare := '000000'B }, bVCI := '04D2'O, nS_SDU := '261E8106058207D003820640018203E81C82032006820000'O } } in state NSE_S_DEAD_BLOCKED (0)

on my machine:

3@DELL: Rx Unexpected NS PDU { pDU_NS_Reset := { nsPduType := '02'O, causeNS := { iEI := '00'O, ext := '1'B, lengthIndicator := { length1 := 1 }, cause := '01'O }, nS_VCI := { iEI := '01'O, ext := '1'B, lengthIndicator := { length1 := 2 }, nS_VCI := '04D2'O }, nSEI_NS := { iEI := '04'O, ext := '1'B, lengthIndicator := { length1 := 2 }, nSEI := '04D2'O } } } in state NSE_S_DEAD_BLOCKED (0)
3@DELL: Rx Unexpected NS PDU { pDU_NS_Reset := { nsPduType := '02'O, causeNS := { iEI := '00'O, ext := '1'B, lengthIndicator := { length1 := 1 }, cause := '01'O }, nS_VCI := { iEI := '01'O, ext := '1'B, lengthIndicator := { length1 := 2 }, nS_VCI := '04D2'O }, nSEI_NS := { iEI := '04'O, ext := '1'B, lengthIndicator := { length1 := 2 }, nSEI := '04D2'O } } } in state NSE_S_DEAD_BLOCKED (0)
3@DELL: Rx Unexpected NS PDU { pDU_NS_Reset := { nsPduType := '02'O, causeNS := { iEI := '00'O, ext := '1'B, lengthIndicator := { length1 := 1 }, cause := '01'O }, nS_VCI := { iEI := '01'O, ext := '1'B, lengthIndicator := { length1 := 2 }, nS_VCI := '04D2'O }, nSEI_NS := { iEI := '04'O, ext := '1'B, lengthIndicator := { length1 := 2 }, nSEI := '04D2'O } } } in state NSE_S_DEAD_BLOCKED (0)
3@DELL: Rx Unexpected NS PDU { pDU_NS_Reset := { nsPduType := '02'O, causeNS := { iEI := '00'O, ext := '1'B, lengthIndicator := { length1 := 1 }, cause := '01'O }, nS_VCI := { iEI := '01'O, ext := '1'B, lengthIndicator := { length1 := 2 }, nS_VCI := '04D2'O }, nSEI_NS := { iEI := '04'O, ext := '1'B, lengthIndicator := { length1 := 2 }, nSEI := '04D2'O } } } in state NSE_S_DEAD_BLOCKED (0)

#7 Updated by fixeria 10 days ago

02:44:24.130178 67 NS_Emulation.ttcnpp:209 Timeout Tns_alive: 3 s
02:44:24.130208 67 NS_Emulation.ttcnpp:210 Tns-alive expired: changing to DEAD_BLOCKED + starting Tns-test
02:44:24.130227 67 NS_Emulation.ttcnpp:179 NS State Transition: NSE_S_ALIVE_UNBLOCKED (3) -> NSE_S_DEAD_BLOCKED (0)

#8 Updated by fixeria 10 days ago

  • Status changed from In Progress to Resolved

The test case is passing reliably several times in a raw on my machine, so I think it was some regression that got fixed. The only issue was missing f_shutdown(final := true) at the end of the test code, see:

https://gerrit.osmocom.org/c/osmo-ttcn3-hacks/+/20709 PCU_Tests: add missing f_shutdown(final := true) statements

I think we can close this ticket now.

#9 Updated by fixeria 10 days ago

Just for the record:

Huh, I wanted to run this test case on my own machine, and... it does not even start due to the same error:

the problem was that I didn't have 'handle_sns := false' in my PCU_Tests.cfg, see also:

https://gerrit.osmocom.org/c/osmo-ttcn3-hacks/+/20704 PCU_Tests.cfg: synchronize with docker-playground

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)