Is there a bug in HTTPClient.cpp disconnect()?

[CelliesProjects]

Hardware:

Board: M5Stack Grey
Core Installation version: 1.0.4 & 1.03
IDE name: Arduino IDE
Flash Frequency: 80Mhz
PSRAM enabled: no
Upload Speed: 115200
Computer OS: Ubuntu

Description:

I am trying to make a barebone webradio with a M5stack board. I am using code from https://github.com/earlephilhower/ESP8266Audio as a starting point.
My repo can be found at https://github.com/CelliesProjects/ESP32_radio

I can start playing a MP3 just fine. The problem is that on changing stations the boards pauses up to 10-15 seconds (but not always).
The pause seems to be caused by HTTPClient disconnect().
Posted below is a debug log showing the output.
I run into this with every existing ESP32 web radio repo I try to use a a base.

So in short: Booting and starting a stream is instantaneous, but changing the stream makes the board stall for up to 15 seconds.
The stall happens at

[D][HTTPClient.cpp:361] disconnect(): still data in buffer (5437), clean up.

in the logs.

Anybody willing to try the sketch and confirm this?

Sketch:

#include <Arduino.h>

#ifdef ESP32
#include <WiFi.h>
#include <M5Stack.h>
#else
#include <ESP8266WiFi.h>
#endif

#include "AudioFileSourceICYStream.h"
#include "AudioFileSourceBuffer.h"
#include "AudioGeneratorMP3.h"
#include "AudioOutputI2SNoDAC.h"

// To run, set your ESP8266 build to 160MHz, update the SSID info, and upload.

// Enter your WiFi setup here:
const char *SSID = "SSID";
const char *PASSWORD = "PSK";

// Randomly picked URL
const char *URL[3] = { "http://icecast.omroep.nl/3fm-bb-mp3", "http://icecast.omroep.nl/radio5-bb-mp3", "http://icecast.omroep.nl/radio6-bb-mp3" };

AudioGeneratorMP3 *mp3;
AudioFileSourceICYStream *file;
AudioFileSourceBuffer *buff;
AudioOutputI2S *out;
int gain = 0;

// Called when a metadata event occurs (i.e. an ID3 tag, an ICY block, etc.
void IRAM_ATTR MDCallback(void *cbData, const char *type, bool isUnicode, const char *string)
{
  const char *ptr = reinterpret_cast<const char *>(cbData);
  (void)isUnicode; // Punt this ball for now
  // Note that the type and string may be in PROGMEM, so copy them to RAM for printf
  char s1[32], s2[64];
  strncpy_P(s1, type, sizeof(s1));
  s1[sizeof(s1) - 1] = 0;
  strncpy_P(s2, string, sizeof(s2));
  s2[sizeof(s2) - 1] = 0;
  M5.Lcd.printf("METADATA(%s) '%s' = '%s'\n", ptr, s1, s2);
  Serial.printf("METADATA(%s) '%s' = '%s'\n", ptr, s1, s2);
  Serial.flush();
}

// Called when there's a warning or error (like a buffer underflow or decode hiccup)
void IRAM_ATTR StatusCallback(void *cbData, int code, const char *string)
{
  const char *ptr = reinterpret_cast<const char *>(cbData);
  // Note that the string may be in PROGMEM, so copy it to RAM for printf
  char s1[64];
  strncpy_P(s1, string, sizeof(s1));
  s1[sizeof(s1) - 1] = 0;
  M5.Lcd.printf("STATUS(%s) '%d' = '%s'\n", ptr, code, s1);

}


