tests: lib: date_time: Tests for scheduled updates #17477

trantanen · 2024-09-25T09:59:56Z

Adding tests for scheduled date-time updates verifying that they occur at configured intervals.

Some small clean-up and additional logging into date-time library.

Branch coverage is going from ~44% to ~98% having 3 branches untested. These are related to failure of clock_gettime/clock_settime which cannot really be achieved without creating a different test set and mocking those APIs.

With default configuration, the tests run 30-40s due to update intervals that we need to wait.

Jira: NCSDK-28887

trantanen · 2024-09-25T10:01:27Z

lib/date_time/date_time_core.c

+ /* Scheduling new update cannot fail because we are never doing retries
+ * if we have fresh enough time
+ */
+ date_time_core_schedule_work(CONFIG_DATE_TIME_RETRY_INTERVAL_SECONDS);
+ LOG_DBG("Date time update retry in: %d seconds", CONFIG_DATE_TIME_RETRY_INTERVAL_SECONDS);


I don't think scheduling a retry can fail because we are not doing a retry if we had a valid and fresh time.
@glarsennordic

Suppose someone uses date_time_core_update_async half-way through the long interval, and the first attempt fails, then, to prevent upsetting the originally scheduled update, the retry will be cancelled.

We could split retry_count into retry_count and retry_count_manual, and similarly split reschedule_blocked, to allow manually triggered updates and their retries to completely not interfere with automatically scheduled updates (similar to how there are already two separate work items for the two update sources).

Or we can accept this as a limitation of using date_time_core_update_async. I'm down for either.

But as-written, retry schedule can fail

Ok, I'll need to create a test for this to see how it behaves.

Suppose someone uses date_time_core_update_async half-way through the long interval, and the first attempt fails, then, to prevent upsetting the originally scheduled update, the retry will be cancelled.

I have reverted this change and I still cannot make retry scheduling fail. It would require that
atomic_clear(&reschedule_blocked); was not called in date_time_update_work_fn but that always happen if we start an update whether it's a scheduled update or one triggered by date_time_core_update_async.

A log from unit tests with failing date_time_core_update_async update causing a retry to be scheduled (see test_date_time_update_cycle_with_failing_async):

