search

sle118 / squeezelite-esp32

ESP32 Music streaming based on Squeezelite, with support for multi-room sync, AirPlay, Bluetooth, Hardware buttons, display and more
1.25k stars 114 forks source link

AirPlay trouble on ESParagus: poor audio & "not enough space" or "packet too late" #446

Open roens opened 1 month ago

roens commented 1 month ago

Describe the bug

I've got a "Loud" unit from the ESParagus folks. I'm using it for AirPlay (from Music in macOS). But it's having trouble playing consistently. In the output via telnet, I see lots of each:

As far as I know, no device(s) are experiencing WiFi trouble. I'm using Ruckus WiFi6-capable APs, with a 10GbE router running OPNsense.

Preliminary Information

  1. Firmware Version: I2S-4MFlash-1681
  2. Plugin Version: Mode: Squeezelite-ESP32

Hardware Details

Please describe your hardware setup:

NVS Settings

Settings, afaik, are default, aside from setting device name and disabling modes I do not intend to use (bluetooth & spotify).


{
  "a2dp_ctmt": "1000",
  "a2dp_ctrld": "500",
  "a2dp_dev_name": "ESParagus-Kitchen",
  "a2dp_sink_name": "SMSL BT4.2",
  "a2dp_spin": "0000",
  "actrls_config": "",
  "airplay_name": "ESParagus-Kitchen",
  "airplay_port": "5000",
  "ap_channel": "1",
  "ap_ip_address": "192.168.4.1",
  "ap_ip_gateway": "192.168.4.1",
  "ap_ip_netmask": "255.255.255.0",
  "ap_pwd": "squeezelite",
  "ap_ssid": "ESParagus-Kitchen",
  "autoexec": "1",
  "autoexec1": "squeezelite -o i2s -n ESParagus-Kitchen -b 500:2000 -C 30 -d all=info",
  "bat_config": "",
  "bt_name": "ESParagus-Kitchen",
  "bt_sink_pin": "1234",
  "bt_sink_volume": "127",
  "bypass_wm": "0",
  "cspot_config": "{\t\"deviceName\":\t\"ESParagus-Kitchen\",\t\"bitrate\":\t160,\t\"zeroConf\":\t1}",
  "dac_config": "model=I2S,bck=26,ws=25,do=22",
  "dac_controlset": "",
  "dhcp_tmout": "8",
  "display_config": "",
  "enable_airplay": "Y",
  "enable_bt_sink": "N",
  "enable_cspot": "N",
  "equalizer": "",
  "eth_config": "",
  "ethtmout": "8",
  "gpio_exp_config": "",
  "host_name": "ESParagus-Kitchen",
  "i2c_config": "",
  "jack_mutes_amp": "n",
  "led_brightness": "",
  "led_vu_config": "WS2812,length=1,gpio=33,scale=100",
  "lms_ctrls_raw": "n",
  "loudness": "0",
  "metadata_config": "",
  "model_config": "",
  "ota_erase_blk": "249856",
  "ota_prio": "6",
  "ota_stack": "10240",
  "pollmin": "15",
  "pollmx": "600",
  "rel_api": "https://api.github.com/repos/sle118/squeezelite-esp32/releases",
  "release_url": "CONFIG_SQUEEZELITE_ESP32_RELEASE_URL",
  "rotary_config": "",
  "set_GPIO": "39=ir",
  "sleep_config": "",
  "spdif_config": "",
  "spi_config": "",
  "stats": "N",
  "target": "",
  "telnet_block": "500",
  "telnet_buffer": "40000",
  "telnet_enable": "Y"
}

Logs

I can't use your web installer tool as I do not use Chrome. Log collected via telnet, as device is located where direct connection is complicated.

I've had to truncate repititous sections so as to fit within the description length limit (maximum is 65536 characters).


I (1624) esp_app_main: Setting up config subsystem.
W (1704) nvs_utilities: Configuration memory usage.  Heap internal:228675 (min:228535) (used:216) external:4054831 (min:4047227) (used:15556)
I (1704) esp_app_main: Registering default values
I (1704) system_api: Base MAC address is not set
I (1704) system_api: read default base MAC address from EFUSE
W (1704) config: Waiting for config commit ...
I (2704) config: configuration has some uncommitted entries
I (2704) config: Committing configuration to nvs. Locking config object.
I (2704) config: Done Committing configuration to nvs.
I (2704) config: Config committed!
I (2704) esp_app_main: Configuring services
I (2714) services: Configuring I2C sda:-1 scl:-1 port:1 speed:400000
W (2714) services: no I2C configured
I (2714) services: Configuring SPI mosi:-1 miso:-1 clk:-1 host:1 dc:-1
W (2714) services: no SPI configured
W (2714) led: LED GPIO -1 ignored
W (2714) led: LED GPIO -1 ignored
I (2714) led: Configuring LEDs green:-1 (on:0 rmt:-1 -1% ), red:-1 (on:0 rmt:-1 -1% )
I (2714) battery: No battery
I (2714) monitor: Initializing monitoring
I (2714) monitor: Heap internal:229351 (min:228347) external:4038247 (min:4038231) dma:221611 (min:220623)
I (2714) esp_app_main: Initializing display
I (2714) display: Trying to configure display with N/A
W (2714) display: No display driver
I (2714) esp_app_main: Initializing led_vu
I (2714) led_vu: vu meter using length:1 left:0 right:0 status:0 scale:100
I (2714) led_vu: led_vu using gpio:33 length:1 on channel:0
I (2714) esp_app_main: Checking for update url
W (2714) config: Value not found for key fwurl
I (2714) IR: Starting Infrared Receiver mode nec on gpio 39 and channel 7
I (2714) buttons: Created infrared receiver using GPIO 39
I (2714) buttons: starting button tasks
W (2714) config: Value not found for key 
I (2714) esp_app_main: Starting Network Manager
W (2714) config: Value not found for key apdelay
I (2714) uart: queue free spaces: 3
I (2714) network_handlers: Network manager configuration: polling max 10176, polling min 15000, ap delay 20000, dhcp timeout 8000, eth timeout 8000
I (2724) http_server: Initializing HTTP Server
I (2734) network_ethernet: Attempting to initialize Ethernet
I (2734) network_ethernet: No Ethernet configuration, or configuration invalid
I (2744) wifi:wifi driver task: 3ffdf1c4, prio:23, stack:6656, core=0
I (2744) wifi:wifi firmware version: 9ec65ef
I (2744) wifi:wifi certification version: v7.0
I (2744) wifi:config NVS flash: enabled
I (2744) wifi:config nano formating: disabled
I (2744) wifi:Init data frame dynamic rx buffer num: 40
I (2744) wifi:Init management frame dynamic rx buffer num: 40
I (2744) wifi:Init management short buffer num: 32
I (2754) wifi:Init static tx buffer num: 12
I (2754) wifi:Init tx cache buffer num: 32
I (2754) wifi:Init static rx buffer size: 1600
I (2754) wifi:Init static rx buffer num: 12
I (2754) wifi:Init dynamic rx buffer num: 40
I (2754) wifi_init: tcpip mbox: 32
I (2754) wifi_init: udp mbox: 32
I (2754) wifi_init: tcp mbox: 32
I (2754) wifi_init: tcp tx win: 8192
I (2754) wifi_init: tcp rx win: 32768
I (2754) wifi_init: tcp mss: 1440
I (2754) wifi_init: WiFi/LWIP prefer SPIRAM
I (2754) network_wifi: Starting wifi
I (2754) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (2854) wifi:mode : sta (08:b6:1f:b7:ae:c0)
I (2854) wifi:enable tsf
I (2854) network_handlers: Existing wifi config found. Attempting to connect.
I (2854) network: Starting DHCP client
I (2854) network_wifi: Wifi Connecting to darkdarkdork…...

