Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

ERROR - RX QUEUE FULL #291

Closed
galah92 opened this issue Oct 17, 2023 · 13 comments
Closed

ERROR - RX QUEUE FULL #291

galah92 opened this issue Oct 17, 2023 · 13 comments

Comments

@galah92
Copy link

galah92 commented Oct 17, 2023

Consider the following code:

#![no_std]
#![no_main]

use embedded_svc::wifi::{ClientConfiguration, Configuration, Wifi};
use esp_backtrace as _;
use esp_println::println;
use esp_wifi::wifi::WifiMode;
use esp_wifi::{initialize, EspWifiInitFor};
use hal::{clock::ClockControl, peripherals::Peripherals, prelude::*, Delay, IO};
use hal::{systimer::SystemTimer, Rng};

#[entry]
fn main() -> ! {
    let peripherals = Peripherals::take();
    let system = peripherals.SYSTEM.split();
    let clocks = ClockControl::max(system.clock_control).freeze();
    let mut delay = Delay::new(&clocks);

    // setup logger
    // To change the log_level change the env section in .cargo/config.toml
    // or remove it and set ESP_LOGLEVEL manually before running cargo run
    // this requires a clean rebuild because of https://github.com/rust-lang/cargo/issues/10358
    esp_println::logger::init_logger_from_env();
    log::info!("Logger is setup");

    println!("Hello world!");

    let timer = SystemTimer::new(peripherals.SYSTIMER).alarm0;
    let init = initialize(
        EspWifiInitFor::Wifi,
        timer,
        Rng::new(peripherals.RNG),
        system.radio_clock_control,
        &clocks,
    )
    .unwrap();

    let (wifi, _) = peripherals.RADIO.split();
    let (_wifi_interface, mut controller) =
        esp_wifi::wifi::new_with_mode(&init, wifi, WifiMode::Sta).unwrap();
    println!("Device capabilities: {:?}", controller.get_capabilities());

    const SSID: &str = env!("SSID");
    const PASSWORD: &str = env!("PASSWORD");
    let client_config = Configuration::Client(ClientConfiguration {
        ssid: SSID.into(),
        password: PASSWORD.into(),
        ..Default::default()
    });
    println!("Setting configuration: {:?}", &client_config);
    controller.set_configuration(&client_config).unwrap();
    controller.start().unwrap();
    println!("Wifi started: {}", controller.is_started().unwrap());
    controller.connect().unwrap();

    // Set GPIO7 as an output, and set its state high initially.
    let io = IO::new(peripherals.GPIO, peripherals.IO_MUX);
    let button = io.pins.gpio9.into_pull_up_input();
    let mut led = io.pins.gpio7.into_push_pull_output();
    led.set_high().unwrap();

    let mut i = 0;
    loop {
        if button.is_high().unwrap() {
            println!("Loop... {} {:?}", i, controller.is_connected());
            led.toggle().unwrap();
        }
        i += 1;
        delay.delay_ms(500u32);
    }
}

I'm using ESP32-C3, and getting bombard with these logs:

Loop... 251 Ok(true)
Loop... 252 Ok(true)
Loop... 253 Ok(true)
Loop... 254 Ok(true)
ERROR - RX QUEUE FULL
Loop... 255 Ok(true)
ERROR - RX QUEUE FULL
ERROR - RX QUEUE FULL
Loop... 256 Ok(true)
ERROR - RX QUEUE FULL
Loop... 257 Ok(true)
ERROR - RX QUEUE FULL
ERROR - RX QUEUE FULL
ERROR - RX QUEUE FULL
Loop... 258 Ok(true)
ERROR - RX QUEUE FULL
ERROR - RX QUEUE FULL
Loop... 259 Ok(true)
ERROR - RX QUEUE FULL
ERROR - RX QUEUE FULL

Is this a legitimate behavior? If yes, how can I silent these logs? It no, what can be done?

Thanks
@bjoernQ
Copy link
Contributor

bjoernQ commented Oct 17, 2023

That should probably get logged as WARN not ERROR. Besides that, you should be able to get rid of all the logs by configurating the logger accordingly or not configuring the logger at all.

It's also possible to configure the queue size and other options: https://github.com/esp-rs/esp-wifi/blob/main/docs/tuning.md

@bugadani
Copy link
Contributor

bugadani commented Oct 17, 2023 •
edited
Loading

I think it's fine for this to be an error. In my experience things rarely recover if the firmware hits this more than once in a while. I'd advise agains just hiding the pain; tuning the queue sizes may be a good way to reduce them.

@galah92
Copy link
Author

galah92 commented Oct 17, 2023

I see. The default rx_queue_size is 5, what's the best way to tweak it?

@bugadani
Copy link
Contributor

I set it to 15 for my project. I'm still not satisfied with how my wifi works but at least it's reasonably stable :)

@galah92
Copy link
Author

galah92 commented Oct 19, 2023

With 15 the ESP disconnect after a couple's seconds run:

