search

sle118 / squeezelite-esp32

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

ESP32-S3 Slimproto works, Cspot and Airplay are fixed. Experimental build #419

Closed anabolyc closed 4 months ago

anabolyc commented 4 months ago

Describe the bug

hey folks, I'm testing squeezelite-esp32 with the ESP32-S3 board built with espidf v.4.4.7 Took me some time to prepare working sdkconfig, but code builds and runs, I was able to configure wifi and find device in the network. However only slim-proto seems to work as expected. Neither scpot nor airplay works as it should.

Preliminary Information

  1. Firmware Version: 38d28a
  2. Music Assistant slimproto built-in into version 2024.3.6

Hardware Details

Please describe your hardware setup:

Airplay Logs

Airplay connects fine, but as soon as audio starts, errors are fired into the log. Speakers seem to issue occasional sounds, but you'd not recognize any audio of it.


=== START OF LOG ===
I (24) boot: ESP-IDF v4.4.7 2nd stage bootloader
I (24) boot: compile time 07:36:59
I (24) boot: Multicore bootloader
I (26) boot: chip revision: v0.2
I (30) qio_mode: Enabling default flash chip QIO
I (35) boot.esp32s3: Boot SPI Speed : 80MHz
I (40) boot.esp32s3: SPI Mode       : QIO
I (45) boot.esp32s3: SPI Flash Size : 4MB
I (49) boot: Enabling RNG early entropy source...
I (55) boot: Partition Table:
I (58) boot: ## Label            Usage          Type ST Offset   Length
I (66) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (73) boot:  1 otadata          OTA data         01 00 0000d000 00002000
I (81) boot:  2 phy_init         RF data          01 01 0000f000 00001000
I (88) boot:  3 recovery         factory app      00 00 00010000 00140000
I (95) boot:  4 ota_0            OTA app          00 10 00150000 002a0000
I (103) boot:  5 settings         WiFi data        01 02 003f0000 00010000
I (111) boot: End of partition table
I (115) esp_image: segment 0: paddr=00150020 vaddr=3c160020 size=a81f4h (688628) map
I (228) esp_image: segment 1: paddr=001f821c vaddr=3fc96300 size=04bb4h ( 19380) load
I (231) esp_image: segment 2: paddr=001fcdd8 vaddr=40374000 size=03240h ( 12864) load
I (236) esp_image: segment 3: paddr=00200020 vaddr=42000020 size=1583ach (1409964) map
I (456) esp_image: segment 4: paddr=003583d4 vaddr=40377240 size=0f0c0h ( 61632) load
I (468) esp_image: segment 5: paddr=0036749c vaddr=600fe000 size=0002ch (    44) load
I (476) boot: Loaded app from partition at offset 0x150000
I (476) boot: Disabling RNG early entropy source...
I (488) cpu_start: Multicore app
I (489) opi psram: vendor id : 0x0d (AP)
I (489) opi psram: dev id    : 0x02 (generation 3)
I (491) opi psram: density   : 0x03 (64 Mbit)
I (496) opi psram: good-die  : 0x01 (Pass)
I (501) opi psram: Latency   : 0x01 (Fixed)
I (506) opi psram: VCC       : 0x01 (3V)
I (510) opi psram: SRF       : 0x01 (Fast Refresh)
I (516) opi psram: BurstType : 0x01 (Hybrid Wrap)
I (521) opi psram: BurstLen  : 0x01 (32 Byte)
I (526) opi psram: Readlatency  : 0x02 (10 cycles@Fixed)
I (532) opi psram: DriveStrength: 0x00 (1/1)
I (538) MSPI Timing: PSRAM timing tuning index: 5
I (542) spiram: Found 64MBit SPI RAM device
I (547) spiram: SPI RAM mode: sram 80m
I (552) spiram: PSRAM initialized, cache is in normal (1-core) mode.
I (559) cpu_start: Pro cpu up.
I (562) cpu_start: Starting app cpu, entry point is 0x40375314
0x40375314: call_start_cpu1 at /opt/esp/idf/components/esp_system/port/cpu_start.c:175

I (551) cpu_start: App cpu up.
I (995) spiram: SPI SRAM memory test OK
I (1004) cpu_start: Pro cpu start user code
I (1004) cpu_start: cpu freq: 160000000
I (1004) cpu_start: Application information:
I (1007) cpu_start: Project name:     Squeezelite-ESP32
I (1013) cpu_start: App version:      local.500.cmake-master
I (1019) cpu_start: Compile time:     May 15 2024 07:46:23
I (1025) cpu_start: ELF file SHA256:  0000000000000000...
I (1031) cpu_start: ESP-IDF:          v4.4.7
I (1036) cpu_start: Min chip rev:     v0.0
I (1041) cpu_start: Max chip rev:     v0.99 
I (1046) cpu_start: Chip rev:         v0.2
I (1051) heap_init: Initializing. RAM available for dynamic allocation:
I (1058) heap_init: At 3FCB0618 len 000390F8 (228 KiB): D/IRAM
I (1064) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DIRAM
I (1071) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (1078) heap_init: At 600FE02C len 00001FD4 (7 KiB): RTCRAM
I (1084) spiram: Adding pool of 8192K of external SPI memory to heap allocator
I (1092) spi_flash: detected chip: gd
I (1096) spi_flash: flash io: qio
W (1100) spi_flash: Detected size(16384k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
I (1115) sleep: Configure to isolate all GPIO pins in sleep state
I (1120) sleep: Enable automatic switching of GPIO sleep configuration
I (1128) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1138) spiram: Reserving pool of 32K of internal memory for DMA/internal allocations
I (1148) esp_app_main: Reset reason is: 3
I (1158) esp_app_main: Reboot counter=1

