Klok op hol

[thekr1s]

After upgrading esp-open-rtos, the clock runs wild. Continuously switching time to a random time.

[Rutger798]

Ik hoopte dat de stack vergroting het zou oplossen maar ik heb het nog een keer gezien, Gezien de links boven de led rood brand tijdens het flippen lijkt het me iets wifi/sntp gerelateerd.

[thekr1s]

Dit is inderdaad sntp. SNTP stelt de clock rate in. Ik vermoed dat door omstandigheden deze clock rate helemaal fout kom te staat en de tijd als een dolle voortschreidt.

in sntp_update_rtc() in sntp_fun.c wordt onderstaande aangeroepen.
cal = sdk_system_rtc_clock_cali_proc();

mijn vermoeden gaat naar die hoek. Maar het reproduceert zo moeilijk. Debuggen lastig.
Zat wel te denken of het te detecteren is in sw. vermoedelijk wel

[thekr1s]

Mogelijke workaround:
Detecteer in sntp_client.c ron regel 65 dat _rtcTicsPerSec een absurde waarde heeft. Of vraag tijd op via time() en zie dat het niet klopt met de 5 sec wachttijd.
Als fout, dan sntp_stop() en opnieuw sntp_init() aanroepen.

[Rutger798]

Ik ga dan daaromheen wat meer logging toevoegen en dan een Klok aan mn werk PC koppelen zodat ik hopelijk kan gaan zien wat er mis is, Dan maakt ik de workaround er in om te detecteren dat het mis gaat
Ik zie het namelijk zelf echt maar 1 keer per week ofzo....

[Rutger798]

In de onderstaande log is te zien dat de tijd terug loopt gezien TSdiff een negatieve waarde heeft, Normaal zou dit 1 moeten zijn gezien de TSdiff elke seconde wordt uitgelezen.
Het probleem zit hem dus in het wrappen van de RTC counter

*15-04 14:39:21*SNTP RTC adjust: 0.004 s; 265.692 ppm over 15.066 s; cal: 25540 *15-04 14:39:34*Time: Tue Apr 14 22:46:27 2020 TSdiff: -53587 diff: 160245/160214, _rtcTimePerSec: 160245 *15-04 14:39:35*SNTP RTC counter wrappedSNTP RTC counter wrappedSNTP RTC counter wrappedSNTP RTC counter wrappedSNTP RTC counter wrappedSNTP RTC counter wrappedSNTP RTC counter wrappedSNTP RTC counter wrappedERROR RHU1 *15-04 14:39:35*Time: Sun Apr 12 11:13:53 2020 TSdiff: -187559 diff: 160156/160245, _rtcTimePerSec: 160156 *15-04 14:39:36*SNTP RTC counter wrappedSNTP RTC counter wrappedSNTP RTC counter wrappedSNTP RTC counter wrappedSNTP RTC counter wrappedSNTP RTC counter wrappedSNTP RTC counter wrappedSNTP RTC adjust: 455502.463 s; 30256393037.520 ppm over 15.055 s; cal: 25553 *15-04 14:39:36*Time: Wed Apr 15 13:39:37 2020 TSdiff: 294738 diff: 159653/160156, _rtcTimePerSec: 159653 *15-04 14:39:51*SNTP RTC adjust: 0.005 s; 349.005 ppm over 15.049 s; cal: 25546 *15-04 14:40:06*SNTP RTC adjust: -0.004 s; -291.821 ppm over 15.067 s; cal: 25554

[thekr1s]

Ik kan je conclusie niet volgen, ik weet ook niet wat die TSdiff is.
Ik heb het idee dat de calibratie niet goed gaat waardoor de timer als een dolle loopt. Omdat hij zo snel loopt, wrapt de timer ook snel. Daardoor wordt TSdiff negatief. Is niet zo dat de klok terud loopt. En dat wrappen is m.i. een gevolg en niet de oorzaak...

[Rutger798]

Het was ook meer mn eigen naslag werk,
maar TSdiff is de timestamp diff van time(NULL) voor de delay en time(NULL) na de delay

de SNTP RTC counter wrapped zou je maar 1 keer moeten zien omdat de counter in de zelfde functie uit zn wrapping wordt gehaald.

Nadat ik een ik de pull request van SuperHouse/esp-open-rtos#148 werkend heb gekregen heb ik het niet meer gezien.

[Rutger798]

Created a pull request to the SuperHouse git repo,
SuperHouse/esp-open-rtos#744

But for now its fixed in a fork from SuperHouse repo