Add a bunch of logging from playback stream investigatons

src/audio/audio_element_handle.cpp

@@ -39,15 +39,15 @@ auto AudioElementHandle::Quit() -> void {
 
 auto AudioElementHandle::PauseSync() -> void {
   PlayPause(PAUSE);
-  MonitorUtilState(eSuspended);
+  MonitorUntilState(eSuspended);
 }
 
 auto AudioElementHandle::QuitSync() -> void {
   Quit();
-  MonitorUtilState(eDeleted);
+  MonitorUntilState(eDeleted);
 }
 
-auto AudioElementHandle::MonitorUtilState(eTaskState desired) -> void {
+auto AudioElementHandle::MonitorUntilState(eTaskState desired) -> void {
   while (eTaskGetState(*task_) != desired) {
     WakeUpTask();
     vTaskDelay(pdMS_TO_TICKS(1));

src/audio/audio_playback.cpp

@@ -54,7 +54,7 @@ auto AudioPlayback::create(drivers::GpioExpander* expander,
 
 // TODO(jacqueline): think about sizes
 AudioPlayback::AudioPlayback()
-    : stream_start_(128, 128), stream_end_(128, 128) {}
+    : stream_start_(128, 256), stream_end_(128, 256) {}
 
 AudioPlayback::~AudioPlayback() {
   for (auto& element : element_handles_) {

src/audio/audio_task.cpp

@@ -22,6 +22,8 @@
 
 namespace audio {
 
+  static const char *kTag = "task";
+
 auto StartAudioTask(const std::string& name,
                     std::shared_ptr<IAudioElement> element)
     -> std::unique_ptr<AudioElementHandle> {
@@ -30,6 +32,7 @@ auto StartAudioTask(const std::string& name,
   // Newly created task will free this.
   AudioTaskArgs* args = new AudioTaskArgs{.element = element};
 
+  ESP_LOGI(kTag, "starting audio task %s", name.c_str());
   xTaskCreate(&AudioTaskMain, name.c_str(), element->StackSizeBytes(), args,
               kTaskPriorityAudio, task_handle.get());
 
@@ -37,18 +40,19 @@ auto StartAudioTask(const std::string& name,
 }
 
 void AudioTaskMain(void* args) {
+  // Nest the body within an additional scope to ensure that destructors are
+  // called before the task quits.
   {
     AudioTaskArgs* real_args = reinterpret_cast<AudioTaskArgs*>(args);
     std::shared_ptr<IAudioElement> element = std::move(real_args->element);
     delete real_args;
 
-    char tag[] = "task";
     ChunkReader chunk_reader = ChunkReader(element->InputBuffer());
 
     while (element->ElementState() != STATE_QUIT) {
       if (element->ElementState() == STATE_PAUSE) {
         // TODO: park with a condition variable or something?
-        vTaskDelay(100);
+        vTaskDelay(1000);
         continue;
       }
 
@@ -67,11 +71,11 @@ void AudioTaskMain(void* args) {
               return {};
             }
           },
-          element->IdleTimeout());
+          0);
 
       if (chunk_res == CHUNK_PROCESSING_ERROR ||
           chunk_res == CHUNK_DECODING_ERROR) {
-        ESP_LOGE(tag, "failed to process chunk");
+        ESP_LOGE(kTag, "failed to process chunk");
         break;  // TODO.
       } else if (chunk_res == CHUNK_STREAM_ENDED) {
         has_received_message = true;
@@ -83,12 +87,12 @@ void AudioTaskMain(void* args) {
         if (type == TYPE_STREAM_INFO) {
           auto parse_res = ReadMessage<StreamInfo>(&StreamInfo::Parse, message);
           if (parse_res.has_error()) {
-            ESP_LOGE(tag, "failed to parse stream info");
+            ESP_LOGE(kTag, "failed to parse stream info");
             break;  // TODO.
           }
           auto info_res = element->ProcessStreamInfo(parse_res.value());
           if (info_res.has_error()) {
-            ESP_LOGE(tag, "failed to process stream info");
+            ESP_LOGE(kTag, "failed to process stream info");
             break;  // TODO.
           }
         }
@@ -112,8 +116,16 @@ void AudioTaskMain(void* args) {
       // Signal the element to do any of its idle tasks.
       auto process_error = element->ProcessIdle();
       if (process_error.has_error()) {
-        ESP_LOGE(tag, "failed to process idle");
-        break;  // TODO.
+        auto err = process_error.error();
+        if (err == OUT_OF_DATA) {
+          // If we ran out of data, then place ourselves into the pause state.
+          // We will be woken up when there's something to do.
+          element->ElementState(STATE_PAUSE);
+          continue;
+        } else {
+          ESP_LOGE(kTag, "failed to process idle");
+          break;  // TODO.
+        }
       }
     }
   }

src/audio/chunk.cpp

@@ -7,12 +7,15 @@
 #include <optional>
 
 #include "cbor.h"
+#include "esp_log.h"
 
 #include "stream_buffer.hpp"
 #include "stream_message.hpp"
 
 namespace audio {
 
+static const char* kTag = "chunk";
+
 ChunkWriter::ChunkWriter(StreamBuffer* buffer)
     : stream_(buffer), leftover_bytes_(0) {}
 
@@ -53,9 +56,11 @@ auto ChunkWriter::WriteChunkToStream(
 
   // Try to write to the buffer. Note the return type here will be either 0 or
   // header_size + chunk_size, as MessageBuffer doesn't allow partial writes.
+  size_t intended_write_size = header_size.value() + chunk_size;
+  ESP_LOGI(kTag, "writing chunk of size %d", intended_write_size);
   size_t actual_write_size =
       xMessageBufferSend(stream_->Handle(), write_buffer.data(),
-                         header_size.value() + chunk_size, max_wait);
+          intended_write_size, max_wait);
 
   if (actual_write_size == 0) {
     leftover_bytes_ = chunk_size;
@@ -86,6 +91,7 @@ auto ChunkReader::ReadChunkFromStream(
   // First, wait for a message to arrive over the buffer.
   cpp::span<std::byte> new_data_dest = stream_->ReadBuffer().last(
       stream_->ReadBuffer().size() - leftover_bytes_);
+  ESP_LOGI(kTag, "reading chunk of size %d", new_data_dest.size());
   last_message_size_ = xMessageBufferReceive(
       stream_->Handle(), new_data_dest.data(), new_data_dest.size(), max_wait);
 

src/audio/fatfs_audio_input.cpp

@@ -131,6 +131,10 @@ auto FatfsAudioInput::ProcessIdle() -> cpp::result<void, AudioProcessingError> {
         file_buffer_write_pos_ = file_buffer_.begin();
       }
     }
+  } else if (GetRingBufferDistance() == 0) {
+    // We have no file open, and no data waiting to be written. We're out of
+    // stuff to do, so signal a pause.
+    return cpp::fail(OUT_OF_DATA);
   }
 
   // Now stream data into the output buffer until it's full.
@@ -152,6 +156,8 @@ auto FatfsAudioInput::ProcessIdle() -> cpp::result<void, AudioProcessingError> {
     }
   }
 
+  // We've finished writing out chunks, but there may be more of the file to
+  // read. Return, and begin again in the next idle call.
   return {};
 }
 

src/audio/include/audio_element.hpp

@@ -32,6 +32,8 @@ enum AudioProcessingError {
   UNSUPPORTED_STREAM,
   // Indicates an error with reading or writing stream data.
   IO_ERROR,
+  // Indicates that the element has run out of data to process.
+  OUT_OF_DATA,
 };
 
 /*
@@ -65,7 +67,7 @@ class IAudioElement {
    * to ProcessIdle(). If this is portMAX_DELAY (the default), then ProcessIdle
    * will never be called.
    */
-  virtual auto IdleTimeout() const -> TickType_t { return portMAX_DELAY; }
+  virtual auto IdleTimeout() const -> TickType_t { return 10; }
 
   virtual auto InputMinChunkSize() const -> std::size_t { return 0; }
 

src/audio/include/audio_element_handle.hpp

@@ -33,7 +33,7 @@ class AudioElementHandle {
   std::unique_ptr<TaskHandle_t> task_;
   std::shared_ptr<IAudioElement> element_;
 
-  auto MonitorUtilState(eTaskState desired) -> void;
+  auto MonitorUntilState(eTaskState desired) -> void;
   auto SetStateAndWakeUp(ElementState state) -> void;
   auto WakeUpTask() -> void;
 };

src/audio/stream_buffer.cpp

@@ -1,4 +1,6 @@
 #include "stream_buffer.hpp"
+#include "assert.h"
+#include "esp_log.h"
 
 namespace audio {
 
@@ -14,7 +16,11 @@ StreamBuffer::StreamBuffer(std::size_t chunk_size, std::size_t buffer_size)
       input_chunk_(raw_input_chunk_, chunk_size * 1.5),
       raw_output_chunk_(static_cast<std::byte*>(
           heap_caps_malloc(chunk_size, MALLOC_CAP_SPIRAM))),
-      output_chunk_(raw_output_chunk_, chunk_size) {}
+      output_chunk_(raw_output_chunk_, chunk_size) {
+        assert(input_chunk_.size() <= buffer_size);
+        assert(output_chunk_.size() <= buffer_size);
+        ESP_LOGI("streambuf", "created buffer of chunk size %d, total size %d", chunk_size, buffer_size);
+      }
 
 StreamBuffer::~StreamBuffer() {
   vMessageBufferDelete(handle_);