HTTP server handler sends wrong events and panics

[giomf]

Hello everyone,

I have observed a strange behavior of the http server. I'm not quite sure if it's my fault as this is my first esp project.
I have a simple project which should realize ota over a http server. I have a wifi service that connects in STA mode on my network. Additionally I listen for wifi events to reconnect if necessary. I also have an /update handler that accepts a firmware file and then installs it via the ota server. Here is the stripped down code:

mod base36;

use anyhow::{Context, Result};
use core::convert::TryInto;
use embedded_svc::{
    http::{Headers, Method},
    wifi::{self, AuthMethod, ClientConfiguration},
};
use esp_idf_svc::{
    eventloop::EspSystemEventLoop,
    hal::{prelude::Peripherals, task::block_on},
    http::server::{self, EspHttpServer},
    mdns::EspMdns,
    nvs::EspDefaultNvsPartition,
    timer::EspTaskTimerService,
    wifi::{AsyncWifi, EspWifi, WifiEvent},
};

const SSID: &str = env!("WIFI_SSID");
const PASSWORD: &str = env!("WIFI_PASS");
const OTA_PARTITION_SIZE: usize = 0x1f0000;
const OTA_CHNUNK_SIZE: usize = 1024 * 20;
const HTTP_STACK_SIZE: usize = 1024 * 30;

fn main() -> Result<()> {
    esp_idf_svc::sys::link_patches();
    esp_idf_svc::log::EspLogger::initialize_default();

    let peripherals = Peripherals::take()?;
    let event_loop = EspSystemEventLoop::take()?;
    let nvs = EspDefaultNvsPartition::take()?;
    let wifi_driver = EspWifi::new(peripherals.modem, event_loop.clone(), Some(nvs))
        .context("Failed to create wifi driver")?;
    let _http_server = http_server_init().context("Failed to intialize http server")?;

    block_on(async move {
        let mut wifi = wifi_init(wifi_driver, event_loop.clone())
            .await
            .context("Failed to initialize wifi")
            .unwrap();
        let mut wifi_subscription = event_loop.subscribe_async::<WifiEvent>().unwrap();

        loop {
            let event = wifi_subscription.recv().await.unwrap();
            log::error!("Wifi event: {:#?}", event);
         }
    });

    Ok(())
}

async fn wifi_init<'a>(
    wifi_driver: EspWifi<'a>,
    event_loop: EspSystemEventLoop,
) -> Result<AsyncWifi<EspWifi<'a>>> {
    let timer_service = EspTaskTimerService::new()?;
    let mut wifi = AsyncWifi::wrap(wifi_driver, event_loop.clone(), timer_service)?;
    let wifi_configuration = wifi::Configuration::Client(ClientConfiguration {
        ssid: SSID.try_into().unwrap(),
        auth_method: AuthMethod::WPA2Personal,
        password: PASSWORD.try_into().unwrap(),
        channel: None,
        ..Default::default()
    });

    wifi.set_configuration(&wifi_configuration)?;
    wifi.start().await?;

    while let Err(err) = wifi.connect().await {
        log::error!("Error connecting to wifi {err}! Retrying.");
    }

    wifi.wait_netif_up().await?;
    Ok(wifi)
}

fn http_server_init() -> Result<EspHttpServer<'static>> {
    let configuration = server::Configuration {
        stack_size: HTTP_STACK_SIZE,
        ..Default::default()
    };
    let mut server = EspHttpServer::new(&configuration)?;
    server.fn_handler::<anyhow::Error, _>("/update", Method::Post, |mut request| {
        log::info!("Starting updater");
        let firmware_size = request.content_len().unwrap_or(0) as usize;
        let mut buffer = vec![0; OTA_CHNUNK_SIZE];
        let mut total_bytes_read: usize = 0;

        log::info!("Start uploading. Expect {firmware_size} bytes");
        loop {
            log::debug!("Read {total_bytes_read}/{firmware_size} bytes");
            let bytes_read = request.read(&mut buffer).unwrap_or_default();
            total_bytes_read += bytes_read;
             if total_bytes_read >= firmware_size {
                 break;
             }
        }

        request.into_ok_response()?.write("".as_bytes())?;
        Ok(())
    })?;

    Ok(server)
}

The error I have observed is that StaDisconnected events are thrown when the handler processes the request buffer. Here is some snipit frm it:

E (29238) esp: Wifi event: StaDisconnected
D (29528) httpd_txrx: httpd_recv_with_opt: received length = 4320
D (29528) httpd_txrx: httpd_req_recv: received length = 4320
D (29528) event: running post ESP_HTTP_SERVER_EVENT:5 with handler 0x4200b21c and context 0x3fcb12b8 on loop 0x3fc9c4b0
0x4200b21c - esp_idf_svc::eventloop::EspSubscription<T>::handle
    at /home/guif/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp-idf-svc-0.49.1/src/eventloop.rs:354
D (29538) esp: Read 1242595/1302640 bytes
D (29538) httpd_txrx: httpd_req_recv: remaining length = 60045
D (29548) httpd_txrx: httpd_recv_with_opt: requested length = 20480
D (29558) httpd_txrx: httpd_recv_with_opt: received length = 4320
D (29558) httpd_txrx: httpd_req_recv: received length = 4320
D (29568) esp: Read 1246915/1302640 bytes
D (29568) httpd_txrx: httpd_req_recv: remaining length = 55725
D (29578) httpd_txrx: httpd_recv_with_opt: requested length = 20480
D (29578) httpd_txrx: httpd_recv_with_opt: received length = 5760
D (29588) httpd_txrx: httpd_req_recv: received length = 5760
D (29598) esp: Read 1252675/1302640 bytes
D (29598) httpd_txrx: httpd_req_recv: remaining length = 49965
D (29598) httpd_txrx: httpd_recv_with_opt: requested length = 20480
E (29608) esp: Wifi event: StaDisconnected
D (29618) event: running post ESP_HTTP_SERVER_EVENT:5 with handler 0x4200b21c and context 0x3fcb12b8 on loop 0x3fc9c4b0
0x4200b21c - esp_idf_svc::eventloop::EspSubscription<T>::handle
    at /home/guif/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp-idf-svc-0.49.1/src/eventloop.rs:354
D (29628) httpd_txrx: httpd_recv_with_opt: received length = 5760
D (29628) httpd_txrx: httpd_req_recv: received length = 5760
D (29638) esp: Read 1258435/1302640 bytes
D (29638) httpd_txrx: httpd_req_recv: remaining length = 44205
D (29648) httpd_txrx: httpd_recv_with_opt: requested length = 20480
D (29658) httpd_txrx: httpd_recv_with_opt: received length = 5760
D (29658) httpd_txrx: httpd_req_recv: received length = 5760
D (29668) esp: Read 1264195/1302640 bytes
D (29668) httpd_txrx: httpd_req_recv: remaining length = 38445
D (29678) httpd_txrx: httpd_recv_with_opt: requested length = 20480
E (29678) esp: Wifi event: StaDisconnected

After many many of the above logs the application crashes with:

0x4200b21c - esp_idf_svc::eventloop::EspSubscription<T>::handle
    at /home/guif/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp-idf-svc-0.49.1/src/eventloop.rs:354
thread 'main' panicked at /home/guif/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp-idf-svc-0.49.1/src/wifi.rs:2129:40:
range end index 57 out of range for slice of length 3
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

To summarize, the http handler sends wifi events for some reason and ends up crashing. Does anyone have any idea what I'm doing wrong or if it's actually a bug?

[ivmarkov]

What is the ESP IDF version you are compiling against?

[giomf]

Ah yes forgot about this.

esp-idf-svc: v0.49.1
esp-idf: v5.2.2
cargo 1.84.0-nightly (4a2d8dc63 2024-11-09)

[ivmarkov]

That's very weird. Where it breaks it should absolutely not break or else ESP IDF has a bug (which I doubt).

Can you increase the system events' task size? You might have a stack smashing case that goes undetected by FreeRTOS...

[giomf]

Yes, for sure.
Could you point me in the right direction how to do it.
I found this. Do you mean CONFIG_ESP_MAIN_TASK_STACK_SIZE?'

Edit: I think you meant this one: CONFIG_ESP_SYSTEM_EVENT_TASK_STACK_SIZE

[giomf]

So I have increased CONFIG_ESP_SYSTEM_EVENT_TASK_STACK_SIZE to 10000 but it is still the same.
The whole crash can be seen here.

I (13258) esp: Starting updater
I (13258) esp: Start uploading. Expect 20000 bytes
D (13268) esp: Read 0/20000 bytes
D (13268) httpd_txrx: httpd_req_recv: remaining length = 20000
D (13278) httpd_txrx: httpd_recv_with_opt: requested length = 10240
D (13278) httpd_txrx: httpd_recv_with_opt: pending length = 5
D (13288) httpd_txrx: httpd_recv_with_opt: received length = 5637
D (13298) httpd_txrx: httpd_req_recv: received length = 5637
D (13298) esp: Read 5637/20000 bytes
D (13308) httpd_txrx: httpd_req_recv: remaining length = 14363
D (13308) httpd_txrx: httpd_recv_with_opt: requested length = 10240
E (13318) esp: Wifi event: StaStarted
D (13318) httpd_txrx: httpd_recv_with_opt: received length = 4320
D (13328) httpd_txrx: httpd_req_recv: received length = 4320
D (13338) esp: Read 9957/20000 bytes
D (13338) httpd_txrx: httpd_req_recv: remaining length = 10043
D (13338) httpd_txrx: httpd_recv_with_opt: requested length = 10043
D (13348) httpd_txrx: httpd_recv_with_opt: received length = 1440
D (13358) httpd_txrx: httpd_req_recv: received length = 1440
D (13358) esp: Read 11397/20000 bytes
D (13358) httpd_txrx: httpd_req_recv: remaining length = 8603
D (13368) httpd_txrx: httpd_recv_with_opt: requested length = 8603
D (13378) httpd_txrx: httpd_recv_with_opt: received length = 5760
D (13378) httpd_txrx: httpd_req_recv: received length = 5760
D (13388) esp: Read 17157/20000 bytes
D (13388) httpd_txrx: httpd_req_recv: remaining length = 2843
D (13398) httpd_txrx: httpd_recv_with_opt: requested length = 2843
D (13408) httpd_txrx: httpd_recv_with_opt: received length = 2843
D (13408) httpd_txrx: httpd_req_recv: received length = 2843
D (13418) httpd_txrx: httpd_send_all: sent = 61
D (13418) httpd_txrx: httpd_send_all: sent = 2
D (13418) httpd_sess: httpd_sess_process: httpd_req_delete
D (13428) httpd_sess: httpd_sess_process: success
D (13438) httpd: httpd_server: doing select maxfd+1 = 58
D (13438) event: running post ESP_HTTP_SERVER_EVENT:3 with handler 0x4200b21c and context 0x3fcb157c on loop 0x3fc9c4b0
D (13448) httpd: httpd_process_session: processing socket 57
D (13458) httpd_sess: httpd_sess_process: httpd_req_new
D (13458) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (13468) httpd_txrx: httpd_recv_with_opt: received length = 0
D (13468) httpd_parse: read_block: connection closed
D (13478) httpd_sess: httpd_sess_delete: fd = 57
D (13488) httpd_sess: httpd_sess_delete: active sockets: 0
D (13488) httpd: httpd_server: doing select maxfd+1 = 56
E (13498) esp: Wifi event: StaStopped
D (13498) event: running post ESP_HTTP_SERVER_EVENT:5 with handler 0x4200b21c and context 0x3fcb157c on loop 0x3fc9c4b0
E (13508) esp: Wifi event: StaDisconnected
D (13518) event: running post ESP_HTTP_SERVER_EVENT:5 with handler 0x4200b21c and context 0x3fcb157c on loop 0x3fc9c4b0
E (13528) esp: Wifi event: StaDisconnected
D (13528) event: running post ESP_HTTP_SERVER_EVENT:5 with handler 0x4200b21c and context 0x3fcb157c on loop 0x3fc9c4b0
E (13538) esp: Wifi event: StaDisconnected
D (13548) event: running post ESP_HTTP_SERVER_EVENT:5 with handler 0x4200b21c and context 0x3fcb157c on loop 0x3fc9c4b0
E (13558) esp: Wifi event: StaDisconnected
D (13558) event: running post ESP_HTTP_SERVER_EVENT:5 with handler 0x4200b21c and context 0x3fcb157c on loop 0x3fc9c4b0
E (13568) esp: Wifi event: StaDisconnected
D (13578) event: running post ESP_HTTP_SERVER_EVENT:4 with handler 0x4200b21c and context 0x3fcb157c on loop 0x3fc9c4b0
E (13588) esp: Wifi event: StaConnected
D (13588) event: running post ESP_HTTP_SERVER_EVENT:6 with handler 0x4200b21c and context 0x3fcb157c on loop 0x3fc9c4b0
E (13598) esp: Wifi event: StaAuthmodeChanged
D (13608) event: running post ESP_HTTP_SERVER_EVENT:7 with handler 0x4200b21c and context 0x3fcb157c on loop 0x3fc9c4b0
thread 'main' panicked at /home/guif/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp-idf-svc-0.49.1/src/wifi.rs:2129:40:
range end index 57 out of range for slice of length 3
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

