Hello.
I am developing using nRF5340DK and nRF Connect SDK v2.9.0.
I am checking the operation of "Scheduler Server".
The action was executed, and the date and time are correct.
However, it was executed many times, not just once.
Extract my log.
- Receive "Scheduler Action Set"
Turn off lights at 10:55:00AM every day.
Target uptime: 329954. Current uptime: 99680.[00:01:39.680,175] <dbg> bt_mesh_scheduler_srv: action_set: Rx: scheduler server action index 0 set, ack 1 [00:01:39.680,267] <dbg> bt_mesh_scheduler_srv: schedule_action: Current uptime 99680 [00:01:39.680,267] <dbg> bt_mesh_scheduler_srv: schedule_action: Current time: [00:01:39.680,267] <dbg> bt_mesh_scheduler_srv: schedule_action: year: 124 [00:01:39.680,297] <dbg> bt_mesh_scheduler_srv: schedule_action: month: 11 [00:01:39.680,297] <dbg> bt_mesh_scheduler_srv: schedule_action: day: 25 [00:01:39.680,328] <dbg> bt_mesh_scheduler_srv: schedule_action: hour: 10 [00:01:39.680,328] <dbg> bt_mesh_scheduler_srv: schedule_action: minute: 51 [00:01:39.680,328] <dbg> bt_mesh_scheduler_srv: schedule_action: second: 9 [00:01:39.680,419] <dbg> bt_mesh_scheduler_srv: schedule_action: Scheduled time: [00:01:39.680,450] <dbg> bt_mesh_scheduler_srv: schedule_action: year: 124 [00:01:39.680,450] <dbg> bt_mesh_scheduler_srv: schedule_action: month: 11 [00:01:39.680,480] <dbg> bt_mesh_scheduler_srv: schedule_action: day: 25 [00:01:39.680,480] <dbg> bt_mesh_scheduler_srv: schedule_action: hour: 10 [00:01:39.680,511] <dbg> bt_mesh_scheduler_srv: schedule_action: minute: 55 [00:01:39.680,511] <dbg> bt_mesh_scheduler_srv: schedule_action: second: 0 [00:01:39.680,572] <dbg> bt_mesh_scheduler_srv: run_scheduler: Scheduler started. Target uptime: 329954. Current uptime: 99680. [00:01:39.696,289] <dbg> bt_mesh_scheduler_srv: encode_action_status: Tx: scheduler server action status: [00:01:39.696,289] <dbg> bt_mesh_scheduler_srv: encode_action_status: index: 0 [00:01:39.696,319] <dbg> bt_mesh_scheduler_srv: encode_action_status: year: 100 [00:01:39.696,319] <dbg> bt_mesh_scheduler_srv: encode_action_status: month: 0xfff [00:01:39.696,350] <dbg> bt_mesh_scheduler_srv: encode_action_status: day: 0 [00:01:39.696,350] <dbg> bt_mesh_scheduler_srv: encode_action_status: wday: 0x7f [00:01:39.696,380] <dbg> bt_mesh_scheduler_srv: encode_action_status: hour: 10 [00:01:39.696,380] <dbg> bt_mesh_scheduler_srv: encode_action_status: minute: 55 [00:01:39.696,380] <dbg> bt_mesh_scheduler_srv: encode_action_status: second: 0 [00:01:39.696,411] <dbg> bt_mesh_scheduler_srv: encode_action_status: action: 0 [00:01:39.696,411] <dbg> bt_mesh_scheduler_srv: encode_action_status: transition: 0 [00:01:39.696,441] <dbg> bt_mesh_scheduler_srv: encode_action_status: scene: 0 [00:01:39.696,441] <dbg> bt_mesh_scheduler_srv: encode_action_status: Tx: scheduler server action status: [00:01:39.696,472] <dbg> bt_mesh_scheduler_srv: encode_action_status: index: 0 [00:01:39.696,472] <dbg> bt_mesh_scheduler_srv: encode_action_status: year: 100 [00:01:39.696,472] <dbg> bt_mesh_scheduler_srv: encode_action_status: month: 0xfff [00:01:39.696,502] <dbg> bt_mesh_scheduler_srv: encode_action_status: day: 0 [00:01:39.696,502] <dbg> bt_mesh_scheduler_srv: encode_action_status: wday: 0x7f [00:01:39.696,533] <dbg> bt_mesh_scheduler_srv: encode_action_status: hour: 10 [00:01:39.696,533] <dbg> bt_mesh_scheduler_srv: encode_action_status: minute: 55 [00:01:39.696,563] <dbg> bt_mesh_scheduler_srv: encode_action_status: second: 0 [00:01:39.696,563] <dbg> bt_mesh_scheduler_srv: encode_action_status: action: 0 [00:01:39.696,563] <dbg> bt_mesh_scheduler_srv: encode_action_status: transition: 0 [00:01:39.696,594] <dbg> bt_mesh_scheduler_srv: encode_action_status: scene: 0
- 1st Execution
Target uptime: 329954. Current uptime: 330498.
(CONFIG_LOG_BUFFER_SIZE is at maximum but some messages dropped.)[00:05:30.497,985] <dbg> bt_mesh_scheduler_srv: schedule_action: hour: 10 --- 9999 messages dropped --- [00:05:30.498,016] <dbg> bt_mesh_scheduler_srv: schedule_action: minute: 55 [00:05:30.498,016] <dbg> bt_mesh_scheduler_srv: schedule_action: second: 0 [00:05:30.498,107] <dbg> bt_mesh_scheduler_srv: run_scheduler: Scheduler started. Target uptime: 329954. Current uptime: 330498.
- 2nd Execution
Target uptime: 329954. Current uptime: 330498.[00:05:30.498,229] <dbg> bt_mesh_scheduler_srv: scheduled_action_handle: Scheduler action fired: 0 [00:05:30.498,291] <dbg> bt_mesh_scheduler_srv: scheduled_action_handle: Onoff srv addr: 163 set: 0 [00:05:30.498,382] <dbg> bt_mesh_scheduler_srv: scheduled_action_handle: Onoff srv addr: 164 set: 0 [00:05:30.498,413] <dbg> bt_mesh_scheduler_srv: scheduled_action_handle: Onoff srv addr: 165 set: 0 [00:05:30.498,504] <dbg> bt_mesh_scheduler_srv: schedule_action: Current uptime 330498 [00:05:30.498,504] <dbg> bt_mesh_scheduler_srv: schedule_action: Current time: [00:05:30.498,535] <dbg> bt_mesh_scheduler_srv: schedule_action: year: 124 [00:05:30.498,565] <dbg> bt_mesh_scheduler_srv: schedule_action: month: 11 [00:05:30.498,565] <dbg> bt_mesh_scheduler_srv: schedule_action: day: 25 [00:05:30.498,596] <dbg> bt_mesh_scheduler_srv: schedule_action: hour: 10 [00:05:30.498,626] <dbg> bt_mesh_scheduler_srv: schedule_action: minute: 54 [00:05:30.498,657] <dbg> bt_mesh_scheduler_srv: schedule_action: second: 59 [00:05:30.498,748] <dbg> bt_mesh_scheduler_srv: schedule_action: Scheduled time: [00:05:30.498,779] <dbg> bt_mesh_scheduler_srv: schedule_action: year: 124 [00:05:30.498,779] <dbg> bt_mesh_scheduler_srv: schedule_action: month: 11 [00:05:30.498,809] <dbg> bt_mesh_scheduler_srv: schedule_action: day: 25 [00:05:30.498,840] <dbg> bt_mesh_scheduler_srv: schedule_action: hour: 10 [00:05:30.498,870] <dbg> bt_mesh_scheduler_srv: schedule_action: minute: 55 [00:05:30.498,901] <dbg> bt_mesh_scheduler_srv: schedule_action: second: 0 [00:05:30.498,962] <dbg> bt_mesh_scheduler_srv: run_scheduler: Scheduler started. Target uptime: 329954. Current uptime: 330498.
- Last Execution
Target uptime: 86729954. Current uptime: 330580.[00:05:30.579,406] <dbg> bt_mesh_scheduler_srv: scheduled_action_handle: Scheduler action fired: 0 [00:05:30.579,437] <dbg> bt_mesh_scheduler_srv: scheduled_action_handle: Onoff srv addr: 163 set: 0 [00:05:30.579,498] <dbg> bt_mesh_scheduler_srv: scheduled_action_handle: Onoff srv addr: 164 set: 0 [00:05:30.579,559] <dbg> bt_mesh_scheduler_srv: scheduled_action_handle: Onoff srv addr: 165 set: 0 [00:05:30.579,650] <dbg> bt_mesh_scheduler_srv: schedule_action: Current uptime 330579 [00:05:30.579,650] <dbg> bt_mesh_scheduler_srv: schedule_action: Current time: [00:05:30.579,681] <dbg> bt_mesh_scheduler_srv: schedule_action: year: 124 [00:05:30.579,711] <dbg> bt_mesh_scheduler_srv: schedule_action: month: 11 [00:05:30.579,742] <dbg> bt_mesh_scheduler_srv: schedule_action: day: 25 [00:05:30.579,742] <dbg> bt_mesh_scheduler_srv: schedule_action: hour: 10 [00:05:30.579,772] <dbg> bt_mesh_scheduler_srv: schedule_action: minute: 55 [00:05:30.579,803] <dbg> bt_mesh_scheduler_srv: schedule_action: second: 0 [00:05:30.579,925] <dbg> bt_mesh_scheduler_srv: schedule_action: Scheduled time: [00:05:30.579,956] <dbg> bt_mesh_scheduler_srv: schedule_action: year: 124 [00:05:30.579,986] <dbg> bt_mesh_scheduler_srv: schedule_action: month: 11 [00:05:30.579,986] <dbg> bt_mesh_scheduler_srv: schedule_action: day: 26 [00:05:30.580,017] <dbg> bt_mesh_scheduler_srv: schedule_action: hour: 10 [00:05:30.580,047] <dbg> bt_mesh_scheduler_srv: schedule_action: minute: 55 [00:05:30.580,078] <dbg> bt_mesh_scheduler_srv: schedule_action: second: 0 [00:05:30.580,169] <dbg> bt_mesh_scheduler_srv: run_scheduler: Scheduler started. Target uptime: 86729954. Current uptime: 330580.
During the first execution, "Current uptime" exceeded "Target uptime".
Also, "Current uptime" was converted to 10:54:59AM instead of 10:55:00AM.
As a result, "scheduled_action_handle()" was executed immediately.
This continued until "Current uptime" was converted to 10:55:00AM.
What could be the cause of this discrepancy in "Current uptime"(k_uptime_get())?
scheduler_srv.c
static void run_scheduler(struct bt_mesh_scheduler_srv *srv)
{
struct tm sched_time;
int64_t current_uptime = k_uptime_get();
uint8_t planned_idx = get_least_time_index(srv);
if (planned_idx == BT_MESH_SCHEDULER_ACTION_ENTRY_COUNT) {
return;
}
tai_to_ts(&srv->sched_tai[planned_idx], &sched_time);
int64_t scheduled_uptime = bt_mesh_time_srv_mktime(srv->time_srv,
&sched_time);
if (scheduled_uptime < 0) {
LOG_WRN("Scheduler not started. Error: %lld.", scheduled_uptime);
return;
}
srv->idx = planned_idx;
k_work_reschedule(&srv->delayed_work,
K_MSEC(MAX(scheduled_uptime - current_uptime, 0)));
LOG_DBG("Scheduler started. Target uptime: %lld. Current uptime: %lld.",
scheduled_uptime, current_uptime);
}
This is my full log.
241225_scheduler_105500.log
Thanks for reading.