I (43) boot: ESP-IDF v5.1-beta1-378-gea5e0ff298-dirt 2nd stage bootloader
I (43) boot: compile time Jun  7 2023 07:59:10
I (44) boot: chip revision: v0.3
I (48) boot.esp32c3: SPI Speed      : 40MHz
I (53) boot.esp32c3: SPI Mode       : DIO
I (57) boot.esp32c3: SPI Flash Size : 4MB
I (62) boot: Enabling RNG early entropy source...
I (68) boot: Partition Table:
I (71) boot: ## Label            Usage          Type ST Offset   Length
I (78) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (86) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (93) boot:  2 factory          factory app      00 00 00010000 003f0000
I (101) boot: End of partition table
I (105) esp_image: segment 0: paddr=00010020 vaddr=3c090020 size=15368h ( 86888) map
I (133) esp_image: segment 1: paddr=00025390 vaddr=3fc83f40 size=0120ch (  4620) load
I (134) esp_image: segment 2: paddr=000265a4 vaddr=3fc9cd90 size=00168h (   360) load
I (138) esp_image: segment 3: paddr=00026714 vaddr=40380000 size=03f3ch ( 16188) load
I (151) esp_image: segment 4: paddr=0002a658 vaddr=00000000 size=059c0h ( 22976) 
I (160) esp_image: segment 5: paddr=00030020 vaddr=42000020 size=806c0h (526016) map
I (280) boot: Loaded app from partition at offset 0x10000
I (280) boot: Disabling RNG early entropy source...
INFO - Logger is setup
Hello world!
INFO - esp-wifi configuration Config { rx_queue_size: 15, tx_queue_size: 3, static_rx_buf_num: 10, dynamic_rx_buf_num: 32, static_tx_buf_num: 0, dynamic_tx_buf_num: 32, ampdu_rx_enable: 0, ampdu_tx_enable: 0, amsdu_tx_enable: 0, rx_ba_win: 6, max_burst_size: 1, country_code: "CN", country_code_operating_class: 0, mtu: 1492, heap_size: 65536, tick_rate_hz: 50, listen_interval: 3, beacon_timeout: 6, ap_beacon_timeout: 300, failure_retry_cnt: 1, scan_method: 0 }
Device capabilities: Ok(EnumSet(Client | AccessPoint))
Setting configuration: Client(ClientConfiguration { ssid: "Noga", bssid: None, auth_method: WPA2Personal, channel: None })
Wifi started: true
Loop... 0 Ok(false)
Loop... 1 Ok(false)
Loop... 2 Ok(false)
Loop... 3 Ok(false)
Loop... 4 Ok(true)
Loop... 5 Ok(true)
Loop... 6 Ok(true)
Loop... 7 Ok(true)
Loop... 8 Ok(true)
Loop... 9 Ok(true)
Loop... 10 Ok(true)
Loop... 11 Ok(true)
Loop... 12 Ok(true)
Loop... 13 Ok(true)
Loop... 14 Ok(true)
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
Loop... 15 Ok(true)
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
Loop... 16 Ok(true)
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
Loop... 17 Ok(true)
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
Loop... 18 Ok(true)
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
Loop... 19 Ok(true)
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
Loop... 20 Ok(true)
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
INFO - Unhandled event: StaBeaconTimeout
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
Loop... 21 Ok(true)
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
Loop... 22 Ok(true)
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
Loop... 23 Ok(true)
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
WARN - Unable to allocate 2312 bytes
Loop... 24 Ok(true)
WARN - Unable to allocate 2312 bytes
Loop... 25 Err(Disconnected)
Loop... 26 Err(Disconnected)
Loop... 27 Err(Disconnected)

Is it by design?

@MabezDev
Copy link
Member

This probably shouldn't even be a warning, probably a debug statement. Packet memory is now entirely stored in the heap, the warning is about the number of packet headers in the queue, setting this to a low-ish number is fine, because if there is no space in the queue then the wifi stack will just keep retrying. Depending on what you're application needs, you can tune the stack to either be more performant and use more memory (you will need to either increase the heap size or increase the static buffer count) or slower but less memory intensive. See tuning.md for more details.

@MabezDev
Copy link
Member

I think it's fine for this to be an error. In my experience things rarely recover if the firmware hits this more than once in a while. I'd advise agains just hiding the pain; tuning the queue sizes may be a good way to reduce them.

This was probably true before, but not anymore, I've had this running in the last 24hrs and it will log this error constantly but still work just fine.

@galah92
Copy link
Author

galah92 commented Oct 20, 2023

@MabezDev I'm a bit confused.

First saw ERROR - RX QUEUE FULL logs. I then set rx_queue_size = 15, which removed these logs but made things worse: I got WARN - Unable to allocate 2312 bytes logs and WiFi disconnections after ~15 seconds.
I now added heap_size = 131072 (doubled the heap size) to get again ERROR - RX QUEUE FULL logs, but this time without disconnections.

Considering the code I shared above, which basically does nothing in terms of network, I assume I should keep the default config values, and just find a way to silent the ERROR - RX QUEUE FULL logs until this log severity will change. Is this correct?

@galah92
Copy link
Author

galah92 commented Oct 20, 2023

... and just find a way to silent the ERROR - RX QUEUE FULL logs ...

I can't seem to find a way to disable specifically the logs coming from the esp-wifi crate. Can this be done at all?

@MabezDev
Copy link
Member

I explained it here #291 (comment), ERROR - RX QUEUE FULL is a red herring and should not be an error log.

@galah92
Copy link
Author

galah92 commented Oct 20, 2023

I understand, but that's something that needs to be changed in the library implementation, right? I seem there's no way for me to disable these logs in the meantime, without disabling all logs (as suggested here).

@bjoernQ
Copy link
Contributor

bjoernQ commented Oct 23, 2023

You cannot disable logging for specific crates/paths but you can do it the other way around and only enable logging for the things you want to see logs from - see https://github.com/esp-rs/esp-println#logging ( ESP_LOGTARGETS )

@MabezDev
Copy link
Member

The log has since been removed.

@github-project-automation github-project-automation bot moved this from Todo to Done in esp-rs Feb 20, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
esp-rs
Archived in project
Milestone
No milestone
Development

No branches or pull requests
4 participants
@bugadani @bjoernQ @MabezDev @galah92