I (1158) esp_app_main: Starting app_main
I (1168) nvs_utilities: Initializing flash nvs 
I (1188) nvs_utilities: Initializing nvs partition settings
I (1228) esp_app_main: Setting up telnet.
I (1238) telnet: Telnet support disabled
I (1238) esp_app_main: Setting up config subsystem.
W (1288) nvs_utilities: Configuration memory usage.  Heap internal:263287 (min:262911) (used:0) external:8372223 (min:8364783) (used:13908)
I (1288) esp_app_main: Registering default values
I (1298) system_api: Base MAC address is not set
I (1298) system_api: read default base MAC address from EFUSE
W (1308) config: Waiting for config commit ...
I (2288) config: configuration has some uncommitted entries
I (2288) config: Committing configuration to nvs. Locking config object.
I (2288) config: Done Committing configuration to nvs.
I (2288) config: Config committed!
I (2298) esp_app_main: Configuring services
I (2298) services: set GPIO 17 to vcc
I (2308) services: Configuring I2C sda:8 scl:9 port:1 speed:400000
I (2308) services: Configuring SPI mosi:-1 miso:-1 clk:-1 host:1 dc:-1
W (2318) services: no SPI configured
W (2328) led: LED GPIO -1 ignored
W (2328) led: LED GPIO -1 ignored
I (2328) led: Configuring LEDs green:-1 (on:0 rmt:-1 -1% ), red:-1 (on:0 rmt:-1 -1% )
I (2338) battery: No battery
I (2348) monitor: Initializing monitoring
I (2348) monitor: Heap internal:262707 (min:262675) external:8355567 (min:8355547) dma:254939 (min:254907)
I (2358) esp_app_main: Initializing display
I (2368) display: Trying to configure display with N/A
W (2368) display: No display driver
I (2378) esp_app_main: Initializing led_vu
I (2378) led_vu: led_vu configuration invalid
I (2378) esp_app_main: Checking for update url
W (2388) config: Value not found for key fwurl
W (2398) config: Value not found for key 
I (2398) esp_app_main: Starting Network Manager
W (2408) config: Value not found for key apdelay
I (2408) uart: queue free spaces: 3
I (2408) network_handlers: Network manager configuration: polling max 10176, polling min 15000, ap delay 20000, dhcp timeout 8000, eth timeout 8000
I (2428) http_server: Initializing HTTP Server
I (2428) network_ethernet: Detected driver w5500 
I (2428) network_ethernet: Attempting to initialize Ethernet
I (2428) network_ethernet: Detected driver w5500 
I (2438) network_ethernet: Ethernet config => model: w5500, valid: YES, type: SPI, mdc:0, mdio:0, rst:5, intr:6, cs:10, speed:20000000, host:-1
E (2448) spi_master: spi_bus_add_device(311): invalid host
E (2458) network_ethernet: SPI host failed : ESP_ERR_INVALID_ARG
E (2468) messaging: Configuring Ethernet failed: ESP_ERR_INVALID_ARG
I (2468) pp: pp rom version: e7ae62f
I (2478) net80211: net80211 rom version: e7ae62f
I (2488) wifi:wifi driver task: 3fcb31e4, prio:23, stack:6656, core=0
I (2498) wifi:wifi firmware version: 1fd20f4
I (2498) wifi:wifi certification version: v7.0
I (2498) wifi:config NVS flash: enabled
I (2498) wifi:config nano formating: disabled
I (2508) wifi:Init data frame dynamic rx buffer num: 40
I (2508) wifi:Init static rx mgmt buffer num: 5
I (2508) wifi:Init management short buffer num: 32
I (2528) wifi:Init static tx buffer num: 12
I (2528) wifi:Init tx cache buffer num: 32
I (2528) wifi:Init static tx FG buffer num: 2
I (2538) wifi:Init static rx buffer size: 1600
I (2538) wifi:Init static rx buffer num: 12
I (2538) wifi:Init dynamic rx buffer num: 40
I (2548) wifi_init: tcpip mbox: 32
I (2548) wifi_init: udp mbox: 32
I (2548) wifi_init: tcp mbox: 32
I (2558) wifi_init: tcp tx win: 8192
I (2568) wifi_init: tcp rx win: 32768
I (2568) wifi_init: tcp mss: 1440
I (2568) network_wifi: Starting wifi
I (2578) phy_init: phy_version 640,cd64a1a,Jan 24 2024,17:28:12
I (2618) wifi:mode : sta (80:65:99:c4:00:20)
I (2618) wifi:enable tsf
I (2618) network_handlers: Existing wifi config found. Attempting to connect.
I (2618) network: Starting DHCP client
I (2638) network_wifi: Wifi Connecting to wifi-12-private...

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 (2688) console: Processing autoexec commands while network manager active.  Wifi related commands will be ignored.
I (2698) console: autoexec is set to perform auto-process
I (2698) console: Running command autoexec1 = squeezelite -o I2S -b 500:2000 -d all=info -C 30 -W -n squeezelite-c4020
W (2708) config: Value not found for key autoexec2
squeezelite-esp32> I (2718) squeezelite_cmd: Calling squeezelite
[00:21:11.018] sb_controls_init:249 initializing audio (buttons/rotary/ir) controls (raw:0)
[00:21:11.030] sb_displayer_init:327 no display or led visualizer for LMS
[00:21:11.032] stream_init:539 init stream
[00:21:11.033] output_init_embedded:78 init device: I2S
[00:21:11.045] output_init_common:433 supported rates: 192000 176400 96000 88200 48000 44100 32000 24000 22050 16000 12000 11025 8000 
[00:21:11.058] output_init_embedded:100 init I2S/SPDIF
I (2768) DAC core: DAC uses I2C port:0, sda:8, scl:9
I (2768) DAC external: DAC on I2C @45
[00:21:11.073] output_init_i2s:363 configuring MCLK on GPIO -1
I (2788) I2S: DMA Malloc info, datalen=blocksize=2048, dma_buf_count=12
[00:21:11.078] output_init_i2s:376 I2S DAC using I2S bck:14, ws:15, do:16, mute:-1:0 (res:0)
[00:21:11.090] output_init_i2s:396 Initializing I2S mode normal with rate: 44100, bits per sample: 16, buffer frames: 512, number of buffers: 12 
[00:21:11.103] equalizer_set_samplerate:121 equalizer sample rate 44100
[00:21:11.105] output_thread_i2s:518 Output state is -1
[00:21:11.105] output_visu_init:75 Initialize VISUEXPORT 512 16 bits samples
[00:21:11.117] output_thread_i2s:522 switching off amp GPIO -1
[00:21:11.118] output_init_embedded:108 init completed.
[00:21:11.131] decode_init:153 init decode
[00:21:11.132] register_alac:547 using alac to decode alc
[00:21:11.143] register_helixaac:686 using helix-aac to decode aac
[00:21:11.145] register_vorbis:526 using vorbis to decode ogg
[00:21:11.146] register_opus:458 using opus to decode ops
[00:21:11.157] register_flac:338 using flac to decode ogf,flc
[00:21:11.159] register_pcm:468 using pcm to decode wav,aif,pcm
[00:21:11.170] register_mad:417 using mad to decode mp3
[00:21:11.172] register_external:469 Initializing AirPlay sink
[00:21:11.173] register_external:480 Initializing CSpot sink
[00:21:11.188] discover_server:844 sending discovery 25
[00:21:11.189] discover_server:848 error sending discovery
I (5048) wifi:new:<13,2>, old:<1,0>, ap:<255,255>, sta:<13,2>, prof:1
I (5568) wifi:state: init -> auth (b0)
I (5568) wifi:state: auth -> assoc (0)
I (5568) wifi:state: assoc -> run (10)
I (5588) wifi:connected with wifi-12-private, aid = 12, channel 13, 40D, bssid = 34:5d:9e:5f:a5:c4
I (5588) wifi:security: WPA2-PSK, phy: bgn, rssi: -63
I (5588) wifi:pm start, type: 1

