[Bug] LPF2 Motors appear to go out of sync sometimes.

[laurensvalk]

Describe the bug
Sometimes the control update loop stops, which manifests as a ENODEV at the user level.

Although technically inconclusive, this appears to have started in pybricks/pybricks-micropython@ae927ac, so before switching to the new calib mode and before fixing uartdev for fast syncing.

The reason why I currently believe it really does goes out of sync, is that you can restart the failed script a bit sooner than before, now that we fixed the fast syncup.

To reproduce

While it doesn't seem deterministic, the following program seems to eventually reproduce it within a few minutes.

Repeatedly Use F5/F6 in Pybricks Code to stop and restart the following program. Just let two motors C and D spin freely. No need to build a drivebase.

Repeat until you eventually get:

Traceback (most recent call last):
  File "main.py", line 15, in <module>
OSError: [Errno 19] ENODEV: 

A sensor or motor is not connected to the specified port:
--> Check the cables to each motor and sensor.
--> Check the port settings in your script.
--> Check the line in your script that matches
    the line number given in the 'Traceback' above.

from pybricks.pupdevices import Motor
from pybricks.tools import wait
from pybricks.parameters import Port, Direction
from pybricks.robotics import DriveBase
from pybricks import version

print(version)

# Initialize default "Driving Base" with medium motors and wheels.
left_motor = Motor(Port.C, Direction.COUNTERCLOCKWISE)
right_motor = Motor(Port.D)
drive_base = DriveBase(left_motor, right_motor, wheel_diameter=56, axle_track=112)

# Drive straight forward and back again.
drive_base.straight(500)
drive_base.straight(-500)

[dlech]

How long do you let the program run before stopping? How many iterations does it take to get a failure? Which motors are you using? Which hub are you using?

[laurensvalk]

A second, maybe two. It doesn’t seem to matter. Sometimes it happens in 5 tries, sometimes more.

This particular test was two medium angular motors (blue) on a prime hub.

[laurensvalk]

It’s quite possible it’s something else though. I was planning to see if I could reproduce it with just the IODevice class to rule that out.

Now that we use a single mode, that class works fine for reading motor modes too.

[laurensvalk]

I've also noticed that it gets stuck in an infinite poll loop sometimes after this happens when you restart the program. So here's a theory why this usually happens at the start of a program, and why it didn't happen before.

In pb_device we now always call set_mode at the start. This is supposed to do nothing if the mode is already set, but maybe we occasionally get a bad message that sets the mode wrong.

Then when setting the mode again on restart, it all goes wrong.

[dlech]

I am not able to reproduce the issue with firmware built from pybricks/pybricks-micropython@697a368 and the same hardware.

[laurensvalk]

I've seen it multiple times today even with the latest build. I'll try on different hardware tomorrow.

[laurensvalk]

The aforementioned infinite loop (light matrix keeps going) when immediately restarting when this occurs is probably a separate bug.

When you try set up the motor, pb_device_stm32 calls set_mode. If this happens while the motor is re-syncing, it gets stuck rather than raising the error. It gets stuck trying to set the mode from 2 to 4. (Even though 2 was never set).

[laurensvalk]

Back to the main bug. With debug prints on, we see a bit more:

Invalid mode received

But that's only part of it. The mode may be "valid" (low enough), but still wrong.

I also added the following debug info. See also comment about mode check:

diff --git a/lib/pbio/src/uartdev.c b/lib/pbio/src/uartdev.c
index a0f77af5..cb23364c 100644
--- a/lib/pbio/src/uartdev.c
+++ b/lib/pbio/src/uartdev.c
@@ -15,7 +15,7 @@
 
 #if PBIO_CONFIG_UARTDEV
 
-#define DEBUG 0
+#define DEBUG 1
 #if DEBUG
 #include <inttypes.h>
 #define debug_pr(fmt, ...)   printf((fmt), __VA_ARGS__)
@@ -579,11 +579,14 @@ static void pbio_uartdev_parse_msg(uartdev_port_data_t *data) {
                 DBG_ERR(data->last_err = "Invalid mode received");
                 goto err;
             }
-            data->iodev.mode = mode;
+            data->iodev.mode = mode; // <--- Should this be inside the switch below?
             if (mode == data->new_mode) {
                 memcpy(data->iodev.bin_data, data->rx_msg + 1, msg_size - 2);
             }
-
+            else {
+                debug_pr("Expected data for mode %d ", data->new_mode);
+                debug_pr("but got data for mode %d\n", mode);
+            }
 
             // setting type_id in info struct lets external modules know a device is connected and receiving good data
             data->info->type_id = data->type_id;

And then we see:

Expected data for mode 4 but got data for mode 2

Which explains this:

It gets stuck trying to set the mode from 2 to 4. (Even though 2 was never set).

It appears that ignoring garbage data might work. Let's see if the normal absolute position mode has this problem too (last time I checked, it did).

[laurensvalk]

This script triggers it more quickly.

Since this script completes quickly, just keep pressing F5 to run it:

from pybricks.pupdevices import Motor
from pybricks.tools import wait
from pybricks.parameters import Port, Direction
from pybricks.robotics import DriveBase
from pybricks import version

print(version)

unused = Motor(Port.A)
left_motor = Motor(Port.C, Direction.COUNTERCLOCKWISE)
right_motor = Motor(Port.D)
drive_base = DriveBase(left_motor, right_motor, wheel_diameter=56, axle_track=112)

drive_base.straight(10)

Build it with debug print on, with a variant of the above patch to print debug info on a bad mode.

This happens more often (but still not every time).

[laurensvalk]

Or maybe this is of those inconvenient timing issues that make it harder to reproduce. If I comment out

pb_flash_file_write("/_pybricks/main.mpy", *buf, len);

in main, which is partially blocking, this does not appear to occur, so far.

[dlech]

That makes sense (and is why we can't have any blocking functions). The UART buffer is probably overflowing while the blocking function is running.

To add a hack on top of a hack, we could probably run PBIO events (MICROPY_VM_HOOK_LOOP) in the loop in flash_wait_ready().

[laurensvalk]

This still seems to be happening, but now it has to be for different reasons.

EDIT: See #738

[laurensvalk]

This was reopened for #738 which is now fixed, so we can close this too.