Frequently getting RESYNCING HARD messages

[miLORD1337]

Hi all,
as seen in #106 and #116, in some situations RESYNCING HARD messages occur quite frequently when on current develop branch.

My setup:
48kHz, 20ms, 500ms or 700ms buffer (1000 doesn't work) on SnapServer
Another ESP SnapClient with older firmware runs fine in this exact setup.

The new client experiences RESYNCING HARD, watchdog triggers and sometimes even kernel panics.

For example:

Log

I (3922) SC: ############### CODEC
I (3925) SC: fLaC sampleformat: 48000:16:2
I (3947) PLAYER: player_setup_i2s: dma_buf_len is 100, dma_buf_count is 22, sample rate: 48000, bits: 16
I (3948) PLAYER: created new queue with 41
I (3951) PLAYER: snapserver config changed, buffer 1000ms, chunk 1152 frames, sample rate 48000, ch 2, bits 16 mute 0 latency 0
I (4521) SC: latency buffer full
I (4669) PLAYER: DMA completely loaded
I (5275) PLAYER: initial sync age: 1us, chunk duration: 24000us
W (6572) PLAYER: RESYNCING HARD 2: age -37335us, latency 1729567970229us, free 179540, largest block 65536, 0, rssi: -62
W (8120) PLAYER: RESYNCING HARD 1: age 1465138us, latency 1729567970229us, free 177044, largest block 110592, rssi: -67
W (8124) PLAYER: RESYNCING HARD 1: age 1445923us, latency 1729567970229us, free 176212, largest block 110592, rssi: -67
W (8136) PLAYER: RESYNCING HARD 1: age 1433992us, latency 1729567970229us, free 178760, largest block 110592, rssi: -67

and also

I (3853) SC: ############### CODEC
I (3856) SC: fLaC sampleformat: 48000:16:2
I (3921) PLAYER: player_setup_i2s: dma_buf_len is 100, dma_buf_count is 22, sample rate: 48000, bits: 16
I (3923) PLAYER: created new queue with 41
I (3926) PLAYER: snapserver config changed, buffer 1000ms, chunk 1152 frames, sample rate 48000, ch 2, bits 16 mute 0 latency 0
I (4232) SC: latency buffer full
I (4241) PLAYER: DMA completely loaded
W (5113) PLAYER: couldn't get memory to insert chunk, inserting an chunk containing just 0
W (5113) PLAYER: 10632, 3328, 10584, 3328
I (5132) PLAYER: initial sync age: 1us, chunk duration: 24000us
E (5162) SC: write_callback, failed to allocate PCM chunk payload
E (5162) SC: http_get_task: FLAC__stream_decoder_process_single failed
W (5225) PLAYER: couldn't get memory to insert chunk, inserting an chunk containing just 0
W (5225) PLAYER: 5320, 1920, 19272, 13824
W (5227) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5235) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5243) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5250) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5257) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5264) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5271) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5279) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5286) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5293) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5300) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5308) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5315) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5322) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5329) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5336) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5344) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5351) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5358) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5365) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5372) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5380) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5387) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5394) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5401) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5408) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (5416) SC: malloc decoderChunk.inData failed, wait 1ms and try again
E (10421) task_wdt: Task watchdog got triggered. The following tasks/users did not reset the watchdog in time:
E (10421) task_wdt:  - IDLE1 (CPU 1)
E (10421) task_wdt: Tasks currently running:
E (10421) task_wdt: CPU 0: IDLE0
E (10421) task_wdt: CPU 1: http
E (10421) task_wdt: Print CPU 1 backtrace


Backtrace: 0x40084EF6:0x3FFB2290 0x40082C35:0x3FFB22B0 0x400D85A7:0x3FFD6AB0
--- 0x40084ef6: esp_crosscore_isr at .../components/esp_system/crosscore_int.c:96
0x40082c35: _xt_lowint1 at .../components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1240
0x400d85a7: http_get_task at .../snapclient/main/main.c:1484

@CarlosDerSeher, I'm not sure whether you can move the relevant parts from the other issue over to here. Could be less confusing for both issues?

[CarlosDerSeher]

I (527) WIFI_IF: retry to connect to the AP
I (527) WIFI_IF: connect to the AP fail

In your log you have those entries. I've never got the disconnect event during start. Are you sure your WiFi is good? can you try with older FW in the same location. Also du you use improv or menuconfig to set wifi credentials?

Also you talk about older firmware. Are able to pinpoint to some commit? Are you seeing this in master too?

Things you can try:
Increase http task priority. I think I lowered this at some point and the new implementation does all the decoding in http task.

Use another sdkconfig template and menuconfig it for your board.

Play with wifi buffer sizes in menuconfig.

[miLORD1337]

