micros() behaves strangely after sntp finishes.

[jordansissel]

Code:

void beep(void *arg) {
  LOG(LL_INFO, ("mg_time: %lf", mg_time()));
  LOG(LL_INFO, ("micros: %lu", micros()));
  (void) arg;
}

enum mgos_app_init_result mgos_app_init(void) {
  mgos_set_timer(1000, true, beep, NULL);
  
  return MGOS_APP_INIT_SUCCESS;
}

Console before/after sntp:

[Sep  6 21:38:18.698] beep                 mg_time: 1.341552
[Sep  6 21:38:18.704] beep                 micros: 1346312
[Sep  6 21:38:19.698] beep                 mg_time: 2.341633
[Sep  6 21:38:19.704] beep                 micros: 2346268
[Sep  6 21:38:20.715] dhcp client start...
[Sep  6 21:38:20.716] mgos_net_on_change_c WiFi STA: connected
[Sep  6 21:38:21.588] ip:192.168.1.161,mask:255.255.255.0,gw:192.168.1.1
[Sep  6 21:38:21.594] mgos_net_on_change_c WiFi STA: ready, IP 192.168.1.161, GW 192.168.1.1, DNS 192.168.1.1
[Sep  6 21:38:21.697] beep                 mg_time: 4.340778
[Sep  6 21:38:21.702] beep                 micros: 4345307
[Sep  6 21:38:22.591] mgos_sntp_query      SNTP query to pool.ntp.org
[Sep  6 21:38:22.595] mongoose_poll        New heap free LWM: 44872
[Sep  6 21:38:22.606] mongoose_poll        New heap free LWM: 42744
[Sep  6 21:38:22.627] mongoose_poll        New heap free LWM: 42608
[Sep  6 21:38:22.697] beep                 mg_time: 5.341536
[Sep  6 21:38:22.701] beep                 micros: 5345951
[Sep  6 21:38:22.715] mgos_sntp_ev         SNTP reply from 192.111.144.114: time 1504759101.576770, local 5.358226, delta 1504759096.218544
[Sep  6 21:38:23.710] beep                 mg_time: 1504759102.560543
[Sep  6 21:38:23.714] beep                 micros: 4294967295
[Sep  6 21:38:24.709] beep                 mg_time: 1504759103.559169
[Sep  6 21:38:24.716] beep                 micros: 4294967295
[Sep  6 21:38:25.710] beep                 mg_time: 1504759104.559839
[Sep  6 21:38:25.715] beep                 micros: 4294967295
[Sep  6 21:38:26.709] beep                 mg_time: 1504759105.559733

After SNTP, micros() starts returning 4294967295 (2^32 - 1) for all calls.

micros() is based on mg_time() which returns a double and reports wall clock (it is not monotonic).

The Arduino docs say this about micros():

Returns the number of microseconds since the Arduino board began running the current program

Should mongoose's Arduino compat, then, use the boot-time (monotonic?) clock instead of the wall clock (sync'd with sntp)?

[jordansissel]

Context on how I encountered this:

Adafruit's Neopixel library has a 'send' method that waits/blocks if the previous send was too-recently. This wait relies on micros() for duration computation. Because micros() becomes stuck at max_unsigned_int after sntp runs, the micros() clock never moves, and the next Neopixel send() will get stuck and trigger the watchdog.

[jordansissel]

I am working around this by commenting out the while (!canSend()) call which skips the busy wait