search

sle118 / squeezelite-esp32

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

RTP thread aborts during AirPlay playback #328

Closed emlynmac closed 1 year ago

emlynmac commented 1 year ago

To help us resolve your issue as quickly as possible, please follow these guidelines when submitting an issue. Providing all the necessary information will save both your time and ours.

Describe the bug

Seeing crashes when running AirPlay on 16 bit build 1598

Preliminary Information

  1. FW: Squeezeamp-1598
  2. Plugin Version: N/A

Hardware Details

Please describe your hardware setup: ESP32 Wrover B 16M with squeeze amp v3, no charger populated.

NVS Settings

Follow these steps to share your NVS settings:

  1. Open the web UI of your device.
  2. Click on the "Credit" tab.
  3. Enable the "Show NVS Editor" checkbox. This allows you to view or change the NVS configuration even when not in recovery mode.
  4. Navigate to the "NVS Editor" tab.
  5. Scroll to the bottom and click "Download Config".
  6. Share the downloaded content here.

{
  "a2dp_ctmt": "1000",
  "a2dp_ctrld": "500",
  "a2dp_dev_name": "Garage",
  "a2dp_sink_name": "SMSL BT4.2",
  "a2dp_spin": "0000",
  "actrls_config": "",
  "airplay_name": "Garage",
  "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": "",
  "ap_ssid": "Garage",
  "autoexec": "1",
  "autoexec1": "squeezelite  -o i2s  -b  500:2000 -C  30 ",
  "bat_config": "",
  "bt_name": "Garage",
  "bt_sink_pin": "1234",
  "bt_sink_volume": "20",
  "bypass_wm": "0",
  "cspot_config": "{\t\"deviceName\":\t\"Garage\",\t\"bitrate\":\t160}",
  "dac_config": "",
  "dac_controlset": "",
  "dhcp_tmout": "8",
  "display_config": "",
  "enable_airplay": "Y",
  "enable_bt_sink": "Y",
  "enable_cspot": "N",
  "equalizer": "0,0,0,0,0,0,0,0,0,0",
  "eth_config": "",
  "ethtmout": "8",
  "gpio_exp_config": "",
  "host_name": "Garage",
  "i2c_config": "",
  "jack_mutes_amp": "n",
  "led_brightness": "",
  "led_vu_config": "",
  "lms_ctrls_raw": "n",
  "loudness": "0",
  "metadata_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": "https://github.com/sle118/squeezelite-esp32/releases",
  "rotary_config": "",
  "set_GPIO": "0=ir",
  "sleep_config": "",
  "spdif_config": "",
  "spi_config": "",
  "stats": "N",
  "target": "",
  "telnet_block": "500",
  "telnet_buffer": "40000",
  "telnet_enable": "N"
}

Logs

To share logs:

  1. Connect your player to a computer using a USB cable. Use a built-in Serial-USB adapter if your player has one, or an external USB adapter otherwise.
  2. Go to the web installer.
  3. Click "Connect to Device".
  4. Select the appropriate serial port.
  5. Click "Logs And Console".
  6. Download the logs and share them here. Please remove any sensitive information like Wi-Fi passwords or MAC addresses.
    • If the problem occurs soon after booting: Share the full log until the issue occurs.
    • If the problem occurs later during playback: Trim the logs to include information just before and after the problem occurs.

