mbedmicro-rtos-mbed-basic test failed on master

[toyowata]

Description of defect

rtos-tests-tests-mbedmicro-rtos-mbed-basic test case of the master branch failed on K64F target. Same test case on mbed-os-6.2.0 does not fail.

mbedgt: selecting test case observer...
	calling mbedhtrun: mbedhtrun -m K64F -p /dev/tty.usbmodem14202:9600 -f "BUILD/tests/K64F/GCC_ARM/rtos/tests/TESTS/mbedmicro-rtos-mbed/basic/basic.bin" -d /Volumes/DAPLINK -c default -t 0240000034544e45003800038e41003d8321000097969900 -r default -C 4 --sync 5 -P 60
mbedgt: mbed-host-test-runner: started
[1595901856.71][HTST][INF] host test executor ver. 0.0.15
[1595901856.71][HTST][INF] copy image onto target...
[1595901856.72][COPY][INF] Waiting up to 60 sec for '0240000034544e45003800038e41003d8321000097969900' mount point (current is '/Volumes/DAPLINK')...
[1595901873.07][HTST][INF] starting host test process...
[1595901873.08][CONN][INF] starting connection process...
[1595901873.08][CONN][INF] notify event queue about extra 60 sec timeout for serial port pooling
[1595901873.08][CONN][INF] initializing serial port listener...
[1595901873.08][PLGN][INF] Waiting up to 60 sec for '0240000034544e45003800038e41003d8321000097969900' serial port (current is '/dev/tty.usbmodem14202')...
[1595901873.09][HTST][INF] setting timeout to: 60 sec
[1595901874.03][SERI][INF] serial(port=/dev/tty.usbmodem14202, baudrate=9600, read_timeout=0.01, write_timeout=5)
[1595901874.04][SERI][INF] reset device using 'default' plugin...
[1595901874.44][SERI][INF] waiting 1.00 sec after reset
[1595901875.44][SERI][INF] wait for it...
[1595901875.44][SERI][TXD] mbedmbedmbedmbedmbedmbedmbedmbedmbedmbed
[1595901875.44][CONN][INF] sending up to 5 __sync packets (specified with --sync=5)
[1595901875.44][CONN][INF] sending preamble '3d81c830-02b1-432a-a94b-14f83b81519b'
[1595901875.44][SERI][TXD] {{__sync;3d81c830-02b1-432a-a94b-14f83b81519b}}
[1595901875.58][CONN][RXD] mbedmbedmbedmbedmbedmbedmbedmbed
[1595901875.62][CONN][INF] found SYNC in stream: {{__sync;3d81c830-02b1-432a-a94b-14f83b81519b}} it is #0 sent, queued...
[1595901875.62][HTST][INF] sync KV found, uuid=3d81c830-02b1-432a-a94b-14f83b81519b, timestamp=1595901875.621755
[1595901875.65][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
[1595901875.65][HTST][INF] DUT greentea-client version: 1.3.0
[1595901875.67][CONN][INF] found KV pair in stream: {{__timeout;40}}, queued...
[1595901875.67][HTST][INF] setting timeout to: 40 sec
[1595901875.71][CONN][INF] found KV pair in stream: {{__host_test_name;timing_drift_auto}}, queued...
[1595901875.72][HTST][ERR] host test not detected: timing_drift_auto
[1595901875.72][HTST][INF] __exit_event_queue received
[1595901875.72][HTST][INF] test suite run finished after 0.05 sec...
[1595901875.73][CONN][INF] received special event '__host_test_finished' value='True', finishing
[1595901875.78][HTST][INF] CONN exited with code: 0
[1595901875.78][HTST][INF] No events in queue
[1595901875.78][HTST][INF] stopped consuming events
[1595901875.78][HTST][INF] host test result() call skipped, received: error
[1595901875.78][HTST][WRN] missing __exit event from DUT
[1595901875.78][HTST][INF] calling blocking teardown()
[1595901875.78][HTST][INF] teardown() finished
[1595901875.78][HTST][INF] {{result;error}}
mbedgt: retry mbedhtrun 1/1
mbedgt: ['mbedhtrun', '-m', 'K64F', '-p', '/dev/tty.usbmodem14202:9600', '-f', '"BUILD/tests/K64F/GCC_ARM/rtos/tests/TESTS/mbedmicro-rtos-mbed/basic/basic.bin"', '-d', '/Volumes/DAPLINK', '-c', 'default', '-t', '0240000034544e45003800038e41003d8321000097969900', '-r', 'default', '-C', '4', '--sync', '5', '-P', '60'] failed after 1 count
mbedgt: checking for GCOV data...
mbedgt: mbed-host-test-runner: stopped and returned 'ERROR'
mbedgt: test case summary event not found
	no test case report present, assuming test suite to be a single test case!
	test suite: rtos-tests-tests-mbedmicro-rtos-mbed-basic
	test case: rtos-tests-tests-mbedmicro-rtos-mbed-basic
mbedgt: test on hardware with target id: 0240000034544e45003800038e41003d8321000097969900
mbedgt: test suite 'rtos-tests-tests-mbedmicro-rtos-mbed-basic' ...................................... ERROR in 19.54 sec
	test case: 'rtos-tests-tests-mbedmicro-rtos-mbed-basic' ...................................... ERROR in 19.54 sec
mbedgt: test case summary: 0 passes, 1 failure

Target(s) affected by this defect ?

• FRDM-K64F (and possibly others)

Toolchain(s) (name and version) displaying this defect ?

arm-none-eabi-gcc (GNU Arm Embedded Toolchain 9-2020-q2-update) 9.3.1 20200408 (release)

What version of Mbed-os are you using (tag or sha) ?

master (#6bd52719f62c)

What version(s) of tools are you using. List all that apply (E.g. mbed-cli)

Package            Version
------------------ -------------
appdirs            1.4.4
asn1ate            0.6.0
attrs              19.3.0
beautifulsoup4     4.6.3
cbor               1.0.0
certifi            2020.4.5.2
cffi               1.14.0
chardet            3.0.4
Click              7.0
cmsis-pack-manager 0.2.10
colorama           0.3.9
cryptography       2.9.2
ecdsa              0.15
esptool            2.8
fasteners          0.15
future             0.16.0
hidapi             0.7.99.post21
icetea             1.2.4
idna               2.7
importlib-metadata 1.6.1
intelhex           2.2.1
intervaltree       3.0.2
Jinja2             2.10.3
jsonmerge          1.7.0
jsonschema         2.6.0
junit-xml          1.8
lockfile           0.12.2
lxml               4.5.1
manifest-tool      1.5.2
MarkupSafe         1.1.1
mbed-cli           1.10.4
mbed-cloud-sdk     2.0.8
mbed-flasher       0.10.1
mbed-greentea      1.7.4
mbed-host-tests    1.5.10
mbed-ls            1.7.12
mbed-os-tools      0.0.15
milksnake          0.1.5
monotonic          1.5
more-itertools     8.4.0
packaging          20.4
pip                20.1.1
pluggy             0.13.1
prettytable        0.7.2
protobuf           3.5.2.post1
psutil             5.6.6
py                 1.8.2
pyaes              1.6.1
pyasn1             0.2.3
pyasn1-modules     0.2.8
pycparser          2.20
pycryptodome       3.9.8
pyelftools         0.25
pylink-square      0.6.1
pyocd              0.26.1
pyparsing          2.4.7
pyserial           3.4
pytest             5.4.3
python-dateutil    2.8.1
python-dotenv      0.13.0
pyusb              1.0.2
PyYAML             4.2b1
requests           2.20.1
semver             2.10.1
setuptools         28.8.0
six                1.12.0
sortedcontainers   2.2.2
urllib3            1.24.2
wcwidth            0.2.4
ws4py              0.5.1
yattag             1.13.2
zipp               3.1.0

How is this defect reproduced ?

$ git clone https://github.com/ARMmbed/mbed-os
$ cd mbed-os
$ mbed test -m k64f -t gcc_arm -n "RTOS-TESTS-*" --compile
$ mbed test -m k64f -t gcc_arm -n "RTOS-TESTS-*" --run -v

Full log output

• master branch (#6bd52719f62c390d67af6a5501773b07f19bb837) - Failed
  k64f_rtos-test_master.txt
• mbed-os-6.2.0 (#a2ada74770f043aff3e61e29d164a8e78274fcd4) - Passed
  k64f_rtos-test_os62.txt

Assumptions

It is probably related to this change?
cc @ashok-rao

[ciarmcom]

@toyowata thank you for raising this issue.Please take a look at the following comments:

We cannot automatically identify a release based on the version of Mbed OS that you have provided.
Please provide either a single valid sha of the form #abcde12 or #3b8265d70af32261311a06e423ca33434d8d80de
or a single valid release tag of the form mbed-os-x.y.z .
E.g. '(#6bd52719f62c)' has not been matched as a valid tag or sha.
NOTE: If there are fields which are not applicable then please just add 'n/a' or 'None'.This indicates to us that at least all the fields have been considered.
Please update the issue header with the missing information, the issue will not be mirroredto our internal defect tracking system or investigated until this has been fully resolved.

[0xc0170]

It is probably related to this change?

Oh, moving files would affect a test in the runtime? 😨 Lets see what we can find.

[jainvikas8]

@toyowata Can you please copy mbed-os/TESTS/host_tests/timing_drift_auto.py to mbed-os/rtos/tests/TESTS/host_tests/timing_drift_auto.py to see if this works on master?

[0xc0170]

@toyowata Can you copy mbed-os/TESTS/host_tests/timing_drift_auto.py to mbed-os/rtos/tests/TESTS/host_tests/timing_drift_auto.py to see if this works on 6.2.0?

That could be it, as the test now uses the default host script, not the one written explicitly for it?

[toyowata]

@jainvikas8 @0xc0170 Thanks. Now it works.

18:43 ~/dev/test/master $ mbed test -m k64f -t gcc_arm -n rtos-tests-tests-mbedmicro-rtos-mbed-basic --run -v
[mbed] Working path "/Users/toywat01/dev/test/master" (program)
[mbed] Exec "mbedgt --test-spec ./BUILD/tests/K64F/GCC_ARM/test_spec.json -n rtos-tests-tests-mbedmicro-rtos-mbed-basic -V" in "/Users/toywat01/dev/test/master"
mbedgt: greentea test automation tool ver. 1.7.4
mbedgt: test specification file './BUILD/tests/K64F/GCC_ARM/test_spec.json' (specified with --test-spec option)
mbedgt: using './BUILD/tests/K64F/GCC_ARM/test_spec.json' from current directory!
mbedgt: detecting connected mbed-enabled devices...
mbedgt: detected 1 device
	| platform_name | platform_name_unique | serial_port            | mount_point      | target_id                                        |
	|---------------|----------------------|------------------------|------------------|--------------------------------------------------|
	| K64F          | K64F[0]              | /dev/tty.usbmodem14202 | /Volumes/DAPLINK | 0240000034544e45003800038e41003d8321000097969900 |
mbedgt: processing target 'K64F' toolchain 'GCC_ARM' compatible platforms... (note: switch set to --parallel 1)
	| platform_name | platform_name_unique | serial_port                 | mount_point      | target_id                                        |
	|---------------|----------------------|-----------------------------|------------------|--------------------------------------------------|
	| K64F          | K64F[0]              | /dev/tty.usbmodem14202:9600 | /Volumes/DAPLINK | 0240000034544e45003800038e41003d8321000097969900 |
mbedgt: test case filter (specified with -n option)
	rtos-tests-tests-mbedmicro-rtos-mbed-basic
	test filtered in 'rtos-tests-tests-mbedmicro-rtos-mbed-basic'
mbedgt: running 1 test for platform 'K64F' and toolchain 'GCC_ARM'
	use 1 instance of execution threads for testing
mbedgt: checking for 'host_tests' directory above image directory structure
	found 'host_tests' directory in: 'rtos/tests/TESTS/host_tests'
mbedgt: selecting test case observer...
	calling mbedhtrun: mbedhtrun -m K64F -p /dev/tty.usbmodem14202:9600 -f "BUILD/tests/K64F/GCC_ARM/rtos/tests/TESTS/mbedmicro-rtos-mbed/basic/basic.bin" -e "rtos/tests/TESTS/host_tests" -d /Volumes/DAPLINK -c default -t 0240000034544e45003800038e41003d8321000097969900 -r default -C 4 --sync 5 -P 60
mbedgt: mbed-host-test-runner: started
[1595929473.19][HTST][INF] host test executor ver. 0.0.15
[1595929473.19][HTST][INF] copy image onto target...
[1595929473.19][COPY][INF] Waiting up to 60 sec for '0240000034544e45003800038e41003d8321000097969900' mount point (current is '/Volumes/DAPLINK')...
[1595929489.00][HTST][INF] starting host test process...
[1595929489.00][CONN][INF] starting connection process...
[1595929489.01][CONN][INF] notify event queue about extra 60 sec timeout for serial port pooling
[1595929489.01][CONN][INF] initializing serial port listener...
[1595929489.01][PLGN][INF] Waiting up to 60 sec for '0240000034544e45003800038e41003d8321000097969900' serial port (current is '/dev/tty.usbmodem14202')...
[1595929489.01][HTST][INF] setting timeout to: 60 sec
[1595929489.88][SERI][INF] serial(port=/dev/tty.usbmodem14202, baudrate=9600, read_timeout=0.01, write_timeout=5)
[1595929489.89][SERI][INF] reset device using 'default' plugin...
[1595929490.29][SERI][INF] waiting 1.00 sec after reset
[1595929491.29][SERI][INF] wait for it...
[1595929491.29][SERI][TXD] mbedmbedmbedmbedmbedmbedmbedmbedmbedmbed
[1595929491.29][CONN][INF] sending up to 5 __sync packets (specified with --sync=5)
[1595929491.29][CONN][INF] sending preamble '6e90d5ca-6ca3-41ce-af0f-1cd240d885bc'
[1595929491.29][SERI][TXD] {{__sync;6e90d5ca-6ca3-41ce-af0f-1cd240d885bc}}
[1595929491.43][CONN][RXD] mbedmbedmbedmbedmbedmbedmbedmbed
[1595929491.47][CONN][INF] found SYNC in stream: {{__sync;6e90d5ca-6ca3-41ce-af0f-1cd240d885bc}} it is #0 sent, queued...
[1595929491.47][HTST][INF] sync KV found, uuid=6e90d5ca-6ca3-41ce-af0f-1cd240d885bc, timestamp=1595929491.472826
[1595929491.50][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
[1595929491.50][HTST][INF] DUT greentea-client version: 1.3.0
[1595929491.52][CONN][INF] found KV pair in stream: {{__timeout;40}}, queued...
[1595929491.52][HTST][INF] setting timeout to: 40 sec
[1595929491.56][CONN][INF] found KV pair in stream: {{__host_test_name;timing_drift_auto}}, queued...
[1595929491.56][HTST][INF] host test class: '<class 'timing_drift_auto.TimingDriftSync'>'
[1595929491.57][HTST][INF] host test setup() call...
[1595929491.57][HTST][INF] CALLBACKs updated
[1595929491.57][HTST][INF] host test detected: timing_drift_auto
[1595929491.59][CONN][INF] found KV pair in stream: {{__testcase_count;1}}, queued...
[1595929491.61][CONN][RXD] >>> Running 1 test cases...
[1595929491.68][CONN][RXD]
[1595929491.68][CONN][INF] found KV pair in stream: {{__testcase_name;Test ThisThread::sleep_for accuracy}}, queued...
[1595929491.73][CONN][RXD] >>> Running case #1: 'Test ThisThread::sleep_for accuracy'...
[1595929491.80][CONN][INF] found KV pair in stream: {{__testcase_start;Test ThisThread::sleep_for accuracy}}, queued...
[1595929491.83][CONN][INF] found KV pair in stream: {{timing_drift_check_start;0}}, queued...
[1595929491.85][SERI][TXD] {{base_time;0}}
[1595929491.89][CONN][INF] found KV pair in stream: {{base_time;73000}}, queued...
[1595929501.44][HTST][INF] Device base time 73000
[1595929501.44][HTST][INF] sleeping for 9.546012878417969 to measure drift accurately
[1595929501.45][SERI][TXD] {{final_time;0}}
[1595929501.49][CONN][INF] found KV pair in stream: {{final_time;9676000}}, queued...
[1595929501.49][HTST][INF] Device final time 9676000
[1595929501.49][HTST][INF] Compute host events
[1595929501.49][HTST][INF] Transport delay 0: 0.05682516098022461
[1595929501.49][HTST][INF] Transport delay 1: 0.05318927764892578
[1595929501.49][HTST][INF] DUT base time : 73000.0
[1595929501.49][HTST][INF] DUT end time  : 9676000.0
[1595929501.49][HTST][INF] min_pass : 9.175090706348419 , max_pass : 10.025374567508697 for 5.0%%
[1595929501.49][HTST][INF] min_inconclusive : 9.070576989650727 , max_inconclusive : 10.140889728069306
[1595929501.49][HTST][INF] Time reported by device: 9.603
[1595929501.49][HTST][INF] Test passed !!!
[1595929501.50][SERI][TXD] {{pass;0}}
[1595929501.59][CONN][INF] found KV pair in stream: {{__testcase_finish;Test ThisThread::sleep_for accuracy;1;0}}, queued...
[1595929501.65][CONN][RXD] >>> 'Test ThisThread::sleep_for accuracy': 1 passed, 0 failed
[1595929501.66][CONN][RXD]
[1595929501.69][CONN][RXD] >>> Test cases: 1 passed, 0 failed
[1595929501.72][CONN][INF] found KV pair in stream: {{__testcase_summary;1;0}}, queued...
[1595929501.75][CONN][INF] found KV pair in stream: {{end;success}}, queued...
[1595929501.75][HTST][INF] __notify_complete(True)
[1595929501.75][HTST][INF] __exit_event_queue received
[1595929501.75][HTST][INF] test suite run finished after 10.23 sec...
[1595929501.76][CONN][INF] found KV pair in stream: {{__exit;0}}, queued...
[1595929501.76][CONN][INF] received special event '__host_test_finished' value='True', finishing
[1595929501.80][HTST][INF] CONN exited with code: 0
[1595929501.81][HTST][INF] Some events in queue
[1595929501.81][HTST][INF] stopped consuming events
[1595929501.81][HTST][INF] host test result() call skipped, received: True
[1595929501.81][HTST][WRN] missing __exit event from DUT
[1595929501.81][HTST][INF] calling blocking teardown()
[1595929501.81][HTST][INF] teardown() finished
[1595929501.81][HTST][INF] {{result;success}}
mbedgt: checking for GCOV data...
mbedgt: mbed-host-test-runner: stopped and returned 'OK'
mbedgt: test on hardware with target id: 0240000034544e45003800038e41003d8321000097969900
mbedgt: test suite 'rtos-tests-tests-mbedmicro-rtos-mbed-basic' ...................................... OK in 29.12 sec
	test case: 'Test ThisThread::sleep_for accuracy' ............................................. OK in 9.79 sec
mbedgt: test case summary: 1 pass, 0 failures
mbedgt: all tests finished!
mbedgt: shuffle seed: 0.2817304109
mbedgt: test suite report:
| target       | platform_name | test suite                                 | result | elapsed_time (sec) | copy_method |
|--------------|---------------|--------------------------------------------|--------|--------------------|-------------|
| K64F-GCC_ARM | K64F          | rtos-tests-tests-mbedmicro-rtos-mbed-basic | OK     | 29.12              | default     |
mbedgt: test suite results: 1 OK
mbedgt: test case report:
| target       | platform_name | test suite                                 | test case                           | passed | failed | result | elapsed_time (sec) |
|--------------|---------------|--------------------------------------------|-------------------------------------|--------|--------|--------|--------------------|
| K64F-GCC_ARM | K64F          | rtos-tests-tests-mbedmicro-rtos-mbed-basic | Test ThisThread::sleep_for accuracy | 1      | 0      | OK     | 9.79               |
mbedgt: test case results: 1 OK
mbedgt: completed in 30.20 sec

[jamesbeyond]

should be fixed now

[toyowata]

@jamesbeyond
I also confirmed that the rtos-tests-tests-mbedmicro-rtos-mbed-basic test case works fine on master (aa882d3). Thank you very much.

[0xc0170]

Fixed, I'll close this.