esp-rs/espmonitor

Error: The device does not recognize the command. (os error 22)

mihai-dinculescu opened this issue · 4 comments

I've been happily using espmonitor with several ESP32s, but with a FeatherS3 from UM, it crashes when winding down.

I (2870) esp_idf_svc::wifi: Stopping
I (2880) wifi:state: run -> init (0)
I (2880) wifi:pm stop, total sleep time: 1454770 us / 2006276 us
W (2890) wifi:<ba-del>idx
I (2890) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (2900) esp_idf_svc::wifi: Disconnect requested
I (2900) wifi:flush txq
I (2900) wifi:stop sw txq
I (2900) wifi:lmac stop hw txq
I (2910) esp_idf_svc::wifi: Stop requested
I (2910) esp_idf_svc::wifi: Got wifi event: StaDisconnected
Error: The device does not recognize the command. (os error 22)

$ espmonitor --version
ESPMonitor 0.7.0

idf.py monitor behaves as expected

I (2870) esp_idf_svc::wifi: Stopping
I (2880) wifi:state: run -> init (0)
I (2880) wifi:pm stop, total sleep time: 1363234 us / 2000715 us

W (2890) wifi:<ba-del>idx
I (2890) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (2900) esp_idf_svc::wifi: Disconnect requested
I (2900) wifi:flush txq
I (2900) wifi:stop sw txq
I (2900) wifi:lmac stop hw txq
I (2910) esp_idf_svc::wifi: Stop requested
I (2910) esp_idf_svc::wifi: Got wifi event: StaDisconnected
I (2920) esp_idf_svc::wifi: STA event StaDisconnected handled, set status: Status(Started(Disconnected), Stopped)
I (2920) esp_idf_svc::wifi: About to wait for status
I (2940) esp_idf_svc::wifi: Got wifi event: StaStopped
I (2940) esp_idf_svc::wifi: STA event StaStopped handled, set status: Status(Stopped, Stopped)
I (2950) esp_idf_svc::wifi: Waiting for status done - success
I (2960) esp_idf_svc::wifi: Stopped
I (2960) esp_idf_svc::wifi: Event handlers deregistered
I (2970) wifi:Deinit lldesc rx mblock:10
I (2980) esp_idf_svc::wifi: Driver deinitialized
I (2980) esp_idf_svc::wifi: Deinitialization complete
I (2980) esp_idf_svc::wifi: Dropped
I (2990) esp_idf_svc::netif: Dropped
I (2990) esp_idf_svc::nvs: Dropped
I (2990) esp_idf_svc::eventloop: Dropped
we've been up for 2993154 ms.
going to sleep...
ClearCommError failed (PermissionError(13, 'The device does not recognize the command.', None, 22))
Waiting for the device to reconnect....

OS: MINGW64 on Windows 11

Can you run it through strace -f and post the result? Not really sure what's failing there. I suspect something Windows-specific, but I don't have the ability to test on Windows.

I couldn't get strace to work, but I have attached the export of Process Monitor.

From the little I understand about all this, The device does not recognize the command. is actually an expected error, on Windows.

When the ESP32 S3 device goes into deep sleep the USB port gets disconnected, the serial connection is closed, and that error is produced. From the logs above you can see that idf.py receives the very same error, but it handles it gracefully by attempting to reconnect until the device wakes up.

I suspect that espmonitor could benefit from the same reconnect functionality?

Another issue that I've discovered is that the data that was produced close to the port getting disconnected is not getting handled. This must be because dev.read returns Uncategorized, a fatal error, instead of a non-fatal one like Interrupted. I suspect that espmonitor crashes with data left in the buffer.

This is the code I've had to change in order to get the same behavior as idf.py monitor.

The only way I've been able to make sure to get all the data before disconnection was to change the buffer size to 1, which obviously is far from ideal...

Please let me know if you're open to exploring this avenue. I can put a PR up.

    let mut buf = [0u8; 1];

    // reconnect = -1  => connected
    // reconnect = 0   => something went wrong, trying to reconnect for the first time
    // reconnect > 0   => multiple reconnects attempted so far
    let mut reconnect = -1;

    loop {
        if reconnect >= 0 {
            if reconnect == 0 {
                print!("Waiting for the device to reconnect");
                std::io::stdout().flush()?;
            }

            let dev_new = || -> Result<_, Box<dyn std::error::Error>> {
                let mut dev_new = serial::open(&args.serial)?;
                dev_new.set_timeout(Duration::from_secs(60))?;
                dev_new.reconfigure(&|settings| settings.set_baud_rate(speed))?;

                Ok(dev_new)
            }();

            if let Ok(dev_new) = dev_new {
                dev = dev_new;
                reconnect = -1;
            } else {
                print!(".");
                std::io::stdout().flush()?;
                std::thread::sleep(Duration::from_secs(1));
            }
        }

        match dev.read(&mut buf) {
            Ok(bytes) if bytes > 0 => {
                handle_serial(&mut serial_state, &buf[0..bytes], &mut output)?
            }
            Ok(_) => {
                if dev.read_dsr().is_err() {
                    rprintln!("Device disconnected; exiting");
                    break Ok(());
                }
            }
            Err(err) if err.kind() == ErrorKind::TimedOut => (),
            Err(err) if err.kind() == ErrorKind::WouldBlock => (),
            Err(err) if err.kind() == ErrorKind::Interrupted => (),
            Err(_) => {
                reconnect += 1;
                ()
            }
        }

So I'm kinda torn on this. On one hand I do kinda like espmonitor to automatically quit if I disconnect the device. But I can see how it could be useful to wait and auto-reconnect.

The only way I've been able to make sure to get all the data before disconnection was to change the buffer size to 1, which obviously is far from ideal...

Hmm, that's strange; I would think that if the read() is able to give at least one byte, it would return that data, and then the next read would throw the error.