Closed
Description
Description
- Type: Bug
- Priority: Minor
Bug
Target
ARM_BEETLE_SOC
Toolchain:
ARM (maybe others)
Toolchain version:
5
meed-os sha:
Release candidate 5.5.1
Failure
The test will sometimes halt printing {{tick}} messages. The failure log looks like this:
[1498053971.96][HTST][INF] host test executor ver. 1.1.8
[1498053971.96][HTST][INF] copy image onto target...
[1498053971.96][COPY][INF] Waiting up to 60 sec for '500200001d17283f00000000000000000000000097969902' mount point (current is 'J:')...
1 file(s) copied.
[1498053980.07][HTST][INF] starting host test process...
[1498053980.40][CONN][INF] starting connection process...
[1498053980.40][CONN][INF] notify event queue about extra 60 sec timeout for serial port pooling
[1498053980.40][CONN][INF] initializing serial port listener...
[1498053980.40][PLGN][INF] Waiting up to 60 sec for '500200001d17283f00000000000000000000000097969902' serial port (current is 'COM8')...
[1498053980.41][HTST][INF] setting timeout to: 60 sec
[1498053981.20][SERI][INF] serial(port=COM8, baudrate=9600, read_timeout=0.01, write_timeout=5)
[1498053981.20][SERI][INF] reset device using 'default' plugin...
[1498053981.45][SERI][INF] waiting 1.00 sec after reset
[1498053982.45][SERI][INF] wait for it...
[1498053982.45][SERI][TXD] mbedmbedmbedmbedmbedmbedmbedmbedmbedmbed
[1498053982.45][CONN][INF] sending up to 2 __sync packets (specified with --sync=2)
[1498053982.45][CONN][INF] sending preamble 'ef3c7a85-c178-49d3-b71a-845f38fad58f'
[1498053982.45][SERI][TXD] {{__sync;ef3c7a85-c178-49d3-b71a-845f38fad58f}}
[1498053982.59][CONN][RXD] mbedmbedmbedmbedmbedmbedmbedmbed
[1498053982.64][CONN][INF] found SYNC in stream: {{__sync;ef3c7a85-c178-49d3-b71a-845f38fad58f}} it is #0 sent, queued...
[1498053982.65][HTST][INF] sync KV found, uuid=ef3c7a85-c178-49d3-b71a-845f38fad58f, timestamp=1498053982.644000
[1498053982.66][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
[1498053982.66][HTST][INF] DUT greentea-client version: 1.3.0
[1498053982.67][CONN][INF] found KV pair in stream: {{__timeout;45}}, queued...
[1498053982.68][HTST][INF] setting timeout to: 45 sec
[1498053982.71][CONN][INF] found KV pair in stream: {{__host_test_name;timing_drift_auto}}, queued...
[1498053982.72][HTST][INF] host test class: '<class 'timing_drift_auto.TimingDriftTest'>'
[1498053982.72][HTST][INF] host test setup() call...
[1498053982.72][HTST][INF] CALLBACKs updated
[1498053982.72][HTST][INF] host test detected: timing_drift_auto
[1498053982.74][CONN][INF] found KV pair in stream: {{__testcase_count;3}}, queued...
[1498053982.77][CONN][RXD] >>> Running 3 test cases...
[1498053982.81][CONN][INF] found KV pair in stream: {{__testcase_name;Timers: 1x ticker}}, queued...
[1498053982.87][CONN][INF] found KV pair in stream: {{__testcase_name;Timers: 2x tickers}}, queued...
[1498053982.91][CONN][RXD]
[1498053982.91][CONN][INF] found KV pair in stream: {{__testcase_name;Timers: 2x callbacks}}, queued...
[1498053982.95][CONN][RXD] >>> Running case #1: 'Timers: 1x ticker'...
[1498053982.99][CONN][INF] found KV pair in stream: {{__testcase_start;Timers: 1x ticker}}, queued...
[1498053984.02][CONN][INF] found KV pair in stream: {{tick;0}}, queued...
[1498053984.03][HTST][INF] tick! 1498053984.022000
[1498053985.02][CONN][INF] found KV pair in stream: {{tick;1}}, queued...
[1498053985.03][HTST][INF] tick! 1498053985.019000
[1498053986.02][CONN][INF] found KV pair in stream: {{tick;2}}, queued...
[1498053986.02][HTST][INF] tick! 1498053986.016000
[1498053987.02][CONN][INF] found KV pair in stream: {{tick;3}}, queued...
[1498053987.02][HTST][INF] tick! 1498053987.019000
[1498053988.02][CONN][INF] found KV pair in stream: {{tick;4}}, queued...
[1498053988.03][HTST][INF] tick! 1498053988.021000
[1498053989.02][CONN][INF] found KV pair in stream: {{tick;5}}, queued...
[1498053989.02][HTST][INF] tick! 1498053989.016000
[1498053990.02][CONN][INF] found KV pair in stream: {{tick;6}}, queued...
[1498053990.03][HTST][INF] tick! 1498053990.021000
[1498053991.02][CONN][INF] found KV pair in stream: {{tick;7}}, queued...
[1498053991.03][HTST][INF] tick! 1498053991.016000
[1498053992.02][CONN][INF] found KV pair in stream: {{tick;8}}, queued...
[1498053992.04][HTST][INF] tick! 1498053992.021000
[1498053993.02][CONN][INF] found KV pair in stream: {{tick;9}}, queued...
[1498053993.02][HTST][INF] tick! 1498053993.018000
[1498053994.02][CONN][INF] found KV pair in stream: {{tick;10}}, queued...
[1498053994.03][HTST][INF] tick! 1498053994.015000
[1498053994.06][CONN][INF] found KV pair in stream: {{__testcase_finish;Timers: 1x ticker;1;0}}, queued...
[1498053994.10][CONN][RXD] >>> 'Timers: 1x ticker': 1 passed, 0 failed
[1498053994.10][CONN][RXD]
[1498053994.15][CONN][RXD] >>> Running case #2: 'Timers: 2x tickers'...
[1498053994.19][CONN][INF] found KV pair in stream: {{__testcase_start;Timers: 2x tickers}}, queued...
[1498053995.21][CONN][INF] found KV pair in stream: {{tick;0}}, queued...
[1498053995.21][HTST][INF] tick! 1498053995.208000
[1498053996.21][CONN][INF] found KV pair in stream: {{tick;1}}, queued...
[1498053996.21][HTST][INF] tick! 1498053996.213000
[1498054027.69][HTST][INF] test suite run finished after 45.01 sec...
[1498054027.70][CONN][INF] received special even '__host_test_finished' value='True', finishing
[1498054027.73][HTST][INF] CONN exited with code: 0
[1498054027.73][HTST][INF] No events in queue
[1498054027.74][HTST][INF] stopped consuming events
[1498054027.74][HTST][INF] host test result(): True
[1498054027.74][HTST][WRN] missing __exit event from DUT
[1498054027.74][HTST][WRN] missing __exit_event_queue event from host test
[1498054027.74][HTST][INF] calling blocking teardown()
[1498054027.74][HTST][INF] teardown() finished
[1498054027.74][HTST][INF] {{result;success}}
Greentea sometimes won't report this as a failure, this is due to a bug in how the host test is written. PR #4599 should help with this.