Hard resync triggers infinite loop due to stale timing filters

[craigmillard86]

When WiFi congestion causes the audio queue to empty, the player triggers a hard resync but fails to reset timing filters. This
causes an infinite resync loop where audio never recovers.

Symptoms

• Hundreds of RESYNCING HARD 1: age Xus, latency Yus log messages in rapid succession
• Corrupted latency values (e.g., 1469934083866us = ~17 days)
• Queue always shows 0 messages
• TAS5805M reports repeated clock faults
• Audio never recovers (or takes minutes to eventually recover by chance)

Trigger Sequence

1. WiFi congestion occurs

• Network latency spike (1+ seconds observed in testing)
• No audio chunks arrive during spike

2. Queue drains

• Player task keeps consuming chunks but nothing arriving
• consecutive_empty_count increments each empty read
• Threshold hit after CONFIG_PLAYER_QUEUE_EMPTY_THRESHOLD (default 3) empty reads

3. Hard resync triggers

• HARD 2 resync fires: stops I2S, sets initialSync = 0
• BUG: TimeFilter and median filters NOT reset

4. WiFi recovers, but timing is corrupted

• Chunks start arriving again
• Age calculated using serverNow from get_diff_to_server()
• TimeFilter was extrapolating clock drift during outage with no updates
• Kalman filter extrapolated wildly → returns garbage value (17+ days offset)

5. Infinite loop

• Every chunk appears massively late due to corrupt diff2Server
• HARD 1 resync fires → drops chunk, continues
• Next chunk also has garbage age → HARD 1 again
• Never recovers because filters never reset

Root Cause

When hard resync is triggered in player.c, the code resets initialSync but does not reset:

• latencyTimeFilter (Kalman filter for time sync)
• shortMedianFilter / miniMedianFilter (sync drift tracking)

The race condition is between WiFi recovery (chunks arriving) and TimeFilter state (extrapolating into garbage). If chunks arrive
before TimeFilter is reset, stale extrapolated values corrupt all subsequent timing calculations.

Why It Sometimes Recovered

If by chance a chunk's calculated age went negative (appeared "early"), the age < 0 code path does reset median filters. This allowed
partial recovery, but was luck-based and slow.

Affected Code

components/lightsnapcast/player.c:

• HARD 1 resync path (~line 1535-1576)
• HARD 2 resync path (~line 1810-1836)

