addClockEvent not reliably firing

[ostat]

Describe the bug While testing some automated lighting using the autoexec.bat file, I was getting inconsistent results relating to the clockevents. The events were meant to trigger lighting changes however they events appeared not to fire. Below is a simpler example.

Firmware:

• Version 1.17.11
• Chip/model: BK7231T

To Reproduce Steps to reproduce the behavior:

1. create autoexec.bat
2. add script below
3. Adjust times to appropriate values for testing
4. Confirm in logs if all events are fired.

startDriver ntp
ntp_timeZoneOfs 10:00

addRepeatingEvent 2 -1 echo stat: failedBoots $failedBoots, uptime $uptime, NTPOn $NTPOn, time $day $hour $minute $second

waitFor NTPState 1

addClockEvent 22:49:55 0xff 4 backlog led_dimmer 50; echo test event for 4
addClockEvent 22:50 0xff 5 backlog led_dimmer 75; echo test event for 5
addClockEvent 22:50:05 0xff 6 backlog led_dimmer 100; echo test event for 6

my output

Info:CMD:stat: failedBoots 1, uptime 94, NTPOn 1, time 4 22 49 50 Info:CMD:stat: failedBoots 1, uptime 100, NTPOn 1, time 4 22 49 56 Info:CMD:stat: failedBoots 1, uptime 104, NTPOn 1, time 4 22 50 0 Info:CMD:stat: failedBoots 1, uptime 106, NTPOn 1, time 4 22 50 2 Info:CMD:stat: failedBoots 1, uptime 108, NTPOn 1, time 4 22 50 4 Info:CMD:test event for 6 Info:CMD:stat: failedBoots 1, uptime 110, NTPOn 1, time 4 22 50 6 Info:CMD:stat: failedBoots 1, uptime 112, NTPOn 1, time 4 22 50 8

[openshwprojects]

Thank you for reporting problem, I have checked and I found so far one issue with the system:

In case of no seconds value specified, the random garbage value got into the second variable, giving you 60/256 chance of it working properly.

A fix (along with self test) has been added: https://github.com/openshwprojects/OpenBK7231T_App/commit/2bd4bff5bad1ec911c73e908e9abd94995c434c2

Can you recheck, is there still any other issue?

[DeDaMrAzR]

Build 1.17.14 BK7231T device

[ostat]

I am still testing, I can see it working for the hh:mm so that appears fixed thanks. But I was getting some inconsistent results, so want to see if it is repeatable.

Reading the NTP_RunEvents code, I wonder if it is as intended. ntp_eventsTime is the previous trigger time, and the i for the delta loop starts at 0. So the first loop will run for the previous trigger time, then all the way up to 1 second before the newTime. NTP_RunEvents is always running 1 second behind, I guess it does not matter as long as NTP_RunEvents keeps being called?

    if (ntp_events) {
        // NTP resynchronization could cause us to skip some seconds in some rare cases?
        delta = newTime - ntp_eventsTime;
        // a large shift in time is not expected, so limit to a constant number of seconds
        if (delta > 100)
            delta = 100;
        for (i = 0; i < delta; i++) {
            NTP_RunEventsForSecond(ntp_eventsTime + i);
        }
    }
    ntp_eventsTime = newTime;

Bit of an aside do you know why this might appear in the logs? Error:CMD:cmd Status NOT found (args 0)?

[ostat]

@openshwprojects, did you have thoughts on the above comment regarding the loop being off by a second.

Otherwise I think this can be closed, your fix has resolved the issues. Thanks