Skip to content

node.nmt.wait_for_bootup misses boot message if a bootmessage is immidiately followed by another heartbeat message #560

Description

@jackodirks

CANopen version 2.3.0

I have this CANopen node that boots twice during an update. Here is the relevant code:

    print(f"Awaiting first bootup {time.ctime()}")
    node.nmt.wait_for_bootup(20)
    print(f"First bootup found! {time.ctime()}")
    print(f"Awaiting second bootup {time.ctime()}")
    node.nmt.wait_for_bootup(20)
    print(f"Second bootup found! {time.ctime()}")

Waiting for the first bootup message always works exactly as expected. Waiting for the second one fails randomly. What is weird is that the second boot message is definitely there:

Awaiting first bootup Mon Feb 24 09:13:03 2025
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 0
First bootup found! Mon Feb 24 09:13:03 2025
Awaiting second bootup Mon Feb 24 09:13:03 2025
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 0
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127
DEBUG:canopen.nmt:Received heartbeat can-id 1804, state is 127

But it gets ignored, somehow? Eventually the second wait_for_bootup times out.
As said, sometimes this works, but most often it does not seem to work.

Activity

  1. jackodirks commented on Feb 24, 2025

    @jackodirks
    Author

    This problem seems to be related to how close a "real" heartbeat follows a boot message. The following works very inconsistently

     (2025-02-24 10:04:07.801501)  can0  RX - -  70C   [1]  7F
     (2025-02-24 10:04:20.469853)  can0  RX - -  70C   [1]  00
     (2025-02-24 10:04:20.470673)  can0  RX - -  70C   [1]  7F
    

    (note how the first heartbeat was <1ms after the boot message)
    But this sequence always works as expected:

     (2025-02-24 10:06:40.321521)  can0  RX - -  70C   [1]  7F
     (2025-02-24 10:06:40.404523)  can0  RX - -  70C   [1]  00
     (2025-02-24 10:06:50.094791)  can0  RX - -  70C   [1]  7F
    

    (Time between boot and heartbeat is almost 10 seconds).

    Just speculating here: I think that the relevant condition (node.nmt.state_update) gets notified twice with so little time in between that wait_for_bootup never gets the chance to check if self._state_received was ever zero.

  2. acolomb commented on Feb 24, 2025

    @acolomb
    Member

    I think this is a pretty simple bug, but haven't investigated deeply.

    https://github.com/christiansandberg/canopen/blob/5382f245d8ede61b113c6a648cb99b199667f0cd/canopen/nmt.py#L162-L170

    The check for self._state_received == 0 happens after the condition has been released, thus the next PRE-OP heartbeat could already have been processed (which sets the attribute back to 127). Try moving the check within the with self.state_update: block, see if that fixes the issue.

  3. jackodirks commented on Feb 27, 2025

    @jackodirks
    Author

    The suggestion by acolomb does not solve the issue.

    Adding a new debug statement on line 167 shows that in case two messages come in really close together, the notification does not lead to code execution in wait_for_bootup.

    So I believe that self.state_update.notify_all() does not guarantee that all listeners get CPU time immediately, and therefore another CAN message could be handled first, so that _state_received updates twice without wait_for_bootup ever getting CPU time. So I think a separate condition for just boot messages would be required to solve this.

  4. changed the title [-]Node boots twice, second boot message cannot be waited for.[/-] [+]node.nmt.wait_for_bootup misses boot message if a bootmessage is immidiately followed by another heartbeat message[/+] on Feb 27, 2025
  5. acolomb commented on Jul 15, 2025

    @acolomb
    Member

    @jackodirks Do you have a specific improvement in mind that solves this problem? Please open a PR in that case. I don't know how to proceed from my side.

  6. added a commit that references this issue on Oct 4, 2026
    cf24116
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions