WiFi association unstable

[LeoSum8]

Hi all,
I found some time today to retry getting squeezelite to run on my Louder ESP32.
Most of the time, the first attempt to connect to my home wifi fails and squeezelite falls back to AP mode. A manual reboot via RST-Button usually results in a successfull connection. Is this a known problem with certain setups? Would it be possible to make squeezelite try connecting several times before failing to AP-Mode? I saw that with other firmwares (euphonium, snapclient) the first connection attempt to my wifi sometimes fails too, but sinc those other firmwares just retry, I usually don't notice.

I think this behaviour also explains, why I sometimes seem to "loose" the client. I haven't been able to record that yet, since I don't have it hooked up to serial all of the time, but I guess if wifi fails at a later point, it would fall back to AP-Mode too and not retry connecting, right?

Preliminary Information

1. Firmware Version: 2.1672-16#v4.3#I2S-4MFlash#master-v4.3
2. Plugin Version: LMS disabled (see log)

Hardware Details

Please describe your hardware setup:

• ESP32 Module: ESP32 WROOM with external PSRAM
• Board Type: Louder ESP32
• DAC Chip: TAS5805m
• Additional Hardware: -

NVS Settings

{
  "a2dp_ctmt": "1000",
  "a2dp_ctrld": "500",
  "a2dp_dev_name": "Squeezelite",
  "a2dp_sink_name": "SMSL BT4.2",
  "a2dp_spin": "0000",
  "actrls_config": "",
  "airplay_name": "ESP32-AirPlay-738894",
  "airplay_port": "5000",
  "ap_channel": "1",
  "ap_ip_address": "192.168.4.1",
  "ap_ip_gateway": "192.168.4.1",
  "ap_ip_netmask": "255.255.255.0",
  "ap_pwd": "squeezelite",
  "ap_ssid": "squeezelite-738894",
  "autoexec": "1",
  "autoexec1": "squeezelite  -o i2s  -s  -disable -b  500:2000 -C  30 -d  all=info ",
  "bat_config": "",
  "bt_name": "ESP32-BT-738894",
  "bt_sink_pin": "1234",
  "bt_sink_volume": "127",
  "bypass_wm": "0",
  "cspot_config": "{\"deviceName\":\"Squeezelite\",\"bitrate\":160,\"zeroConf\":1,\"volume\":32768}",
  "dac_config": "model=I2S,bck=26,ws=25,do=22,sda=21,scl=27,i2c=45",
  "dac_controlset": "{\"init\":[{\"reg\":3,\"val\":2},{\"reg\":3,\"val\":3}],\"poweron\":[{\"reg\":3,\"val\":3}],\"poweroff\":[{\"reg\":3,\"val\":0}]} ",
  "dhcp_tmout": "8",
  "display_config": "",
  "enable_airplay": "1",
  "enable_bt_sink": "1",
  "enable_cspot": "1",
  "equalizer": "",
  "eth_config": "",
  "ethtmout": "8",
  "gpio_exp_config": "",
  "host_name": "squeezelite-738894",
  "i2c_config": "scl=27,sda=21,speed=400000,port=1",
  "jack_mutes_amp": "n",
  "led_brightness": "",
  "led_vu_config": "",
  "lms_ctrls_raw": "n",
  "loudness": "0",
  "metadata_config": "",
  "model_config": "",
  "ota_erase_blk": "249856",
  "ota_prio": "6",
  "ota_stack": "10240",
  "pollmin": "15",
  "pollmx": "600",
  "rel_api": "https://api.github.com/repos/sle118/squeezelite-esp32/releases",
  "release_url": "CONFIG_SQUEEZELITE_ESP32_RELEASE_URL",
  "rotary_config": "",
  "set_GPIO": "33=vcc",
  "sleep_config": "",
  "spdif_config": "",
  "spi_config": "",
  "stats": "n",
  "target": "",
  "telnet_block": "500",
  "telnet_buffer": "40000",
  "telnet_enable": ""
}

Logs

Full Log

ets Jul 29 2019 12:21:46
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:6424

load:0x40078000,len:15632

load:0x40080400,len:4348

entry 0x40080688

I (27) boot: ESP-IDF v4.3.5-dirty 2nd stage bootloader

I (27) boot: compile time 03:05:16

I (27) boot: chip revision: v3.0

I (31) qio_mode: Enabling default flash chip QIO

I (36) boot.esp32: SPI Speed      : 80MHz

I (41) boot.esp32: SPI Mode       : QIO

I (45) boot.esp32: SPI Flash Size : 4MB

I (50) boot: Enabling RNG early entropy source...

I (55) boot: Partition Table:

I (59) boot: ## Label            Usage          Type ST Offset   Length

I (66) boot:  0 nvs              WiFi data        01 02 00009000 00004000

I (74) boot:  1 otadata          OTA data         01 00 0000d000 00002000

I (81) boot:  2 phy_init         RF data          01 01 0000f000 00001000

I (89) boot:  3 recovery         factory app      00 00 00010000 00140000

I (96) boot:  4 ota_0            OTA app          00 10 00150000 002a0000

I (104) boot:  5 settings         WiFi data        01 02 003f0000 00010000

I (111) boot: End of partition table

I (115) esp_image: segment 0: paddr=00150020 vaddr=3f400020 size=aeaf0h (715504) map

