CRON bug just started

General
1

If you are asking a question, please follow this template:

  1. My goal is: Fix a cron rescheduling bug
  2. My actions are: Boot up a device that has worked for months
  3. The result I see is: After SNTP, the cron job is rescheduled with results in a loop
  4. 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

2

RESOLVED: This line in mos.yml killed our fleet:

  • [“sys.tz_spec”, “s”, “EST5EDT4,M4.1.0/02:00:00,M10.5.0/02:00:00”, {title: “See formats for the TZ env var: “man tzset”. Formats like “:/path/to/file” are not supported”}]

DO NOT USE sys.tz_spec!