I (5598) wifi:set rx beacon pti, rx_bcn_pti: 0, bcn_timeout: 0, mt_pti: 25000, mt_time: 10000
I (5618) network: Got an IP address from interface Wifi. IP=192.168.1.216, Gateway=192.168.1.1, NetMask=255.255.255.0, Address was changed
I (5618) esp_netif_handlers: sta ip: 192.168.1.216, mask: 255.255.255.0, gw: 192.168.1.1
I (5638) esp_app_main: Network connected and mDNS initialized with squeezelite-c4020
[00:21:13.938] raop_sink_start:178 starting Airplay for ip 192.168.1.216 with servicename ESP32-AirPlay-c4020
I (5648) wifi:AP's beacon interval = 102400 us, DTIM period = 1
[00:21:13.941] raop_create:201 starting mDNS with 806599C40020@ESP32-AirPlay-c4020
I (5668) cspot: starting Spotify on host squeezelite-c4020
[00:21:13.985] I Shim.cpp:344: CSpot instance service name squeezelite-c4020 (id 142137fd329622137a1490160000000292251584)
[00:21:13.989] I Shim.cpp:331: ZeroConf mode (port 80)
I (5948) httpd_handlers: serving /status.json to peer 192.168.1.16 port 36505
[00:21:16.190] discover_server:844 sending discovery 24
[00:21:16.200] discover_server:856 got response from: 192.168.1.48:3483
[00:21:16.203] slimproto:964 connecting to 192.168.1.48:3483
[00:21:16.213] slimproto:1011 connected
[00:21:16.215] sendHELO:153 mac: 80:65:99:c4:00:20
[00:21:16.217] sendHELO:155 cap: Model=squeezeesp32,AccuratePlayPoints=1,HasDigitalOut=1,HasPolarityInversion=1,Balance=1,Depth=16,Firmware=v1.0-,ModelName=SqueezeESP32,MaxSampleRate=192000,alc,aac,ogg,ops,ogf,flc,wav,aif,pcm,mp3
I (7948) httpd_handlers: serving /config.json to peer 192.168.1.16 port 33433
[00:21:16.246] notify:228 notified server 192.168.1.48 hport 9000 cport 9090
I (7958) network_status: LMS IP: 192.168.1.48, hport: 9000, cport: 9090
I (7968) network_ethernet: Detected driver w5500 
[00:21:16.263] process:578 unhandled vers
[00:21:16.269] process:578 unhandled grfb
[00:21:16.271] process:578 unhandled grfe
[00:21:16.283] process:578 unhandled grfe
[00:21:16.287] process:578 unhandled grfb
[00:21:16.292] process:578 unhandled grfe
[00:21:16.315] process:578 unhandled grfe
[00:21:21.319] process:578 unhandled grfe
[00:21:26.336] process:578 unhandled grfe
[00:21:31.103] rtsp_thread:397 got RTSP connection 55
[00:21:31.354] process:578 unhandled grfe
[00:21:36.576] process:578 unhandled grfe
[00:21:37.469] handle_rtsp:451 [0x3fce366c]: challenge Gb8TJZ4qveTdKFHK6DgIIw==
[00:21:37.778] handle_rtsp:444 [0x3fce366c]: received ANNOUNCE
[00:21:38.017] handle_rtsp:667 [0x3fce366c]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 4

