[BUG] testrunner matching local echo

[cladmi]

Contribution description

When local echo is enabled, pexpect will also match on send lines to the
node. So could think a node is echoing when it is only seeing the sent
message.
The sent messages are still written to logfile but now only once.

This may show issues with our current tests implementation that expected
this behavior.

Testing procedure

I included a test commit to show the fixed issue.
Sending a string to hello-world and matching on the same string works in master even if the nodes does not echo anything.

When running the test commit alone, it will fail with a RuntimeError to show the erroneous behavior.
With the disable local echo fix, the test passes.

# both with native and a board to show it is not a `pyterm` issue

BOARD=native make -C examples/hello-world flash test
BOARD=samr21-xpro make -C examples/hello-world flash test

EDIT: it can now be tested with #11094 alone.

I will retry all our test suite on this:

• native after running dist/tools/tapsetup/tapsetup
  • Only have the same error as in master
    • tests/gnrc_ipv6_ext No root permission
    • tests/gnrc_rpl_srh No root permission
• samr21-xpro
  • Only have the same error as in master
    • tests/gnrc_ipv6_ext No root permission
    • tests/gnrc_rpl_srh No root permission
    • tests/pkg_fatfs_vfs It needs a special initial configuration

Issues/PRs references

Found while implementing #10949 based on testrunner handling.

Depends on #11064
Depends on #11086 Silencing codacy for assert
Handling make term without local echo.

[miri64]

I think the correct way to do this pexpect style would be

Suggested change

	child.expect_exact("the test should not match this")
	res child.expect([pexpect.TIMEOUT, "the test should not match this"])
	if res == 0:
	raise RuntimeError("There should have been a timeout on the match,"
	" and not match on stdin")

See e.g. this of pexpect's own examples

[cladmi]

It is just a throwaway commit anyway but I take the suggestion for other uses.
I think it would still require expect_exact here to have the same behavior.

[cladmi]

I implemented the test with expect_exact([pexpect.TIMEOUT, msg]) for #10949 in commit cladmi@f386f39

[cladmi]

Now that my computer finished testing samr21-xpro I updated the first commit and force-pushed to do this.

[cladmi]

This did not introduce regression in our testsuite according to running ./dist/tools/compile_and_test_for_board/compile_and_test_for_board.py for native and samr21-xpro.

Unrelated: I somehow noticed that pexpect.EOF exception should not be handled as test failure but more as test setup failure so as an error. It could return a different return value to be handled differently.

[cladmi]

The codacy error can be ignored as it is the goal to have an assert here and also, it is in a throwaway commit anyway.

[MrKevinWeiss]

Test results on native

main(): This is RIOT! (Version: 2019.04-devel-120-g2558e-tstxxx/10952)
Hello World!
You are running RIOT on a(n) native board.
This board features a(n) native MCU.
the test should not match this

Test results on nucleo-f103rb

2019-02-06 13:59:43,756 - INFO # �main(): This is RIOT! (Version: 2019.04-devel-120-g2558e-tstxxx/10952)
2019-02-06 13:59:43,758 - INFO # Hello World!
the test should not match this
2019-02-06 13:59:43,762 - INFO # You are running RIOT on a(n) nucleo-f103rb board.
2019-02-06 13:59:43,765 - INFO # This board features a(n) stm32f1 MCU.

I suppose seeing the message on native is expected?

[jcarrano]

I think that the test should not be removed. It is an important sanity check for the test runner.

[miri64]

I think that the test should not be removed. It is an important sanity check for the test runner.

I think so as well. Also, it finally starts introducing test-scripts for the examples, which I dearly miss ;-).

[cladmi]

@MrKevinWeiss We see the message on both boards, it is displayed before on nucleo-f103rb. And yes it is expected as all messages sent are saved to the logfile.

A test for this is important, but I would not put it in examples/hello-world.
Here it is not really testing hello-world just using one of its property to test something else.

I found about it while testing the riotnode wrapping #10949
(Currently is only a rewrite as a class on the pexpect initialization).
And have a dedicated library only test using a fake node over there:

