Decode error after running configure

[rodja]

After running configure, Lizard always reports the error Could not decode serial data:

read: I (592) spi_flash: flash io: dio
read: W (595) spi_flash: Detected size(16384k) larger than the size in the binary image header(2048k). Using the size in the b
read: Ready.
read: I (699) gpio: GPIO[15]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
read: I (699) gpio: GPIO[12]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
read: I (709) BTDM_INIT: BT controller compile version [6a07b06]
read: I (709) system_api: Base MAC address is not set
read: I (719) system_api: read default base MAC address from EFUSE
read: I (729) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
send: bms.send(0xdd, 0xa5, 0x03, 0x00, 0xff, 0xfd, 0x77)@52
read: I (1059) esp_zeug/FrtosUtil: Task [ble_host] executing on core [PRO]
read: I (1109) NimBLE: GAP procedure initiated: advertise;
read: I (1109) NimBLE: disc_mode=2
read: I (1109) NimBLE:  adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0
read: I (1109) NimBLE:
read:
read: I (1139) gpio: GPIO[25]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
read: I (1139) gpio: GPIO[14]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
Could not decode serial data: b'p0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: \x95\xedbumper_front_top.change=0;bumper_front_top.in\xf6I (12) boot: ESP-IDF v4.4 2nd stage bootloader@87\r\np0: I (13) boot: compile time 08:53:25@71\r\np0: I (13) boot: chip revision: 3@14\r\np0: I (13) boot_comm: chip revision: 3, min. bootloader chip revision: 0@03\r\np0: I (17) boot.esp32: SPI Speed      : 40MHz@1d\r\np0: I (21) boot.esp32: SPI Mode       : DIO@65\r\np0: I (25) boot.esp32: SPI Flash Size : 2MB@68\r\np0: I (28) boot: Enabling RNG early entropy source...@50\r\np0: I (33) boot: Partition Table:@18\r\np0: I (35) boot: ## Label            Usage          Type ST Offset   Length@35\r\np0: I (42) boot:  0 nvs              WiFi data        01 02 00009000 00006000@4e\r\np0: I (48) boot:  1 phy_init         RF data          01 01 0000f000 00001000@74\r\np0: I (55) boot:  2 factory          factory app      00 00 00010000 00177000@4d\r\np0: I (61) boot: End of partition table@63\r\np0: I (64) boot_comm: chip revision: 3, min. application chip revision: 0@7e\r\np0: I (71) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=49f58h (302936) map@29\r\n'
Traceback (most recent call last):
  File "/app/rosys/hardware/communication/serial_communication.py", line 71, in read
    s = s.decode()
        ^^^^^^^^^^
UnicodeDecodeError: 'utf-8' codec can't decode byte 0x95 in position 328: invalid start byte
read: p0: I (188) esp_image: segment 1: paddr=00059f80 vaddr=3ffbdb60 size=04774h ( 18292) load@7d
read: p0: I (195) esp_image: segment 2: paddr=0005e6fc vaddr=40080000 size=0191ch (  6428) load@6c
read: p0: I (198) esp_image: segment 3: paddr=00060020 vaddr=400d0020 size=a6900h (682240) map@15
read: p0: I (446) esp_image: segment 4: paddr=00106928 vaddr=4008191c size=16each ( 93868) load@72
read: p0: I (485) esp_image: segment 5: paddr=0011d7dc vaddr=50000000 size=00010h (    16) load@35
read: p0: I (497) boot: Loaded app from partition at offset 0x10000@77
read: p0: I (497) boot: Disabling RNG early entropy source...@15
read: p0: I (507) cpu_start: Pro cpu up.@63

The configure data is

