Problems with communication-generator-rtsp.ino example

[Nils-github]

I successfully build the communication-generator-rtsp.ino example and flashed it on an ESP-WROOM-32.
I get no sound in VLC and the (Debug) log shows "RTP Stream can't keep up" messages for al packets and then the WatchDog timer reboots the board.
Do you have any suggestions what i have done wrong?

The logs:
`
ets Jun 8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0030,len:4980
load:0x40078000,len:16612
load:0x40080400,len:3480
entry 0x400805b4
[D] SoundGenerator.h : 40 - bool audio_tools::SoundGenerator::begin() [with T = short int]
[I] AudioTypes.h : 126 - SoundGenerator: sample_rate: 16000 / channels: 1 / bits_per_sample: 16
[I] Buffers.h : 420 - resize: 2
[D] Allocator.h : 76 - Allocated 2
[D] SoundGenerator.h : 704 - step: 11.112301
.................................
connect to rtsp://10.42.0.236:554

[I] RTSPServer.h : 198 - Running RTSP server on port 554
[I] RTSPAudioStreamer.h : 151 - initAudioSource
[I] RTSPAudioStreamer.h : 160 - m_fragmentSize (bytes): 640
[I] RTSPServer.h : 202 - RTSP server started on port 554
[I] Task.h : 58 - staring task
[D] RTSPServer.h : 225 - Server thread listening... (numClients: 0)
[D] RTSPServer.h : 225 - Server thread listening... (numClients: 0)
[D] RTSPServer.h : 225 - Server thread listening... (numClients: 0)
[D] RTSPServer.h : 225 - Server thread listening... (numClients: 0)
[I] RTSPServer.h : 232 - Client connected
[I] Task.h : 58 - staring task
[D] RTSPServer.h : 288 - RTSP Task running
[I] RTSPSession.h : 102 - RTSP session created
[I] RTSPServer.h : 297 - Session ready
[D] RTSPSession.h : 149 - handleRequests
[D] RTSPSession.h : 286 - init
[D] Allocator.h : 76 - Allocated 10000
[D] Allocator.h : 76 - Allocated 10000
[D] Allocator.h : 76 - Allocated 100
[D] Allocator.h : 76 - Allocated 100
[D] Allocator.h : 76 - Allocated 100
[D] Allocator.h : 76 - Allocated 256
[D] Allocator.h : 76 - Allocated 1024
[D] Allocator.h : 76 - Allocated 2251
[D] Allocator.h : 76 - Allocated 1024
[D] Allocator.h : 76 - Allocated 1024
[D] Allocator.h : 76 - Allocated 256
[D] Allocator.h : 76 - Allocated 256
[D] Allocator.h : 76 - Allocated 100
[I] RTSPServer.h : 238 - Number of clients: 1
[D] RTSPServer.h : 225 - Server thread listening... (numClients: 1)
[D] RTSPServer.h : 242 - Waiting for current session to end (numClients: 1)
[D] RTSPServer.h : 225 - Server thread listening... (numClients: 1)
[D] RTSPServer.h : 242 - Waiting for current session to end (numClients: 1)
[D] RTSPServer.h : 225 - Server thread listening... (numClients: 1)
[D] RTSPServer.h : 242 - Waiting for current session to end (numClients: 1)
[D] RTSPServer.h : 225 - Server thread listening... (numClients: 1)
[D] RTSPServer.h : 242 - Waiting for current session to end (numClients: 1)
[D] RTSPServer.h : 225 - Server thread listening... (numClients: 1)
[D] RTSPServer.h : 242 - Waiting for current session to end (numClients: 1)
[I] RTSPSession.h : 397 - aRequest: ------------------------␊
SETUP rtsp://10.42.0.236:554 RTSP/1.0
CSeq: 0
Transport: RTP/AVP;unicast;client_port=9424-9425

[I] RTSPSession.h : 500 - RTSP received SETUP
[D] RTSPSession.h : 543 - m_URLHostPort: 10.42.0.236:554
[D] RTSPSession.h : 585 - m_URLSuffix:
[D] RTSPSession.h : 586 - m_URLPreSuffix:
[D] RTSPSession.h : 587 - URL Suffix parse succeeded: 0
[D] RTSPSession.h : 609 - Look for CSeq success: 1
[I] RTSPSession.h : 833 - SETUP peer resolved: 10.42.0.1:40392 (RTP client_port=9424)
[I] RTSPAudioStreamer.h : 210 - RTP Streamer set up with client IP 10.42.0.1 and client Port 9424

RTSP/1.0 200 OK
CSeq: 0
Date: Thu, Jan 01 1970 00:00:30 GMT
Session: 8430
Transport: RTP/AVP;unicast;client_port=9424-9425;server_port=6970-6971;ssrc=13F97E67

[D] RTSPServer.h : 308 - Request handling successful
[D] RTSPSession.h : 149 - handleRequests
[I] RTSPServer.h : 310 - Request handling timed out or no data yet
[D] RTSPSession.h : 149 - handleRequests
[D] RTSPServer.h : 225 - Server thread listening... (numClients: 1)
[D] RTSPServer.h : 242 - Waiting for current session to end (numClients: 1)
[D] RTSPServer.h : 225 - Server thread listening... (numClients: 1)
[D] RTSPServer.h : 242 - Waiting for current session to end (numClients: 1)
[D] RTSPServer.h : 225 - Server thread listening... (numClients: 1)
[D] RTSPServer.h : 242 - Waiting for current session to end (numClients: 1)
[D] RTSPServer.h : 225 - Server thread listening... (numClients: 1)
[D] RTSPServer.h : 242 - Waiting for current session to end (numClients: 1)
[D] RTSPServer.h : 225 - Server thread listening... (numClients: 1)
[D] RTSPServer.h : 242 - Waiting for current session to end (numClients: 1)
[I] RTSPSession.h : 397 - aRequest: ------------------------␊
PLAY rtsp://10.42.0.236:554/stream=0 RTSP/1.0
CSeq: 1
Session: 8430

[I] RTSPSession.h : 500 - RTSP received PLAY
[D] RTSPSession.h : 543 - m_URLHostPort: 10.42.0.236:554
[D] RTSPSession.h : 553 - m_URLPath: /stream=0
[D] RTSPSession.h : 585 - m_URLSuffix: 0
[D] RTSPSession.h : 586 - m_URLPreSuffix: stream
[D] RTSPSession.h : 587 - URL Suffix parse succeeded: 1
[D] RTSPSession.h : 609 - Look for CSeq success: 1

RTSP/1.0 200 OK
CSeq: 1
Range: npt=0.000-
Session: 8430
RTP-Info: url=rtsp://10.42.0.236:554/trackID=0;seq=3048;rtptime=0

[D] RTSPServer.h : 225 - Server thread listening... (numClients: 1)
[I] RTSPAudioStreamer.h : 704 - Starting RTP Stream with timer
[I] RTSPAudioStreamer.h : 345 - Starting audio source (base)
[D] Allocator.h : 76 - Allocated 3073
[I] RTSPAudioStreamer.h : 151 - initAudioSource
[I] RTSPAudioStreamer.h : 160 - m_fragmentSize (bytes): 640
[I] RTSPAudioSource.h : 142 - virtual void audio_tools::RTSPAudioSource::start()
[I] RTSPAudioStreamer.h : 354 - Audio source started - ready for manual streaming
[D] AudioTimerESP32.h : 38 - virtual bool audio_tools::TimerAlarmRepeatingDriverESP32::begin(audio_tools::repeating_timer_callback_t, uint32_t, audio_tools::TimeUnit)
[I] AudioTimerESP32.h : 53 - Timer every: 1 us
[D] AudioTimerESP32.h : 69 - esp_timer_create: 0x3ffc3ac8
[D] AudioTimerESP32.h : 79 - esp_timer_start_periodic
[I] RTSPAudioStreamer.h : 715 - timer: 20000 us
[I] RTSPAudioStreamer.h : 717 - Free heap size: 117 KB
[D] RTSPServer.h : 308 - Request handling successful
[D] RTSPSession.h : 149 - handleRequests
[D] RTSPServer.h : 242 - Waiting for current session to end (numClients: 1)
[D] RTSPAudioStreamer.h : 478 - timerCallback
[D] RTSPAudioSource.h : 128 - readDataTo: 640
[D] AudioStreams.h : 457 - GeneratedSoundStream::readBytes: 640
[D] SoundGenerator.h : 63 - readBytes: 640
[I] RTSPAudioStreamer.h : 322 - Read 640 bytes from audio source
[I] RTSPAudioStreamer.h : 607 - Sending UDP: 652 bytes (to 10.42.0.1:9424)
[D] RTSPAudioStreamer.h : 496 - 320 samples (ts inc) sent; timestamp: 320
[W] RTSPAudioStreamer.h : 502 - RTP Stream can't keep up (took 33898 us, 20000 is max)!
[D] RTSPAudioStreamer.h : 478 - timerCallback
[D] RTSPAudioSource.h : 128 - readDataTo: 640
[D] AudioStreams.h : 457 - GeneratedSoundStream::readBytes: 640
[D] SoundGenerator.h : 63 - readBytes: 640
[I] RTSPAudioStreamer.h : 322 - Read 640 bytes from audio source
[I] RTSPAudioStreamer.h : 607 - Sending UDP: 652 bytes (to 10.42.0.1:9424)
[D] RTSPAudioStreamer.h : 496 - 320 samples (ts inc) sent; timestamp: 640
[W] RTSPAudioStreamer.h : 502 - RTP Stream can't keep up (took 33651 us, 20000 is max)!
[D] RTSPAudioStreamer.h : 478 - timerCallback
[D] RTSPAudioSource.h : 128 - readDataTo: 640
[D] AudioStreams.h : 457 - GeneratedSoundStream::readBytes: 640
[D] SoundGenerator.h : 63 - readBytes: 640
[I] RTSPAudioStreamer.h : 322 - Read 640 bytes from audio source
[I] RTSPAudioStreamer.h : 607 - Sending UDP: 652 bytes (to 10.42.0.1:9424)
[D] RTSPAudioStreamer.h : 496 - 320 samples (ts inc) sent; timestamp: 960
[W] RTSPAudioStreamer.h : 502 - RTP Stream can't keep up (took 33443 us, 20000 is max)!
[D] RTSPAudioStreamer.h : 478 - timerCallback
[D] RTSPAudioSource.h : 128 - readDataTo: 640
[D] AudioStreams.h : 457 - GeneratedSoundStream::readBytes: 640
[D] SoundGenerator.h : 63 - readBytes: 640
[I] RTSPAudioStreamer.h : 322 - Read 640 bytes from audio source
[I] RTSPAudioStreamer.h : 607 - Sending UDP: 652 bytes (to 10.42.0.1:9424)
[D] RTSPAudioStreamer.h : 496 - 320 samples (ts inc) sent; timestamp: 1280
[W] RTSPAudioStreamer.h : 502 - RTP Stream can't keep up (took 33717 us, 20000 is max)!
[D] RTSPAudioStreamer.h : 478 - timerCallback
[D] RTSPAudioSource.h : 128 - readDataTo: 640
[D] AudioStreams.h : 457 - GeneratedSoundStream::readBytes: 640
[D] SoundGenerator.h : 63 - readBytes: 640
[I] RTSPAudioStreamer.h : 322 - Read 640 bytes from audio source
[I] RTSPAudioStreamer.h : 607 - Sending UDP: 652 bytes (to 10.42.0.1:9424)
[D] RTSPAudioStreamer.h : 496 - 320 samples (ts inc) sent; timestamp: 1600
[W] RTSPAudioStreamer.h : 502 - RTP Stream can't keep up (took 33575 us, 20000 is max)!
[D] RTSPAudioStreamer.h : 478 - timerCallback
[D] RTSPAudioSource.h : 128 - readDataTo: 640
[D] AudioStreams.h : 457 - GeneratedSoundStream::readBytes: 640
[D] SoundGenerator.h : 63 - readBytes: 640
[I] RTSPAudioStreamer.h : 322 - Read 640 bytes from audio source
[I] RTSPAudioStreamer.h : 607 - Sending UDP: 652 bytes (to 10.42.0.1:9424)
[D] RTSPAudioStreamer.h : 496 - 320 samples (ts inc) sent; timestamp: 1920
[W] RTSPAudioStreamer.h : 502 - RTP Stream can't keep up (took 33710 us, 20000 is max)!
[D] RTSPAudioStreamer.h : 478 - timerCallback
......................................................................................
[D] SoundGenerator.h : 63 - readBytes: 640
[I] RTSPAudioStreamer.h : 322 - Read 640 bytes from audio source
[I] RTSPAudioStreamer.h : 607 - Sending UDP: 652 bytes (to 10.42.0.1:9424)
[D] RTSPAudioStreamer.h : 496 - 320 samples (ts inc) sent; timestamp: 34880
E (37606) task_wdt: Task watchdog got triggered. The following tasks/users did not reset the watchdog in time:
E (37606) task_wdt: - IDLE0 (CPU 0)
E (37606) task_wdt: Tasks currently running:
E (37606) task_wdt: CPU 0: wifi
E (37606) task_wdt: CPU 1: IDLE1
E (37606) task_wdt: Aborting.
E (37606) task_wdt: Print CPU 0 (current core) backtrace

Backtrace: 0x4014cb0b:0x3ffd5090 0x40147969:0x3ffd5120 0x4017adc9:0x3ffd5230 0x4017ae25:0x3ffd5290 0x4017d309:0x3ffd52b0 0x40177b0b:0x3ffd52d0 0x4008e049:0x3ffd5300

ELF file SHA256: 23c49cbd9

Rebooting...
ets Jun 8 2016 00:22:57

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
`

[pschatzmann]

First of all, this does not work with log level debug: This is adding too much latency.
I was testing with ffplay and noticed that I was running into a timeout which was set too low. I increased the timout and and it it working w/o any issues using ffmpeg now. I even increased to sample rate to 48000 and with log level Warning this also works w/o issues. Example command

ffplay rtsp://192.168.1.43:554/

I was running down the VLC rabbit hole and found that this can't work if RTSP has not been enabled at compile time.
You can double-check if it is available in Tools - Preferences.
Click on Show Settings: all
In Input / Codecs - Demuxers you must have an entry for RTP/RTSP. If this is missing, It will not work...
Looking at your log which start with SETUP this support is not available!

I was testing with a VLC version that supports RTSP and I confirm that it was indeed working...

[Nils-github]

Thanks for your support!
I used VLC with RTSP in the past and wasn't aware that they removed RTSP support in Debian. I installed the snap version and now it works.
I still see scary messages with the default log level Info:
"[I] RTSPServer.h : 312 - Request handling timed out or no data yet"
Is it that the generator can't keep up with the streaming server?

[pschatzmann]

Thats just an info from the session manager informing that no request was received from the client during the timeout period.