Actions
Bug #4780
closedttcn3-pcu-test: regression: PCU_Tests.TC_ul_all_sizes fails due to "Timeout of T_guard"
Added by fixeria over 3 years ago. Updated over 3 years ago.
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.
Updated by fixeria over 3 years 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.
Updated by fixeria over 3 years ago
- Status changed from New to In Progress
- Assignee set to fixeria
Updated by fixeria over 3 years ago
- % Done changed from 0 to 20
I manually compared both capture files from the build artifacts:
vs
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));
}
Updated by fixeria over 3 years 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
Updated by laforge over 3 years 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
Updated by fixeria over 3 years ago
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)
Updated by fixeria over 3 years 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)
Updated by fixeria over 3 years 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.
Updated by fixeria over 3 years 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
Actions