Are you sure your WiFi is good?

I am fairly sure, because my other client is in another room through two walls and playing fine - whereas this new one sits more or less next to the router. Is the WiFi quality such hit or miss on these?

Do you use improv or menuconfig to set wifi credentials?

I use menuconfig for the time being.

[miLORD1337]

Also you talk about older firmware. Are able to pinpoint to some commit? Are you seeing this in master too?

I don't experience this with 7bbc07d, but a lot has happened since then. I'll try to narrow it down some more.

With master it isn't as bad, but it's there, so I wouldn't want to say with verve. That could be WiFi variations for sure. With the above commit I don't see any messages at all.

[CarlosDerSeher]

Maybe you first try if this was introduced by the 20ms bug fix. Since then the decoding is done in http task directly. Fhis could be the root cause. I am just on the phone so can't give you a commit nr right now.

But please try my other suggestions first. It's a pity I can't reproduce this. In my house I can hardly see any other wifi network at all, so could be related to packet drops. Maybe higher priority or bigger Buffers help

Edit:
Ok, I saw you already referenced a commit with the 20ms big fix in place. So that can't be it

[miLORD1337]

Increase http task priority. I think I lowered this at some point and the new implementation does all the decoding in http task.

I think you increased it again in 4e73d36. Current setting is 9, working setting is 9 as well. Should I try increasing it anyways?

Edit:
My current assumption is the change of the IDF version. Hasn't the driver changed with that, too? I didn't have time to investigate yet.

[CarlosDerSeher]

Current setting is 9, working setting is 9

Ok then this shouldn't be it.

My current assumption is the change of the IDF version. Hasn't the driver changed with that, too?

Maybe. I'll check what has changed by upgrading. But which driver do you mean? I assume I2S?

[CarlosDerSeher]

Hmm didn't see any suspicious entries in esp idf release notes. Will check my own repo as soon as I can.

Edit: maybe something happened here f96ff18? There has been a change to the sdkconfigs because of idf v5.1.5 upgrade.

[miLORD1337]

Hmm didn't see any suspicious entries in esp idf release notes.

Yeah, I didn't see any either. Sorry about that, don't know where I got that from.

I now have narrowed it down to 111501e with the rather suspicious commit message "Rework sync algorithm". That's the commit not working anymore.

I looked at the commit tree and found that my referenced commit probably doesn't include the 20 ms bug fix. I'm using flac, so I tried c228584 as well, in which the bug was already fixed for flac (and fixed for PCM). And it works. From this I infer that it's not the 20 ms bug fix introducing the problem, but rather the sync algorithm rework.

To me it looks like it's fine as long as it's fine. But once you hit a HARD RESYNC, you likely never recover. On the working commit, you can have a sporadic HARD RESYNC, but you recover and keep playing. Maybe that's a hint on what's happening?

[CarlosDerSeher]

Thanks for investigating this. I'll try to reproduce this by setting a too small buffer on the server or put the esp32 in a metal box (or disconnect the pcb antenna) so I'll have bad reception... I'll definitely have another look at th sync algorithm, maybe there is just some variable which needs to be reset on initial sync/hard resync

[CarlosDerSeher]

So I reduced my access point's TX power to the minimum of 0dBm so I can simulate bad wifi reception. With this I can run into hard resyncs quite easily by touching the ESP32 antenna with my hand. Here is the log, nothing really suspicious or surprising here:

Log

I (389) SC: Start codec chip
I (404) ES8388_DRIVER: init,out:02, in:00
I (409) SC: Audio board_init done
I (409) AUDIO_HAL: Codec mode is 2, Ctrl:0
I (411) PLAYER: deinit player done
I (412) PLAYER: player_setup_i2s: dma_buf_len is 100, dma_buf_count is 22, sample rate: 44100, bits: 16
I (423) PLAYER: init initial sync timer
I (427) PLAYER: Start player_task
I (431) PLAYER: init player done
I (431) PLAYER: started sync task
I (451) phy_init: phy_version 4840,02e0d70,Sep  2 2024,19:39:07
I (514) WIFI_IF: wifi_init_sta finished. Trying to connect to xxx
I (514) UI_HTTP: Initializing SPIFFS
I (542) UI_HTTP: Partition size: total: 534881, used: 50200
I (542) UI_HTTP: Mount /html to storage success
I (543) UI_HTTP: d_name=/html/index.html d_ino=0 d_type=1
I (548) UI_HTTP: d_name=/html/favicon.ico d_ino=0 d_type=1
I (555) UI_HTTP: d_name=/html/ESP-LOGO.txt d_ino=0 d_type=1
I (572) UI_HTTP: Starting HTTP Server on port: '8000'
I (574) NETF: Setup mdns
I (574) mdns_mem: mDNS task will be created from internal RAM
I (577) OTA: idf.py build ; curl snapclient.local:8032 --data-binary @- < build/snapclient.bin
I (586) SC: Wait for network connection
I (1590) SC: Lookup snapcast service on network
I (2178) esp_netif_handlers: sta ip: xxx.xxx.xxx.xxx, mask: xxx.xxx.xxx.xxx, gw: xxx.xxx.xxx.xxx
I (2178) WIFI_IF: Wifi Got IP Address
I (2180) WIFI_IF: ~~~~~~~~~~~
I (2184) WIFI_IF: WIFIIP:xxx.xxx.xxx.xxx
I (2188) WIFI_IF: WIFIMASK:xxx.xxx.xxx.xxx
I (2193) WIFI_IF: WIFIGW:xxx.xxx.xxx.xxx
I (2197) WIFI_IF: ~~~~~~~~~~~
I (4674) SC: 
~~~~~~~~~~ MDNS Query success ~~~~~~~~~~
I (4674) NETF: Interface: sta
I (4675) NETF: Type: V4
I (4676) NETF:   PTR : Snapcast
I (4680) NETF:   SRV : openmediavault.local:1704
I (4685) NETF:   A   : xxx.xxx.xxx.xxx
I (4689) SC: ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