Example Logs:

  [1B][0;32mI (1390379) PLAYER: initial sync age: 1us, chunk duration: 24000us[1B][0m
  [1B][0;33mW (1392630) TAS5805M: Faults detected: err0=0x00, err1=0x04, err2=0x00, ot_warn=0x00[1B][0m
  [1B][0;33mW (1392630) TAS5805M: tas5805m_decode_faults: Clock fault[1B][0m
  [1B][0;32mI (1392634) TAS5805M: Faults cleared[1B][0m
  [1B][0;33mW (1662579) PLAYER: RESYNCING HARD 2: age -110us, latency 1469934083866us, free 8426135, largest block 8126464, 0, rssi:
  -42[1B][0m
  [1B][0;33mW (1662856) TAS5805M: Faults detected: err0=0x00, err1=0x04, err2=0x00, ot_warn=0x00[1B][0m
  [1B][0;33mW (1662856) TAS5805M: tas5805m_decode_faults: Clock fault[1B][0m
  [1B][0;32mI (1662860) TAS5805M: Faults cleared[1B][0m
  [1B][0;33mW (1663333) PLAYER: RESYNCING HARD 1: age 1419276us, latency 1469934083864us, free 8426135, largest block 8126464, rssi:
  -42, left in queue 0[1B][0m
  [1B][0;33mW (1663826) PLAYER: RESYNCING HARD 1: age 1888074us, latency 1469934083863us, free 8426207, largest block 8126464, rssi:
  -41, left in queue 0[1B][0m
  [1B][0;33mW (1664073) PLAYER: RESYNCING HARD 1: age 2110976us, latency 1469934083862us, free 8412567, largest block 8126464, rssi:
  -41, left in queue 0[1B][0m
  [1B][0;33mW (1664080) PLAYER: RESYNCING HARD 1: age 2094070us, latency 1469934083862us, free 8403631, largest block 8126464, rssi:
  -41, left in queue 0[1B][0m
  [1B][0;33mW (1664093) PLAYER: RESYNCING HARD 1: age 2082371us, latency 1469934083862us, free 8388007, largest block 8126464, rssi:
  -41, left in queue 0[1B][0m
  [1B][0;33mW (1664106) PLAYER: RESYNCING HARD 1: age 2071777us, latency 1469934083862us, free 8389775, largest block 8126464, rssi:
  -41, left in queue 0[1B][0m
  ...
  [1B][0;33mW (1666677) PLAYER: RESYNCING HARD 1: age 11127us, latency 1469934083854us, free 8389711, largest block 8126464, rssi: -42,
   left in queue 0[1B][0m
  [1B][0;32mI (1666695) PLAYER: DMA completely loaded[1B][0m
  [1B][0;32mI (1666697) PLAYER: initial sync age: 1us, chunk duration: 24000us[1B][0m
  [1B][0;33mW (1667868) TAS5805M: Faults detected: err0=0x00, err1=0x04, err2=0x00, ot_warn=0x00[1B][0m
  [1B][0;33mW (1667868) TAS5805M: tas5805m_decode_faults: Clock fault[1B][0m
  [1B][0;32mI (1667872) TAS5805M: Faults cleared[1B][0m
  [1B][0;33mW (1669061) PLAYER: RESYNCING HARD 2: age 5214us, latency 1469934083845us, free 7937727, largest block 7733248, 105, rssi:
  -41[1B][0m
  [1B][0;32mI (1669063) PLAYER: DMA completely loaded[1B][0m
  [1B][0;32mI (1669116) PLAYER: initial sync age: 2us, chunk duration: 24000us[1B][0m
  [1B][0;33mW (1672881) TAS5805M: Faults detected: err0=0x00, err1=0x04, err2=0x00, ot_warn=0x00[1B][0m
  [1B][0;33mW (1672881) TAS5805M: tas5805m_decode_faults: Clock fault[1B][0m
  [1B][0;32mI (1672885) TAS5805M: Faults cleared[1B][0m

[luar123]

• Chunks start arriving again
• Age calculated using serverNow from get_diff_to_server()
• TimeFilter was extrapolating clock drift during outage with no updates
• Kalman filter extrapolated wildly → returns garbage value (17+ days offset)

This is interesting, so during congestion also no time messages arrive and then the first samples arrive before the first time message, right?
Maybe there is a bug in the drift calculation or the settings are wrong?
I think it would be better to fix that instead of just resetting it.

Do you have logs where we can see latency inserts and retrieve? You could enable logging here:

snapclient/components/lightsnapcast/player.c

Line 591 in d82cbfd

//ESP_LOGI(TAG, "Timefilter: drift %f, max err %lldus, \n%lldus new val\n%fus offset", drift_, max_error, newValue, offset_);

and here:

snapclient/components/lightsnapcast/player.c

Line 711 in d82cbfd

// ESP_LOGW(TAG,

and here:

snapclient/components/lightsnapcast/player.c

Lines 761 to 763 in d82cbfd

	// ESP_LOGI(TAG, "now: %lldus", now);
	// ESP_LOGI(TAG, "diff: %lldus", diff);
	// ESP_LOGI(TAG, "serverNow: %lldus", *snow);

[luar123]

Kalman filter extrapolated wildly → returns garbage value (17+ days offset)

If you take the 17 days from latency in logs:
PLAYER: RESYNCING HARD 1: age 2082371us, latency 1469934083862us, free 8388007, largest block 8126464, rssi: -41, left in queue

latency here is diff2server with local and server clock being the time since startup. So having huge values here is not uncommon and simply depends on when you restarted your snapserver the last time. But there should be no big difference before and after the congestion.

[CarlosDerSeher]

Thank you for clarification. I meant to mention that too. Maybe the log message is misleading here and should be changed?

[craigmillard86]

Hey Both,

I have attached the logs - I have gone back to basics and have worked from the develop branch, prior testing was without the sync rework! It seems to recover much faster without the changes now but I am still getting brief audio drops throughout everysong.

I have then only implemented the median filter reset and this seems to clean up all the remaining audio drops. I defer to the sync experts for best resolution here :)

I have attached logs as per your request @luar123, let me know if you want more.

log.txt

[CarlosDerSeher]

I have then only implemented the median filter reset and this seems to clean up all the remaining audio drops.

So with this all is good?

[craigmillard86]

I have then only implemented the median filter reset and this seems to clean up all the remaining audio drops.

So with this all is good?

Actually i dont think it is, still get small blips for approx 30s then goes into a hard 1 loop and never recovers. logs attached

log.txt

Interstingly, if i remove the logging i get clean playback? this is with develop + median filters added

[CarlosDerSeher]

a lot of logging results in slow down which prevents synced playback from beeing stable. I've seen this in the past too

[luar123]

Thanks for the logs, I would say timefilter and latencies are as expected. Also drift is very low. Some resyncs because of logging delay are expected, if it works without the logging it should be fine.

I am not sure why it can't recover from resyncing in your second log. Could be the logs, could be something else, but I think latencies and timefilter are fine.

This is with develop + median filters added

Only median filter reset or also the other changes from #192 ?

[craigmillard86]

Should just be the median filters only, i will update the PR shortly as still contains some other attempted changes.

[craigmillard86]

Should just be the median filters only, i will update the PR shortly as still contains some other attempted changes.

Just pushed and corrected to just median filters.

[craigmillard86]

Right, I have done some more expirimenting and now believe this is due to blocking on the HTTP server side which is why the queue stays empty for so many hard resync1's, looking for input here.

During network congestion, the HARD 1 resync loop would never recover:

1. Network burst delays chunks
2. Chunks arrive late (age >= 0)
3. HARD 1 triggers, discards late chunks
4. Queue becomes empty
5. Player task spins at priority 20 on core 1
6. HTTP task (priority 17, same core) starved - can't receive new chunks
7. Queue stays empty → loop forever or significant time with no audio

• Without fix: left in queue 0 - HTTP starved, no chunks arriving
• With 50ms delay: left in queue 107 - HTTP received chunks but most late.

20ms as larger doesnt seem to improve further and chunks are dropped as late anyway

// Yield to let HTTP task receive new chunks from network
// Only yield if queue is empty - otherwise rely on existing discard logic
if (uxQueueMessagesWaiting(pcmChkQHdl) == 0) {
vTaskDelay(pdMS_TO_TICKS(20));
}

Why it works:

1. Only yields when queue is empty (actual starvation)
2. 20ms delay gives HTTP task CPU time to receive chunks
3. Doesn't yield if queue has chunks (no unnecessary delay)
4. Relies on existing age-based discard logic for sync
5. Preserves multi-room synchronization

This seems to be working far better, as in when a hard sync is needed it only takes one attempt to resync with minimal interuptions.

Logs with fix:

  I (622517) PLAYER: DMA completely loaded
  I (622525) PLAYER: initial sync age: 4us, chunk duration: 24000us
  W (626688) TAS5805M: Faults detected: err0=0x00, err1=0x04, err2=0x00, ot_warn=0x00
  W (626688) TAS5805M: tas5805m_decode_faults: Clock fault
  I (626691) TAS5805M: Faults cleared
  W (682715) PLAYER: RESYNCING HARD 2: age 62us, latency 1959532170124us, free 8416267, largest block 8257536, 0, rssi: -46
  I (682726) PLAYER: DMA completely loaded
  I (682765) PLAYER: initial sync age: 40us, chunk duration: 24000us
  W (686746) TAS5805M: Faults detected: err0=0x00, err1=0x04, err2=0x00, ot_warn=0x00
  W (686746) TAS5805M: tas5805m_decode_faults: Clock fault
  I (686749) TAS5805M: Faults cleared
  W (1042356) PLAYER: RESYNCING HARD 2: age 1us, latency 1959532170300us, free 8419979, largest block 7733248, 0, rssi: -46
  W (1042364) PLAYER: RESYNCING HARD 1: age 129507us, latency 1959532170300us, free 8412387, largest block 7733248, rssi: -46, left in queue 0
  W (1042391) PLAYER: RESYNCING HARD 1: age 132928us, latency 1959532170300us, free 8391143, largest block 7733248, rssi: -46, left in queue 7
  I (1042443) PLAYER: DMA completely loaded
  I (1042446) PLAYER: initial sync age: 1us, chunk duration: 24000us
  W (1044810) PLAYER: RESYNCING HARD 2: age 17563us, latency 1959532170301us, free 7934667, largest block 7733248, 106, rssi: -46
  I (1044813) PLAYER: DMA completely loaded
  I (1044852) PLAYER: initial sync age: 1us, chunk duration: 24000us
  W (1047043) TAS5805M: Faults detected: err0=0x00, err1=0x04, err2=0x00, ot_warn=0x00
  W (1047043) TAS5805M: tas5805m_decode_faults: Clock fault
  I (1047047) TAS5805M: Faults cleared
  W (1642238) PLAYER: RESYNCING HARD 2: age 26us, latency 1959532170280us, free 8414691, largest block 8257536, 0, rssi: -45
  W (1642242) PLAYER: RESYNCING HARD 1: age 7466us, latency 1959532170280us, free 8419327, largest block 8257536, rssi: -45, left in queue 0
  W (1642273) PLAYER: RESYNCING HARD 1: age 14940us, latency 1959532170280us, free 8403607, largest block 8257536, rssi: -45, left in queue 3
  I (1642278) PLAYER: DMA completely loaded
  I (1642308) PLAYER: initial sync age: 1us, chunk duration: 24000us
  W (1642542) TAS5805M: Faults detected: err0=0x00, err1=0x04, err2=0x00, ot_warn=0x00
  W (1642545) TAS5805M: tas5805m_decode_faults: Clock fault
  I (1642548) TAS5805M: Faults cleared

Fix on branch here: https://github.com/anabolyc/esp32-snapclient/tree/bugfix/hard-resync-filter-reset

[CarlosDerSeher]

Now this sounds like a real solution. I've suspected we have some race condition/ deadlock issue for quite some now.

Will have a closer look later, just one thing. Could you edit your post and please use code tags for the log. Also try not to capture those color specifiers in the log.

[craigmillard86]

Now this sounds like a real solution. I've suspected we have some race condition/ deadlock issue for quite some now.

Will have a closer look later, just one thing. Could you edit your post and please use code tags for the log. Also try not to capture those color specifiers in the log.

I have also looked at the power mode of the Wifi and suggest having it as configurable as per changes here: https://github.com/anabolyc/esp32-snapclient/tree/feature/wifi-power-config

This reduced my ping time down from 50-200ms down to 5-15ms.

It seems to have stabilised it a little more as well :)