Synchronization start logic

Author: pschatzmann

README.md

@@ -10,7 +10,7 @@
 - Auto connect to snapcast server on network
 - The functionality has been tested on an ESP32
 - Memory efficient implementation, so that PSRAM is not needed
-- Use any output device suppored by the [Audio Tools](https://github.com/pschatzmann/arduino-audio-tools)
+- Use any output device or DSP chain suppored by the [Audio Tools](https://github.com/pschatzmann/arduino-audio-tools)
 
 ### Description
 
@@ -64,10 +64,9 @@ void loop() {
 ### Dependencies
 
 - [Audio Tools](https://github.com/pschatzmann/arduino-audio-tools)
-
-- [LibOpus](https://github.com/pschatzmann/arduino-libopus)
-- [LibFLAC.h](https://github.com/pschatzmann/arduino-libflac)
-- [CodecVorbis](https://github.com/pschatzmann/arduino-libvorbis-idec)
+- [LibOpus](https://github.com/pschatzmann/arduino-libopus) (optional)
+- [LibFLAC.h](https://github.com/pschatzmann/arduino-libflac) (optinal)
+- [CodecVorbis](https://github.com/pschatzmann/arduino-libvorbis-idec) (optional)
 
 
 ### Configuration

docs/html/SnapProcessor.h

@@ -101,7 +101,6 @@ class SnapProcessor {
   uint32_t client_state_muted = 0;
   struct timeval now, last_time_sync;
   uint8_t timestamp_size[12];
-  float time_diff = 0.0;
   int id_counter = 0;
   IPAddress server_ip;
   int server_port = CONFIG_SNAPCAST_SERVER_PORT;
@@ -463,7 +462,7 @@ class SnapProcessor {
     retbuf[9] = (uavg & 0x000000ff);
     // ws_server_send_bin_client(0,(char*)retbuf, 10);
 
-    time_diff = time_message.latency.usec / 1000 +
+    float time_diff = time_message.latency.usec / 1000 +
                 base_message.received.usec / 1000 -
                 base_message.sent.usec / 1000;
     time_diff = (time_diff > 1000) ? time_diff - 1000 : time_diff;

examples/SnapClientAudioKit/SnapClientAudioKit.ino

@@ -15,7 +15,7 @@
 AudioKitStream out;
 //FLACDecoder flac;
 //VorbisDecoder vorbis;
-//PCMDecoder pcm;
+//WAVDecoder pcm;
 OpusAudioDecoder opus;
 SnapClient client(out, opus);
 

src/SnapClient.h

@@ -143,7 +143,7 @@ class SnapClient {
     const int daylightOffset_sec = 1 * 60 * 60;
     for (int retry = 0; retry < 5; retry++) {
       configTime(gmtOffset_sec, daylightOffset_sec, ntpServer);
-      if(!printLocalTime()){
+      if(!SnapTime().instance().printLocalTime()){
         continue;
       }
       checkHeap();

src/SnapConfig.h

@@ -13,6 +13,9 @@
 #ifndef CONFIG_SNAPCLIENT_SNTP_ENABLE 
 #  define CONFIG_SNAPCLIENT_SNTP_ENABLE false
 #endif
+#ifndef CONFIG_SNAPCLIENT_SETTIME_ALLOWD
+#  define CONFIG_SNAPCLIENT_SETTIME_ALLOWD true
+#endif
 #ifndef CONFIG_SNAPCLIENT_USE_MDNS 
 #  define CONFIG_SNAPCLIENT_USE_MDNS true
 #endif
@@ -23,7 +26,7 @@
 #  define CONFIG_CHECK_HEAP true
 #endif
 
-// snapast parameters; 
+// snapcast parameters; 
 #ifndef CONFIG_SNAPCAST_SERVER_HOST 
 #  define CONFIG_SNAPCAST_SERVER_HOST "192.168.1.38"
 #endif
@@ -42,6 +45,10 @@
 #ifndef CONFIG_CLIENT_TIMEOUT_SEC 
 #  define CONFIG_CLIENT_TIMEOUT_SEC 5
 #endif
+#ifndef CONFIG_PLAYBACK_LAG_MS 
+#  define CONFIG_PLAYBACK_LAG_MS 200
+#endif
+
 
 // wifi
 #define CONFIG_WIFI_SSID "piratnet"

src/api/SnapCommon.h

@@ -3,7 +3,9 @@
  */
 
 #pragma once
-#include <sys/time.h>
+#include <iostream>
+#include <iomanip>
+#include <ctime>
 
 enum codec_type { NO_CODEC, PCM, FLAC, OGG, OPUS, VORBIS };
 static const char *TAG="COMMON";
@@ -38,12 +40,3 @@ inline void logHeap() {
 #endif
 }
 
-inline bool printLocalTime() {
-  tm timeinfo;
-  if (!getLocalTime(&timeinfo)) {
-    ESP_LOGE(TAG, "Failed to obtain time");
-    return false;
-  }
-  Serial.println(&timeinfo, "%A, %B %d %Y %H:%M:%S");
-  return true;
-}

src/api/SnapOutputSimple.h

@@ -23,9 +23,9 @@ class SnapOutputSimple : public SnapOutput {
   size_t write(const uint8_t *data, size_t size) {
     ESP_LOGD(TAG, "%zu", size);
 
-    // if(!synchAtStart()){
-    //   return size;
-    // }
+    if(!synchAtStart()){
+      return size;
+    }
 
     size_t result = audioWrite(data, size);
     if (measure_stream.isUpdate()) measure_stream.logResult();
@@ -49,18 +49,20 @@ class SnapOutputSimple : public SnapOutput {
   SnapAudioHeader header;
   bool is_sync_active = true;
 
+  /// start to play audio only in valid server time
   bool synchAtStart(){
     // start audio when first package in the future becomes valid
     if (is_sync_active){
       auto msg_time = snap_time.toMillis(header.sec,header.usec);
       auto server_time = snap_time.serverMillis();
       if (msg_time < server_time){
         // ignore the data and report it as processed
-        ESP_LOGW(TAG, "audio data expired...");
+        ESP_LOGW(TAG, "audio data expired: msg(%u) < time(%u)", msg_time, server_time);
         return false;
       } else {
         // wait for the audio to become valid
-        delay(msg_time - server_time);
+        int diff_ms = msg_time - server_time;
+        delay(diff_ms + SnapTime::instance().getStartDelay());
         is_sync_active = false;
       }
     }

src/api/SnapProcessor.h

@@ -99,7 +99,7 @@ class SnapProcessor {
   uint32_t client_state_muted = 0;
   char *start = nullptr;
   int size = 0;
-  struct timeval now,tdif;
+  timeval now;
   uint64_t last_time_sync = 0;
   int id_counter = 0;
   IPAddress server_ip;
@@ -108,6 +108,7 @@ class SnapProcessor {
   bool output_start = true;
   bool http_task_start = true;
   bool header_received = false;
+  bool is_time_set = false;
   SnapTime& snap_time = SnapTime::instance();
 
   void processLoop(void *pvParameters = nullptr) {
@@ -129,11 +130,7 @@ class SnapProcessor {
         return true;
       }
 
-      int result = gettimeofday(&now, NULL);
-      if (result) {
-        ESP_LOGI(TAG, "Failed to gettimeofday");
-        return false;
-      }
+      now = snap_time.time();
 
       if (!writeHallo())
         return false;
@@ -210,7 +207,7 @@ class SnapProcessor {
 
   bool connectClient() {
     ESP_LOGD(TAG, "start");
-    //p_client->setTimeout(CONFIG_CLIENT_TIMEOUT_SEC);
+    p_client->setTimeout(CONFIG_CLIENT_TIMEOUT_SEC);
     if (!p_client->connect(server_ip, server_port)) {
       ESP_LOGE(TAG, "... socket connect failed errno=%d", errno);
       delay(4000);
@@ -279,14 +276,11 @@ class SnapProcessor {
     size = p_client->readBytes(&send_receive_buffer[0], BASE_MESSAGE_SIZE);
     ESP_LOGD(TAG, "Bytes read: %d", size);
 
-    int result = gettimeofday(&now, NULL);
-    if (result) {
-      ESP_LOGW(TAG, "Failed to gettimeofday");
-      return false;
-    }
+    now = snap_time.time();
 
-    result =
-        base_message_deserialize(&base_message, &send_receive_buffer[0], size);
+    int result = base_message_deserialize(&base_message, 
+                    &send_receive_buffer[0],
+                    size);
     if (result) {
       ESP_LOGW(TAG, "Failed to read base message: %d", result);
       return false;
@@ -327,7 +321,7 @@ class SnapProcessor {
     size = codec_header_message.size;
     start = codec_header_message.payload;
     if (strcmp(codec_header_message.codec, "opus") == 0) {
-      if (!processMessageCodecHeaderExt(OPUS))
+      if (!processMessageCodecHeaderOpus(OPUS))
         return false;
     } else if (strcmp(codec_header_message.codec, "flac") == 0) {
       if (!processMessageCodecHeaderExt(FLAC))
@@ -336,7 +330,7 @@ class SnapProcessor {
       if (!processMessageCodecHeaderExt(VORBIS))
         return false;
     } else if (strcmp(codec_header_message.codec, "pcm") == 0) {
-      if (!processMessageCodecHeaderPCM())
+      if (!processMessageCodecHeaderExt(PCM))
         return false;
     } else {
       ESP_LOGI(TAG, "Codec : %s not supported", codec_header_message.codec);
@@ -350,7 +344,7 @@ class SnapProcessor {
     return true;
   }
 
-  bool processMessageCodecHeaderExt(codec_type codecType) {
+  bool processMessageCodecHeaderOpus(codec_type codecType) {
     ESP_LOGD(TAG, "start");
     uint32_t rate;
     memcpy(&rate, start + 4, sizeof(rate));
@@ -363,9 +357,9 @@ class SnapProcessor {
     return true;
   }
 
-  bool processMessageCodecHeaderPCM() {
+  bool processMessageCodecHeaderExt(codec_type codecType) {
     ESP_LOGD(TAG, "start");
-    codec_from_server = PCM;
+    codec_from_server = codecType;
     return true;
   }
 
@@ -428,6 +422,9 @@ class SnapProcessor {
     ESP_LOGI(TAG, "Mute:           %d", server_settings_message.muted);
     ESP_LOGI(TAG, "Setting volume: %d", server_settings_message.volume);
 
+    // define the start delay 
+    snap_time.setDelay(server_settings_message.buffer_ms);
+
     // set volume
     if (header_received){
       setMute(server_settings_message.muted);
@@ -447,29 +444,34 @@ class SnapProcessor {
       ESP_LOGI(TAG, "Failed to deserialize time message");
       return false;
     }
-    // Calculate TClienctx.tdif : Trx-Tsend-Tnetdelay/2
+
+    // // Calculate TClienctx.tdif : Trx-Tsend-Tnetdelay/2
     struct timeval ttx, trx;
     ttx.tv_sec = base_message.sent.sec;
     ttx.tv_usec = base_message.sent.usec;
     trx.tv_sec = base_message.received.sec;
     trx.tv_usec = base_message.received.usec;
-    snap_time.setTime(trx, ttx);
-
-    timersub(&trx, &ttx, &tdif);
-    uint32_t usec = tdif.tv_usec;
+    
+    snap_time.updateServerTime(trx);
+    if (!is_time_set){
+      // set time from server
+      snap_time.setTime(trx);
+      last_time_sync = 0;
+      is_time_set = true;
+    } else {
+      int64_t time_diff = snap_time.timeDifferenceMs(trx, ttx);
+      int time_diff_int = time_diff;
+      assert(time_diff_int==time_diff);
+      ESP_LOGI(TAG, "Time Difference to Server: %ld ms", time_diff);
+      snap_time.setTimeDifferenceClientServerMs(time_diff);
+    }
 
-    float time_diff = time_message.latency.usec / 1000 +
-                      base_message.received.usec / 1000 -
-                      base_message.sent.usec / 1000;
-    time_diff = (time_diff > 1000) ? time_diff - 1000 : time_diff;
-    ESP_LOGI(TAG, "TM loopback latency: %03.1f ms", time_diff);
-    snap_time.addLatency(time_diff);
     return true;
   }
 
   bool writeTimedMessage() {
     ESP_LOGD(TAG, "start");
-    int time_ms = millis() - last_time_sync;
+    uint32_t time_ms = millis() - last_time_sync;
     if (time_ms >= 1000) {
       last_time_sync = millis();
       if (!writeMessage()) {
@@ -481,9 +483,8 @@ class SnapProcessor {
 
   bool writeMessage() {
     ESP_LOGD(TAG, "start");
-    if (gettimeofday(&now, NULL)!=0){
-      ESP_LOGE(TAG, "gettimeofday");
-    }
+
+    now = snap_time.time();
 
     base_message.type = SNAPCAST_MESSAGE_TIME;
     base_message.id = id_counter++;