[00:21:38.020] search_remote:747 starting remote search
[00:21:38.053] handle_rtsp:444 [0x3fce366c]: received SETUP
[00:21:38.055] raop_sink_cmd_handler:293 resizing buffer 423360
[00:21:38.056] output_thread_i2s:518 Output state is 0
[00:21:38.058] buffer_alloc:380 allocated 1153 buffers (min=375) from buffer of 1624640 bytes
[00:21:38.068] output_thread_i2s:585 Restarting I2S.
[00:21:38.074] handle_rtsp:667 [0x3fce366c]: responding:
W (29788) wifi:mem fail
RTSP/1.0 200 OK
Transport: RTP/AVP/UDP;unicast;mode=record;control_port=57073;timing_port=57074;server_port=57072
Session: DEADBEEF
Audio-Jack-Status: connected; type=analog
CSeq: 5

[00:21:38.085] equalizer_process:222 equalizer deactivated
[00:21:38.118] handle_rtsp:444 [0x3fce366c]: received RECORD
[00:21:38.120] rtp_record:367 [0x3da9f6f8]: record 0 - 0
[00:21:38.121] raop_sink_cmd_handler:297 Stream
[00:21:38.133] handle_rtsp:667 [0x3fce366c]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 6

[00:21:38.164] handle_rtsp:444 [0x3fce366c]: received SET_PARAMETER
[00:21:38.166] handle_rtsp:613 [0x3fce366c]: SET PARAMETER volume -20.000000
[00:21:38.168] raop_sink_cmd_handler:331 Volume[0..1] 0.3333
[00:21:38.181] handle_rtsp:667 [0x3fce366c]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 7

[00:21:38.315] rtp_thread_func:740 [0x3da9f6f8]: 1st sync packet received
[00:21:38.318] buffer_put_packet:466 [0x3da9f6f8]: 1st accepted packet:40371, waiting for FLUSH
E (30038) esp-aes: Failed to allocate memory
[00:21:38.354] handle_rtsp:444 [0x3fce366c]: received SET_PARAMETER
[00:21:38.356] handle_rtsp:613 [0x3fce366c]: SET PARAMETER volume -20.000000
[00:21:38.357] raop_sink_cmd_handler:331 Volume[0..1] 0.3333
E (30078) esp-aes: Failed to allocate memory
E (30078) esp-aes: Failed to allocate memory
E (30078) esp-aes: Failed to allocate memory
[00:21:38.376] handle_rtsp:667 [0x3fce366c]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 8

E (30098) esp-aes: Failed to allocate memory
E (30108) esp-aes: Failed to allocate memory
E (30118) esp-aes: Failed to allocate memory
E (30128) esp-aes: Failed to allocate memory
E (30128) esp-aes: Failed to allocate memory
E (30128) esp-aes: Failed to allocate memory
[00:21:38.436] handle_rtsp:444 [0x3fce366c]: received FLUSH
[00:21:38.438] handle_rtsp:667 [0x3fce366c]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 9

[00:21:38.441] buffer_put_packet:475 [0x3da9f6f8]: done waiting for FLUSH with packet:40388, now playing starting:40371
[00:21:38.455] raop_sink_cmd_handler:319 Play
[00:21:38.466] raop_sink_cmd_handler:324 Starting at 32153 (in 1983 ms)
E (30178) esp-aes: Failed to allocate memory
E (30178) esp-aes: Failed to allocate memory
[00:21:38.476] output_thread_i2s:518 Output state is 5
E (30188) esp-aes: Failed to allocate memory
E (30198) esp-aes: Failed to allocate memory
E (30198) esp-aes: Failed to allocate memory
E (30208) esp-aes: Failed to allocate memory
E (30208) esp-aes: Failed to allocate memory
E (30228) esp-aes: Failed to allocate memory
E (30228) esp-aes: Failed to allocate memory
E (30228) esp-aes: Failed to allocate memory
E (30238) esp-aes: Failed to allocate memory
E (30238) esp-aes: Failed to allocate memory
E (30248) esp-aes: Failed to allocate memory
E (30248) esp-aes: Failed to allocate memory
E (30248) esp-aes: Failed to allocate memory
E (30268) esp-aes: Failed to allocate memory
E (30268) esp-aes: Failed to allocate memory
E (30288) esp-aes: Failed to allocate memory
E (30288) esp-aes: Failed to allocate memory
E (30298) esp-aes: Failed to allocate memory
E (30308) esp-aes: Failed to allocate memory
E (30318) esp-aes: Failed to allocate memory
E (30318) esp-aes: Failed to allocate memory
E (30348) esp-aes: Failed to allocate memory
E (30348) esp-aes: Failed to allocate memory
E (30348) esp-aes: Failed to allocate memory
E (30358) esp-aes: Failed to allocate memory
E (30358) esp-aes: Failed to allocate memory
E (30368) esp-aes: Failed to allocate memory
E (30378) esp-aes: Failed to allocate memory
E (30388) esp-aes: Failed to allocate memory
E (30388) esp-aes: Failed to allocate memory
E (30408) esp-aes: Failed to allocate memory
E (30408) esp-aes: Failed to allocate memory
E (30408) esp-aes: Failed to allocate memory
E (30538) esp-aes: Failed to allocate memory
E (30538) esp-aes: Failed to allocate memory
E (30548) esp-aes: Failed to allocate memory
E (30548) esp-aes: Failed to allocate memory
E (30548) esp-aes: Failed to allocate memory
E (30558) esp-aes: Failed to allocate memory
E (30558) esp-aes: Failed to allocate memory
E (30568) esp-aes: Failed to allocate memory
E (30578) esp-aes: Failed to allocate memory
E (30578) esp-aes: Failed to allocate memory
E (30578) esp-aes: Failed to allocate memory
E (30588) esp-aes: Failed to allocate memory
E (30588) esp-aes: Failed to allocate memory
E (30598) esp-aes: Failed to allocate memory
E (30608) esp-aes: Failed to allocate memory
E (30608) esp-aes: Failed to allocate memory
E (30618) esp-aes: Failed to allocate memory
E (30618) esp-aes: Failed to allocate memory
E (30618) esp-aes: Failed to allocate memory
E (30628) esp-aes: Failed to allocate memory
E (30628) esp-aes: Failed to allocate memory
E (30648) esp-aes: Failed to allocate memory
E (30648) esp-aes: Failed to allocate memory
E (30648) esp-aes: Failed to allocate memory
E (31108) esp-aes: Failed to allocate memory
E (31108) esp-aes: Failed to allocate memory
E (31108) esp-aes: Failed to allocate memory
E (31118) esp-aes: Failed to allocate memory
E (31128) esp-aes: Failed to allocate memory
E (31128) esp-aes: Failed to allocate memory
E (31178) esp-aes: Failed to allocate memory
E (31188) esp-aes: Failed to allocate memory
E (31198) esp-aes: Failed to allocate memory
[00:21:39.496] handle_rtsp:444 [0x3fce366c]: received SET_PARAMETER
[00:21:39.498] handle_rtsp:646 [0x3fce366c]: received JPEG image of 88280 bytes (ts:1483340158)
[00:21:39.501] handle_rtsp:667 [0x3fce366c]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 10