abort() was called at PC 0x4203fbd1 on core 0
Core  0 register dump:
MEPC    : 0x4038164e  RA      : 0x40385520  SP      : 0x3fc9aee0  GP      : 0x3fc91400
TP      : 0x3fc539a8  T0      : 0x37363534  T1      : 0x7271706f  T2      : 0x33323130
S0/FP   : 0x3fc9af1c  S1      : 0x3fc9af1c  A0      : 0x3fc9af1c  A1      : 0x3fc9aefe
A2      : 0x00000000  A3      : 0x3fc9af49  A4      : 0x00000001  A5      : 0x3fc97000
A6      : 0x7a797877  A7      : 0x76757473  S2      : 0x3fc9af00  S3      : 0x00000000
S4      : 0x3fc9b018  S5      : 0x3fc93708  S6      : 0x00000000  S7      : 0x00000003
S8      : 0x3fc9b124  S9      : 0x00000000  S10     : 0x3fc974ac  S11     : 0x00000002
T3      : 0x6e6d6c6b  T4      : 0x6a696867  T5      : 0x66656463  T6      : 0x62613938
MSTATUS : 0x00001801  MTVEC   : 0x40380001  MCAUSE  : 0x00000007  MTVAL   : 0x00000000
MHARTID : 0x00000000