[00:00:16.180,000] <dbg> date_time: date_time_core_register_handler: Registering handler 0x804bb1f [00:00:19.190,000] <dbg> date_time: date_time_update_work_fn: Updating date time UTC... [00:00:19.190,000] <dbg> date_time: date_time_core_current_check: Current date time too old [00:00:19.190,000] <dbg> date_time: date_time_update_work_fn: Getting time from cellular network [00:00:19.190,000] <dbg> date_time: date_time_modem_get: Time obtained from cellular network [00:00:19.190,000] <dbg> date_time: date_time_core_schedule_update: New periodic date time update in: 3 seconds [00:00:19.190,000] <dbg> date_time: date_time_core_store_tz: System time updated: 2024-01-30 20:40:52+12 [00:00:20.200,000] <dbg> date_time: date_time_core_update_async: Requesting date-time update asynchronously [00:00:20.200,000] <dbg> date_time: date_time_update_work_fn: Updating date time UTC... [00:00:20.200,000] <dbg> date_time: date_time_core_current_check: Current date time too old [00:00:20.200,000] <dbg> date_time: date_time_update_work_fn: Getting time from cellular network [00:00:20.200,000] <wrn> date_time: Did not get time from cellular network (error: -12). This may be normal as some cellular networks don't provide it or time may not be available yet. [00:00:20.200,000] <dbg> date_time: date_time_update_work_fn: Getting time from NTP server [00:00:20.200,000] <err> lte_lc: Could not get registration status, error: -12 [00:00:20.200,000] <wrn> date_time: Failed getting LTE network registration status, error: -14 [00:00:20.200,000] <dbg> date_time: date_time_ntp_get: Not connected to LTE, skipping NTP UTC time update [00:00:20.200,000] <dbg> date_time: date_time_update_work_fn: Did not get time from any time source [00:00:20.200,000] <dbg> date_time: date_time_core_schedule_retry: Date time update retry in: 1 seconds [00:00:21.210,000] <dbg> date_time: date_time_update_work_fn: Updating date time UTC... [00:00:21.210,000] <dbg> date_time: date_time_core_current_check: Current date time too old [00:00:21.210,000] <dbg> date_time: date_time_update_work_fn: Getting time from cellular network [00:00:21.210,000] <wrn> date_time: Did not get time from cellular network (error: -12). This may be normal as some cellular networks don't provide it or time may not be available yet. [00:00:21.210,000] <dbg> date_time: date_time_update_work_fn: Getting time from NTP server [00:00:21.210,000] <err> lte_lc: Could not get registration status, error: -12 [00:00:21.210,000] <wrn> date_time: Failed getting LTE network registration status, error: -14 [00:00:21.210,000] <dbg> date_time: date_time_ntp_get: Not connected to LTE, skipping NTP UTC time update [00:00:21.210,000] <dbg> date_time: date_time_update_work_fn: Did not get time from any time source [00:00:21.210,000] <dbg> date_time: date_time_core_schedule_retry: Date time update retry in: 1 seconds [00:00:22.220,000] <dbg> date_time: date_time_update_work_fn: Updating date time UTC... [00:00:22.220,000] <dbg> date_time: date_time_core_current_check: Current date time too old [00:00:22.220,000] <dbg> date_time: date_time_update_work_fn: Getting time from cellular network [00:00:22.220,000] <wrn> date_time: Did not get time from cellular network (error: -12). This may be normal as some cellular networks don't provide it or time may not be available yet. [00:00:22.220,000] <dbg> date_time: date_time_update_work_fn: Getting time from NTP server [00:00:22.220,000] <err> lte_lc: Could not get registration status, error: -12 [00:00:22.220,000] <wrn> date_time: Failed getting LTE network registration status, error: -14 [00:00:22.220,000] <dbg> date_time: date_time_ntp_get: Not connected to LTE, skipping NTP UTC time update [00:00:22.220,000] <dbg> date_time: date_time_update_work_fn: Did not get time from any time source [00:00:22.220,000] <dbg> date_time: date_time_core_schedule_update: New periodic date time update in: 3 seconds [00:00:25.230,000] <dbg> date_time: date_time_update_work_fn: Updating date time UTC... [00:00:25.230,000] <dbg> date_time: date_time_core_current_check: Current date time too old [00:00:25.230,000] <dbg> date_time: date_time_update_work_fn: Getting time from cellular network [00:00:25.230,000] <dbg> date_time: date_time_modem_get: Time obtained from cellular network [00:00:25.230,000] <dbg> date_time: date_time_core_schedule_update: New periodic date time update in: 3 seconds [00:00:25.230,000] <dbg> date_time: date_time_core_store_tz: System time updated: 2024-01-30 20:40:52+12 [00:00:25.230,000] <dbg> date_time: date_time_core_register_handler: Previously registered handler 0 de-registered src/main.c:727:test_date_time_update_cycle_with_failing_async:PASS

trantanen · 2024-09-25T10:10:09Z

tests/lib/date_time/src/main.c

+ /* TODO: The 2nd retry is already 4.5 due to async call. Is that intentional? */
+ test_date_time_cb_data[2].time_expected = 4500;


@glarsennordic, I think this is a bit of a flaw (if not a bug) that date_time_update_async() takes one retry cycle. We have configurations that there should be CONFIG_DATE_TIME_RETRY_COUNT=2 retries with CONFIG_DATE_TIME_RETRY_INTERVAL_SECONDS=1. If date_time_update_async() is called before all retries are done, it will be counted as one retry.
I'm not sure we need to add code to get around this but in that case I will document it in the code.

Yes, in fact retries cannot happen at all for date_time_update_async if it is called between regularly scheduled updates.

The fix for both issues unfortunately does require keeping two separate retry counters and two separate schedule blocking flags. One set for date_time_update_async and associated retries, and the other set for just normal updates

Or we can document this as a limitation. I'm fine with either, though admittedly you are right that this is not exactly the most intuitive behavior

Yes, in fact retries cannot happen at all for date_time_update_async if it is called between regularly scheduled updates.

This is actually something I didn't even think about. I'll think about it when I get back to this PR.

NordicBuilder · 2024-09-25T10:24:32Z

You can find the documentation preview for this PR at this link. It will be updated about 10 minutes after the documentation build succeeds.