E (31218) esp-aes: Failed to allocate memory
[00:21:39.552] handle_rtsp:444 [0x3fce366c]: received SET_PARAMETER
[00:21:39.554] handle_rtsp:623 [0x3fce366c]: SET PARAMETER progress 694000/1800000 progress: 1452733521/1483350366/1532113521

E (31268) esp-aes: Failed to allocate memory
E (31278) esp-aes: Failed to allocate memory
E (31278) esp-aes: Failed to allocate memory
E (31288) esp-aes: Failed to allocate memory
E (31288) esp-aes: Failed to allocate memory
[00:21:39.582] handle_rtsp:667 [0x3fce366c]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 11

[00:21:39.630] handle_rtsp:444 [0x3fce366c]: received SET_PARAMETER
[00:21:39.632] handle_rtsp:639 [0x3fce366c]: received metadata (ts: 1483353182)
        artist: Chilled D&B with Rohaan
        album:  
        title:  Radio 1's Drum & Bass Mix
[00:21:39.646] handle_rtsp:667 [0x3fce366c]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
E (31358) esp-aes: Failed to allocate memory
E (31368) esp-aes: Failed to allocate memory
E (31378) esp-aes: Failed to allocate memory
E (31378) esp-aes: Failed to allocate memory
E (31378) esp-aes: Failed to allocate memory
E (31398) esp-aes: Failed to allocate memory
CSeq: 12

E (31398) esp-aes: Failed to allocate memory
E (31398) esp-aes: Failed to allocate memory
E (31408) esp-aes: Failed to allocate memory
E (31408) esp-aes: Failed to allocate memory
=== END OF LOG ===

Cspot Logs

Cspot crashes as soon as I connect the client to the device


=== START OF LOG ===
mode:DIO, clock div:1
load:0x3fce3808,len:0x148c
load:0x403c9700,len:0xe60
load:0x403cc700,len:0x3060
entry 0x403c9970
I (24) boot: ESP-IDF v4.4.7 2nd stage bootloader
I (24) boot: compile time 07:36:59
I (25) boot: Multicore bootloader
I (26) boot: chip revision: v0.2
I (30) qio_mode: Enabling default flash chip QIO
I (36) boot.esp32s3: Boot SPI Speed : 80MHz
I (40) boot.esp32s3: SPI Mode       : QIO
I (45) boot.esp32s3: SPI Flash Size : 4MB
I (50) boot: Enabling RNG early entropy source...
I (55) boot: Partition Table:
I (59) boot: ## Label            Usage          Type ST Offset   Length
I (66) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (74) boot:  1 otadata          OTA data         01 00 0000d000 00002000
I (81) boot:  2 phy_init         RF data          01 01 0000f000 00001000
I (89) boot:  3 recovery         factory app      00 00 00010000 00140000
I (96) boot:  4 ota_0            OTA app          00 10 00150000 002a0000
I (103) boot:  5 settings         WiFi data        01 02 003f0000 00010000
I (111) boot: End of partition table
I (115) esp_image: segment 0: paddr=00150020 vaddr=3c160020 size=a81f4h (688628) map
I (228) esp_image: segment 1: paddr=001f821c vaddr=3fc96300 size=04bb4h ( 19380) load
I (232) esp_image: segment 2: paddr=001fcdd8 vaddr=40374000 size=03240h ( 12864) load
I (236) esp_image: segment 3: paddr=00200020 vaddr=42000020 size=1583ach (1409964) map
I (456) esp_image: segment 4: paddr=003583d4 vaddr=40377240 size=0f0c0h ( 61632) load
I (468) esp_image: segment 5: paddr=0036749c vaddr=600fe000 size=0002ch (    44) load
I (476) boot: Loaded app from partition at offset 0x150000
I (476) boot: Disabling RNG early entropy source...
I (489) cpu_start: Multicore app
I (489) opi psram: vendor id : 0x0d (AP)
I (489) opi psram: dev id    : 0x02 (generation 3)
I (491) opi psram: density   : 0x03 (64 Mbit)
I (496) opi psram: good-die  : 0x01 (Pass)
I (501) opi psram: Latency   : 0x01 (Fixed)
I (506) opi psram: VCC       : 0x01 (3V)
I (511) opi psram: SRF       : 0x01 (Fast Refresh)
I (516) opi psram: BurstType : 0x01 (Hybrid Wrap)
I (522) opi psram: BurstLen  : 0x01 (32 Byte)
I (527) opi psram: Readlatency  : 0x02 (10 cycles@Fixed)
I (533) opi psram: DriveStrength: 0x00 (1/1)
I (538) MSPI Timing: PSRAM timing tuning index: 5
I (543) spiram: Found 64MBit SPI RAM device
I (548) spiram: SPI RAM mode: sram 80m
I (552) spiram: PSRAM initialized, cache is in normal (1-core) mode.
I (559) cpu_start: Pro cpu up.
I (563) cpu_start: Starting app cpu, entry point is 0x40375314
0x40375314: call_start_cpu1 at /opt/esp/idf/components/esp_system/port/cpu_start.c:175