I (4695) SC: Found xxx.xxx.xxx.xxx:1704
I (4935) SC: netconn connected using WIFI_STA_DEF
I (4936) SC: sta mac: 94:B9:7E:65:C5:88
I (4937) SC: netconn sent hello message
I (4943) SC: Buffer length:  758
I (4943) SC: Latency:        0
I (4946) SC: Mute:           0
I (4950) SC: Setting volume: 100
I (4955) SC: fLaC sampleformat: 44100:16:2
I (5039) PLAYER: player_setup_i2s: dma_buf_len is 100, dma_buf_count is 22, sample rate: 44100, bits: 16
I (5040) PLAYER: created new queue with 29
I (5043) PLAYER: snapserver config changed, buffer 758ms, chunk 1152 frames, sample rate 44100, ch 2, bits 16 mute 0 latency 0
I (5151) SC: latency buffer full
I (5206) PLAYER: DMA completely loaded
I (5893) AUDIO_HAL: Codec mode is 2, Ctrl:1
I (5895) PLAYER: initial sync age: 6us, chunk duration: 26122us
W (63366) PLAYER: RESYNCING HARD 2: age 115us, latency 2243027057363us, free 171676, largest block 110592, 0, rssi: -88
W (64162) PLAYER: RESYNCING HARD 1: age 747290us, latency 2243027057363us, free 168188, largest block 110592, rssi: -88, left in queue 0
W (64171) PLAYER: RESYNCING HARD 1: age 731000us, latency 2243027057363us, free 165232, largest block 110592, rssi: -88, left in queue 0
W (64180) PLAYER: RESYNCING HARD 1: age 686948us, latency 2243027057363us, free 169656, largest block 110592, rssi: -88, left in queue 0
W (64192) PLAYER: RESYNCING HARD 1: age 673574us, latency 2243027057363us, free 168088, largest block 110592, rssi: -88, left in queue 0
W (64205) PLAYER: RESYNCING HARD 1: age 634444us, latency 2243027057363us, free 168476, largest block 110592, rssi: -88, left in queue 0
W (64219) PLAYER: RESYNCING HARD 1: age 595603us, latency 2243027057363us, free 160192, largest block 106496, rssi: -88, left in queue 0
W (64233) PLAYER: RESYNCING HARD 1: age 504724us, latency 2243027057363us, free 165164, largest block 110592, rssi: -70, left in queue 0
W (64244) PLAYER: RESYNCING HARD 1: age 411946us, latency 2243027057363us, free 165172, largest block 110592, rssi: -70, left in queue 0
W (64257) PLAYER: RESYNCING HARD 1: age 320153us, latency 2243027057347us, free 165192, largest block 110592, rssi: -70, left in queue 0
W (64274) PLAYER: RESYNCING HARD 1: age 232241us, latency 2243027057347us, free 165152, largest block 106496, rssi: -70, left in queue 0
W (64283) PLAYER: RESYNCING HARD 1: age 137071us, latency 2243027057347us, free 161740, largest block 110592, rssi: -70, left in queue 0
I (64297) PLAYER: DMA completely loaded
I (64305) PLAYER: initial sync age: 2us, chunk duration: 26122us

I've tried this a couple of times with lyrat v4.3 and my custom board without any issues whatsoever. Could you please try and use my sdkconfig just to see if there is some problem with the template for your DAC?

sdkconfig.txt