Note: This comment is automatically posted by the Documentation Publishing GitHub Action.

NordicBuilder · 2024-09-25T16:51:00Z

CI Information

^{To view the history of this post, clich the 'edited' button above}
Build number: 7

Inputs:

Sources:

sdk-nrf: PR head: d30579f78180751a5d430d09e2d601c1a09d94d4

more details

sdk-nrf:

PR head: d30579f78180751a5d430d09e2d601c1a09d94d4
merge base: f456180510cc36c5c1bdceededf6bf6e3108f5c7
target head (main): 2c7add3b620b1256abf0508b22674c31c6d79366
Diff

Github labels

Enabled	Name	Description
	ci-disabled	Disable the ci execution
	ci-all-test	Run all of ci, no test spec filtering will be done
	ci-force-downstream	Force execution of downstream even if twister fails
	ci-run-twister	Force run twister
	ci-run-zephyr-twister	Force run zephyr twister

List of changed files detected by CI (5)

doc
│  ├── nrf
│  │  ├── libraries
│  │  │  ├── others
│  │  │  │  │ date_time.rst
lib
│  ├── date_time
│  │  ├── date_time_core.c
│  │  │ date_time_modem.c
tests
│  ├── lib
│  │  ├── date_time
│  │  │  ├── prj.conf
│  │  │  ├── src
│  │  │  │  │ main.c

Outputs:

Toolchain

Version: e6645c1dde
Build docker image: docker-dtr.nordicsemi.no/sw-production/ncs-build:e6645c1dde_81ed5a52d6

Test Spec & Results: ✅ Success; ❌ Failure; 🟠 Queued; 🟡 Progress; ◻️ Skipped; ⚠️ Quarantine

◻️ Toolchain - Skipped: existing toolchain is used
✅ Build twister
- sdk-nrf test count: 224
❌ Integration tests
- ✅ test-fw-nrfconnect-nrf-iot_cloud
- ❌ test-fw-nrfconnect-nrf-iot_serial_lte_modem
- ❌ test-fw-nrfconnect-nrf-iot_zephyr_lwm2m
- ✅ test-fw-nrfconnect-nrf-iot_thingy91
- ✅ test-fw-nrfconnect-nrf-iot_mosh
- ✅ test-fw-nrfconnect-nrf-iot_positioning

Disabled integration tests

- desktop52_verification
- doc-internal
- test_ble_nrf_config
- test-fw-nrfconnect-apps
- test-fw-nrfconnect-ble_mesh
- test-fw-nrfconnect-ble_samples
- test-fw-nrfconnect-boot
- test-fw-nrfconnect-chip
- test-fw-nrfconnect-fem
- test-fw-nrfconnect-nfc
- test-fw-nrfconnect-nrf-iot_libmodem-nrf
- test-fw-nrfconnect-nrf-iot_lwm2m
- test-fw-nrfconnect-nrf-iot_nrf_provisioning
- test-fw-nrfconnect-nrf-iot_samples
- test-fw-nrfconnect-nrf_crypto
- test-fw-nrfconnect-proprietary_esb
- test-fw-nrfconnect-ps
- test-fw-nrfconnect-rpc
- test-fw-nrfconnect-rs
- test-fw-nrfconnect-tfm
- test-fw-nrfconnect-thread
- test-fw-nrfconnect-zigbee
- test-low-level
- test-sdk-audio
- test-sdk-dfu
- test-sdk-find-my
- test-sdk-mcuboot
- test-sdk-pmic-samples
- test-sdk-sidewalk
- test-sdk-wifi
- test-secdom-samples-public

Note: This message is automatically posted and updated by the CI

Adding tests for scheduled date-time updates verifying that they occur at configured intervals. Some small clean-up and additional logging into date-time library. Branch coverage is going from ~44% to ~98% having 3 branches untested. These are related to failure of clock_gettime/clock_settime which cannot really be achieved without creating a different test set and mocking those APIs. With default configuration, the tests run almost 30s due to update intervals that we need to wait. Jira: NCSDK-28887 Signed-off-by: Tommi Rantanen <tommi.rantanen@nordicsemi.no>

Signed-off-by: Tommi Rantanen <tommi.rantanen@nordicsemi.no>