I (0) cpu_start: App cpu up.
I (996) spiram: SPI SRAM memory test OK
I (1004) cpu_start: Pro cpu start user code
I (1004) cpu_start: cpu freq: 160000000
I (1004) cpu_start: Application information:
I (1007) cpu_start: Project name:     Squeezelite-ESP32
I (1013) cpu_start: App version:      local.500.cmake-master
I (1019) cpu_start: Compile time:     May 15 2024 07:46:23
I (1026) cpu_start: ELF file SHA256:  0000000000000000...
I (1032) cpu_start: ESP-IDF:          v4.4.7
I (1037) cpu_start: Min chip rev:     v0.0
I (1041) cpu_start: Max chip rev:     v0.99 
I (1046) cpu_start: Chip rev:         v0.2
I (1051) heap_init: Initializing. RAM available for dynamic allocation:
I (1059) heap_init: At 3FCB0618 len 000390F8 (228 KiB): D/IRAM
I (1065) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DIRAM
I (1072) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (1078) heap_init: At 600FE02C len 00001FD4 (7 KiB): RTCRAM
I (1084) spiram: Adding pool of 8192K of external SPI memory to heap allocator
I (1093) spi_flash: detected chip: gd
I (1097) spi_flash: flash io: qio
W (1101) spi_flash: Detected size(16384k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
I (1116) sleep: Configure to isolate all GPIO pins in sleep state
I (1121) sleep: Enable automatic switching of GPIO sleep configuration
I (1128) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1139) spiram: Reserving pool of 32K of internal memory for DMA/internal allocations
I (1149) esp_app_main: System is booting from power on.
I (1159) esp_app_main: Reset reason is: 0
I (1159) esp_app_main: Reboot counter=1

