sle118
commented
1 year ago Thank you for following the bug submission template. You have the gold Star ⭐ here!
It seems like the crash happens when decoding Vorbis?
Closed ElFishi closed 1 year ago
sle118
commented
1 year ago Thank you for following the bug submission template. You have the gold Star ⭐ here!
It seems like the crash happens when decoding Vorbis?
ElFishi
commented
1 year ago Thank you, but you guys are doing such a magnificent job here. The least I can do is follow your suggestions.
It happens when streaming via spotty which is 99% of what the ESP does. Is that Vorbis?
sle118
commented
1 year ago Yes it is. Are you able to try streaming a different source and see if this happens? For example if you have a local collection compressed with FLAC or something like that.
Vorbis is the area that @philippe44 knows so perhaps he would have a clue.
ElFishi
commented
1 year ago I can stream local FLAC. Will try.
ElFishi
commented
1 year ago Seems like two problems atm (current fw is I2S-4MFlash-1627),
One is the Guru Meditation error. So far I have not been able to trigger it by playing local FLAC.
The other is that network connection currently is hit and miss. Log of unsuccessful reboot
ets Jun 8 2016 00:22:57
rst:0x1 (POWERON_RESET),boot:0x1f (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:0x3fff0018,len:4
load:0x3fff001c,len:6948
load:0x40078000,len:13772
load:0x40080400,len:4532
entry 0x400806a0
(61) boot: Chip Revision: 1
(63) boot_comm: chip revision: 1, min. bootloader chip revision: 0
(39) boot: ESP-IDF v4.0.2-206-g5630b17e1 2nd stage bootloader
(39) boot: compile time 05:46:08
(39) boot: Enabling RNG early entropy source...
(45) qio_mode: Enabling default flash chip QIO
(50) boot: SPI Speed : 80MHz
(54) boot: SPI Mode : QIO
(58) boot: SPI Flash Size : 4MB
(62) boot: Partition Table:
(66) boot: ## Label Usage Type ST Offset Length
(73) boot: 0 nvs WiFi data 01 02 00009000 00004000
(80) boot: 1 otadata OTA data 01 00 0000d000 00002000
(88) boot: 2 phy_init RF data 01 01 0000f000 00001000
(95) boot: 3 recovery factory app 00 00 00010000 00140000
(103) boot: 4 ota_0 OTA app 00 10 00150000 002a0000
(110) boot: 5 settings WiFi data 01 02 003f0000 00010000
(118) boot: End of partition table
(122) boot_comm: chip revision: 1, min. application chip revision: 0
(129) esp_image: segment 0: paddr=0x00150020 vaddr=0x3f400020 size=0xb4660 (738912) map
(376) esp_image: segment 1: paddr=0x00204688 vaddr=0x3ffbdb60 size=0x05a3c ( 23100) load
(384) esp_image: segment 2: paddr=0x0020a0cc vaddr=0x40080000 size=0x05f4c ( 24396) load
(394) esp_image: segment 3: paddr=0x00210020 vaddr=0x400d0020 size=0x1b3408 (1782792) map
(967) esp_image: segment 4: paddr=0x003c3430 vaddr=0x40085f4c size=0x18390 ( 99216) load
(1004) esp_image: segment 5: paddr=0x003db7c8 vaddr=0x400c0000 size=0x00068 ( 104) load
(1023) boot: Loaded app from partition at offset 0x150000
(1023) boot: Disabling RNG early entropy source...
(1023) psram: This chip is ESP32-D0WD
(1028) spiram: Found 64MBit SPI RAM device
(1033) spiram: SPI RAM mode: flash 80m sram 80m
(1038) spiram: PSRAM initialized, cache is in low/high (2-core) mode.
(1045) cpu_start: Pro cpu up.
(1049) cpu_start: Starting app cpu, entry point is 0x40081408
(0) cpu_start: App cpu up.
(1552) spiram: SPI SRAM memory test OK
(1565) cpu_start: Pro cpu start user code
(1565) cpu_start: cpu freq: 240000000
(1565) cpu_start: Application information:
(1568) cpu_start: Project name: Squeezelite-ESP32
(1574) cpu_start: App version: I2S-4MFlash-1627
(1580) cpu_start: Compile time: Oct 25 2023 01:53:05
(1586) cpu_start: ELF file SHA256: 0000000000000000...
(1592) cpu_start: ESP-IDF: v4.3.5-dirty
(1597) cpu_start: Min chip rev: v1.0
(1602) cpu_start: Max chip rev: v3.99
(1607) cpu_start: Chip rev: v1.0
(1612) heap_init: Initializing. RAM available for dynamic allocation:
(1619) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
(1625) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
(1632) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
(1638) heap_init: At 3FFC6F28 len 000190D8 (100 KiB): DRAM
(1644) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
(1651) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
(1657) heap_init: At 4009E2DC len 00001D24 (7 KiB): IRAM
(1663) spiram: Adding pool of 4018K of external SPI memory to heap allocator
(1672) spi_flash: detected chip: generic
(1676) spi_flash: flash io: qio
(1683) cpu_start: Starting scheduler on PRO CPU.
(0) cpu_start: Starting scheduler on APP CPU.
(1691) spiram: Reserving pool of 64K of internal memory for DMA/internal allocations
(1701) esp_app_main: System is booting from power on.
(1711) esp_app_main: Reset reason is: 1
(1711) esp_app_main: Reboot counter=1
(1711) esp_app_main: Starting app_main
(1721) nvs_utilities: Initializing flash nvs
(1751) nvs_utilities: Initializing nvs partition settings
(1781) esp_app_main: Setting up telnet.
(1791) telnet: ***Redirecting log output to telnet
(1791) esp_app_main: Setting up config subsystem.(1861) nvs_utilities: Configuration memory usage. Heap internal:226311 (min:226171) (used:216) external:4054423 (min:4046467) (used:16260)
(1871) esp_app_main: Registering default values
(1871) system_api: Base MAC address is not set
(1881) system_api: read default base MAC address from EFUSE(1891) config: Waiting for config commit ...
(2871) config: configuration has some uncommitted entries
(2871) config: Committing configuration to nvs. Locking config object.
(2871) config: Done Committing configuration to nvs.
(2881) config: Config committed!
(2881) esp_app_main: Configuring services
(2881) services: Configuring I2C sda:2 scl:4 port:1 speed:400000
(2891) services: Configuring SPI mosi:-1 miso:-1 clk:-1 host:1 dc:-1(2901) services: no SPI configured
(2901) led: Configuring LEDs green:19 (on:1 rmt:-1 -1% ), red:18 (on:1 rmt:-1 -1% )
(2911) battery: No battery
(2911) monitor: Initializing monitoring
(2921) monitor: Heap internal:226555 (min:225983) external:4037783 (min:4037735) dma:219475 (min:218919)
(2931) esp_app_main: Initializing display
(2931) display: Trying to configure display with I2C,width=128,height=64,address=60,driver=SSD1306
(2941) SSD1306: SSD1306 driver
(2981) display: Display is I2C on port 60
(2991) gds: Adding line 1 at -3 (height:14)
(2991) gds: Adding line 2 at 8 (height:24)
(2991) esp_app_main: Initializing led_vu
(2991) led_vu: led_vu configuration invalid
(3001) esp_app_main: Checking for update url(3001) config: Value not found for key fwurl
(3011) IR: Starting Infrared Receiver mode nec on gpio 15 and channel 7
(3021) buttons: Created infrared receiver using GPIO 15
(3021) buttons: starting button tasks(3031) config: Value not found for key
(3041) config: Value not found for key apdelay
(3041) uart: queue free spaces: 3
(3041) network_handlers: Network manager configuration: polling max 10176, polling min 15000, ap delay 20000, dhcp timeout 8000, eth timeout 8000(3071) network_wifi: No known access point found
(3071) network_wifi: Adding legacy/active wifi connection to the known list
(3081) http_server: Initializing HTTP Server
(3081) network_ethernet: Attempting to initialize Ethernet
(3091) network_ethernet: No Ethernet configuration, or configuration invalid
I (3111) wifi:wifi driver task: 3ffcaba0, prio:23, stack:6656, core=0
I (3121) wifi:wifi firmware version: 9ec65ef
I (3121) wifi:wifi certification version: v7.0
I (3121) wifi:config NVS flash: enabled
I (3121) wifi:config nano formating: disabled
I (3131) wifi:Init data frame dynamic rx buffer num: 40
I (3131) wifi:Init management frame dynamic rx buffer num: 40
I (3141) wifi:
Init management short buffer num: 32
I (3151) wifi:Init static tx buffer num: 12
I (3151) wifi:Init tx cache buffer num: 32
I (3151) wifi:Init static rx buffer size: 1600Type '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 (3171) wifi:Init static rx buffer num: 12
I (3171) wifi:Init dynamic rx buffer num: 40To automatically execute lines at startup:
<9>Set NVS variable autoexec (U8) = 1 to enable, 0 to disable automatic execution.
<9>Set NVS variable autoexec[1~9] (string)to a command that should be executed automatically
(3201) wifi_init: tcpip mbox: 32
(3201) wifi_init: udp mbox: 32
(3211) wifi_init: tcp mbox: 32
(3211) wifi_init: tcp tx win: 8192
(3211) wifi_init: tcp rx win: 32768
****************************
Your terminal application does not support escape sequences.
Line editing and history features are disabled.
On Windows, try using Putty instead.
****************************
(3221) wifi_init: tcp mss: 1440(3231) console: Processing autoexec commands while network manager active. Wifi related commands will be ignored.
(3241) wifi_init: WiFi/LWIP prefer SPIRAM
(3251) console: autoexec is set to perform auto-process
(3261) network_wifi: Starting wifi
(3271) console: Running command autoexec1 = squeezelite -o I2S -b 500:2000 -d all=info -C 30 -W -n "Scarlet"
(3271) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07(3281) config: Value not found for key autoexec2
(3281) squeezelite_cmd: Calling squeezelite
squeezelite-esp32> [00:00:01.733] sb_controls_init:249 initializing audio (buttons/rotary/ir) controls (raw:0)
[00:00:01.745] sendSETD:440 sending dimension display:128x64 led_config:0
(3311) embedded: setting power GPIO 26 (active:1)
[00:00:01.748] stream_init:387 init stream
[00:00:01.760] output_init_embedded:78 init device: I2S
[00:00:01.761] output_init_common:433 supported rates: 192000 176400 96000 88200 48000 44100 32000 24000 22050 16000 12000 11025 8000
[00:00:01.773] output_init_embedded:100 init I2S/SPDIF
(3341) DAC core: DAC uses I2C port:0, sda:14, scl:13
(3351) DAC external: DAC on I2C @72
[00:00:01.787] output_init_i2s:347 configuring MCLK on GPIO -1
[00:00:01.799] output_init_i2s:359 invalid MCK gpio -1
(3361) I2S: DMA Malloc info, datalen=blocksize=2048, dma_buf_count=12
(3371) I2S: APLL: Req RATE: 44100, real rate: 44099.988, BITS: 16, CLKM: 1, BCK_M: 8, MCLK: 11289597.000, SCLK: 1411199I (3371) wifi:.625000, diva: 1, divb: 0
mode : sta (30:ae:a4:c5:yy:yy)
[00:00:01.824] output_init_i2s:376 i2s DAC using I2S bck:25, ws:33, do:32, mute:-1:0 (res:0)
I (3391) wifi:enable tsf[00:00:01.836] 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.848] equalizer_set_samplerate:121 equalizer sample rate 44100
(3411) network_handlers: Existing wifi config found. Attempting to connect.
[00:00:01.850] output_thread_i2s:518 Output state is -1
[00:00:01.851] output_visu_init:75 Initialize VISUEXPORT 512 16 bits samples
(3431) network: Starting DHCP client
[00:00:01.861] output_thread_i2s:522 switching off amp GPIO -1
(3441) network_wifi: Wifi Connecting to mySSID...
[00:00:01.873] output_init_embedded:108 init completed.
[00:00:01.897] decode_init:153 init decode
[00:00:01.897] register_alac:547 using alac to decode alc
[00:00:01.898] register_helixaac:686 using helix-aac to decode aac
[00:00:01.909] register_vorbis:506 using vorbis to decode ogg
[00:00:01.910] register_opus:444 using opus to decode ops
[00:00:01.921] register_flac:332 using flac to decode ogf,flc
[00:00:01.921] register_pcm:468 using pcm to decode wav,aif,pcm
[00:00:01.932] register_mad:417 using mad to decode mp3
[00:00:01.933] register_external:478 Initializing CSpot sink
[00:00:01.947] discover_server:832 sending discovery 25
[00:00:01.949] discover_server:836 error sending discovery
I (5861) wifi:new:<11,0>, old:<1,0>, ap:<255,255>, sta:<11,0>, prof:1
I (6441) wifi:state: init -> auth (b0)
I (6441) wifi:state: auth -> init (8a0)
I (6441) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1(6451) network_wifi: WIFI_EVENT_STA_DISCONNECTED. From BSSID: 98:9b:cb:16:xx:xx, reason code: 202 (WIFI_REASON_AUTH_FAIL)
W (6461) wifi:Haven't to connect to a suitable AP now!
(6461) network_wifi: Configuring Access Point.
(6471) network: Stopping DHCP server
(6471) network: Starting DHCP server
(6481) network_wifi: AP SSID: squeezelite-Scarlet
(6481) network_wifi: AP Password: squeezelite
I (6481) wifi:mode : sta (30:ae:a4:c5:yy:yy) + softAP (30:ae:a4:c5:43:bd)
I (6501) wifi:Total power save buffer number: 6
I (6501) wifi:Init max length of beacon: 752/752
I (6511) wifi:Init max length of beacon: 752/752
I (7091) wifi:Total power save buffer number: 6
I (7101) wifi:Total power save buffer number: 6
I (7101) wifi:Set ps type: 1
(7101) network_wifi: Initiating wifi network scan
(7101) dns_server: DNS Server listening on 53/udp
[00:00:06.946] discover_server:832 sending discovery 24
[00:00:11.946] discover_server:832 sending discovery 23
<27>[0;31mE (18451) network: network manager Unhandled Event NETWORK_WIFI_CONFIGURING_ACTIVE_STATE(WIFI_CONFIGURING_STATE) [EN_TIMER]
[00:00:16.946] discover_server:832 sending discovery 22
[00:00:21.946] discover_server:832 sending discovery 21
[00:00:26.946] discover_server:832 sending discovery 20
[00:00:31.946] discover_server:832 sending discovery 19
[00:00:36.946] discover_server:832 sending discovery 18
(...)
Log of successful reboot
rst:0x1 (POWERON_RESET),boot:0x1f (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:0x3fff0018,len:4
load:0x3fff001c,len:6948
load:0x40078000,len:13772
load:0x40080400,len:4532
entry 0x400806a0
(61) boot: Chip Revision: 1
(63) boot_comm: chip revision: 1, min. bootloader chip revision: 0
(39) boot: ESP-IDF v4.0.2-206-g5630b17e1 2nd stage bootloader
(39) boot: compile time 05:46:08
(39) boot: Enabling RNG early entropy source...
(45) qio_mode: Enabling default flash chip QIO
(50) boot: SPI Speed : 80MHz
(54) boot: SPI Mode : QIO
(58) boot: SPI Flash Size : 4MB
(62) boot: Partition Table:
(66) boot: ## Label Usage Type ST Offset Length
(73) boot: 0 nvs WiFi data 01 02 00009000 00004000
(80) boot: 1 otadata OTA data 01 00 0000d000 00002000
(88) boot: 2 phy_init RF data 01 01 0000f000 00001000
(95) boot: 3 recovery factory app 00 00 00010000 00140000
(103) boot: 4 ota_0 OTA app 00 10 00150000 002a0000
(110) boot: 5 settings WiFi data 01 02 003f0000 00010000
(118) boot: End of partition table
(122) boot_comm: chip revision: 1, min. application chip revision: 0
(129) esp_image: segment 0: paddr=0x00150020 vaddr=0x3f400020 size=0xb4660 (738912) map
(376) esp_image: segment 1: paddr=0x00204688 vaddr=0x3ffbdb60 size=0x05a3c ( 23100) load
(384) esp_image: segment 2: paddr=0x0020a0cc vaddr=0x40080000 size=0x05f4c ( 24396) load
(394) esp_image: segment 3: paddr=0x00210020 vaddr=0x400d0020 size=0x1b3408 (1782792) map
(967) esp_image: segment 4: paddr=0x003c3430 vaddr=0x40085f4c size=0x18390 ( 99216) load
(1004) esp_image: segment 5: paddr=0x003db7c8 vaddr=0x400c0000 size=0x00068 ( 104) load
(1023) boot: Loaded app from partition at offset 0x150000
(1023) boot: Disabling RNG early entropy source...
(1023) psram: This chip is ESP32-D0WD
(1028) spiram: Found 64MBit SPI RAM device
(1033) spiram: SPI RAM mode: flash 80m sram 80m
(1038) spiram: PSRAM initialized, cache is in low/high (2-core) mode.
(1045) cpu_start: Pro cpu up.
(1049) cpu_start: Starting app cpu, entry point is 0x40081408
(0) cpu_start: App cpu up.
(1552) spiram: SPI SRAM memory test OK
(1565) cpu_start: Pro cpu start user code
(1565) cpu_start: cpu freq: 240000000
(1565) cpu_start: Application information:
(1568) cpu_start: Project name: Squeezelite-ESP32
(1574) cpu_start: App version: I2S-4MFlash-1627
(1580) cpu_start: Compile time: Oct 25 2023 01:53:05
(1586) cpu_start: ELF file SHA256: 0000000000000000...
(1592) cpu_start: ESP-IDF: v4.3.5-dirty
(1597) cpu_start: Min chip rev: v1.0
(1602) cpu_start: Max chip rev: v3.99
(1607) cpu_start: Chip rev: v1.0
(1612) heap_init: Initializing. RAM available for dynamic allocation:
(1619) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
(1625) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
(1632) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
(1638) heap_init: At 3FFC6F28 len 000190D8 (100 KiB): DRAM
(1644) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
(1651) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
(1657) heap_init: At 4009E2DC len 00001D24 (7 KiB): IRAM
(1663) spiram: Adding pool of 4018K of external SPI memory to heap allocator
(1672) spi_flash: detected chip: generic
(1676) spi_flash: flash io: qio
(1683) cpu_start: Starting scheduler on PRO CPU.
(0) cpu_start: Starting scheduler on APP CPU.
(1691) spiram: Reserving pool of 64K of internal memory for DMA/internal allocations
(1701) esp_app_main: System is booting from power on.
(1711) esp_app_main: Reset reason is: 1
(1711) esp_app_main: Reboot counter=1
(1711) esp_app_main: Starting app_main
(1721) nvs_utilities: Initializing flash nvs
(1751) nvs_utilities: Initializing nvs partition settings
(1781) esp_app_main: Setting up telnet.
(1791) telnet: ***Redirecting log output to telnet
(1791) esp_app_main: Setting up config subsystem.(1861) nvs_utilities: Configuration memory usage. Heap internal:226311 (min:226171) (used:216) external:4054423 (min:4046467) (used:16260)
(1871) esp_app_main: Registering default values
(1871) system_api: Base MAC address is not set
(1881) system_api: read default base MAC address from EFUSE(1891) config: Waiting for config commit ...
(2871) config: configuration has some uncommitted entries
(2871) config: Committing configuration to nvs. Locking config object.
(2871) config: Done Committing configuration to nvs.
(2881) config: Config committed!
(2881) esp_app_main: Configuring services
(2881) services: Configuring I2C sda:2 scl:4 port:1 speed:400000
(2891) services: Configuring SPI mosi:-1 miso:-1 clk:-1 host:1 dc:-1(2901) services: no SPI configured
(2901) led: Configuring LEDs green:19 (on:1 rmt:-1 -1% ), red:18 (on:1 rmt:-1 -1% )
(2911) battery: No battery
(2911) monitor: Initializing monitoring
(2921) monitor: Heap internal:226555 (min:225983) external:4037783 (min:4037735) dma:219475 (min:218919)
(2931) esp_app_main: Initializing display
(2931) display: Trying to configure display with I2C,width=128,height=64,address=60,driver=SSD1306
(2941) SSD1306: SSD1306 driver
(2981) display: Display is I2C on port 60
(2991) gds: Adding line 1 at -3 (height:14)
(2991) gds: Adding line 2 at 8 (height:24)
(2991) esp_app_main: Initializing led_vu
(2991) led_vu: led_vu configuration invalid
(3001) esp_app_main: Checking for update url(3001) config: Value not found for key fwurl
(3011) IR: Starting Infrared Receiver mode nec on gpio 15 and channel 7
(3021) buttons: Created infrared receiver using GPIO 15
(3021) buttons: starting button tasks(3031) config: Value not found for key
(3041) config: Value not found for key apdelay
(3041) uart: queue free spaces: 3
(3041) network_handlers: Network manager configuration: polling max 10176, polling min 15000, ap delay 20000, dhcp timeout 8000, eth timeout 8000(3071) network_wifi: No known access point found
(3071) network_wifi: Adding legacy/active wifi connection to the known list
(3081) http_server: Initializing HTTP Server
(3081) network_ethernet: Attempting to initialize Ethernet
(3091) network_ethernet: No Ethernet configuration, or configuration invalid
I (3111) wifi:wifi driver task: 3ffcaba0, prio:23, stack:6656, core=0
I (3121) wifi:wifi firmware version: 9ec65ef
I (3121) wifi:wifi certification version: v7.0
I (3121) wifi:config NVS flash: enabled
I (3121) wifi:config nano formating: disabled
I (3131) wifi:Init data frame dynamic rx buffer num: 40
I (3131) wifi:Init management frame dynamic rx buffer num: 40
I (3141) wifi:
Init management short buffer num: 32
I (3151) wifi:Init static tx buffer num: 12
I (3151) wifi:Init tx cache buffer num: 32
I (3151) wifi:Init static rx buffer size: 1600Type '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 (3171) wifi:Init static rx buffer num: 12
I (3171) wifi:Init dynamic rx buffer num: 40To automatically execute lines at startup:
<9>Set NVS variable autoexec (U8) = 1 to enable, 0 to disable automatic execution.
<9>Set NVS variable autoexec[1~9] (string)to a command that should be executed automatically
(3201) wifi_init: tcpip mbox: 32
(3201) wifi_init: udp mbox: 32
(3211) wifi_init: tcp mbox: 32
(3211) wifi_init: tcp tx win: 8192
(3211) wifi_init: tcp rx win: 32768
****************************
Your terminal application does not support escape sequences.
Line editing and history features are disabled.
On Windows, try using Putty instead.
****************************
(3221) wifi_init: tcp mss: 1440(3231) console: Processing autoexec commands while network manager active. Wifi related commands will be ignored.
(3241) wifi_init: WiFi/LWIP prefer SPIRAM
(3251) console: autoexec is set to perform auto-process
(3261) network_wifi: Starting wifi
(3271) console: Running command autoexec1 = squeezelite -o I2S -b 500:2000 -d all=info -C 30 -W -n "Scarlet"
(3271) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07(3281) config: Value not found for key autoexec2
(3281) squeezelite_cmd: Calling squeezelite
squeezelite-esp32> [00:00:01.733] sb_controls_init:249 initializing audio (buttons/rotary/ir) controls (raw:0)
[00:00:01.745] sendSETD:440 sending dimension display:128x64 led_config:0
(3311) embedded: setting power GPIO 26 (active:1)
[00:00:01.748] stream_init:387 init stream
[00:00:01.759] output_init_embedded:78 init device: I2S
[00:00:01.761] output_init_common:433 supported rates: 192000 176400 96000 88200 48000 44100 32000 24000 22050 16000 12000 11025 8000
[00:00:01.773] output_init_embedded:100 init I2S/SPDIF
(3341) DAC core: DAC uses I2C port:0, sda:14, scl:13
(3351) DAC external: DAC on I2C @72
[00:00:01.787] output_init_i2s:347 configuring MCLK on GPIO -1
[00:00:01.798] output_init_i2s:359 invalid MCK gpio -1
(3361) I2S: DMA Malloc info, datalen=blocksize=2048, dma_buf_count=12
I (3371) wifi:mode : sta (30:ae:a4:c5:yy:yy)
(3381) I2S: APLL: Req RATE: 44100, real rate: 44099.988, BITS: 16, CLKM: 1, BCK_M: 8, MCLK: 11289597.000, SCLK: 1411199I (3381) wifi:.625000, diva: 1, divb: 0
enable tsf
[00:00:01.824] output_init_i2s:376 i2s DAC using I2S bck:25, ws:33, do:32, mute:-1:0 (res:0)
(3391) network_handlers: Existing wifi config found. Attempting to connect.
[00:00:01.836] output_init_i2s:396 Initializing I2S mode normal with rate: 44100, bits per sample: 16, buffer frames: 512, number of buffers: 12
(3401) network: Starting DHCP client
[00:00:01.859] equalizer_set_samplerate:121 equalizer sample rate 44100
(3431) network_wifi: Wifi Connecting to mySSID...
[00:00:01. output_thread_i2s:518 Output state is -1
[00:00:01.864] output_visu_init:75 Initialize VISUEXPORT 512 16 bits samples
[00:00:01.876] output_thread_i2s:522 switching off amp GPIO -1
[00:00:01.888] output_init_embedded:108 init completed.
[00:00:01.889] decode_init:153 init decode
[00:00:01.900] register_alac:547 using alac to decode alc
[00:00:01.901] register_helixaac:686 using helix-aac to decode aac
[00:00:01.912] register_vorbis:506 using vorbis to decode ogg
[00:00:01.912] register_opus:444 using opus to decode ops
[00:00:01.923] register_flac:332 using flac to decode ogf,flc
[00:00:01.924] register_pcm:468 using pcm to decode wav,aif,pcm
[00:00:01.925] register_mad:417 using mad to decode mp3
[00:00:01.936] register_external:478 Initializing CSpot sink
[00:00:01.940] discover_server:832 sending discovery 25
[00:00:01.941] discover_server:836 error sending discovery
I (5851) wifi:new:<11,0>, old:<1,0>, ap:<255,255>, sta:<11,0>, prof:1
I (6431) wifi:state: init -> auth (b0)
I (6441) wifi:state: auth -> assoc (0)
I (6441) wifi:state: assoc -> run (10)
I (6471) wifi:connected with mySSID, aid = 6, channel 11, BW20, bssid = 98:9b:cb:16:xx:xx
I (6471) wifi:security: WPA2-PSK, phy: bgn, rssi: -46
I (6471) wifi:pm start, type: 1
(6491) network: Got an IP address from interface Wifi. IP=192.168.0.124, Gateway=192.168.0.1, NetMask=255.255.255.0, Address was changed
(6491) esp_netif_handlers: sta ip: 192.168.0.124, mask: 255.255.255.0, gw: 192.168.0.1
(6511) esp_app_main: Network connected and mDNS initialized with Scarlet
I (6521) wifi:AP's beacon interval = 102400 us, DTIM period = 1
(6521) cspot: starting Spotify on host Scarlet
[00:00:04.988] <27>[0;34mI <27>[0;95mShim.cpp:344: CSpot instance service name Scarlet-cspot (id 142137fd329622137a1490160000003305913177)
[00:00:04.992] <27>[0;34mI <27>[0;95mShim.cpp:331: ZeroConf mode (port 80)
[00:00:06.956] discover_server:832 sending discovery 24
[00:00:06.966] discover_server:844 got response from: 192.168.0.105:3483
[00:00:06.967] slimproto:952 connecting to 192.168.0.105:3483
[00:00:06.973] slimproto:999 connected
[00:00:06.974] sendHELO:153 mac: 30:ae:a4:c5:yy:yy
[00:00:06.985] sendHELO:155 cap: Model=squeezeesp32,AccuratePlayPoints=1,HasDigitalOut=1,HasPolarityInversion=1,Balance=1,Depth=16,Firmware=v1.0-1627-16,ModelName=SqueezeESP32,MaxSampleRate=192000,alc,aac,ogg,ops,ogf,flc,wav,aif,pcm,mp3
[00:00:07.009] sendSETD:440 sending dimension display:128x64 led_config:0
[00:00:07.014] notify:228 notified server 192.168.0.105 hport 9000 cport 9090
(8581) network_status: LMS IP: 192.168.0.105, hport: 9000, cport: 9090
[00:00:07.027] decode_flush:251 decode flush
[00:00:07.028] output_flush:446 flush output buffer
[00:00:07.044] codec_open:283 codec open: 'f'
[00:00:07.046] stream_sock:508 connecting to 192.168.0.105:9000
[00:00:07.051] stream_sock:582 header: GET /stream.mp3?player=30:ae:a4:c5:yy:yy HTTP/1.0
[00:00:07.059] grfb_handler:755 brightness 4
[00:00:07.070] grfs_handler:807 scroller current size 1280 (w:436)
[00:00:07.072] grfs_handler:807 scroller current size 2256 (w:436)
[00:00:07.091] visu_handler:1260 Visualizer with 2 bars of width 0:63:1:0 (w:128,h:32,c:0,r:32,s:0.00)
[00:00:07.095] equalizer_set_gain:165 equalizer gain 0,0,0,0,0,0,0,0,0,0
[00:00:07.098] equalizer_set_loudness:187 loudness 0
(8671) embedded: powering player ON
[00:00:07.173] visu_handler:1260 Visualizer with 2 bars of width 0:63:1:0 (w:128,h:32,c:0,r:32,s:0.00)
[00:00:07.192] stream_thread:264 headers: len: 494
HTTP/1.1 200 OK
Server: Logitech Media Server (8.3.1 - 1676361197)
Connection: close
Content-Type: audio/x-flac
Set-Cookie: Squeezebox-albumView=1; path=/
Set-Cookie: Squeezebox-expandPlayerControl=true; path=/
Set-Cookie: Squeezebox-expanded-MY_MUSIC=0; path=/
Set-Cookie: Squeezebox-expanded-FAVORITES=1; path=/
Set-Cookie: Squeezebox-expanded-PLUGINS=0; path=/
Set-Cookie: Squeezebox-expanded-PLUGIN_MY_APPS_MODULE_NAME=1; path=/
Set-Cookie: Squeezebox-expanded-RADIO=0; path=/
[00:00:07.464] output_thread_i2s:518 Output state is 1
[00:00:07.469] output_thread_i2s:585 Restarting I2S.
[00:00:07.522] equalizer_process:222 equalizer deactivated
[00:00:07.530] write_cb:141 setting track_start
[00:00:07.549] _output_frames:65 start buffer frames: 4096
[00:00:07.551] _output_frames:150 track start sample rate: 44100 replay_gain: 0
[00:00:07.552] output_thread_i2s:518 Output state is 2
[00:00:37.223] grfb_handler:755 brightness 2
(182871) httpd_handlers: serving / to peer 192.168.0.142 port 30948
(183431) httpd_handlers: serving /commands.json to peer 192.168.0.142 port 31204
(183591) httpd_handlers: serving /messages.json to peer 192.168.0.142 port 32228
(185031) network_wifi: Initiating wifi network scan
(187901) httpd_handlers: serving /messages.json to peer 192.168.0.142 port 31460(188031) httpd_txrx: httpd_sock_err: error in send : 104(188041) httpd_txrx: httpd_sock_err: error in recv : 104
[00:03:29.958] stream_thread:337 end of stream (12549788 bytes)
[00:03:43.337] decode_thread:100 decode complete
[00:03:43.481] codec_open:283 codec open: 'f'
[00:03:43.484] stream_sock:508 connecting to 192.168.0.105:9000
[00:03:43.489] stream_sock:582 header: GET /stream.mp3?player=30:ae:a4:c5:yy:yy HTTP/1.0
[00:03:43.624] stream_thread:264 headers: len: 494
HTTP/1.1 200 OK
Server: Logitech Media Server (8.3.1 - 1676361197)
(...)
Currently I have several unsuccessful reboots for one successful.
ElFishi
commented
1 year ago Went back to streaming spotty. Recorded another crash and connection failure.
(...)
[02:55:33.727] stream_thread:337 end of stream (11362844 bytes)
[02:55:42.670] vorbis_decode:380 end of decode
[02:55:42.672] decode_thread:100 decode complete
[02:55:42.910] codec_open:283 codec open: 'o'
[02:55:42.911] vorbis_open:399 OPENING CODEC
[02:55:42.915] stream_sock:508 connecting to 192.168.0.105:9000
[02:55:42.920] stream_sock:582 header: GET /stream.mp3?player=30:ae:a4:c5:yy:yy HTTP/1.0
[02:55:43.045] stream_thread:264 headers: len: 491
HTTP/1.1 200 OK
Server: Logitech Media Server (8.3.1 - 1676361197)
Connection: close
Content-Type: audio/ogg
Set-Cookie: Squeezebox-albumView=1; path=/
Set-Cookie: Squeezebox-expandPlayerControl=true; path=/
Set-Cookie: Squeezebox-expanded-MY_MUSIC=0; path=/
Set-Cookie: Squeezebox-expanded-FAVORITES=1; path=/
Set-Cookie: Squeezebox-expanded-PLUGINS=0; path=/
Set-Cookie: Squeezebox-expanded-PLUGIN_MY_APPS_MODULE_NAME=1; path=/
Set-Cookie: Squeezebox-expanded-RADIO=0; path=/
[02:55:43.435] read_vorbis_header:211 id acquired
[02:55:43.441] read_vorbis_header:247 comment skipped succesfully
[02:55:43.485] read_vorbis_header:229 codec up and running (rate: 44100, channels:2)
[02:55:43.487] vorbis_decode:294 setting track_start
[02:55:43.490] vorbis_decode:384 no frame decoded
Guru Meditation Error: Core 1 panic'ed (StoreProhibited). Exception was unhandled.
Core 1 register dump:
PC : 0x400941ef PS : 0x00060830 A0 : 0x801968ce A1 : 0x3ffe9630
A2 : 0x00000000 A3 : 0x00000000 A4 : 0x00001000 A5 : 0x00000000
A6 : 0x0000000d A7 : 0x00000100 A8 : 0x3fb945dc A9 : 0x3fb39528
A10 : 0x3fb39698 A11 : 0x3fb94650 A12 : 0x3fb89b14 A13 : 0x0000001d
A14 : 0x000000d0 A15 : 0x00008000 SAR : 0x0000001c EXCCAUSE: 0x0000001d
EXCVADDR: 0x00000000 LBEG : 0x400940d5 LEND : 0x400940f7 LCOUNT : 0x00000000
Backtrace:0x400941ec:0x3ffe9630 0x401968cb:0x3ffe9640 0x4018c98e:0x3ffe9720 0x401019c1:0x3ffe9750 0x400f7354:0x3ffe9790 0x400d58c8:0x3ffe97c0
ELF file SHA256: 0000000000000000
Rebooting...
ets Jun 8 2016 00:22:57
rst:0xc (SW_CPU_RESET),boot:0x1f (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:0x3fff0018,len:4
load:0x3fff001c,len:6948
load:0x40078000,len:13772
load:0x40080400,len:4532
entry 0x400806a0
I (62) boot: Chip Revision: 1
I (64) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (39) boot: ESP-IDF v4.0.2-206-g5630b17e1 2nd stage bootloader
I (39) boot: compile time 05:46:08
I (40) boot: Enabling RNG early entropy source...
I (46) qio_mode: Enabling default flash chip QIO
I (51) boot: SPI Speed : 80MHz
I (55) boot: SPI Mode : QIO
I (59) boot: SPI Flash Size : 4MB
I (63) boot: Partition Table:
I (67) boot: ## Label Usage Type ST Offset Length
I (74) boot: 0 nvs WiFi data 01 02 00009000 00004000
I (81) boot: 1 otadata OTA data 01 00 0000d000 00002000
I (89) boot: 2 phy_init RF data 01 01 0000f000 00001000
I (96) boot: 3 recovery factory app 00 00 00010000 00140000
I (104) boot: 4 ota_0 OTA app 00 10 00150000 002a0000
I (111) boot: 5 settings WiFi data 01 02 003f0000 00010000
I (119) boot: End of partition table
I (123) boot_comm: chip revision: 1, min. application chip revision: 0
I (130) esp_image: segment 0: paddr=0x00150020 vaddr=0x3f400020 size=0xb4660 (738912) map
I (377) esp_image: segment 1: paddr=0x00204688 vaddr=0x3ffbdb60 size=0x05a3c ( 23100) load
I (385) esp_image: segment 2: paddr=0x0020a0cc vaddr=0x40080000 size=0x05f4c ( 24396) load
I (395) esp_image: segment 3: paddr=0x00210020 vaddr=0x400d0020 size=0x1b3408 (1782792) map
I (968) esp_image: segment 4: paddr=0x003c3430 vaddr=0x40085f4c size=0x18390 ( 99216) load
I (1005) esp_image: segment 5: paddr=0x003db7c8 vaddr=0x400c0000 size=0x00068 ( 104) load
I (1024) boot: Loaded app from partition at offset 0x150000
I (1024) boot: Disabling RNG early entropy source...
I (1024) psram: This chip is ESP32-D0WD
I (1029) spiram: Found 64MBit SPI RAM device
I (1034) spiram: SPI RAM mode: flash 80m sram 80m
I (1039) spiram: PSRAM initialized, cache is in low/high (2-core) mode.
I (1046) cpu_start: Pro cpu up.
I (1050) cpu_start: Starting app cpu, entry point is 0x40081408
I (1037) cpu_start: App cpu up.
I (1553) spiram: SPI SRAM memory test OK
I (1566) cpu_start: Pro cpu start user code
I (1566) cpu_start: cpu freq: 240000000
I (1566) cpu_start: Application information:
I (1569) cpu_start: Project name: Squeezelite-ESP32
I (1575) cpu_start: App version: I2S-4MFlash-1627
I (1581) cpu_start: Compile time: Oct 25 2023 01:53:05
I (1587) cpu_start: ELF file SHA256: 0000000000000000...
I (1593) cpu_start: ESP-IDF: v4.3.5-dirty
I (1598) cpu_start: Min chip rev: v1.0
I (1603) cpu_start: Max chip rev: v3.99
I (1608) cpu_start: Chip rev: v1.0
I (1613) heap_init: Initializing. RAM available for dynamic allocation:
I (1620) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (1626) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (1633) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (1639) heap_init: At 3FFC6F28 len 000190D8 (100 KiB): DRAM
I (1645) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1652) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1658) heap_init: At 4009E2DC len 00001D24 (7 KiB): IRAM
I (1664) spiram: Adding pool of 4018K of external SPI memory to heap allocator
I (1673) spi_flash: detected chip: generic
I (1677) spi_flash: flash io: qio
I (1684) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1692) spiram: Reserving pool of 64K of internal memory for DMA/internal allocations
I (1702) esp_app_main: Reset reason is: 4
I (1702) esp_app_main: Reboot counter=1
I (1712) esp_app_main: Starting app_main
I (1712) nvs_utilities: Initializing flash nvs
I (1752) nvs_utilities: Initializing nvs partition settings
I (1782) esp_app_main: Setting up telnet.
I (1782) telnet: ***Redirecting log output to telnet
I (1782) esp_app_main: Setting up config subsystem.
W (1862) nvs_utilities: Configuration memory usage. Heap internal:226311 (min:226171) (used:216) external:4054423 (min:4046467) (used:16260)
I (1862) esp_app_main: Registering default values
I (1872) system_api: Base MAC address is not set
I (1872) system_api: read default base MAC address from EFUSE
W (1882) config: Waiting for config commit ...
I (2862) config: configuration has some uncommitted entries
I (2862) config: Committing configuration to nvs. Locking config object.
I (2862) config: Done Committing configuration to nvs.
I (2872) config: Config committed!
I (2872) esp_app_main: Configuring services
I (2872) services: Configuring I2C sda:2 scl:4 port:1 speed:400000
I (2882) services: Configuring SPI mosi:-1 miso:-1 clk:-1 host:1 dc:-1
W (2892) services: no SPI configured
I (2892) led: Configuring LEDs green:19 (on:1 rmt:-1 -1% ), red:18 (on:1 rmt:-1 -1% )
I (2902) battery: No battery
I (2902) monitor: Initializing monitoring
I (2912) monitor: Heap internal:226555 (min:225983) external:4037783 (min:4037735) dma:219475 (min:218919)
I (2922) esp_app_main: Initializing display
I (2922) display: Trying to configure display with I2C,width=128,height=64,address=60,driver=SSD1306
I (2932) SSD1306: SSD1306 driver
I (2972) display: Display is I2C on port 60
I (2982) gds: Adding line 1 at -3 (height:14)
I (2982) gds: Adding line 2 at 8 (height:24)
I (2982) esp_app_main: Initializing led_vu
I (2982) led_vu: led_vu configuration invalid
I (2992) esp_app_main: Checking for update url
W (2992) config: Value not found for key fwurl
I (3002) IR: Starting Infrared Receiver mode nec on gpio 15 and channel 7
I (3012) buttons: Created infrared receiver using GPIO 15
I (3012) buttons: starting button taW (3032) config: Value not found for key apdelay
I (3032) uart: queue free spaces: 3
I (3032) network_handlers: Network manager configuration: polling max 10176, polling min 15000, ap delay 20000, dhcp timeout 8000, eth timeout 8000
W (3052) network_wifi: No known access point found
I (3052) network_wifi: Adding legacy/active wifi connection to the known list
I (3062) http_server: Initializing HTTP Server
I (3072) network_ethernet: Attempting to initialize Ethernet
I (3072) network_ethernet: No Ethernet configuration, or configuration invalid
I (3092) wifi:wifi driver task: 3ffcaba0, prio:23, stack:6656, core=0
I (3102) wifi:wifi firmware version: 9ec65ef
I (3102) wifi:wifi certification version: v7.0
I (3102) wifi:config NVS flash: enabled
I (3102) wifi:config nano formating: disabled
I (3112) wifi:Init data frame dynamic rx buffer num: 40
I (3112) wifi:Init management frame dynamic rx buffer num: 40
I (3122) wifi:
Init management short buffer num: 32
I (3132) wifi:Init static tx buffer num: 12
I (3132) wifi:Init tx cache buffer num: 32
I (3132) wifi:Init static rx buffer size: 1600Type '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 (3152) wifi:Init static rx buffer num: 12
I (3152) 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 automatically
I (3182) wifi_init: tcpip mbox: 32
I (3182) wifi_init: udp mbox: 32
I (3192) wifi_init: tcp mbox: 32
I (3192) wifi_init: tcp tx win: 8192
I (3192) wifi_init: tcp rx win: 32768
****************************
Your terminal application does not support escape sequences.
Line editing and history features are disabled.
On Windows, try using Putty instead.
****************************
I (3202) wifi_init: tcp mss: 1440
W (3212) console: Processing autoexec commands while network manager active. Wifi related commands will be ignored.
I (3222) wifi_init: WiFi/LWIP prefer SPIRAM
I (3232) console: autoexec is set to perform auto-process
I (3242) network_wifi: Starting wifi
I (3252) console: Running command autoexec1 = squeezelite -o I2S -b 500:2000 -d all=info -C 30 -W -n "Scarlet"
I (3252) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
W (3262) config: Value not found for key autoexec2
I (3262) squeezelite_cmd: Calling squeezelite
[02:56:02.313] sb_controls_init:249 initializing audio (buttons/rotary/ir) controls (raw:0)
[02:56:02.325] sendSETD:440 sending dimension display:128x64 led_config:0
squeezelite-esp32> I (3302) embedded: setting power GPIO 26 (active:1)
[02:56:02.339] stream_init:387 init stream
[02:56:02.340] output_init_embedded:78 init device: I2S
[02:56:02.351] output_init_common:433 supported rates: 192000 176400 96000 88200 48000 44100 32000 24000 22050 16000 12000 11025 8000
[02:56:02.363] output_init_embedded:100 init I2S/SPDIF
I (3322) DAC core: DAC uses I2C port:0, sda:14, scl:13
I (3322) DAC external: DAC on I2C @72
[02:56:02.377] output_init_i2s:347 configuring MCLK on GPIO -1
[02:56:02.378] output_init_i2s:359 invalid MCK gpio -1
I (3342) wifi:mode : sta (30:ae:a4:c5:yy:yy)
I (3352) wifi:I (3352) I2S: DMA Malloc info, datalen=blocksize=2048, dma_buf_count=12
enable tsf
I (3362) network_handlers: Existing wifi config found. Attempting to connect.
I (3362) I2S: APLL: Req RATE: 44100, real rate: 44099.988, BITS: 16, CLKM: 1, BCK_M: 8, MCLK: 11289597.000, SCLK: 1411199I (3362) network: Starting DHCP client
.625000, diva: 1, divb: 0
I (3382) network_wifi: Wifi Connecting to mySSID...
[02:56:02.427] output_init_i2s:376 i2s DAC using I2S bck:25, ws:33, do:32, mute:-1:0 (res:0)
[02:56:02.440] output_init_i2s:396 Initializing I2S mode normal with rate: 44100, bits per sample: 16, buffer frames: 512, number of buffers: 12
[02:56:02.451] equalizer_set_samplerate:121 equalizer sample rate 44100
[02:56:02. output_thread_i2s:518 Output state is -1
[02:56:02.453] output_visu_init:75 Initialize VISUEXPORT 512 16 bits samples
[02:56:02.465] output_thread_i2s:522 switching off amp GPIO -1
[02:56:02.466] output_init_embedded:108 init completed.
[02:56:02.477] decode_init:153 init decode
[02:56:02.488] register_alac:547 using alac to decode alc
[02:56:02.489] register_helixaac:686 using helix-aac to decode aac
[02:56:02.490] register_vorbis:506 using vorbis to decode ogg
[02:56:02.501] register_opus:444 using opus to decode ops
[02:56:02.501] register_flac:332 using flac to decode ogf,flc
[02:56:02.512] register_pcm:468 using pcm to decode wav,aif,pcm
[02:56:02.513] register_mad:417 using mad to decode mp3
[02:56:02.524] register_external:478 Initializing CSpot sink
[02:56:02.528] discover_server:832 sending discovery 25
[02:56:02.529] discover_server:836 error sending discovery
I (5792) wifi:new:<11,0>, old:<1,0>, ap:<255,255>, sta:<11,0>, prof:1
I (6382) wifi:state: init -> auth (b0)
I (6392) wifi:state: auth -> init (8a0)
I (6392) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
W (6402) network_wifi: WIFI_EVENT_STA_DISCONNECTED. From BSSID: 98:9b:cb:16:xx:xx, reason code: 202 (WIFI_REASON_AUTH_FAIL)
W (6412) wifi:Haven't to connect to a suitable AP now!
I (6412) network_wifi: Configuring Access Point.
I (6422) network: Stopping DHCP server
I (6422) network: Starting DHCP server
I (6432) network_wifi: AP SSID: squeezelite-Scarlet
I (6432) network_wifi: AP Password: squeezelite
I (6432) wifi:mode : sta (30:ae:a4:c5:yy:yy) + softAP (30:ae:a4:c5:zz:zz)
I (6452) wifi:Total power save buffer number: 6
I (6452) wifi:Init max length of beacon: 752/752
I (6462) wifi:Init max length of beacon: 752/752
I (7042) wifi:Total power save buffer number: 6
I (7042) wifi:Total power save buffer number: 6
I (7052) wifi:Set ps type: 1
I (7052) network_wifi: Initiating wifi network scan
I (7052) dns_server: DNS Server listening on 53/udp
[02:56:07.542] discover_server:832 sending discovery 24
[02:56:12.542] discover_server:832 sending discovery 23
E (18392) network: network manager Unhandled Event NETWORK_WIFI_CONFIGURING_ACTIVE_STATE(WIFI_CONFIGURING_STATE) [EN_TIMER]
[02:56:17.542] discover_server:832 sending discovery 22
[02:56:22.542] discover_server:832 sending discovery 21
[02:56:27.542] discover_server:832 sending discovery 20
[02:56:32.542] discover_server:832 sending discovery 19
[02:56:37.542] discover_server:832 sending discovery 18
[02:56:42.542] discover_server:832 sending discovery 17
[02:56:47.542] discover_server:832 sending discovery 16
[02:56:52.542] discover_server:832 sending discovery 15
[02:56:57.542] discover_server:832 sending discovery 14
[02:57:02.542] discover_server:832 sending discovery 13
[02:57:07.542] discover_server:832 sending discovery 12
[02:57:12.542] discover_server:832 sending discovery 11
[02:57:17.542] discover_server:832 sending discovery 10
[02:57:22.542] discover_server:832 sending discovery 9
[02:57:27.542] discover_server:832 sending discovery 8
[02:57:32.542] discover_server:832 sending discovery 7
[02:57:37.542] discover_server:832 sending discovery 6
[02:57:42.542] discover_server:832 sending discovery 5
[02:57:47.542] discover_server:832 sending discovery 4
[02:57:52.542] discover_server:832 sending discovery 3
[02:57:57.542] discover_server:832 sending discovery 2
[02:58:02.542] discover_server:832 sending discovery 1
[02:58:07.542] decode_close:233 close decode
[02:58:07.622] deregister_external:500 Stopping CSpot sink
[02:58:07.623] stream_close:441 close stream
[02:58:07.642] output_close_embedded:112 close output
W (128642) messaging: cfg-audio-tmpl
squeezelite exited with error code 0
W (128642) messaging: cfg-audio-tmpl
squeezelite exited with error code 0
E (128652) messaging: cfg-audio-tmpl
Rebooting in 60 sec
E (128652) messaging: cfg-audio-tmpl
Rebooting in 60 sec
I (188662) wifi:flush txq
I (188662) wifi:stop sw txq
I (188662) wifi:lmac stop hw txq
ets Jun 8 2016 00:22:57
rst:0xc (SW_CPU_RESET),boot:0x1f (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:0x3fff0018,len:4
load:0x3fff001c,len:6948
load:0x40078000,len:13772
load:0x40080400,len:4532
entry 0x400806a0
I (62) boot: Chip Revision: 1
I (64) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (39) boot: ESP-IDF v4.0.2-206-g5630b17e1 2nd stage bootloader
I (39) boot: compile time 05:46:08
I (40) boot: Enabling RNG early entropy source...
I (46) qio_mode: Enabling default flash chip QIO
I (51) boot: SPI Speed : 80MHz
I (55) boot: SPI Mode : QIO
I (59) boot: SPI Flash Size : 4MB
I (63) boot: Partition Table:
I (67) boot: ## Label Usage Type ST Offset Length
I (74) boot: 0 nvs WiFi data 01 02 00009000 00004000
I (81) boot: 1 otadata OTA data 01 00 0000d000 00002000
I (89) boot: 2 phy_init RF data 01 01 0000f000 00001000
I (96) boot: 3 recovery factory app 00 00 00010000 00140000
I (104) boot: 4 ota_0 OTA app 00 10 00150000 002a0000
I (111) boot: 5 settings WiFi data 01 02 003f0000 00010000
I (119) boot: End of partition table
I (123) boot_comm: chip revision: 1, min. application chip revision: 0
I (130) esp_image: segment 0: paddr=0x00150020 vaddr=0x3f400020 size=0xb4660 (738912) map
I (377) esp_image: segment 1: paddr=0x00204688 vaddr=0x3ffbdb60 size=0x05a3c ( 23100) load
I (385) esp_image: segment 2: paddr=0x0020a0cc vaddr=0x40080000 size=0x05f4c ( 24396) load
I (395) esp_image: segment 3: paddr=0x00210020 vaddr=0x400d0020 size=0x1b3408 (1782792) map
I (968) esp_image: segment 4: paddr=0x003c3430 vaddr=0x40085f4c size=0x18390 ( 99216) load
I (1005) esp_image: segment 5: paddr=0x003db7c8 vaddr=0x400c0000 size=0x00068 ( 104) load
I (1023) boot: Loaded app from partition at offset 0x150000
I (1024) boot: Disabling RNG early entropy source...
I (1024) psram: This chip is ESP32-D0WD
I (1029) spiram: Found 64MBit SPI RAM device
I (1034) spiram: SPI RAM mode: flash 80m sram 80m
I (1039) spiram: PSRAM initialized, cache is in low/high (2-core) mode.
I (1046) cpu_start: Pro cpu up.
I (1050) cpu_start: Starting app cpu, entry point is 0x40081408
I (1037) cpu_start: App cpu up.
I (1553) spiram: SPI SRAM memory test OK
I (1566) cpu_start: Pro cpu start user code
I (1566) cpu_start: cpu freq: 240000000
I (1566) cpu_start: Application information:
I (1569) cpu_start: Project name: Squeezelite-ESP32
I (1575) cpu_start: App version: I2S-4MFlash-1627
I (1581) cpu_start: Compile time: Oct 25 2023 01:53:05
I (1587) cpu_start: ELF file SHA256: 0000000000000000...
I (1593) cpu_start: ESP-IDF: v4.3.5-dirty
I (1598) cpu_start: Min chip rev: v1.0
I (1603) cpu_start: Max chip rev: v3.99
I (1608) cpu_start: Chip rev: v1.0
I (1613) heap_init: Initializing. RAM available for dynamic allocation:
I (1620) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (1626) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (1632) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (1639) heap_init: At 3FFC6F28 len 000190D8 (100 KiB): DRAM
I (1645) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1651) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1658) heap_init: At 4009E2DC len 00001D24 (7 KiB): IRAM
I (1664) spiram: Adding pool of 4018K of external SPI memory to heap allocator
I (1673) spi_flash: detected chip: generic
I (1677) spi_flash: flash io: qio
I (1684) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1692) spiram: Reserving pool of 64K of internal memory for DMA/internal allocations
I (1702) esp_app_main: Reset reason is: 3
I (1702) esp_app_main: Reboot counter=1
I (1712) esp_app_main: Starting app_main
I (1712) nvs_utilities: Initializing flash nvs
I (1752) nvs_utilities: Initializing nvs partition settings
I (1782) esp_app_main: Setting up telnet.
I (1782) telnet: ***Redirecting log output to telnet
I (1782) esp_app_main: Setting up config subsystem.
W (1862) nvs_utilities: Configuration memory usage. Heap internal:226311 (min:226171) (used:216) external:4054423 (min:4046467) (used:16260)
I (1862) esp_app_main: Registering default values
I (1872) system_api: Base MAC address is not set
I (1872) system_api: read default base MAC address from EFUSE
W (1882) config: Waiting for config commit ...
I (2862) config: configuration has some uncommitted entries
I (2862) config: Committing configuration to nvs. Locking config object.
I (2862) config: Done Committing configuration to nvs.
I (2872) config: Config committed!
I (2872) esp_app_main: Configuring services
I (2872) services: Configuring I2C sda:2 scl:4 port:1 speed:400000
I (2882) services: Configuring SPI mosi:-1 miso:-1 clk:-1 host:1 dc:-1
W (2892) services: no SPI configured
I (2892) led: Configuring LEDs green:19 (on:1 rmt:-1 -1% ), red:18 (on:1 rmt:-1 -1% )
I (2902) battery: No battery
I (2902) monitor: Initializing monitoring
I (2912) monitor: Heap internal:226555 (min:225983) external:4037783 (min:4037735) dma:219475 (min:218919)
I (2922) esp_app_main: Initializing display
I (2922) display: Trying to configure display with I2C,width=128,height=64,address=60,driver=SSD1306
I (2932) SSD1306: SSD1306 driver
I (2972) display: Display is I2C on port 60
I (2982) gds: Adding line 1 at -3 (height:14)
I (2982) gds: Adding line 2 at 8 (height:24)
I (2982) esp_app_main: Initializing led_vu
I (2982) led_vu: led_vu configuration invalid
I (2992) esp_app_main: Checking for update url
W (2992) config: Value not found for key fwurl
I (3002) IR: Starting Infrared Receiver mode nec on gpio 15 and channel 7
I (3012) buttons: Created infrared receiver using GPIO 15
I (3012) buttons: starting button taW (3032) config: Value not found for key apdelay
I (3032) uart: queue free spaces: 3
I (3032) network_handlers: Network manager configuration: polling max 10176, polling min 15000, ap delay 20000, dhcp timeout 8000, eth timeout 8000
W (3052) network_wifi: No known access point found
I (3052) network_wifi: Adding legacy/active wifi connection to the known list
I (3062) http_server: Initializing HTTP Server
I (3072) network_ethernet: Attempting to initialize Ethernet
I (3072) network_ethernet: No Ethernet configuration, or configuration invalid
I (3092) wifi:wifi driver task: 3ffcaba0, prio:23, stack:6656, core=0
I (3102) wifi:wifi firmware version: 9ec65ef
I (3102) wifi:wifi certification version: v7.0
I (3102) wifi:config NVS flash: enabled
I (3102) wifi:config nano formating: disabled
I (3112) wifi:Init data frame dynamic rx buffer num: 40
I (3112) wifi:Init management frame dynamic rx buffer num: 40
I (3122) wifi:
Init management short buffer num: 32
I (3132) wifi:Init static tx buffer num: 12
I (3132) wifi:Init tx cache buffer num: 32
I (3132) wifi:Init static rx buffer size: 1600Type '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 (3152) wifi:Init static rx buffer num: 12
I (3152) 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 automatically
I (3182) wifi_init: tcpip mbox: 32
I (3182) wifi_init: udp mbox: 32
I (3192) wifi_init: tcp mbox: 32
I (3192) wifi_init: tcp tx win: 8192
I (3192) wifi_init: tcp rx win: 32768
****************************
Your terminal application does not support escape sequences.
Line editing and history features are disabled.
On Windows, try using Putty instead.
****************************
I (3202) wifi_init: tcp mss: 1440
W (3212) console: Processing autoexec commands while network manager active. Wifi related commands will be ignored.
I (3222) wifi_init: WiFi/LWIP prefer SPIRAM
I (3232) console: autoexec is set to perform auto-process
I (3242) network_wifi: Starting wifi
I (3252) console: Running command autoexec1 = squeezelite -o I2S -b 500:2000 -d all=info -C 30 -W -n "Scarlet"
I (3252) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
W (3262) config: Value not found for key autoexec2
I (3262) squeezelite_cmd: Calling squeezelite
squeezelite-esp32> [02:59:10.982] sb_controls_init:249 initializing audio (buttons/rotary/ir) controls (raw:0)
[02:59:10.994] sendSETD:440 sending dimension display:128x64 led_config:0
I (3292) embedded: setting power GPIO 26 (active:1)
[02:59:10.997] stream_init:387 init stream
[02:59:11.009] output_init_embedded:78 init device: I2S
[02:59:11.010] output_init_common:433 supported rates: 192000 176400 96000 88200 48000 44100 32000 24000 22050 16000 12000 11025 8000
[02:59:11.022] output_init_embedded:100 init I2S/SPDIF
I (3322) DAC core: DAC uses I2C port:0, sda:14, scl:13
I (3332) DAC external: DAC on I2C @72
[02:59:11.036] output_init_i2s:347 configuring MCLK on GPIO -1
[02:59:11.048] output_init_i2s:359 invalid MCK gpio -1
I (3342) I2S: DMA Malloc info, datalen=blocksize=2048, dma_buf_count=12
I (3352) I2S: APLL: Req RATE: 44100, real rate: 44099.988, BITS: 16, CLKM: 1, BCK_M: 8, MCLK: 11289597.000, SCLK: 1411199I (3362) wifi:.625000, diva: 1, divb: 0
mode : sta (30:ae:a4:c5:yy:yy)
[02:59:11.073] output_init_i2s:376 i2s DAC using I2S bck:25, ws:33, do:32, mute:-1:0 (res:0)
I (3372) wifi:enable tsf[02:59:11.085] output_init_i2s:396 Initializing I2S mode normal with rate: 44100, bits per sample: 16, buffer frames: 512, number of buffers: 12
[02:59:11.097] equalizer_set_samplerate:121 equalizer sample rate 44100
I (3392) network_handlers: Existing wifi config found. Attempting to connect.
[02:59:11. output_thread_i2s:518 Output state is -1
[02:59:11.099] output_visu_init:75 Initialize VISUEXPORT 512 16 bits samples
I (3412) network: Starting DHCP client
[02:59:11.110] output_thread_i2s:522 switching off amp GPIO -1
I (3422) network_wifi: Wifi Connecting to mySSID...
[02:59:11.122] output_init_embedded:108 init completed.
[02:59:11.146] decode_init:153 init decode
[02:59:11.146] register_alac:547 using alac to decode alc
[02:59:11.147] register_helixaac:686 using helix-aac to decode aac
[02:59:11.158] register_vorbis:506 using vorbis to decode ogg
[02:59:11.159] register_opus:444 using opus to decode ops
[02:59:11.170] register_flac:332 using flac to decode ogf,flc
[02:59:11.170] register_pcm:468 using pcm to decode wav,aif,pcm
[02:59:11.181] register_mad:417 using mad to decode mp3
[02:59:11.182] register_external:478 Initializing CSpot sink
[02:59:11.196] discover_server:832 sending discovery 25
[02:59:11.198] discover_server:836 error sending discovery
I (5842) wifi:new:<11,0>, old:<1,0>, ap:<255,255>, sta:<11,0>, prof:1
I (6422) wifi:state: init -> auth (b0)
I (6432) wifi:state: auth -> assoc (0)
I (6432) wifi:state: assoc -> run (10)
I (6462) wifi:connected with mySSID, aid = 6, channel 11, BW20, bssid = 98:9b:cb:16:xx:xx
I (6462) wifi:security: WPA2-PSK, phy: bgn, rssi: -47
I (6462) wifi:pm start, type: 1
I (6482) network: Got an IP address from interface Wifi. IP=192.168.0.124, Gateway=192.168.0.1, NetMask=255.255.255.0, Address was changed
I (6492) esp_netif_handlers: sta ip: 192.168.0.124, mask: 255.255.255.0, gw: 192.168.0.1
I (6502) esp_app_main: Network connected and mDNS initialized with Scarlet
I (6512) cspot: starting Spotify on host Scarlet
I (6522) wifi:AP's beacon interval = 102400 us, DTIM period = 1
[02:59:14.246] I Shim.cpp:344: CSpot instance service name Scarlet-cspot (id 142137fd329622137a1490160000003305913177)
[02:59:14.249] I Shim.cpp:331: ZeroConf mode (port 80)
[02:59:16.195] discover_server:832 sending discovery 24
[02:59:16.203] discover_server:844 got response from: 192.168.0.105:3483
[02:59:16.205] slimproto:952 connecting to 192.168.0.105:3483
[02:59:16.214] slimproto:999 connected
[02:59:16.215] sendHELO:153 mac: 30:ae:a4:c5:yy:yy
[02:59:16.216] sendHELO:155 cap: Model=squeezeesp32,AccuratePlayPoints=1,HasDigitalOut=1,HasPolarityInversion=1,Balance=1,Depth=16,Firmware=v1.0-1627-16,ModelName=SqueezeESP32,MaxSampleRate=192000,alc,aac,ogg,ops,ogf,flc,wav,aif,pcm,mp3
[02:59:16.250] sendSETD:440 sending dimension display:128x64 led_config:0
[02:59:16.255] notify:228 notified server 192.168.0.105 hport 9000 cport 9090
I (8552) network_status: LMS IP: 192.168.0.105, hport: 9000, cport: 9090
[02:59:16.268] decode_flush:251 decode flush
[02:59:16.269] output_flush:446 flush output buffer
[02:59:16.384] codec_open:283 codec open: 'o'
[02:59:16.386] vorbis_open:399 OPENING CODEC
[02:59:16.387] stream_sock:508 connecting to 192.168.0.105:9000
[02:59:16.391] stream_sock:582 header: GET /stream.mp3?player=30:ae:a4:c5:yy:yy HTTP/1.0
[02:59:16.405] grfb_handler:755 brightness 4
[02:59:16.416] grfs_handler:807 scroller current size 1280 (w:290)
[02:59:16.417] grfs_handler:807 scroller current size 1672 (w:290)
[02:59:16.438] visu_handler:1260 Visualizer with 2 bars of width 0:63:1:0 (w:128,h:32,c:0,r:32,s:0.00)
[02:59:16.445] equalizer_set_gain:165 equalizer gain 0,0,0,0,0,0,0,0,0,0
[02:59:16.447] equalizer_set_loudness:187 loudness 0
I (8742) embedded: powering player ON
[02:59:16.509] visu_handler:1260 Visualizer with 2 bars of width 0:63:1:0 (w:128,h:32,c:0,r:32,s:0.00)
[02:59:16.522] stream_thread:264 headers: len: 491
HTTP/1.1 200 OK
Server: Logitech Media Server (8.3.1 - 1676361197)
Connection: close
Content-Type: audio/ogg
Set-Cookie: Squeezebox-albumView=1; path=/
Set-Cookie: Squeezebox-expandPlayerControl=true; path=/
Set-Cookie: Squeezebox-expanded-MY_MUSIC=0; path=/
Set-Cookie: Squeezebox-expanded-FAVORITES=1; path=/
Set-Cookie: Squeezebox-expanded-PLUGINS=0; path=/
Set-Cookie: Squeezebox-expanded-PLUGIN_MY_APPS_MODULE_NAME=1; path=/
Set-Cookie: Squeezebox-expanded-RADIO=0; path=/
[02:59:17.220] output_thread_i2s:518 Output state is 1
[02:59:17.222] output_thread_i2s:585 Restarting I2S.
[02:59:17.225] equalizer_process:222 equalizer deactivated
[02:59:17.317] read_vorbis_header:211 id acquired
[02:59:17.329] read_vorbis_header:247 comment skipped succesfully
[02:59:17.370] read_vorbis_header:229 codec up and running (rate: 44100, channels:2)
[02:59:17.375] vorbis_decode:294 setting track_start
[02:59:17.402] vorbis_decode:384 no frame decoded
[02:59:17.855] _output_frames:65 start buffer frames: 26176
[02:59:17.858] _output_frames:150 track start sample rate: 44100 replay_gain: 65536
[02:59:17.860] output_thread_i2s:518 Output state is 2
(...)
Will go back to streaming flac.
sle118
commented
1 year ago What bothers me is the auth failures. https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-guides/wifi.html#auth-phase
s2.4: The AP rejects authentication in the response and WIFI_EVENT_STA_DISCONNECTED arises, while the reason code is WIFI_REASON_AUTH_FAIL or the reasons specified by the AP. Refer to Wi-Fi Reason Code.
So it's the ap that rejects the esp32. Not sure why. Which brand of ap do you own?
ElFishi
commented
1 year ago AVM FRITZ!Box 7530 latest fw FRITZ!OS: 7.57
philippe44
commented
1 year ago Re Vorbis there is something in the code that should never have made its way there, but I let it slip. I don't think it does explain your issue, but it is worth trying.
ElFishi
commented
1 year ago v2.1630?
philippe44
commented
1 year ago yes
ElFishi
commented
1 year ago running...
ElFishi
commented
1 year ago Got another crash streaming spotty. This time triggered by skipping to the next track in the playlist in Squeezelite-X.
[01:44:21.699] stream_thread:337 end of stream (5711881 bytes)
[01:44:37.603] vorbis_decode:380 end of decode
[01:44:37.604] decode_thread:100 decode complete
[01:44:37.765] codec_open:283 codec open: 'o'
[01:44:37.770] stream_sock:508 connecting to 192.168.0.105:9000
[01:44:37.774] stream_sock:582 header: GET /stream.mp3?player=30:ae:a4:c5:43:bc HTTP/1.0
[01:44:37.958] stream_thread:264 headers: len: 491
HTTP/1.1 200 OK
Server: Logitech Media Server (8.3.1 - 1676361197)
Connection: close
Content-Type: audio/ogg
Set-Cookie: Squeezebox-albumView=1; path=/
Set-Cookie: Squeezebox-expandPlayerControl=true; path=/
Set-Cookie: Squeezebox-expanded-MY_MUSIC=0; path=/
Set-Cookie: Squeezebox-expanded-FAVORITES=1; path=/
Set-Cookie: Squeezebox-expanded-PLUGINS=0; path=/
Set-Cookie: Squeezebox-expanded-PLUGIN_MY_APPS_MODULE_NAME=1; path=/
Set-Cookie: Squeezebox-expanded-RADIO=0; path=/
[01:44:38.257] read_vorbis_header:211 id acquired
[01:44:38.269] read_vorbis_header:247 comment skipped succesfully
[01:44:38.313] read_vorbis_header:229 codec up and running (rate: 44100, channels:2)
[01:44:38.320] vorbis_decode:294 setting track_start
[01:44:38.333] vorbis_decode:384 no frame decoded
[01:44:49.042] _output_frames:150 track start sample rate: 44100 replay_gain: 65536
[01:44:50.106] grfs_handler:807 scroller current size 1280 (w:262)
[01:44:50.121] grfs_handler:807 scroller current size 1560 (w:262)
[01:46:16.365] decode_flush:251 decode flush
[01:46:16.370] output_flush:446 flush output buffer
[01:46:16.407] output_thread_i2s:518 Output state is 0
[01:46:16.413] codec_open:283 codec open: 'o'
[01:46:16.415] stream_sock:508 connecting to 192.168.0.105:9000
[01:46:16.424] stream_sock:582 header: GET /stream.mp3?player=30:ae:a4:c5:43:bc HTTP/1.0
[01:46:16.580] stream_thread:264 headers: len: 491
HTTP/1.1 200 OK
Server: Logitech Media Server (8.3.1 - 1676361197)
Connection: close
Content-Type: audio/ogg
Set-Cookie: Squeezebox-albumView=1; path=/
Set-Cookie: Squeezebox-expandPlayerControl=true; path=/
Set-Cookie: Squeezebox-expanded-MY_MUSIC=0; path=/
Set-Cookie: Squeezebox-expanded-FAVORITES=1; path=/
Set-Cookie: Squeezebox-expanded-PLUGINS=0; path=/
Set-Cookie: Squeezebox-expanded-PLUGIN_MY_APPS_MODULE_NAME=1; path=/
Set-Cookie: Squeezebox-expanded-RADIO=0; path=/
[01:46:16.783] output_thread_i2s:518 Output state is 1
[01:46:16.854] read_vorbis_header:211 id acquired
[01:46:16.864] read_vorbis_header:247 comment skipped succesfully
[01:46:16.910] read_vorbis_header:229 codec up and running (rate: 44100, channels:2)
[01:46:16.916] vorbis_decode:294 setting track_start
[01:46:16.922] vorbis_decode:384 no frame decoded
Guru Meditation Error: Core 1 panic'ed (StoreProhibited). Exception was unhandled.
Core 1 register dump:
PC : 0x400941ef PS : 0x00060030 A0 : 0x8019690a A1 : 0x3ffe95b0
A2 : 0x00000000 A3 : 0x00000000 A4 : 0x00001000 A5 : 0x00000000
A6 : 0x00000000 A7 : 0x00000100 A8 : 0x3fbb6b0c A9 : 0x3fbc2110
A10 : 0x3fbc2280 A11 : 0x3fbb6b80 A12 : 0x3fbd7b1c A13 : 0x0000001d
A14 : 0x000000d0 A15 : 0x00008000 SAR : 0x00000002 EXCCAUSE: 0x0000001d
EXCVADDR: 0x00000000 LBEG : 0x40094054 LEND : 0x40094070 LCOUNT : 0x00000000
Backtrace:0x400941ec:0x3ffe95b0 0x40196907:0x3ffe95c0 0x4018c9ca:0x3ffe96a0 0x401019b9:0x3ffe96d0 0x400f734c:0x3ffe9710 0x400d58c0:0x3ffe9740
ELF file SHA256: 0000000000000000
Rebooting...
ets Jun 8 2016 00:22:57
Followed by a discover_server:836 error sending discovery, just as before.
In the end there is a reboot that did connect alright.
(...)
[01:47:45.230] discover_server:832 sending discovery 1
[01:47:50.231] decode_close:233 close decode
[01:47:50.330] deregister_external:500 Stopping CSpot sink
[01:47:50.331] stream_close:441 close stream
[01:47:50.340] output_close_embedded:112 close output
W (128662) messaging: cfg-audio-tmpl
squeezelite exited with error code 0
W (128662) messaging: cfg-audio-tmpl
squeezelite exited with error code 0
E (128672) messaging: cfg-audio-tmpl
Rebooting in 60 sec
E (128672) messaging: cfg-audio-tmpl
Rebooting in 60 sec
I (188682) wifi:flush txq
I (188682) wifi:stop sw txq
I (188682) wifi:lmac stop hw txq
ets Jun 8 2016 00:22:57
Next observation: Streaming Spotify via LMS/Spotty leads to a crash every 10k sec or so:
[01:46:16.783] output_thread_i2s:518 Output state is 1
[01:46:16.854] read_vorbis_header:211 id acquired
[01:46:16.864] read_vorbis_header:247 comment skipped succesfully
[01:46:16.910] read_vorbis_header:229 codec up and running (rate: 44100, channels:2)
[01:46:16.916] vorbis_decode:294 setting track_start
[01:46:16.922] vorbis_decode:384 no frame decoded
Guru Meditation Error: Core 1 panic'ed (StoreProhibited). Exception was unhandled.
Core 1 register dump:
PC : 0x400941ef PS : 0x00060030 A0 : 0x8019690a A1 : 0x3ffe95b0
A2 : 0x00000000 A3 : 0x00000000 A4 : 0x00001000 A5 : 0x00000000
A6 : 0x00000000 A7 : 0x00000100 A8 : 0x3fbb6b0c A9 : 0x3fbc2110
A10 : 0x3fbc2280 A11 : 0x3fbb6b80 A12 : 0x3fbd7b1c A13 : 0x0000001d
A14 : 0x000000d0 A15 : 0x00008000 SAR : 0x00000002 EXCCAUSE: 0x0000001d
EXCVADDR: 0x00000000 LBEG : 0x40094054 LEND : 0x40094070 LCOUNT : 0x00000000
Backtrace:0x400941ec:0x3ffe95b0 0x40196907:0x3ffe95c0 0x4018c9ca:0x3ffe96a0 0x401019b9:0x3ffe96d0 0x400f734c:0x3ffe9710 0x400d58c0:0x3ffe9740
ELF file SHA256: 0000000000000000
Rebooting...
(...)
[04:25:08.476] read_vorbis_header:211 id acquired
[04:25:08.486] read_vorbis_header:247 comment skipped succesfully
[04:25:08.533] read_vorbis_header:229 codec up and running (rate: 44100, channels:2)
[04:25:08.535] vorbis_decode:294 setting track_start
[04:25:08.538] vorbis_decode:384 no frame decoded
Guru Meditation Error: Core 1 panic'ed (StoreProhibited). Exception was unhandled.
Core 1 register dump:
PC : 0x400941ef PS : 0x00060230 A0 : 0x8019690a A1 : 0x3ffe96a0
A2 : 0x00000000 A3 : 0x00000000 A4 : 0x00001000 A5 : 0x00000000
A6 : 0x0000000d A7 : 0x00000100 A8 : 0x3fb71b78 A9 : 0x3fb7164c
A10 : 0x3fb717bc A11 : 0x3fb71bec A12 : 0x3fbe7bc8 A13 : 0x0000001d
A14 : 0x000000d0 A15 : 0x00008000 SAR : 0x0000001c EXCCAUSE: 0x0000001d
EXCVADDR: 0x00000000 LBEG : 0x400941f6 LEND : 0x40094201 LCOUNT : 0x00000000
Backtrace:0x400941ec:0x3ffe96a0 0x40196907:0x3ffe96b0 0x4018c9ca:0x3ffe9790 0x401019b9:0x3ffe97c0 0x400f734c:0x3ffe9800 0x400d58c0:0x3ffe9830
ELF file SHA256: 0000000000000000
Rebooting...
(...)
[07:01:14.501] read_vorbis_header:211 id acquired
[07:01:14.510] read_vorbis_header:247 comment skipped succesfully
[07:01:14.557] read_vorbis_header:229 codec up and running (rate: 44100, channels:2)
[07:01:14.565] vorbis_decode:294 setting track_start
[07:01:14.574] vorbis_decode:384 no frame decoded
[07:01:25.193] _output_frames:150 track start sample rate: 44100 replay_gain: 65536
Guru Meditation Error: Core 0 panic'ed (LoadProhibited). Exception was unhandled.
Core 0 register dump:
PC : 0x400e5300 PS : 0x00060630 A0 : 0x800e41ba A1 : 0x3f837480
A2 : 0x00000000 A3 : 0x3f814678 A4 : 0x00000042 A5 : 0x00000000
A6 : 0x00000001 A7 : 0x000000ff A8 : 0x0000001b A9 : 0x3f814678
A10 : 0x00000001 A11 : 0x3f81466c A12 : 0x00000000 A13 : 0x3f814610
A14 : 0x00000001 A15 : 0x0000000a SAR : 0x00000004 EXCCAUSE: 0x0000001c
EXCVADDR: 0x00000020 LBEG : 0x400956b5 LEND : 0x400956c5 LCOUNT : 0xfffffffe
Backtrace:0x400e52fd:0x3f837480 0x400e41b7:0x3f8374b0 0x400e443b:0x3f8374e0 0x400d677d:0x3f837500 0x40094586:0x3f837520 0x400930e5:0x3f837540 0x40093174:0x3f837560 0x4026023d:0x3f837590 0x4025cf6c:0x3f8376b0 0x4026029b:0x3f8379c0 0x402833e6:0x3f8379f0 0x4009c5d3:0x3f837a20 0x400e42b5:0x3f837a70
ELF file SHA256: 0000000000000000
Rebooting...
(...)
[09:59:02.419] read_vorbis_header:211 id acquired
[09:59:02.430] read_vorbis_header:247 comment skipped succesfully
[09:59:02.476] read_vorbis_header:229 codec up and running (rate: 44100, channels:2)
[09:59:02.485] vorbis_decode:294 setting track_start
[09:59:02.501] vorbis_decode:384 no frame decoded
Guru Meditation Error: Core 1 panic'ed (StoreProhibited). Exception was unhandled.
Core 1 register dump:
PC : 0x400941ef PS : 0x00060630 A0 : 0x8019690a A1 : 0x3ffe96a0
A2 : 0x00000000 A3 : 0x00000000 A4 : 0x00001000 A5 : 0x00000000
A6 : 0x00000000 A7 : 0x00000100 A8 : 0x3fbf6e78 A9 : 0x3fba3f48
A10 : 0x3fba40b8 A11 : 0x3fbf6eec A12 : 0x3fbc5f30 A13 : 0x0000001d
A14 : 0x000000d0 A15 : 0x00008000 SAR : 0x00000002 EXCCAUSE: 0x0000001d
EXCVADDR: 0x00000000 LBEG : 0x400941f6 LEND : 0x40094201 LCOUNT : 0x00000000
Backtrace:0x400941ec:0x3ffe96a0 0x40196907:0x3ffe96b0 0x4018c9ca:0x3ffe9790 0x401019b9:0x3ffe97c0 0x400f734c:0x3ffe9800 0x400d58c0:0x3ffe9830
ELF file SHA256: 0000000000000000
Rebooting...
(...)
[12:45:02.462] read_vorbis_header:211 id acquired
[12:45:02.466] read_vorbis_header:247 comment skipped succesfully
[12:45:02.518] read_vorbis_header:229 codec up and running (rate: 44100, channels:2)
[12:45:02.522] vorbis_decode:294 setting track_start
[12:45:02.528] vorbis_decode:384 no frame decoded
Guru Meditation Error: Core 1 panic'ed (StoreProhibited). Exception was unhandled.
Core 1 register dump:
PC : 0x400941ef PS : 0x00060a30 A0 : 0x8019690a A1 : 0x3ffe96a0
A2 : 0x00000000 A3 : 0x00000000 A4 : 0x00001000 A5 : 0x00000000
A6 : 0x00000001 A7 : 0x00000100 A8 : 0x80192df8 A9 : 0x3ffe9640
A10 : 0x00000000 A11 : 0x00000000 A12 : 0x3f400e86 A13 : 0x00000000
A14 : 0x00000008 A15 : 0x00000003 SAR : 0x00000005 EXCCAUSE: 0x0000001d
EXCVADDR: 0x00000000 LBEG : 0x400941f6 LEND : 0x40094201 LCOUNT : 0x00000000
Backtrace:0x400941ec:0x3ffe96a0 0x40196907:0x3ffe96b0 0x4018c9ca:0x3ffe9790 0x401019b9:0x3ffe97c0 0x400f734c:0x3ffe9800 0x400d58c0:0x3ffe9830
ELF file SHA256: 0000000000000000
Rebooting...
(...)
[15:35:39.026] read_vorbis_header:211 id acquired
[15:35:39.035] read_vorbis_header:247 comment skipped succesfully
[15:35:39.084] read_vorbis_header:229 codec up and running (rate: 44100, channels:2)
[15:35:39.088] vorbis_decode:294 setting track_start
[15:35:39.096] vorbis_decode:384 no frame decoded
Guru Meditation Error: Core 1 panic'ed (StoreProhibited). Exception was unhandled.
Core 1 register dump:
PC : 0x400941ef PS : 0x00060e30 A0 : 0x8019690a A1 : 0x3ffe96a0
A2 : 0x00000000 A3 : 0x00000000 A4 : 0x00001000 A5 : 0x00000000
A6 : 0x00000000 A7 : 0x00000100 A8 : 0x3fb50610 A9 : 0x3fbf6f88
A10 : 0x3fbf70f8 A11 : 0x3fb50684 A12 : 0x3fbb5304 A13 : 0x0000001d
A14 : 0x000000d0 A15 : 0x00008000 SAR : 0x00000002 EXCCAUSE: 0x0000001d
EXCVADDR: 0x00000000 LBEG : 0x400941f6 LEND : 0x40094201 LCOUNT : 0x00000000
Backtrace:0x400941ec:0x3ffe96a0 0x40196907:0x3ffe96b0 0x4018c9ca:0x3ffe9790 0x401019b9:0x3ffe97c0 0x400f734c:0x3ffe9800 0x400d58c0:0x3ffe9830
ELF file SHA256: 0000000000000000
Rebooting...
(...)
The last lines before Guru Meditation Error: Core 1 panic'ed (StoreProhibited). Exception was unhandled.
are
[01:46:16.922] vorbis_decode:384 no frame decoded
[04:25:08.538] vorbis_decode:384 no frame decoded
[07:01:25.193] _output_frames:150 track start sample rate: 44100 replay_gain: 65536
[09:59:02.501] vorbis_decode:384 no frame decoded
[12:45:02.528] vorbis_decode:384 no frame decoded
[15:35:39.096] vorbis_decode:384 no frame decoded
times between each crash are 9532, 9377, 10657, 9960, and 10237 seconds, respectively.
edit: fw: I2S-4MFlash-1630
ElFishi
commented
1 year ago ran another 5 hrs this morning, playing local flac from my hard drive ith fw: I2S-4MFlash-1630 and without problems.
philippe44
commented
1 year ago So it's very likely a vorbis problem. But then it can be in my codec wrapper or in the decoder itself. I'll re-re-re-read the wrapper but for the codec, I can't do anything
philippe44
commented
1 year ago So it ended being a memory leak that I should have seen before but become obvious when you listen to vorbis for many hours :smile:. It should be fixed in the latest build (not released yet, I'm waiting for your confirmation.
Thanks very much for finding that issue!
ElFishi
commented
1 year ago Hang in there, I can only get back to it on Monday. How would I get that latest build to confirm?
philippe44
commented
1 year ago Scroll to artifacts https://github.com/sle118/squeezelite-esp32/actions/runs/6675518757
sle118
commented
1 year ago well, I did push a release to resolve the recovery boot loop so the most release should contain the fix
ElFishi
commented
1 year ago Nailed it.
I streamed spotify via spotty for 5hrs yesterday and for 8.5 hrs today without crash.
Also I can't reproduce the connection error today. Was my router having a bad day? idk.
So I am closing this issue now. Well done lads.
Describe the bug
Every few hours or so my ESP crashes with a Guru Meditation Error. After the ensuing reboot the ESP can't connect to the server anymore. Only another reboot will clear the issue
Preliminary Information
Hardware Details
NVS Settings
Logs
Issue Description