send: !-@0c
send: !+rdyp = Output(15)@12
send: !+en3 = Output(12)@32
send: !+bluetooth = Bluetooth("uckerbot-u6")@6b
send: !+can = Can(32, 33, 1000000)@26
send: !+l0 = ODriveMotor(can, 0)@72
send: !+r0 = ODriveMotor(can, 512)@6a
send: !+l1 = ODriveMotor(can, 256)@72
send: !+r1 = ODriveMotor(can, 768)@64
send: !+l0.m_per_tick = 0.05567092651757189@79
send: !+r0.m_per_tick = 0.05567092651757189@67
send: !+l1.m_per_tick = 0.05567092651757189@78
send: !+r1.m_per_tick = 0.05567092651757189@66
send: !+l0.reversed = false@3c
send: !+r0.reversed = true@49
send: !+l1.reversed = false@3d
send: !+r1.reversed = true@48
send: !+wheels = ODriveWheels(l0, r0)@07
send: !+wheels_front = ODriveWheels(l1, r1)@39
send: !+wheels.width = 0.47@62
send: !+wheels_front.width = 0.47@5c
send: !+wheels.shadow(wheels_front)@1d
send: !+@0a
send: !+serial = Serial(26, 27, 115200, 1)@2d
send: !+p0 = Expander(serial, 25, 14)@45
send: !+master = CanOpenMaster(can)@02
send: !+master.sync_interval = 5@77
send: !+@0a
send: !+yaxis_motor = CanOpenMotor(can, 112)@19
send: !+yaxis_end_l = p0.Input(25)@70
send: !+yaxis_end_l.inverted = true@65
send: !+yaxis_end_r = p0.Input(12)@6a
send: !+yaxis_end_r.inverted = true@7b
send: !+yaxis = MotorAxis(yaxis_motor, yaxis_end_r, yaxis_end_l)@74
send: !+@0a
send: !+zaxis_motor = CanOpenMotor(can, 96)@27
send: !+zaxis_end_t = p0.Input(22)@6c
send: !+zaxis_end_t.inverted = true@7e
send: !+zaxis_end_b = p0.Input(23)@7b
send: !+zaxis_end_b.inverted = true@68
send: !+zaxis = MotorAxis(zaxis_motor, zaxis_end_b, zaxis_end_t)@7c
send: !+@0a
send: !+flashlight = PwmOutput(5)@78
send: !+flashlight.duty = 255@39
send: !+flashlight_back = PwmOutput(4)@2d
send: !+flashlight_back.duty = 255@6d
send: !+flashlight.shadow(flashlight_back)@77
send: !+@0a
send: !+bms = p0.Serial(26, 27, 9600, 2)@34
send: !+bms.unmute()@4b
send: !+@0a
send: !+estop_1 = Input(34)@74
send: !+estop_2 = Input(35)@76
send: !+battery_control_reset = p0.Output(15)@1c
send: !+battery_control_status = p0.Input(13)@12
send: !+@0a
send: !+bumper_front_top = p0.Input(35)@1f
send: !+bumper_front_bottom = p0.Input(18)@74
send: !+bumper_back = p0.Input(21)@44
send: !+rdyp_status = Input(39)@3e
send: !+vdp_status = p0.Input(39)@2d
send: !+@0a
send: !+let stop do wheels.speed(0, 0); yaxis.stop(); zaxis.stop();end@57
send: !+when estop_1.level == 0 then stop(); end@3f
send: !+when estop_2.level == 0 then stop(); end@3c
send: !+when bumper_front_top.level == 1 or bumper_front_bottom.level == 1 or bumper_back.level == 1 then wheels.off(); end@59
send: !+when core.last_message_age > 1000 then wheels.speed(0, 0); end@11
send: !+when core.last_message_age > 20000 then stop(); end@7f
send: !+@0a
send: !+core.output("core.millis wheels.linear_speed:3 wheels.angular_speed:3 yaxis_end_l.active yaxis_end_r.active yaxis_motor.actua

[falkoschindler]

@rodja I can't reproduce the problem. You seem to have used the Lizard configuration tool from RoSys, which might cause the issue. And your core output line is incomplete, so I changed it slightly. But then running ./configure.py startup.liz /dev/tty.SLAB_USBtoUART works fine.

[falkoschindler]

Oh, maybe I need a port expander attached... I'll look into it once again.

[falkoschindler]

Maybe a reproduction:

b = b'p0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: @5a\r\np0: \x95\xedbumper_front_top.change=0;bumper_front_top.in\xf6I (12) boot: ESP-IDF v4.4 2nd stage bootloader@87\r\np0: I (13) boot: compile time 08:53:25@71\r\np0: I (13) boot: chip revision: 3@14\r\np0: I (13) boot_comm: chip revision: 3, min. bootloader chip revision: 0@03\r\np0: I (17) boot.esp32: SPI Speed      : 40MHz@1d\r\np0: I (21) boot.esp32: SPI Mode       : DIO@65\r\np0: I (25) boot.esp32: SPI Flash Size : 2MB@68\r\np0: I (28) boot: Enabling RNG early entropy source...@50\r\np0: I (33) boot: Partition Table:@18\r\np0: I (35) boot: ## Label            Usage          Type ST Offset   Length@35\r\np0: I (42) boot:  0 nvs              WiFi data        01 02 00009000 00006000@4e\r\np0: I (48) boot:  1 phy_init         RF data          01 01 0000f000 00001000@74\r\np0: I (55) boot:  2 factory          factory app      00 00 00010000 00177000@4d\r\np0: I (61) boot: End of partition table@63\r\np0: I (64) boot_comm: chip revision: 3, min. application chip revision: 0@7e\r\np0: I (71) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=49f58h (302936) map@29\r\n'
b.decode()

UnicodeDecodeError: 'utf-8' codec can't decode byte 0x95 in position 328: invalid start byte

But why is \x95 an invalid "start byte"?

[falkoschindler]

Possible solution:

b.decode(errors='replace')

[falkoschindler]

Restarting the ESP via core.restart() causes the same decode error, but only via RoSys' Lizard interface. Using Lizard's monitor.py doesn't cause an exception, because it is already using errors='replace'.

I think what is happening is that when rebooting the port expander, there are still bytes in the serial transmission buffer. After booting they mix with the boot message and potentially form "invalid start bytes". According to ChatGPT, UTF-8 characters should start with one of those:

Single-byte characters (ASCII): Range: 0x00 to 0x7F These represent standard ASCII characters and use one byte.

Two-byte characters: Range: 0xC2 to 0xDF These represent the start of a two-byte sequence.

Three-byte characters: Range: 0xE0 to 0xEF These represent the start of a three-byte sequence.

Four-byte characters: Range: 0xF0 to 0xF4 These represent the start of a four-byte sequence.

But 0x95 doesn't fit.

The question is, should we simply replace these errors, or should we drop the line altogether? The latter sounds more reasonable to me.

[falkoschindler]

We fixed this problem by reviewing and updating how the serial port is read in different Python scripts. In RoSys we decided to replace decode errors and skip corrupted lines based on checksums: https://github.com/zauberzeug/rosys/commit/d279b615ab28732487e7cf5362d65576214330ac