I (1169) esp_app_main: Starting app_main
I (1169) nvs_utilities: Initializing flash nvs 
I (1189) nvs_utilities: Initializing nvs partition settings
I (1239) esp_app_main: Setting up telnet.
I (1239) telnet: Telnet support disabled
I (1239) esp_app_main: Setting up config subsystem.
W (1299) nvs_utilities: Configuration memory usage.  Heap internal:263287 (min:262911) (used:0) external:8372223 (min:8364783) (used:13908)
I (1299) esp_app_main: Registering default values
I (1309) system_api: Base MAC address is not set
I (1309) system_api: read default base MAC address from EFUSE
W (1319) config: Waiting for config commit ...
I (2299) config: configuration has some uncommitted entries
I (2299) config: Committing configuration to nvs. Locking config object.
I (2299) config: Done Committing configuration to nvs.
I (2299) config: Config committed!
I (2309) esp_app_main: Configuring services
I (2309) services: set GPIO 17 to vcc
I (2319) services: Configuring I2C sda:8 scl:9 port:1 speed:400000
I (2319) services: Configuring SPI mosi:-1 miso:-1 clk:-1 host:1 dc:-1
W (2329) services: no SPI configured
W (2339) led: LED GPIO -1 ignored
W (2339) led: LED GPIO -1 ignored
I (2339) led: Configuring LEDs green:-1 (on:0 rmt:-1 -1% ), red:-1 (on:0 rmt:-1 -1% )
I (2349) battery: No battery
I (2359) monitor: Initializing monitoring
I (2359) monitor: Heap internal:262707 (min:262675) external:8355567 (min:8355547) dma:254939 (min:254907)
I (2369) esp_app_main: Initializing display
I (2379) display: Trying to configure display with N/A
W (2379) display: No display driver
I (2389) esp_app_main: Initializing led_vu
I (2389) led_vu: led_vu configuration invalid
I (2389) esp_app_main: Checking for update url
W (2399) config: Value not found for key fwurl
W (2409) config: Value not found for key 
I (2409) esp_app_main: Starting Network Manager
I (2409) network: Setting wifi priotitized flag to false
W (2419) config: Value not found for key apdelay
I (2419) uart: queue free spaces: 3
I (2419) network_handlers: Network manager configuration: polling max 10176, polling min 15000, ap delay 20000, dhcp timeout 8000, eth timeout 8000
I (2439) http_server: Initializing HTTP Server
I (2439) network_ethernet: Detected driver w5500 
I (2449) network_ethernet: Attempting to initialize Ethernet
I (2449) network_ethernet: Detected driver w5500 
I (2459) network_ethernet: Ethernet config => model: w5500, valid: YES, type: SPI, mdc:0, mdio:0, rst:5, intr:6, cs:10, speed:20000000, host:-1
E (2469) spi_master: spi_bus_add_device(311): invalid host
E (2479) network_ethernet: SPI host failed : ESP_ERR_INVALID_ARG
E (2479) messaging: Configuring Ethernet failed: ESP_ERR_INVALID_ARG
I (2489) pp: pp rom version: e7ae62f
I (2489) net80211: net80211 rom version: e7ae62f
I (2509) wifi:wifi driver task: 3fcb31e4, prio:23, stack:6656, core=0
I (2509) wifi:wifi firmware version: 1fd20f4
I (2509) wifi:wifi certification version: v7.0
I (2519) wifi:config NVS flash: enabled
I (2519) wifi:config nano formating: disabled
I (2519) wifi:Init data frame dynamic rx buffer num: 40
I (2529) wifi:Init static rx mgmt buffer num: 5
I (2529) wifi:Init management short buffer num: 32
I (2539) wifi:Init static tx buffer num: 12
I (2549) wifi:Init tx cache buffer num: 32
I (2549) wifi:Init static tx FG buffer num: 2
I (2549) wifi:Init static rx buffer size: 1600
I (2559) wifi:Init static rx buffer num: 12
I (2559) wifi:Init dynamic rx buffer num: 40
I (2559) wifi_init: tcpip mbox: 32
I (2559) wifi_init: udp mbox: 32
I (2569) wifi_init: tcp mbox: 32
I (2579) wifi_init: tcp tx win: 8192
I (2579) wifi_init: tcp rx win: 32768
I (2589) wifi_init: tcp mss: 1440
I (2589) network_wifi: Starting wifi
I (2589) phy_init: phy_version 640,cd64a1a,Jan 24 2024,17:28:12
I (2639) wifi:mode : sta (80:65:99:c4:00:20)
I (2639) wifi:enable tsf
I (2639) network_handlers: Existing wifi config found. Attempting to connect.
I (2639) network: Starting DHCP client
I (2659) network_wifi: Wifi Connecting to wifi-12-private...

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 (2709) console: Processing autoexec commands while network manager active.  Wifi related commands will be ignored.
I (2719) console: autoexec is set to perform auto-process
I (2719) console: Running command autoexec1 = squeezelite -o I2S -b 500:2000 -d all=info -C 30 -W -n squeezelite-c4020
W (2739) config: Value not found for key autoexec2
squeezelite-esp32> I (2739) squeezelite_cmd: Calling squeezelite
[00:00:01.739] sb_controls_init:249 initializing audio (buttons/rotary/ir) controls (raw:0)
[00:00:01.751] sb_displayer_init:327 no display or led visualizer for LMS
[00:00:01.753] stream_init:539 init stream
[00:00:01.754] output_init_embedded:78 init device: I2S
[00:00:01.766] output_init_common:433 supported rates: 192000 176400 96000 88200 48000 44100 32000 24000 22050 16000 12000 11025 8000 
[00:00:01.779] output_init_embedded:100 init I2S/SPDIF
I (2789) DAC core: DAC uses I2C port:0, sda:8, scl:9
I (2789) DAC external: DAC on I2C @45
[00:00:01.794] output_init_i2s:363 configuring MCLK on GPIO -1
I (2809) I2S: DMA Malloc info, datalen=blocksize=2048, dma_buf_count=12
[00:00:01.799] output_init_i2s:376 I2S DAC using I2S bck:14, ws:15, do:16, mute:-1:0 (res:0)
[00:00:01.811] output_init_i2s:396 Initializing I2S mode normal with rate: 44100, bits per sample: 16, buffer frames: 512, number of buffers: 12 
[00:00:01.824] equalizer_set_samplerate:121 equalizer sample rate 44100
[00:00:01.826] output_thread_i2s:518 Output state is -1
[00:00:01.826] output_visu_init:75 Initialize VISUEXPORT 512 16 bits samples
[00:00:01.838] output_thread_i2s:522 switching off amp GPIO -1
[00:00:01.839] output_init_embedded:108 init completed.
[00:00:01.852] decode_init:153 init decode
[00:00:01.853] register_alac:547 using alac to decode alc
[00:00:01.864] register_helixaac:686 using helix-aac to decode aac
[00:00:01.866] register_vorbis:526 using vorbis to decode ogg
[00:00:01.867] register_opus:458 using opus to decode ops
[00:00:01.878] register_flac:338 using flac to decode ogf,flc
[00:00:01.880] register_pcm:468 using pcm to decode wav,aif,pcm
[00:00:01.891] register_mad:417 using mad to decode mp3
[00:00:01.893] register_external:469 Initializing AirPlay sink
[00:00:01.894] register_external:480 Initializing CSpot sink
[00:00:01.909] discover_server:844 sending discovery 25
[00:00:01.910] discover_server:848 error sending discovery
I (5069) wifi:new:<13,2>, old:<1,0>, ap:<255,255>, sta:<13,2>, prof:1
I (5589) wifi:state: init -> auth (b0)
I (5589) wifi:state: auth -> assoc (0)
I (5599) wifi:state: assoc -> run (10)
I (5619) wifi:connected with wifi-12-private, aid = 12, channel 13, 40D, bssid = 34:5d:9e:5f:a5:c4
I (5619) wifi:security: WPA2-PSK, phy: bgn, rssi: -63
I (5629) wifi:pm start, type: 1

