pschatzmann / arduino-audio-tools

Arduino Audio Tools (a powerful Audio library not only for Arduino)
GNU General Public License v3.0
1.48k stars 230 forks source link

How to repeat mp3 stream from web #261

Closed e11ni closed 2 years ago

e11ni commented 2 years ago

Hi, I have the working code scratch to play mp3 file stored on a web server (without repeat):

#define USE_HELIX 

#include "AudioTools.h"
#include "AudioCodecs/CodecMP3Helix.h"

URLStream url("mal", "K@ktz!112");

typedef int16_t sound_t;                                   // sound will be represented as int16_t (with 2 bytes)
uint16_t sample_rate=44100;
uint8_t channels = 2;  

AnalogAudioStream out;
EncodedAudioStream dec(&out, new MP3DecoderHelix()); // Decoding stream
StreamCopy copier(dec, url); // copy url to decoder

void setup(){
  Serial.begin(115200);
  AudioLogger::instance().begin(Serial, AudioLogger::Info);  

  // setup analog
  auto config = out.defaultConfig(TX_MODE);
  config.sample_rate = sample_rate; 
  out.begin(config);

  // setup I2S based on sampling rate provided by decoder
  dec.setNotifyAudioChange(out);
  dec.begin();

// mp3 radio
  url.begin("http://192.168.8.103/test.mp3","audio/mp3");

}

void loop(){
  copier.copy();
}

on the end of file I want to repeat it to get cyclic playback. In order to achieve this I modified loop as follows:

void loop(){
  if (url) {
    copier.copy();
  } else {
    // restart from the beginning
    Serial.println("Restarting...");
    delay(100);
    out.begin();
    dec.begin();
    url.begin("http://192.168.8.103/test.mp3","audio/mp3");
  }
}

But with this code no sound is played at all. Could you help to get correct repeat on the end of file?

pschatzmann commented 2 years ago

Try to use the logic that you can find in the Readme to detect the end

e11ni commented 2 years ago

Hi, I have tried.. It seems if (!copier.copy()) logic is not applicable for urlstreams out of the box, because the first copy attempt returns false. So I found example how to detect end using timeout in AudioPlayer class. This logic works well but I faced another sporadic problem that prevents to run cyclic playback. Sometimes URLStream doesn't work properly, according to logs it starting to read file data as http header.

Bad case:

10:57:58.711 -> [I] HttpRequest.h : 182 - process connecting to host 192.168.8.103 port 80
10:57:58.711 -> [I] HttpRequest.h : 170 - connect 192.168.8.103
10:57:58.711 -> [I] HttpRequest.h : 193 - Free heap: 171448
10:57:58.759 -> [I] HttpHeader.h : 357 - HttpRequestHeader::setValues - path: /test.mp3
10:57:58.759 -> [I] HttpHeader.h : 254 - HttpHeader::write
10:57:58.759 -> [I] HttpHeader.h : 366 - HttpRequestHeader::write1stLine
10:57:58.759 -> [I] HttpHeader.h : 381 - -> GET /test.mp3 HTTP/1.1
10:57:58.759 -> [I] HttpHeader.h : 191 -  -> Host: 192.168.8.103 
10:57:58.759 -> [I] HttpHeader.h : 191 -  -> Connection: close 
10:57:58.759 -> [I] HttpHeader.h : 191 -  -> Accept: audio/mp3 
10:57:58.759 -> [I] HttpHeader.h : 297 -  -> <CR LF> 
10:57:58.759 -> [I] HttpRequest.h : 217 - Request written ... waiting for reply
10:57:58.759 -> [I] HttpHeader.h : 224 - HttpHeader::read
10:57:58.759 -> [W] HttpHeader.h : 231 - Waiting for data...
10:57:58.807 -> [I] HttpHeader.h : 161 - HttpHeader::readLine -> ⸮`⸮2:`ţ⸮),⸮⸮⸮⸮D#!
⸮D"`*N0⸮D⸮Fq#PTg⸮⸮⸮⸮@&
10:57:58.807 -> [I] HttpHeader.h : 161 - HttpHeader::readLine -> ⸮D⸮⸮⸮⸮⸮⸮⸮⸮|⸮⸮⸮⸮p⸮
⸮a⸮⸮9%⸮T*008,⸮⸮⸮⸮⸮⸮⸮*⸮]⸮LRnj⸮"r ⸮⸮O3⸮⸮4⸮⸮&b⸮⸮Af⸮⸮⸮⸮⸮⸮⸮⸮⸮⸮Q⸮?⸮8I⸮uzF⸮
10:57:58.807 -> [I] HttpHeader.h : 161 - HttpHeader::readLine -> ⸮@@U⸮:@p⸮⸮:b3⸮⸮⸮⸮⸮⃘⸮⸮4⸮⸮^Z⸮l⸮⸮⸮⸮⸮⸮⸮⸮ )1 G000⸮0XK⸮/⸮⸮⸮⸮⸮@yJ⸮mvUF`⸮⸮⸮⸮5⸮⸮?$⸮;⸮$J%⸮v⸮⸮l2⸮⸮#⸮'P⸮mJB⸮+⸮⸮Uz
10:57:58.807 -> [I] HttpHeader.h : 161 - HttpHeader::readLine -> &⸮%⸮⸮⸮+r?⸮⸮TeRŲ⸮⸮⸮E⸮B⸮m⸮7U⸮5a@⸮⸮⸮>⸮⸮(j⸮^غ⸮f!⸮
10:57:58.843 -> [I] HttpHeader.h : 161 - HttpHeader::readLine ->    z!B⸮ ⸮:⸮Vg7    <⸮rRl)t⸮&⸮⸮Jʚ⸮8⸮)X⸮nR⸮⸮
10:57:58.843 -> [I] HttpHeader.h : 161 - HttpHeader::readLine -> KEd⸮H⸮⸮m⸮+s{
...... <Some lines are skipped>
10:58:12.700 -> 
10:58:12.700 -> Stack smashing protect failure!
10:58:12.700 -> 
10:58:12.700 -> 
10:58:12.700 -> abort() was called at PC 0x400ea000 on core 1
10:58:12.700 -> 
10:58:12.700 -> 
10:58:12.700 -> Backtrace:0x4008384d:0x3ffb24800x4008cffd:0x3ffb24a0 0x400921d9:0x3ffb24c0 0x400ea000:0x3ffb2540 0x400d7096:0x3ffb2560 0x400d7555:0x3ffb2690 0x400d761c:0x3ffb26c0 0x400d7751:0x3ffb2700 0x400d3f13:0x3ffb2730 0x400d651b:0x3ffb2760 0x400d6c6a:0x3ffb2800 0x400df72d:0x3ffb2820 
10:58:12.738 -> 
10:58:12.738 -> 
10:58:12.738 -> 
10:58:12.738 -> 
10:58:12.738 -> ELF file SHA256: 0000000000000000
10:58:12.738 -> 
10:58:12.738 -> Rebooting...

Good case log:

0:57:51.877 -> [I] HttpRequest.h : 182 - process connecting to host 192.168.8.103 port 80
10:57:51.877 -> [I] HttpRequest.h : 170 - connect 192.168.8.103
10:57:51.877 -> [I] HttpRequest.h : 193 - Free heap: 171028
10:57:51.877 -> [I] HttpHeader.h : 357 - HttpRequestHeader::setValues - path: /test.mp3
10:57:51.877 -> [I] HttpHeader.h : 254 - HttpHeader::write
10:57:51.877 -> [I] HttpHeader.h : 366 - HttpRequestHeader::write1stLine
10:57:51.877 -> [I] HttpHeader.h : 381 - -> GET /test.mp3 HTTP/1.1
10:57:51.877 -> [I] HttpHeader.h : 191 -  -> Host: 192.168.8.103 
10:57:51.877 -> [I] HttpHeader.h : 191 -  -> Connection: close 
10:57:51.925 -> [I] HttpHeader.h : 191 -  -> Accept: audio/mp3 
10:57:51.925 -> [I] HttpHeader.h : 297 -  -> <CR LF> 
10:57:51.925 -> [I] HttpRequest.h : 217 - Request written ... waiting for reply
10:57:51.925 -> [I] HttpHeader.h : 224 - HttpHeader::read
10:57:51.925 -> [I] HttpHeader.h : 161 - HttpHeader::readLine -> HTTP/1.1 200 OK
10:57:51.925 -> [I] HttpHeader.h : 161 - HttpHeader::readLine -> Server: nginx/1.18.0 (Ubuntu)
10:57:51.925 -> [I] HttpHeader.h : 161 - HttpHeader::readLine -> Date: Fri, 15 Jul 2022 07:57:51 GMT
10:57:51.925 -> [I] HttpHeader.h : 161 - HttpHeader::readLine -> Content-Type: audio/mpeg
10:57:51.925 -> [I] HttpHeader.h : 161 - HttpHeader::readLine -> Content-Length: 193097
10:57:51.972 -> [I] HttpHeader.h : 161 - HttpHeader::readLine -> Last-Modified: Thu, 14 Jul 2022 11:51:34 GMT
10:57:51.972 -> [I] HttpHeader.h : 161 - HttpHeader::readLine -> Connection: close
10:57:51.972 -> [I] HttpHeader.h : 161 - HttpHeader::readLine -> ETag: "62d00346-2f249"
10:57:51.972 -> [I] HttpHeader.h : 161 - HttpHeader::readLine -> Accept-Ranges: bytes
10:57:51.972 -> [I] HttpHeader.h : 161 - HttpHeader::readLine -> 
10:57:51.972 -> [I] URLStream.h : 84 - size: 193097
10:57:51.972 -> 29323 SNDPRJ Begin Streams
10:57:51.972 -> 29323 SNDPRJ Processing...
10:57:51.972 -> 29333 SNDPRJ Copied
10:57:51.972 -> 29333 SNDPRJ Processing...
10:57:52.020 -> [I] AudioCopy.h : 121 - StreamCopy::copy 1024 -> 1024 -> 1024 bytes - in 1 hops

I use v0.8.7 version. Could you help to fix this issue?

pschatzmann commented 2 years ago

The following works for me

void loop(){
  if (copier.available()) { 
    copier.copy();
  } else {
    url.begin("http://192.168.8.103/test.mp3","audio/mp3");
  }
}
e11ni commented 2 years ago

I switched to 'main' branch and now this snippet works for me. But still ~1/5 cases occurs sporadic issue I described in previous message. Is it known issue?

e11ni commented 2 years ago

I reproduced the issue multiple times. When error occurs there is a line "[W] HttpHeader.h : 231 - Waiting for data..." in log. In good scenario there is no such line in log.

pschatzmann commented 2 years ago

Obviously your stack is too small. I have never seen this error before so can you provide some more details about your environment.

Here are a couple of solution approaches

e11ni commented 2 years ago

Here is the full sketch:

#define TIMEOUT_STOP 50

#include "AudioTools.h"
#include "AudioCodecs/CodecMP3Helix.h"
//#include "AudioCodecs/CodecMP3MAD.h"

int button_pin=12;
int timeout=0;
int start=0;

URLStream url("myssid", "mypass");

typedef int16_t sound_t;                                   // sound will be represented as int16_t (with 2 bytes)
uint16_t sample_rate=44100;
uint8_t channels = 2;  

I2SStream out;
VolumeStream volume(out);
EncodedAudioStream dec(&volume, new MP3DecoderHelix());
//EncodedAudioStream dec(&volume, new MP3DecoderMAD());
StreamCopy copier(dec, url);

void start_stream(){
  // start I2S
  Serial.println("Starting I2S...");
  auto config = out.defaultConfig(TX_MODE);
  config.sample_rate = sample_rate; 
  config.channels = channels;
  config.bits_per_sample = 16;
  out.begin(config);

  // setup I2S based on sampling rate provided by decoder
  dec.setNotifyAudioChange(out);
  dec.begin();

  // set initial volume
  volume.begin(config);
  volume.setVolume(1.0);

  // mp3 track
  url.begin("http://192.168.8.103/timing.mp3","audio/mp3");
}

void setup(){
  Serial.begin(115200);
  pinMode(button_pin, INPUT);
  AudioLogger::instance().begin(Serial, AudioLogger::Info);  
  start = millis();

  start_stream();
}

void loop(){
  Serial.print(millis() - start);
  Serial.println(" SNDPRJ Processing...");
  bool copied = copier.copy();
  if (copied || timeout == 0) {
    Serial.print(millis() - start);
    Serial.print(" SNDPRJ Copied: ");
    Serial.println(copied);
    // reset timeout
    timeout = millis() + TIMEOUT_STOP;
  }
  if (millis() > timeout || digitalRead(button_pin) > 0) {
    out.end();
    dec.end();
    url.end();
    Serial.print(millis() - start);
    Serial.println(" SNDPRJ End Streams");
    start_stream();
    Serial.print(millis() - start);
    Serial.println(" SNDPRJ Begin Streams");
    timeout = 0;
  }
}

IDE: Arduino 1.8.16 Board: esp32 dev module esp32 version: 2.0.4

You could try to activate USE_URLSTREAM_TASK in the AutioConfig.h

Didn't help.

Maybe to change the Codec from MP3DecoderHelix to MP3DecoderMAD makes a difference.

Tried both decoders, it didn't help.

You could try to create your own task with an increased stack in your sketch

Have not tried yet...

pschatzmann commented 2 years ago

I looked again at your log and maybe the stack error is not the root cause of the issue. Here is what I think is happening: After the reboot your server did not recognise that the connection has been lost and continues to send audio data. When the ESP32 restarts it sends a request to the server and when it wants to interpret the reply it does not receive any header data but still audio data, which leads to this ugly crash

I would guess that adding a delay at the beginning of start_stream() should help or there might be some timeout settings related to write errors in your web server that you can play with

This explanation make more sense now because I have never seen any Stack Issues related to my URLStream.

e11ni commented 2 years ago

I checked this theory. On my server side I use nginx and according to access logs each case (both bad and good scenarios) it has separated request which is answered with code OK (200). I think, probably, some data is missing on receiving side for some reason... can be some tcp packets ignored somehow? I also noticed that this issue is reproduced less often with debug logs.. maybe there is some data race?

pschatzmann commented 2 years ago

The issue is not with the requests - but with the fact that the first request does not recognize that it has been dropped. So the client receives data from 2 requests at the same time: the original request and the new request and there is no way to hold this apart on the client side. Did you try with the delay to trigger a timeout ?

e11ni commented 2 years ago

Currently I'm testing without board reboot, in sketch there is functionality to restart streams using button:

if (millis() > timeout || **digitalRead(button_pin) > 0**) {

I checked wireshark traces. There is no overlap between tcp sessions for different http requests. TCP session for request always gets RST packet before the next session is initialized. Also sometimes the issue is reproduced right after successfully completed request.

I'm going to add printing hex bytes in HttpHeader::readLine to check if it is real audio data or just some trash bytes. I hope it will help to understand if it is stack issue or not..

pschatzmann commented 2 years ago

I also suggest that you double check if you can reproduce the issue with some other urls: e.g. http://stream.srg-ssr.ch/m/rsj/mp3_128

e11ni commented 2 years ago

My analysis of logs shown the following: In bad scenario readLine always reads real data (mp3 file) starting from the second or the third payload TCP packet, so first one or two TCP data packets from server are ignored/missed on client side. The first TCP packet contains HTTP header and first chunk of data. Example of what I see in logs:

15:10:34.518 -> [I] HttpRequest.h : 227 - Request written ... waiting for reply
15:10:34.518 -> [I] HttpHeader.h : 234 - HttpHeader::read
15:10:34.518 -> [W] HttpHeader.h : 241 - Waiting for data...
15:10:35.049 -> [I] HttpHeader.h : 169 - HttpHeader::readLine ->     ⸮A
15:10:35.049 -> \x09\x20\x88\x41\x0C
15:10:35.049 -> [I] HttpHeader.h : 169 - HttpHeader::readLine -> R48⸮⸮,⸮⸮6⸮⸮!D⸮⸮1Ō5Bl⸮`&Ar⸮⸮⸮M⸮ME⸮\⸮1xOS⸮Zs⸮⸮h:⸮
4⸮(C⸮⸮⸮⸮q⸮O⸮^⸮Q⸮Bh⸮DW 9⸮g⸮$<⸮⸮K⸮⸮⸮⸮& *⸮q⸮⸮⸮⸮⸮
15:10:35.049 -> \x04\x52\x34\x38\x98\x82\x1E\x2C\x80\xB8\x36\x02\xF0\x87\x21\x44\xC8\xF9\x31\xC5\x8C\x35\x42\x6C\x12\x02\xA0\x18\x60\x26\x41\x72\x13\x95\xD0\xFE\x4D\xCA\x4D\x45\x10\xEA\x5C\x93\x31\x78\x4F\x53\x81\x5A\x73\x93\xC1\x68\x3A\x9D\x0D\x34\xEA\x28\x06\x43\xA0\xE7\x16\x90\xBB\x12\x71\x80\x4F\xC2\x5E\x10\xB3\x14\x51\x95\x42\x68\x15\x83\x44\x57\x14\x20\x39\x9D\x67\xFA\x24\x3C\x96\xF7\x4B\x90\xFF\xFE\xDD\x06\x26\x20\x2A\xBD\x71\x16\xB3\xB8\xB3\x97\xB3

And in wireshark I see that "\x09\x20\x88\x41\x0C ..." is exact start of data from the second payload TCP packet form server. There are also some cases when I see in log start of the third packet. I reproduced issue multiple times (>20) and picture is always the same.

The problem was not reproduced with url you provided.

For me it looks like there is some wrong handling on TCP client side (because client.read() returns data not from the first chunk). But as issue is not reproduced with your url issue may be probably caused by some specific payload packet sizes, some timings, or loss of packets (both devices client and server connected to wifi, probably there are some interference issues).

I'm going to check difference in handling my nginx url and url provided by you.

pschatzmann commented 2 years ago

Have you already checked if a delay of some seconds in the setup makes any difference ?

e11ni commented 2 years ago

Yes, I have checked, no difference with delay up to 10 sec at the beginning of start_stream() in my scratch. So issue is reproduced regardless this delay.

pschatzmann commented 2 years ago

Do you have this issue when you restart by resetting the esp32 or with your end() logic triggered in the loop at the end of the file ?

e11ni commented 2 years ago

Issue is reproducible in both scenarios you mentioned.

I checked difference in handling url to internet radio you provided and my local url. TCP packet sizes are the same, also I tried to use my local nginx server as proxy for url you provided and issue was not reproduced. So I crossed out wifi interference and packet sizes as possible root cause. The last theory is that issue is related to timings. HTTP requests to url to the internet radio has ~200ms delay before response is received, and my local requests has ~1ms delay. I added 100ms delay on server side before response is sent and issue gone away. So I think this last theory is confirmed.

e11ni commented 2 years ago

Basically adding of delay for response is just workaround. I still think that there is some issue in TCP client that leads to ignoring first packets. Need to doublecheck with some clean reproducer. As the client is not part of arduino-audio-tools project I think this issue can be closed. @pschatzmann Thank you for your help!

pschatzmann commented 2 years ago

I agree, I am not aware of anything I can do on my side. For somebody who runs into the same issue: How did you add this delay in NGINX ?

e11ni commented 2 years ago

I switched to openresty which is nginx based web server but has module to execute lua scripts and some other extensions. With openresty need to modify location by adding sleep, for example:

    location / {
        access_by_lua_block { ngx.sleep(0.1) }
        try_files $uri $uri/ /index.html;
    }