Type 'help' to get the list of commands.
Use UP/DOWN arrows to navigate through command history.
Press TAB when typing command name to auto-complete.

To automatically execute lines at startup:
    Set NVS variable autoexec (U8) = 1 to enable, 0 to disable automatic execution.
    Set NVS variable autoexec[1~9] (string)to a command that should be executed automatically

****************************
Your terminal application does not support escape sequences.
Line editing and history features are disabled.
On Windows, try using Putty instead.
****************************
W (2884) console: Processing autoexec commands while network manager active.  Wifi related commands will be ignored.
I (2884) console: autoexec is set to perform auto-process
I (2884) console: Running command autoexec1 = squeezelite -o i2s -n ESParagus-Kitchen -b 500:2000 -C 30 -d all=info
W (2884) config: Value not found for key autoexec2
squeezelite-esp32> I (2884) squeezelite_cmd: Calling squeezelite
[00:03:09.756] sb_controls_init:249 initializing audio (buttons/rotary/ir) controls (raw:0)
[00:03:09.756] sendSETD:440 sending dimension display:0x0 led_config:1
[00:03:09.758] stream_init:539 init stream
[00:03:09.758] output_init_embedded:78 init device: i2s
[00:03:09.759] output_init_common:433 supported rates: 96000 88200 48000 44100 32000 24000 22050 16000 12000 11025 8000 
[00:03:09.760] output_init_embedded:100 init I2S/SPDIF
W (2894) DAC core: DAC does not use i2c
I (2894) DAC external: DAC on I2C @0
W (2894) DAC external: no i2c controlset found
[00:03:09.761] output_init_i2s:347 configuring MCLK on GPIO -1
[00:03:09.761] output_init_i2s:359 invalid MCK gpio -1
I (2894) I2S: DMA Malloc info, datalen=blocksize=4088, dma_buf_count=12
I (2894) I2S: APLL: Req RATE: 44100, real rate: 44099.988, BITS: 32, CLKM: 1, BCK_M: 8, MCLK: 22579194.000, SCLK: 2822399.250000, diva: 1, divb: 0
[00:03:09.763] output_init_i2s:376 I2S DAC using I2S bck:26, ws:25, do:22, mute:-1:0 (res:0)
[00:03:09.763] output_init_i2s:396 Initializing I2S mode normal with rate: 44100, bits per sample: 32, buffer frames: 512, number of buffers: 12 
[00:03:09.764] equalizer_set_samplerate:124 no equalizer with 32 bits samples
[00:03:09. output_thread_i2s:518 Output state is -1
[00:03:09.765] output_visu_init:75 Initialize VISUEXPORT 512 32 bits samples
[00:03:09.765] output_thread_i2s:522 switching off amp GPIO -1
[00:03:09.766] output_init_embedded:108 init completed.
[00:03:09.766] decode_init:153 init decode
[00:03:09.766] register_alac:547 using alac to decode alc
[00:03:09.766] register_helixaac:686 using helix-aac to decode aac
[00:03:09.766] register_vorbis:526 using vorbis to decode ogg
[00:03:09.767] register_opus:458 using opus to decode ops
[00:03:09.767] register_flac:338 using flac to decode ogf,flc
[00:03:09.767] register_pcm:483 using pcm to decode aif,pcm
[00:03:09.767] register_mad:417 using mad to decode mp3
[00:03:09.768] register_external:469 Initializing AirPlay sink
[00:03:09.771] discover_server:844 sending discovery 25
[00:03:09.771] discover_server:848 error sending discovery
I (5264) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (5264) wifi:state: init -> auth (b0)
I (6604) wifi:state: auth -> assoc (0)
I (6604) wifi:state: assoc -> run (10)
I (6644) wifi:connected with darkdarkdork…, aid = 4, channel 1, BW20, bssid = 34:15:93:56:a2:e1
I (6644) wifi:security: WPA3-SAE, phy: bgn, rssi: -42
I (6644) wifi:pm start, type: 1

I (6654) network: Got an IP address from interface Wifi. IP=10.4.2.151, Gateway=10.4.2.1, NetMask=255.255.255.0, Address was changed
I (6654) esp_netif_handlers: sta ip: 10.4.2.151, mask: 255.255.255.0, gw: 10.4.2.1
I (6654) esp_app_main: Network connected and mDNS initialized with ESParagus-Kitchen
[00:03:13.531] raop_sink_start:178 starting Airplay for ip 10.4.2.151 with servicename ESParagus-Kitchen
[00:03:13.532] raop_create:201 starting mDNS with 08B61FB7AEC0@ESParagus-Kitchen
I (6734) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (7864) httpd_handlers: serving /status.json to peer 10.4.2.153 port 18163
[00:03:14.775] discover_server:844 sending discovery 24
[00:03:19.775] discover_server:844 sending discovery 23
[00:03:24.775] discover_server:844 sending discovery 22
[00:03:24.792] rtsp_thread:397 got RTSP connection 54
[00:03:24.837] rtsp_thread:413 RTSP close 54
I (22254) httpd_handlers: serving /status.json to peer 10.4.2.153 port 22515
[00:03:29.775] discover_server:844 sending discovery 21
[00:03:34.775] discover_server:844 sending discovery 20
[00:03:39.775] discover_server:844 sending discovery 19
[00:03:44.775] discover_server:844 sending discovery 18
[00:03:49.775] discover_server:844 sending discovery 17
[00:03:54.775] discover_server:844 sending discovery 16
[00:03:59.775] discover_server:844 sending discovery 15
[00:04:04.775] discover_server:844 sending discovery 14
[00:04:09.775] discover_server:844 sending discovery 13
[00:04:14.775] discover_server:844 sending discovery 12
[00:04:19.775] discover_server:844 sending discovery 11
[00:04:24.775] discover_server:844 sending discovery 10
[00:04:29.775] discover_server:844 sending discovery 9
[00:04:34.775] discover_server:844 sending discovery 8
I (88694) telnet: We have a new client connection 55
[00:04:39.775] discover_server:844 sending discovery 7
[00:04:44.775] discover_server:844 sending discovery 6
[00:04:49.775] discover_server:844 sending discovery 5
[00:04:54.775] discover_server:844 sending discovery 4
[00:04:54.787] rtsp_thread:397 got RTSP connection 56
[00:04:54.815] handle_rtsp:444 [0x3fad0188]: received ANNOUNCE
[00:04:55.029] handle_rtsp:667 [0x3fad0188]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 1

[00:04:55.030] search_remote:747 starting remote search
[00:04:55.084] handle_rtsp:444 [0x3fad0188]: received SETUP
[00:04:55.085] raop_sink_cmd_handler:293 resizing buffer 846720
[00:04:55.087] buffer_alloc:380 allocated 853 buffers (min=375) from buffer of 1201280 bytes
[00:04:55.093] handle_rtsp:667 [0x3fad0188]: responding:
RTSP/1.0 200 OK
Transport: RTP/AVP/UDP;unicast;mode=record;control_port=56001;timing_port=56002;server_port=56000
Session: DEADBEEF
Audio-Jack-Status: connected; type=analog
CSeq: 2

[00:04:55.160] output_thread_i2s:518 Output state is 0
[00:04:55.162] output_thread_i2s:585 Restarting I2S.
[00:04:55.219] handle_rtsp:444 [0x3fad0188]: received RECORD
[00:04:55.220] rtp_record:367 [0x3fad49bc]: record 46228 - 235316462
[00:04:55.220] raop_sink_cmd_handler:297 Stream
[00:04:55.223] handle_rtsp:667 [0x3fad0188]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 3

[00:04:55.276] handle_rtsp:444 [0x3fad0188]: received SET_PARAMETER
[00:04:55.277] handle_rtsp:613 [0x3fad0188]: SET PARAMETER volume -13.832344
[00:04:55.277] raop_sink_cmd_handler:331 Volume[0..1] 0.5389
[00:04:55.279] handle_rtsp:667 [0x3fad0188]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 4

[00:04:55.304] rtp_thread_func:740 [0x3fad49bc]: 1st sync packet received
[00:04:55.307] rtp_thread_func:697 [0x3fad49bc]: 1st audio packet received
[00:04:55.308] buffer_put_packet:459 [0x3fad49bc]: 1st accepted packet:46228, now playing
[00:04:55.308] raop_sink_cmd_handler:319 Play
[00:04:55.308] raop_sink_cmd_handler:324 Starting at 109076 (in 2161 ms)
[00:04:55.313] output_thread_i2s:518 Output state is 5
[00:04:55.349] handle_rtsp:444 [0x3fad0188]: received SET_PARAMETER
[00:04:55.350] handle_rtsp:613 [0x3fad0188]: SET PARAMETER volume -13.832344
[00:04:55.350] raop_sink_cmd_handler:331 Volume[0..1] 0.5389
[00:04:55.352] handle_rtsp:667 [0x3fad0188]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 5

[00:04:55.496] rtp_thread_func:763 [0x3fad49bc]: discarding NTP roundtrip of 192 ms
[00:04:56.794] handle_rtsp:444 [0x3fad0188]: received SET_PARAMETER
[00:04:56.795] handle_rtsp:639 [0x3fad0188]: received metadata (ts: 235316462)
    artist: 
    album:  
    title:  SomaFM: Fluid (#1): Drown in the electronic sound of instrumental hiphop, future soul and liquid trap.
[00:04:56.797] handle_rtsp:667 [0x3fad0188]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 6

[00:04:56.930] handle_rtsp:444 [0x3fad0188]: received SET_PARAMETER
[00:04:56.931] handle_rtsp:650 Unhandled SET PARAMETER
CSeq: 7
Session: DEADBEEF
Content-Type: image/none
Content-Length: 0
RTP-Info: rtptime=235316462
User-Agent: Music/1.4.6 (Macintosh; OS X 14.6.1) AppleWebKit/618.3.11.11.5
Client-Instance: 0B6EA274C3CCCAD3
DACP-ID: 0B6EA274C3CCCAD3
Active-Remote: 8310744

[00:04:56.933] handle_rtsp:667 [0x3fad0188]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 7

[00:04:57.025] handle_rtsp:444 [0x3fad0188]: received SET_PARAMETER
[00:04:57.026] handle_rtsp:623 [0x3fad0188]: SET PARAMETER progress 388000/0 progress: 218197358/235316462/218197358

[00:04:57.028] handle_rtsp:667 [0x3fad0188]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 8

[00:04:57.482] output_thread_i2s:518 Output state is 2
[00:04:58.144] search_remote:766 found remote iTunes_Ctrl_0B6EA274C3CCCAD3 10.4.2.153:49370
[00:04:58.319] raop_sink_cmd_handler:258 skipping 617 frames (count:1)
[00:04:58.320] raop_sink_cmd_handler:272 backend played 2148, desired 2134, (delta:-14)
[00:04:58.360] output_thread_i2s:518 Output state is 4
[00:04:58.361] _output_frames:73 skip 617 of 617 frames
[00:04:58.407] output_thread_i2s:518 Output state is 2
[00:04:59.785] discover_server:844 sending discovery 3
[00:05:00.639] raop_sink_cmd_handler:275 switching to slow sync mode 32
[00:05:03.289] buffer_put_packet:521 [0x3fad49bc]: fill [level:1 rec:2] [W:47229 R:47228]
[00:05:03.293] buffer_push_packet:589 [0x3fad49bc]: drain [level:0 head:2219 ms] [W:47229 R:47229] [req:2 sil:0 dis:0]
[00:05:04.785] discover_server:844 sending discovery 2
[00:05:09.780] discover_server:844 sending discovery 1
[00:05:11.321] buffer_push_packet:589 [0x3fad49bc]: drain [level:0 head:2189 ms] [W:48230 R:48230] [req:2 sil:0 dis:0]
[00:05:11.323] buffer_put_packet:521 [0x3fad49bc]: fill [level:1 rec:2] [W:48231 R:48230]
[00:05:14.922] slimproto:964 connecting to 0.0.0.0:3483
[00:05:19.263] buffer_push_packet:589 [0x3fad49bc]: drain [level:0 head:2238 ms] [W:49231 R:49231] [req:48 sil:0 dis:0]
[00:05:19.275] buffer_put_packet:521 [0x3fad49bc]: fill [level:1 rec:48] [W:49233 R:49232]
[00:05:19.925] slimproto:989 unable to connect to server 0
[00:05:24.324] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49493 rtptime:236465742 (W:49734 R:49620)
[00:05:24.325] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49494 rtptime:236466094 (W:49734 R:49620)
[00:05:24.326] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49495 rtptime:236466446 (W:49734 R:49620)
[00:05:24.330] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49496 rtptime:236466798 (W:49747 R:49621)
[00:05:24.375] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49493 rtptime:236465742 (W:49789 R:49626)
   [TRUNCATED REPEATING LINES]
[00:05:24.636] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49651 rtptime:236521358 (W:49884 R:49657)
[00:05:24.637] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49653 rtptime:236522062 (W:49884 R:49657)
[00:05:24.638] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49654 rtptime:236522414 (W:49884 R:49657)
[00:05:24.639] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49655 rtptime:236522766 (W:49884 R:49657)
[00:05:24.641] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49656 rtptime:236523118 (W:49884 R:49657)
[00:05:24.648] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:24.650] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49658 rtptime:236523822 (W:49884 R:49660)
[00:05:24.650] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49659 rtptime:236524174 (W:49884 R:49660)
[00:05:24.654] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:24.659] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:24.666] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:24.672] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:24.676] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:24.681] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
   [TRUNCATED REPEATING LINES]
[00:05:24.776] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:24.784] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:24.790] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:24.798] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:24.809] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:24.817] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:24.840] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49600 rtptime:236503406 (W:49896 R:49692)
[00:05:24.842] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49601 rtptime:236503758 (W:49896 R:49692)
[00:05:24.842] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49602 rtptime:236504110 (W:49896 R:49692)
[00:05:24.843] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49603 rtptime:236504462 (W:49896 R:49692)
[00:05:24.844] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49604 rtptime:236504814 (W:49896 R:49692)
[00:05:24.844] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49605 rtptime:236505166 (W:49896 R:49692)
[00:05:24.845] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49606 rtptime:236505518 (W:49896 R:49692)
[00:05:24.861] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:24.864] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:24.868] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:24.869] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49607 rtptime:236505870 (W:49914 R:49692)
[00:05:24.870] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49608 rtptime:236506222 (W:49914 R:49692)
[00:05:24.871] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49609 rtptime:236506574 (W:49914 R:49692)
   [TRUNCATED REPEATING LINES]
[00:05:24.892] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49628 rtptime:236513262 (W:49914 R:49692)
[00:05:24.892] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49629 rtptime:236513614 (W:49914 R:49692)
[00:05:24.893] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49630 rtptime:236513966 (W:49914 R:49692)
[00:05:24.897] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:24.899] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49631 rtptime:236514318 (W:49915 R:49692)
[00:05:24.900] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49616 rtptime:236509038 (W:49915 R:49692)
[00:05:24.900] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49617 rtptime:236509390 (W:49915 R:49692)
[00:05:24.901] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49618 rtptime:236509742 (W:49915 R:49692)
[00:05:24.902] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49619 rtptime:236510094 (W:49915 R:49692)
[00:05:24.903] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49620 rtptime:236510446 (W:49915 R:49692)
[00:05:24.904] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49621 rtptime:236510798 (W:49915 R:49692)
[00:05:24.908] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:24.913] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49622 rtptime:236511150 (W:49916 R:49693)
[00:05:24.914] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49623 rtptime:236511502 (W:49916 R:49693)
[00:05:24.916] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49624 rtptime:236511854 (W:49916 R:49693)
   [TRUNCATED REPEATING LINES]
[00:05:25.023] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49694 rtptime:236536494 (W:49929 R:49719)
[00:05:25.025] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49697 rtptime:236537550 (W:49929 R:49719)
[00:05:25.026] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49698 rtptime:236537902 (W:49929 R:49719)
[00:05:25.037] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.041] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
   [TRUNCATED REPEATING LINES]
[00:05:25.171] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.175] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.202] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49630 rtptime:236513966 (W:49929 R:49752)
[00:05:25.203] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49631 rtptime:236514318 (W:49929 R:49752)
[00:05:25.212] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49654 rtptime:236522414 (W:49929 R:49752)
[00:05:25.213] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49655 rtptime:236522766 (W:49929 R:49752)
[00:05:25.214] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49659 rtptime:236524174 (W:49929 R:49752)
[00:05:25.251] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.256] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.259] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.266] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.272] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.275] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.292] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.298] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.304] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.305] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49648 rtptime:236520302 (W:49977 R:49752)
[00:05:25.309] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.313] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49649 rtptime:236520654 (W:49979 R:49752)
[00:05:25.314] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49650 rtptime:236521006 (W:49979 R:49752)
[00:05:25.316] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49651 rtptime:236521358 (W:49979 R:49752)
[00:05:25.317] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49653 rtptime:236522062 (W:49979 R:49752)
[00:05:25.318] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49654 rtptime:236522414 (W:49979 R:49752)
[00:05:25.423] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.459] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.461] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49655 rtptime:236522766 (W:49992 R:49825)
[00:05:25.462] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49656 rtptime:236523118 (W:49992 R:49825)
   [TRUNCATED REPEATING LINES]
