nightly: CY8CPROTO_062_4343W target failed at sleep/deep sleep test

[maciejbocianski]

Description of defect

Sleep test are failing on CY8CPROTO_062_4343W.
It looks that it fail to enter deep sleep due to uart.
I thought it was already fixed by introducing uart flush wait time ?

mbed-os/TESTS/mbed_hal/sleep/sleep_test_utils.h

Lines 32 to 45 in bac5ffe

	/* To prevent a loss of Greentea data, the serial buffers have to be flushed
	* before the UART peripheral shutdown. The UART shutdown happens when the
	* device is entering the deepsleep mode or performing a reset.
	*
	* With the current API, it is not possible to check if the hardware buffers
	* are empty. However, it is possible to determine the time required for the
	* buffers to flush.
	*
	* Assuming the biggest Tx FIFO of 128 bytes (as for CY8CPROTO_062_4343W)
	* and a default UART config (9600, 8N1), flushing the Tx FIFO wold take:
	* (1 start_bit + 8 data_bits + 1 stop_bit) * 128 * 1000 / 9600 = 133.3 ms.
	* To be on the safe side, set the wait time to 150 ms.
	*/
	#define SERIAL_FLUSH_TIME_MS 150

@dustin-crossman
Does the issue described here (#11792 (comment)) was already fixed?

Target(s) affected by this defect ?

CY8CPROTO_062_4343W

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

all

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

latest master
69a7d67

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

mbed-cli 1.10.2
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.10
mbed-os-tools 0.0.9

How is this defect reproduced ?

mbed test -t GCC_ARM -m CY8CPROTO_062_4343W -n tests-mbed_hal-sleep -v

[1581672999.57][CONN][RXD] >>> Running case #1: 'sleep - source of wake-up - us ticker'...
[1581672999.61][CONN][INF] found KV pair in stream: {{__testcase_start;sleep - source of wake-up - us ticker}}, queued...
[1581673000.11][CONN][INF] found KV pair in stream: {{__testcase_finish;sleep - source of wake-up - us ticker;1;0}}, queued...
[1581673000.17][CONN][RXD] >>> 'sleep - source of wake-up - us ticker': 1 passed, 0 failed
[1581673000.17][CONN][RXD]
[1581673000.25][CONN][RXD] >>> Running case #2: 'deep-sleep - source of wake-up - lp ticker'...
[1581673000.31][CONN][INF] found KV pair in stream: {{__testcase_start;deep-sleep - source of wake-up - lp ticker}}, queued...
mbedgt: :151::FAIL: Delta ticks: 331, Ticker width: 32, Expected wake up tick: 72118, Actual wake up tick: 71464, delay ticks: 655, wake up after ticks: 1
[1581673000.88][CONN][RXD] :151::FAIL: Delta ticks: 331, Ticker width: 32, Expected wake up tick: 72118, Actual wake up tick: 71464, delay ticks: 655, wake up after ticks: 1
mbedgt: :151::FAIL: Delta ticks: 331, Ticker width: 32, Expected wake up tick: 73388, Actual wake up tick: 72078, delay ticks: 1310, wake up after ticks: 0
[1581673001.04][CONN][RXD] :151::FAIL: Delta ticks: 331, Ticker width: 32, Expected wake up tick: 73388, Actual wake up tick: 72078, delay ticks: 1310, wake up after ticks: 0
mbedgt: :151::FAIL: Delta ticks: 331, Ticker width: 32, Expected wake up tick: 79066, Actual wake up tick: 77100, delay ticks: 1966, wake up after ticks: 0
[1581673001.18][CONN][RXD] :151::FAIL: Delta ticks: 331, Ticker width: 32, Expected wake up tick: 79066, Actual wake up tick: 77100, delay ticks: 1966, wake up after ticks: 0
mbedgt: :151::FAIL: Delta ticks: 331, Ticker width: 32, Expected wake up tick: 84743, Actual wake up tick: 82122, delay ticks: 2621, wake up after ticks: 0
[1581673001.34][CONN][RXD] :151::FAIL: Delta ticks: 331, Ticker width: 32, Expected wake up tick: 84743, Actual wake up tick: 82122, delay ticks: 2621, wake up after ticks: 0
mbedgt: :151::FAIL: Delta ticks: 331, Ticker width: 32, Expected wake up tick: 90420, Actual wake up tick: 87145, delay ticks: 3276, wake up after ticks: 1
[1581673001.48][CONN][RXD] :151::FAIL: Delta ticks: 331, Ticker width: 32, Expected wake up tick: 90420, Actual wake up tick: 87145, delay ticks: 3276, wake up after ticks: 1
mbedgt: :151::FAIL: Delta ticks: 331, Ticker width: 32, Expected wake up tick: 96099, Actual wake up tick: 92168, delay ticks: 3932, wake up after ticks: 1
[1581673001.63][CONN][RXD] :151::FAIL: Delta ticks: 331, Ticker width: 32, Expected wake up tick: 96099, Actual wake up tick: 92168, delay ticks: 3932, wake up after ticks: 1
mbedgt: :151::FAIL: Delta ticks: 331, Ticker width: 32, Expected wake up tick: 101778, Actual wake up tick: 97192, delay ticks: 4587, wake up after ticks: 1
[1581673001.79][CONN][RXD] :151::FAIL: Delta ticks: 331, Ticker width: 32, Expected wake up tick: 101778, Actual wake up tick: 97192, delay ticks: 4587, wake up after ticks: 1
mbedgt: :151::FAIL: Delta ticks: 331, Ticker width: 32, Expected wake up tick: 107490, Actual wake up tick: 102249, delay ticks: 5242, wake up after ticks: 1
[1581673001.95][CONN][RXD] :151::FAIL: Delta ticks: 331, Ticker width: 32, Expected wake up tick: 107490, Actual wake up tick: 102249, delay ticks: 5242, wake up after ticks: 1
mbedgt: :151::FAIL: Delta ticks: 331, Ticker width: 32, Expected wake up tick: 113237, Actual wake up tick: 107339, delay ticks: 5898, wake up after ticks: 0
[1581673002.12][CONN][RXD] :151::FAIL: Delta ticks: 331, Ticker width: 32, Expected wake up tick: 113237, Actual wake up tick: 107339, delay ticks: 5898, wake up after ticks: 0
[1581673002.17][CONN][INF] found KV pair in stream: {{__testcase_finish;deep-sleep - source of wake-up - lp ticker;0;9}}, queued...
[1581673002.28][CONN][RXD] >>> 'deep-sleep - source of wake-up - lp ticker': 0 passed, 9 failed with reason 'Test Cases Failed'
[1581673002.28][CONN][RXD]
[1581673002.36][CONN][RXD] >>> Running case #3: 'deep-sleep - high-speed clocks are turned off'...
[1581673002.44][CONN][INF] found KV pair in stream: {{__testcase_start;deep-sleep - high-speed clocks are turned off}}, queued...
mbedgt: :202::FAIL: Delta ticks: 331, Ticker width: 32, Expected wake up tick: 141588, Actual wake up tick: 140933
[1581673002.96][CONN][RXD] :202::FAIL: Delta ticks: 331, Ticker width: 32, Expected wake up tick: 141588, Actual wake up tick: 140933
[1581673003.02][CONN][INF] found KV pair in stream: {{__testcase_finish;deep-sleep - high-speed clocks are turned off;0;1}}, queued...
[1581673003.14][CONN][RXD] >>> 'deep-sleep - high-speed clocks are turned off': 0 passed, 1 failed with reason 'Test Cases Failed'
[1581673003.14][CONN][RXD]
[1581673003.20][CONN][RXD] >>> Test cases: 1 passed, 2 failed with reason 'Test Cases Failed'
[1581673003.22][CONN][RXD] >>> TESTS FAILED!
[1581673003.24][CONN][INF] found KV pair in stream: {{__testcase_summary;1;2}}, queued...
[1581673003.28][CONN][INF] found KV pair in stream: {{end;failure}}, queued...
[1581673003.28][CONN][INF] found KV pair in stream: {{__exit;0}}, queued...
[1581673003.29][HTST][INF] __exit(0)
[1581673003.29][HTST][INF] __notify_complete(False)
[1581673003.29][HTST][INF] __exit_event_queue received
[1581673003.29][HTST][INF] test suite run finished after 4.08 sec...
[1581673003.30][CONN][INF] received special event '__host_test_finished' value='True', finishing
[1581673003.33][HTST][INF] CONN exited with code: 0
[1581673003.33][HTST][INF] Some events in queue
[1581673003.33][HTST][INF] stopped consuming events
[1581673003.33][HTST][INF] host test result() call skipped, received: False
[1581673003.33][HTST][INF] calling blocking teardown()
[1581673003.33][HTST][INF] teardown() finished
[1581673003.33][HTST][INF] {{result;failure}}
mbedgt: retry mbedhtrun 1/1
mbedgt: ['mbedhtrun', '-m', u'CY8CPROTO_062_4343W', '-p', u'COM103:9600', '-f', u'"BUILD/tests/CY8CPROTO_062_4343W/GCC_ARM/TESTS/mbed_hal/sleep/sleep.hex"', '-e', u'"TESTS\\host_tests"', '-d', 'D:', '-c', 'default', '-t', u'190113018b0c1a06028b0c1a00000000000000002e127069', '-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 'FAIL'
mbedgt: test on hardware with target id: 190113018b0c1a06028b0c1a00000000000000002e127069
mbedgt: test suite 'tests-mbed_hal-sleep' ............................................................ FAIL in 20.12 sec
        test case: 'deep-sleep - high-speed clocks are turned off' ................................... FAIL in 0.58 sec
        test case: 'deep-sleep - source of wake-up - lp ticker' ...................................... FAIL in 1.86 sec
        test case: 'sleep - source of wake-up - us ticker' ........................................... OK in 0.50 sec
mbedgt: test case summary: 1 pass, 2 failures
mbedgt: all tests finished!
mbedgt: shuffle seed: 0.3200347114
mbedgt: test suite report:
| target                      | platform_name       | test suite           | result | elapsed_time (sec) | copy_method |
|-----------------------------|---------------------|----------------------|--------|--------------------|-------------|
| CY8CPROTO_062_4343W-GCC_ARM | CY8CPROTO_062_4343W | tests-mbed_hal-sleep | FAIL   | 20.12              | default     |
mbedgt: test suite results: 1 FAIL
mbedgt: test case report:
| target                      | platform_name       | test suite           | test case                                     | passed | failed | result | elapsed_time (sec) |
|-----------------------------|---------------------|----------------------|-----------------------------------------------|--------|--------|--------|--------------------|
| CY8CPROTO_062_4343W-GCC_ARM | CY8CPROTO_062_4343W | tests-mbed_hal-sleep | deep-sleep - high-speed clocks are turned off | 0      | 1      | FAIL   | 0.58               |
| CY8CPROTO_062_4343W-GCC_ARM | CY8CPROTO_062_4343W | tests-mbed_hal-sleep | deep-sleep - source of wake-up - lp ticker    | 0      | 9      | FAIL   | 1.86               |
| CY8CPROTO_062_4343W-GCC_ARM | CY8CPROTO_062_4343W | tests-mbed_hal-sleep | sleep - source of wake-up - us ticker         | 1      | 0      | OK     | 0.5                |

[0xc0170]

cc @ARMmbed/team-cypress

[ciarmcom]

Internal Jira reference: https://jira.arm.com/browse/MBOTRIAGE-2548

[dustin-crossman]

Increasing the sleep time fixed an issue where some tests were failing when Greentea was run with a 9600 baudrate. See the issue here: #11909
The sleep failures are similarly caused by the UART preventing the board from entering sleep but it is a separate and distinct issue not resolved by increasing the wait time.
In the meantime we are evaluating a fix for this particular failure and will submit it in a future PR.

[dustin-crossman]

After investigating this I've found a couple different causes for the sleep test failures. The specific case that is failing is the deepsleep_lpticker_test():

Our low-level (psoc6pdl) UART driver prevents the system from entering deep sleep if there is any data in the UART RX or TX FIFOs (initially we assumed this was the hardware itself preventing deep sleep but that does not appear so). During the deepsleep test, just before entering deep sleep, it turns out there is data on both the RX and TX FIFOs.

The data in the TX FIFO comes from the GT messages being sent at the end of the for loop in deepsleep_ticker_test(). This can be fixed by simply moving the busy_wait_ms(SERIAL_FLUSH_TIME_MS) call into the for loop instead of above it.

The data in the RX FIFO was harder to track down. The data consists of a single byte in the FIFO: a '\n'. This '\n' was sent by GT as part of the __sync kv packet during test initialization. It was not being read off the FIFO because of a bug in the DUT side greentea client: specifically HandleKV() in greentea_test_env.cpp. HandleKV() reads up to the final "}}" and returns success but does not read the final '\n'. This does not cause an error otherwise because the greentea-client code ignores whitespace coming in across the UART. Note: According to https://github.com/ARMmbed/mbed-os-tools/blob/master/src/mbed_os_tools/test/host_tests_conn_proxy/conn_primitive.py#L39 all kv pairs are sent with a terminating '\n'. The fix for this (I'll put in a PR soon) is to add a line that reads that final '\n' in the HandleKV code.

Once issue 1 was cleared up I ran into another issue: The board would successfully enter deep sleep but consistently took 100ms too long to wake up. The root cause here is a delay in our SDHC deepsleep wake up code. The delay was added to allow time for clock stabilization. A proper resolution to this issue is being discussed but simply removing the delay fixes the deepsleep issue.

So ultimately 3 things need to happen to close this issue:

1. The GT client needs fixed. I'll submit a PR soon for this.
2. The sleep test itself needs fixing. I'll submit a PR soon for this as well.
3. Our SDHC deepsleep wake up needs fixing. This will come in a future PR (probably as part of an entire asset version update since this comes from psoc6pdl code).

[0xc0170]

@dustin-crossman Nice findings! Will wait for the fixes

[maciejbocianski]

• @jamesbeyond

[ifyall]

Cypress is waiting for the fix of #3 before applying all three fixes at the same time. Fixing issues #1 and #2 without #3 would cause more test failures than we see now.
Ian

[0xc0170]

Cypress is waiting for the fix of #3 before applying all three fixes at the same time. Fixing issues #1 and #2 without #3 would cause more test failures than we see now.

The numbers point to old PRs (first three to this repo) , should they reference different numbers?

[dustin-crossman]

@0xc0170 That's just an autolink issue. #s 1, 2, and 3 refer to the issues from my comment above: #12434 (comment)

Also to update: Issue 3 is being worked on right now.

[dustin-crossman]

Just to update, this has been fixed by:
#13210
and
#13247

[jamesbeyond]

This is fixed