cladmi@f386f39

Would that be enough or do you prefer to also have a board test for this too ?

One issue I see for tests with a real board is that it may require multiple firmwares for testing everything. But it could make sense to have a few directories in test/ to handle these integration tests too.

With all this, should I add dedicated test to this PR instead of the throwaway commit ?

[cladmi]

I just tested with picocom and the test fails as picocom does a local echo itself:

RIOT_TERMINAL=picocom BOARD=samr21-xpro make --no-print-directory -C examples/hello-world test
picocom --nolock --imap lfcrlf --echo --baud "115200" "/dev/ttyACM0"
picocom v2.2

port is        : /dev/ttyACM0
flowcontrol    : none
baudrate is    : 115200
parity is      : none
databits are   : 8
stopbits are   : 1
escape is      : C-a
local echo is  : yes
noinit is      : no
noreset is     : no
nolock is      : yes
send_cmd is    : sz -vv
receive_cmd is : rz -vv -E
imap is        : lfcrlf,
omap is        : 
emap is        : crcrlf,delbs,

Type [C-a] [C-h] to see available commands

Terminal ready
main(): This is RIOT! (Version: 2019.04-devel-120-g2558e-pr/bmain(): This is RIOT! (Version: 2019.04-devel-120-g2558e-pr/bug/testrunner/matching_local_echo)
Hello World!
the test should not match this
You are running RIOT on a(n) samr21-xpro board.
This board features a(n) samd21 MCU.
the test should not match this

Traceback (most recent call last):
  File "/home/harter/work/git/RIOT/examples/hello-world/tests/01-run.py", line 20, in <module>
    sys.exit(run(testfunc))
  File "/home/harter/work/git/RIOT/dist/pythonlibs/testrunner/__init__.py", line 57, in run
    testfunc(child)
  File "/home/harter/work/git/RIOT/examples/hello-world/tests/01-run.py", line 16, in testfunc
    assert res == 0, "There should have been a timeout and not match stdin"
AssertionError: There should have been a timeout and not match stdin
/home/harter/work/git/RIOT/examples/hello-world/../../Makefile.include:568: recipe for target 'test' failed
make: *** [test] Error 1

So having a dedicated test could be good.

[MrKevinWeiss]

One issue I see for tests with a real board is that it may require multiple firmwares for testing everything. But it could make sense to have a few directories in test/ to handle these integration tests too.

I think a test should be in the test/ folder. What do you mean by multiple firmwares? I agree that there would need to be multiple environments (RIOT_TERMINAL=) per test firmware.
Can that be written into the 01-run.py somehow or should it the different terms be tested on a higher level (eg. calling compile_and_test_for_board.py with RIOT_TERMINAL=)?

[cladmi]

One issue I see for tests with a real board is that it may require multiple firmwares for testing everything. But it could make sense to have a few directories in test/ to handle these integration tests too.

I think a test should be in the test/ folder. What do you mean by multiple firmwares? I agree that there would need to be multiple environments (RIOT_TERMINAL=) per test firmware.
Can that be written into the 01-run.py somehow or should it the different terms be tested on a higher level (eg. calling compile_and_test_for_board.py with RIOT_TERMINAL=)?

For multiple firmwares I was thinking about testing both a non echo case, a shell, a case where the nodes starts and flood and everything that could be needed for testing. But this would be more high level tests than the issue here.

I will write a simple one at least for this.

Running with different terminals can come in a second step.
It would be more a "Run it with your board and setup and see how it works and if it can be used for testing".

[MrKevinWeiss]

Ahh, got it! Thanks!

[cladmi]

As there is issue currently with make term, I will split this pull request in two. I will keep the fix here as having echo=False is already better and move the test to another pull request until the main issue is fixed.

[cladmi]

The test has been split out to #11094 until the main issue is fixed. It includes this pull request fix.
It can be tested from that pull request with an include HACK for picocom to make it work on murdock.

[jcarrano]

If nobody has anything more to say I'll merge this.

[cladmi]

I can still re-add the test on local echo from #11094 now that murdock does not fail because of it.