search

OpenCyphal / pycyphal

Python implementation of the Cyphal protocol stack.
https://pycyphal.readthedocs.io/
MIT License
117 stars 105 forks source link

Bogus CRC error with CAN #288

Closed pavel-kirienko closed 1 year ago

pavel-kirienko commented 1 year ago

Run the following commands simultaneously:

y pub 1101:reg.udral.service.actuator.common.sp.Vector31.0.1 '{}'
y sub 1101:reg.udral.service.actuator.common.sp.Vector31.0.1
y -vv sub 1101:uavcan.primitive.scalar.Real16

Both subscribers should emit data. The actual behavior is that the second subscriber reports transfer CRC errors. The log emitted by the second subscriber is shown below (relevant part thereof):

2023-04-11 23:14:45 0276874 DEB pycyphal.transport.can._can: CANTransport(SocketCANMedia('slcan0', mtu=8), local_node_id=90): Parsing received CAN frames:
2023-04-11T23:14:45.296711/108118.416993 Envelope(frame=DataFrame(id=0x10644c7f, data=09300000000000b4), loopback=False)
2023-04-11 23:14:45 0276874 DEB pycyphal.transport.can._can: CANTransport(SocketCANMedia('slcan0', mtu=8), local_node_id=90): Accepted: 2023-04-11T23:14:45.296711/108118.416993 CyphalFrame(identifier=0x10644c7f, transfer_id=20, start_of_transfer=True, end_of_transfer=False, toggle_bit=True, padded_payload=09300000000000) MessageCANID(priority=<Priority.NOMINAL: 4>, source_node_id=127, subject_id=1100)
2023-04-11 23:14:45 0276874 DEB pycyphal.transport.can._can: CANTransport(SocketCANMedia('slcan0', mtu=8), local_node_id=90): Parsing received CAN frames:
2023-04-11T23:14:45.299738/108118.419996 Envelope(frame=DataFrame(id=0x10644c7f, data=0000000000000014), loopback=False)
2023-04-11 23:14:45 0276874 DEB pycyphal.transport.can._can: CANTransport(SocketCANMedia('slcan0', mtu=8), local_node_id=90): Accepted: 2023-04-11T23:14:45.299738/108118.419996 CyphalFrame(identifier=0x10644c7f, transfer_id=20, start_of_transfer=False, end_of_transfer=False, toggle_bit=False, padded_payload=00000000000000) MessageCANID(priority=<Priority.NOMINAL: 4>, source_node_id=127, subject_id=1100)
2023-04-11 23:14:45 0276874 DEB pycyphal.transport.can._can: CANTransport(SocketCANMedia('slcan0', mtu=8), local_node_id=90): Parsing received CAN frames:
2023-04-11T23:14:45.305769/108118.426047 Envelope(frame=DataFrame(id=0x10644c7f, data=0000000000000034), loopback=False)
2023-04-11 23:14:45 0276874 DEB pycyphal.transport.can._can: CANTransport(SocketCANMedia('slcan0', mtu=8), local_node_id=90): Accepted: 2023-04-11T23:14:45.305769/108118.426047 CyphalFrame(identifier=0x10644c7f, transfer_id=20, start_of_transfer=False, end_of_transfer=False, toggle_bit=True, padded_payload=00000000000000) MessageCANID(priority=<Priority.NOMINAL: 4>, source_node_id=127, subject_id=1100)
2023-04-11 23:14:45 0276874 DEB pycyphal.transport.can._can: CANTransport(SocketCANMedia('slcan0', mtu=8), local_node_id=90): Parsing received CAN frames:
2023-04-11T23:14:45.308731/108118.429025 Envelope(frame=DataFrame(id=0x10644c7f, data=0000000000000014), loopback=False)
2023-04-11 23:14:45 0276874 DEB pycyphal.transport.can._can: CANTransport(SocketCANMedia('slcan0', mtu=8), local_node_id=90): Accepted: 2023-04-11T23:14:45.308731/108118.429025 CyphalFrame(identifier=0x10644c7f, transfer_id=20, start_of_transfer=False, end_of_transfer=False, toggle_bit=False, padded_payload=00000000000000) MessageCANID(priority=<Priority.NOMINAL: 4>, source_node_id=127, subject_id=1100)
2023-04-11 23:14:45 0276874 DEB pycyphal.transport.can._can: CANTransport(SocketCANMedia('slcan0', mtu=8), local_node_id=90): Parsing received CAN frames:
2023-04-11T23:14:45.311704/108118.431985 Envelope(frame=DataFrame(id=0x10644c7f, data=0000000000000034), loopback=False)
2023-04-11 23:14:45 0276874 DEB pycyphal.transport.can._can: CANTransport(SocketCANMedia('slcan0', mtu=8), local_node_id=90): Accepted: 2023-04-11T23:14:45.311704/108118.431985 CyphalFrame(identifier=0x10644c7f, transfer_id=20, start_of_transfer=False, end_of_transfer=False, toggle_bit=True, padded_payload=00000000000000) MessageCANID(priority=<Priority.NOMINAL: 4>, source_node_id=127, subject_id=1100)
2023-04-11 23:14:45 0276874 DEB pycyphal.transport.can._can: CANTransport(SocketCANMedia('slcan0', mtu=8), local_node_id=90): Parsing received CAN frames:
2023-04-11T23:14:45.314729/108118.434961 Envelope(frame=DataFrame(id=0x10644c7f, data=0000000000000014), loopback=False)
2023-04-11 23:14:45 0276874 DEB pycyphal.transport.can._can: CANTransport(SocketCANMedia('slcan0', mtu=8), local_node_id=90): Accepted: 2023-04-11T23:14:45.314729/108118.434961 CyphalFrame(identifier=0x10644c7f, transfer_id=20, start_of_transfer=False, end_of_transfer=False, toggle_bit=False, padded_payload=00000000000000) MessageCANID(priority=<Priority.NOMINAL: 4>, source_node_id=127, subject_id=1100)
2023-04-11 23:14:45 0276874 DEB pycyphal.transport.can._can: CANTransport(SocketCANMedia('slcan0', mtu=8), local_node_id=90): Parsing received CAN frames:
2023-04-11T23:14:45.317736/108118.437964 Envelope(frame=DataFrame(id=0x10644c7f, data=0000000000000034), loopback=False)
2023-04-11 23:14:45 0276874 DEB pycyphal.transport.can._can: CANTransport(SocketCANMedia('slcan0', mtu=8), local_node_id=90): Accepted: 2023-04-11T23:14:45.317736/108118.437964 CyphalFrame(identifier=0x10644c7f, transfer_id=20, start_of_transfer=False, end_of_transfer=False, toggle_bit=True, padded_payload=00000000000000) MessageCANID(priority=<Priority.NOMINAL: 4>, source_node_id=127, subject_id=1100)
2023-04-11 23:14:45 0276874 DEB pycyphal.transport.can._can: CANTransport(SocketCANMedia('slcan0', mtu=8), local_node_id=90): Parsing received CAN frames:
2023-04-11T23:14:45.320728/108118.440960 Envelope(frame=DataFrame(id=0x10644c7f, data=0000000000000014), loopback=False)
2023-04-11 23:14:45 0276874 DEB pycyphal.transport.can._can: CANTransport(SocketCANMedia('slcan0', mtu=8), local_node_id=90): Accepted: 2023-04-11T23:14:45.320728/108118.440960 CyphalFrame(identifier=0x10644c7f, transfer_id=20, start_of_transfer=False, end_of_transfer=False, toggle_bit=False, padded_payload=00000000000000) MessageCANID(priority=<Priority.NOMINAL: 4>, source_node_id=127, subject_id=1100)
2023-04-11 23:14:45 0276874 DEB pycyphal.transport.can._can: CANTransport(SocketCANMedia('slcan0', mtu=8), local_node_id=90): Parsing received CAN frames:
2023-04-11T23:14:45.323725/108118.443949 Envelope(frame=DataFrame(id=0x10644c7f, data=0000000000001034), loopback=False)
2023-04-11 23:14:45 0276874 DEB pycyphal.transport.can._can: CANTransport(SocketCANMedia('slcan0', mtu=8), local_node_id=90): Accepted: 2023-04-11T23:14:45.323725/108118.443949 CyphalFrame(identifier=0x10644c7f, transfer_id=20, start_of_transfer=False, end_of_transfer=False, toggle_bit=True, padded_payload=00000000000010) MessageCANID(priority=<Priority.NOMINAL: 4>, source_node_id=127, subject_id=1100)
2023-04-11 23:14:45 0276874 DEB pycyphal.transport.can._can: CANTransport(SocketCANMedia('slcan0', mtu=8), local_node_id=90): Parsing received CAN frames:
2023-04-11T23:14:45.326739/108118.446995 Envelope(frame=DataFrame(id=0x10644c7f, data=4a54), loopback=False)
2023-04-11 23:14:45 0276874 DEB pycyphal.transport.can._can: CANTransport(SocketCANMedia('slcan0', mtu=8), local_node_id=90): Accepted: 2023-04-11T23:14:45.326739/108118.446995 CyphalFrame(identifier=0x10644c7f, transfer_id=20, start_of_transfer=False, end_of_transfer=True, toggle_bit=False, padded_payload=4a) MessageCANID(priority=<Priority.NOMINAL: 4>, source_node_id=127, subject_id=1100)
2023-04-11 23:14:45 0276874 DEB pycyphal.transport.can._session._input: CANInputSession(InputSessionSpecifier(data_specifier=MessageDataSpecifier(subject_id=1100), remote_node_id=None), PayloadMetadata(extent_bytes=2)): Rejecting CAN frame CyphalFrame(identifier=0x10644c7f, transfer_id=20, start_of_transfer=False, end_of_transfer=True, toggle_bit=False, padded_payload=4a) because TransferReassemblyErrorID.TRANSFER_CRC_MISMATCH; current stats: CANInputSessionStatistics(transfers=0, frames=1362, payload_bytes=0, errors=138, drops=0, reception_error_counters={<TransferReassemblyErrorID.MISSED_START_OF_TRANSFER: 1>: 2, <TransferReassemblyErrorID.UNEXPECTED_TOGGLE_BIT: 2>: 0, <TransferReassemblyErrorID.UNEXPECTED_TRANSFER_ID: 3>: 0, <TransferReassemblyErrorID.TRANSFER_CRC_MISMATCH: 4>: 136})

