search

OpenCyphal / pycyphal

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

Feedback message handler only called 32 times (SocketCAN) #120

Closed timokroeger closed 3 years ago

timokroeger commented 4 years ago

I tested following code on a Raspberry Pi 3:

#!/usr/bin/env python3

import asyncio
import pyuavcan.application
import pyuavcan.transport.can
import pyuavcan.transport.can.media.socketcan
import time
import uavcan.node
import uavcan.time

SYNCHRONIZATION_PUBLICATION_PERIOD = 0.1

cnt = 0
last_sync_message_timestamp = time.monotonic_ns()

def synchronization_loopback(feedback):
    global last_sync_message_timestamp, cnt
    cnt += 1
    print(cnt, last_sync_message_timestamp)
    last_sync_message_timestamp = (
        feedback.first_frame_transmission_timestamp.monotonic_ns
    )

async def synchronization_master():
    next_sync_at = time.monotonic()
    while True:
        sync_msg = uavcan.time.Synchronization_1_0(
            previous_transmission_timestamp_microsecond=last_sync_message_timestamp
            / 1000
        )
        await pub_synchronization.publish(sync_msg)
        next_sync_at += SYNCHRONIZATION_PUBLICATION_PERIOD
        await asyncio.sleep(next_sync_at - time.monotonic())

media = pyuavcan.transport.can.media.socketcan.SocketCANMedia("vcan0", mtu=8)
transport = pyuavcan.transport.can.CANTransport(media, local_node_id=42)

presentation = pyuavcan.presentation.Presentation(transport)
node_info = uavcan.node.GetInfo_1_0.Response(
    protocol_version=uavcan.node.Version_1_0(*pyuavcan.UAVCAN_SPECIFICATION_VERSION),
    software_version=uavcan.node.Version_1_0(major=0, minor=1),
    name="bug.timesync",
)
node = pyuavcan.application.Node(presentation, node_info)

node.heartbeat_publisher.mode = uavcan.node.Heartbeat_1_0.MODE_OPERATIONAL

pub_synchronization = node.presentation.make_publisher_with_fixed_subject_id(
    uavcan.time.Synchronization_1_0
)
pub_synchronization.priority = pyuavcan.transport.Priority.HIGH
pub_synchronization.send_timeout = SYNCHRONIZATION_PUBLICATION_PERIOD / 2
pub_synchronization.transport_session.enable_feedback(synchronization_loopback)

node.start()

asyncio.get_event_loop().create_task(synchronization_master())
asyncio.get_event_loop().run_until_complete(asyncio.gather(*asyncio.Task.all_tasks()))

Output:

1 1864886070973
2 1865108044410
3 1865208428836
...
29 1867808863361
30 1867908834561
31 1868008836542
32 1868112195947

Running candump vcan0 shows that the messages are still being sent to the bus even after the loopback handler stopped working.

pavel-kirienko commented 4 years ago

Indeed. I am able to reproduce this.

[pavel@deep-thought python]$ export PYUAVCAN_LOGLEVEL=DEBUG
[pavel@deep-thought python]$ ./tstest.py 
2020-07-06 12:06:39,452  6628 INFO     pyuavcan: Log config from env var; level: 'DEBUG'
2020-07-06 12:06:39,681  6628 DEBUG    asyncio: Using selector: EpollSelector
2020-07-06 12:06:39,694  6628 DEBUG    pyuavcan.presentation._port._publisher: PublisherImpl(dtype='uavcan.node.Heartbeat.1.0', transport_session=BroadcastCANOutputSession(OutputSessionSpecifier(data_specifier=MessageDataSpecifier(subject_id=32085), remote_node_id=None), PayloadMetadata(data_type_hash=0x666666667bc49901, max_size_bytes=7)), proxy_count=1) got a new proxy, new count 1
2020-07-06 12:06:39,706  6628 INFO     pyuavcan.transport.can.media.socketcan._socketcan: SocketCANMedia(interface_name='vcan0', mtu=8) FIXME: acceptance filter configuration is not yet implemented; please submit patches! Requested configuration: ext:xxx1x0xxxxxxxxx0101010xxxxxxx, ext:xxxxx0xxxxxxxxxxxxxxxx0101010, ext:xxx0x01111101010101010xxxxxxx
2020-07-06 12:06:39,707  6628 DEBUG    pyuavcan.presentation._port._publisher: PublisherImpl(dtype='uavcan.time.Synchronization.1.0', transport_session=BroadcastCANOutputSession(OutputSessionSpecifier(data_specifier=MessageDataSpecifier(subject_id=31744), remote_node_id=None), PayloadMetadata(data_type_hash=0x66666666d308cd01, max_size_bytes=7)), proxy_count=1) got a new proxy, new count 1
./tstest.py:61: DeprecationWarning: Task.all_tasks() is deprecated, use asyncio.all_tasks() instead
  asyncio.get_event_loop().run_until_complete(asyncio.gather(*asyncio.Task.all_tasks()))