[00:05:25.468] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49650 rtptime:236521006 (W:49992 R:49825)
[00:05:25.468] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49651 rtptime:236521358 (W:49992 R:49825)
[00:05:25.472] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.476] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.481] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.527] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49653 rtptime:236522062 (W:49998 R:49825)
[00:05:25.529] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49654 rtptime:236522414 (W:49998 R:49825)
[00:05:25.530] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49655 rtptime:236522766 (W:49998 R:49825)
   [TRUNCATED REPEATING LINES]
[00:05:25.754] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49697 rtptime:236537550 (W:50001 R:49825)
[00:05:25.756] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49698 rtptime:236537902 (W:50001 R:49825)
[00:05:25.758] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49697 rtptime:236537550 (W:50001 R:49825)
[00:05:25.759] buffer_put_packet:521 [0x3fad49bc]: fill [level:176 rec:137] [W:50001 R:49825]
[00:05:25.761] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49698 rtptime:236537902 (W:50001 R:49825)
[00:05:25.767] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49755 rtptime:236557966 (W:50001 R:49825)
[00:05:25.768] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49756 rtptime:236558318 (W:50001 R:49825)
[00:05:25.778] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.783] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.811] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49719 rtptime:236545294 (W:50001 R:49825)
[00:05:25.812] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49720 rtptime:236545646 (W:50001 R:49825)
   [TRUNCATED REPEATING LINES]
[00:05:25.817] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49756 rtptime:236558318 (W:50001 R:49825)
[00:05:25.818] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49757 rtptime:236558670 (W:50001 R:49825)
[00:05:25.824] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.827] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.831] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.835] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.839] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.888] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.911] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.920] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49755 rtptime:236557966 (W:50050 R:49825)
[00:05:25.922] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49756 rtptime:236558318 (W:50050 R:49825)
[00:05:25.923] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49757 rtptime:236558670 (W:50050 R:49825)
[00:05:25.943] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.947] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.956] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.961] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49752 rtptime:236556910 (W:50056 R:49825)
[00:05:25.962] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49753 rtptime:236557262 (W:50056 R:49825)
   [TRUNCATED REPEATING LINES]
[00:05:25.966] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49756 rtptime:236558318 (W:50056 R:49825)
[00:05:25.968] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49757 rtptime:236558670 (W:50056 R:49825)
[00:05:25.982] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:25.987] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:26.001] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
   [TRUNCATED REPEATING LINES]
[00:05:26.047] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:26.054] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:26.058] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:26.063] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49829 rtptime:236584014 (W:50056 R:49839)
[00:05:26.065] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49756 rtptime:236558318 (W:50056 R:49839)
   [TRUNCATED REPEATING LINES]
[00:05:26.071] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49830 rtptime:236584366 (W:50056 R:49839)
[00:05:26.071] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49831 rtptime:236584718 (W:50056 R:49839)
[00:05:26.081] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:26.085] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
   [TRUNCATED REPEATING LINES]
[00:05:26.113] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:26.116] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:26.344] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49836 rtptime:236586478 (W:50071 R:49844)
[00:05:26.349] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49839 rtptime:236587534 (W:50071 R:49844)
[00:05:26.350] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49840 rtptime:236587886 (W:50071 R:49844)
[00:05:26.351] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49843 rtptime:236588942 (W:50071 R:49844)
[00:05:26.380] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:26.381] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49845 rtptime:236589646 (W:50071 R:49897)
[00:05:26.382] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49846 rtptime:236589998 (W:50071 R:49897)
   [TRUNCATED REPEATING LINES]
[00:05:26.389] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49857 rtptime:236593870 (W:50071 R:49897)
[00:05:26.389] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49858 rtptime:236594222 (W:50071 R:49897)
[00:05:26.393] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:26.396] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
   [TRUNCATED REPEATING LINES]
[00:05:26.609] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:26.614] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:26.626] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49757 rtptime:236558670 (W:50072 R:49910)
[00:05:26.629] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49840 rtptime:236587886 (W:50072 R:49910)
   [TRUNCATED REPEATING LINES]
[00:05:26.650] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49852 rtptime:236592110 (W:50072 R:49910)
[00:05:26.651] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49853 rtptime:236592462 (W:50072 R:49910)
[00:05:26.658] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:26.662] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:26.666] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:26.687] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:26.689] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49839 rtptime:236587534 (W:50072 R:49952)
[00:05:26.691] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49840 rtptime:236587886 (W:50072 R:49952)
[00:05:26.693] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49843 rtptime:236588942 (W:50072 R:49952)
   [TRUNCATED REPEATING LINES]
[00:05:26.714] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49898 rtptime:236608302 (W:50072 R:49952)
[00:05:26.714] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49899 rtptime:236608654 (W:50072 R:49952)
[00:05:26.715] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49900 rtptime:236609006 (W:50072 R:49952)
[00:05:26.729] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:26.737] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:26.746] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:26.750] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:26.757] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49835 rtptime:236586126 (W:50072 R:49965)
[00:05:26.759] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49836 rtptime:236586478 (W:50072 R:49965)
[00:05:26.761] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49839 rtptime:236587534 (W:50072 R:49965)
   [TRUNCATED REPEATING LINES]