Edit: OK now I am able to reproduce. I've set the sample rate to 48kHz and now the log looks exactly like yours...

Log

...
I (26648) PLAYER: player_setup_i2s: dma_buf_len is 100, dma_buf_count is 22, sample rate: 48000, bits: 16
I (26649) PLAYER: created new queue with 31
I (26653) PLAYER: snapserver config changed, buffer 758ms, chunk 1152 frames, sample rate 48000, ch 2, bits 16 mute 0 latency 0
I (26679) PLAYER: DMA completely loaded
I (27381) AUDIO_HAL: Codec mode is 2, Ctrl:1
I (27383) PLAYER: initial sync age: 6us, chunk duration: 24000us
W (27384) PLAYER: RESYNCING HARD 2: age 91229us, latency 5328446660us, free 171056, largest block 110592, 0, rssi: -67
W (29012) PLAYER: RESYNCING HARD 1: age 1583417us, latency 5328446660us, free 156400, largest block 94208, rssi: -70, left in queue 0
W (29015) PLAYER: RESYNCING HARD 1: age 1562561us, latency 5328446660us, free 159556, largest block 94208, rssi: -70, left in queue 0
W (29031) PLAYER: RESYNCING HARD 1: age 1530935us, latency 5328446660us, free 158436, largest block 106496, rssi: -70, left in queue 0
W (29043) PLAYER: RESYNCING HARD 1: age 1494950us, latency 5328446660us, free 165592, largest block 106496, rssi: -70, left in queue 0
W (29058) PLAYER: RESYNCING HARD 1: age 1485493us, latency 5328446660us, free 152812, largest block 94208, rssi: -70, left in queue 0
W (29073) PLAYER: RESYNCING HARD 1: age 1428440us, latency 5328446660us, free 152672, largest block 94208, rssi: -70, left in queue 0
W (29079) PLAYER: RESYNCING HARD 1: age 1386531us, latency 5328446660us, free 166400, largest block 98304, rssi: -70, left in queue 0
W (29094) PLAYER: RESYNCING HARD 1: age 1377604us, latency 5328446660us, free 161252, largest block 98304, rssi: -70, left in queue 0
W (29107) PLAYER: RESYNCING HARD 1: age 1342346us, latency 5328446660us, free 164684, largest block 106496, rssi: -70, left in queue 0
W (29120) PLAYER: RESYNCING HARD 1: age 1331695us, latency 5328446660us, free 157820, largest block 98304, rssi: -70, left in queue 0
W (29135) PLAYER: RESYNCING HARD 1: age 265934us, latency 5328446660us, free 154420, largest block 98304, rssi: -70, left in queue 0
W (29151) PLAYER: RESYNCING HARD 1: age 210465us, latency 5328446660us, free 163032, largest block 106496, rssi: -70, left in queue 0
W (29157) PLAYER: RESYNCING HARD 1: age 192368us, latency 5328446660us, free 159536, largest block 98304, rssi: -70, left in queue 0
W (29172) PLAYER: RESYNCING HARD 1: age 158867us, latency 5328446660us, free 168116, largest block 106496, rssi: -70, left in queue 0
W (29183) PLAYER: RESYNCING HARD 1: age 146272us, latency 5328446660us, free 157724, largest block 98304, rssi: -70, left in queue 0
W (29198) PLAYER: RESYNCING HARD 1: age 89252us, latency 5328446660us, free 157820, largest block 98304, rssi: -70, left in queue 0
W (29210) PLAYER: RESYNCING HARD 1: age 29480us, latency 5328446660us, free 162968, largest block 106496, rssi: -69, left in queue 0
I (29228) PLAYER: DMA completely loaded
I (29231) PLAYER: initial sync age: 1us, chunk duration: 24000us
W (33756) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (33757) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (33761) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (38896) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (38897) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (38901) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (38908) SC: malloc decoderChunk.inData failed, wait 1ms and try again
W (38915) SC: malloc decoderChunk.inData failed, wait 1ms and try again

[miLORD1337]

Thanks for investigating. So a quick workaround is to set the sample rate to 44100:16:2. That's good news already :)

Might be a stupid question, but here goes: How do chunk/frames, queue length, sample rate and buffer relate?
It feels weird, that the queue length increased when the sample rate was increased but everything else stayed the same... I thought it would go down, as fewer chunks fit in.

[CarlosDerSeher]

@miLORD1337 so it works for you with 44.1kHz?

How do chunk/frames, queue length, sample rate and buffer relate?

int entries = ceil(((float)__scSet.sr / (float)__scSet.chkInFrames) * ((float)__scSet.buf_ms / 1000));

but you might be on to something here. I'll have to rethink this after I've solved this issue. For some reason the code is completely broken when using 48kHz (maybe other sample rates too, don't know)...