tests/pkg_libschc: Failing test_reassemble_success_ack_always

[MrKevinWeiss]

Description

Some of the test cases in tests/pkg_libschc seem to be failing

Steps to reproduce the issue

BOARD=nucleo-g474re make flash test -C tests/pkg_libschc

Expected results

...pass

Actual results

first run with nucleo-g474re

``` ====================================================================================================================================== FAILURES ====================================================================================================================================== __________________________________________________________________________________________________________________ TestSelfTest.test_reassemble_success_ack_always ___________________________________________________________________________________________________________________ self = <01-run.TestSelfTest testMethod=test_reassemble_success_ack_always> def test_reassemble_success_ack_always(self): self.input( b"\x17\x66\x00\x00\x00\x00\x00\xc1\x14\x0f\xe8\x00\x00\x00\x00\x00\x00\x00" b"\x00\x00\x00\x00\x00\x00\x00" ) self.spawn.sendline("reassemble init") self.spawn.sendline("reassemble 1 100") self.input_reset() self.input( b"\x17\x51\xfe\x80\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x02" b"\x1f\x41\x1f\x42\x00\x0c\x84" ) self.spawn.sendline("reassemble 1 100") self.input_reset() > self.input(b"\x17\x73\x14\xc8\x77\xf4\xe4\x00\x00\x00\x00") tests/01-run.py:657: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ tests/01-run.py:42: in input self.expect_od_dump_of(input_hex[:self.MAX]) tests/01-run.py:64: in expect_od_dump_of self.spawn.expect_exact("{:08x}{}".format(i * 16, od_bytes)) /home/weiss/.local/lib/python3.8/site-packages/pexpect/spawnbase.py:421: in expect_exact return exp.expect_loop(timeout) /home/weiss/.local/lib/python3.8/site-packages/pexpect/expect.py:181: in expect_loop return self.timeout(e) _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ self = , err = TIMEOUT('Timeout exceeded.') def timeout(self, err=None): spawn = self.spawn spawn.before = spawn._before.getvalue() spawn.after = TIMEOUT index = self.searcher.timeout_index if index >= 0: spawn.match = TIMEOUT spawn.match_index = index return index else: spawn.match = None spawn.match_index = None msg = str(spawn) msg += '\nsearcher: %s' % self.searcher if err is not None: msg = str(err) + '\n' + msg exc = TIMEOUT(msg) exc.__cause__ = None # in Python 3.x we can use "raise exc from None" > raise exc E pexpect.exceptions.TIMEOUT: Timeout exceeded. E E command: /usr/bin/make E args: [b'/usr/bin/make', b'cleanterm'] E buffer (last 100 chars): '00 17 73 14 C8 7F 4E 40 00\r\n\r\n> ' E before (last 100 chars): '\r\n00000000 17 73 14 C8 7F 4E 40 00\r\n\r\n> ' E after: E match: None E match_index: None E exitstatus: None E flag_eof: False E pid: 1902253 E child_fd: 13 E closed: False E timeout: 10 E delimiter: E logfile: None E logfile_read: None E logfile_send: None E maxread: 2000 E ignorecase: False E searchwindowsize: None E delaybeforesend: 0.05 E delayafterclose: 0.1 E delayafterterminate: 0.1 E searcher: searcher_string: E 0: '00000000 17 73 14 C8 77 F4 E4 00' /home/weiss/.local/lib/python3.8/site-packages/pexpect/expect.py:144: TIMEOUT ============================================================================================================================== short test summary info =============================================================================================================================== FAILED tests/01-run.py::TestSelfTest::test_reassemble_success_ack_always - pexpect.exceptions.TIMEOUT: Timeout exceeded. ```

second run

``` __________________________________________________________________________________________________________________ TestSelfTest.test_reassemble_success_ack_always ___________________________________________________________________________________________________________________ self = <01-run.TestSelfTest testMethod=test_reassemble_success_ack_always> def test_reassemble_success_ack_always(self): self.input( b"\x17\x66\x00\x00\x00\x00\x00\xc1\x14\x0f\xe8\x00\x00\x00\x00\x00\x00\x00" b"\x00\x00\x00\x00\x00\x00\x00" ) self.spawn.sendline("reassemble init") self.spawn.sendline("reassemble 1 100") self.input_reset() self.input( b"\x17\x51\xfe\x80\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x02" b"\x1f\x41\x1f\x42\x00\x0c\x84" ) self.spawn.sendline("reassemble 1 100") self.input_reset() > self.input(b"\x17\x73\x14\xc8\x77\xf4\xe4\x00\x00\x00\x00") tests/01-run.py:657: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ tests/01-run.py:42: in input self.expect_od_dump_of(input_hex[:self.MAX]) tests/01-run.py:64: in expect_od_dump_of self.spawn.expect_exact("{:08x}{}".format(i * 16, od_bytes)) /home/weiss/.local/lib/python3.8/site-packages/pexpect/spawnbase.py:421: in expect_exact return exp.expect_loop(timeout) /home/weiss/.local/lib/python3.8/site-packages/pexpect/expect.py:181: in expect_loop return self.timeout(e) _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ self = , err = TIMEOUT('Timeout exceeded.') def timeout(self, err=None): spawn = self.spawn spawn.before = spawn._before.getvalue() spawn.after = TIMEOUT index = self.searcher.timeout_index if index >= 0: spawn.match = TIMEOUT spawn.match_index = index return index else: spawn.match = None spawn.match_index = None msg = str(spawn) msg += '\nsearcher: %s' % self.searcher if err is not None: msg = str(err) + '\n' + msg exc = TIMEOUT(msg) exc.__cause__ = None # in Python 3.x we can use "raise exc from None" > raise exc E pexpect.exceptions.TIMEOUT: Timeout exceeded. E E command: /usr/bin/make E args: [b'/usr/bin/make', b'cleanterm'] E buffer (last 100 chars): '00 17 73 14 C8 7F 4E 40 00\r\n\r\n> ' E before (last 100 chars): '\r\n00000000 17 73 14 C8 7F 4E 40 00\r\n\r\n> ' E after: E match: None E match_index: None E exitstatus: None E flag_eof: False E pid: 1913359 E child_fd: 13 E closed: False E timeout: 10 E delimiter: E logfile: None E logfile_read: None E logfile_send: None E maxread: 2000 E ignorecase: False E searchwindowsize: None E delaybeforesend: 0.05 E delayafterclose: 0.1 E delayafterterminate: 0.1 E searcher: searcher_string: E 0: '00000000 17 73 14 C8 77 F4 E4 00' /home/weiss/.local/lib/python3.8/site-packages/pexpect/expect.py:144: TIMEOUT ```