peknis · 2024-10-09T05:43:26Z

doc/nrf/libraries/others/date_time.rst

+ Exceptions to the regular date-time update interval set by the :kconfig:option:`CONFIG_DATE_TIME_UPDATE_INTERVAL_SECONDS` Kconfig option occur when
+ the :c:func:`date_time_update_async` function is called and a new date-time update is triggered and scheduled.
+ Either retry or regular update interval is used depending on the outcome of the date-time update procedure.
+ Date-time update from modem through AT%XTIME notification will not disturb regular update interval.


Suggested change

Date-time update from modem through AT%XTIME notification will not disturb regular update interval.

Date-time update from modem through an ``AT%XTIME`` notification does not disturb the regular update interval.

github-actions bot added the changelog-entry-required Update changelog before merge. Remove label if entry is not needed or already added. label Sep 25, 2024

trantanen commented Sep 25, 2024

View reviewed changes

trantanen force-pushed the date_time_more_tests branch 3 times, most recently from 7e98397 to 0327cf4 Compare October 7, 2024 03:44

trantanen added this to the 2.8.0 milestone Oct 7, 2024

trantanen force-pushed the date_time_more_tests branch 2 times, most recently from ab2e91c to 7405754 Compare October 9, 2024 05:19

github-actions bot added the doc-required PR must not be merged without tech writer approval. label Oct 9, 2024

trantanen added 2 commits October 9, 2024 08:21

Revert date_time_core_schedule_work return value check for retry

d30579f

Signed-off-by: Tommi Rantanen <tommi.rantanen@nordicsemi.no>

trantanen force-pushed the date_time_more_tests branch from 7405754 to d30579f Compare October 9, 2024 05:21

trantanen marked this pull request as ready for review October 9, 2024 05:22

trantanen requested review from tokangas and a team as code owners October 9, 2024 05:22

peknis requested changes Oct 9, 2024

View reviewed changes

tokangas approved these changes Oct 9, 2024

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

tests: lib: date_time: Tests for scheduled updates #17477

tests: lib: date_time: Tests for scheduled updates #17477

trantanen commented Sep 25, 2024 •

edited

Loading

trantanen Sep 25, 2024

glarsennordic Sep 25, 2024

trantanen Sep 26, 2024

trantanen Oct 9, 2024

trantanen Sep 25, 2024

glarsennordic Sep 25, 2024 •

edited

Loading

trantanen Sep 26, 2024

NordicBuilder commented Sep 25, 2024

NordicBuilder commented Sep 25, 2024 •

edited

Loading

peknis Oct 9, 2024

		/* TODO: The 2nd retry is already 4.5 due to async call. Is that intentional? */
		test_date_time_cb_data[2].time_expected = 4500;

	Date-time update from modem through AT%XTIME notification will not disturb regular update interval.
	Date-time update from modem through an ``AT%XTIME`` notification does not disturb the regular update interval.

tests: lib: date_time: Tests for scheduled updates #17477

Are you sure you want to change the base?

tests: lib: date_time: Tests for scheduled updates #17477

Conversation

trantanen commented Sep 25, 2024 • edited Loading

trantanen Sep 25, 2024

Choose a reason for hiding this comment

glarsennordic Sep 25, 2024

Choose a reason for hiding this comment

trantanen Sep 26, 2024

Choose a reason for hiding this comment

trantanen Oct 9, 2024

Choose a reason for hiding this comment

trantanen Sep 25, 2024

Choose a reason for hiding this comment

glarsennordic Sep 25, 2024 • edited Loading

Choose a reason for hiding this comment

trantanen Sep 26, 2024

Choose a reason for hiding this comment

NordicBuilder commented Sep 25, 2024

NordicBuilder commented Sep 25, 2024 • edited Loading

CI Information

Inputs:

Sources:

Github labels

Outputs:

Toolchain

Test Spec & Results: ✅ Success; ❌ Failure; 🟠 Queued; 🟡 Progress; ◻️ Skipped; ⚠️ Quarantine

peknis Oct 9, 2024

Choose a reason for hiding this comment

trantanen commented Sep 25, 2024 •

edited

Loading

glarsennordic Sep 25, 2024 •

edited

Loading

NordicBuilder commented Sep 25, 2024 •

edited

Loading