"scheduled_action_handle()" is executed many times

[a.da]

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.

1. 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

2. 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.

3. 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.

4. 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.

[Hung Bui]

Hi A.da,

I'm not so familiar with the mesh scheduler server so you may need to explain the issue a little bit more clear. 
Was the problem showed in the first log that "scheduler server action status" is executed 2 times  ? 

Could you tell me how to reproduce the issue ? Which sample you based your test on ? 

[a.da]

Hi Hung, thanks for your reply.

Was the problem showed in the first log that "scheduler server action status" is executed 2 times  ?

I don't think executing it twice is a problem. It is because there are cases where "send_scheduler_action_status()" may be called twice when receiving a "Scheduler Action Set".
The first log was quoted to show the value of ”Current uptime” when receiving the "Scheduler Action Set".
scheduler_srv.c

static int action_set(const struct bt_mesh_model *model, struct bt_mesh_msg_ctx *ctx,
		      struct net_buf_simple *buf, bool ack)
{
	struct bt_mesh_scheduler_srv *srv = model->rt->user_data;
	uint8_t idx;
	struct bt_mesh_schedule_entry tmp = { 0 };

	scheduler_action_unpack(buf, &idx, &tmp);

	if (!scheduler_action_valid(&tmp, idx)) {
		return -EINVAL;
	}

	srv->sch_reg[idx] = tmp;
	LOG_DBG("Rx: scheduler server action index %d set, ack %d", idx, ack);

	if (srv->sch_reg[idx].action < BT_MESH_SCHEDULER_SCENE_RECALL ||
	   (srv->sch_reg[idx].action == BT_MESH_SCHEDULER_SCENE_RECALL &&
	    srv->sch_reg[idx].scene_number != 0)) {
		schedule_action(srv, idx);
		run_scheduler(srv);
	}

	if (srv->action_set_cb) {
		srv->action_set_cb(srv, ctx, idx, &srv->sch_reg[idx]);
	}

	if (IS_ENABLED(CONFIG_BT_SETTINGS)) {
		store(srv, idx, is_entry_defined(srv, idx));
	}

	if (is_entry_defined(srv, idx)) {
		/* publish state changing */
		send_scheduler_action_status(model, NULL, idx, false);
	}

	if (ack) { /* reply on the action set command */
		send_scheduler_action_status(model, ctx, idx, false);
	}

	return 0;
}

The Scheduler Server will delay the work by the difference between "Target uptime" and "Current uptime".
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);
}

However, when the work resumes, it seems to be behaving abnormally for the following reasons.

• "Current uptime" exceeded "Target uptime".
• "Current uptime" was converted to 10:54:59AM instead of 10:55:00AM.

Could you tell me how to reproduce the issue ? Which sample you based your test on ? 

We are developing based on the Light fixture. We have added components such as the Scheduler Server and Time Server to the sample.
However, the smartphone app is developed in-house, and testing of the Scheduler Server cannot be performed within nRF Mesh App.

Is there anything else you need?

a.da