with dumb sleeps

``` __________________________________________________________________________________________________________________ TestSelfTest.test_reassemble_success_ack_always ___________________________________________________________________________________________________________________ self = <01-run.TestSelfTest testMethod=test_reassemble_success_ack_always> def test_reassemble_success_ack_always(self): self.input( b"\x17\x66\x00\x00\x00\x00\x00\xc1\x14\x0f\xe8\x00\x00\x00\x00\x00\x00\x00" b"\x00\x00\x00\x00\x00\x00\x00" ) # input add 17660000000000c1140fe80000000000000000000000000000 self.spawn.sendline("reassemble init") self.spawn.sendline("reassemble 1 100") self.input_reset() self.input( b"\x17\x51\xfe\x80\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x02" b"\x1f\x41\x1f\x42\x00\x0c\x84" ) # input add 1751fe8000000000000000000000000000021f411f42000c84 self.spawn.sendline("reassemble 1 100") from time import sleep sleep(0.5) self.input_reset() from time import sleep sleep(0.5) self.input(b"\x17\x73\x14\xc8\x77\xf4\xe4\x00\x00\x00\x00") # input add 177314c877f4e400000000 sleep(0.5) self.spawn.sendline("reassemble 1 100") sleep(0.5) self.spawn.expect_exact("Packet sent on dev 0x1") sleep(0.5) > self.expect_od_dump_of(b"\x17\x20") tests/01-run.py:679: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ tests/01-run.py:72: in expect_od_dump_of self.spawn.expect_exact("{:08x}{}".format(i * 16, od_bytes), timeout=2) /home/weiss/.local/lib/python3.8/site-packages/pexpect/spawnbase.py:421: in expect_exact return exp.expect_loop(timeout) /home/weiss/.local/lib/python3.8/site-packages/pexpect/expect.py:181: in expect_loop return self.timeout(e) _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ self = , err = TIMEOUT('Timeout exceeded.') def timeout(self, err=None): spawn = self.spawn spawn.before = spawn._before.getvalue() spawn.after = TIMEOUT index = self.searcher.timeout_index if index >= 0: spawn.match = TIMEOUT spawn.match_index = index return index else: spawn.match = None spawn.match_index = None msg = str(spawn) msg += '\nsearcher: %s' % self.searcher if err is not None: msg = str(err) + '\n' + msg exc = TIMEOUT(msg) exc.__cause__ = None # in Python 3.x we can use "raise exc from None" > raise exc E pexpect.exceptions.TIMEOUT: Timeout exceeded. E E command: /usr/bin/make E args: [b'/usr/bin/make', b'cleanterm'] E buffer (last 100 chars): '40 00 00 00\r\n' E before (last 100 chars): '00000020 00 00 00 00 00 00 00 02 1F 41 1F 42 00 0C 84 4E\r\n00000030 40 00 00 00\r\n' E after: E match: None E match_index: None E exitstatus: None E flag_eof: False E pid: 1919218 E child_fd: 13 E closed: False E timeout: 10 E delimiter: E logfile: None E logfile_read: None E logfile_send: None E maxread: 2000 E ignorecase: False E searchwindowsize: None E delaybeforesend: 0.05 E delayafterclose: 0.1 E delayafterterminate: 0.1 E searcher: searcher_string: E 0: '00000000 17 20' /home/weiss/.local/lib/python3.8/site-packages/pexpect/expect.py:144: TIMEOUT ```

Versions

docker

[MrKevinWeiss]

I did an update of riotctrl and retested resulting in getting:

expected: '00000000  17  51  FE  80  00  00  00  00'
in the before buffer: `'\r\n00000000  17  5F  E8  00  00  00  00  00\r\n\r\n> '

It looks like it missed the hex 1 in 17 51 FE 80 which makes me think it is a bit of a printing issue. This means it is either a problem with the od_hex_dump_ext implementation or the application not respecting the thread requirements/protections needed.

Now, this passes on native and the goal of the test, I suppose, is to test a purely software based module. We could say that the failing is not due to the test itself, but some side effect that we currently lack a test to catch. If this is the case we can keep this issue open and use native in the allowlist.

I know you are a busy woman but maybe @miri64 can take a quick peek to confirm or deny my assumptions.

[miri64]

I know you are a busy woman but maybe @miri64 can take a quick peek to confirm or deny my assumptions.

I don't think od is the problem here, but rather some behavior in libschc (it acts on the byte level after all, so 4 bits missing smells suspiciously like libSCHC dropping something), but I agree with the conclusion to only whitelist for native (and maybe one of the LoRaWAN boards in the IoT-LAB so we can make sure it runs at least there?).

[MrKevinWeiss]

It also fails on the iotlab-m3 test. I will leave it as a known issue then for the release if we cannot fix it in time. This is a new feature and not a regression.