[00:05:26.776] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49900 rtptime:236609006 (W:50072 R:49965)
[00:05:26.778] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49913 rtptime:236613582 (W:50072 R:49965)
[00:05:26.809] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49900 rtptime:236609006 (W:50073 R:49965)
[00:05:26.883] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:26.948] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49832 rtptime:236585070 (W:50170 R:49965)
[00:05:26.950] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49834 rtptime:236585774 (W:50170 R:49965)
   [TRUNCATED REPEATING LINES]
[00:05:26.954] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49852 rtptime:236592110 (W:50170 R:49965)
[00:05:26.955] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49853 rtptime:236592462 (W:50170 R:49965)
   [TRUNCATED REPEATING LINES]
[00:05:27.134] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49850 rtptime:236591406 (W:50204 R:50007)
[00:05:27.134] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49851 rtptime:236591758 (W:50204 R:50007)
[00:05:27.136] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49840 rtptime:236587886 (W:50204 R:50007)
[00:05:27.137] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49843 rtptime:236588942 (W:50204 R:50007)
[00:05:27.138] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49845 rtptime:236589646 (W:50204 R:50007)
[00:05:27.196] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:27.202] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:27.208] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:27.213] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:27.214] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:49899 rtptime:236608654 (W:50204 R:50023)
[00:05:27.225] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:27.818] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:50036 rtptime:236656878 (W:50267 R:50060)
[00:05:27.987] handle_rtsp:444 [0x3fad0188]: received SET_PARAMETER
[00:05:27.988] handle_rtsp:613 [0x3fad0188]: SET PARAMETER volume -13.832344
[00:05:27.988] raop_sink_cmd_handler:331 Volume[0..1] 0.5389
[00:05:27.990] handle_rtsp:667 [0x3fad0188]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 10

[00:05:28.220] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:50078 rtptime:236671662 (W:50309 R:50121)
[00:05:28.222] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:50080 rtptime:236672366 (W:50309 R:50121)
[00:05:28.223] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:50082 rtptime:236673070 (W:50309 R:50121)
   [TRUNCATED REPEATING LINES]
[00:05:28.310] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:50068 rtptime:236668142 (W:50309 R:50121)
[00:05:28.311] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:50069 rtptime:236668494 (W:50309 R:50121)
[00:05:28.315] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:50080 rtptime:236672366 (W:50309 R:50121)
[00:05:28.399] buffer_push_packet:589 [0x3fad49bc]: drain [level:40 head:1394 ms] [W:50309 R:50269] [req:4051 sil:145 dis:0]
[00:05:28.422] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:50121 rtptime:236686798 (W:50313 R:50269)
[00:05:28.426] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:50122 rtptime:236687150 (W:50313 R:50269)
[00:05:28.737] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:28.741] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:28.751] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:28.823] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:28.827] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:28.847] buffer_put_packet:521 [0x3fad49bc]: fill [level:129 rec:479] [W:50398 R:50269]
[00:05:28.935] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:50122 rtptime:236687150 (W:50422 R:50269)
[00:05:28.956] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
   [TRUNCATED REPEATING LINES]
[00:05:29.084] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:05:29.167] rtp_thread_func:763 [0x3fad49bc]: discarding NTP roundtrip of 437 ms
[00:05:29.536] rtp_thread_func:721 discarding remote timing information 10045
[00:05:29.886] handle_rtsp:444 [0x3fad0188]: received SET_PARAMETER
[00:05:29.887] handle_rtsp:613 [0x3fad0188]: SET PARAMETER volume -13.832344
[00:05:29.888] raop_sink_cmd_handler:331 Volume[0..1] 0.5389
[00:05:29.889] handle_rtsp:667 [0x3fad0188]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 11

[00:05:29.941] slimproto:989 unable to connect to server 1
[00:05:30.511] rtp_thread_func:721 discarding remote timing information 11051
[00:05:31.517] rtp_thread_func:721 discarding remote timing information 12057
[00:05:32.512] rtp_thread_func:721 discarding remote timing information 13063
[00:05:35.030] buffer_put_packet:521 [0x3fad49bc]: fill [level:1 rec:616] [W:51195 R:51194]
[00:05:35.580] buffer_push_packet:589 [0x3fad49bc]: drain [level:0 head:2196 ms] [W:51270 R:51270] [req:4579 sil:145 dis:0]
[00:05:39.945] slimproto:989 unable to connect to server 2
I (153814) httpd_handlers: serving /status.json to peer 10.4.2.153 port 51187
[00:05:42.942] buffer_put_packet:521 [0x3fad49bc]: fill [level:1 rec:616] [W:52197 R:52196]
[00:05:43.654] buffer_push_packet:589 [0x3fad49bc]: drain [level:0 head:2113 ms] [W:52271 R:52271] [req:4579 sil:145 dis:0]
[00:05:46.617] raop_sink_cmd_handler:258 skipping 573 frames (count:39)
[00:05:46.622] output_thread_i2s:518 Output state is 4
[00:05:46.622] _output_frames:73 skip 573 of 573 frames
[00:05:46.668] output_thread_i2s:518 Output state is 2
[00:05:49.944] slimproto:989 unable to connect to server 3
[00:05:50.946] buffer_put_packet:521 [0x3fad49bc]: fill [level:1 rec:616] [W:53199 R:53198]
[00:05:51.649] buffer_push_packet:589 [0x3fad49bc]: drain [level:0 head:2076 ms] [W:53272 R:53272] [req:4579 sil:145 dis:0]
[00:05:54.644] raop_sink_cmd_handler:258 skipping 4939 frames (count:8)
[00:05:54.652] output_thread_i2s:518 Output state is 4
[00:05:54.653] _output_frames:73 skip 4939 of 4939 frames
[00:05:54.698] output_thread_i2s:518 Output state is 2
[00:05:58.937] buffer_put_packet:521 [0x3fad49bc]: fill [level:1 rec:616] [W:54201 R:54200]
[00:05:59.612] buffer_push_packet:589 [0x3fad49bc]: drain [level:0 head:2139 ms] [W:54273 R:54273] [req:4579 sil:145 dis:0]
[00:05:59.944] slimproto:989 unable to connect to server 4
[00:06:00.930] rtp_thread_func:763 [0x3fad49bc]: discarding NTP roundtrip of 198 ms
[00:06:06.941] buffer_put_packet:521 [0x3fad49bc]: fill [level:1 rec:616] [W:55203 R:55202]
[00:06:07.519] buffer_push_packet:589 [0x3fad49bc]: drain [level:0 head:2221 ms] [W:55274 R:55274] [req:4579 sil:145 dis:0]
[00:06:09.945] slimproto:989 unable to connect to server 5
[00:06:13.803] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:13.807] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:14.773] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:14.991] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:15.000] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:15.006] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55850 rtptime:238703406 (W:56178 R:55969)
[00:06:15.008] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55851 rtptime:238703758 (W:56178 R:55969)
[00:06:15.008] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55852 rtptime:238704110 (W:56178 R:55969)
   [TRUNCATED REPEATING LINES]
