Buffer problems

[ghost]

Hello, I'm using an ESP32 with PSRAM, when I play a stream after some time it stops, below I leave the log to see if anyone can help me.

It seems to me that the buffer is not filled with data again

[D][esp32-hal-psram.c:60] psramInit(): PSRAM enabled
[D][WiFiGeneric.cpp:374] _eventCallback(): Event: 0 - WIFI_READY
[D][WiFiGeneric.cpp:374] _eventCallback(): Event: 2 - STA_START
[D][WiFiGeneric.cpp:374] _eventCallback(): Event: 4 - STA_CONNECTED
[D][WiFiGeneric.cpp:374] _eventCallback(): Event: 7 - STA_GOT_IP
[D][WiFiGeneric.cpp:419] _eventCallback(): STA IP: 192.168.1.143, MASK: 255.255.255.0, GW: 192.168.1.254

You can connect to 192.168.1.143
[D][sketch_apr06a.ino:74] setup(): Total heap: 327224
[D][sketch_apr06a.ino:75] setup(): Free heap: 215756
[D][sketch_apr06a.ino:76] setup(): Total PSRAM: 4194252
[D][sketch_apr06a.ino:77] setup(): Free PSRAM: 4194252
info        PSRAM found, inputBufferSize: 298399 bytes
[V][ssl_client.cpp:265] stop_ssl_socket(): Cleaning SSL connection.
info        buffers freed, free Heap: 212704 bytes
info        Connect to new host: "https://centova.radio.com.pt/proxy/401?mp=/stream"
info        Connect to "centova.radio.com.pt" on port 443, extension "/proxy/401?mp=/stream"
[V][ssl_client.cpp:59] start_ssl_client(): Free internal heap before TLS 214228
[V][ssl_client.cpp:65] start_ssl_client(): Starting socket
[V][ssl_client.cpp:104] start_ssl_client(): Seeding the random number generator
[V][ssl_client.cpp:113] start_ssl_client(): Setting up the SSL/TLS structure...
[I][ssl_client.cpp:127] start_ssl_client(): WARNING: Skipping SSL Verification. INSECURE!
[V][ssl_client.cpp:197] start_ssl_client(): Setting hostname for TLS session...
[V][ssl_client.cpp:212] start_ssl_client(): Performing the SSL/TLS handshake...
[V][ssl_client.cpp:233] start_ssl_client(): Verifying peer X.509 certificate...
[V][ssl_client.cpp:242] start_ssl_client(): Certificate verified.
[V][ssl_client.cpp:257] start_ssl_client(): Free internal heap after TLS 173220
[E][WiFiClient.cpp:309] setOption(): fail on fd -1, errno: 9, "Bad file number"
[V][ssl_client.cpp:295] send_ssl_data(): Writing HTTP request with 128 bytes...
info        SSL has been established in 1041 ms, free Heap: 171308 bytes
inBufferFilled: 0
inBufferFree: 298399
inBufferFilled: 0
inBufferFree: 298399
info        HTTP/1.1 200 OK
info        server: cc-web/1.6.3
info        date: Fri, 09 Apr 2021 18:58:12 GMT
info        content-type: audio/mpeg, format is mp3
info        MP3Decoder has been initialized, free Heap: 158044 bytes
info        chunked data transfer
info        icy-notice1: <BR>This stream requires <a href="http://www.winamp.com">Winamp</a><BR>
info        icy-notice2: Shoutcast DNAS/posix(linux x64) v2.6.0.753<BR>
info        access-control-allow-origin: *
info        icy-name: Radio ORBITAL
station     Radio ORBITAL
bitrate     128000
info        icy-sr: 44100
info        icy-url: http://www.orbital.pt
icyurl      http://www.orbital.pt
info        x-clacks-overhead: GNU Terry Pratchett
info        Switch to DATA, metaint is 8192
lasthost    centova.radio.com.pt/proxy/401
info        inputbuffer is being filled
streamtitle ALESSO  - LEAVE A LITTLE LOVE
info        StreamTitle="ALESSO  - LEAVE A LITTLE LOVE"
inBufferFilled: 81920
inBufferFree: 216479
info        stream ready
info        buffer filled in 908 ms
info        syncword found at pos 0
info        Channels: 2
info        SampleRate: 44100
info        BitsPerSample: 16
info        BitRate: 128000
inBufferFilled: 105440
inBufferFree: 192959
inBufferFilled: 109240
inBufferFree: 189159
inBufferFilled: 110195
inBufferFree: 188204
inBufferFilled: 113993
inBufferFree: 184406
inBufferFilled: 118625
inBufferFree: 179774
inBufferFilled: 119161
inBufferFree: 179238
inBufferFilled: 119697
inBufferFree: 178702
inBufferFilled: 124328
inBufferFree: 174071
inBufferFilled: 124447
inBufferFree: 173952
inBufferFilled: 124983
inBufferFree: 173416
inBufferFilled: 129615
inBufferFree: 168784
inBufferFilled: 130151
inBufferFree: 168248
inBufferFilled: 130270
inBufferFree: 168129
inBufferFilled: 134901
inBufferFree: 163498
inBufferFilled: 135437
inBufferFree: 162962
inBufferFilled: 135556
inBufferFree: 162843
inBufferFilled: 136092
inBufferFree: 162307
inBufferFilled: 140724
inBufferFree: 157675
inBufferFilled: 141260
inBufferFree: 157139
inBufferFilled: 141379
inBufferFree: 157020
inBufferFilled: 141953
inBufferFree: 156446
inBufferFilled: 146546
inBufferFree: 151853
inBufferFilled: 146665
inBufferFree: 151734
inBufferFilled: 147618
inBufferFree: 150781
inBufferFilled: 151833
inBufferFree: 146566
inBufferFilled: 152369
inBufferFree: 146030
inBufferFilled: 152905
inBufferFree: 145494
inBufferFilled: 157119
inBufferFree: 141280
inBufferFilled: 157655
inBufferFree: 140744
inBufferFilled: 158191
inBufferFree: 140208
inBufferFilled: 162406
inBufferFree: 135993
inBufferFilled: 162942
inBufferFree: 135457
inBufferFilled: 163061
inBufferFree: 135338
inBufferFilled: 167692
inBufferFree: 130707
inBufferFilled: 168645
inBufferFree: 129754
inBufferFilled: 168764
inBufferFree: 129635
inBufferFilled: 165205
inBufferFree: 133194
inBufferFilled: 148942
inBufferFree: 149457
inBufferFilled: 133096
inBufferFree: 165303
inBufferFilled: 117250
inBufferFree: 181149
inBufferFilled: 100987
inBufferFree: 197412
inBufferFilled: 85141
inBufferFree: 213258
inBufferFilled: 69295
inBufferFree: 229104
inBufferFilled: 53032
inBufferFree: 245367
inBufferFilled: 37186
inBufferFree: 261213
inBufferFilled: 21340
inBufferFree: 277059
inBufferFilled: 5494
inBufferFree: 292905
info        slow stream, dropouts are possible
inBufferFilled: 1324
inBufferFree: 297075
info        slow stream, dropouts are possible

