If you are asking a question, please follow this template:
- My goal is: Fix a cron rescheduling bug
- My actions are: Boot up a device that has worked for months
- The result I see is: After SNTP, the cron job is rescheduled with results in a loop
- My expectation & question is: Raising the alarm about a potential massive bug
I have hundred of devices in the field that began looping like this last night. All use MOS cron lib. If I disable the cron job, the device boots fine. So I think there is a huge bug in cron job rescheduling code.
My log:
[Apr 4 11:30:22.316] mgos_mqtt_conn.c:223 MQTT0 event: 204
[Apr 4 11:30:22.316] mgos_mqtt_conn.c:165 MQTT0 ack 2
[Apr 4 11:30:23.818] mg_net.c:911 0x3ffb52bc udp://time.google.com:123 -,-,-
[Apr 4 11:30:23.824] mg_net.c:911 0x3ffb58c0 udp://8.8.8.8:53 -,-,-
[Apr 4 11:30:23.829] mg_net.c:779 0x3ffb58c0 udp://8.8.8.8:53
[Apr 4 11:30:23.835] mgos_sntp.c:95 SNTP query to time.google.com
[Apr 4 11:30:23.835] mgos_sntp.c:127 SNTP next query in 8168 ms
[Apr 4 11:30:23.841] mg_net.c:794 0x3ffb58c0 udp://8.8.8.8:53 -> 0
[Apr 4 11:30:24.204] mg_net.c:779 0x3ffb52bc udp://216.239.35.12:123
[Apr 4 11:30:24.204] mg_net.c:794 0x3ffb52bc udp://216.239.35.12:123 -> 0
[Apr 4 11:30:24.209] mgos_sntp.c:48 SNTP sent query to 216.239.35.12
[Apr 4 11:30:24.523] mgos_sntp.c:59 SNTP reply from 216.239.35.12: time 1586014225.271883, local 20.911577, delta 1586014204.360306
[Apr 4 11:30:24.528] mgos_event.c:135 ev MOS3 triggered 3 handlers
[Apr 4 11:30:24.534] mgos_sntp.c:78 SNTP close
[Apr 4 11:30:24.540] mgos_sntp.c:127 SNTP next query in 6942010 ms
[Apr 4 11:30:24.547] mg_mqtt.c:184 Send PINGREQ
[Apr 4 11:30:24.547] mgos_cron.c:727 Rescheduling cron job 0x3ffc771c after time change
[Apr 4 11:30:24.558] mgos_cron.c:231 Next invocation: 1585990800 [2020/04/04 09:00:00 UTC]
[Apr 4 11:30:24.564] mgos_cron.c:404 (after -23425 seconds)
[Apr 4 11:30:24.569] mgos_cron.c:231 Next invocation: 1585990800 [2020/04/04 09:00:00 UTC]
[Apr 4 11:30:24.575] mgos_cron.c:404 (after -23425 seconds)
[Apr 4 11:30:24.581] mgos_cron.c:231 Next invocation: 1585990800 [2020/04/04 09:00:00 UTC]
[Apr 4 11:30:24.586] mgos_cron.c:404 (after -23425 seconds)
[Apr 4 11:30:24.592] mgos_cron.c:231 Next invocation: 1585990800 [2020/04/04 09:00:00 UTC]
[Apr 4 11:30:24.599] mgos_cron.c:404 (after -23425 seconds)
[Apr 4 11:30:24.603] mgos_cron.c:231 Next invocation: 1585990800 [2020/04/04 09:00:00 UTC]
[Apr 4 11:30:24.609] mgos_cron.c:404 (after -23425 seconds)
[Apr 4 11:30:24.615] mgos_cron.c:231 Next invocation: 1585990800 [2020/04/04 09:00:00 UTC]
[Apr 4 11:30:24.621] mgos_cron.c:404 (after -23425 seconds)
…loop forever