.[0;32mI (3382) console: Running command autoexec1 = squeezelite -o i2s -b 500:2000 -C 30 .[0m .[0;33mW (3392) config: Value not found for key autoexec2.[0m squeezelite-esp32> .[0;32mI (3392) squeezelite_cmd: Calling squeezelite.[0m [00:00:01.922] sb_controls_init:249 initializing audio (buttons/rotary/ir) controls (raw:0) [00:00:01.933] sb_displayer_init:327 no display or led visualizer for LMS .[0;32mI (3422) DAC core: DAC uses I2C port:0, sda:27, scl:26.[0m .[0;33mW (3432) DAC core: I2C read failed.[0m .[0;32mI (3432) TAS575x/8x: Detected TAS @0x4c.[0m [00:00:01.950] output_init_i2s:359 invalid MCK gpio -1 .[0;32mI (3442) I2S: DMA Malloc info, datalen=blocksize=2048, dma_buf_count=12.[0m .[0;32mI (3442) I2S: APLL: Req RATE: 44100, real rate: 44099.988, BITS: 16, CLKM: 1, BCK_M: 8, MCLK: 11289597.000, SCLK: 1411199.625000, diva: 1, divb: 0.[0m [00:00:01.975] equalizer_set_samplerate:121 equalizer sample rate 44100 .[0;33mW (3472) BT_AV: BT Sink pin code is: [1234] .[0m .[0;32mI (3472) BTDM_INIT: BT controller compile version [2c56073].[0m .[0;32mI (3862) BT_AV: Bluetooth Init complete.[0m I (5252) wifi:new:<3,0>, old:<1,0>, ap:<255,255>, sta:<3,0>, prof:1 I (5802) wifi:state: init -> auth (b0) I (6802) wifi:state: auth -> init (200) I (6802) wifi:new:<3,0>, old:<3,0>, ap:<255,255>, sta:<3,0>, prof:1 .[0;33mW (6812) network_wifi: WIFI_EVENT_STA_DISCONNECTED. From BSSID: 82:8a:20:8d:ec:65, reason code: 2 (WIFI_REASON_AUTH_EXPIRE).[0m .[0;32mI (6822) network_handlers: Wifi was disconnected from previous access point. Waiting to connect..[0m .[0;32mI (18332) network_handlers: Timer: Wifi Polling timeout .[0m .[0;32mI (18332) network_wifi: Wifi Connecting to AP-IoT....[0m I (20022) wifi:new:<3,0>, old:<3,0>, ap:<255,255>, sta:<3,0>, prof:1 I (20022) wifi:state: init -> auth (b0) I (21022) wifi:state: auth -> init (200) I (21022) wifi:new:<3,0>, old:<3,0>, ap:<255,255>, sta:<3,0>, prof:1 .[0;33mW (21022) network_wifi: WIFI_EVENT_STA_DISCONNECTED. From BSSID: 82:8a:20:8d:ec:65, reason code: 2 (WIFI_REASON_AUTH_EXPIRE).[0m .[0;32mI (21042) network_handlers: Wifi was disconnected from previous access point. Waiting to connect..[0m .[0;31mE (593901) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:.[0m .[0;31mE (593901) task_wdt: - IDLE (CPU 0).[0m .[0;31mE (593901) task_wdt: Tasks currently running:.[0m .[0;31mE (593901) task_wdt: CPU 0: wifi.[0m .[0;31mE (593901) task_wdt: CPU 1: IDLE.[0m .[0;31mE (593901) task_wdt: Print CPU 0 (current core) backtrace.[0m

....

Backtrace:0x401E5BBE:0x3FFBED40 0x40084891:0x3FFBED60 0x4027F21B:0x3FFCAA00 0x4027DEA7:0x3FFCAA20 0x40209BD2:0x3FFCAA40 0x4020A2D1:0x3FFCAA60 0x40209008:0x3FFCAA80 0x4027B5E1:0x3FFCAAA0

Issue Description

  1. Observed Behavior: Crash during AirPlay playback
  2. Expected Behavior: No crash
  3. Steps to Reproduce: Connect over airplay from Mac / iPhone and wait for a few minutes

Sometimes also seeing:

.[0;31mE (128822) messaging: cfg-audio-tmpl Rebooting in 60 sec

emlynmac commented 1 year ago

Just updated to the latest build and experienced different error / reset:

ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0030,len:6480
load:0x40078000,len:15868
load:0x40080400,len:4384
entry 0x40080684
I (27) boot: ESP-IDF v4.3.2-dirty 2nd stage bootloader
I (27) boot: compile time 22:28:30
I (27) boot: chip revision: 1
I (30) qio_mode: Enabling default flash chip QIO
I (35) boot.esp32: SPI Speed      : 80MHz
I (40) boot.esp32: SPI Mode       : QIO
I (45) boot.esp32: SPI Flash Size : 4MB
I (49) boot: Enabling RNG early entropy source...
I (54) boot: Partition Table:
I (58) boot: ## Label            Usage          Type ST Offset   Length
I (65) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (73) boot:  1 otadata          OTA data         01 00 0000d000 00002000
I (80) 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 (110) boot: End of partition table
I (115) boot_comm: chip revision: 1, min. application chip revision: 0
I (122) esp_image: segment 0: paddr=00150020 vaddr=3f400020 size=af030h (716848) map
I (343) esp_image: segment 1: paddr=001ff058 vaddr=3ffbdb60 size=00fc0h (  4032) load
I (344) esp_image: segment 2: paddr=00200020 vaddr=400d0020 size=1b30d4h (1781972) map
I (876) esp_image: segment 3: paddr=003b30fc vaddr=3ffbeb20 size=04a7ch ( 19068) load
I (883) esp_image: segment 4: paddr=003b7b80 vaddr=40080000 size=1e2dch (123612) load
I (926) esp_image: segment 5: paddr=003d5e64 vaddr=400c0000 size=00068h (   104) load
I (941) boot: Loaded app from partition at offset 0x150000
I (941) boot: Disabling RNG early entropy source...
I (953) psram: This chip is ESP32-D0WD
I (953) spiram: Found 64MBit SPI RAM device
I (953) spiram: SPI RAM mode: flash 80m sram 80m
I (956) spiram: PSRAM initialized, cache is in low/high (2-core) mode.
I (963) cpu_start: Pro cpu up.
I (967) cpu_start: Starting app cpu, entry point is 0x40081408
I (0) cpu_start: App cpu up.
I (1470) spiram: SPI SRAM memory test OK
I (1483) cpu_start: Pro cpu start user code
I (1483) cpu_start: cpu freq: 240000000
I (1483) cpu_start: Application information:
I (1486) cpu_start: Project name:     SqueezeAMP
I (1491) cpu_start: App version:      SqueezeAmp-1598
I (1497) cpu_start: Compile time:     Oct  4 2023 23:00:33
I (1503) cpu_start: ELF file SHA256:  0000000000000000...
I (1509) cpu_start: ESP-IDF:          v4.3.5-dirty
I (1515) cpu_start: Min chip rev:     v1.0
I (1519) cpu_start: Max chip rev:     v3.99 
I (1524) cpu_start: Chip rev:         v1.0
I (1529) heap_init: Initializing. RAM available for dynamic allocation:
I (1537) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (1543) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (1549) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (1555) heap_init: At 3FFC6F28 len 000190D8 (100 KiB): DRAM
I (1561) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1568) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1574) heap_init: At 4009E2DC len 00001D24 (7 KiB): IRAM
I (1581) spiram: Adding pool of 4018K of external SPI memory to heap allocator
I (1589) spi_flash: detected chip: generic
I (1593) spi_flash: flash io: qio
W (1597) spi_flash: Detected size(16384k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
I (1613) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1621) spiram: Reserving pool of 64K of internal memory for DMA/internal allocations
I (1631) esp_app_main: System is booting from power on.
I (1641) esp_app_main: Reset reason is: 1
I (1641) esp_app_main: Reboot counter=1

I (1641) esp_app_main: Starting app_main
I (1651) nvs_utilities: Initializing flash nvs 
I (1671) nvs_utilities: Initializing nvs partition settings
I (1711) esp_app_main: Setting up telnet.
I (1711) telnet: Telnet support disabled
I (1711) esp_app_main: Setting up config subsystem.
W (1781) nvs_utilities: Configuration memory usage.  Heap internal:227999 (min:227855) (used:216) external:4095779 (min:4088295) (used:15164)
I (1781) esp_app_main: Registering default values
I (1791) system_api: Base MAC address is not set
I (1791) system_api: read default base MAC address from EFUSE
W (1801) config: Waiting for config commit ...
I (2781) config: configuration has some uncommitted entries
I (2781) config: Committing configuration to nvs. Locking config object.
I (2781) config: Done Committing configuration to nvs.
I (2781) config: Config committed!
I (2791) esp_app_main: Configuring services
I (2791) services: Configuring I2C sda:-1 scl:-1 port:1 speed:400000
W (2801) services: no I2C configured
I (2801) services: Configuring SPI mosi:-1 miso:-1 clk:-1 host:1 dc:-1
W (2811) services: no SPI configured
I (2821) led: Configuring LEDs green:12 (on:0 rmt:-1 -1% ), red:13 (on:0 rmt:-1 -1% )
I (2821) battery: Battery measure channel: 7, scale 20.240000, atten 0, cells 2, avg 0.00V
I (2831) monitor: Initializing monitoring
I (2841) monitor: Adding jack (low) detection GPIO 34
I (2841) buttons: Creating button using GPIO 34, type 0, pull-up/down 0, long press 0 shifter -1
I (2851) buttons: starting button tasks
I (2851) monitor: Adding speaker fault (low) detection GPIO 2
I (2861) buttons: Creating button using GPIO 2, type 0, pull-up/down 0, long press 0 shifter -1
I (2871) monitor: Heap internal:228295 (min:227783) external:4078687 (min:4078671) dma:221215 (min:220719)
I (2881) esp_app_main: Initializing display
I (2891) display: Trying to configure display with N/A
W (2891) display: No display driver
I (2901) esp_app_main: Initializing led_vu
I (2901) led_vu: led_vu configuration invalid
I (2911) esp_app_main: Checking for update url
W (2911) config: Value not found for key fwurl
I (2921) IR: Starting Infrared Receiver mode nec on gpio 0 and channel 7
I (2931) buttons: Created infrared receiver using GPIO 0
W (2931) config: Value not found for key 
0;33mW (2951) config: Value not found for key apdelay
I (2951) uart: queue free spaces: 3
I (2951) network_handlers: Network manager configuration: polling max 10176, polling min 15000, ap delay 20000, dhcp timeout 8000, eth timeout 8000
I (2981) http_server: Initializing HTTP Server
I (2981) network_ethernet: Attempting to initialize Ethernet
I (2981) network_ethernet: No Ethernet configuration, or configuration invalid
I (3011) wifi:wifi driver task: 3ffdfc38, prio:23, stack:6656, core=0
I (3011) wifi:wifi firmware version: 9ec65ef
I (3011) wifi:wifi certification version: v7.0
I (3011) wifi:config NVS flash: enabled
I (3021) wifi:config nano formating: disabled
I (3021) wifi:Init data frame dynamic rx buffer num: 40
I (3021) wifi:Init management frame dynamic rx buffer num: 40
I (3031) wifi:Init management short buffer num: 32
I (3031) wifi:Init static tx buffer num: 12
I (3041) wifi:Init tx cache buffer num: 32
I (3051) wifi:Init static rx buffer size: 1600
I (3051) wifi:Init static rx buffer num: 12
I (3061) wifi:Init dynamic rx buffer num: 40
I (3061) wifi_init: tcpip mbox: 32
I (3061) wifi_init: udp mbox: 32
I (3061) wifi_init: tcp mbox: 32
I (3071) wifi_init: tcp tx win: 8192
I (3071) wifi_init: tcp rx win: 32768
I (3081) wifi_init: tcp mss: 1440
I (3081) wifi_init: WiFi/LWIP prefer SPIRAM
I (3081) network_wifi: Starting wifi
I (3091) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (3191) wifi:mode : sta (0c:dc:7e:50:1f:88)
I (3191) wifi:enable tsf
I (3191) network_handlers: Existing wifi config found. Attempting to connect.
I (3191) network: Starting DHCP client
I (3201) network_wifi: Wifi Connecting to B-IoT...

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 (3251) console: Processing autoexec commands while network manager active.  Wifi related commands will be ignored.
I (3261) console: autoexec is set to perform auto-process
I (3271) console: Running command autoexec1 = squeezelite  -o i2s  -b  500:2000 -C  30 
W (3291) config: Value not found for key autoexec2
squeezelite-esp32> I (3291) squeezelite_cmd: Calling squeezelite
[00:00:01.816] sb_controls_init:249 initializing audio (buttons/rotary/ir) controls (raw:0)
[00:00:01.817] sb_displayer_init:327 no display or led visualizer for LMS
I (3311) DAC core: DAC uses I2C port:0, sda:27, scl:26
W (3311) DAC core: I2C read failed
I (3311) TAS575x/8x: Detected TAS @0x4c
[00:00:01.845] output_init_i2s:359 invalid MCK gpio -1
I (3331) I2S: DMA Malloc info, datalen=blocksize=2048, dma_buf_count=12
I (3341) I2S: APLL: Req RATE: 44100, real rate: 44099.988, BITS: 16, CLKM: 1, BCK_M: 8, MCLK: 11289597.000, SCLK: 1411199.625000, diva: 1, divb: 0
[00:00:01.870] equalizer_set_samplerate:121 equalizer sample rate 44100
W (3351) BT_AV: BT Sink pin code is: [1234] 
I (3351) BTDM_INIT: BT controller compile version [2c56073]
I (3741) BT_AV: Bluetooth Init complete
I (5131) wifi:new:<3,0>, old:<1,0>, ap:<255,255>, sta:<3,0>, prof:1
I (5681) wifi:state: init -> auth (b0)
I (6681) wifi:state: auth -> init (200)
I (6691) wifi:new:<3,0>, old:<3,0>, ap:<255,255>, sta:<3,0>, prof:1
W (6691) network_wifi: WIFI_EVENT_STA_DISCONNECTED. From BSSID: 82:8a:20:8d:ec:65, reason code: 2 (WIFI_REASON_AUTH_EXPIRE)
I (6701) network_handlers: Wifi was disconnected from previous access point. Waiting to connect.
I (18201) network_handlers: Timer: Wifi Polling timeout 
I (18201) network_wifi: Wifi Connecting to B-IoT...
I (19891) wifi:new:<3,0>, old:<3,0>, ap:<255,255>, sta:<3,0>, prof:1
I (19901) wifi:state: init -> auth (b0)
I (19901) wifi:state: auth -> assoc (0)
I (20901) wifi:state: assoc -> init (400)
I (20901) wifi:new:<3,0>, old:<3,0>, ap:<255,255>, sta:<3,0>, prof:1
W (20911) network_wifi: WIFI_EVENT_STA_DISCONNECTED. From BSSID: 82:8a:20:8d:ec:65, reason code: 4 (WIFI_REASON_ASSOC_EXPIRE)
I (20921) network_handlers: Wifi was disconnected from previous access point. Waiting to connect.
helpets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0030,len:6480
load:0x40078000,len:15868
load:0x40080400,len:4384
entry 0x40080684
I (26) boot: ESP-IDF v4.3.2-dirty 2nd stage bootloader
I (27) boot: compile time 22:28:30
I (27) boot: chip revision: 1
I (30) qio_mode: Enabling default flash chip QIO
I (35) boot.esp32: SPI Speed      : 80MHz
I (40) boot.esp32: SPI Mode       : QIO
I (44) boot.esp32: SPI Flash Size : 4MB
I (49) boot: Enabling RNG early entropy source...
I (54) boot: Partition Table:
I (58) boot: ## Label            Usage          Type ST Offset   Length
I (65) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (73) boot:  1 otadata          OTA data         01 00 0000d000 00002000
I (80) 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 (110) boot: End of partition table
I (114) boot_comm: chip revision: 1, min. application chip revision: 0
I (122) esp_image: segment 0: paddr=00150020 vaddr=3f400020 size=af030h (716848) map
I (342) esp_image: segment 1: paddr=001ff058 vaddr=3ffbdb60 size=00fc0h (  4032) load
I (344) esp_image: segment 2: paddr=00200020 vaddr=400d0020 size=1b30d4h (1781972) map
I (876) esp_image: segment 3: paddr=003b30fc vaddr=3ffbeb20 size=04a7ch ( 19068) load
I (883) esp_image: segment 4: paddr=003b7b80 vaddr=40080000 size=1e2dch (123612) load
I (925) esp_image: segment 5: paddr=003d5e64 vaddr=400c0000 size=00068h (   104) load
I (941) boot: Loaded app from partition at offset 0x150000
I (941) boot: Disabling RNG early entropy source...
I (953) psram: This chip is ESP32-D0WD
I (953) spiram: Found 64MBit SPI RAM device
I (953) spiram: SPI RAM mode: flash 80m sram 80m
I (956) spiram: PSRAM initialized, cache is in low/high (2-core) mode.
I (963) cpu_start: Pro cpu up.
I (967) cpu_start: Starting app cpu, entry point is 0x40081408
I (0) cpu_start: App cpu up.
I (1470) spiram: SPI SRAM memory test OK
I (1483) cpu_start: Pro cpu start user code
I (1483) cpu_start: cpu freq: 240000000
I (1483) cpu_start: Application information:
I (1486) cpu_start: Project name:     SqueezeAMP
I (1491) cpu_start: App version:      SqueezeAmp-1598
I (1497) cpu_start: Compile time:     Oct  4 2023 23:00:33
I (1503) cpu_start: ELF file SHA256:  0000000000000000...
I (1509) cpu_start: ESP-IDF:          v4.3.5-dirty
I (1515) cpu_start: Min chip rev:     v1.0
I (1519) cpu_start: Max chip rev:     v3.99 
I (1524) cpu_start: Chip rev:         v1.0
I (1529) heap_init: Initializing. RAM available for dynamic allocation:
I (1536) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (1542) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (1549) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (1555) heap_init: At 3FFC6F28 len 000190D8 (100 KiB): DRAM
I (1561) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1568) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1574) heap_init: At 4009E2DC len 00001D24 (7 KiB): IRAM
I (1580) spiram: Adding pool of 4018K of external SPI memory to heap allocator
I (1589) spi_flash: detected chip: generic
I (1593) spi_flash: flash io: qio
W (1597) spi_flash: Detected size(16384k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
I (1613) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1621) spiram: Reserving pool of 64K of internal memory for DMA/internal allocations
I (1631) esp_app_main: System is booting from power on.
I (1641) esp_app_main: Reset reason is: 1
I (1641) esp_app_main: Reboot counter=1

I (1641) esp_app_main: Starting app_main
I (1651) nvs_utilities: Initializing flash nvs 
I (1671) nvs_utilities: Initializing nvs partition settings
I (1711) esp_app_main: Setting up telnet.
I (1711) telnet: Telnet support disabled
I (1711) esp_app_main: Setting up config subsystem.
W (1781) nvs_utilities: Configuration memory usage.  Heap internal:227999 (min:227855) (used:216) external:4095779 (min:4088295) (used:15164)
I (1781) esp_app_main: Registering default values
I (1791) system_api: Base MAC address is not set
I (1791) system_api: read default base MAC address from EFUSE
W (1801) config: Waiting for config commit ...
I (2781) config: configuration has some uncommitted entries
I (2781) config: Committing configuration to nvs. Locking config object.
I (2781) config: Done Committing configuration to nvs.
I (2781) config: Config committed!
I (2791) esp_app_main: Configuring services
I (2791) services: Configuring I2C sda:-1 scl:-1 port:1 speed:400000
W (2801) services: no I2C configured
I (2801) services: Configuring SPI mosi:-1 miso:-1 clk:-1 host:1 dc:-1
W (2811) services: no SPI configured
I (2821) led: Configuring LEDs green:12 (on:0 rmt:-1 -1% ), red:13 (on:0 rmt:-1 -1% )
I (2821) battery: Battery measure channel: 7, scale 20.240000, atten 0, cells 2, avg 0.00V
I (2831) monitor: Initializing monitoring
I (2841) monitor: Adding jack (low) detection GPIO 34
I (2841) buttons: Creating button using GPIO 34, type 0, pull-up/down 0, long press 0 shifter -1
I (2851) buttons: starting button tasks
I (2851) monitor: Adding speaker fault (low) detection GPIO 2
I (2861) buttons: Creating button using GPIO 2, type 0, pull-up/down 0, long press 0 shifter -1
I (2871) monitor: Heap internal:228295 (min:227783) external:4078687 (min:4078671) dma:221215 (min:220719)
I (2881) esp_app_main: Initializing display
I (2891) display: Trying to configure display with N/A
W (2891) display: No display driver
I (2901) esp_app_main: Initializing led_vu
I (2901) led_vu: led_vu configuration invalid
I (2911) esp_app_main: Checking for update url
W (2911) config: Value not found for key fwurl
I (2921) IR: Starting Infrared Receiver mode nec on gpio 0 and channel 7
I (2931) buttons: Created infrared receiver using GPIO 0
W (2931) config: Value not found for key 
0;33mW (2951) config: Value not found for key apdelay
I (2951) uart: queue free spaces: 3
I (2951) network_handlers: Network manager configuration: polling max 10176, polling min 15000, ap delay 20000, dhcp timeout 8000, eth timeout 8000
I (2981) http_server: Initializing HTTP Server
I (2981) network_ethernet: Attempting to initialize Ethernet
I (2981) network_ethernet: No Ethernet configuration, or configuration invalid
I (3011) wifi:wifi driver task: 3ffdfc38, prio:23, stack:6656, core=0
I (3011) wifi:wifi firmware version: 9ec65ef
I (3011) wifi:wifi certification version: v7.0
I (3011) wifi:config NVS flash: enabled
I (3021) wifi:config nano formating: disabled
I (3021) wifi:Init data frame dynamic rx buffer num: 40
I (3021) wifi:Init management frame dynamic rx buffer num: 40
I (3031) wifi:Init management short buffer num: 32
I (3031) wifi:Init static tx buffer num: 12
I (3041) wifi:Init tx cache buffer num: 32
I (3051) wifi:Init static rx buffer size: 1600
I (3051) wifi:Init static rx buffer num: 12
I (3061) wifi:Init dynamic rx buffer num: 40
I (3061) wifi_init: tcpip mbox: 32
I (3061) wifi_init: udp mbox: 32
I (3061) wifi_init: tcp mbox: 32
I (3071) wifi_init: tcp tx win: 8192
I (3071) wifi_init: tcp rx win: 32768
I (3081) wifi_init: tcp mss: 1440
I (3081) wifi_init: WiFi/LWIP prefer SPIRAM
I (3081) network_wifi: Starting wifi
I (3091) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (3191) wifi:mode : sta (0c:dc:7e:50:1f:88)
I (3191) wifi:enable tsf
I (3191) network_handlers: Existing wifi config found. Attempting to connect.
I (3191) network: Starting DHCP client
I (3201) network_wifi: Wifi Connecting to Bolton-IoT...

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 (3251) console: Processing autoexec commands while network manager active.  Wifi related commands will be ignored.
I (3261) console: autoexec is set to perform auto-process
I (3271) console: Running command autoexec1 = squeezelite  -o i2s  -b  500:2000 -C  30 
W (3291) config: Value not found for key autoexec2
squeezelite-esp32> I (3291) squeezelite_cmd: Calling squeezelite
[00:00:01.817] sb_controls_init:249 initializing audio (buttons/rotary/ir) controls (raw:0)
[00:00:01.818] sb_displayer_init:327 no display or led visualizer for LMS
I (3311) DAC core: DAC uses I2C port:0, sda:27, scl:26
W (3311) DAC core: I2C read failed
I (3311) TAS575x/8x: Detected TAS @0x4c
[00:00:01.845] output_init_i2s:359 invalid MCK gpio -1
I (3331) I2S: DMA Malloc info, datalen=blocksize=2048, dma_buf_count=12
I (3341) I2S: APLL: Req RATE: 44100, real rate: 44099.988, BITS: 16, CLKM: 1, BCK_M: 8, MCLK: 11289597.000, SCLK: 1411199.625000, diva: 1, divb: 0
[00:00:01.871] equalizer_set_samplerate:121 equalizer sample rate 44100
W (3351) BT_AV: BT Sink pin code is: [1234] 
I (3361) BTDM_INIT: BT controller compile version [2c56073]
I (3751) BT_AV: Bluetooth Init complete
I (5141) wifi:new:<3,0>, old:<1,0>, ap:<255,255>, sta:<3,0>, prof:1
I (5691) wifi:state: init -> auth (b0)
I (6691) wifi:state: auth -> init (200)
I (6691) wifi:new:<3,0>, old:<3,0>, ap:<255,255>, sta:<3,0>, prof:1
W (6701) network_wifi: WIFI_EVENT_STA_DISCONNECTED. From BSSID: 82:8a:20:8d:ec:65, reason code: 2 (WIFI_REASON_AUTH_EXPIRE)
I (6711) network_handlers: Wifi was disconnected from previous access point. Waiting to connect.
I (18201) network_handlers: Timer: Wifi Polling timeout 
I (18201) network_wifi: Wifi Connecting to Bolton-IoT...
I (19891) wifi:new:<3,0>, old:<3,0>, ap:<255,255>, sta:<3,0>, prof:1
I (19891) wifi:state: init -> auth (b0)
I (19891) wifi:state: auth -> assoc (0)
I (19911) wifi:state: assoc -> run (10)
I (20951) wifi:connected with Bolton-IoT, aid = 1, channel 3, BW20, bssid = 82:8a:20:8d:ec:65
I (20951) wifi:security: WPA2-PSK, phy: bgn, rssi: -72
I (20961) wifi:pm start, type: 1

I (20971) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (22061) network: Got an IP address from interface Wifi. IP=192.168.210.71, Gateway=192.168.210.1, NetMask=255.255.255.0, Address was changed
I (22071) esp_netif_handlers: sta ip: 192.168.210.71, mask: 255.255.255.0, gw: 192.168.210.1
I (22081) esp_app_main: Network connected and mDNS initialized with Garage
[00:00:20.608] raop_sink_start:178 starting Airplay for ip 192.168.210.71 with servicename Garage
[00:00:20.610] raop_create:201 starting mDNS with 0CDC7E501F88@Garage
I (68011) httpd_handlers: serving / to peer 192.168.210.140 port 64993
I (68691) httpd_handlers: serving /commands.json to peer 192.168.210.140 port 482
I (68791) httpd_handlers: serving /config.json to peer 192.168.210.140 port 226
I (68901) httpd_handlers: serving /messages.json to peer 192.168.210.140 port 994
I (69081) httpd_handlers: serving /status.json to peer 192.168.210.140 port 1250
I (70271) network_wifi: Initiating wifi network scan
I (72091) httpd_handlers: serving /messages.json to peer 192.168.210.140 port 1762
W (84681) messaging: System reboot to recovery requested
W (84681) messaging: System reboot to recovery requested
I (84681) messaging: Looking for partition type 0
I (84691) messaging: Found application partition recovery sub type 0
I (84691) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=5309ch (340124) map
I (84781) esp_image: segment 1: paddr=000630c4 vaddr=3ffbdb60 size=04988h ( 18824) 
I (84791) esp_image: segment 2: paddr=00067a54 vaddr=40080000 size=085c4h ( 34244) 
I (84801) esp_image: segment 3: paddr=00070020 vaddr=400d0020 size=ce1e8h (844264) map
I (84951) esp_image: segment 4: paddr=0013e210 vaddr=400885c4 size=0c480h ( 50304) 
I (84971) esp_image: segment 5: paddr=0014a698 vaddr=400c0000 size=00068h (   104) 
I (84981) esp_image: segment 6: paddr=0014a708 vaddr=50000000 size=00010h (    16) 
I (85821) wifi:state: run -> init (0)
I (85821) wifi:pm stop, total sleep time: 42838621 us / 64856564 us

I (85821) wifi:new:<3,0>, old:<3,0>, ap:<255,255>, sta:<3,0>, prof:1
W (85831) network_wifi: WIFI_EVENT_STA_DISCONNECTED. From BSSID: 82:8a:20:8d:ec:65, reason code: 8 (WIFI_REASON_ASSOC_LEAVE)
W (85831) httpd_txrx: httpd_sock_err: error in recv : 113
W (85861) httpd_txrx: httpd_sock_err: error in recv : 113
W (90831) wifi:TX Q not empty: 500, TXQ_BLOCK=0
W (90831) wifi:force witi stop
I (90831) wifi:flush txq
I (90831) wifi:stop sw txq
I (90831) wifi:lmac stop hw txq
W (90841) wifi:sw tx 0 state not idle, potential error!
W (90841) wifi:force sw tx 0 state to idle, ebuf flag=0
ets Jun  8 2016 00:22:57

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:6480
load:0x40078000,len:15868
load:0x40080400,len:4384
entry 0x40080684
I (27) boot: ESP-IDF v4.3.2-dirty 2nd stage bootloader
I (27) boot: compile time 22:28:30
I (27) boot: chip revision: 1
I (30) qio_mode: Enabling default flash chip QIO
I (36) boot.esp32: SPI Speed      : 80MHz
I (40) boot.esp32: SPI Mode       : QIO
I (45) boot.esp32: 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 (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) boot: Defaulting to factory image
I (120) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=5309ch (340124) map
I (229) esp_image: segment 1: paddr=000630c4 vaddr=3ffbdb60 size=04988h ( 18824) load
I (235) esp_image: segment 2: paddr=00067a54 vaddr=40080000 size=085c4h ( 34244) load
I (247) esp_image: segment 3: paddr=00070020 vaddr=400d0020 size=ce1e8h (844264) map
I (498) esp_image: segment 4: paddr=0013e210 vaddr=400885c4 size=0c480h ( 50304) load
I (515) esp_image: segment 5: paddr=0014a698 vaddr=400c0000 size=00068h (   104) load
I (516) esp_image: segment 6: paddr=0014a708 vaddr=50000000 size=00010h (    16) load
I (532) boot: Loaded app from partition at offset 0x10000
I (532) boot: Disabling RNG early entropy source...
I (544) psram: This chip is ESP32-D0WD
I (544) spiram: Found 64MBit SPI RAM device
I (544) spiram: SPI RAM mode: flash 80m sram 80m
I (547) spiram: PSRAM initialized, cache is in low/high (2-core) mode.
I (555) cpu_start: Pro cpu up.
I (558) cpu_start: Starting app cpu, entry point is 0x40081308
I (552) cpu_start: App cpu up.
I (1061) spiram: SPI SRAM memory test OK
I (1070) cpu_start: Pro cpu start user code
I (1070) cpu_start: cpu freq: 240000000
I (1070) cpu_start: Application information:
I (1073) cpu_start: Project name:     SqueezeAMP
I (1079) cpu_start: App version:      SqueezeAmp.16.2.1299.master-v4.
I (1086) cpu_start: Compile time:     Apr 19 2023 22:30:10
I (1092) cpu_start: ELF file SHA256:  5b65e671b6ce7c32...
I (1098) cpu_start: ESP-IDF:          v4.3.2-dirty
I (1104) heap_init: Initializing. RAM available for dynamic allocation:
I (1111) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
W (1117) REMOVE: NEW POOL of 7268 bytes, ctrl_size: 416 sli_c:8 fli_c:10 small_b 32 max_b:16384
I (1126) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
W (1133) REMOVE: NEW POOL of 16628 bytes, ctrl_size: 736 sli_c:16 fli_c:10 small_b 64 max_b:32768
I (1142) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
W (1148) REMOVE: NEW POOL of 112772 bytes, ctrl_size: 872 sli_c:16 fli_c:12 small_b 64 max_b:131072
I (1158) heap_init: At 3FFC4768 len 0001B898 (110 KiB): DRAM
I (1164) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1171) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
W (1177) REMOVE: NEW POOL of 46504 bytes, ctrl_size: 804 sli_c:16 fli_c:11 small_b 64 max_b:65536
I (1187) heap_init: At 40094A44 len 0000B5BC (45 KiB): IRAM
I (1193) spiram: Adding pool of 4066K of external SPI memory to heap allocator
W (1201) REMOVE: NEW POOL of 4164143 bytes, ctrl_size: 2168 sli_c:32 fli_c:16 small_b 128 max_b:4194304
I (1212) spi_flash: detected chip: generic
I (1216) spi_flash: flash io: qio
W (1220) spi_flash: Detected size(16384k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
I (1234) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
W (1244) REMOVE: NEW POOL of 15052 bytes, ctrl_size: 416 sli_c:8 fli_c:10 small_b 32 max_b:16384
W (1254) REMOVE: NEW POOL of 113820 bytes, ctrl_size: 872 sli_c:16 fli_c:12 small_b 64 max_b:131072
I (1264) spiram: Reserving pool of 64K of internal memory for DMA/internal allocations
W (1274) REMOVE: NEW POOL of 65515 bytes, ctrl_size: 804 sli_c:16 fli_c:11 small_b 64 max_b:65536
I (1284) esp_app_main: Reset reason is: 3
I (1284) esp_app_main: Recovery Reboot counter=1

I (1294) esp_app_main: Starting app_main
I (1294) nvs_utilities: Initializing flash nvs 
I (1314) nvs_utilities: Initializing nvs partition settings
I (1354) esp_app_main: Setting up telnet.
I (1354) telnet: Telnet support disabled
I (1354) esp_app_main: Setting up config subsystem.
W (1424) nvs_utilities: Configuration memory usage.  Heap internal:264111 (min:263751) (used:13248) external:4159859 (min:4152383) (used:0)
I (1424) esp_app_main: Registering default values
I (1434) system_api: Base MAC address is not set
I (1434) system_api: read default base MAC address from EFUSE
W (1444) config: Waiting for config commit ...
I (2424) config: configuration has some uncommitted entries
I (2424) config: Committing configuration to nvs. Locking config object.
I (2424) config: Done Committing configuration to nvs.
I (2424) config: Config committed!
I (2434) esp_app_main: Configuring services
I (2434) services: Configuring I2C sda:-1 scl:-1 port:1 speed:400000
W (2444) services: no I2C configured
I (2444) services: Configuring SPI mosi:-1 miso:-1 clk:-1 host:1 dc:-1
W (2454) services: no SPI configured
I (2464) led: Configuring LEDs green:12 (active:0 -1%), red:13 (active:0 -1%)
I (2464) battery: Battery measure channel: 7, scale 20.240000, atten 0, cells 2, avg 0.00V
I (2474) monitor: Initializing monitoring
I (2484) monitor: Adding jack (low) detection GPIO 34
I (2484) buttons: Creating button using GPIO 34, type 0, pull-up/down 0, long press 0 shifter -1
I (2494) buttons: starting button tasks
I (2494) monitor: Adding speaker fault (low) detection GPIO 2
I (2504) buttons: Creating button using GPIO 2, type 0, pull-up/down 0, long press 0 shifter -1
I (2514) monitor: Heap internal:264387 (min:263751) external:4142971 (min:4142959) dma:218687 (min:218063)
I (2524) esp_app_main: Initializing display
I (2534) display: Trying to configure display with N/A
W (2534) display: No display driver
I (2544) esp_app_main: Checking for update urlW (2554) config: Value not found for key apdelay
I (2554) uart: queue free spaces: 3
I (2554) network_handlers: Network manager configuration: polling max 10176, polling min 15000, ap delay 20000, dhcp timeout 8000, eth timeout 8000
I (2584) http_server: Initializing HTTP Server
I (2594) network_handlers: Running recovery. Skipping ethernet, starting WiFi
I (2604) wifi:wifi driver task: 3ffca590, prio:23, stack:6656, core=0
I (2604) wifi:wifi firmware version: eb52264
I (2604) wifi:wifi certification version: v7.0
I (2614) wifi:config NVS flash: enabled
I (2614) wifi:config nano formating: disabled
I (2614) wifi:Init data frame dynamic rx buffer num: 40
I (2624) wifi:Init management frame dynamic rx buffer num: 40
I (2624) wifi:Init management short buffer num: 32
I (2624) wifi:Init static tx buffer num: 12
I (2644) wifi:Init tx cache buffer num: 32
I (2644) wifi:Init static rx buffer size: 1600
I (2644) wifi:Init static rx buffer num: 12
I (2654) wifi:Init dynamic rx buffer num: 40
I (2654) wifi_init: tcpip mbox: 32
I (2654) wifi_init: udp mbox: 32
I (2664) wifi_init: tcp mbox: 32
I (2664) wifi_init: tcp tx win: 8192
I (2664) wifi_init: tcp rx win: 32768
I (2674) wifi_init: tcp mss: 1440
I (2674) wifi_init: WiFi/LWIP prefer SPIRAM
I (2674) network_wifi: Starting wifi
I (2694) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
W (2844) phy_init: saving new calibration data because of checksum failure, mode(0)

****************************************************************
RECOVERY APPLICATION
This mode is used to flash Squeezelite into the OTA partition
****

I (2864) wifi:mode : sta (0c:dc:7e:50:1f:88)
I (2864) wifi:enable tsf
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.

I (2884) network_handlers: Existing wifi config found. Attempting to connect.
I (2894) network: Starting DHCP client
I (2904) network_wifi: Wifi Connecting to Bolton-IoT...

****************************
Your terminal application does not support escape sequences.
Line editing and history features are disabled.
On Windows, try using Putty instead.
****************************
recovery-squeezelite-esp32>W (4954) network_wifi: WIFI_EVENT_STA_DISCONNECTED. From BSSID: 00:00:00:00:00:00, reason code: 201 (WIFI_REASON_NO_AP_FOUND)
W (4954) wifi:Haven't to connect to a suitable AP now!
I (4964) network_wifi: Configuring Access Point.
I (4974) network: Stopping DHCP server
I (4984) network: Starting DHCP server
I (4984) network_wifi: AP SSID: Garage
I (4984) network_wifi: AP Password: LetMeIn!
I (4994) wifi:mode : sta (0c:dc:7e:50:1f:88) + softAP (0c:dc:7e:50:1f:89)
I (4994) wifi:Total power save buffer number: 6
I (4994) wifi:Init max length of beacon: 752/752
I (5004) wifi:Init max length of beacon: 752/752
I (5544) wifi:Total power save buffer number: 6
I (5554) wifi:Total power save buffer number: 6
I (5554) wifi:Set ps type: 1

I (5554) network_wifi: Initiating wifi network scan
I (5554) dns_server: DNS Server listening on 53/udp
E (17904) network: network manager Unhandled Event NETWORK_WIFI_CONFIGURING_ACTIVE_STATE(WIFI_CONFIGURING_STATE) [EN_TIMER]
I (266794) wifi:new:<1,0>, old:<1,0>, ap:<1,0>, sta:<0,0>, prof:1
I (266794) wifi:station: f0:18:98:a9:33:47 join, AID=1, bgn, 20
W (267084) httpd_handlers: redirect_processor(1002): 192.168.4.2 requested invalid URL: [/hotspot-detect.html]
W (267094) httpd_handlers: process_redirect(957): Redirecting host [192.168.4.2] to http://192.168.4.1/ (from uri /hotspot-detect.html)
I (268654) esp_netif_lwip: DHCP server assigned IP to a station, IP is: 192.168.4.2
I (269924) httpd_handlers: serving / to peer 192.168.4.2 port 16842
W (270464) httpd_handlers: redirect_processor(1002): 192.168.4.2 requested invalid URL: [/hotspot-detect.html]
W (270474) httpd_handlers: process_redirect(957): Redirecting host [192.168.4.2] to http://192.168.4.1/ (from uri /hotspot-detect.html)
I (270504) httpd_handlers: serving / to peer 192.168.4.2 port 45055
I (271214) httpd_handlers: serving /messages.json to peer 192.168.4.2 port 45567
I (271274) httpd_handlers: serving /commands.json to peer 192.168.4.2 port 45311
W (271404) httpd_handlers: redirect_processor(1002): 192.168.4.2 requested invalid URL: [/hotspot-detect.html]
W (271404) httpd_handlers: process_redirect(957): Redirecting host [192.168.4.2] to http://192.168.4.1/ (from uri /hotspot-detect.html)
I (271634) httpd_handlers: serving /status.json to peer 192.168.4.2 port 46591
I (272674) network_wifi: Initiating wifi network scan
I (272684) httpd_handlers: serving / to peer 192.168.4.2 port 17354
I (274704) httpd_handlers: serving /ap.json to peer 192.168.4.2 port 46847
I (284854) network: Starting DHCP client
I (284854) network_wifi: Wifi Connecting to Bolton...
I (287704) wifi:switch to channel 6
I (287704) wifi:ap channel adjust o:1,0 n:6,0
I (287704) wifi:new:<6,0>, old:<1,0>, ap:<6,0>, sta:<0,0>, prof:1
I (287704) wifi:new:<6,0>, old:<6,0>, ap:<6,0>, sta:<6,0>, prof:1
I (288304) wifi:state: init -> auth (b0)
I (288314) wifi:state: auth -> init (2500)
I (288314) wifi:new:<6,0>, old:<6,0>, ap:<6,0>, sta:<6,0>, prof:1
I (288714) wifi:switch to channel 8
I (288714) wifi:ap channel adjust o:6,0 n:8,0
I (288724) wifi:new:<8,0>, old:<6,0>, ap:<8,0>, sta:<6,0>, prof:1
I (288724) wifi:new:<8,0>, old:<8,0>, ap:<8,0>, sta:<8,0>, prof:1
I (288734) wifi:state: init -> auth (b0)
I (288734) wifi:state: auth -> assoc (0)
E (288814) wifi:Set status to INIT
I (288814) wifi:state: assoc -> init (100)
I (288814) wifi:new:<8,0>, old:<8,0>, ap:<8,0>, sta:<8,0>, prof:1
I (289214) wifi:switch to channel 3
I (289214) wifi:ap channel adjust o:8,0 n:3,0
I (289214) wifi:new:<3,0>, old:<8,0>, ap:<3,0>, sta:<8,0>, prof:1
I (289214) wifi:new:<3,0>, old:<3,0>, ap:<3,0>, sta:<3,0>, prof:1
I (289224) wifi:state: init -> auth (b0)
I (290224) wifi:state: auth -> init (200)
I (290224) wifi:new:<3,0>, old:<3,0>, ap:<3,0>, sta:<3,0>, prof:1
W (290234) network_wifi: WIFI_EVENT_STA_DISCONNECTED. From BSSID: 78:8a:20:8d:ec:65, reason code: 2 (WIFI_REASON_AUTH_EXPIRE)
W (290244) wifi:Haven't to connect to a suitable AP now!
I (294654) wifi:new:<3,0>, old:<3,0>, ap:<3,0>, sta:<3,0>, prof:1
I (294654) wifi:station: f0:18:98:a9:33:47 join, AID=1, bgn, 20
I (298654) wifi:station: f0:18:98:a9:33:47 leave, AID = 1, bss_flags is 655458, bss:0x3f824788
I (298654) wifi:new:<3,0>, old:<3,0>, ap:<3,0>, sta:<3,0>, prof:1
I (298844) wifi:new:<3,0>, old:<3,0>, ap:<3,0>, sta:<3,0>, prof:1
I (298854) wifi:station: f0:18:98:a9:33:47 join, AID=1, bgn, 20
I (299134) httpd_handlers: serving /status.json to peer 192.168.4.2 port 47359
I (299154) esp_netif_lwip: DHCP server assigned IP to a station, IP is: 192.168.4.2
I (302464) battery: Voltage 0.00V
W (304564) httpd_txrx: httpd_sock_err: error in recv : 104
W (308624) httpd_txrx: httpd_sock_err: error in send : 104
W (308624) httpd_txrx: httpd_sock_err: error in recv : 104
I (362724) httpd_handlers: serving /messages.json to peer 192.168.4.2 port 47615
I (427034) httpd_handlers: serving /status.json to peer 192.168.4.2 port 47871
I (487164) network: Starting DHCP client
I (487164) network_wifi: Wifi Connecting to Bolton...
I (490004) wifi:switch to channel 6
I (490004) wifi:ap channel adjust o:3,0 n:6,0
I (490004) wifi:new:<6,0>, old:<3,0>, ap:<6,0>, sta:<3,0>, prof:1
I (490004) wifi:new:<6,0>, old:<6,0>, ap:<6,0>, sta:<6,0>, prof:1
I (490564) wifi:state: init -> auth (b0)
I (490574) wifi:state: auth -> init (2500)
I (490574) wifi:new:<6,0>, old:<6,0>, ap:<6,0>, sta:<6,0>, prof:1
W (490594) httpd_txrx: httpd_sock_err: error in recv : 104
I (490684) httpd_handlers: serving /messages.json to peer 192.168.4.2 port 48127
I (490974) wifi:switch to channel 8
I (490974) wifi:ap channel adjust o:6,0 n:8,0
I (490984) wifi:new:<8,0>, old:<6,0>, ap:<8,0>, sta:<6,0>, prof:1
I (490984) wifi:new:<8,0>, old:<8,0>, ap:<8,0>, sta:<8,0>, prof:1
I (490994) wifi:state: init -> auth (b0)
I (490994) wifi:state: auth -> assoc (0)
E (491054) wifi:Set status to INIT
I (491054) wifi:state: assoc -> init (100)
I (491054) wifi:new:<8,0>, old:<8,0>, ap:<8,0>, sta:<8,0>, prof:1
I (491454) wifi:switch to channel 3
I (491454) wifi:ap channel adjust o:8,0 n:3,0
I (491454) wifi:new:<3,0>, old:<8,0>, ap:<3,0>, sta:<8,0>, prof:1
I (491454) wifi:new:<3,0>, old:<3,0>, ap:<3,0>, sta:<3,0>, prof:1
I (491474) wifi:state: init -> auth (b0)
I (491474) wifi:state: auth -> assoc (0)
I (491484) wifi:state: assoc -> run (10)
I (494534) wifi:state: run -> init (fc0)
I (494534) wifi:new:<3,0>, old:<3,0>, ap:<3,0>, sta:<3,0>, prof:1
I (494534) wifi:new:<3,0>, old:<3,0>, ap:<3,0>, sta:<3,0>, prof:1
W (494544) network_wifi: WIFI_EVENT_STA_DISCONNECTED. From BSSID: 78:8a:20:8d:ec:65, reason code: 15 (WIFI_REASON_4WAY_HANDSHAKE_TIMEOUT)
W (494564) wifi:Haven't to connect to a suitable AP now!
I (495434) httpd_handlers: serving /status.json to peer 192.168.4.2 port 48383
I (519684) network: Starting DHCP client
I (519684) network_wifi: Wifi Connecting to Bolton-IoT...
I (522134) wifi:new:<3,0>, old:<3,0>, ap:<3,0>, sta:<3,0>, prof:1
I (522684) wifi:state: init -> auth (b0)
I (522684) wifi:state: auth -> assoc (0)
I (522694) wifi:state: assoc -> run (10)
I (522734) wifi:connected with Bolton-IoT, aid = 1, channel 3, BW20, bssid = 82:8a:20:8d:ec:65
I (522734) wifi:security: WPA2-PSK, phy: bgn, rssi: -66
I (522744) wifi:pm start, type: 1

I (522744) network_handlers: Wifi was connected. Waiting for IP address
I (522824) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (522934) network: Got an IP address from interface Wifi. IP=192.168.210.71, Gateway=192.168.210.1, NetMask=255.255.255.0, Address was changed
I (522954) esp_netif_handlers: sta ip: 192.168.210.71, mask: 255.255.255.0, gw: 192.168.210.1
W (537014) messaging: System reboot to Application requested
W (537014) messaging: System reboot to Application requested
I (537014) messaging: Looking for partition type 16
I (537034) messaging: Found application partition ota_0 sub type 16
I (537034) esp_image: segment 0: paddr=00150020 vaddr=3f400020 size=af030h (716848) map
I (537174) esp_image: segment 1: paddr=001ff058 vaddr=3ffbdb60 size=00fc0h (  4032) 
I (537184) esp_image: segment 2: paddr=00200020 vaddr=400d0020 size=1b30d4h (1781972) map
I (537504) esp_image: segment 3: paddr=003b30fc vaddr=3ffbeb20 size=04a7ch ( 19068) 
I (537514) esp_image: segment 4: paddr=003b7b80 vaddr=40080000 size=1e2dch (123612) 
I (537544) esp_image: segment 5: paddr=003d5e64 vaddr=400c0000 size=00068h (   104) 
I (538364) wifi:state: run -> init (0)
I (538364) wifi:pm stop, total sleep time: 11696238 us / 15617189 us

I (538364) wifi:new:<3,0>, old:<3,0>, ap:<3,0>, sta:<3,0>, prof:1
I (538374) wifi:station: f0:18:98:a9:33:47 leave, AID = 1, bss_flags is 655459, bss:0x3f824788
I (538374) wifi:new:<3,0>, old:<3,0>, ap:<3,0>, sta:<3,0>, prof:1
W (538374) wifi:hmac tx: ifx0 stop, discard
W (538384) wifi:age timer already deinit
W (538384) wifi:age timer already deinit
W (538384) network_wifi: WIFI_EVENT_STA_DISCONNECTED. From BSSID: 82:8a:20:8d:ec:65, reason code: 8 (WIFI_REASON_ASSOC_LEAVE)
W (538414) httpd_txrx: httpd_sock_err: error in recv : 113
I (538464) wifi:flush txq
I (538464) wifi:stop sw txq
I (538464) wifi:lmac stop hw txq
ets Jun  8 2016 00:22:57

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:6480
load:0x40078000,len:15868
load:0x40080400,len:4384
entry 0x40080684
I (27) boot: ESP-IDF v4.3.2-dirty 2nd stage bootloader
I (27) boot: compile time 22:28:30
I (27) boot: chip revision: 1
I (30) qio_mode: Enabling default flash chip QIO
I (36) boot.esp32: SPI Speed      : 80MHz
I (40) boot.esp32: SPI Mode       : QIO
I (45) boot.esp32: 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 (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) boot_comm: chip revision: 1, min. application chip revision: 0
I (122) esp_image: segment 0: paddr=00150020 vaddr=3f400020 size=af030h (716848) map
I (343) esp_image: segment 1: paddr=001ff058 vaddr=3ffbdb60 size=00fc0h (  4032) load
I (345) esp_image: segment 2: paddr=00200020 vaddr=400d0020 size=1b30d4h (1781972) map
I (877) esp_image: segment 3: paddr=003b30fc vaddr=3ffbeb20 size=04a7ch ( 19068) load
I (883) esp_image: segment 4: paddr=003b7b80 vaddr=40080000 size=1e2dch (123612) load
I (926) esp_image: segment 5: paddr=003d5e64 vaddr=400c0000 size=00068h (   104) load
I (942) boot: Loaded app from partition at offset 0x150000
I (942) boot: Disabling RNG early entropy source...
I (953) psram: This chip is ESP32-D0WD
I (953) spiram: Found 64MBit SPI RAM device
I (954) spiram: SPI RAM mode: flash 80m sram 80m
I (957) spiram: PSRAM initialized, cache is in low/high (2-core) mode.
I (964) cpu_start: Pro cpu up.
I (968) cpu_start: Starting app cpu, entry point is 0x40081408
I (961) cpu_start: App cpu up.
I (1471) spiram: SPI SRAM memory test OK
I (1483) cpu_start: Pro cpu start user code
I (1483) cpu_start: cpu freq: 240000000
I (1483) cpu_start: Application information:
I (1486) cpu_start: Project name:     SqueezeAMP
I (1492) cpu_start: App version:      SqueezeAmp-1598
I (1497) cpu_start: Compile time:     Oct  4 2023 23:00:33
I (1503) cpu_start: ELF file SHA256:  0000000000000000...
I (1510) cpu_start: ESP-IDF:          v4.3.5-dirty
I (1515) cpu_start: Min chip rev:     v1.0
I (1520) cpu_start: Max chip rev:     v3.99 
I (1525) cpu_start: Chip rev:         v1.0
I (1530) heap_init: Initializing. RAM available for dynamic allocation:
I (1537) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (1543) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (1549) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (1555) heap_init: At 3FFC6F28 len 000190D8 (100 KiB): DRAM
I (1562) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1568) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1575) heap_init: At 4009E2DC len 00001D24 (7 KiB): IRAM
I (1581) spiram: Adding pool of 4018K of external SPI memory to heap allocator
I (1589) spi_flash: detected chip: generic
I (1594) spi_flash: flash io: qio
W (1598) spi_flash: Detected size(16384k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
I (1614) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1622) spiram: Reserving pool of 64K of internal memory for DMA/internal allocations
I (1632) esp_app_main: Reset reason is: 3
I (1632) esp_app_main: Reboot counter=1

I (1642) esp_app_main: Starting app_main
I (1642) nvs_utilities: Initializing flash nvs 
I (1662) nvs_utilities: Initializing nvs partition settings
I (1712) esp_app_main: Setting up telnet.
I (1712) telnet: Telnet support disabled
I (1712) esp_app_main: Setting up config subsystem.
W (1782) nvs_utilities: Configuration memory usage.  Heap internal:227999 (min:227855) (used:216) external:4095779 (min:4088295) (used:15164)
I (1782) esp_app_main: Registering default values
I (1782) system_api: Base MAC address is not set
I (1792) system_api: read default base MAC address from EFUSE
W (1802) config: Waiting for config commit ...
I (2782) config: configuration has some uncommitted entries
I (2782) config: Committing configuration to nvs. Locking config object.
I (2782) config: Done Committing configuration to nvs.
I (2782) config: Config committed!
I (2792) esp_app_main: Configuring services
I (2792) services: Configuring I2C sda:-1 scl:-1 port:1 speed:400000
W (2802) services: no I2C configured
I (2802) services: Configuring SPI mosi:-1 miso:-1 clk:-1 host:1 dc:-1
W (2812) services: no SPI configured
I (2822) led: Configuring LEDs green:12 (on:0 rmt:-1 -1% ), red:13 (on:0 rmt:-1 -1% )
I (2822) battery: Battery measure channel: 7, scale 20.240000, atten 0, cells 2, avg 0.00V
I (2832) monitor: Initializing monitoring
I (2842) monitor: Adding jack (low) detection GPIO 34
I (2842) buttons: Creating button using GPIO 34, type 0, pull-up/down 0, long press 0 shifter -1
I (2852) buttons: starting button tasks
I (2852) monitor: Adding speaker fault (low) detection GPIO 2
I (2862) buttons: Creating button using GPIO 2, type 0, pull-up/down 0, long press 0 shifter -1
I (2872) monitor: Heap internal:228295 (min:227783) external:4078687 (min:4078671) dma:221215 (min:220719)
I (2882) esp_app_main: Initializing display
I (2892) display: Trying to configure display with N/A
W (2892) display: No display driver
I (2902) esp_app_main: Initializing led_vu
I (2902) led_vu: led_vu configuration invalid
I (2912) esp_app_main: Checking for update url
W (2912) config: Value not found for key fwurl
I (2922) IR: Starting Infrared Receiver mode nec on gpio 0 and channel 7
I (2932) buttons: Created infrared receiver using GPIW (2942) config: Value not found for key apdelay
I (2942) uart: queue free spaces: 3
I (2942) network_handlers: Network manager configuration: polling max 10176, polling min 15000, ap delay 20000, dhcp timeout 8000, eth timeout 8000
I (2972) http_server: Initializing HTTP Server
I (2982) network_ethernet: Attempting to initialize Ethernet
I (2982) network_ethernet: No Ethernet configuration, or configuration invalid
I (3002) wifi:wifi driver task: 3ffdfc38, prio:23, stack:6656, core=0
I (3002) wifi:wifi firmware version: 9ec65ef
I (3002) wifi:wifi certification version: v7.0
I (3002) wifi:config NVS flash: enabled
I (3012) wifi:config nano formating: disabled
I (3012) wifi:Init data frame dynamic rx buffer num: 40
I (3012) wifi:Init management frame dynamic rx buffer num: 40
I (3022) wifi:Init management short buffer num: 32
I (3022) wifi:Init static tx buffer num: 12
I (3032) wifi:Init tx cache buffer num: 32
I (3042) wifi:Init static rx buffer size: 1600
I (3042) wifi:Init static rx buffer num: 12
I (3052) wifi:Init dynamic rx buffer num: 40
I (3052) wifi_init: tcpip mbox: 32
I (3052) wifi_init: udp mbox: 32
I (3052) wifi_init: tcp mbox: 32
I (3062) wifi_init: tcp tx win: 8192
I (3062) wifi_init: tcp rx win: 32768
I (3072) wifi_init: tcp mss: 1440
I (3072) wifi_init: WiFi/LWIP prefer SPIRAM
I (3072) network_wifi: Starting wifi
I (3082) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
W (3262) phy_init: saving new calibration data because of checksum failure, mode(0)

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
I (3342) wifi:mode : sta (0c:dc:7e:50:1f:88)
I (3352) wifi:enable tsf
I (3362) network_handlers: Existing wifi config found. Attempting to connect.
I (3372) network: Starting DHCP client
I (3372) network_wifi: Wifi Connecting to Bolton-IoT...

****************************
Your terminal application does not support escape sequences.
Line editing and history features are disabled.
On Windows, try using Putty instead.
****************************
W (3392) console: Processing autoexec commands while network manager active.  Wifi related commands will be ignored.
I (3412) console: autoexec is set to perform auto-process
I (3412) console: Running command autoexec1 = squeezelite  -o i2s  -b  500:2000 -C  30 
W (3422) config: Value not found for key autoexec2
squeezelite-esp32> I (3422) squeezelite_cmd: Calling squeezelite
[00:10:32.777] sb_controls_init:249 initializing audio (buttons/rotary/ir) controls (raw:0)
[00:10:32.788] sb_displayer_init:327 no display or led visualizer for LMS
I (3442) DAC core: DAC uses I2C port:0, sda:27, scl:26
W (3462) DAC core: I2C read failed
I (3462) TAS575x/8x: Detected TAS @0x4c
[00:10:32.805] output_init_i2s:359 invalid MCK gpio -1
I (3462) I2S: DMA Malloc info, datalen=blocksize=2048, dma_buf_count=12
I (3472) I2S: APLL: Req RATE: 44100, real rate: 44099.988, BITS: 16, CLKM: 1, BCK_M: 8, MCLK: 11289597.000, SCLK: 1411199.625000, diva: 1, divb: 0
[00:10:32.830] equalizer_set_samplerate:121 equalizer sample rate 44100
W (3502) BT_AV: BT Sink pin code is: [1234] 
I (3502) BTDM_INIT: BT controller compile version [2c56073]
I (3882) BT_AV: Bluetooth Init complete
I (5272) wifi:new:<3,0>, old:<1,0>, ap:<255,255>, sta:<3,0>, prof:1
I (5822) wifi:state: init -> auth (b0)
I (6832) wifi:state: auth -> init (200)
I (6832) wifi:new:<3,0>, old:<3,0>, ap:<255,255>, sta:<3,0>, prof:1
W (6832) network_wifi: WIFI_EVENT_STA_DISCONNECTED. From BSSID: 82:8a:20:8d:ec:65, reason code: 2 (WIFI_REASON_AUTH_EXPIRE)
I (6842) network_handlers: Wifi was disconnected from previous access point. Waiting to connect.
I (18372) network_handlers: Timer: Wifi Polling timeout 
I (18372) network_wifi: Wifi Connecting to Bolton-IoT...
I (20062) wifi:new:<3,0>, old:<3,0>, ap:<255,255>, sta:<3,0>, prof:1
I (20062) wifi:state: init -> auth (b0)
I (20082) wifi:state: auth -> assoc (0)
I (20092) wifi:state: assoc -> run (10)
I (20132) wifi:connected with Bolton-IoT, aid = 1, channel 3, BW20, bssid = 82:8a:20:8d:ec:65
I (20142) wifi:security: WPA2-PSK, phy: bgn, rssi: -67
I (20152) wifi:pm start, type: 1

I (20162) network: Got an IP address from interface Wifi. IP=192.168.210.71, Gateway=192.168.210.1, NetMask=255.255.255.0, Address was changed
I (20172) esp_netif_handlers: sta ip: 192.168.210.71, mask: 255.255.255.0, gw: 192.168.210.1
I (20172) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (20192) esp_app_main: Network connected and mDNS initialized with Garage
[00:10:49.534] raop_sink_start:178 starting Airplay for ip 192.168.210.71 with servicename Garage
[00:10:49.547] raop_create:201 starting mDNS with 0CDC7E501F88@Garage
I (21432) httpd_handlers: serving /messages.json to peer 192.168.210.140 port 16610
I (39822) httpd_handlers: serving /messages.json to peer 192.168.210.140 port 16866
[00:11:18.894] rtsp_thread:397 got RTSP connection 52
[00:11:18.921] rtsp_thread:413 RTSP close 52
[00:11:20.125] rtsp_thread:397 got RTSP connection 52
[00:11:20.161] handle_rtsp:444 [0x3fac6470]: received ANNOUNCE
[00:11:20.366] search_remote:747 starting remote search
[00:11:20.367] handle_rtsp:667 [0x3fac6470]: responding:

[00:11:20.413] handle_rtsp:444 [0x3fac6470]: received SETUP
[00:11:20.416] buffer_alloc:387 allocated 1153 buffers (min=375) from buffer of 1624640 bytes
[00:11:20.422] handle_rtsp:667 [0x3fac6470]: responding:

[00:11:20.474] equalizer_process:222 equalizer deactivated
[00:11:20.479] handle_rtsp:444 [0x3fac6470]: received RECORD
[00:11:20.480] rtp_record:374 [0x3fac91e4]: record 53107 3893625783
[00:11:20.482] handle_rtsp:667 [0x3fac6470]: responding:

[00:11:20.528] handle_rtsp:444 [0x3fac6470]: received SET_PARAMETER
[00:11:20.529] handle_rtsp:613 [0x3fac6470]: SET PARAMETER volume -5.437325
[00:11:20.531] handle_rtsp:667 [0x3fac6470]: responding:

[00:11:20.549] rtp_thread_func:714 [0x3fac91e4]: 1st sync packet received
[00:11:20.551] rtp_thread_func:671 [0x3fac91e4]: 1st audio packet received
[00:11:20.617] handle_rtsp:444 [0x3fac6470]: received SET_PARAMETER
[00:11:20.619] handle_rtsp:613 [0x3fac6470]: SET PARAMETER volume -5.437325
[00:11:20.621] handle_rtsp:667 [0x3fac6470]: responding:

[00:11:21.462] handle_rtsp:444 [0x3fac6470]: received SET_PARAMETER
[00:11:21.467] handle_rtsp:639 [0x3fac6470]: received metadata (ts: 2147483647)
    artist: Matchbox Twenty
    album:  Mad Season (Deluxe Version)
    title:  If You're Gone
[00:11:21.480] handle_rtsp:667 [0x3fac6470]: responding:

[00:11:23.434] search_remote:766 found remote iTunes_Ctrl_241BAC86BF37BCA2 192.168.210.140:51885
[00:11:25.394] handle_rtsp:444 [0x3fac6470]: received SET_PARAMETER
[00:11:25.396] handle_rtsp:650 Unhandled SET PARAMETER
Active-Remote: 4148062643

[00:11:25.427] handle_rtsp:667 [0x3fac6470]: responding:

[00:11:25.500] handle_rtsp:444 [0x3fac6470]: received SET_PARAMETER
[00:11:25.501] handle_rtsp:623 [0x3fac6470]: SET PARAMETER progress 161000/274000 progress: 3886501879/3893625783/3898629307

[00:11:25.515] handle_rtsp:667 [0x3fac6470]: responding:

[00:11:28.539] buffer_put_packet:504 [0x3fac91e4]: fill [level:1 rec:6] [W:54108 R:54107]
[00:11:28.544] buffer_push_packet:570 [0x3fac91e4]: drain [level:0 head:2228 ms] [W:54108 R:54108] [req:6 sil:0 dis:0]
[00:11:36.520] buffer_push_packet:570 [0x3fac91e4]: drain [level:0 head:2241 ms] [W:55109 R:55109] [req:11 sil:0 dis:0]
[00:11:36.529] buffer_put_packet:504 [0x3fac91e4]: fill [level:1 rec:11] [W:55110 R:55109]
[00:11:44.522] buffer_push_packet:570 [0x3fac91e4]: drain [level:0 head:2231 ms] [W:56110 R:56110] [req:20 sil:0 dis:0]
[00:11:44.524] buffer_put_packet:504 [0x3fac91e4]: fill [level:1 rec:19] [W:56111 R:56110]
[00:11:52.588] buffer_push_packet:570 [0x3fac91e4]: drain [level:0 head:2156 ms] [W:57111 R:57111] [req:27 sil:0 dis:0]
[00:11:52.605] buffer_put_packet:504 [0x3fac91e4]: fill [level:1 rec:26] [W:57113 R:57112]
[00:12:00.581] buffer_put_packet:504 [0x3fac91e4]: fill [level:5 rec:34] [W:58116 R:58111]
[00:12:00.589] buffer_push_packet:570 [0x3fac91e4]: drain [level:0 head:2176 ms] [W:58116 R:58116] [req:36 sil:0 dis:0]
[00:12:08.512] buffer_put_packet:504 [0x3fac91e4]: fill [level:1 rec:43] [W:59117 R:59116]
[00:12:08.517] buffer_push_packet:570 [0x3fac91e4]: drain [level:0 head:2236 ms] [W:59117 R:59117] [req:44 sil:0 dis:0]
[00:12:16.507] buffer_push_packet:570 [0x3fac91e4]: drain [level:0 head:2239 ms] [W:60118 R:60118] [req:52 sil:0 dis:0]
[00:12:16.511] buffer_put_packet:504 [0x3fac91e4]: fill [level:1 rec:51] [W:60119 R:60118]
[00:12:24.496] buffer_push_packet:570 [0x3fac91e4]: drain [level:0 head:2238 ms] [W:61119 R:61119] [req:60 sil:0 dis:0]
[00:12:24.510] buffer_put_packet:504 [0x3fac91e4]: fill [level:1 rec:59] [W:61121 R:61120]
[00:12:31.868] handle_rtsp:444 [0x3fac6470]: received SET_PARAMETER
[00:12:31.869] handle_rtsp:613 [0x3fac6470]: SET PARAMETER volume -11.537104
[00:12:31.872] handle_rtsp:667 [0x3fac6470]: responding:

[00:12:32.585] handle_rtsp:444 [0x3fac6470]: received SET_PARAMETER
[00:12:32.587] handle_rtsp:613 [0x3fac6470]: SET PARAMETER volume -10.574460
[00:12:32.589] handle_rtsp:667 [0x3fac6470]: responding:

[00:12:33.108] handle_rtsp:444 [0x3fac6470]: received SET_PARAMETER
[00:12:33.110] handle_rtsp:613 [0x3fac6470]: SET PARAMETER volume -10.454395
[00:12:33.112] handle_rtsp:667 [0x3fac6470]: responding:

[00:12:33.492] handle_rtsp:444 [0x3fac6470]: received SET_PARAMETER
[00:12:33.494] handle_rtsp:613 [0x3fac6470]: SET PARAMETER volume -10.333788
[00:12:33.496] handle_rtsp:667 [0x3fac6470]: responding:

[00:12:34.224] buffer_push_packet:570 [0x3fac91e4]: drain [level:0 head:447 ms] [W:62120 R:62120] [req:138 sil:2 dis:0]
[00:12:34.232] buffer_put_packet:504 [0x3fac91e4]: fill [level:1 rec:124] [W:62123 R:62122]
[00:12:34.336] handle_rtsp:444 [0x3fac6470]: received SET_PARAMETER
[00:12:34.337] handle_rtsp:613 [0x3fac6470]: SET PARAMETER volume -9.852598
[00:12:34.343] handle_rtsp:667 [0x3fac6470]: responding:

[00:12:35.458] rtp_thread_func:695 discarding remote timing information 4294967250
[00:12:40.450] buffer_put_packet:504 [0x3fac91e4]: fill [level:1 rec:129] [W:63118 R:63117]
[00:12:40.478] buffer_push_packet:570 [0x3fac91e4]: drain [level:0 head:2237 ms] [W:63121 R:63121] [req:143 sil:2 dis:0]
[00:12:48.449] buffer_put_packet:504 [0x3fac91e4]: fill [level:1 rec:136] [W:64120 R:64119]
[00:12:48.467] buffer_push_packet:570 [0x3fac91e4]: drain [level:0 head:2239 ms] [W:64122 R:64122] [req:150 sil:2 dis:0]
[00:12:56.448] buffer_put_packet:504 [0x3fac91e4]: fill [level:1 rec:143] [W:65122 R:65121]
[00:12:56.459] buffer_push_packet:570 [0x3fac91e4]: drain [level:0 head:2239 ms] [W:65123 R:65123] [req:157 sil:2 dis:0]
[00:13:04.447] buffer_put_packet:504 [0x3fac91e4]: fill [level:1 rec:151] [W:588 R:587]
[00:13:04.450] buffer_push_packet:570 [0x3fac91e4]: drain [level:0 head:2239 ms] [W:588 R:588] [req:165 sil:2 dis:0]
[00:13:12.440] buffer_push_packet:570 [0x3fac91e4]: drain [level:0 head:2241 ms] [W:1589 R:1589] [req:172 sil:2 dis:0]
[00:13:12.445] buffer_put_packet:504 [0x3fac91e4]: fill [level:1 rec:158] [W:1590 R:1589]
[00:13:14.305] rtp_thread_func:671 [0x3fac91e4]: 1st audio packet received
[00:13:14.659] handle_rtsp:444 [0x3fac6470]: received SET_PARAMETER
[00:13:14.661] handle_rtsp:639 [0x3fac6470]: received metadata (ts: 2147483647)
    artist: Dave Matthews Band
    album:  Before These Crowded Streets
    title:  Spoon
[00:13:14.676] handle_rtsp:667 [0x3fac6470]: responding:

[00:13:16.662] handle_rtsp:444 [0x3fac6470]: received SET_PARAMETER
[00:13:16.664] handle_rtsp:650 Unhandled SET PARAMETER
Active-Remote: 4148062643

[00:13:16.690] handle_rtsp:667 [0x3fac6470]: responding:

[00:13:16.760] handle_rtsp:444 [0x3fac6470]: received SET_PARAMETER
[00:13:16.761] handle_rtsp:623 [0x3fac6470]: SET PARAMETER progress 0/453000 progress: 3898611767/3898642487/3918597879

[00:13:16.778] handle_rtsp:667 [0x3fac6470]: responding:

[00:13:20.430] buffer_push_packet:570 [0x3fac91e4]: drain [level:0 head:2240 ms] [W:2590 R:2590] [req:177 sil:2 dis:0]
[00:13:20.444] buffer_put_packet:504 [0x3fac91e4]: fill [level:1 rec:163] [W:2592 R:2591]
[00:13:28.425] buffer_push_packet:570 [0x3fac91e4]: drain [level:0 head:2231 ms] [W:3591 R:3591] [req:184 sil:2 dis:0]
[00:13:28.450] buffer_put_packet:504 [0x3fac91e4]: fill [level:1 rec:170] [W:3594 R:3593]
[00:13:36.411] buffer_push_packet:570 [0x3fac91e4]: drain [level:0 head:2241 ms] [W:4592 R:4592] [req:192 sil:2 dis:0]
[00:13:36.440] buffer_put_packet:504 [0x3fac91e4]: fill [level:1 rec:178] [W:4596 R:4595]
[00:13:44.410] buffer_push_packet:570 [0x3fac91e4]: drain [level:0 head:2232 ms] [W:5593 R:5593] [req:200 sil:2 dis:0]
[00:13:44.439] buffer_put_packet:504 [0x3fac91e4]: fill [level:1 rec:186] [W:5598 R:5597]
[00:13:52.392] buffer_push_packet:570 [0x3fac91e4]: drain [level:0 head:2242 ms] [W:6594 R:6594] [req:206 sil:2 dis:0]
[00:13:52.436] buffer_put_packet:504 [0x3fac91e4]: fill [level:1 rec:192] [W:6600 R:6599]
[00:14:00.381] buffer_push_packet:570 [0x3fac91e4]: drain [level:0 head:2243 ms] [W:7595 R:7595] [req:215 sil:2 dis:0]
[00:14:00.428] buffer_put_packet:504 [0x3fac91e4]: fill [level:1 rec:200] [W:7601 R:7600]
[00:14:03.021] rtp_thread_func:768 [0x3fac91e4]: terminating
[00:14:03.025] cleanup_rtsp:684 [0x3fac6470]: RTP thread aborted
[00:14:03.027] cleanup_rtsp:700 [0x3fac6470]: Remote search thread aborted
W (213822) messaging: cfg-audio-tmpl
squeezelite exited with error code 0

W (213822) messaging: cfg-audio-tmpl
squeezelite exited with error code 0

E (213832) messaging: cfg-audio-tmpl
Rebooting in 60 sec

E (213832) messaging: cfg-audio-tmpl
Rebooting in 60 sec

Then gets into a reboot loop

sle118 commented 1 year ago

Dave Matthews. Good choice :)

Now it looks like you have some WiFi issues on your network. The messages below are indicating some association issues (WIFI_REASON_ASSOC_EXPIRE).

Ok after taking the time to read through the entire log, it appears that the the RTP encounters a condition that causes it to abort, but there isn't a clear indication why it's happening. This is something @philippe44 would have to look into.

emlynmac commented 1 year ago

@sle118 thanks, I'm also going to be looking at getting my local environment up and running for building / debugging. Any tips for doing this would be much appreciated, I've got docker installed so far but I don't think I can pass my serial port through to the docker build environment in MacOS - or can I? Maybe time to set it up properly on macOS. Are the build instructions up-to-date?

I'm seeing failures when trying to use the docker instructions to build.

I followed instructions from https://github.com/sle118/squeezelite-esp32#docker

docker pull sle118/squeezelite-esp32-idfv435

Then docker run -it -vpwd:/workspace/squeezelite-esp32 sle118/squeezelite-esp32-idfv435 and cd to workspace/squeezelite-esp32

idf.py build then fails to build:

[1338/1550] Building C object esp-idf/tools/CMakeFiles/__idf_tools.dir/tools.c.obj
FAILED: esp-idf/tools/CMakeFiles/__idf_tools.dir/tools.c.obj 
ccache /opt/esp/tools/xtensa-esp32-elf/esp-2021r2-patch3-8.4.0/xtensa-esp32-elf/bin/xtensa-esp32-elf-gcc -DHAVE_CONFIG_H -DHIERARCHICAL_STATES=1 -DMBEDTLS_CONFIG_FILE=\"mbedtls/esp_config.h\" -DMODEL_NAME=SqueezeESP32 -DSTATE_MACHINE_LOGGER=1 -Iconfig -I../components/tools -I/opt/esp/idf/components/newlib/platform_include -I/opt/esp/idf/components/freertos/include -I/opt/esp/idf/components/freertos/include/esp_additions -I/opt/esp/idf/components/freertos/port/xtensa/include -I/opt/esp/idf/components/esp_hw_support/include -I/opt/esp/idf/components/esp_hw_support/port/esp32/. -I/opt/esp/idf/components/esp_hw_support/port/esp32/private_include -I/opt/esp/idf/components/heap/include -I/opt/esp/idf/components/log/include -I/opt/esp/idf/components/lwip/include/apps -I/opt/esp/idf/components/lwip/include/apps/sntp -I/opt/esp/idf/components/lwip/lwip/src/include -I/opt/esp/idf/components/lwip/port/esp32/include -I/opt/esp/idf/components/lwip/port/esp32/include/arch -I/opt/esp/idf/components/soc/include -I/opt/esp/idf/components/soc/esp32/. -I/opt/esp/idf/components/soc/esp32/include -I/opt/esp/idf/components/hal/esp32/include -I/opt/esp/idf/components/hal/include -I/opt/esp/idf/components/esp_rom/include -I/opt/esp/idf/components/esp_rom/esp32 -I/opt/esp/idf/components/esp_rom/include/esp32 -I/opt/esp/idf/components/esp_common/include -I/opt/esp/idf/components/esp_system/include -I/opt/esp/idf/components/esp32/include -I/opt/esp/idf/components/driver/include -I/opt/esp/idf/components/driver/esp32/include -I/opt/esp/idf/components/esp_ringbuf/include -I/opt/esp/idf/components/efuse/include -I/opt/esp/idf/components/efuse/esp32/include -I/opt/esp/idf/components/xtensa/include -I/opt/esp/idf/components/xtensa/esp32/include -I/opt/esp/idf/components/espcoredump/include -I/opt/esp/idf/components/espcoredump/include/port/xtensa -I/opt/esp/idf/components/esp_timer/include -I/opt/esp/idf/components/esp_ipc/include -I/opt/esp/idf/components/esp_pm/include -I/opt/esp/idf/components/vfs/include -I/opt/esp/idf/components/esp_wifi/include -I/opt/esp/idf/components/esp_wifi/esp32/include -I/opt/esp/idf/components/esp_event/include -I/opt/esp/idf/components/esp_netif/include -I/opt/esp/idf/components/esp_eth/include -I/opt/esp/idf/components/tcpip_adapter/include -I/opt/esp/idf/components/app_trace/include -I/opt/esp/idf/components/pthread/include -I/opt/esp/idf/components/esp_http_client/include -I/opt/esp/idf/components/nghttp/port/include -I/opt/esp/idf/components/nghttp/nghttp2/lib/includes -I/opt/esp/idf/components/esp-tls -I/opt/esp/idf/components/esp-tls/esp-tls-crypto -I/opt/esp/idf/components/mbedtls/port/include -I/opt/esp/idf/components/mbedtls/mbedtls/include -I/opt/esp/idf/components/mbedtls/esp_crt_bundle/include -mlongcalls -Wno-frame-address   -ffunction-sections -fdata-sections -Wall -Werror=all -Wno-error=unused-function -Wno-error=unused-variable -Wno-error=deprecated-declarations -Wextra -Wno-unused-parameter -Wno-sign-compare -ggdb -mfix-esp32-psram-cache-issue -mfix-esp32-psram-cache-strategy=memw -Os -freorder-blocks -fstrict-volatile-bitfields -Wno-error=unused-but-set-variable -std=gnu99 -Wno-old-style-declaration -D_GNU_SOURCE -DIDF_VER=\"v4.3.5-dirty\" -DESP_PLATFORM -MD -MT esp-idf/tools/CMakeFiles/__idf_tools.dir/tools.c.obj -MF esp-idf/tools/CMakeFiles/__idf_tools.dir/tools.c.obj.d -o esp-idf/tools/CMakeFiles/__idf_tools.dir/tools.c.obj   -c ../components/tools/tools.c
../components/tools/tools.c:24:2: error: #error CONFIG_FREERTOS_THREAD_LOCAL_STORAGE_POINTERS must be at least 2
 #error CONFIG_FREERTOS_THREAD_LOCAL_STORAGE_POINTERS must be at least 2
  ^~~~~
[1351/1550] Building CXX object esp-idf/spotify/cspot/CMakeFiles/cspot.dir/src/MercurySession.cpp.obj
ninja: build stopped: subcommand failed.
ninja failed with exit code 1

I assumed out of date code but a git pull and git submodule update --init --recursive made no difference.

sle118 commented 1 year ago

First thing to do also is to copy the content of build-script/yourhardwareofchoice to sdkconfig.

philippe44 commented 1 year ago

Do you have a LMS server running on your network? And re the build, the error is self-explanatory : you need to change that config in freertos/pthread in menuconfig

emlynmac commented 1 year ago

I do not, but i can set one up if that would help debug

emlynmac commented 1 year ago

First thing to do also is to copy the content of build-script/yourhardwareofchoice to sdkconfig.

OK, done, copied the SqueezeAmp config across, removed CSPOT and updated from 4mb to 16mb flash. idf.py build now building fine.

Now I need to go set up a linux VM so I can actually flash...

philippe44 commented 1 year ago

So if you do not have a LMS server, it will reboot every 5-10 mins. It's in bold here https://github.com/sle118/squeezelite-esp32#additional-configuration-notes-from-the-web-ui. The RTP thread aborts because the system goes reboot.

emlynmac commented 1 year ago

So if you do not have a LMS server, it will reboot every 5-10 mins. It's in bold here https://github.com/sle118/squeezelite-esp32#additional-configuration-notes-from-the-web-ui. The RTP thread aborts because the system goes reboot.

Was this a recent change? It had been working fine for a few months until I updated from 1306 to latest.

So adding -s -disable to the command line will fix this up?

Anyway, all good learning for me; I now have the linux VM set up with docker so I should be able to actually build and look into the code.

Thanks for the pointers!

philippe44 commented 1 year ago

Yes that was a change a few versions ago as the WiFi sometimes get stalls and would never recover connection. It's really problematic especially on battery-powered devices without an on/off or reset.

emlynmac commented 1 year ago

OK, so that explains the reboot loop.

Does it also explain the AirPlay crash, or was that fixed in updating from the older version to the more recent? I can try it out for a bit and see I guess.

philippe44 commented 1 year ago

The crash IMHO happened because of the reboot

emlynmac commented 1 year ago

The crash IMHO happened because of the reboot

I can buy that :)

And if the way to have it auto-reconnect is to have LMS on my network, then I will happily have that.

philippe44 commented 1 year ago

Let's see how it goes - don't hesitate to re-open this if it happens again.