[00:06:15.027] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55873 rtptime:238711502 (W:56178 R:55969)
[00:06:15.028] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55874 rtptime:238711854 (W:56178 R:55969)
[00:06:15.029] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55875 rtptime:238712206 (W:56178 R:55969)
[00:06:15.056] discover_server:844 sending discovery 5
[00:06:15.125] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55811 rtptime:238689678 (W:56203 R:56045)
[00:06:15.127] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55812 rtptime:238690030 (W:56203 R:56045)
[00:06:15.128] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55813 rtptime:238690382 (W:56203 R:56045)
   [TRUNCATED REPEATING LINES]
[00:06:15.352] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55908 rtptime:238723822 (W:56239 R:56045)
[00:06:15.353] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55909 rtptime:238724174 (W:56239 R:56045)
[00:06:15.353] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55910 rtptime:238724526 (W:56239 R:56045)
[00:06:15.358] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:15.363] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:15.365] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55807 rtptime:238688270 (W:56242 R:56045)
[00:06:15.368] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55808 rtptime:238688622 (W:56242 R:56045)
[00:06:15.370] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55809 rtptime:238688974 (W:56242 R:56045)
[00:06:15.371] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55810 rtptime:238689326 (W:56242 R:56045)
[00:06:15.372] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55811 rtptime:238689678 (W:56242 R:56045)
[00:06:15.374] buffer_put_packet:521 [0x3fad49bc]: fill [level:197 rec:666] [W:56242 R:56045]
[00:06:15.381] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55850 rtptime:238703406 (W:56242 R:56045)
[00:06:15.382] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55851 rtptime:238703758 (W:56242 R:56045)
[00:06:15.382] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55852 rtptime:238704110 (W:56242 R:56045)
[00:06:15.383] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55853 rtptime:238704462 (W:56242 R:56045)
   [TRUNCATED REPEATING LINES]
[00:06:15.587] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55883 rtptime:238715022 (W:56267 R:56045)
[00:06:15.588] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55884 rtptime:238715374 (W:56267 R:56045)
[00:06:15.589] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55885 rtptime:238715726 (W:56267 R:56045)
[00:06:15.590] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:55886 rtptime:238716078 (W:56267 R:56045)
[00:06:15.639] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:15.647] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:15.651] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:15.655] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
   [TRUNCATED REPEATING LINES]
[00:06:15.921] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:15.926] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:15.930] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:15.948] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:16.014] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56068 rtptime:238780142 (W:56274 R:56096)
[00:06:16.016] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56069 rtptime:238780494 (W:56274 R:56096)
[00:06:16.017] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56070 rtptime:238780846 (W:56274 R:56096)
   [TRUNCATED REPEATING LINES]
[00:06:16.024] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56078 rtptime:238783662 (W:56274 R:56096)
[00:06:16.025] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56079 rtptime:238784014 (W:56274 R:56096)
[00:06:16.025] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56085 rtptime:238786126 (W:56274 R:56096)
[00:06:16.088] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:16.114] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56098 rtptime:238790702 (W:56274 R:56108)
[00:06:16.116] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56096 rtptime:238789998 (W:56274 R:56108)
   [TRUNCATED REPEATING LINES]
[00:06:16.122] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56102 rtptime:238792110 (W:56274 R:56108)
[00:06:16.124] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56104 rtptime:238792814 (W:56274 R:56108)
[00:06:16.180] rtp_thread_func:763 [0x3fad49bc]: discarding NTP roundtrip of 316 ms
[00:06:16.221] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56048 rtptime:238773102 (W:56289 R:56129)
[00:06:16.222] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56049 rtptime:238773454 (W:56289 R:56129)
[00:06:16.223] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56050 rtptime:238773806 (W:56289 R:56129)
   [TRUNCATED REPEATING LINES]
[00:06:16.803] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56110 rtptime:238794926 (W:56364 R:56134)
[00:06:16.803] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56111 rtptime:238795278 (W:56364 R:56134)
[00:06:16.804] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56112 rtptime:238795630 (W:56364 R:56134)
[00:06:16.805] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:16.822] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:16.840] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
   [TRUNCATED REPEATING LINES]
[00:06:16.886] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:16.889] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:16.895] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:16.897] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56084 rtptime:238785774 (W:56375 R:56234)
[00:06:16.901] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:16.905] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:16.906] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56085 rtptime:238786126 (W:56377 R:56234)
[00:06:16.907] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56086 rtptime:238786478 (W:56377 R:56234)
[00:06:16.908] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56088 rtptime:238787182 (W:56377 R:56234)
[00:06:16.909] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56091 rtptime:238788238 (W:56377 R:56234)
[00:06:16.910] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56092 rtptime:238788590 (W:56377 R:56234)
[00:06:16.914] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:16.917] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56096 rtptime:238789998 (W:56378 R:56234)
[00:06:16.919] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56097 rtptime:238790350 (W:56378 R:56234)
[00:06:16.919] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56098 rtptime:238790702 (W:56378 R:56234)
[00:06:16.920] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56099 rtptime:238791054 (W:56378 R:56234)
[00:06:16.921] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56100 rtptime:238791406 (W:56378 R:56234)
   [TRUNCATED REPEATING LINES]