void setup()
{
  M5.begin();
  delay(1000);
  M5.Lcd.println("Connecting to WiFi");

  WiFi.disconnect();
  WiFi.softAPdisconnect(true);
  WiFi.mode(WIFI_STA);

  WiFi.begin(SSID, PASSWORD);

  // Try forever
  while (WiFi.status() != WL_CONNECTED) {
    //M5.Lcd.println("...Connecting to WiFi");
    delay(1000);
  }
  M5.Lcd.println("Connected");

  file = new AudioFileSourceICYStream(URL[0]);
  file->RegisterMetadataCB(MDCallback, (void*)"ICY");
  buff = new AudioFileSourceBuffer(file, 32 * 1024);
  buff->loop();
  //buff->RegisterStatusCB(StatusCallback, (void*)"buffer");
  //while ( buff->getFillLevel() < 32 * 1024 ) buff->loop();
  out = new AudioOutputI2S(0, 1, 8);
  mp3 = new AudioGeneratorMP3();
  //mp3->RegisterStatusCB(StatusCallback, (void*)"mp3");
  out->SetGain(0);
  mp3->begin(buff, out);
  delay(100);
  if ( mp3->isRunning() ) out->SetGain(0.2);
  else {
    M5.Lcd.println("Could not start MP3.");
  }
}

void loop()
{
  mp3->loop();
  static uint8_t current = 0;
  const bool BTN_A_PRESSED = !digitalRead( 39 );
  if ( mp3 && !mp3->loop()) {
    mp3->stop();
  }
  if ( mp3->isRunning() && BTN_A_PRESSED ) {
    M5.Lcd.printf("Opening %s\n", URL[current]);
    out->SetGain(0);
    mp3->stop();
    //delay(10);
    if (file->isOpen() ) file->close();
    //delay(10);
    current++;
    if ( current == 3 ) current = 0;
    file->open(URL[current]);
    mp3->begin(buff, out);
    if ( mp3->isRunning() ) out->SetGain(0.2);
  }
  //delay(0);
}

Debug Messages:

ho 0 tail 12 room 4
load:0x40080400,len:6320
entry 0x400806a8
M5Stack initializing...[W][sd_diskio.cpp:137] sdCommand(): no token received
[W][sd_diskio.cpp:137] sdCommand(): no token received
[W][sd_diskio.cpp:137] sdCommand(): no token received
[W][sd_diskio.cpp:471] ff_sd_initialize(): GO_IDLE_STATE failed
[E][sd_diskio.cpp:739] sdcard_mount(): f_mount failed 0x(3)
OK
[D][WiFiGeneric.cpp:337] _eventCallback(): Event: 0 - WIFI_READY
[D][WiFiGeneric.cpp:337] _eventCallback(): Event: 2 - STA_START
[D][WiFiGeneric.cpp:337] _eventCallback(): Event: 4 - STA_CONNECTED
[D][WiFiGeneric.cpp:337] _eventCallback(): Event: 7 - STA_GOT_IP
[D][WiFiGeneric.cpp:381] _eventCallback(): STA IP: 192.168.0.106, MASK: 255.255.255.0, GW: 192.168.0.1
[V][HTTPClient.cpp:235] beginInternal(): url: http://icecast.omroep.nl/3fm-bb-mp3
[D][HTTPClient.cpp:276] beginInternal(): host: icecast.omroep.nl port: 80 url: /3fm-bb-mp3
[D][HTTPClient.cpp:1025] connect():  connected to icecast.omroep.nl:80
[V][HTTPClient.cpp:1123] handleHeaderResponse(): RX: 'HTTP/1.0 200 OK'
[V][HTTPClient.cpp:1123] handleHeaderResponse(): RX: 'Content-Type: audio/mpeg'
[V][HTTPClient.cpp:1123] handleHeaderResponse(): RX: 'Date: Wed, 05 Feb 2020 14:10:32 GMT'
[V][HTTPClient.cpp:1123] handleHeaderResponse(): RX: 'icy-br:192'
[V][HTTPClient.cpp:1123] handleHeaderResponse(): RX: 'ice-audio-info: samplerate=48000;channels=2;bitrate=192'
[V][HTTPClient.cpp:1123] handleHeaderResponse(): RX: 'icy-br:192'
[V][HTTPClient.cpp:1123] handleHeaderResponse(): RX: 'icy-genre:Pop'
[V][HTTPClient.cpp:1123] handleHeaderResponse(): RX: 'icy-metadata:1'
[V][HTTPClient.cpp:1123] handleHeaderResponse(): RX: 'icy-name:NPO 3FM'
[V][HTTPClient.cpp:1123] handleHeaderResponse(): RX: 'icy-pub:0'
[V][HTTPClient.cpp:1123] handleHeaderResponse(): RX: 'icy-url:http://www.3fm.nl'
[V][HTTPClient.cpp:1123] handleHeaderResponse(): RX: 'Server: Icecast 2.4.0-kh10'
[V][HTTPClient.cpp:1123] handleHeaderResponse(): RX: 'Cache-Control: no-cache, no-store'
[V][HTTPClient.cpp:1123] handleHeaderResponse(): RX: 'Access-Control-Allow-Origin: *'
[V][HTTPClient.cpp:1123] handleHeaderResponse(): RX: 'Access-Control-Allow-Headers: Origin, Accept, X-Requested-With, Content-Type'
[V][HTTPClient.cpp:1123] handleHeaderResponse(): RX: 'Access-Control-Allow-Methods: GET, OPTIONS, HEAD'
[V][HTTPClient.cpp:1123] handleHeaderResponse(): RX: 'Connection: Close'
[V][HTTPClient.cpp:1123] handleHeaderResponse(): RX: 'Expires: Mon, 26 Jul 1997 05:00:00 GMT'
[V][HTTPClient.cpp:1123] handleHeaderResponse(): RX: 'icy-metaint:16000'
[V][HTTPClient.cpp:1123] handleHeaderResponse(): RX: ''
[D][HTTPClient.cpp:1158] handleHeaderResponse(): code: 200
METADATA(ICY) 'StreamTitle' = 'MARSHMELLO FT YUNGBLUD&BLACKBEAR - TONGUE TIED'
[D][HTTPClient.cpp:361] disconnect(): still data in buffer (5437), clean up.

