occasional sanitycheck failures in samples/subsys/settings

[andrewboie]

$ scr -a x86
Deleting output directory /dev/shm/sanity-out
INFO    - JOBS: 48
INFO    - Selecting default platforms per test case
INFO    - Building initial testcase list...
INFO    - 1237 test configurations selected, 227004 configurations discarded due to filters.
INFO    - Adding tasks to the queue...
INFO    - Total complete:   71/1237   5%  skipped:   17, failed:    0
ERROR   - qemu_x86                  samples/subsys/settings/sample.subsys.settings     FAILED: unexpected eof
ERROR   - see: /dev/shm/sanity-out/qemu_x86/samples/subsys/settings/sample.subsys.settings/handler.log

Might be a problem with the regexes used? The handler.log looks normal:

�[0mSeaBIOS (version rel-1.12.1-0-ga5cab58-dirty-20200625_115407-9426dddc0a1f-zephyr
)
Booting from ROM..*** Booting Zephyr OS build zephyr-v2.3.0-1144-g6c69bc94b35b  ***

*** Settings usage example ***

settings subsys initialization: OK.
subtree <alpha> handler registered: OK
subtree <alpha/beta> has static handler

##############
# iteration 0
##############

=================================================
basic load and save using registered handlers

load all key-value pairs using registered handlers
loading all settings under <beta> handler is done
loading all settings under <alpha> handler is done

save <alpha/beta/voltage> key directly: OK.

load <alpha/beta> key-value pairs using registered handlers
<alpha/beta/voltage> = -3025
loading all settings under <beta> handler is done

save all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

load all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

=================================================
loading subtree to destination provided by the caller

direct load: <alpha/length/2>
direct load: <alpha/length/1>
direct load: <alpha/length>
  direct.length = 100
  direct.length_1 = 41
  direct.length_2 = 59

=================================================
Delete a key-value pair

immediate load: OK.
  <alpha/length> value exist in the storage
delete <alpha/length>: OK.
  Can't to load the <alpha/length> value as expected

=================================================
Service a key-value pair without dedicated handlers

<gamma> = 0 (default)
save <gamma> key directly: OK.

##############
# iteration 1
##############

=================================================
basic load and save using registered handlers

load all key-value pairs using registered handlers
<alpha/length/2> = 59
<alpha/length/1> = 41
<alpha/angle/1> = 1
<alpha/beta/source> = a
<alpha/beta/voltage> = -3025
loading all settings under <beta> handler is done
loading all settings under <alpha> handler is done

save <alpha/beta/voltage> key directly: OK.

load <alpha/beta> key-value pairs using registered handlers
<alpha/beta/source> = a
<alpha/beta/voltage> = -3050
loading all settings under <beta> handler is done

save all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

load all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

=================================================
loading subtree to destination provided by the caller

direct load: <alpha/length>
direct load: <alpha/length/2>
direct load: <alpha/length/1>
  direct.length = 100
  direct.length_1 = 42
  direct.length_2 = 58

=================================================
Delete a key-value pair

immediate load: OK.
  <alpha/length> value exist in the storage
delete <alpha/length>: OK.
  Can't to load the <alpha/length> value as expected

=================================================
Service a key-value pair without dedicated handlers

immediate load: OK.
<gamma> = 1
save <gamma> key directly: OK.

##############
# iteration 2
##############

=================================================
basic load and save using registered handlers

load all key-value pairs using registered handlers
<alpha/length/2> = 58
<alpha/length/1> = 42
<alpha/angle/1> = 2
<alpha/beta/source> = ab
<alpha/beta/voltage> = -3050
loading all settings under <beta> handler is done
loading all settings under <alpha> handler is done

save <alpha/beta/voltage> key directly: OK.

load <alpha/beta> key-value pairs using registered handlers
<alpha/beta/source> = ab
<alpha/beta/voltage> = -3075
loading all settings under <beta> handler is done

save all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

load all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

=================================================
loading subtree to destination provided by the caller

direct load: <alpha/length>
direct load: <alpha/length/2>
direct load: <alpha/length/1>
  direct.length = 100
  direct.length_1 = 43
  direct.length_2 = 57

=================================================
Delete a key-value pair

immediate load: OK.
  <alpha/length> value exist in the storage
delete <alpha/length>: OK.
  Can't to load the <alpha/length> value as expected

=================================================
Service a key-value pair without dedicated handlers

immediate load: OK.
<gamma> = 2
save <gamma> key directly: OK.

##############
# iteration 3
##############

=================================================
basic load and save using registered handlers

load all key-value pairs using registered handlers
<alpha/length/2> = 57
<alpha/length/1> = 43
<alpha/angle/1> = 3
<alpha/beta/source> = abc
<alpha/beta/voltage> = -3075
loading all settings under <beta> handler is done
loading all settings under <alpha> handler is done

save <alpha/beta/voltage> key directly: OK.

load <alpha/beta> key-value pairs using registered handlers
<alpha/beta/source> = abc
<alpha/beta/voltage> = -3100
loading all settings under <beta> handler is done

save all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

load all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

=================================================
loading subtree to destination provided by the caller

direct load: <alpha/length>
direct load: <alpha/length/2>
direct load: <alpha/length/1>
  direct.length = 100
  direct.length_1 = 44
  direct.length_2 = 56

=================================================
Delete a key-value pair

immediate load: OK.
  <alpha/length> value exist in the storage
delete <alpha/length>: OK.
  Can't to load the <alpha/length> value as expected

=================================================
Service a key-value pair without dedicated handlers

immediate load: OK.
<gamma> = 3
save <gamma> key directly: OK.

##############
# iteration 4
##############

=================================================
basic load and save using registered handlers

load all key-value pairs using registered handlers
<alpha/length/2> = 56
<alpha/length/1> = 44
<alpha/angle/1> = 4
<alpha/beta/source> = abcd
<alpha/beta/voltage> = -3100
loading all settings under <beta> handler is done
loading all settings under <alpha> handler is done

save <alpha/beta/voltage> key directly: OK.

load <alpha/beta> key-value pairs using registered handlers
<alpha/beta/source> = abcd
<alpha/beta/voltage> = -3125
loading all settings under <beta> handler is done

save all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

load all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

=================================================
loading subtree to destination provided by the caller

direct load: <alpha/length>
direct load: <alpha/length/2>
direct load: <alpha/length/1>
  direct.length = 100
  direct.length_1 = 45
  direct.length_2 = 55

=================================================
Delete a key-value pair

immediate load: OK.
  <alpha/length> value exist in the storage
delete <alpha/length>: OK.
  Can't to load the <alpha/length> value as expected

=================================================
Service a key-value pair without dedicated handlers

immediate load: OK.
<gamma> = 4
save <gamma> key directly: OK.

##############
# iteration 5
##############

=================================================
basic load and save using registered handlers

load all key-value pairs using registered handlers
<alpha/length/2> = 55
<alpha/length/1> = 45
<alpha/angle/1> = 5
<alpha/beta/source> is not compatible with the application
<alpha/beta/voltage> = -3125
loading all settings under <beta> handler is done
loading all settings under <alpha> handler is done

save <alpha/beta/voltage> key directly: OK.

load <alpha/beta> key-value pairs using registered handlers
<alpha/beta/source> is not compatible with the application
<alpha/beta/voltage> = -3150
loading all settings under <beta> handler is done

save all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

load all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

=================================================
loading subtree to destination provided by the caller

direct load: <alpha/length>
direct load: <alpha/length/2>
direct load: <alpha/length/1>
  direct.length = 100
  direct.length_1 = 46
  direct.length_2 = 54

=================================================
Delete a key-value pair

immediate load: OK.
  <alpha/length> value exist in the storage
delete <alpha/length>: OK.
  Can't to load the <alpha/length> value as expected

=================================================
Service a key-value pair without dedicated handlers

immediate load: OK.
<gamma> = 5
save <gamma> key directly: OK.

=================================================
Inject the value to the setting destination in runtime

<alpha/beta/source> = RT
injected <alpha/beta/source>: OK.
  The settings destination off the key <alpha/beta/source> has got value: "RT"


=================================================
Read a value from the setting destination in runtime

fetched <alpha/beta/source>: OK.
  String value "rtos" was retrieved from the settings destination off the key <alpha/beta/source>

*** THE END  ***

I have also seen this fail with truncated output in handler.log which I suspect may be an instance of #24649

[andrewboie]

still seeing this, although with recent sanitycheck fixes this reports "Timeout" and not "Unexpected EOF"

[de-nordic]

What does the scr do?
Is this something like:
./scripts/sanitycheck -p qemu_x86 -s samples/subsys/settings/sample.subsys.settings
I have looped that test for quite long and have not been able to reproduce the problem.

[andrewboie]

It's a bash alias on my workstations equivalent to:

nice sanitycheck -j48 -M -c --outdir /dev/shm/sanity-out

[andrewboie]

By the way I linked the wrong bug earlier, it's possible this is an instance of or related to #26949

[de-nordic]

It's a bash alias on my workstations equivalent to:

nice sanitycheck -j48 -M -c --outdir /dev/shm/sanity-out

I have run the command altering it a little bit:
sanitycheck -j48 -M -c --outdir /dev/shm/sanity-out -s samples/subsys/settings/sample.subsys.settings

After ~2h of run I have not faced the issue. In my case -j48 is redundant for two tests and 8 core cpu, though I left it there.

[nvlsianpu]

Might be a problem with the regexes used?

I believe not, regex is ok and console output looks fine to me (match regex).

What I saw at the beginning of the output there is 0x1B character which is escape character, see:

�[0mSeaBIOS (version rel-1.12.1-0-ga5cab58-dirty-20200625_115407-9426dddc0a1f-zephyr

Is this might be an issue here?

[andrewboie]

What I saw at the beginning of the output there is 0x1B character which is escape character, see:

�[0mSeaBIOS (version rel-1.12.1-0-ga5cab58-dirty-20200625_115407-9426dddc0a1f-zephyr

Is this might be an issue here?

This is always printed by the emulated firmware.

[nvlsianpu]

Anyway - looks like this is not settings or its test issue but test infrastructure issue.

[nvlsianpu]

@andrewboie We were totally unable to reproduce occasional failure you had reported. This tests also is passing all the time on buldkite we are using here, eg.: https://buildkite.com/zephyr/zephyr/builds/7718#e2d59170-240c-40aa-b1ec-34e91454c193

Can we close this issue?

[andrewboie]

I just reproduced this today.
Please do not close this until a root cause is found.
If you have evidence that this is a sanitycheck problem, and not an issue with the test (for example, the regexes used for success/failure match the provided output) this can be reassigned.

Deleting output directory /dev/shm/sanity-out
INFO    - JOBS: 48
INFO    - Building initial testcase list...
INFO    - 936 test configurations selected, 522 configurations discarded due to filters.
INFO    - Adding tasks to the queue...
INFO    - Total complete:   80/ 414  19%  skipped:    5, failed:    0
ERROR   - qemu_x86                  samples/subsys/settings/sample.subsys.settings     FAILED: Timeout
ERROR   - see: /dev/shm/sanity-out/qemu_x86/samples/subsys/settings/sample.subsys.settings/handler.log
INFO    - Total complete:  414/ 414  100%  skipped:   44, failed:    1
INFO    - 369 of 370 tests passed (99.73%), 1 failed, 566 skipped with 0 warnings in 341.18 seconds
INFO    - In total 1886 test cases were executed on 1 out of total 295 platforms (0.34%)
INFO    - 248 tests executed on platforms, 122 tests were only built.
apboie@apboie-mobl4:~/projects/zephyr/zephyr (1) page-tables-overhaul /home/apboie/projects/zephyr/zephyr
$ cat /dev/shm/sanity-out/qemu_x86/samples/subsys/settings/sample.subsys.settings/handler.log
SeaBIOS (version rel-1.12.1-0-ga5cab58-dirty-20200625_115407-9426dddc0a1f-zephyr
)
Booting from ROM..*** Booting Zephyr OS build zephyr-v2.4.0-682-g525fd0838746  ***

*** Settings usage example ***

settings subsys initialization: OK.
subtree <alpha> handler registered: OK
subtree <alpha/beta> has static handler

##############
# iteration 0
##############

=================================================
basic load and save using registered handlers

load all key-value pairs using registered handlers
loading all settings under <beta> handler is done
loading all settings under <alpha> handler is done

save <alpha/beta/voltage> key directly: OK.

load <alpha/beta> key-value pairs using registered handlers
<alpha/beta/voltage> = -3025
loading all settings under <beta> handler is done

save all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

load all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

=================================================
loading subtree to destination provided by the caller

direct load: <alpha/length/2>
direct load: <alpha/length/1>
direct load: <alpha/length>
  direct.length = 100
  direct.length_1 = 41
  direct.length_2 = 59

=================================================
Delete a key-value pair

immediate load: OK.
  <alpha/length> value exist in the storage
delete <alpha/length>: OK.
  Can't to load the <alpha/length> value as expected

=================================================
Service a key-value pair without dedicated handlers

<gamma> = 0 (default)
save <gamma> key directly: OK.

##############
# iteration 1
##############

=================================================
basic load and save using registered handlers

load all key-value pairs using registered handlers
<alpha/length/2> = 59
<alpha/length/1> = 41
<alpha/angle/1> = 1
<alpha/beta/source> = a
<alpha/beta/voltage> = -3025
loading all settings under <beta> handler is done
loading all settings under <alpha> handler is done

save <alpha/beta/voltage> key directly: OK.

load <alpha/beta> key-value pairs using registered handlers
<alpha/beta/source> = a
<alpha/beta/voltage> = -3050
loading all settings under <beta> handler is done

save all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

load all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

=================================================
loading subtree to destination provided by the caller

direct load: <alpha/length>
direct load: <alpha/length/2>
direct load: <alpha/length/1>
  direct.length = 100
  direct.length_1 = 42
  direct.length_2 = 58

=================================================
Delete a key-value pair

immediate load: OK.
  <alpha/length> value exist in the storage
delete <alpha/length>: OK.
  Can't to load the <alpha/length> value as expected

=================================================
Service a key-value pair without dedicated handlers

immediate load: OK.
<gamma> = 1
save <gamma> key directly: OK.

##############
# iteration 2
##############

=================================================
basic load and save using registered handlers

load all key-value pairs using registered handlers
<alpha/length/2> = 58
<alpha/length/1> = 42
<alpha/angle/1> = 2
<alpha/beta/source> = ab
<alpha/beta/voltage> = -3050
loading all settings under <beta> handler is done
loading all settings under <alpha> handler is done

save <alpha/beta/voltage> key directly: OK.

load <alpha/beta> key-value pairs using registered handlers
<alpha/beta/source> = ab
<alpha/beta/voltage> = -3075
loading all settings under <beta> handler is done

save all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

load all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

=================================================
loading subtree to destination provided by the caller

direct load: <alpha/length>
direct load: <alpha/length/2>
direct load: <alpha/length/1>
  direct.length = 100
  direct.length_1 = 43
  direct.length_2 = 57

=================================================
Delete a key-value pair

immediate load: OK.
  <alpha/length> value exist in the storage
delete <alpha/length>: OK.
  Can't to load the <alpha/length> value as expected

=================================================
Service a key-value pair without dedicated handlers

immediate load: OK.
<gamma> = 2
save <gamma> key directly: OK.

##############
# iteration 3
##############

=================================================
basic load and save using registered handlers

load all key-value pairs using registered handlers
<alpha/length/2> = 57
<alpha/length/1> = 43
<alpha/angle/1> = 3
<alpha/beta/source> = abc
<alpha/beta/voltage> = -3075
loading all settings under <beta> handler is done
loading all settings under <alpha> handler is done

save <alpha/beta/voltage> key directly: OK.

load <alpha/beta> key-value pairs using registered handlers
<alpha/beta/source> = abc
<alpha/beta/voltage> = -3100
loading all settings under <beta> handler is done

save all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

load all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

=================================================
loading subtree to destination provided by the caller

direct load: <alpha/length>
direct load: <alpha/length/2>
direct load: <alpha/length/1>
  direct.length = 100
  direct.length_1 = 44
  direct.length_2 = 56

=================================================
Delete a key-value pair

immediate load: OK.
  <alpha/length> value exist in the storage
delete <alpha/length>: OK.
  Can't to load the <alpha/length> value as expected

=================================================
Service a key-value pair without dedicated handlers

immediate load: OK.
<gamma> = 3
save <gamma> key directly: OK.

##############
# iteration 4
##############

=================================================
basic load and save using registered handlers

load all key-value pairs using registered handlers
<alpha/length/2> = 56
<alpha/length/1> = 44
<alpha/angle/1> = 4
<alpha/beta/source> = abcd
<alpha/beta/voltage> = -3100
loading all settings under <beta> handler is done
loading all settings under <alpha> handler is done

save <alpha/beta/voltage> key directly: OK.

load <alpha/beta> key-value pairs using registered handlers
<alpha/beta/source> = abcd
<alpha/beta/voltage> = -3125
loading all settings under <beta> handler is done

save all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

load all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

=================================================
loading subtree to destination provided by the caller

direct load: <alpha/length>
direct load: <alpha/length/2>
direct load: <alpha/length/1>
  direct.length = 100
  direct.length_1 = 45
  direct.length_2 = 55

=================================================
Delete a key-value pair

immediate load: OK.
  <alpha/length> value exist in the storage
delete <alpha/length>: OK.
  Can't to load the <alpha/length> value as expected

=================================================
Service a key-value pair without dedicated handlers

immediate load: OK.
<gamma> = 4
save <gamma> key directly: OK.

##############
# iteration 5
##############

=================================================
basic load and save using registered handlers

load all key-value pairs using registered handlers
<alpha/length/2> = 55
<alpha/length/1> = 45
<alpha/angle/1> = 5
<alpha/beta/source> is not compatible with the application
<alpha/beta/voltage> = -3125
loading all settings under <beta> handler is done
loading all settings under <alpha> handler is done

save <alpha/beta/voltage> key directly: OK.

load <alpha/beta> key-value pairs using registered handlers
<alpha/beta/source> is not compatible with the application
<alpha/beta/voltage> = -3150
loading all settings under <beta> handler is done

save all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

load all key-value pairs using registered handlers
export keys under <beta> handler
export keys under <alpha> handler

=================================================
loading subtree to destination provided by the caller

direct load: <alpha/length>
direct load: <alpha/length/2>
direct load: <alpha/length/1>
  direct.length = 100
  direct.length_1 = 46
  direct.length_2 = 54

=================================================
Delete a key-value pair

immediate load: OK.
  <alpha/length> value exist in the storage
delete <alpha/length>: OK.
  Can't to load the <alpha/length> value as expected

=================================================
Service a key-value pair without dedicated handlers

immediate load: OK.
<gamma> = 5
save <gamma> key directly: OK.

=================================================
Inject the value to the setting destination in runtime

<alpha/beta/source> = RT
injected <alpha/beta/source>: OK.
  The settings destination off the key <alpha/beta/source> has got value: "RT"


=================================================
Read a value from the setting destination in runtime

fetched <alpha/beta/source>: OK.
  String value "rtos" was retrieved from the settings destination off the key <alpha/beta/source>

*** THE END  ***

[github-actions]

This issue has been marked as stale because it has been open (more than) 60 days with no activity. Remove the stale label or add a comment saying that you would like to have the label removed otherwise this issue will automatically be closed in 14 days. Note, that you can always re-open a closed issue at any time.