I (321) esp_image: segment 1: paddr=001feb18 vaddr=3ffbdb60 size=01500h (  5376) load

I (323) esp_image: segment 2: paddr=00200020 vaddr=400d0020 size=1b2e5ch (1781340) map

I (818) esp_image: segment 3: paddr=003b2e84 vaddr=3ffbf060 size=0453ch ( 17724) load

I (823) esp_image: segment 4: paddr=003b73c8 vaddr=40080000 size=1e014h (122900) load

I (863) esp_image: segment 5: paddr=003d53e4 vaddr=400c0000 size=00068h (   104) load

I (878) boot: Loaded app from partition at offset 0x150000

I (879) boot: Disabling RNG early entropy source...

I (890) psram: This chip is ESP32-D0WD

I (890) spiram: Found 64MBit SPI RAM device

I (890) spiram: SPI RAM mode: flash 80m sram 80m

I (893) spiram: PSRAM initialized, cache is in low/high (2-core) mode.

I (901) cpu_start: Pro cpu up.

I (904) cpu_start: Starting app cpu, entry point is 0x400813fc

I (0) cpu_start: App cpu up.

I (1410) spiram: SPI SRAM memory test OK

I (1423) cpu_start: Pro cpu start user code

I (1423) cpu_start: cpu freq: 240000000

I (1423) cpu_start: Application information:

I (1426) cpu_start: Project name:     Squeezelite-ESP32

I (1432) cpu_start: App version:      I2S-4MFlash-1672

I (1437) cpu_start: Compile time:     Mar 22 2024 03:06:48

I (1444) cpu_start: ELF file SHA256:  0000000000000000...

I (1450) cpu_start: ESP-IDF:          v4.3.5-dirty

I (1455) cpu_start: Min chip rev:     v1.0

I (1460) cpu_start: Max chip rev:     v3.99

I (1465) cpu_start: Chip rev:         v3.0

I (1470) heap_init: Initializing. RAM available for dynamic allocation:

I (1477) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM

I (1483) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM

I (1489) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM

I (1495) heap_init: At 3FFC6EC8 len 00019138 (100 KiB): DRAM

I (1502) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM

I (1508) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM

I (1515) heap_init: At 4009E014 len 00001FEC (7 KiB): IRAM

I (1521) spiram: Adding pool of 4018K of external SPI memory to heap allocator

I (1529) spi_flash: detected chip: gd

I (1533) spi_flash: flash io: qio

W (1537) spi_flash: Detected size(16384k) larger than the size in the binary image header(4096k). Using the size in the binary image header.

I (1553) cpu_start: Starting scheduler on PRO CPU.

I (0) cpu_start: Starting scheduler on APP CPU.

I (1561) spiram: Reserving pool of 64K of internal memory for DMA/internal allocations

I (1571) esp_app_main: System is booting from power on.

I (1581) esp_app_main: Reset reason is: 1

I (1581) esp_app_main: Reboot counter=1
I (1581) esp_app_main: Starting app_main

I (1591) nvs_utilities: Initializing flash nvs

I (1611) nvs_utilities: Initializing nvs partition settings

I (1651) esp_app_main: Setting up telnet.

I (1651) telnet: Telnet support disabled

I (1651) esp_app_main: Setting up config subsystem.

W (1731) nvs_utilities: Configuration memory usage.  Heap internal:229071 (min:228927) (used:216) external:4094935 (min:4087159) (used:15680)

I (1731) esp_app_main: Registering default values

I (1731) system_api: Base MAC address is not set

I (1741) system_api: read default base MAC address from EFUSE

W (1751) config: Waiting for config commit ...

I (2731) config: configuration has some uncommitted entries

I (2731) config: Committing configuration to nvs. Locking config object.

I (2741) config: Done Committing configuration to nvs.

I (2741) config: Config committed!

I (2741) esp_app_main: Configuring services

I (2741) services: set GPIO 33 to vcc

I (2751) services: Configuring I2C sda:21 scl:27 port:1 speed:400000

I (2751) services: Configuring SPI mosi:-1 miso:-1 clk:-1 host:1 dc:-1

W (2761) services: no SPI configured

W (2771) led: LED GPIO -1 ignored

W (2771) led: LED GPIO -1 ignored

I (2771) led: Configuring LEDs green:-1 (on:0 rmt:-1 -1% ), red:-1 (on:0 rmt:-1 -1% )

I (2781) battery: No battery

I (2791) monitor: Initializing monitoring

I (2791) monitor: Heap internal:229315 (min:228855) external:4078295 (min:4078271) dma:221523 (min:221079)

I (2801) esp_app_main: Initializing display

I (2811) display: Trying to configure display with N/A

W (2811) display: No display driver

I (2821) esp_app_main: Initializing led_vu

I (2821) led_vu: led_vu configuration invalid

I (2821) esp_app_main: Checking for update url

W (2831) config: Value not found for key fwurl

W (2841) config: Value not found for key