Transfer example:

 (1681243583.288644)  slcan0  RX - -  10644C7F   [8]  09 30 00 00 00 00 00 B1   '.0......'
 (1681243583.291624)  slcan0  RX - -  10644C7F   [8]  00 00 00 00 00 00 00 11   '........'
 (1681243583.294662)  slcan0  RX - -  10644C7F   [8]  00 00 00 00 00 00 00 31   '.......1'
 (1681243583.297647)  slcan0  RX - -  10644C7F   [8]  00 00 00 00 00 00 00 11   '........'
 (1681243583.300635)  slcan0  RX - -  10644C7F   [8]  00 00 00 00 00 00 00 31   '.......1'
 (1681243583.303616)  slcan0  RX - -  10644C7F   [8]  00 00 00 00 00 00 00 11   '........'
 (1681243583.306614)  slcan0  RX - -  10644C7F   [8]  00 00 00 00 00 00 00 31   '.......1'
 (1681243583.309578)  slcan0  RX - -  10644C7F   [8]  00 00 00 00 00 00 00 11   '........'
 (1681243583.312569)  slcan0  RX - -  10644C7F   [8]  00 00 00 00 00 00 10 31   '.......1'
 (1681243583.315564)  slcan0  RX - -  10644C7F   [2]  4A 51                     'JQ'
pavel-kirienko commented 1 year ago

This is caused by a regression introduced while fixing #198