Stack memory:
3fc9aee0: 0x3fc974b4 0x3fc9af6c 0x3fc9af1c 0x4038c81c 0x00000004 0x3c0ece10 0x3c0f2e04 0x00000030
3fc9af00: 0x33303234 0x31646266 0x00000000 0x3fc92ea8 0x3fc9af00 0x3fc92ec4 0x3fc9aefc 0x726f6261
3fc9af20: 0x20292874 0x20736177 0x6c6c6163 0x61206465 0x43502074 0x34783020 0x66333032 0x20316462
3fc9af40: 0x63206e6f 0x2065726f 0x00000030 0x02cb0000 0x00000001 0x3c0ece10 0x3c0e3cc8 0x4203fbd4
3fc9af60: 0x3fc936d8 0x3c0e0820 0x3fc90c3c 0x4203bd96 0x3fc9af50 0x3fc9af54 0x00000000 0x42038e60
3fc9af80: 0x00000001 0x3c0ece10 0x3fcb1ea4 0x4203b96e 0x00000009 0x3c0ece10 0x3c0e3cc8 0x420277ce
3fc9afa0: 0x3fc539a8 0x4204c95c 0x40381c46 0x3fc9b018 0x3c0ece10 0x3c0e3cc8 0x00000001 0x00000001
3fc9afc0: 0x3fc97000 0x3fc97000 0x00000000 0x600c2194 0x3fcb1500 0x3fcb151c 0x3fc9b018 0x3c0f2edc
3fc9afe0: 0x3c0e3cc8 0x00000001 0x3fcb1370 0x00000003 0x3fc9b124 0x3b9aca00 0x00000001 0x00000004
3fc9b000: 0x00000000 0x3fc9ef78 0x3fc9b034 0x4201a792 0x3fc9b4d4 0x00000001 0x00000040 0x3fcb11c4
3fc9b020: 0x00000035 0x3fc9b034 0x3fc9b45c 0x4201a656 0x00000000 0x3fc9b058 0x3c0e3cc8 0x3fc9b044
3fc9b040: 0x00000000 0x3fc9b058 0x3c0e3cc8 0x00000001 0x00000039 0x00000003 0x3c0ffd40 0x00000002
3fc9b060: 0x3fc9b070 0x00000002 0x00000000 0x00000004 0x3fc9b050 0x4205288a 0x3fc9b054 0x4205288a
3fc9b080: 0x00000000 0x00000007 0x3fcb151c 0x4200159a 0x00000000 0x00000000 0x3fcb153c 0x42054dbe
3fc9b0a0: 0x00000000 0x3fc9ef78 0x3fcb151c 0x4200123a 0x3fc9b0bc 0x3fcb08b8 0x00000000 0x3fc9f1e4
3fc9b0c0: 0x3fca8f00 0x3fca8f44 0x3c10d424 0x0000000b 0xffffffff 0x3fca8ed0 0x3fc9f3d8 0x3fcaa448
3fc9b0e0: 0x3fcaa290 0x3fc9f1e4 0xa5a5a504 0x00000000 0x3fc9f1e4 0x3fcb1e8c 0x3fcb158c 0x00000000
3fc9b100: 0x00000009 0xffffffff 0x3fcb151c 0x3fcb1501 0x00000000 0x3fc9f1e4 0x3fca8f00 0x3fca8f44
3fc9b120: 0x3c10d424 0x0000000b 0xffffffff 0x3fca8ed0 0x3fc9f3d8 0x3fcaa448 0x3fcaa290 0x3fc9f1e4
3fc9b140: 0x3fc9b0ec 0x3fc9b0ec 0x3fc9b108 0x3fcb151c 0x3fcb151c 0x3fcb1524 0x20746f01 0x40373400
3fc9b160: 0x00000000 0x00000000 0x3fcb08b8 0x4201360a 0x3fc9f1e4 0x0000000b 0x39696245 0x35696978
3fc9b180: 0x00000004 0x3fc9f1e4 0x00000000 0x3fc9b45c 0x4201436a 0x00001800 0x73746f48 0x20746f70
3fc9b1a0: 0x40373432 0x00000000 0x00000000 0x3fcb08b8 0x4201360a 0x3fc9f1e4 0x00000008 0x00020003
3fc9b1c0: 0x3fcb0810 0xa5000003 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5 0xa5a5a5a5
3fc9b1e0: 0x4004c0d8 0x400481c4 0x3fc9b730 0x3fc91400 0x3fc539a8 0x4005890e 0x00000000 0xffffffff
3fc9b200: 0x0000006e 0x00000008 0x00000000 0x0000006e 0x0000002e 0x6000001c 0x3fc9b7f8 0xc0380000
3fc9b220: 0x00000000 0x3fc97000 0x00060000 0xc0380000 0x00000000 0x03c97000 0x00060001 0xc0380000
3fc9b240: 0x0000000f 0x00000000 0x00000000 0x00000000 0x00000000 0x3fc9f1e4 0x3fcb1e8c 0x3fcb1540
3fc9b260: 0x3c10c198 0x00000009 0xffffffff 0x3fcb08c8 0x3fcb15a8 0x3c0e129c 0x3fcb10f0 0x3fcb157c
3fc9b280: 0x0000000f 0x00000000 0x00000000 0x00000000 0x3fc9b2f5 0x3fc9b124 0x3fc9b250 0x3fc9b2f5
3fc9b2a0: 0x3fc9b124 0x3fc9b26c 0x3fcb08d0 0x00000001 0x00001801 0x0000000c 0x0000000f 0x00000000
3fc9b2c0: 0x00000000 0x3fc9b7bc 0x3fc9b270 0x3fcb1584 0x00000003 0x00000000 0x3fc9b29c 0x00000000