panic_abort when connecting to wifi with logger enabled

[usbalbin]

Hi!

I found that when connecting to a wifi and having logging enabled things go wrong.

assert failed: spinlock_acquire spinlock.h:122 (result == core_id || result == SPINLOCK_FREE)
Backtrace:0x40081bb6 [panic_abort:/home/decahe/iot/.embuild/espressif/esp-idf/release-v4.4/components/esp_system/panic.c:402]:0x3ffbd4b00x40087d49 [esp_system_abort:/home/decahe/iot/.embuild/espressif/esp-idf/release-v4.4/components/esp_system/esp_system.c:128]:0x3ffbd4d0 0x4008e165 [__assert_func:/home/decahe/iot/.embuild/espressif/esp-idf/release-v4.4/components/newlib/assert.c:85]:0x3ffbd4f0 0x4008aaa3 [spinlock_acquire:/home/decahe/iot/.embuild/espressif/esp-idf/release-v4.4/components/esp_hw_support/include/soc/spinlock.h:122]:0x3ffbd610 0x400887a1 [vPortEnterCritical:/home/decahe/iot/.embuild/espressif/esp-idf/release-v4.4/components/freertos/port/xtensa/include/freertos/portmacro.h:578]:0x3ffbd630 0x4008891d [xQueueGiveMutexRecursive:/home/decahe/iot/.embuild/espressif/esp-idf/release-v4.4/components/freertos/queue.c:685]:0x3ffbd670 0x4016c32d [esp_event_loop_run:/home/decahe/iot/.embuild/espressif/esp-idf/release-v4.4/components/esp_event/esp_event.c:628]:0x3ffbd690 0x4016c340 [esp_event_loop_run_task:/home/decahe/iot/.embuild/espressif/esp-idf/release-v4.4/components/esp_event/esp_event.c:115]:0x3ffbd6e0 

Output with logging Output without logging

Am I missing something or is this a bug?

use embedded_svc::httpd::{Request, Response};
use embedded_svc::ipv4;
use embedded_svc::storage::Storage;
use embedded_svc::wifi::{
    AuthMethod, Wifi,
};
use std::collections::HashMap;
use std::sync::{Arc, Mutex};

use embedded_hal::can::nb::Can;
use embedded_hal::delay::blocking::DelayUs;
use embedded_hal::nb;
use embedded_svc::wifi;
use esp_idf_hal::can::{self, CAN};
use esp_idf_hal::delay::FreeRtos;
use esp_idf_hal::gpio::{InputPin, OutputPin};
use esp_idf_svc::{netif, nvs, nvs_storage, sysloop, wifi as esp_wifi};
use esp_idf_sys::{self as _, EspError}; // If using the `binstart` feature of `esp-idf-sys`, always keep this module imported
use unwrap_infallible::UnwrapInfallible;

static HOSTNAME: &str = "thing-123";

fn main() -> Result<(), EspError> {
    esp_idf_sys::link_patches();

    esp_idf_svc::log::EspLogger::initialize_default(); // Everything is fine when removing this line

    let wifi_interface =
        Arc::new(netif::EspNetifStack::new().unwrap());
    let system_loop =
        Arc::new(sysloop::EspSysLoopStack::new().unwrap());
    let storage = Arc::new(
        nvs::EspDefaultNvs::new().unwrap(),
    );
    let mut wifi = esp_wifi::EspWifi::new(wifi_interface, system_loop, Arc::clone(&storage))
        .unwrap();

    wifi.set_configuration(&wifi::Configuration::Client(wifi::ClientConfiguration{
        ssid: String::from("some SSID"),
        password: String::from("the password"),
        auth_method: AuthMethod::WPA2Personal,
        ip_conf: Some(ipv4::ClientConfiguration::DHCP(ipv4::DHCPClientSettings{ hostname: Some(String::from(HOSTNAME))})),
        ..Default::default()
    })).unwrap();

    loop {
        println!("{:?}", wifi.get_status());
        FreeRtos.delay_ms(1000).unwrap_infallible();
    }
}

$ git log

commit aaad3f5ce8749fd1996cdb2842a4de47a0a8e053 (HEAD -> master, upstream/master)
Merge: 1e66deff 7500afac
Author: Scott Mabin <[email protected]>
Date:   Wed May 4 14:21:00 2022 +0200

    Merge pull request #72 from bakery/http-client-buffer-size-tx

    Add support for buffer_size_tx config option in HTTP Client

[ivmarkov]

I don't think the root cause of this problem is logging. It might be that logging is triggering some sort of timing issue, that the no-logging code does not, but other than this I can't find a relation between logging and your problem.

By the way, this looks very strange, it is the first time I see these messages - perhaps you want to check what is causing those:

I (5268) wifi:state: assoc -> assoc (0)
E (5278) wifi:Association refused temporarily, comeback time 0 mSec
I (5278) wifi:state: assoc -> assoc (0)
E (5288) wifi:Association refused temporarily, comeback time 0 mSec
I (5288) wifi:state: assoc -> assoc (0)
E (5298) wifi:Association refused temporarily, comeback time 0 mSec
I (5298) wifi:state: assoc -> assoc (0)

[CyanBlob]

Did you ever figure this out? I'm having the same spinlock error

[MabezDev]

I read through some esp-idf issues, some mentioned that it's possible a task migrated core when it shouldn't have. Does this still happen with CONFIG_FREERTOS_UNICORE=y inside sdkconfig?

[CyanBlob]

The issue went away at some point while I was refactoring, so I'm still not sure what the cause was. If I run into it again I'll try that config change. Thanks!

[MabezDev]

If this was on an S3 it could be related to this: https://github.com/espressif/esp-idf/issues/9120.

[usbalbin]

My error is on an ESP32 (not s3 or anything else)

[ivmarkov]

@usbalbin Is this still happening for you?

[usbalbin]

I will try to test this, hopefully soonish...