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 = <pexpect.expect.Expecter object at 0x7fa3673ffa00>, 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           <pexpect.pty_spawn.spawn object at 0x7fa3673ffb80>
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: <class 'pexpect.exceptions.TIMEOUT'>
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: <class 'pexpect.exceptions.EOF'>
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 = <pexpect.expect.Expecter object at 0x7f165391f2b0>, 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           <pexpect.pty_spawn.spawn object at 0x7f165391f430>
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: <class 'pexpect.exceptions.TIMEOUT'>
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: <class 'pexpect.exceptions.EOF'>
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 = <pexpect.expect.Expecter object at 0x7f65ed55efd0>, 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           <pexpect.pty_spawn.spawn object at 0x7f65ed55ecd0>
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: <class 'pexpect.exceptions.TIMEOUT'>
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: <class 'pexpect.exceptions.EOF'>
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.