search

pschatzmann / arduino-snapclient

Snapcast client for Arduino
40 stars 4 forks source link

SnapProcessor Socket connect to server failed when using Ethernet #39

Open Wardstein opened 1 day ago

Wardstein commented 1 day ago

Hi, thanks first for the awesome lib. Just trying to get started with the snapclient. With WiFi on the ESP32 it works, but I cannot get the audio 100% glitch and crack free. Thats why I now want to move to Ethernet. I have a W5500 board, connected via SPI. That works fine, I can ping my board.

First thing I noticed when moving to Ethernet instead of wifi, is that mDNS does not work (prints an error on the serial at startup). So I disabled it (via #define CONFIG_SNAPCLIENT_USE_MDNS false) after reading that it only supports WiFi in the current implementation?

After calling client.begin() the SnapClient cannot connect to my snapcast server. All I get on the Serial output is

[   628][E][SnapProcessor.h:296] connectClient(): [SnapProcessor] Socket connect to 192.168.10.18:1704 failed (errno = 0)

Do you have any hints? I looked at the other Ethernet related issues here, but cannot find any significant difference in the code.

This is my code:

#include <Arduino.h>
#include <SPI.h>
#include <Ethernet.h>
#include "config.h"         // Must be above "SnapClient.h" include, as here are some defines, which are otherwise defaulted in "SnapClient.h/SnapConfig.h"
#include "AudioTools.h"
#include "SnapClient.h"
#include "AudioTools/AudioCodecs/CodecOpus.h"

EthernetClient eth;
byte mac[] = {0xC0, 0x49, 0xEF, 0xCE, 0x14, 0xD4};

AudioInfo infoOut(48000, 2, 16); 
OpusAudioDecoder codec;
I2SStream out;
SnapTimeSyncDynamic synch(172, 10); 
SnapClient client(eth, out, codec);

IPAddress ip(192, 168, 10, 99);
IPAddress gateway(192, 168, 10, 1);
IPAddress dns(192, 168, 10, 1);

void setup()
{
    Serial.begin(115200);

    Serial.println("Start SPI ...");
    SPI.begin(18, 19, 23, 5);

    // start the Ethernet connection:
    Serial.println("Start Ethernet ...");
    Ethernet.init(5);
    // Ethernet.begin(mac);
    Ethernet.begin(mac, ip, dns, gateway);

    // Check for Ethernet hardware present
    if (Ethernet.hardwareStatus() == EthernetNoHardware)
    {
        Serial.println("Ethernet shield was not found.  Sorry, can't run without hardware. :(");
        while (true);
    }
    Serial.print("Hardware type found: ");
    Serial.println(Ethernet.hardwareStatus());

    // Check link status
    if (Ethernet.linkStatus() == LinkOFF)
    {
        Serial.println("Ethernet cable is not connected.");
    }

    // wait for link
    Serial.println("waiting for link...");
    while(Ethernet.linkStatus() != LinkON)
    {
        delay(1000);
    }
    Serial.println("Ethernet link Up");

    Serial.print("local IP: ");
    Serial.println(Ethernet.localIP());

    Serial.println("starting I2S...");
    // setup I2S to define custom pins
    auto cfg = out.defaultConfig();
    cfg.copyFrom(infoOut);
    cfg.pin_data = 19;
    cfg.pin_bck = 18;
    cfg.pin_ws = 5;
    // cfg.pin_mck = 0;
    cfg.i2s_format = I2S_STD_FORMAT;
    cfg.buffer_size = 1024;
    cfg.buffer_count = 10;
    out.begin(cfg);

    Serial.println("starting SnapClient...");
    client.setWiFi(false);
    client.setServerIP(IPAddress(192, 168, 10, 18));
    client.begin(synch);

    Serial.println("started...");
}

void loop()
{
    client.doLoop();
}

I'm using PlatformIO, so for completeness this is my platformio.ini with the libs and versions:

[platformio]
description = ESP32 Snapclient test
default_envs = nodemcu-32s

[env:nodemcu-32s]
platform = espressif32
; platform = https://github.com/platformio/platform-espressif32.git#develop         ; TEST TEST TEST
board = nodemcu-32s
framework = arduino
; platform_packages =
;     platformio/framework-arduinoespressif32 @ https://github.com/espressif/arduino-esp32.git#2.0.14           ; TEST TEST TEST
lib_deps = 
    https://github.com/pschatzmann/arduino-audio-tools.git#v1.0.0
    https://github.com/pschatzmann/arduino-snapclient#v.0.2.0
    https://github.com/pschatzmann/arduino-libopus#a1.1.0
    arduino-libraries/Ethernet@^2.0.2
build_flags = -DCORE_DEBUG_LEVEL=2 -Wno-unused-variable -Wno-unused-but-set-variable -Wno-unused-function -Wno-format-extra-args        ; CORE_DEBUG_LEVEL=2 stands for Warning; debug = 5
pschatzmann commented 1 day ago

My expectation would be that this should just work.

Double check the IP address of your snap server and make sure that there is no firewall blocking the server port (1704)

Wardstein commented 1 day ago

I'm a step ahead. Switched from using the ESP32 SPI-V to the SPI-H for my Ethernet board (W5500) and it connects now. But I get only a small fraction of audio data and then it just stops. Also the serial output goes no further, but shows no error also.

Here is the output after the setup() until nothing is played anymore. The audio part played is maybe ~100ms.

[  3519][D][SnapProcessor.h:287] connectClient(): [SnapProcessor] start
[  3526][I][SnapProcessor.h:195] processLoopStep(): [SnapProcessor] ... connected
[  3534][D][SnapProcessor.h:304] writeHallo(): [SnapProcessor] start
[  3540][D][SnapProtocol.h:311] to_json(): [SnapMessageHallo] {"MAC":"C0:49:EF:CE:14:D4","HostName":"arduino-snapclient","Version":"0.0.2","ClientName":"libsnapcast","OS":"arduino","Arch":"xtensa","Instance":1,"ID":"C0:49:EF:CE:14:D4","SnapStreamProtocolVersion":2}
[  3564][D][SnapProcessor.h:239] processMessageLoop(): [SnapProcessor] processMessageLoop
[  3572][D][SnapProcessor.h:348] readBaseMessage(): [SnapProcessor] 26
[  3579][D][SnapProcessor.h:352] readBaseMessage(): [SnapProcessor] Bytes read: 26
[  3587][D][SnapProcessor.h:370] readData(): [SnapProcessor] 493
[  3608][D][SnapProcessor.h:239] processMessageLoop(): [SnapProcessor] processMessageLoop
[  3616][D][SnapProcessor.h:348] readBaseMessage(): [SnapProcessor] 26
[  3623][D][SnapProcessor.h:352] readBaseMessage(): [SnapProcessor] Bytes read: 26
[  3630][D][SnapProcessor.h:370] readData(): [SnapProcessor] 493
[  3651][D][SnapProcessor.h:239] processMessageLoop(): [SnapProcessor] processMessageLoop
[  3659][D][SnapProcessor.h:348] readBaseMessage(): [SnapProcessor] 26
[  3666][D][SnapProcessor.h:352] readBaseMessage(): [SnapProcessor] Bytes read: 26
[  3673][D][SnapProcessor.h:370] readData(): [SnapProcessor] 58
[  3680][D][SnapProcessor.h:497] processMessageServerSettings(): [SnapProcessor] start
[  3688][D][SnapProtocol.h:325] deserialize(): [SnapMessageServerSettings] {"bufferMs":100,"latency":0,"muted":false,"volume":71}:
[  3699][D][SnapProtocol.h:333] deserialize(): [COMMON] bufferMs: 100
[  3705][D][SnapProtocol.h:338] deserialize(): [COMMON] latency: 0
[  3711][D][SnapProtocol.h:343] deserialize(): [COMMON] volume: 71
[  3717][D][SnapProtocol.h:349] deserialize(): [COMMON] muted: false
[  3724][I][SnapProcessor.h:510] processMessageServerSettings(): [SnapProcessor] Message Buff.ms:100
[  3733][I][SnapProcessor.h:511] processMessageServerSettings(): [SnapProcessor] Latency:        0
[  3741][I][SnapProcessor.h:512] processMessageServerSettings(): [SnapProcessor] Mute:           false
[  3750][I][SnapProcessor.h:513] processMessageServerSettings(): [SnapProcessor] Setting volume: 71
[  3759][I][SnapTimeSync.h:48] setMessageBufferDelay(): [SnapTimeSync] delay: 100
[  3767][I][SnapOutput.h:68] setVolume(): [SnapOutput] Volume: 0.710000
[  3774][D][SnapProcessor.h:561] writeTimedMessage(): [SnapProcessor] start
[  3781][D][SnapProcessor.h:573] writeMessage(): [SnapProcessor] start
[  3793][D][SnapProcessor.h:239] processMessageLoop(): [SnapProcessor] processMessageLoop
[  3801][D][SnapProcessor.h:348] readBaseMessage(): [SnapProcessor] 26
[  3808][D][SnapProcessor.h:352] readBaseMessage(): [SnapProcessor] Bytes read: 26
[  3815][D][SnapProcessor.h:370] readData(): [SnapProcessor] 24
[  3821][D][SnapProcessor.h:382] processMessageCodecHeader(): [SnapProcessor] start
[  3829][I][SnapProcessor.h:391] processMessageCodecHeader(): [SnapProcessor] Received codec header message
[  3838][D][SnapProcessor.h:420] processMessageCodecHeaderOpus(): [SnapProcessor] start
[  3846][I][SnapOutput.h:106] setAudioInfo(): [SnapOutput] sample_rate: 48000, channels: 2, bits: 16
[  3855][I][SnapOutput.h:35] begin(): [SnapOutput] begin
[  3864][D][SnapOutput.h:213] audioBegin(): [SnapOutput] end
[  3870][I][SnapProcessor.h:413] processMessageCodecHeader(): [SnapProcessor] Codec : opus , Size: 12 
[  3879][D][SnapProcessor.h:561] writeTimedMessage(): [SnapProcessor] start
[  3891][D][SnapProcessor.h:239] processMessageLoop(): [SnapProcessor] processMessageLoop
[  3899][D][SnapProcessor.h:348] readBaseMessage(): [SnapProcessor] 26
[  3906][D][SnapProcessor.h:352] readBaseMessage(): [SnapProcessor] Bytes read: 26
[  3913][D][SnapProcessor.h:370] readData(): [SnapProcessor] 493
[  3929][D][SnapProcessor.h:453] processMessageWireChunk(): [SnapProcessor] start
[  3936][D][SnapProcessor.h:478] wireChunk(): [SnapProcessor] start
[  3942][D][SnapOutput.h:42] write(): [SnapOutput] 481
[  3947][D][SnapTimeSync.h:67] getStartDelay(): [SnapTimeSync] delay: 100
[  3954][W][SnapOutput.h:244] synchronizeOnStart(): [SnapOutput] invalid delay: 754729188 ms
[  3962][D][SnapProcessor.h:561] writeTimedMessage(): [SnapProcessor] start
[  3974][D][SnapProcessor.h:239] processMessageLoop(): [SnapProcessor] processMessageLoop
[  3982][D][SnapProcessor.h:348] readBaseMessage(): [SnapProcessor] 26
[  3989][D][SnapProcessor.h:352] readBaseMessage(): [SnapProcessor] Bytes read: 26
[  3996][D][SnapProcessor.h:370] readData(): [SnapProcessor] 493
[  4012][D][SnapProcessor.h:453] processMessageWireChunk(): [SnapProcessor] start
[  4019][D][SnapProcessor.h:478] wireChunk(): [SnapProcessor] start
[  4025][D][SnapOutput.h:42] write(): [SnapOutput] 481
[  4030][D][SnapTimeSync.h:67] getStartDelay(): [SnapTimeSync] delay: 100
[  4037][W][SnapOutput.h:244] synchronizeOnStart(): [SnapOutput] invalid delay: 754729125 ms
[  4045][D][SnapProcessor.h:561] writeTimedMessage(): [SnapProcessor] start
[  4057][D][SnapProcessor.h:239] processMessageLoop(): [SnapProcessor] processMessageLoop
[  4065][D][SnapProcessor.h:348] readBaseMessage(): [SnapProcessor] 26
[  4072][D][SnapProcessor.h:352] readBaseMessage(): [SnapProcessor] Bytes read: 26
[  4079][D][SnapProcessor.h:370] readData(): [SnapProcessor] 493
[  4095][D][SnapProcessor.h:453] processMessageWireChunk(): [SnapProcessor] start
[  4102][D][SnapProcessor.h:478] wireChunk(): [SnapProcessor] start
[  4108][D][SnapOutput.h:42] write(): [SnapOutput] 481
[  4113][D][SnapTimeSync.h:67] getStartDelay(): [SnapTimeSync] delay: 100
[  4119][W][SnapOutput.h:244] synchronizeOnStart(): [SnapOutput] invalid delay: 754729062 ms
[  4128][D][SnapProcessor.h:561] writeTimedMessage(): [SnapProcessor] start
[  4140][D][SnapProcessor.h:239] processMessageLoop(): [SnapProcessor] processMessageLoop
[  4148][D][SnapProcessor.h:348] readBaseMessage(): [SnapProcessor] 26
[  4155][D][SnapProcessor.h:352] readBaseMessage(): [SnapProcessor] Bytes read: 26
[  4162][D][SnapProcessor.h:370] readData(): [SnapProcessor] 493

I had a look in the output from the snapserver, but there is nothing really informative besides a successful connection:

Oct 23 16:02:50 snapcast snapserver[522]: StreamServer::NewConnection: 192.168.10.167
Oct 23 16:02:50 snapcast snapserver[522]: Hello from C0:49:EF:CE:14:D4, host: arduino-snapclient, v0.0.2, ClientName: libsnapcast, OS: arduino, Arch: xtensa, Protocol version: 2

And this for every time I reset the ESP32.

I played a bit with the chunk_ms and buffer settings in the snapserver config, but that did not change anything besides the settings are reflected in the initial SnapMessageServerSettings serial output from the ESP32.

The SPI frequency is 10MHz, so I guess this should not be the bottleneck.

Any idea why the data suddenly stops?

Wardstein commented 1 day ago

Update: I traced it now down to the readData() function in SnapProcessor.h. It gets stuck in the loop

while (p_client->available() < base_message.size)

I guess this line "waits" for a complete message. According to the logs above and more tests, the readBaseMessage() function for example reads the header and the size field says 463 bytes. But a test output with p_client->available() in the the readData() functions returns only 34. No questions it waits here (for more I guess), but this never happens/arrives.

In this case my end question of the last comment is wrong, the server does not stop. But now what could this be, that there are no additional data received? Or the ESP32 is not receiving them.

pschatzmann commented 1 day ago

My first guess would be that the available() method for this client implementation might not work correctly. Try to increase the buffer size on the client. Maybe that will help....

If that does not help we will need to change the logic to do some incremental reads until will have the full data... What happens if you just comment out the waiting logic ?

Wardstein commented 19 hours ago

I got at least the network part working by now. Your hint with the incremental read was good. I rewrote the SnapProcessor.h readData() like this:

bool readData() {
    ESP_LOGD(TAG, "base_message.size: %d", base_message.size);
    if (base_message.size > send_receive_buffer.size()) {
      send_receive_buffer.resize(base_message.size);
    }
    start = &send_receive_buffer[0];
    int index = 0;
    do
    {
      int readLength = base_message.size;
      int available = p_client->available();
      if(available < readLength)
      {
        readLength = available;
      }
      if(available > readLength)
      {
        readLength = base_message.size - index;
      }
      readLength = p_client->readBytes(&(send_receive_buffer[index]), readLength);
      index += readLength;
    } while (index < base_message.size);
    size = base_message.size;

    return true;
  }

Now I get a stream of data, but this breaks up at some point. I checked this with tcpdump on my snapcast VM. The stream runs for under 10 seconds, then it breaks up (seems ACK packets from the ESP32 are missing then).

I poked a little bit around and it seems when I do not write the audio data into the output stream, everything runs as expected. But I do not understand why. Here is a list what I tried:

I looked at the other issues, especially #7, #12 and #14. But could not find a real solution. Tried also SnapTimeSyncDynamic and SnapTimeSyncFixed, but that does not change anything. I also varied the factor for SnapTimeSyncFixed, but this had no effect. I enabled and disabled CONFIG_SNAPCLIENT_SNTP_ENABLE but this did not change anything.

Do you have any ideas why the stream breaks up, when I use a real audio stream output? Maybe a buffer over-/underrun? I see no error output on the serial.

pschatzmann commented 19 hours ago

Try it with RTOS processor: there you can play around with the buffer size. Check the Ethernet library if there are some timeout values to be changed:

virtual void setConnectionTimeout(uint16_t timeout) { _timeout = timeout; }

Using the following might also help to fix your initial issue:

int EthernetClass::begin(uint8_t *mac, unsigned long timeout, unsigned long responseTimeout)
Wardstein commented 4 hours ago

Hmm, unfortunately the SnapProcessorRTOS does not change the behaviour. I tried it with 20kB at the output and also 20kB for the SnapProcessorRTOS. Does the SnapProcessorRTOS only work with FreeRTOS? Or can I use it also without? Saw the example file where also no RTOS is used, so I guess I do not need to use it? I digged deeper and saw that the espessif framework brings freertos with it and you use it in the rtos processor. Never mind.

And do I need a board with PSRAM? I am currently working with a ESP32-WROOM-32.

pschatzmann commented 3 hours ago

No need for PSRAM, if you keep the buffer small enough...

Wardstein commented 31 minutes ago

One thing I noticed during debugging with the RTOS processor, that I always get this output line: [ 14255][I][SnapProcessorRTOS.h:76] writeAudio(): [SnapProcessorRTOS] size: 531 / buffer 0 which means buffer.available() is always 0. Also if the stream runs for a little longer and a few kB should be written to the buffer.

And therefore as buffer.available() is always 0, the task_copy() is never started, so no output either. Tried to dig into the buffer.writeArray but this then ends in the espessif rtos lib.

I also tried a bit without the RTOS processor and found, that if I do not write into the opus_decode function in CodecOpus.h write(), then it also runs forever. So it seems it would need a buffer before the decoder?

Do you use any ESP32 board with ethernet? Can you recommend one where it works? This here seems like a dead end to me with my ESP32 and a W5500 ethernet chip.

pschatzmann commented 26 minutes ago

So far I was only testing with WiFi and never had the time to look into any alternatives... Maybe you give Wifi with RTOS a try, if the simple version does not work for you...

If the buffer is empty, you never received any audio in the first place.