Add logging to the DAC

13 files changed, 183 insertions, 29 deletions

diff --git a/src/audio/audio_playback.cpp b/src/audio/audio_playback.cpp
index 504a2a4e..edbdcea7 100644
--- a/src/audio/audio_playback.cpp
+++ b/src/audio/audio_playback.cpp
@@ -64,6 +64,11 @@ auto AudioPlayback::Play(const std::string& filename) -> void {
   xQueueSend(input_handle_, &event, portMAX_DELAY);
 }
 
+auto AudioPlayback::LogStatus() -> void {
+  auto event = StreamEvent::CreateLogStatus();
+  xQueueSendToFront(input_handle_, &event, portMAX_DELAY);
+}
+
 auto AudioPlayback::ConnectElements(IAudioElement* src, IAudioElement* sink)
     -> void {
   src->OutputEventQueue(sink->InputEventQueue());
diff --git a/src/audio/audio_task.cpp b/src/audio/audio_task.cpp
index 9d0c4bd0..14f3462d 100644
--- a/src/audio/audio_task.cpp
+++ b/src/audio/audio_task.cpp
@@ -92,6 +92,14 @@ void AudioTaskMain(void* args) {
         } else if (new_event->tag == StreamEvent::CHUNK_NOTIFICATION) {
           ESP_LOGD(kTag, "marking chunk as used");
           element->OnChunkProcessed();
+          delete new_event;
+        } else if (new_event->tag == StreamEvent::LOG_STATUS) {
+          element->ProcessLogStatus();
+          if (element->OutputEventQueue() != nullptr) {
+          xQueueSendToFront(element->OutputEventQueue(), &new_event, 0);
+          } else {
+            delete new_event;
+          }
         } else {
           // This isn't an event that needs to be actioned immediately. Add it
           // to our work queue.
diff --git a/src/audio/i2s_audio_output.cpp b/src/audio/i2s_audio_output.cpp
index 7ecadc03..9a41adff 100644
--- a/src/audio/i2s_audio_output.cpp
+++ b/src/audio/i2s_audio_output.cpp
@@ -110,10 +110,15 @@ auto I2SAudioOutput::ProcessChunk(const cpp::span<std::byte>& chunk)
 }
 
 auto I2SAudioOutput::ProcessEndOfStream() -> void {
+  dac_->Stop();
   SendOrBufferEvent(std::unique_ptr<StreamEvent>(
       StreamEvent::CreateEndOfStream(input_events_)));
 }
 
+auto I2SAudioOutput::ProcessLogStatus() -> void {
+  dac_->LogStatus();
+}
+
 auto I2SAudioOutput::Process() -> cpp::result<void, AudioProcessingError> {
   // Note: no logging here!
   std::size_t bytes_written = dac_->WriteData(latest_chunk_);
diff --git a/src/audio/include/audio_element.hpp b/src/audio/include/audio_element.hpp
index 0c80524c..b881404c 100644
--- a/src/audio/include/audio_element.hpp
+++ b/src/audio/include/audio_element.hpp
@@ -107,6 +107,8 @@ class IAudioElement {
 
   virtual auto ProcessEndOfStream() -> void = 0;
 
+  virtual auto ProcessLogStatus() -> void {}
+
   /*
    * Called when there has been no data received over the input buffer for some
    * time. This could be used to synthesize output, or to save memory by
diff --git a/src/audio/include/audio_playback.hpp b/src/audio/include/audio_playback.hpp
index f05ca327..fc266c9b 100644
--- a/src/audio/include/audio_playback.hpp
+++ b/src/audio/include/audio_playback.hpp
@@ -37,6 +37,8 @@ class AudioPlayback {
    */
   auto Play(const std::string& filename) -> void;
 
+  auto LogStatus() -> void;
+
   // Not copyable or movable.
   AudioPlayback(const AudioPlayback&) = delete;
   AudioPlayback& operator=(const AudioPlayback&) = delete;
diff --git a/src/audio/include/i2s_audio_output.hpp b/src/audio/include/i2s_audio_output.hpp
index fc406665..de2f1f58 100644
--- a/src/audio/include/i2s_audio_output.hpp
+++ b/src/audio/include/i2s_audio_output.hpp
@@ -29,6 +29,7 @@ class I2SAudioOutput : public IAudioElement {
   auto ProcessChunk(const cpp::span<std::byte>& chunk)
       -> cpp::result<std::size_t, AudioProcessingError> override;
   auto ProcessEndOfStream() -> void override;
+  auto ProcessLogStatus() -> void override;
   auto Process() -> cpp::result<void, AudioProcessingError> override;
 
   I2SAudioOutput(const I2SAudioOutput&) = delete;
diff --git a/src/audio/include/stream_event.hpp b/src/audio/include/stream_event.hpp
index e84c8388..d42de411 100644
--- a/src/audio/include/stream_event.hpp
+++ b/src/audio/include/stream_event.hpp
@@ -17,6 +17,7 @@ struct StreamEvent {
       -> StreamEvent*;
   static auto CreateChunkNotification(QueueHandle_t source) -> StreamEvent*;
   static auto CreateEndOfStream(QueueHandle_t source) -> StreamEvent*;
+  static auto CreateLogStatus() -> StreamEvent*;
 
   StreamEvent();
   ~StreamEvent();
@@ -30,6 +31,7 @@ struct StreamEvent {
     CHUNK_DATA,
     CHUNK_NOTIFICATION,
     END_OF_STREAM,
+    LOG_STATUS,
   } tag;
 
   union {
diff --git a/src/audio/stream_event.cpp b/src/audio/stream_event.cpp
index 6efebbca..af470584 100644
--- a/src/audio/stream_event.cpp
+++ b/src/audio/stream_event.cpp
@@ -44,6 +44,12 @@ auto StreamEvent::CreateEndOfStream(QueueHandle_t source) -> StreamEvent* {
   return event;
 }
 
+auto StreamEvent::CreateLogStatus() -> StreamEvent* {
+  auto event = new StreamEvent;
+  event->tag = StreamEvent::LOG_STATUS;
+  return event;
+}
+
 StreamEvent::StreamEvent() : tag(StreamEvent::UNINITIALISED) {}
 
 StreamEvent::~StreamEvent() {
@@ -60,6 +66,8 @@ StreamEvent::~StreamEvent() {
       break;
     case END_OF_STREAM:
       break;
+    case LOG_STATUS:
+      break;
   }
 }
 
@@ -81,6 +89,8 @@ StreamEvent::StreamEvent(StreamEvent&& other) {
       break;
     case END_OF_STREAM:
       break;
+    case LOG_STATUS:
+      break;
   }
   other.tag = StreamEvent::UNINITIALISED;
 }
diff --git a/src/codecs/mad.cpp b/src/codecs/mad.cpp
index dc75a892..3fef3bbf 100644
--- a/src/codecs/mad.cpp
+++ b/src/codecs/mad.cpp
@@ -8,9 +8,9 @@
 
 namespace codecs {
 
-static int32_t scaleTo24Bits(mad_fixed_t sample) {
+static int scaleTo24Bits(mad_fixed_t sample) {
   // Round the bottom bits.
-  sample += (1L << (MAD_F_FRACBITS - 24));
+  sample += (1L << (MAD_F_FRACBITS - 16));
 
   // Clip the leftover bits to within range.
   if (sample >= MAD_F_ONE)
@@ -19,7 +19,7 @@ static int32_t scaleTo24Bits(mad_fixed_t sample) {
     sample = -MAD_F_ONE;
 
   /* quantize */
-  return sample >> (MAD_F_FRACBITS + 1 - 24);
+  return sample >> (MAD_F_FRACBITS + 1 - 16);
 }
 
 MadMp3Decoder::MadMp3Decoder() {
@@ -42,7 +42,7 @@ auto MadMp3Decoder::CanHandleFile(const std::string& path) -> bool {
 auto MadMp3Decoder::GetOutputFormat() -> OutputFormat {
   return OutputFormat{
       .num_channels = static_cast<uint8_t>(synth_.pcm.channels),
-      .bits_per_sample = 24,
+      .bits_per_sample = 16,
       .sample_rate_hz =
           synth_.pcm.samplerate == 0 ? 44100 : synth_.pcm.samplerate,
   };
@@ -120,9 +120,8 @@ auto MadMp3Decoder::WriteOutputSamples(cpp::span<std::byte> output)
     for (int channel = 0; channel < synth_.pcm.channels; channel++) {
       uint32_t sample_24 =
           scaleTo24Bits(synth_.pcm.samples[channel][current_sample_]);
-      output[output_byte++] = static_cast<std::byte>(sample_24 >> 0);
-      output[output_byte++] = static_cast<std::byte>(sample_24 >> 8);
-      output[output_byte++] = static_cast<std::byte>(sample_24 >> 16);
+      output[output_byte++] = static_cast<std::byte>((sample_24 >> 8) & 0xFF);
+      output[output_byte++] = static_cast<std::byte>((sample_24) & 0xFF);
     }
     current_sample_++;
   }
diff --git a/src/drivers/dac.cpp b/src/drivers/dac.cpp
index 70f344c4..fc0f0791 100644
--- a/src/drivers/dac.cpp
+++ b/src/drivers/dac.cpp
@@ -18,6 +18,7 @@
 #include "gpio_expander.hpp"
 #include "hal/i2s_types.h"
 #include "i2c.hpp"
+#include "sys/_stdint.h"
 
 namespace drivers {
 
@@ -49,7 +50,9 @@ auto AudioDac::create(GpioExpander* expander)
   i2s_std_config_t i2s_config = {
       .clk_cfg = dac->clock_config_,
       .slot_cfg = dac->slot_config_,
-      .gpio_cfg = {.mclk = I2S_GPIO_UNUSED,  // PCM5122 is self-clocking
+      .gpio_cfg = {
+        // TODO: investigate running in three wire mode for less noise
+        .mclk = GPIO_NUM_0,
                    .bclk = GPIO_NUM_26,
                    .ws = GPIO_NUM_27,
                    .dout = GPIO_NUM_5,
@@ -68,9 +71,7 @@ auto AudioDac::create(GpioExpander* expander)
     return cpp::fail(Error::FAILED_TO_INSTALL_I2S);
   }
 
-  ESP_ERROR_CHECK(i2s_channel_enable(dac->i2s_handle_));
-
-  // Now let's double check that the DAC itself came up whilst we we working.
+  // Make sure the DAC has booted before sending commands to it.
   bool is_booted = dac->WaitForPowerState(
       [](bool booted, PowerState state) { return booted; });
   if (!is_booted) {
@@ -78,20 +79,21 @@ auto AudioDac::create(GpioExpander* expander)
     return cpp::fail(Error::FAILED_TO_BOOT);
   }
 
-  // Write the initial configuration.
-  dac->WriteRegister(Register::DE_EMPHASIS, 1 << 4);
-  dac->WriteVolume(255);
-
-  // We already started the I2S channel with a default clock rate, but sending
-  // only zeros. The DAC should see this and automatically enter standby (if
-  // it's still waiting for the charge pump then that's also okay.)
-  bool is_configured =
-      dac->WaitForPowerState([](bool booted, PowerState state) {
-        return state == STANDBY || state == WAIT_FOR_CP;
-      });
-  if (!is_configured) {
-    return cpp::fail(Error::FAILED_TO_CONFIGURE);
-  }
+  // The DAC should be booted but in power down mode, but it might not be if we
+  // didn't shut down cleanly. Reset it to ensure it is in a consistent state.
+  dac->WriteRegister(Register::POWER_MODE, 0b10001);
+  dac->WriteRegister(Register::POWER_MODE, 1 << 4);
+  dac->WriteRegister(Register::RESET, 0b10001);
+
+  // Now configure the DAC for standard auto-clock SCK mode.
+  dac->WriteRegister(Register::DAC_CLOCK_SOURCE, 0b11 << 5);
+
+  // Enable auto clocking, and do your best to carry on despite errors.
+  //dac->WriteRegister(Register::CLOCK_ERRORS, 0b1111101);
+
+  i2s_channel_enable(dac->i2s_handle_);
+
+  dac->WaitForPowerState([](bool booted, PowerState state) { return state == STANDBY; });
 
   return dac;
 }
@@ -160,20 +162,33 @@ bool AudioDac::WaitForPowerState(
 }
 
 auto AudioDac::Reconfigure(BitsPerSample bps, SampleRate rate) -> void {
-  // TODO(jacqueline): investigate how reliable the auto-clocking of the dac
-  // is. We might need to explicit reconfigure the dac here as well if it's not
-  // good enough.
-  ESP_ERROR_CHECK(i2s_channel_disable(i2s_handle_));
+  // Disable the current output, if it isn't already stopped.
+  WriteRegister(Register::POWER_MODE, 1 << 4);
+  i2s_channel_disable(i2s_handle_);
+
+  // I2S reconfiguration.
 
   slot_config_.slot_bit_width = (i2s_slot_bit_width_t)bps;
   ESP_ERROR_CHECK(i2s_channel_reconfig_std_slot(i2s_handle_, &slot_config_));
 
   clock_config_.sample_rate_hz = rate;
+  // If we have an MCLK/SCK, then it must be a multiple of both the sample rate
+  // and the bit clock. At 24 BPS, we therefore have to change the MCLK multiple
+  // to avoid issues at some sample rates. (e.g. 48KHz)
   clock_config_.mclk_multiple =
       bps == BPS_24 ? I2S_MCLK_MULTIPLE_384 : I2S_MCLK_MULTIPLE_256;
   ESP_ERROR_CHECK(i2s_channel_reconfig_std_clock(i2s_handle_, &clock_config_));
 
+  // DAC reconfiguration.
+
+  // TODO: base on BPS
+  WriteRegister(Register::I2S_FORMAT, 0);
+
+  // Configuration is all done, so we can now bring the DAC and I2S stream back
+  // up. I2S first, since otherwise the DAC will see that there's no clocks and
+  // shut itself down.
   ESP_ERROR_CHECK(i2s_channel_enable(i2s_handle_));
+  WriteRegister(Register::POWER_MODE, 0);
 }
 
 auto AudioDac::WriteData(cpp::span<std::byte> data) -> std::size_t {
@@ -186,6 +201,55 @@ auto AudioDac::WriteData(cpp::span<std::byte> data) -> std::size_t {
   return bytes_written;
 }
 
+auto AudioDac::Stop() -> void {
+  LogStatus();
+  WriteRegister(Register::POWER_MODE, 1 << 4);
+  i2s_channel_disable(i2s_handle_);
+}
+
+#define BYTE_TO_BINARY_PATTERN "%c%c%c%c%c%c%c%c"
+#define BYTE_TO_BINARY(byte)  \
+  (byte & 0x80 ? '1' : '0'), \
+  (byte & 0x40 ? '1' : '0'), \
+  (byte & 0x20 ? '1' : '0'), \
+  (byte & 0x10 ? '1' : '0'), \
+  (byte & 0x08 ? '1' : '0'), \
+  (byte & 0x04 ? '1' : '0'), \
+  (byte & 0x02 ? '1' : '0'), \
+  (byte & 0x01 ? '1' : '0') 
+
+
+auto AudioDac::LogStatus() -> void {
+  uint8_t res;
+
+  res = ReadRegister(Register::SAMPLE_RATE_DETECTION);
+  ESP_LOGI(kTag, "detected sample rate (want 3): %u", (res >> 4) && 0b111);
+  ESP_LOGI(kTag, "detected SCK ratio (want 6): %u", res && 0b1111);
+
+  res = ReadRegister(Register::BCK_DETECTION);
+  ESP_LOGI(kTag, "detected BCK (want... 16? 32?): %u", res);
+
+  res = ReadRegister(Register::CLOCK_ERROR_STATE);
+  ESP_LOGI(kTag, "clock errors (want zeroes): ");
+  ESP_LOGI(kTag, BYTE_TO_BINARY_PATTERN, BYTE_TO_BINARY(res & 0b1111111));
+
+  res = ReadRegister(Register::CLOCK_STATUS);
+  ESP_LOGI(kTag, "clock status (want zeroes): ");
+  ESP_LOGI(kTag, BYTE_TO_BINARY_PATTERN, BYTE_TO_BINARY(res & 0b10111));
+
+  res = ReadRegister(Register::AUTO_MUTE_STATE);
+  ESP_LOGI(kTag, "automute status (want 3): %u", res & 0b11);
+
+  res = ReadRegister(Register::SOFT_MUTE_STATE);
+  ESP_LOGI(kTag, "soft mute pin status (want 3): %u", res & 0b11);
+
+  res = ReadRegister(Register::SAMPLE_RATE_STATE);
+  ESP_LOGI(kTag, "detected sample speed mode (want 0): %u", res & 0b11);
+
+  auto power = ReadPowerState();
+  ESP_LOGI(kTag, "current power state (want 5): %u", power.second);
+}
+
 void AudioDac::WriteRegister(Register reg, uint8_t val) {
   I2CTransaction transaction;
   transaction.start()
@@ -196,4 +260,19 @@ void AudioDac::WriteRegister(Register reg, uint8_t val) {
   ESP_ERROR_CHECK(transaction.Execute());
 }
 
+uint8_t AudioDac::ReadRegister(Register reg) {
+  uint8_t result = 0;
+  I2CTransaction transaction;
+  transaction.start()
+      .write_addr(kPcm5122Address, I2C_MASTER_WRITE)
+      .write_ack(reg)
+      .start()
+      .write_addr(kPcm5122Address, I2C_MASTER_READ)
+      .read(&result, I2C_MASTER_NACK)
+      .stop();
+
+  ESP_ERROR_CHECK(transaction.Execute());
+  return result;
+}
+
 }  // namespace drivers
diff --git a/src/drivers/include/dac.hpp b/src/drivers/include/dac.hpp
index e682d8d7..06808a78 100644
--- a/src/drivers/include/dac.hpp
+++ b/src/drivers/include/dac.hpp
@@ -16,6 +16,7 @@
 #include "span.hpp"
 
 #include "gpio_expander.hpp"
+#include "sys/_stdint.h"
 
 namespace drivers {
 
@@ -72,6 +73,9 @@ class AudioDac {
 
   auto WriteData(cpp::span<std::byte> data) -> std::size_t;
 
+  auto Stop() -> void;
+  auto LogStatus() -> void;
+
   // Not copyable or movable.
   AudioDac(const AudioDac&) = delete;
   AudioDac& operator=(const AudioDac&) = delete;
@@ -91,13 +95,27 @@ class AudioDac {
 
   enum Register {
     PAGE_SELECT = 0,
+    RESET = 1,
+    POWER_MODE = 2,
     DE_EMPHASIS = 7,
+    DAC_CLOCK_SOURCE = 14,
+    CLOCK_ERRORS = 37,
+    I2S_FORMAT = 40,
     DIGITAL_VOLUME_L = 61,
     DIGITAL_VOLUME_R = 62,
+
+    SAMPLE_RATE_DETECTION = 91,
+    BCK_DETECTION = 93,
+    CLOCK_ERROR_STATE = 94,
+    CLOCK_STATUS = 95,
+    AUTO_MUTE_STATE = 108,
+    SOFT_MUTE_STATE = 114,
+    SAMPLE_RATE_STATE = 115,
     DSP_BOOT_POWER_STATE = 118,
   };
 
   void WriteRegister(Register reg, uint8_t val);
+  uint8_t ReadRegister(Register reg);
 };
 
 }  // namespace drivers
diff --git a/src/main/app_console.cpp b/src/main/app_console.cpp
index a0ada735..40159f4e 100644
--- a/src/main/app_console.cpp
+++ b/src/main/app_console.cpp
@@ -124,6 +124,27 @@ void RegisterVolume() {
   esp_console_cmd_register(&cmd);
 }
 
+int CmdAudioStatus(int argc, char** argv) {
+  static const std::string usage = "usage: audio";
+  if (argc != 1) {
+    std::cout << usage << std::endl;
+    return 1;
+  }
+
+  sInstance->playback_->LogStatus();
+
+  return 0;
+}
+
+void RegisterAudioStatus() {
+  esp_console_cmd_t cmd{.command = "audio",
+                        .help = "logs the current status of the audio pipeline",
+                        .hint = NULL,
+                        .func = &CmdAudioStatus,
+                        .argtable = NULL};
+  esp_console_cmd_register(&cmd);
+}
+
 AppConsole::AppConsole(audio::AudioPlayback* playback) : playback_(playback) {
   sInstance = this;
 }
@@ -136,6 +157,7 @@ auto AppConsole::RegisterExtraComponents() -> void {
   RegisterPlayFile();
   RegisterToggle();
   RegisterVolume();
+  RegisterAudioStatus();
 }
 
 }  // namespace console
diff --git a/src/main/main.cpp b/src/main/main.cpp
index 0dc0f8be..1bbd2cca 100644
--- a/src/main/main.cpp
+++ b/src/main/main.cpp
@@ -97,6 +97,7 @@ extern "C" void app_main(void) {
 
   ESP_LOGI(TAG, "Enable power rails for development");
   expander->with([&](auto& gpio) {
+    gpio.set_pin(drivers::GpioExpander::AUDIO_POWER_ENABLE, 1);
     gpio.set_pin(drivers::GpioExpander::USB_INTERFACE_POWER_ENABLE, 0);
     gpio.set_pin(drivers::GpioExpander::SD_CARD_POWER_ENABLE, 1);
     gpio.set_pin(drivers::GpioExpander::SD_MUX_SWITCH,