�[0;32W (2851) config: Value not found for key apdelay

I (2851) uart: queue free spaces: 3

I (2851) network_handlers: Network manager configuration: polling max 10176, polling min 15000, ap delay 20000, dhcp timeout 8000, eth timeout 8000

W (2881) network_wifi: No known access point found

I (2881) network_wifi: Adding legacy/active wifi connection to the known list

I (2881) http_server: Initializing HTTP Server

I (2891) network_ethernet: Attempting to initialize Ethernet

I (2891) network_ethernet: No Ethernet configuration, or configuration invalid

I (2921) wifi:wifi driver task: 3ffcab40, prio:23, stack:6656, core=0

I (2921) wifi:wifi firmware version: 9ec65ef

I (2921) wifi:wifi certification version: v7.0

I (2921) wifi:config NVS flash: enabled

I (2931) wifi:config nano formating: disabled

I (2931) wifi:Init data frame dynamic rx buffer num: 40

I (2931) wifi:Init management frame dynamic rx buffer num: 40

I (2941) wifi:Init management short buffer num: 32

I (2941) wifi:Init static tx buffer num: 12

I (2951) wifi:Init tx cache buffer num: 32

I (2961) wifi:Init static rx buffer size: 1600

I (2961) wifi:Init static rx buffer num: 12

I (2971) wifi:Init dynamic rx buffer num: 40

I (2971) wifi_init: tcpip mbox: 32

I (2971) wifi_init: udp mbox: 32

I (2971) wifi_init: tcp mbox: 32

I (2981) wifi_init: tcp tx win: 8192

I (2981) wifi_init: tcp rx win: 32768

I (2991) wifi_init: tcp mss: 1440

I (2991) wifi_init: WiFi/LWIP prefer SPIRAM

I (2991) network_wifi: Starting wifi

I (3001) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07

I (3091) wifi:mode : sta (c8:f0:9e:73:88:94)

I (3091) wifi:enable tsf
I (3091) network_handlers: Existing wifi config found. Attempting to connect.

I (3101) network: Starting DHCP client

I (3111) network_wifi: Wifi Connecting to HomeWifi...

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 (3171) console: Processing autoexec commands while network manager active.  Wifi related commands will be ignored.

I (3171) console: autoexec is set to perform auto-process

I (3181) console: Running command autoexec1 = squeezelite  -o i2s  -s  -disable -b  500:2000 -C  30 -d  all=info

W (3191) config: Value not found for key autoexec2

squeezelite-esp32> I (3191) squeezelite_cmd: Calling squeezelite

[00:00:01.781] sb_controls_init:249 initializing audio (buttons/rotary/ir) controls (raw:0)

[00:00:01.792] sb_displayer_init:327 no display or led visualizer for LMS

[00:00:01.793] stream_init:539 init stream

[00:00:01.794] output_init_embedded:78 init device: i2s

[00:00:01.806] output_init_common:433 supported rates: 192000 176400 96000 88200 48000 44100 32000 24000 22050 16000 12000 11025 8000

[00:00:01.818] output_init_embedded:100 init I2S/SPDIF

I (3241) DAC core: DAC uses I2C port:0, sda:21, scl:27

I (3241) DAC external: DAC on I2C @45

[00:00:01.832] output_init_i2s:347 configuring MCLK on GPIO -1

[00:00:01.833] output_init_i2s:359 invalid MCK gpio -1

I (3271) I2S: DMA Malloc info, datalen=blocksize=2048, dma_buf_count=12

I (3271) 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.858] output_init_i2s:376 I2S DAC using I2S bck:26, ws:25, do:22, mute:-1:0 (res:0)

[00:00:01.870] 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.881] equalizer_set_samplerate:121 equalizer sample rate 44100

[00:00:01.893] output_thread_i2s:518 Output state is -1

[00:00:01.893] output_visu_init:75 Initialize VISUEXPORT 512 16 bits samples

[00:00:01.894] output_thread_i2s:522 switching off amp GPIO -1

[00:00:01.895] output_init_embedded:108 init completed.

[00:00:01.907] decode_init:153 init decode

[00:00:01.918] register_alac:547 using alac to decode alc

[00:00:01.918] register_helixaac:686 using helix-aac to decode aac

[00:00:01.929] register_vorbis:526 using vorbis to decode ogg

[00:00:01.930] register_opus:458 using opus to decode ops

[00:00:01.931] register_flac:338 using flac to decode ogf,flc

[00:00:01.942] register_pcm:483 using pcm to decode aif,pcm

[00:00:01.942] register_mad:417 using mad to decode mp3

W (3381) BT_AV: BT Sink pin code is: [1234]

I (3381) BTDM_INIT: BT controller compile version [2c56073]

[00:00:01.955] register_external:469 Initializing AirPlay sink

[00:00:01.967] register_external:480 Initializing CSpot sink

[00:00:01.978] squeezelite_main:816 LMS is disabled