[00:06:17.080] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56202 rtptime:238827310 (W:56394 R:56240)
[00:06:17.098] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56198 rtptime:238825902 (W:56395 R:56240)
[00:06:17.099] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56199 rtptime:238826254 (W:56395 R:56240)
[00:06:17.100] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56200 rtptime:238826606 (W:56395 R:56240)
[00:06:17.101] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56201 rtptime:238826958 (W:56395 R:56240)
[00:06:17.102] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56202 rtptime:238827310 (W:56395 R:56240)
[00:06:17.155] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:17.167] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56129 rtptime:238801614 (W:56444 R:56240)
[00:06:17.188] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:17.197] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:17.202] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:17.206] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:17.225] buffer_push_packet:589 [0x3fad49bc]: drain [level:147 head:683 ms] [W:56444 R:56297] [req:7715 sil:273 dis:70]
[00:06:17.237] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:17.241] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:17.244] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:17.352] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56240 rtptime:238840686 (W:56449 R:56298)
[00:06:17.640] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56298 rtptime:238861102 (W:56503 R:56299)
   [TRUNCATED REPEATING LINES]
[00:06:18.032] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56325 rtptime:238870606 (W:56510 R:56365)
[00:06:18.124] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56335 rtptime:238874126 (W:56563 R:56365)
[00:06:18.821] buffer_put_packet:521 [0x3fad49bc]: fill [level:144 rec:1070] [W:56618 R:56474]
[00:06:18.822] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56407 rtptime:238899470 (W:56618 R:56474)
[00:06:18.823] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56408 rtptime:238899822 (W:56618 R:56474)
[00:06:18.941] rtp_request_resend:858 [0x3fad49bc]: SENDTO failed (Not enough space)
[00:06:18.958] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56420 rtptime:238904046 (W:56664 R:56502)
   [TRUNCATED REPEATING LINES]
[00:06:19.020] buffer_put_packet:516 [0x3fad49bc]: packet too late seqno:56411 rtptime:238900878 (W:56668 R:56502)
[00:06:19.794] rtp_thread_func:721 discarding remote timing information 10947
I (192934) httpd_handlers: serving /status.json to peer 10.4.2.153 port 59635
[00:06:20.052] discover_server:844 sending discovery 4
[00:06:20.819] rtp_thread_func:721 discarding remote timing information 11953
[00:06:23.769] buffer_push_packet:589 [0x3fad49bc]: drain [level:0 head:2128 ms] [W:57298 R:57298] [req:8895 sil:283 dis:72]
[00:06:24.612] buffer_put_packet:521 [0x3fad49bc]: fill [level:1 rec:1284] [W:57392 R:57391]
[00:06:25.055] discover_server:844 sending discovery 3
[00:06:30.076] discover_server:844 sending discovery 2
[00:06:31.659] buffer_push_packet:589 [0x3fad49bc]: drain [level:0 head:2228 ms] [W:58299 R:58299] [req:8895 sil:283 dis:72]
[00:06:32.416] buffer_put_packet:521 [0x3fad49bc]: fill [level:1 rec:1284] [W:58394 R:58393]
[00:06:32.878] raop_sink_cmd_handler:258 skipping 2734 frames (count:32)
[00:06:32.913] output_thread_i2s:518 Output state is 4
[00:06:32.914] _output_frames:73 skip 2734 of 2734 frames
[00:06:32.959] output_thread_i2s:518 Output state is 2
[00:06:35.072] discover_server:844 sending discovery 1
[00:06:37.189] handle_rtsp:444 [0x3fad0188]: received FLUSH
[00:06:37.192] rtp_flush:350 [0x3fad49bc]: FLUSH packets below 58972 - 239802350
[00:06:37.193] raop_sink_cmd_handler:310 Flush
[00:06:37.194] handle_rtsp:667 [0x3fad0188]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 14

[00:06:37.235] output_thread_i2s:518 Output state is 0
[00:06:45.075] slimproto:989 unable to connect to server 6
[00:06:48.678] handle_rtsp:444 [0x3fad0188]: received TEARDOWN
[00:06:48.765] rtp_thread_func:794 [0x3fad49bc]: terminating
[00:06:48.768] cleanup_rtsp:700 [0x3fad0188]: Remote search thread aborted
[00:06:48.768] raop_sink_cmd_handler:310 Stop
[00:06:48.770] handle_rtsp:667 [0x3fad0188]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 15

[00:06:50.076] discover_server:844 sending discovery 5
[00:06:51.169] rtsp_thread:413 RTSP close 56
[00:06:55.075] discover_server:844 sending discovery 4
[00:07:00.075] discover_server:844 sending discovery 3
[00:07:05.075] discover_server:844 sending discovery 2
[00:07:10.075] discover_server:844 sending discovery 1

Issue Description

  1. Observed Behavior: In this instance, I did not experience the former issue where audio ceased coming out of the speakers and the device became unavailable to my audio source: Music app on macOS. Instead, this time, audio persisted, and it played until I stopped playing. However, audio became noticeably choppy (split-second drops in audio, like a high speed pulse).
  2. Expected Behavior: The device should remain available to send audio to via AirPlay, and the audio quality out of the speakers should be "good" (consistent, without dropping any data).
  3. Steps to Reproduce: Reboot the ESP32 device, connect to it in Music via AirPlay, play some audio.
philippe44 commented 1 month ago

It's happens when managing audio in UDP frames. Some frames went missing so we are trying to send with UDP a request for resend. That request cannot be sent because the internal buffers for UDP are full and ultimately we miss, frames. It does not mean that it is a true realtime issue as on other systems as the IP stack would continue to accept packets until the WiFi access is granted (or the IP stack is scheduled), but here we can't. Here, it's likely a limitation of the lwIP stack on esp32 and the fact that there is not a lot of available memory for such handling and cpu is constrained so the IP stack might also not been scheduled.

sle118 commented 1 month ago

@roens can you see if your router has a band steering option? I've had cases in the past where such option would not play well with the esp32 in terms of stability. Also check for TX/RX retries if the router gives you such insights.

You could also try to connect your Mac using a cable instead of using wifi.

Having a capable router is good but might not isolate you from greedy neighbors using the 2.4G at 40Mhz bandwidth which can cause spikes of performance degradation.