1 6253265171062
2 6253292656501
3 6253393580501
4 6253493482324
5 6253593294029
6 6253693127461
7 6253792990034
8 6253893877727
9 6253993760773
10 6254093602781
11 6254193473693
12 6254293904084
13 6254393742520
14 6254493618387
15 6254593510645
16 6254693407780
17 6254793332416
18 6254893150799
19 6254992898855
20 6255093734977
21 6255193585533
22 6255293998011
23 6255393814476
24 6255493738550
25 6255593705706
26 6255693575341
27 6255793482465
28 6255893406847
29 6255993339779
30 6256093241511
31 6256193194320
32 6256293387141
2020-07-06 12:06:42,909  6628 DEBUG    pyuavcan.transport.can._session._output: No pending feedback entry for frame: TimestampedUAVCANFrame(identifier=209453098, padded_payload=<memory at 0x7f84a140e580>, transfer_id=0, start_of_transfer=True, end_of_transfer=True, toggle_bit=True, loopback=True, timestamp=Timestamp(system_ns=1594026402909485000, monotonic_ns=6256493464547))
2020-07-06 12:06:43,009  6628 DEBUG    pyuavcan.transport.can._session._output: No pending feedback entry for frame: TimestampedUAVCANFrame(identifier=209453098, padded_payload=<memory at 0x7f84a140eb80>, transfer_id=1, start_of_transfer=True, end_of_transfer=True, toggle_bit=True, loopback=True, timestamp=Timestamp(system_ns=1594026403009397000, monotonic_ns=6256593381645))
<...>
2020-07-06 12:06:46,009  6628 DEBUG    pyuavcan.transport.can._session._output: No pending feedback entry for frame: TimestampedUAVCANFrame(identifier=209453098, padded_payload=<memory at 0x7f84a140e400>, transfer_id=31, start_of_transfer=True, end_of_transfer=True, toggle_bit=True, loopback=True, timestamp=Timestamp(system_ns=1594026406009236000, monotonic_ns=6259593265852))
2020-07-06 12:06:46,109  6628 DEBUG    pyuavcan.transport.can._session._output: No pending feedback entry for frame: TimestampedUAVCANFrame(identifier=209453098, padded_payload=<memory at 0x7f84a140eb80>, transfer_id=0, start_of_transfer=True, end_of_transfer=True, toggle_bit=True, loopback=True, timestamp=Timestamp(system_ns=1594026406109079000, monotonic_ns=6259693111067))
2020-07-06 12:06:46,209  6628 DEBUG    pyuavcan.transport.can._session._output: No pending feedback entry for frame: TimestampedUAVCANFrame(identifier=209453098, padded_payload=<memory at 0x7f84a140e580>, transfer_id=1, start_of_transfer=True, end_of_transfer=True, toggle_bit=True, loopback=True, timestamp=Timestamp(system_ns=1594026406209031000, monotonic_ns=6259793077689))

You found a bug!

image

The fix is to compute the modulus of transfer.transfer_id by _frame.TRANSFER_ID_MODULO here:

https://github.com/UAVCAN/pyuavcan/blob/a38ce614162be948f61f421eebe1c903389dd578/pyuavcan/transport/can/_session/_output.py#L123

Might you be interested in sending a pull request?