[D][HTTPClient.cpp:370] disconnect(): tcp stop

[V][HTTPClient.cpp:235] beginInternal(): url: http://icecast.omroep.nl/radio5-bb-mp3
[D][HTTPClient.cpp:276] beginInternal(): host: icecast.omroep.nl port: 80 url: /radio5-bb-mp3
[D][HTTPClient.cpp:1025] connect():  connected to icecast.omroep.nl:80
[V][HTTPClient.cpp:1123] handleHeaderResponse(): RX: 'HTTP/1.0 200 OK'
[V][HTTPClient.cpp:1123] handleHeaderResponse(): RX: 'Content-Type: audio/mpeg'

[Jeroen88]

Although I am not sure, I think it is because ::disconnect() waits until the read buffer is empty, but the radio channel keeps on streaming new data into it. Just a wild guess, but maybe you could delete file in stead of file->close(), and of course new it afterwards

[CelliesProjects]

I think I already went that way. I have several iterations on my desktop and (will have to check) I had the same problem with delete\new.

[WebDust21]

I'm having almost the exactly same bug with HTTPClient. Only mine occurs with a known-length file download: it connects and starts downloading instantly, no issues. If I abort the download, it quits instantly. However, when I try to download the file a second time, HTTPClient locks up on "GET" for 10-15 seconds (100% of the time). But after it times out and fails (I can provide error codes if they are of interest), I can "GET" again, and it goes right through with no hesitation.
Without fail...first time perfect. Second time locks up 10-15 seconds (until the first "GET" fails), then the second one goes right through, and works fine. 100% of the time, reproducible without question.

Like this:

if (!http.begin(FilePath)) {Status = usErr_Path; goto ErrEnd;}  // "BEGIN" only parses the path to verify all the necessary parts are present.  Does not actually connect
    
    // Attempt the actual connection request 2x.  Seems there is an Arduino bug causing an aborted HTTPClient to fail on the following connection attempt.  So we try twice...
    //NOTICE: "httpCode" will contain negative values if no valid HTTP code received.
    httpCode = http.GET();
    if (httpCode != 200) {httpCode = http.GET();}
...

[CelliesProjects]

Possibly related: #3722

[CelliesProjects]

I am now pretty sure the bug is in the ESP8266audio library.
https://github.com/schreibfaul1/ESP32-audioI2S works out of the box.
Closing this for now.