�[0;31mE (3401) messaging: [00:00:01.978] squeezelite_main:816 LMS is disabled
I (3761) BT_AV: Bluetooth Init complete

I (5041) wifi:new:<6,0>, old:<1,0>, ap:<255,255>, sta:<6,0>, prof:1

I (5561) wifi:state: init -> auth (b0)

I (5561) wifi:state: auth -> init (8a0)

I (5561) wifi:new:<6,0>, old:<6,0>, ap:<255,255>, sta:<6,0>, prof:1

W (5571) network_wifi: WIFI_EVENT_STA_DISCONNECTED. From BSSID: b0:f2:08:d5:f1:6f, reason code: 202 (WIFI_REASON_AUTH_FAIL)

W (5581) wifi:Haven't to connect to a suitable AP now!

I (5591) network_wifi: Configuring Access Point.

I (5591) network: Stopping DHCP server

I (5591) network: Starting DHCP server

I (5601) network_wifi: AP SSID: squeezelite-738894

I (5601) network_wifi: AP Password: squeezelite

I (5611) wifi:mode : sta (c8:f0:9e:73:88:94) + softAP (c8:f0:9e:73:88:95)

I (5621) wifi:Total power save buffer number: 6

I (5621) wifi:Init max length of beacon: 752/752

I (5631) wifi:Init max length of beacon: 752/752

I (6151) wifi:Total power save buffer number: 6

I (6161) wifi:Total power save buffer number: 6

I (6161) wifi:Set ps type: 1
I (6161) network_wifi: Initiating wifi network scan

I (6161) dns_server: DNS Server listening on 53/udp

�[0;31mE (18111) network: network manager Unhandled Event NETWORK_WIFI_CONFIGURING_ACTIVE_STATE(WIFI_CONFIGURING_STATE) [EN_TIMER]
=======================================

==== MANUAL REBOOT VIA PUSHBUTTON ====
ets Jul 29 2019 12:21:46
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:6424

load:0x40078000,len:15632

load:0x40080400,len:4348

entry 0x40080688

I (27) boot: ESP-IDF v4.3.5-dirty 2nd stage bootloader

I (27) boot: compile time 03:05:16

I (27) boot: chip revision: v3.0

I (31) qio_mode: Enabling default flash chip QIO

I (36) boot.esp32: SPI Speed      : 80MHz

I (41) boot.esp32: SPI Mode       : QIO

I (45) boot.esp32: SPI Flash Size : 4MB

I (50) boot: Enabling RNG early entropy source...

I (55) boot: Partition Table:

I (59) boot: ## Label            Usage          Type ST Offset   Length

I (66) boot:  0 nvs              WiFi data        01 02 00009000 00004000

I (74) boot:  1 otadata          OTA data         01 00 0000d000 00002000

I (81) boot:  2 phy_init         RF data          01 01 0000f000 00001000

I (89) boot:  3 recovery         factory app      00 00 00010000 00140000

I (96) boot:  4 ota_0            OTA app          00 10 00150000 002a0000

I (104) boot:  5 settings         WiFi data        01 02 003f0000 00010000

I (111) boot: End of partition table

I (115) esp_image: segment 0: paddr=00150020 vaddr=3f400020 size=aeaf0h (715504) map

I (321) esp_image: segment 1: paddr=001feb18 vaddr=3ffbdb60 size=01500h (  5376) load

I (323) esp_image: segment 2: paddr=00200020 vaddr=400d0020 size=1b2e5ch (1781340) map

I (818) esp_image: segment 3: paddr=003b2e84 vaddr=3ffbf060 size=0453ch ( 17724) load

I (823) esp_image: segment 4: paddr=003b73c8 vaddr=40080000 size=1e014h (122900) load

I (863) esp_image: segment 5: paddr=003d53e4 vaddr=400c0000 size=00068h (   104) load

I (878) boot: Loaded app from partition at offset 0x150000

I (879) boot: Disabling RNG early entropy source...

I (890) psram: This chip is ESP32-D0WD

I (890) spiram: Found 64MBit SPI RAM device

I (890) spiram: SPI RAM mode: flash 80m sram 80m

I (893) spiram: PSRAM initialized, cache is in low/high (2-core) mode.

I (901) cpu_start: Pro cpu up.

I (904) cpu_start: Starting app cpu, entry point is 0x400813fc

I (0) cpu_start: App cpu up.

I (1410) spiram: SPI SRAM memory test OK

I (1423) cpu_start: Pro cpu start user code

I (1423) cpu_start: cpu freq: 240000000

I (1423) cpu_start: Application information:

I (1426) cpu_start: Project name:     Squeezelite-ESP32

I (1432) cpu_start: App version:      I2S-4MFlash-1672

I (1437) cpu_start: Compile time:     Mar 22 2024 03:06:48

I (1444) cpu_start: ELF file SHA256:  0000000000000000...

I (1450) cpu_start: ESP-IDF:          v4.3.5-dirty

I (1455) cpu_start: Min chip rev:     v1.0

I (1460) cpu_start: Max chip rev:     v3.99

I (1465) cpu_start: Chip rev:         v3.0

I (1470) heap_init: Initializing. RAM available for dynamic allocation:

I (1477) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM

I (1483) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM

I (1489) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM

I (1495) heap_init: At 3FFC6EC8 len 00019138 (100 KiB): DRAM

I (1502) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM

I (1508) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM

I (1515) heap_init: At 4009E014 len 00001FEC (7 KiB): IRAM

I (1521) spiram: Adding pool of 4018K of external SPI memory to heap allocator

I (1529) spi_flash: detected chip: gd

I (1533) spi_flash: flash io: qio

W (1537) spi_flash: Detected size(16384k) larger than the size in the binary image header(4096k). Using the size in the binary image header.

I (1553) cpu_start: Starting scheduler on PRO CPU.

I (0) cpu_start: Starting scheduler on APP CPU.

I (1561) spiram: Reserving pool of 64K of internal memory for DMA/internal allocations

I (1571) esp_app_main: System is booting from power on.

I (1581) esp_app_main: Reset reason is: 1

I (1581) esp_app_main: Reboot counter=1
I (1581) esp_app_main: Starting app_main

I (1591) nvs_utilities: Initializing flash nvs

I (1611) nvs_utilities: Initializing nvs partition settings

I (1651) esp_app_main: Setting up telnet.

I (1651) telnet: Telnet support disabled

I (1651) esp_app_main: Setting up config subsystem.

W (1731) nvs_utilities: Configuration memory usage.  Heap internal:229071 (min:228927) (used:216) external:4094935 (min:4087159) (used:15680)

I (1731) esp_app_main: Registering default values

I (1731) system_api: Base MAC address is not set

I (1741) system_api: read default base MAC address from EFUSE

W (1751) config: Waiting for config commit ...

I (2731) config: configuration has some uncommitted entries

I (2731) config: Committing configuration to nvs. Locking config object.

I (2741) config: Done Committing configuration to nvs.

I (2741) config: Config committed!

I (2741) esp_app_main: Configuring services

I (2741) services: set GPIO 33 to vcc

I (2751) services: Configuring I2C sda:21 scl:27 port:1 speed:400000

I (2751) services: Configuring SPI mosi:-1 miso:-1 clk:-1 host:1 dc:-1

W (2761) services: no SPI configured

W (2771) led: LED GPIO -1 ignored

W (2771) led: LED GPIO -1 ignored

I (2771) led: Configuring LEDs green:-1 (on:0 rmt:-1 -1% ), red:-1 (on:0 rmt:-1 -1% )

I (2781) battery: No battery

I (2791) monitor: Initializing monitoring

I (2791) monitor: Heap internal:229315 (min:228855) external:4078295 (min:4078271) dma:221523 (min:221079)

I (2801) esp_app_main: Initializing display

I (2811) display: Trying to configure display with N/A

W (2811) display: No display driver

I (2821) esp_app_main: Initializing led_vu

I (2821) led_vu: led_vu configuration invalid

I (2821) esp_app_main: Checking for update url

W (2831) config: Value not found for key fwurl

W (2841) config: Value not found for key

�[0;32W (2851) config: Value not found for key apdelay

I (2851) uart: queue free spaces: 3

I (2851) network_handlers: Network manager configuration: polling max 10176, polling min 15000, ap delay 20000, dhcp timeout 8000, eth timeout 8000

W (2881) network_wifi: No known access point found

I (2881) network_wifi: Adding legacy/active wifi connection to the known list

I (2881) http_server: Initializing HTTP Server

I (2891) network_ethernet: Attempting to initialize Ethernet

I (2891) network_ethernet: No Ethernet configuration, or configuration invalid

I (2921) wifi:wifi driver task: 3ffcab40, prio:23, stack:6656, core=0

I (2921) wifi:wifi firmware version: 9ec65ef

I (2921) wifi:wifi certification version: v7.0

I (2921) wifi:config NVS flash: enabled

I (2931) wifi:config nano formating: disabled

I (2931) wifi:Init data frame dynamic rx buffer num: 40

I (2931) wifi:Init management frame dynamic rx buffer num: 40

I (2941) wifi:Init management short buffer num: 32

I (2941) wifi:Init static tx buffer num: 12

I (2951) wifi:Init tx cache buffer num: 32

I (2961) wifi:Init static rx buffer size: 1600

I (2961) wifi:Init static rx buffer num: 12

I (2971) wifi:Init dynamic rx buffer num: 40

I (2971) wifi_init: tcpip mbox: 32

I (2971) wifi_init: udp mbox: 32

I (2971) wifi_init: tcp mbox: 32

I (2981) wifi_init: tcp tx win: 8192

I (2981) wifi_init: tcp rx win: 32768

I (2991) wifi_init: tcp mss: 1440

I (2991) wifi_init: WiFi/LWIP prefer SPIRAM

I (2991) network_wifi: Starting wifi

I (3001) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07

I (3091) wifi:mode : sta (c8:f0:9e:73:88:94)

I (3091) wifi:enable tsf
I (3091) network_handlers: Existing wifi config found. Attempting to connect.

I (3101) network: Starting DHCP client

I (3101) network_wifi: Wifi Connecting to HomeWifi...

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 (3161) console: Processing autoexec commands while network manager active.  Wifi related commands will be ignored.

I (3161) console: autoexec is set to perform auto-process

I (3181) console: Running command autoexec1 = squeezelite  -o i2s  -s  -disable -b  500:2000 -C  30 -d  all=info

W (3191) config: Value not found for key autoexec2

squeezelite-esp32> I (3191) squeezelite_cmd: Calling squeezelite

[00:00:01.778] sb_controls_init:249 initializing audio (buttons/rotary/ir) controls (raw:0)

[00:00:01.790] sb_displayer_init:327 no display or led visualizer for LMS

[00:00:01.791] stream_init:539 init stream

[00:00:01.792] output_init_embedded:78 init device: i2s

[00:00:01.803] output_init_common:433 supported rates: 192000 176400 96000 88200 48000 44100 32000 24000 22050 16000 12000 11025 8000

[00:00:01.816] output_init_embedded:100 init I2S/SPDIF

I (3241) DAC core: DAC uses I2C port:0, sda:21, scl:27

I (3241) DAC external: DAC on I2C @45

[00:00:01.830] output_init_i2s:347 configuring MCLK on GPIO -1

[00:00:01.831] output_init_i2s:359 invalid MCK gpio -1

I (3261) I2S: DMA Malloc info, datalen=blocksize=2048, dma_buf_count=12

I (3271) 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.856] output_init_i2s:376 I2S DAC using I2S bck:26, ws:25, do:22, mute:-1:0 (res:0)

[00:00:01.867] 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.879] equalizer_set_samplerate:121 equalizer sample rate 44100

[00:00:01. output_thread_i2s:518 Output state is -1

[00:00:01.891] output_visu_init:75 Initialize VISUEXPORT 512 16 bits samples

[00:00:01.892] output_thread_i2s:522 switching off amp GPIO -1

[00:00:01.893] output_init_embedded:108 init completed.

[00:00:01.905] decode_init:153 init decode

[00:00:01.915] register_alac:547 using alac to decode alc

[00:00:01.916] register_helixaac:686 using helix-aac to decode aac

[00:00:01.927] register_vorbis:526 using vorbis to decode ogg

[00:00:01.928] register_opus:458 using opus to decode ops

[00:00:01.929] register_flac:338 using flac to decode ogf,flc

[00:00:01.940] register_pcm:483 using pcm to decode aif,pcm

[00:00:01.940] register_mad:417 using mad to decode mp3

W (3371) BT_AV: BT Sink pin code is: [1234]

I (3371) BTDM_INIT: BT controller compile version [2c56073]

[00:00:01.953] register_external:469 Initializing AirPlay sink

[00:00:01.964] register_external:480 Initializing CSpot sink

[00:00:01.976] squeezelite_main:816 LMS is disabled

�[0;31mE (3401) messaging: [00:00:01.976] squeezelite_main:816 LMS is disabled
I (3761) BT_AV: Bluetooth Init complete

I (5031) wifi:new:<6,0>, old:<1,0>, ap:<255,255>, sta:<6,0>, prof:1

I (5561) wifi:state: init -> auth (b0)

I (5561) wifi:state: auth -> assoc (0)

I (5571) wifi:state: assoc -> run (10)

I (5601) wifi:connected with HomeWifi, aid = 2, channel 6, BW20, bssid = b0:f2:08:d5:f1:6f

I (5601) wifi:security: WPA2-PSK, phy: bgn, rssi: -64

I (5611) wifi:pm start, type: 1
I (5621) network: Got an IP address from interface Wifi. IP=192.168.178.36, Gateway=192.168.178.1, NetMask=255.255.255.0, Address was changed

I (5631) esp_netif_handlers: sta ip: 192.168.178.36, mask: 255.255.255.0, gw: 192.168.178.1

I (5641) esp_app_main: Network connected and mDNS initialized with squeezelite-738894

[00:00:04.228] raop_sink_start:178 starting Airplay for ip 192.168.178.36 with servicename ESP32-AirPlay-738894

[00:00:04.230] raop_create:201 starting mDNS with C8F09E738894@ESP32-AirPlay-738894

I (5671) cspot: starting Spotify on host squeezelite-738894

I (5681) wifi:AP's beacon interval = 102400 us, DTIM period = 1

[00:00:04.279] �[0;34mI �[0;95mShim.cpp:344: CSpot instance service name Squeezelite (id 142137fd329622137a1490160000003933849782)

[00:00:04.282] �[0;34mI �[0;95mShim.cpp:331: ZeroConf mode (port 80)

Trimmed Log

...
I (3091) network_handlers: Existing wifi config found. Attempting to connect.
I (3101) network: Starting DHCP client
I (3111) network_wifi: Wifi Connecting to HomeWifi...
...
I (5041) wifi:new:<6,0>, old:<1,0>, ap:<255,255>, sta:<6,0>, prof:1
I (5561) wifi:state: init -> auth (b0)
I (5561) wifi:state: auth -> init (8a0)
I (5561) wifi:new:<6,0>, old:<6,0>, ap:<255,255>, sta:<6,0>, prof:1
W (5571) network_wifi: WIFI_EVENT_STA_DISCONNECTED. From BSSID: b0:f2:08:d5:f1:6f, reason code: 202 (WIFI_REASON_AUTH_FAIL)
W (5581) wifi:Haven't to connect to a suitable AP now!
I (5591) network_wifi: Configuring Access Point.
I (5591) network: Stopping DHCP server
I (5591) network: Starting DHCP server
I (5601) network_wifi: AP SSID: squeezelite-738894
I (5601) network_wifi: AP Password: squeezelite
I (5611) wifi:mode : sta (c8:f0:9e:73:88:94) + softAP (c8:f0:9e:73:88:95)
I (5621) wifi:Total power save buffer number: 6
I (5621) wifi:Init max length of beacon: 752/752
I (5631) wifi:Init max length of beacon: 752/752
I (6151) wifi:Total power save buffer number: 6
I (6161) wifi:Total power save buffer number: 6
I (6161) wifi:Set ps type: 1
I (6161) network_wifi: Initiating wifi network scan

I (6161) dns_server: DNS Server listening on 53/udp

�[0;31mE (18111) network: network manager Unhandled Event NETWORK_WIFI_CONFIGURING_ACTIVE_STATE(WIFI_CONFIGURING_STATE) [EN_TIMER]
=======================================

==== MANUAL REBOOT VIA PUSHBUTTON ====
...

I (3091) network_handlers: Existing wifi config found. Attempting to connect.

I (3101) network: Starting DHCP client

I (3101) network_wifi: Wifi Connecting to HomeWifi...

...

I (5031) wifi:new:<6,0>, old:<1,0>, ap:<255,255>, sta:<6,0>, prof:1

I (5561) wifi:state: init -> auth (b0)

I (5561) wifi:state: auth -> assoc (0)

I (5571) wifi:state: assoc -> run (10)

I (5601) wifi:connected with HomeWifi, aid = 2, channel 6, BW20, bssid = b0:f2:08:d5:f1:6f

I (5601) wifi:security: WPA2-PSK, phy: bgn, rssi: -64

I (5611) wifi:pm start, type: 1
I (5621) network: Got an IP address from interface Wifi. IP=192.168.178.36, Gateway=192.168.178.1, NetMask=255.255.255.0, Address was changed

I (5631) esp_netif_handlers: sta ip: 192.168.178.36, mask: 255.255.255.0, gw: 192.168.178.1

I (5641) esp_app_main: Network connected and mDNS initialized with squeezelite-738894

...

Issue Description

1. Observed Behavior: When powering on, Wifi doesn't connect so it fails over to AP mode. When I restart the board via the reset pushbutton it successfully connects to my wifi on this second try
2. Expected Behavior: Connect sucessfully upon first try or at least try several times before failing to AP mode.
3. Steps to Reproduce: Flash latest version via web tool, boot to AP mode, configure everything, reboot.

[sle118]

@LeoSum8 please do not cross post. I've reopened issue #412. To maximize your chances of being responded there, you need to follow the guidelines when posting an issue. If you don't, then it's wasted time for everyone in the end.
https://github.com/sle118/squeezelite-esp32/issues/new?template=bug_report.md

You've done a good job on the current issue and this saves me a good amount of time when analyzing.

[sle118]

@LeoSum8 one thing I have noticed is that you have a conflicting setup:

You have defined the DAC i2c configuration correctly
"dac_config": "model=I2S,bck=26,ws=25,do=22,sda=21,scl=27,i2c=45"

This config would attempt to create a new i2c driver on the same GPIO but different port.
"i2c_config": "scl=27,sda=21,speed=400000,port=1",

Please remove it from the nvs.

Also, I have checked your logs and I suspect that your wifi issue is hardware related, or perhaps caused by something in your environment. This is revealed by the logs here

I (5561) wifi:state: init -> auth (b0)
I (5561) wifi:state: auth -> init (8a0)

when the wifi driver flips from init -> auth back to auth -> init. If you are able to find what the description of code 8a0 mean, then you might get some answers.

The typical sequence of wifi should be:

I (5561) wifi:state: init -> auth (b0)
I (5561) wifi:state: auth -> assoc (0)
I (5571) wifi:state: assoc -> run (10)

I doubt we can do anything for this issue in our code, so for now I'll go ahead and close the issue.

You could also check your power supply. for example do you get the same issue if you plug the wrover in a different power supply, if you disconnect it from the Louder board, etc.

[sle118]

I'll leave the issue open for a couple of days so you can find it easily.

[LeoSum8]

Hi Sébastien,
sorry if my report caused additional work. I do not mean to waste anybody's time, especially not the time of people who create such great things as sqeezelite-esp32 in their spare time.

However, I am a bit confused. I did not open issue #412. It was opened only after I posted here the additional comment concerning my "ESP_ERR_NVS_KEY_TOO_LONG" find in the logs as I sincerely believed that it was related. But this comment is not visible here any more.

I will be able to do further test and debugging hopefully on Wednesday.

[sle118]

Not worries for the missing info. I want to help as much as possible given my availability and this means I'm not always in front of a computer where I can more easily navigate.

I deleted the "key too long" comment as it was not related to this issue and also because I reopened the other issue where you can add more details. I'm curious to understand how this might happen.

As for the current issue #410, I doubt I'll be able to help

[LeoSum8]

Thank you for checking my logs!

The I (5561) wifi:state: auth -> init (8a0) issue can be found on google and I will try to investigate further how that happens. I'll also watch the bahaviour on different firmwares (snapclient, euphonium) and check with and without the dock attached.

But just to get this off my chest, the incomplete issue #412 was not submitted by me but by @DamnDaniel-98.
I think you thought it was me because it was submitted around the same time with the same content.
I never submit with missing info! ;)

[LeoSum8]

So I just checked if the same behaviour occurs with another firmware (euphonium). It does, but somehow it is caught.
Here is an excerpt from the boot sequence of euphonium:

D [core] Core.cpp:187: EventBus message received
I [core] Core.cpp:268: Connecting to HomeWifi
I (4509) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (4689) wifi:state: init -> auth (b0)
I (4689) wifi:state: auth -> init (8a0)
I (4699) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
E [ESP32Connectivity] ESP32Connectivity.cpp:334: WiFi connection retry, attempt #1
E [ESP32Connectivity] ESP32Connectivity.cpp:334: WiFi connection retry, attempt #2
I (9529) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (9529) wifi:state: init -> auth (b0)
I (9539) wifi:state: auth -> assoc (0)
I (9539) wifi:state: assoc -> run (10)
I (9569) wifi:connected with HomeWifi, aid = 4, channel 1, BW20, bssid = b0:f2:08:d5:f1:6f
I (9569) wifi:security: WPA2-PSK, phy: bgn, rssi: -57
I (9669) wifi:pm start, type: 1

I (9669) wifi:dp: 1, bi: 102400, li: 3, scale listen interval from 307200 us to 307200 us
I (9669) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (9689) wifi:<ba-add>idx:0 (ifx:0, b0:f2:08:d5:f1:6f), tid:6, ssn:2, winSize:64
I (10689) esp_netif_handlers: sta ip: 192.168.178.36, mask: 255.255.255.0, gw: 192.168.178.1
I [ESP32Connectivity] ESP32Connectivity.cpp:312: Connected, ip addr 192.168.178.36
I (10699) mdns_networking: _mdns_pcb_init(tcpip_if=0, ip_protocol=0)
I (10699) mdns_networking: _mdns_pcb_init(tcpip_if=1, ip_protocol=0)
E (10719) mdns_networking: [sock=55] Failed to set IP_ADD_MEMBERSHIP. errno=125: Address not available
E (10729) mdns_networking: Failed to add ipv6 multicast group for protocol 0
I [ESP32Connectivity] ESP32Connectivity.cpp:99: Writing WiFi configuration to NVS storage...

[sle118]

Thank you for checking my logs!

The I (5561) wifi:state: auth -> init (8a0) issue can be found on google and I will try to investigate further how that happens. I'll also watch the bahaviour on different firmwares (snapclient, euphonium) and check with and without the dock attached.

But just to get this off my chest, the incomplete issue #412 was not submitted by me but by @DamnDaniel-98. I think you thought it was me because it was submitted around the same time with the same content. I never submit with missing info! ;)

I do apologize for the mistake and I think you are right. I am not too close #412 anyways since I cannot reproduce.

[sle118]

So I just checked if the same behaviour occurs with another firmware (euphonium). It does, but somehow it is caught. Here is an excerpt from the boot sequence of euphonium:

D [core] Core.cpp:187: EventBus message received
I [core] Core.cpp:268: Connecting to HomeWifi
I (4509) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (4689) wifi:state: init -> auth (b0)
I (4689) wifi:state: auth -> init (8a0)
I (4699) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
E [ESP32Connectivity] ESP32Connectivity.cpp:334: WiFi connection retry, attempt #1
E [ESP32Connectivity] ESP32Connectivity.cpp:334: WiFi connection retry, attempt #2
I (9529) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (9529) wifi:state: init -> auth (b0)
I (9539) wifi:state: auth -> assoc (0)
I (9539) wifi:state: assoc -> run (10)
I (9569) wifi:connected with HomeWifi, aid = 4, channel 1, BW20, bssid = b0:f2:08:d5:f1:6f
I (9569) wifi:security: WPA2-PSK, phy: bgn, rssi: -57
I (9669) wifi:pm start, type: 1

I (9669) wifi:dp: 1, bi: 102400, li: 3, scale listen interval from 307200 us to 307200 us
I (9669) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (9689) wifi:<ba-add>idx:0 (ifx:0, b0:f2:08:d5:f1:6f), tid:6, ssn:2, winSize:64
I (10689) esp_netif_handlers: sta ip: 192.168.178.36, mask: 255.255.255.0, gw: 192.168.178.1
I [ESP32Connectivity] ESP32Connectivity.cpp:312: Connected, ip addr 192.168.178.36
I (10699) mdns_networking: _mdns_pcb_init(tcpip_if=0, ip_protocol=0)
I (10699) mdns_networking: _mdns_pcb_init(tcpip_if=1, ip_protocol=0)
E (10719) mdns_networking: [sock=55] Failed to set IP_ADD_MEMBERSHIP. errno=125: Address not available
E (10729) mdns_networking: Failed to add ipv6 multicast group for protocol 0
I [ESP32Connectivity] ESP32Connectivity.cpp:99: Writing WiFi configuration to NVS storage...

I will see what I can do. The system could probably try a couple of times on (WIFI_REASON_AUTH_FAIL) before jumping to access point mode. I don't want to invest too much time on this version (a refactoring is in progress) but since it will improve stability of this release, it is worth the effort.

Thanks for the finding

[LeoSum8]

Thank you for taking the time for this edge case. A couple of retries should definitely help me.

When trying to find out what (8a0) means, as you suggested, I did find a couple of mentions. Could be a problem with the combination of certain ESP32 boards, the AVM Fritz!Box routers (very common in Germany) and signal strength.

The reason code 202 (AUTH_FAIL) is not very helpful: "Espressif-specific Wi-Fi reason code: the authentication fails, but not because of a timeout."

[sle118]

Thank you for taking the time for this edge case. A couple of retries should definitely help me.

When trying to find out what (8a0) means, as you suggested, I did find a couple of mentions. Could be a problem with the combination of certain ESP32 boards, the AVM Fritz!Box routers (very common in Germany) and signal strength.

The reason code 202 (AUTH_FAIL) is not very helpful: "Espressif-specific Wi-Fi reason code: the authentication fails, but not because of a timeout."

Given how other projects have delt with this, it might not be that much of an edge case

[DAONEW]

Hi @LeoSum8 ,

I had a very similar problem after changing my Fritz!Box to the 7530. My squeezelite-esp32 clients were disconnecting all the time. The 8a0 was shown in my logs too.

For me disabling the Package acceleration did the trick. They are not disconnecting anymore - as far as I can see.
(Strangely I also had another issue changing to the new AP at all. For some other reason the squeezelite would not change the new AP even though it would successfully login. I had to reflash the firmware completely and thereby resetting the AP internal variables. Now, it accepted the new AP login.)

PS: thank you for this great project btw!