[schreibfaul1]

It looks more like the stream will break. In processWebStream() availableBytes will become zero

[ghost]

@schreibfaul1 Hi, I thank you for the quick response. Are you believing that the problem is with the link in the stream ??

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[smithjacobj]

I'm hoping it's ok to leave a message on stale/wontfix issues.

I was using this library as part of an ESPHome project (github.com/smithjacobj/dementia-radio-muse-luxe) and ran into this problem repeatedly. I don't have a device with JTAG access so I haven't been able to break down the issue more, but there's a race condition somewhere that corrupts m_datamode resetting it to AUDIO_NONE, seeming to be somewhere in the hot loop in playSample. Some of the serial debugging logging I did in lieu of JTAG fixed the issue (because I used mutexes to validate the memory state of my logging vars) but hasn't actually pinpointed where the race condition is caused. I tried only wrapping m_datamode in a std::atomic but that doesn't resolve it, but also wrapping m_curSample fixed it. I wrapped m_validSamples for good measure.

See https://github.com/smithjacobj/dementia-radio-muse-luxe/blob/faf78ec9e47810c49526d2ec963484505dcfbea6/lib/ESP32-audioI2S/src/Audio.h#L520-L522

[schreibfaul1]

So far, I have not been able to observe this behaviour in my test environments. But it is conceivable in systems with multiple tasks. I don't use ESPHome, but I want there to be no problems there either. I have implemented your suggestion in the "Arduino V3.0" branch, which will become the master in the upcoming stable Arduino 3.0x version.

[smithjacobj]

Cool, I hope it helps, but as I haven't been able to do proper tooled debugging, it may just be a Band-Aid that gets called often enough to enforce memory ordering on something else.