Timesync is called with every remotecommand on port 2

[ChrSchultz]

If I send any command on port2 , causes each time a timesync call

TIMESYNC_LORASERVER 1
TIMESYN_INTERVAL 60
LoRaServer 1.3 RedNode RaspberryPI 3

[cyberman54]

Is this issue for code in master, or for development branch?

[cyberman54]

Yes, i can reproduce this with code in dev branch, will take a closer look to this later.

20:08:18.080 > [I][lorawan.cpp:81] lora_setupForNetwork(): RSSI: 14 | SNR: 7
20:08:18.080 > [I][lorawan.cpp:85] lora_setupForNetwork(): Radio parameters: SF7 | BW125 | CR 4/5
20:08:18.080 > [I][lorawan.cpp:266] lora_send(): 1 byte(s) sent to LORA
20:08:19.964 > [I][lorawan.cpp:509] myRxCallback(): Received 6 byte(s) of payload on port 9
20:08:22.182 > [I][timekeeper.cpp:89] setMyTime(): [26.813] UTC time: 1601921303.356 sec
20:08:22.831 > [I][lorawan.cpp:266] lora_send(): 1 byte(s) sent to LORA
20:08:22.831 > [I][power.cpp:106] AXP192_showstatus(): No Battery
20:08:37.982 > [I][power.cpp:110] AXP192_showstatus(): USB powered, 697mW
20:08:37.982 > [I][power.cpp:106] AXP192_showstatus(): No Battery        
20:09:07.988 > [I][power.cpp:110] AXP192_showstatus(): USB powered, 706mW
20:09:07.988 > [I][lorawan.cpp:266] lora_send(): 0 byte(s) sent to LORA  
20:09:07.988 > [I][lorawan.cpp:509] myRxCallback(): Received 2 byte(s) of payload on port 2
20:09:09.111 > [I][rcommand.cpp:343] set_enscount(): Remote command: set ENS_COUNT to off
20:09:09.111 > [I][configmanager.cpp:73] saveConfig(): Storing settings to NVRAM...
20:09:09.111 > [I][configmanager.cpp:89] saveConfig(): Device settings saved
20:09:09.111 > [W][timesync.cpp:215] timesync_serverAnswer(): [73.084] Timeserver error: spurious data received
20:09:09.111 > [I][lorawan.cpp:266] lora_send(): 4 byte(s) sent to LORA
20:09:10.303 > [I][lorawan.cpp:266] lora_send(): 1 byte(s) sent to LORA
20:09:15.517 > [I][lorawan.cpp:509] myRxCallback(): Received 6 byte(s) of payload on port 9
20:09:18.851 > [W][timesync.cpp:104] timesync_processReq(): [82.832] Timesync aborted: handshake out of sync

[cyberman54]

This is weird! I have no clue where / why this came in. Need some help to spot this bug. Can you test / do you know the last version, which did not have this bug?

[ChrSchultz]

I think that the timesync task hangs , and is not finished. but after initial timesync after reboot/startup I got on Port2 FF I think that is the callback for seting the time?

[cyberman54]

0xFF is the TIME_SYNC_END_FLAG, generated by the timesync processing task on the node, signalling that the timesync handshake ended.

But why is a timesync triggered by a remote command?

The timesync processing task is normally in blocked mode, waiting to be notified. The task notification method of FreeRTOS is used here. I have no clue, how the task can get notified when an rcommand is received.

[ChrSchultz]

I tested it with v1.9.996 and I got also this bug,

[cyberman54]

Are you sure that this is effect triggered by rcommand? I tested, too, and it seems so, but i don't see any coherence in the code. If so, it must be some weird kind of side effect.

[ChrSchultz]

There is a possibility, that It is caused by ESP32-idf... maybe. I'll check it with an older espressif32 version.

[cyberman54]

There is a possibility, that It is caused by ESP32-idf... maybe. I'll check it with an older espressif32 version.

Yes, i had same idea. Thanks for testing.

[ChrSchultz]

I tested it down to platform-espressif@1.11.0 and had the bug every time

[cyberman54]

Allright, thanks. Then this bug must came in with one of the commits of last months. In the past i spent plenty of time with timesync testing, for getting the code realtime stable with high preciscion +/- 100ms. But i never observed this bug before. Strange.