I (5639) wifi:set rx beacon pti, rx_bcn_pti: 0, bcn_timeout: 0, mt_pti: 25000, mt_time: 10000
I (5639) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (5659) network: Got an IP address from interface Wifi. IP=192.168.1.216, Gateway=192.168.1.1, NetMask=255.255.255.0, Address was changed
I (5659) esp_netif_handlers: sta ip: 192.168.1.216, mask: 255.255.255.0, gw: 192.168.1.1
I (5679) esp_app_main: Network connected and mDNS initialized with squeezelite-c4020
[00:00:04.680] raop_sink_start:178 starting Airplay for ip 192.168.1.216 with servicename ESP32-AirPlay-c4020
[00:00:04.683] raop_create:201 starting mDNS with 806599C40020@ESP32-AirPlay-c4020
I (5719) cspot: starting Spotify on host squeezelite-c4020
[00:00:04.724] I Shim.cpp:344: CSpot instance service name squeezelite-c4020 (id 142137fd329622137a1490160000000292251584)
[00:00:04.727] I Shim.cpp:331: ZeroConf mode (port 80)
I (7759) httpd_handlers: serving /status.json to peer 192.168.1.16 port 24745
[00:00:06.910] discover_server:844 sending discovery 24
I (11249) httpd_handlers: serving /messages.json to peer 192.168.1.16 port 38569
[00:00:11.910] discover_server:844 sending discovery 23
I (14179) httpd_handlers: serving /messages.json to peer 192.168.1.16 port 57509
[00:00:16.910] discover_server:844 sending discovery 22
[00:00:20.743] I Shim.cpp:358: Spotify client launched for squeezelite-c4020
E (21839) esp-sha: Failed to allocate buf memory
[00:00:20.828] E TLSSocket.cpp:74: failed! config returned -1

abort() was called at PC 0x4210bc1f on core 0

Backtrace: 0x40375d8a:0x3da9d410 0x4037f289:0x3da9d430 0x403842e6:0x3da9d450 0x4210bc1f:0x3da9d4c0 0x4210bc66:0x3da9d4e0 0x4210bf73:0x3da9d500 0x42047d39:0x3da9d520 0x420477df:0x3da9d580 0x42046dcd:0x3da9d5a0 0x42040615:0x3da9d610 0x42041cbd:0x3da9d650 0x4203a6e2:0x3da9d6a0 0x42031576:0x3da9d710 0x4202f9e2:0x3da9d7b0
0x40375d8a: uart_ll_get_sclk_freq at /opt/esp/idf/components/hal/esp32s3/include/hal/uart_ll.h:130 (discriminator 8)
 (inlined by) uart_ll_set_baudrate at /opt/esp/idf/components/hal/esp32s3/include/hal/uart_ll.h:152 (discriminator 8)
 (inlined by) esp_rom_uart_set_clock_baudrate at /opt/esp/idf/components/esp_rom/patches/esp_rom_uart.c:35 (discriminator 8)

0x4037f289: _xt_coproc_savecs at /opt/esp/idf/components/freertos/port/xtensa/xtensa_context.S:507

0x403842e6: memspi_host_program_page at /opt/esp/idf/components/spi_flash/memspi_host_driver.c:173

0x42047d39: tcp_write at /opt/esp/idf/components/lwip/lwip/src/core/tcp_out.c:792

0x420477df: tcp_input at /opt/esp/idf/components/lwip/lwip/src/core/tcp_in.c:490

0x42046dcd: tcp_input at /opt/esp/idf/components/lwip/lwip/src/core/tcp_in.c:238

0x42040615: lwip_setsockopt_impl at /opt/esp/idf/components/lwip/lwip/src/api/sockets.c:3854
 (inlined by) lwip_setsockopt_callback at /opt/esp/idf/components/lwip/lwip/src/api/sockets.c:3417

0x42041cbd: lwip_fcntl at ??:?

0x4203a6e2: esp_netif_destroy at /opt/esp/idf/components/esp_netif/lwip/esp_netif_lwip.c:655

0x42031576: bootloader_common_check_chip_validity at /opt/esp/idf/components/bootloader_support/src/bootloader_common_loader.c:89

0x4202f9e2: uart_read_bytes at /opt/esp/idf/components/driver/uart.c:1344

=== END OF LOG ===

Issue Description

  1. Observed Behavior: Neither Airplay not cspot works
  2. Expected Behavior: Both should work
  3. Steps to Reproduce: Build latest code with espidf 4.4.7 using attached sdkconfig and flash to the device.
martymcbro commented 3 days ago

I thought we already agreed on the fact that telnet isn't working, but more information was needed to possibly fix the telnet issue 😉

sle118 commented 12 hours ago

@anabolyc

Thank you for the hint. Everything worked now using your docker command.

After enabling telnet the system crashed again. The reason is a stack overflow in task Tmr Svc. Attached you find the output of "idf.py monitor" containing the backtrace.

monitor.log

@philippe44

I think you are one of the few persons with enough insight to fix this. Looking at the backtrace, do you have a clue what can be done?

A stack overflow on the timer service would indicate that there's an issue with the amount of memory dedicated to the... Timer service. This is something that would need fixed in the sdkconfig.

I see that the default values were used CONFIG_ESP_TIMER_TASK_STACK_SIZE=3584 But it might require some fine tuning on that platform

philippe44 commented 10 hours ago

We can fix it by increasing the stack but it is precious internal ram AFAIR. The esp-idf timer calls any callback registered under timer service using its own task (not an isr) stack. This is why one has to be careful what we do in that callback and also because it's a shared task for all callbacks, best is to either something really quick or send a message to wake up another task. I'll have to verify all the routines that we register for timer services.