Mbed-os: Failing nvstore-functionality tests on GR_LYCHEE

Created on 30 Jul 2018 · 13Comments · Source: ARMmbed/mbed-os

Description

Type: Bug
Priority: Major

Bug

Target
GR_LYCHEE
RZ_A1H

Toolchain:
GCC_ARM
ARM
IAR

mbed-os sha:
50bd61a4a72332baa6b1bac6caccb44dc5423309
Seems this test was added as part of release, mbed-os-5.9.3

Tests we are failing:
features-nvstore-tests-nvstore-functionality | NVStore: Basic functionality

Steps to reproduce
mbed test -m GR_LYCHEE -t GCC_ARM -n features-nvstore-tests-nvstore-functionality -v

Error we see
mbed assertation failed: num_keys < get_max_possible_keys(), file: ./features/nvstore/source/nvstore.cpp, line 173

log snippet
>

00:22:04.646 mbedgt: mbed-host-test-runner: started
00:22:04.834 [1532549051.17][root]Generating grammar tables from /usr/lib/python2.7/lib2to3/Grammar.txt
00:22:04.850 [1532549051.18][root]Generating grammar tables from /usr/lib/python2.7/lib2to3/PatternGrammar.txt
00:22:04.856 [1532549051.19][HTST][INF] host test executor ver. 1.4.0
00:22:04.856 [1532549051.19][HTST][INF] copy image onto target... SKIPPED!
00:22:04.857 [1532549051.19][HTST][INF] starting host test process...
00:22:04.860 [1532549051.19][CONN][INF] starting connection process...
00:22:04.860 [1532549051.20][CONN][INF] notify event queue about extra 60 sec timeout for serial port pooling
00:22:04.860 [1532549051.20][CONN][INF] initializing global resource mgr listener...
00:22:04.898 [1532549051.23][HTST][INF] setting timeout to: 60 sec
00:22:04.917 [1532549051.25][GLRM][INF] remote resources initialization: remote(host=goku.austin.arm.com, port=8000)
00:22:04.918 [1532549051.25][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:22:04.920 [1532549051.26][urllib3.connectionpool]http://goku.austin.arm.com:8000 "POST /login HTTP/1.1" 200 213
00:22:04.923 [1532549051.26][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:22:04.924 [1532549051.26][urllib3.connectionpool]http://goku.austin.arm.com:8000 "GET /socket.io/?token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJ1c2VybmFtZSI6InVzZXIiLCJncm91cCI6InVzZXIiLCJpYXQiOjE1MzI1NDkwNTEsImV4cCI6MTUzMzE1Mzg1MX0.t1yonPJUN1iY2vrj3r1OT1aZwtr9F3zaPN0bP-1QvJE&EIO=3&transport=polling&t=1532549051256-0 HTTP/1.1" 200 101
00:22:04.928 [1532549051.26][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:22:04.931 [1532549051.27][urllib3.connectionpool]http://goku.austin.arm.com:8000 "GET /this/resource HTTP/1.1" 200 3651
00:22:04.932 [1532549051.27][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:22:04.937 [1532549051.27][urllib3.connectionpool]http://goku.austin.arm.com:8000 "GET /resource HTTP/1.1" 200 49052
00:22:04.941 [1532549051.28][GLRM][INF] remote resources count: 34
00:22:04.950 [1532549051.29][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:22:04.952 [1532549051.29][urllib3.connectionpool]http://goku.austin.arm.com:8000 "GET /resource/5501000003e0fb7200000000000000000000000097969902 HTTP/1.1" 200 1833
00:22:04.952 [1532549051.29][GLRM][INF] remote resources flashing with 'BUILD/tests/GR_LYCHEE/GCC_ARM/features/nvstore/TESTS/nvstore/functionality/functionality.bin'...
00:22:04.954 [1532549051.29][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:22:04.957 [1532549051.29][urllib3.connectionpool]http://goku.austin.arm.com:8000 "POST /file HTTP/1.1" 200 249
00:22:20.351 [1532549066.69][GLRM][INF] opening connection to platform at baudrate='9600'
00:22:20.352 [1532549066.69][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:22:20.487 [1532549066.82][urllib3.connectionpool]http://goku.austin.arm.com:8000 "PUT /resource/5501000003e0fb7200000000000000000000000097969902/connect HTTP/1.1" 200 15
00:22:20.487 [1532549066.82][GLRM][INF] remote resources reset...
00:22:22.705 [1532549069.04][GLRM][TXD] mbedmbedmbedmbedmbedmbedmbedmbedmbedmbed
00:22:22.706 [1532549069.04][CONN][INF] sending up to 10 __sync packets (specified with --sync=10)
00:22:22.706 [1532549069.04][CONN][INF] sending preamble '562a291e-d925-4af9-aa29-f5222a7536e0'
00:22:22.707 [1532549069.04][GLRM][TXD] {{__sync;562a291e-d925-4af9-aa29-f5222a7536e0}}
00:22:23.878 [1532549070.21][CONN][RXD] mbedmbedmbedmbedmbedmbedmbedmbed
00:22:23.878 [1532549070.21][HTST][INF] sync KV found, uuid=562a291e-d925-4af9-aa29-f5222a7536e0, timestamp=1532549070.214005
00:22:23.879 [1532549070.21][CONN][INF] found SYNC in stream: {{__sync;562a291e-d925-4af9-aa29-f5222a7536e0}} it is #0 sent, queued...
00:22:23.879 [1532549070.21][HTST][INF] DUT greentea-client version: 1.3.0
00:22:23.879 [1532549070.21][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
00:22:23.978 [1532549070.31][HTST][INF] setting timeout to: 120 sec
00:22:23.979 [1532549070.31][CONN][INF] found KV pair in stream: {{__timeout;120}}, queued...
00:22:23.979 [1532549070.31][HTST][INF] host test class: '<class 'mbed_host_tests.host_tests.default_auto.DefaultAuto'>'
00:22:23.979 [1532549070.31][HTST][INF] host test setup() call...
00:22:23.979 [1532549070.31][HTST][INF] CALLBACKs updated
00:22:23.979 [1532549070.31][HTST][INF] host test detected: default_auto
00:22:23.979 [1532549070.31][CONN][INF] found KV pair in stream: {{__host_test_name;default_auto}}, queued...
00:22:23.979 [1532549070.32][CONN][INF] found KV pair in stream: {{__testcase_count;3}}, queued...
00:22:24.079 [1532549070.41][CONN][RXD] >>> Running 3 test cases...
00:22:24.079 [1532549070.41][CONN][INF] found KV pair in stream: {{__testcase_name;NVStore: Basic functionality}}, queued...
00:22:24.183 [1532549070.52][CONN][RXD]
00:22:24.183 [1532549070.52][CONN][INF] found KV pair in stream: {{__testcase_name;NVStore: Race test}}, queued...
00:22:24.183 [1532549070.52][CONN][INF] found KV pair in stream: {{__testcase_name;NVStore: Multiple thread test}}, queued...
00:22:24.285 [1532549070.62][CONN][RXD] >>> Running case #1: 'NVStore: Basic functionality'...
00:22:24.286 [1532549070.62][CONN][RXD] NVStore areas:
00:22:24.286 [1532549070.62][CONN][INF] found KV pair in stream: {{__testcase_start;NVStore: Basic functionality}}, queued...
00:22:24.384 [1532549070.72][CONN][RXD] Area 0: address 0x187fe000, size 4096 (0x1000)
00:22:24.505 [1532549070.84][CONN][RXD] Area 1: address 0x187ff000, size 4096 (0x1000)
00:22:24.589 [1532549070.93][CONN][RXD] **mbed assertation failed: num_keys < get_max_possible_keys(), file: ./features/nvstore/source/nvstore.cpp, line 173**
00:24:24.728 [1532549191.07][HTST][INF] test suite run finished after 120.75 sec...
00:24:24.728 [1532549191.07][CONN][INF] received special event '__host_test_finished' value='True', finishing
00:24:24.729 [1532549191.07][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:24:24.761 [1532549191.10][urllib3.connectionpool]http://goku.austin.arm.com:8000 "PUT /resource/5501000003e0fb7200000000000000000000000097969902/disconnect HTTP/1.1" 200 2
00:24:24.762 [1532549191.10][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:24:27.902 [1532549194.24][urllib3.connectionpool]http://goku.austin.arm.com:8000 "PUT /resource/5501000003e0fb7200000000000000000000000097969902/release HTTP/1.1" 200 66
00:24:27.906 [1532549194.24][HTST][INF] CONN exited with code: 0
00:24:27.906 [1532549194.24][HTST][INF] No events in queue
00:24:27.906 [1532549194.24][HTST][INF] stopped consuming events
00:24:27.906 [1532549194.24][HTST][INF] host test result(): None
00:24:27.907 [1532549194.24][HTST][WRN] missing __exit event from DUT
00:24:27.907 [1532549194.24][HTST][WRN] missing __exit_event_queue event from host test
00:24:27.907 [1532549194.24][HTST][ERR] missing __exit_event_queue event from host test and no result from host test, timeout...
00:24:27.907 [1532549194.25][HTST][INF] calling blocking teardown()
00:24:27.907 [1532549194.25][HTST][INF] teardown() finished
00:24:27.907 [1532549194.25][HTST][INF] {{result;timeout}}
00:24:27.934 mbedgt: retry mbedhtrun 1/3
>

[ ] Question
[ ] Enhancement
[X ] Bug

closed_in_jira storage mirrored bug

Source

aashishc1988

Most helpful comment

It seems that mbed assert occurs in NVStore::set_max_keys.
This API is called at here of main.cpp.

Because the page size of Flash that is incorporated on GR-PEACH and GR-LYCHEE is 256 Byte, the return value of get_max_possible_keys() becomes 15.
Since num_keys(= max_test_keys from main.cpp) is 20(= fixed value), the condition is not established.

Could you tell me why max_test_keys is 20(= fixed value)?

TomoYamanaka on 31 Jul 2018

👍2

All 13 comments

@studavekar

aashishc1988 on 30 Jul 2018

@toyowata @maclobdell @bentcooke @davidsaada please review.

studavekar on 30 Jul 2018

It seems that mbed assert occurs in NVStore::set_max_keys.
This API is called at here of main.cpp.

Could you tell me why max_test_keys is 20(= fixed value)?

TomoYamanaka on 31 Jul 2018

👍2

@ARMmbed/mbed-os-storage Please review

0xc0170 on 31 Jul 2018

@TomoYamanaka It is indeed a bug, which I should fix. The functionality test performs a lot of NVStore set and get actions with different keys. I use lower values of the keys to try and squeeze this board in, but the real bug here is the fact I don't check the test number of keys against the max possible number of keys. Will fix it.

davidsaada on 31 Jul 2018

👍1

ARM Internal Ref: MBOTRIAGE-1474

ciarmcom on 31 Jul 2018

@davidsaada
Thank you for your comment.

However, I take back what I said.

Because the page size of Flash that is incorporated on GR-PEACH and GR-LYCHEE is 256 Byte,

As a result of review flash spec, I found that this 256 Byte is not a minimum access size is a maximum size per one writing, and the minimum access size is 1 Byte.
Also, I noticed that the write process that is defined in flash_iap.c does not work correctly when receiving the request of size larger than 256 byte.

As a trial, I changed the above 2 points and run NVStore test and Flash iAP test. As a result of it, test result became all OK.

+-------------------+---------------+----------------------------------------------+-----------------------------------+--------+--------+--------+--------------------+
| target            | platform_name | test suite                                   | test case                         | passed | failed | result | elapsed_time (sec) |
+-------------------+---------------+----------------------------------------------+-----------------------------------+--------+--------+--------+--------------------+
| GR_LYCHEE-GCC_ARM | GR_LYCHEE     | features-nvstore-tests-nvstore-functionality | NVStore: Basic functionality      | 1      | 0      | OK     | 0.42               |
| GR_LYCHEE-GCC_ARM | GR_LYCHEE     | features-nvstore-tests-nvstore-functionality | NVStore: Multiple thread test     | 1      | 0      | OK     | 6.98               |
| GR_LYCHEE-GCC_ARM | GR_LYCHEE     | features-nvstore-tests-nvstore-functionality | NVStore: Race test                | 1      | 0      | OK     | 0.43               |
| GR_LYCHEE-GCC_ARM | GR_LYCHEE     | tests-mbed_drivers-flashiap                  | FlashIAP - init                   | 1      | 0      | OK     | 0.04               |
| GR_LYCHEE-GCC_ARM | GR_LYCHEE     | tests-mbed_drivers-flashiap                  | FlashIAP - program                | 1      | 0      | OK     | 0.56               |
| GR_LYCHEE-GCC_ARM | GR_LYCHEE     | tests-mbed_drivers-flashiap                  | FlashIAP - program across sectors | 1      | 0      | OK     | 0.14               |
| GR_LYCHEE-GCC_ARM | GR_LYCHEE     | tests-mbed_drivers-flashiap                  | FlashIAP - program errors         | 1      | 0      | OK     | 0.06               |
| GR_LYCHEE-GCC_ARM | GR_LYCHEE     | tests-mbed_hal-flash                         | Flash - clock and cache test      | 1      | 0      | OK     | 0.09               |
| GR_LYCHEE-GCC_ARM | GR_LYCHEE     | tests-mbed_hal-flash                         | Flash - erase sector              | 1      | 0      | OK     | 0.08               |
| GR_LYCHEE-GCC_ARM | GR_LYCHEE     | tests-mbed_hal-flash                         | Flash - init                      | 1      | 0      | OK     | 0.06               |
| GR_LYCHEE-GCC_ARM | GR_LYCHEE     | tests-mbed_hal-flash                         | Flash - mapping alignment         | 1      | 0      | OK     | 0.05               |
| GR_LYCHEE-GCC_ARM | GR_LYCHEE     | tests-mbed_hal-flash                         | Flash - program page              | 1      | 0      | OK     | 0.14               |
+-------------------+---------------+----------------------------------------------+-----------------------------------+--------+--------+--------+--------------------+

I will submit a PR for above flash_iap.c when I'm ready.

TomoYamanaka on 1 Aug 2018

🎉1

@TomoYamanaka Nonetheless, this exposed a bug in the NVStore test, which I should fix.

davidsaada on 1 Aug 2018

@aashishc1988 Please check whether #7670 fixes this issue (I don't have access to this board).

davidsaada on 1 Aug 2018

@davidsaada I confirm that https://github.com/ARMmbed/mbed-os/pull/7670 does fix the issue. I am wondering if we should a file a different github issue to track the bug @TomoYamanaka found or address that as a part of this one.

aashishc1988 on 1 Aug 2018

@davidsaada I confirm that #7670 does fix the issue. I am wondering if we should a file a different github issue to track the bug @TomoYamanaka found or address that as a part of this one.

@aashishc1988 Thanks for confirming it. I think it should be in a separate issue. This issue is currently assigned to me (and should likely be closed soon as I opened a PR for it), and we need a different one assigned to @TomoYamanaka for the other problem (which he should resolve in his own time).

davidsaada on 1 Aug 2018

@davidsaada Agreed! It would be better to track it on different PR.

aashishc1988 on 1 Aug 2018

I will wait for the PR to be merged before I close this, and file a new github issue for @TomoYamanaka

aashishc1988 on 1 Aug 2018

👍1

Was this page helpful?

0 / 5 - 0 ratings