-
Notifications
You must be signed in to change notification settings - Fork 157
Description
Describe the bug
Home Assistant / Music Assistant has a built-in LMS server that allows using slimproto clients to play the audio directly from HA. Seems that some communication that comes from the built-in server crashes squeezelite-esp32.
When enabled squeezelite-esp32 immediately goes into the bootloop. As soon as disabled, it acts normally.
Preliminary Information
- fw: I2S-4MFlash-1672, mode: Squeezelite-ESP32
- slimproto built-in into version 2024.3.6
Hardware Details
- ESP32-WROVER N16R8 as a part of Esparagus board
- Same behavior with PCM5102 and MAX98357 DAC
- IR, RGB led, doesn't seem to have any effect on this issue
NVS Settings
nvs_config_loud-esparagus_1714076880283json.txt
{
"a2dp_ctmt": "1000",
"a2dp_ctrld": "500",
"a2dp_dev_name": "loud-esparagus",
"a2dp_sink_name": "SMSL BT4.2",
"a2dp_spin": "0000",
"actrls_config": "",
"airplay_name": "loud-esparagus",
"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": "loud-esparagus",
"autoexec": "1",
"autoexec1": "squeezelite -o I2S -b 500:2000 -d all=info -C 30 -W -n loud-esparagus",
"bat_config": "",
"bt_name": "loud-esparagus",
"bt_sink_pin": "1234",
"bt_sink_volume": "127",
"bypass_wm": "0",
"cspot_config": "{\"deviceName\":\"loud-esparagus\",\"bitrate\":160,\"zeroConf\":1}",
"dac_config": "model=I2S,bck=26,ws=25,do=22",
"dac_controlset": "",
"dhcp_tmout": "8",
"display_config": "",
"enable_airplay": "Y",
"enable_bt_sink": "Y",
"enable_cspot": "Y",
"equalizer": "",
"eth_config": "",
"ethtmout": "8",
"gpio_exp_config": "",
"host_name": "loud-esparagus",
"i2c_config": "",
"jack_mutes_amp": "n",
"led_brightness": "",
"led_vu_config": "type=[WS2812],length=1,gpio=33",
"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": "Y",
"target": "",
"telnet_block": "500",
"telnet_buffer": "40000",
"telnet_enable": "D"
}
Logs
rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0030,len:6424
load:0x40078000,len:15632
load:0x40080400,len:4348
entry 0x40080688
I (27) boot: ESP-IDF v4.3.5-dirty 2nd stage bootloader
I (27) boot: compile time 03:05:16
I (27) boot: chip revision: v3.1
I (31) qio_mode: Enabling default flash chip QIO
I (36) boot.esp32: SPI Speed : 80MHz
I (41) boot.esp32: SPI Mode : QIO
I (45) boot.esp32: 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 (88) 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=3f400020 size=aeaf0h (715504) map
I (321) esp_image: segment 1: paddr=001feb18 vaddr=3ffbdb60 size=01500h ( 5376) load
I (323) esp_image: segment 2: paddr=00200020 vaddr=400d0020 size=1b2e5ch (1781340) map
I (817) esp_image: segment 3: paddr=003b2e84 vaddr=3ffbf060 size=0453ch ( 17724) load
I (823) esp_image: segment 4: paddr=003b73c8 vaddr=40080000 size=1e014h (122900) load
I (863) esp_image: segment 5: paddr=003d53e4 vaddr=400c0000 size=00068h ( 104) load
I (878) boot: Loaded app from partition at offset 0x150000
I (878) boot: Disabling RNG early entropy source...
I (890) psram: This chip is ESP32-D0WD
I (890) spiram: Found 64MBit SPI RAM device
I (890) spiram: SPI RAM mode: flash 80m sram 80m
I (893) spiram: PSRAM initialized, cache is in low/high (2-core) mode.
I (901) cpu_start: Pro cpu up.
I (904) cpu_start: Starting app cpu, entry point is 0x400813fc
I (897) cpu_start: App cpu up.
I (1410) spiram: SPI SRAM memory test OK
I (1422) cpu_start: Pro cpu start user code
I (1422) cpu_start: cpu freq: 240000000
I (1422) cpu_start: Application information:
I (1425) cpu_start: Project name: Squeezelite-ESP32
I (1431) cpu_start: App version: I2S-4MFlash-1672
I (1437) cpu_start: Compile time: Mar 22 2024 03:06:48
I (1443) cpu_start: ELF file SHA256: 0000000000000000...
I (1449) cpu_start: ESP-IDF: v4.3.5-dirty
I (1455) cpu_start: Min chip rev: v1.0
I (1460) cpu_start: Max chip rev: v3.99
I (1465) cpu_start: Chip rev: v3.1
I (1470) heap_init: Initializing. RAM available for dynamic allocation:
I (1477) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (1483) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (1489) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (1495) heap_init: At 3FFC6EC8 len 00019138 (100 KiB): DRAM
I (1502) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1508) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1515) heap_init: At 4009E014 len 00001FEC (7 KiB): IRAM
I (1521) spiram: Adding pool of 4018K of external SPI memory to heap allocator
I (1529) spi_flash: detected chip: gd
I (1533) spi_flash: flash io: qio
W (1537) spi_flash: Detected size(8192k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
I (1553) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1561) spiram: Reserving pool of 64K of internal memory for DMA/internal allocations
I (1571) esp_app_main: Reset reason is: 3
I (1571) esp_app_main: Reboot counter=1I (1581) esp_app_main: Starting app_main
I (1581) nvs_utilities: Initializing flash nvs
I (1601) nvs_utilities: Initializing nvs partition settings
I (1631) esp_app_main: Setting up telnet.
I (1631) telnet: ***Redirecting log output to telnet
I (1631) esp_app_main: Setting up config subsystem.
W (1711) nvs_utilities: Configuration memory usage. Heap internal:228835 (min:228695) (used:216) external:4054843 (min:4047271) (used:15512)
I (1711) esp_app_main: Registering default values
I (1721) system_api: Base MAC address is not set
I (1721) system_api: read default base MAC address from EFUSE
W (1731) config: Waiting for config commit ...
I (2711) config: configuration has some uncommitted entries
I (2711) config: Committing configuration to nvs. Locking config object.
I (2711) config: Done Committing configuration to nvs.
I (2711) config: Config committed!
I (2721) esp_app_main: Configuring services
I (2721) services: Configuring I2C sda:-1 scl:-1 port:1 speed:400000
W (2731) services: no I2C configured
I (2731) services: Configuring SPI mosi:-1 miso:-1 clk:-1 host:1 dc:-1
W (2741) services: no SPI configured
W (2751) led: LED GPIO -1 ignored
W (2751) led: LED GPIO -1 ignored
I (2751) led: Configuring LEDs green:-1 (on:0 rmt:-1 -1% ), red:-1 (on:0 rmt:-1 -1% )
I (2761) battery: No battery
I (2771) monitor: Initializing monitoring
I (2771) monitor: Heap internal:229511 (min:228507) external:4038259 (min:4038243) dma:221719 (min:220731)
I (2781) esp_app_main: Initializing display
I (2791) display: Trying to configure display with N/A
W (2791) display: No display driver
I (2801) esp_app_main: Initializing led_vu
I (2801) led_vu: vu meter using length:1 left:0 right:0 status:0 scale:100
I (2811) led_vu: led_vu using gpio:33 length:1 on channel:0
I (2811) esp_app_main: Checking for update url
W (2821) config: Value not found for key fwurl
I (2821) IR: Starting Infrared Receiver mode nec on gpio 39 and channel 7
I (2831) buttons: Created infrared receiver using GPIO 39
I (2831) buttons: starting button taW (2851) config: Value not found for key apdelay
I (2851) uart: queue free spaces: 3
I (2851) network_handlers: Network manager configuration: polling max 10176, polling min 15000, ap delay 20000, dhcp timeout 8000, eth timeout 8000
I (2881) http_server: Initializing HTTP Server
I (2881) network_ethernet: Attempting to initialize Ethernet
I (2891) network_ethernet: No Ethernet configuration, or configuration invalid
I (2911) wifi:wifi driver task: 3ffdfb20, prio:23, stack:6656, core=0
I (2911) wifi:wifi firmware version: 9ec65ef
I (2911) wifi:wifi certification version: v7.0
I (2911) wifi:config NVS flash: enabled
I (2921) wifi:config nano formating: disabled
I (2921) wifi:Init data frame dynamic rx buffer num: 40
I (2921) wifi:Init management frame dynamic rx buffer num: 40I (2931) wifi:Init management short buffer num: 32
I (2941) wifi:Init static tx buffer num: 12
I (2941) wifi:Init tx cache buffer num: 32Type '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.I (2961) wifi:Init static rx buffer size: 1600
I (2961) wifi:Init static rx buffer num: 12
I (2961) wifi:Init dynamic rx buffer num: 40To 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 automaticallyI (2991) wifi_init: tcpip mbox: 32
I (3001) wifi_init: udp mbox: 32
I (3001) wifi_init: tcp mbox: 32
I (3001) wifi_init: tcp tx win: 8192
Your terminal application does not support escape sequences.
Line editing and history features are disabled.
On Windows, try using Putty instead.
I (3011) wifi_init: tcp rx win: 32768
W (3021) console: Processing autoexec commands while network manager active. Wifi related commands will be ignored.
I (3031) wifi_init: tcp mss: 1440
I (3041) console: autoexec is set to perform auto-process
I (3041) wifi_init: WiFi/LWIP prefer SPIRAM
I (3041) console: Running command autoexec1 = squeezelite -o I2S -b 500:2000 -d all=info -C 30 -W -n loud-esparagus
I (3061) network_wifi: Starting wifi
W (3071) config: Value not found for key autoexec2
I (3071) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (3071) squeezelite_cmd: Calling squeezelite
squeezelite-esp32> [00:10:53.315] sb_controls_init:249 initializing audio (buttons/rotary/ir) controls (raw:0)
[00:10:53.329] sendSETD:440 sending dimension display:0x0 led_config:1
[00:10:53.331] stream_init:539 init stream
[00:10:53.332] output_init_embedded:78 init device: I2S
[00:10:53.344] output_init_common:433 supported rates: 192000 176400 96000 88200 48000 44100 32000 24000 22050 16000 12000 11025 8000
[00:10:53.356] output_init_embedded:100 init I2S/SPDIF
W (3131) DAC core: DAC does not use i2c
I (3141) DAC external: DAC on I2C @0
W (3141) DAC external: no i2c controlset found
[00:10:53.369] output_init_i2s:347 configuring MCLK on GPIO -1
[00:10:53.380] output_init_i2s:359 invalid MCK gpio -1
I (3151) I2S: DMA Malloc info, datalen=blocksize=2048, dma_buf_count=12
I (3161) I2S: APLL: Req RATE: 44100, real rate: 44099.988, BITS: 16, CLKM: 1, BCK_M: 8, MCLK: 11289597.000, SCLK: 1411199I (3171) wifi:.625000, diva: 1, divb: 0
mode : sta (64:b7:08:d1:d8:10)
[00:10:53.406] output_init_i2s:376 I2S DAC using I2S bck:26, ws:25, do:22, mute:-1:0 (res:0)
I (3181) wifi:enable tsf[00:10:53.418] output_init_i2s:396 Initializing I2S mode normal with rate: 44100, bits per sample: 16, buffer frames: 512, number of buffers: 12[00:10:53.430] equalizer_set_samplerate:121 equalizer sample rate 44100
I (3201) network_handlers: Existing wifi config found. Attempting to connect.
[00:10:53. output_thread_i2s:518 Output state is -1
I (3211) network: Starting DHCP client
[00:10:53.443] output_visu_init:75 Initialize VISUEXPORT 512 16 bits samples
[00:10:53.455] output_thread_i2s:522 switching off amp GPIO -1
I (3231) network_wifi: Wifi Connecting to wifi-12-private...
[00:10:53.458] output_init_embedded:108 init completed.
[00:10:53.481] decode_init:153 init decode
[00:10:53.482] register_alac:547 using alac to decode alc
[00:10:53.483] register_helixaac:686 using helix-aac to decode aac
[00:10:53.494] register_vorbis:526 using vorbis to decode ogg
[00:10:53.494] register_opus:458 using opus to decode ops
[00:10:53.505] register_flac:338 using flac to decode ogf,flc
[00:10:53.506] register_pcm:468 using pcm to decode wav,aif,pcm
[00:10:53.517] register_mad:417 using mad to decode mp3
W (3291) BT_AV: BT Sink pin code is: [1234]
I (3291) BTDM_INIT: BT controller compile version [2c56073]
[00:10:53.531] register_external:469 Initializing AirPlay sink
[00:10:53.533] register_external:480 Initializing CSpot sink
[00:10:53.547] discover_server:844 sending discovery 25
[00:10:53.548] discover_server:848 error sending discovery
I (3661) BT_AV: Bluetooth Init complete
I (5191) wifi:new:<13,2>, old:<1,0>, ap:<255,255>, sta:<13,2>, prof:1
I (5711) wifi:state: init -> auth (b0)
I (5711) wifi:state: auth -> assoc (0)
I (5721) wifi:state: assoc -> run (10)
I (5741) wifi:connected with wifi-12-private, aid = 11, channel 13, 40D, bssid = 34:5d:9e:5f:a5:c4
I (5741) wifi:security: WPA2-PSK, phy: bgn, rssi: -59
I (5751) wifi:pm start, type: 1I (5771) network: Got an IP address from interface Wifi. IP=192.168.1.194, Gateway=192.168.1.1, NetMask=255.255.255.0, Address was changed
I (5771) esp_netif_handlers: sta ip: 192.168.1.194, mask: 255.255.255.0, gw: 192.168.1.1
I (5791) esp_app_main: Network connected and mDNS initialized with loud-esparagus
I (5791) wifi:AP's beacon interval = 102400 us, DTIM period = 1
[00:10:56.031] raop_sink_start:178 starting Airplay for ip 192.168.1.194 with servicename loud-esparagus
[00:10:56.044] raop_create:201 starting mDNS with 64B708D1D810@loud-esparagus
I (5831) cspot: starting Spotify on host loud-esparagus
[00:10:56.088] I Shim.cpp:344: CSpot instance service name loud-esparagus (id 142137fd329622137a1490160000001746976115)
[00:10:56.092] I Shim.cpp:331: ZeroConf mode (port 80)
I (7681) httpd_handlers: serving /status.json to peer 192.168.1.16 port 10894
I (7731) httpd_handlers: serving /config.json to peer 192.168.1.16 port 8334
[00:10:58.551] discover_server:844 sending discovery 24
I (11871) monitor: Heap internal:62323 (min:61839) external:1189983 (min:1179903) dma:54531 (min:54063)
[00:11:03.551] discover_server:844 sending discovery 23
[00:11:08.551] discover_server:844 sending discovery 22
I (21891) monitor: Heap internal:62103 (min:61839) external:1188939 (min:1179903) dma:54311 (min:54063)
I (21901) monitor: IDLE (1) 96% s: 948 pseudo_idle (0) 0% s: 3312 IDLE (1) 99% s: 1052
I (21901) monitor: output_i2s (2) 0% s: 2032 decode (2) 0% s:14020 tiT (2) 0% s: 1880
I (21921) monitor: Tmr Svc (2) 0% s: 1192 squeezelite (2) 0% s: 3776 stream (2) 0% s: 3732
I (21941) monitor: telnet (2) 0% s: 3200 console (2) 0% s: 868 sb_displayer (3) 0% s: 2560
I (21961) monitor: ipc1 (2) 0% s: 416 BtAppT (2) 0% s: 1468 BTC_TASK (2) 0% s: 872
I (21971) monitor: hciT (2) 0% s: 1572 BTU_TASK (2) 0% s: 3304 ipc0 (2) 0% s: 484
I (21971) monitor: sys_evt (2) 0% s: 596 RTSP (2) 0% s: 7404 playerInstance (2) 0% s:29708
I (22001) monitor: mdns (2) 0% s: 2344 network (2) 0% s: 812 httpd (2) 0% s: 1140
I (22001) monitor: btController (2) 1% s: 2120 wifi (2) 1% s: 3188 esp_timer (3) 0% s: 3372
I (22021) monitor: buttons (2) 0% s: 1544 led_strip_task (2) 0% s: 456
[00:11:13.551] discover_server:844 sending discovery 21
[00:11:18.551] discover_server:844 sending discovery 20
[00:11:18.561] discover_server:856 got response from: 192.168.1.224:3483
[00:11:18.562] slimproto:964 connecting to 192.168.1.224:3483
[00:11:18.572] slimproto:1011 connected
[00:11:18.574] sendHELO:153 mac: 64:b7:08:d1:d8:10
[00:11:18.574] sendHELO:155 cap: Model=squeezeesp32,AccuratePlayPoints=1,HasDigitalOut=1,HasPolarityInversion=1,Balance=1,Depth=16,Firmware=v1.0-1672-16,ModelName=SqueezeESP32,MaxSampleRate=192000,alc,aac,ogg,ops,ogf,flc,wav,aif,pcm,mp3
[00:11:18.599] sendSETD:440 sending dimension display:0x0 led_config:1
[00:11:18.608] notify:228 notified server 192.168.1.224 hport 9000 cport 9090
I (28381) network_status: LMS IP: 192.168.1.224, hport: 9000, cport: 9090
[00:11:18.613] process:578 unhandled vers
Guru Meditation Error: Core 1 panic'ed (LoadProhibited). Exception was unhandled.Core 1 register dump:
PC : 0x4026ec2f PS : 0x00060f30 A0 : 0x80102b8f A1 : 0x3f801a20
A2 : 0x00000000 A3 : 0x3ffbb1fc A4 : 0x00000001 A5 : 0x00000000
A6 : 0x00000000 A7 : 0x00000000 A8 : 0x80098de7 A9 : 0x3f8019e0
A10 : 0x3ffc4388 A11 : 0x3ffbf5a8 A12 : 0x3ffc438c A13 : 0x00060f20
A14 : 0x000000fe A15 : 0x00000001 SAR : 0x0000001a EXCCAUSE: 0x0000001c
EXCVADDR: 0x00000080 LBEG : 0x40093da8 LEND : 0x40093dc4 LCOUNT : 0xffffffffBacktrace:0x4026ec2c:0x3f801a20 0x40102b8c:0x3f801a40 0x400fb3b9:0x3f801b20 0x400fbe1d:0x3f801b40 0x400ff57a:0x3f801b60 0x400fa0cb:0x3f801c40 0x400de558:0x3f801f70
ELF file SHA256: 0000000000000000
Rebooting...
Issue Description
- Observed Behavior: Presense of the HA slimproto server in the network cause device to bootloop
- Expected Behavior: Server should be discovered and paired normally
- Steps to Reproduce:
3.1. Make sure squeezelite-esp32 device boots and start LMS server discovery
3.2. Enable slimproto player provider in the HA / MA
3.3. Observe squeezelite-esp32 crash and bootloop within seconds.
If you guide me to investigate and possibly fix this issue, I would be happy to do it myself. From the looks of it, seems that message is malformed or at least does not look as expected. I tried to enable more logging via telnet, but this yield no more information that standard logs have