Failing common_ticker tests

[aashishc1988]

Description

• Type: Bug
• Priority: Major

---

Bug

Target
KL25Z, K66F

Toolchain:
GCC_ARM
IAR
ARM

mbed-os sha1
ae40a09

Tests we are failing:
tests-mbed_hal-common_tickers : Microsecond ticker free interrupt test
Seems like a new test that was added with the commit

Steps to reproduce

mbed test -m K66F -t GCC_ARM -n tests-mbed_hal-common_tickers

log snippet

> 
00:04:38.639 [1533668636.24][root]Generating grammar tables from /usr/lib/python2.7/lib2to3/Grammar.txt
00:04:38.667 [1533668636.27][root]Generating grammar tables from /usr/lib/python2.7/lib2to3/PatternGrammar.txt
00:04:38.678 [1533668636.28][HTST][INF] host test executor ver. 1.4.0
00:04:38.678 [1533668636.28][HTST][INF] copy image onto target... SKIPPED!
00:04:38.680 [1533668636.28][HTST][INF] starting host test process...
00:04:38.682 [1533668636.28][CONN][INF] starting connection process...
00:04:38.682 [1533668636.28][CONN][INF] notify event queue about extra 60 sec timeout for serial port pooling
00:04:38.682 [1533668636.28][CONN][INF] initializing global resource mgr listener...
00:04:38.707 [1533668636.31][HTST][INF] setting timeout to: 60 sec
00:04:38.720 [1533668636.32][GLRM][INF] remote resources initialization: remote(host=goku.austin.arm.com, port=8000)
00:04:38.721 [1533668636.32][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:04:38.723 [1533668636.33][urllib3.connectionpool]http://goku.austin.arm.com:8000 "POST /login HTTP/1.1" 200 213
00:04:38.725 [1533668636.33][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:04:38.726 [1533668636.33][urllib3.connectionpool]http://goku.austin.arm.com:8000 "GET /socket.io/?token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJ1c2VybmFtZSI6InVzZXIiLCJncm91cCI6InVzZXIiLCJpYXQiOjE1MzM2Njg2MzYsImV4cCI6MTUzNDI3MzQzNn0.At8crVVoveFZkOzeCTMCgKh8-P6tPihNGGTqAk9Gjps&EIO=3&transport=polling&t=1533668636325-0 HTTP/1.1" 200 101
00:04:38.729 [1533668636.33][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:04:38.731 [1533668636.33][urllib3.connectionpool]http://goku.austin.arm.com:8000 "GET /this/resource HTTP/1.1" 200 3651
00:04:38.731 [1533668636.33][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:04:38.736 [1533668636.34][urllib3.connectionpool]http://goku.austin.arm.com:8000 "GET /resource HTTP/1.1" 200 53894
00:04:38.738 [1533668636.34][GLRM][INF] remote resources count: 39
00:04:38.746 [1533668636.35][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:04:38.747 [1533668636.35][urllib3.connectionpool]http://goku.austin.arm.com:8000 "GET /resource/0200000013894d440085101affff0003ffffffff97969900 HTTP/1.1" 200 1811
00:04:38.748 [1533668636.35][GLRM][INF] remote resources flashing with 'BUILD/tests/KL25Z/IAR/TESTS/mbed_hal/common_tickers/common_tickers.bin'...
00:04:38.748 [1533668636.35][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:04:38.751 [1533668636.35][urllib3.connectionpool]http://goku.austin.arm.com:8000 "POST /file HTTP/1.1" 200 250
00:04:50.635 [1533668648.24][GLRM][INF] opening connection to platform at baudrate='9600'
00:04:50.636 [1533668648.24][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:04:50.761 [1533668648.36][urllib3.connectionpool]http://goku.austin.arm.com:8000 "PUT /resource/0200000013894d440085101affff0003ffffffff97969900/connect HTTP/1.1" 200 15
00:04:50.761 [1533668648.36][GLRM][INF] remote resources reset...
00:04:52.930 [1533668650.53][GLRM][TXD] mbedmbedmbedmbedmbedmbedmbedmbedmbedmbed
00:04:52.930 [1533668650.53][CONN][INF] sending up to 10 __sync packets (specified with --sync=10)
00:04:52.930 [1533668650.53][CONN][INF] sending preamble '3801abb8-4d11-49d5-891b-bb1dfaf91b89'
00:04:52.931 [1533668650.53][GLRM][TXD] {{__sync;3801abb8-4d11-49d5-891b-bb1dfaf91b89}}
00:04:54.104 [1533668651.71][CONN][RXD] mbedmbedmbedmbedmbedmbedmbedmbed
00:04:54.104 [1533668651.71][CONN][INF] found SYNC in stream: {{__sync;3801abb8-4d11-49d5-891b-bb1dfaf91b89}} it is #0 sent, queued...
00:04:54.104 [1533668651.71][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
00:04:54.104 [1533668651.71][HTST][INF] sync KV found, uuid=3801abb8-4d11-49d5-891b-bb1dfaf91b89, timestamp=1533668651.706181
00:04:54.104 [1533668651.71][HTST][INF] DUT greentea-client version: 1.3.0
00:04:54.205 [1533668651.81][CONN][RXD] >>> Running 11 test cases...
00:04:54.205 [1533668651.81][CONN][INF] found KV pair in stream: {{__timeout;30}}, queued...
00:04:54.205 [1533668651.81][CONN][INF] found KV pair in stream: {{__host_test_name;default_auto}}, queued...
00:04:54.205 [1533668651.81][HTST][INF] setting timeout to: 30 sec
00:04:54.205 [1533668651.81][HTST][INF] host test class: '<class 'mbed_host_tests.host_tests.default_auto.DefaultAuto'>'
00:04:54.205 [1533668651.81][HTST][INF] host test setup() call...
00:04:54.205 [1533668651.81][HTST][INF] CALLBACKs updated
00:04:54.205 [1533668651.81][HTST][INF] host test detected: default_auto
00:04:54.304 [1533668651.91][CONN][INF] found KV pair in stream: {{__testcase_name;Microsecond ticker init is safe to call repeatedly}}, queued...
00:04:54.404 [1533668652.01][CONN][INF] found KV pair in stream: {{__testcase_name;Microsecond ticker info test}}, queued...
00:04:54.404 [1533668652.01][CONN][INF] found KV pair in stream: {{__testcase_name;Microsecond ticker interrupt test}}, queued...
00:04:54.504 [1533668652.11][CONN][INF] found KV pair in stream: {{__testcase_name;Microsecond ticker past interrupt test}}, queued...
00:04:54.504 [1533668652.11][CONN][INF] found KV pair in stream: {{__testcase_name;Microsecond ticker reschedule test}}, queued...
00:04:54.604 [1533668652.21][CONN][INF] found KV pair in stream: {{__testcase_name;Microsecond ticker fire interrupt}}, queued...
00:04:54.714 [1533668652.32][CONN][INF] found KV pair in stream: {{__testcase_name;Microsecond ticker overflow test}}, queued...
00:04:54.714 [1533668652.32][CONN][INF] found KV pair in stream: {{__testcase_name;Microsecond ticker increment test}}, queued...
00:04:54.805 [1533668652.41][CONN][INF] found KV pair in stream: {{__testcase_name;Microsecond ticker speed test}}, queued...
00:04:54.805 [1533668652.41][CONN][INF] found KV pair in stream: {{__testcase_name;Microsecond ticker free interrupt test}}, queued...
00:04:54.906 [1533668652.51][CONN][RXD]
00:04:54.906 [1533668652.51][CONN][INF] found KV pair in stream: {{__testcase_name;Microsecond re-init after free test}}, queued...
00:04:55.006 [1533668652.61][CONN][RXD] >>> Running case #1: 'Microsecond ticker init is safe to call repeatedly'...
00:04:55.006 [1533668652.61][CONN][INF] found KV pair in stream: {{__testcase_start;Microsecond ticker init is safe to call repeatedly}}, queued...
00:04:55.104 [1533668652.71][CONN][INF] found KV pair in stream: {{__testcase_finish;Microsecond ticker init is safe to call repeatedly;1;0}}, queued...
00:04:55.205 [1533668652.81][CONN][RXD] >>> 'Microsecond ticker init is safe to call repeatedly': 1 passed, 0 failed
00:04:55.205 [1533668652.81][CONN][RXD]
00:04:55.305 [1533668652.91][CONN][RXD] >>> Running case #2: 'Microsecond ticker info test'...
00:04:55.305 [1533668652.91][CONN][INF] found KV pair in stream: {{__testcase_start;Microsecond ticker info test}}, queued...
00:04:55.405 [1533668653.01][CONN][RXD] >>> 'Microsecond ticker info test': 1 passed, 0 failed
00:04:55.406 [1533668653.01][CONN][RXD]
00:04:55.406 [1533668653.01][CONN][INF] found KV pair in stream: {{__testcase_finish;Microsecond ticker info test;1;0}}, queued...
00:04:55.505 [1533668653.11][CONN][RXD] >>> Running case #3: 'Microsecond ticker interrupt test'...
00:04:55.606 [1533668653.21][CONN][INF] found KV pair in stream: {{__testcase_start;Microsecond ticker interrupt test}}, queued...
00:04:55.606 [1533668653.21][CONN][INF] found KV pair in stream: {{__testcase_finish;Microsecond ticker interrupt test;1;0}}, queued...
00:04:55.706 [1533668653.31][CONN][RXD] >>> 'Microsecond ticker interrupt test': 1 passed, 0 failed
00:04:55.706 [1533668653.31][CONN][RXD]
00:04:55.706 [1533668653.31][CONN][RXD] >>> Running case #4: 'Microsecond ticker past interrupt test'...
00:04:55.882 [1533668653.49][CONN][INF] found KV pair in stream: {{__testcase_start;Microsecond ticker past interrupt test}}, queued...
00:04:55.908 [1533668653.51][CONN][RXD] >>> 'Microsecond ticker past interrupt test': 1 passed, 0 failed
00:04:55.908 [1533668653.51][CONN][RXD]
00:04:55.908 [1533668653.51][CONN][INF] found KV pair in stream: {{__testcase_finish;Microsecond ticker past interrupt test;1;0}}, queued...
00:04:56.008 [1533668653.61][CONN][RXD] >>> Running case #5: 'Microsecond ticker reschedule test'...
00:04:56.112 [1533668653.72][CONN][INF] found KV pair in stream: {{__testcase_start;Microsecond ticker reschedule test}}, queued...
00:04:56.113 [1533668653.72][CONN][INF] found KV pair in stream: {{__testcase_finish;Microsecond ticker reschedule test;1;0}}, queued...
00:04:56.209 [1533668653.81][CONN][RXD] >>> 'Microsecond ticker reschedule test': 1 passed, 0 failed
00:04:56.209 [1533668653.81][CONN][RXD]
00:04:56.309 [1533668653.91][CONN][RXD] >>> Running case #6: 'Microsecond ticker fire interrupt'...
00:04:56.309 [1533668653.91][CONN][INF] found KV pair in stream: {{__testcase_start;Microsecond ticker fire interrupt}}, queued...
00:04:56.409 [1533668654.01][CONN][RXD] >>> 'Microsecond ticker fire interrupt': 1 passed, 0 failed
00:04:56.409 [1533668654.01][CONN][RXD]
00:04:56.409 [1533668654.01][CONN][INF] found KV pair in stream: {{__testcase_finish;Microsecond ticker fire interrupt;1;0}}, queued...
00:04:56.510 [1533668654.11][CONN][RXD] >>> Running case #7: 'Microsecond ticker overflow test'...
00:04:56.609 [1533668654.21][CONN][RXD] Test has been skipped.
00:04:56.609 [1533668654.21][CONN][INF] found KV pair in stream: {{__testcase_start;Microsecond ticker overflow test}}, queued...
00:04:56.609 [1533668654.21][CONN][INF] found KV pair in stream: {{__testcase_finish;Microsecond ticker overflow test;1;0}}, queued...
00:04:56.708 [1533668654.31][CONN][RXD] >>> 'Microsecond ticker overflow test': 1 passed, 0 failed
00:04:56.708 [1533668654.31][CONN][RXD]
00:04:56.809 [1533668654.41][CONN][RXD] >>> Running case #8: 'Microsecond ticker increment test'...
00:04:56.809 [1533668654.41][CONN][INF] found KV pair in stream: {{__testcase_start;Microsecond ticker increment test}}, queued...
00:04:57.009 [1533668654.61][CONN][INF] found KV pair in stream: {{__testcase_finish;Microsecond ticker increment test;1;0}}, queued...
00:04:57.109 [1533668654.71][CONN][RXD] >>> 'Microsecond ticker increment test': 1 passed, 0 failed
00:04:57.109 [1533668654.71][CONN][RXD]
00:04:57.209 [1533668654.81][CONN][RXD] >>> Running case #9: 'Microsecond ticker speed test'...
00:04:57.210 [1533668654.81][CONN][INF] found KV pair in stream: {{__testcase_start;Microsecond ticker speed test}}, queued...
00:04:57.309 [1533668654.91][CONN][RXD] >>> 'Microsecond ticker speed test': 1 passed, 0 failed
00:04:57.309 [1533668654.91][CONN][RXD]
00:04:57.310 [1533668654.91][CONN][INF] found KV pair in stream: {{__testcase_finish;Microsecond ticker speed test;1;0}}, queued...
00:04:57.409 [1533668655.01][CONN][RXD] >>> Running case #10: 'Microsecond ticker free interrupt test'...
00:04:57.509 mbedgt: :538::FAIL: Expected 0 Was 1
00:04:57.510 [1533668655.11][CONN][RXD] :538::FAIL: Expected 0 Was 1
00:04:57.510 [1533668655.11][CONN][INF] found KV pair in stream: {{__testcase_start;Microsecond ticker free interrupt test}}, queued...
00:04:57.610 [1533668655.21][CONN][INF] found KV pair in stream: {{__testcase_finish;Microsecond ticker free interrupt test;0;1}}, queued...
00:04:57.710 [1533668655.31][CONN][RXD] >>> 'Microsecond ticker free interrupt test': 0 passed, 1 failed with reason 'Assertion Failed'
00:04:57.710 [1533668655.31][CONN][RXD]
00:04:57.710 [1533668655.31][CONN][RXD] >>> Test cases: 9 passed, 1 failed with reason 'Assertion Failed'
00:04:57.710 [1533668655.31][CONN][RXD] >>> TESTS FAILED!
00:04:57.810 [1533668655.41][CONN][INF] found KV pair in stream: {{__testcase_summary;9;1}}, queued...
00:04:57.810 [1533668655.41][CONN][INF] found KV pair in stream: {{max_heap_usage;0}}, queued...
00:04:57.810 [1533668655.41][CONN][INF] found KV pair in stream: {{reserved_heap;4096}}, queued...
00:04:57.810 [1533668655.41][HTST][ERR] orphan event in main phase: {{max_heap_usage;0}}, timestamp=1533668655.412324
00:04:57.810 [1533668655.41][HTST][ERR] orphan event in main phase: {{reserved_heap;4096}}, timestamp=1533668655.412326
00:04:57.910 [1533668655.51][CONN][INF] found KV pair in stream: {{__thread_info;"0x020001824",736,4096}}, queued...
00:04:57.910 [1533668655.51][CONN][INF] found KV pair in stream: {{__thread_info;"0x020002d0c",64,512}}, queued...
00:04:57.910 [1533668655.51][HTST][ERR] orphan event in main phase: {{__thread_info;"0x020001824",736,4096}}, timestamp=1533668655.512385
00:04:57.910 [1533668655.51][HTST][ERR] orphan event in main phase: {{__thread_info;"0x020002d0c",64,512}}, timestamp=1533668655.512390
00:04:58.009 [1533668655.61][CONN][RXD] {{__cpu_info        up time;0}}
00:04:58.010 [1533668655.61][CONN][RXD] {{__cpu_info     sleep time;0}}
00:04:58.010 [1533668655.61][CONN][INF] found KV pair in stream: {{__thread_info;"0x01ffffe00",112,768}}, queued...
00:04:58.010 [1533668655.61][HTST][ERR] orphan event in main phase: {{__thread_info;"0x01ffffe00",112,768}}, timestamp=1533668655.612135
00:04:58.109 [1533668655.71][CONN][RXD] {{__cpu_info deepsleep time;0}}
00:04:58.109 [1533668655.71][CONN][RXD] {{__cpu_info  %  sleep/deep;0;0}}
00:04:58.109 [1533668655.71][CONN][INF] found KV pair in stream: {{end;failure}}, queued...
00:04:58.109 [1533668655.71][CONN][INF] found KV pair in stream: {{__exit;0}}, queued...
00:04:58.109 [1533668655.71][HTST][INF] __exit(0)
00:04:58.110 [1533668655.71][HTST][INF] __notify_complete(False)
00:04:58.110 [1533668655.71][HTST][INF] __exit_event_queue received
00:04:58.110 [1533668655.71][HTST][INF] test suite run finished after 3.91 sec...
00:04:58.110 [1533668655.71][CONN][INF] received special event '__host_test_finished' value='True', finishing
00:04:58.110 [1533668655.71][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:04:58.127 [1533668655.73][urllib3.connectionpool]http://goku.austin.arm.com:8000 "PUT /resource/0200000013894d440085101affff0003ffffffff97969900/disconnect HTTP/1.1" 200 2
00:04:58.128 [1533668655.73][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:05:01.277 [1533668658.88][urllib3.connectionpool]http://goku.austin.arm.com:8000 "PUT /resource/0200000013894d440085101affff0003ffffffff97969900/release HTTP/1.1" 200 66
00:05:01.279 [1533668658.88][HTST][INF] CONN exited with code: 0
00:05:01.279 [1533668658.88][HTST][INF] Some events in queue
00:05:01.279 [1533668658.88][HTST][INF] stopped consuming events
00:05:01.279 [1533668658.88][HTST][INF] host test result() call skipped, received: False
00:05:01.279 [1533668658.88][HTST][INF] calling blocking teardown()
00:05:01.279 [1533668658.88][HTST][INF] teardown() finished
00:05:01.279 [1533668658.88][HTST][INF] {{result;failure}}

[ ] Question
[ ] Enhancement 
[X ] Bug 

[aashishc1988]

Caused by:
#7508

cc: @studavekar @mprse

[ciarmcom]

ARM Internal Ref: MBOTRIAGE-1502

[mprse]

I'll check this.

[mprse]

I checked that KL25Z, K66F boards are not on CI. #7508 implements ticker free function only for CI boards. For other boards there is currently only empty stub added.
This is why the test is falling on the mentioned boards. I don't think that this is a reason to disable ticker support for boards with unimplemented ticker free function since it is not used by upper ticker layers.

I think that we need to wait until vendors will add implementation for ticker free. Maybe for now ticker free test cases should be skipped for non CI boards, but I don't know if there is an easy way to do that.

cc @jamesbeyond @0xc0170

[0xc0170]

This is why the test is falling on the mentioned boards. I don't think that this is a reason to disable ticker support for boards with unimplemented ticker free function since it is not used by upper ticker layers.

The test should not be enabled if the implementation is not present for all boards (=failing).

I think that we need to wait until vendors will add implementation for ticker free. Maybe for now ticker free test cases should be skipped for non CI boards, but I don't know if there is an easy way to do that.

When and how implementation is being added?

[mprse]

The test should not be enabled if the implementation is not present for all boards (=failing).

So maybe we should disable these test cases permanently until implementation for all boards is added.

When and how implementation is being added?

I agreed with @jamesbeyond to add implementation only for CI boards for now. Regarding implementation which is to be added by Vendors I don't know the answer to your question.

We have the following requirements for ticker free:

mbed-os/hal/us_ticker_api.h

Lines 76 to 77 in 273a052

	* * The function ticker_free disables the ticker interrupt - ::ticker_free_interrupt_test
	* * The function ticker_init re-initializes ticker after has been disabled by means of ticker_free - Verified by ::ticker_init_free_test

Since many lp tickers are based on RTC after discussion with @c1728p9 we decided to remove requirement about disabling counters. And currently if ticker is not based on RTC, free also disables the counter.

So the hot fix could be to modify the empty stubs of ticker free so they disable ticker interrupt. It should be simple change and test should pass. I can try to create patch before Friday. Then I'm 2 weeks off.

@0xc0170 What's your opinion?

[jamesbeyond]

@0xc0170 I think the issues here is the chicken-egg problem.
We need the test to be there, so that when SiPs impletment their ticker_free() function, they can verify it.

The new ticker API was implemented by the SiPs and merged into master during 5.9.
And later in 5.10, a small change on the ticker API been introduced, which is ticker_free() become a compulsory rather than optional. hence we add the test case for this, and get the ticker_free() implemented only on the CI targets. But the remaining boards left unimplemented which the tests would be failed.

I think we do need to have a formal channel or process with PE team or SiPs to define how to deal with these kinds of patch changes to the API after it been merged to master. At least let people aware the changes we made ASAP.
Then next question would be shall we directly working on the master, or keep working on a feature branch, until all the SiPs got all of their API update-to-date, then merge it back?

@donatieng @c1728p9 @ashok-rao

[0xc0170]

Then next question would be shall we directly working on the master, or keep working on a feature branch, until all the SiPs got all of their API update-to-date, then merge it back?

That is what feature branch is. Let's use it.

[mprse]

Now I agree that this should go on feature branch 😢.
But, like I said before I can try add basic implementation for all boards.

[jamesbeyond]

Using the feature branch would be able to prevent the issues like this, where some non-CI targets failed on some new tests.

But on the downside, it will delay for the features merge into master, cause we need to wait for all/most of the SiPs updated accordingly. So I'd like to have confirmation from both HAL engineer and PE team if they are happy about this decision. @donatieng @MarceloSalazar

Regarding this issue, since it already went into master, if implementing ticket_free() for all targets is not taking very long. I think @mprse you can go ahead and do that. Otherwise, we can move the test to a feature branch. note: the old ticker_spce_hal branch was removed, we will need a new one in this case.