Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Guard condition not getting marked as ready in waitset (possible race condition?) #989

Closed
hoffmann-stefan opened this issue Jun 29, 2022 · 4 comments
Closed

Guard condition not getting marked as ready in waitset (possible race condition?) #989

hoffmann-stefan opened this issue Jun 29, 2022 · 4 comments
Assignees
@ivanpauno
Labels
question Further information is requested

Comments

@hoffmann-stefan
Copy link

Bug report

Required Info:

  • Operating System:
    • Ubuntu 20.04 in WSL2 on Windows 10 20H2 (Build 19042.1706)
    • uname -a: Linux Client-291 5.10.60.1-microsoft-standard-WSL2 #1 SMP Wed Aug 25 23:20:18 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux
  • Installation type:
    • binaries
  • Version or commit hash:
$ apt-cache policy ros-foxy-rcl
ros-foxy-rcl:
  Installed: 1.1.13-1focal.20220209.142931
  Candidate: 1.1.13-1focal.20220209.142931
  Version table:
 *** 1.1.13-1focal.20220209.142931 500
        500 http://packages.ros.org/ros2/ubuntu focal/main amd64 Packages
        100 /var/lib/dpkg/status

Steps to reproduce issue

Using this branch that adds an example to reproduce this run the follwoing command:
https://github.com/hoffmann-stefan/ros2_dotnet/commits/reproduce_gaurd_condition_not_triggerd

$ ros2 run rcldotnet_examples rcldotnet_guard_condition

Here is the console application that causes this: (logging is was added to rcldotnet in the linked branch)

using System;
using System.Threading;
using System.Threading.Tasks;

using ROS2;

namespace ConsoleApplication
{
    public static class RCLDotnetGuardCondition
    {
        static GuardCondition _guardCondition = null;

        public static void Main(string[] args)
        {
            RCLdotnet.Init();

            var node = RCLdotnet.CreateNode("guard_condition_example");

            _guardCondition = node.CreateGuardCondition(GuardConditionTriggered);

            Console.WriteLine(RCLdotnet.GetRMWIdentifier());
            Console.WriteLine($"ThreadId: {Environment.CurrentManagedThreadId}");

            _guardCondition.Trigger();

            RCLdotnet.Spin(node);
        }

        static void GuardConditionTriggered()
        {
            _ = TriggerAfterSomeTime();
        }

        static async Task TriggerAfterSomeTime()
        {
            // This is a multiple of the 500ms used in the loop in
            // RCLdotnet.Spin(). So the guard condition will be triggered nearly
            // at the same time as the wait times out.
            await Task.Delay(1000);

            // This will be called in an background worker thread as console
            // applications don't have an SynchronizationContext by default.
            _guardCondition.Trigger();
        }
    }
}

Expected behavior

This console application should run forever triggering the guard condition every second.

Actual behavior

After some time the callback for the guard condition dosn't get triggerd -> so no retrigger after one second. (The waitset never signals that the gaurd condition is ready)

$ ros2 run rcldotnet_examples rcldotnet_guard_condition
rmw_fastrtps_cpp
ThreadId: 1
2022-06-29T11:18:04.0538064+02:00 ThreadId: 1 GuardCondition.Trigger(): guard condition was triggered
2022-06-29T11:18:04.0610524+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:04.0613053+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): wait done
2022-06-29T11:18:04.0617290+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): trigger guard condition callback
2022-06-29T11:18:04.0637237+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:04.5640404+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): timeout wait
2022-06-29T11:18:04.5643150+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:05.0635021+02:00 ThreadId: 4 GuardCondition.Trigger(): guard condition was triggered
2022-06-29T11:18:05.0635578+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): wait done
2022-06-29T11:18:05.0636181+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): trigger guard condition callback
2022-06-29T11:18:05.0637466+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:05.5640316+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): timeout wait
2022-06-29T11:18:05.5642642+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:06.0644099+02:00 ThreadId: 4 GuardCondition.Trigger(): guard condition was triggered
2022-06-29T11:18:06.0644854+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): wait done
2022-06-29T11:18:06.0646589+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): trigger guard condition callback
2022-06-29T11:18:06.0649019+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:06.5652305+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): timeout wait
2022-06-29T11:18:06.5654583+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:07.0655165+02:00 ThreadId: 4 GuardCondition.Trigger(): guard condition was triggered
2022-06-29T11:18:07.0656442+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): wait done
2022-06-29T11:18:07.0657459+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): trigger guard condition callback
2022-06-29T11:18:07.0659608+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:07.5663083+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): timeout wait
2022-06-29T11:18:07.5665771+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:08.0666496+02:00 ThreadId: 4 GuardCondition.Trigger(): guard condition was triggered
2022-06-29T11:18:08.0667777+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): wait done
2022-06-29T11:18:08.0669019+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): trigger guard condition callback
2022-06-29T11:18:08.0671665+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:08.5675786+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): timeout wait
2022-06-29T11:18:08.5678334+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:09.0678808+02:00 ThreadId: 4 GuardCondition.Trigger(): guard condition was triggered
2022-06-29T11:18:09.0681750+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): wait done
2022-06-29T11:18:09.0684275+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): trigger guard condition callback
2022-06-29T11:18:09.0687320+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:09.5693071+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): timeout wait
2022-06-29T11:18:09.5694989+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:10.0693217+02:00 ThreadId: 4 GuardCondition.Trigger(): guard condition was triggered
2022-06-29T11:18:10.0694448+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): wait done
2022-06-29T11:18:10.0695638+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): trigger guard condition callback
2022-06-29T11:18:10.0698150+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:10.5704322+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): timeout wait
2022-06-29T11:18:10.5706943+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:11.0704566+02:00 ThreadId: 4 GuardCondition.Trigger(): guard condition was triggered
2022-06-29T11:18:11.0705225+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): wait done
2022-06-29T11:18:11.0705979+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): trigger guard condition callback
2022-06-29T11:18:11.0706900+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:11.5709588+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): timeout wait
2022-06-29T11:18:11.5711594+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:12.0712608+02:00 ThreadId: 4 GuardCondition.Trigger(): guard condition was triggered
2022-06-29T11:18:12.0713961+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): wait done
2022-06-29T11:18:12.0715124+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): trigger guard condition callback
2022-06-29T11:18:12.0717579+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:12.5721676+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): timeout wait
2022-06-29T11:18:12.5724525+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:13.0721233+02:00 ThreadId: 4 GuardCondition.Trigger(): guard condition was triggered
2022-06-29T11:18:13.0721984+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): wait done
2022-06-29T11:18:13.0723242+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): trigger guard condition callback
2022-06-29T11:18:13.0724226+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:13.5726046+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): timeout wait
2022-06-29T11:18:13.5726963+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:14.0731557+02:00 ThreadId: 4 GuardCondition.Trigger(): guard condition was triggered
2022-06-29T11:18:14.0732933+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): timeout wait
2022-06-29T11:18:14.0735032+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:14.5739703+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): timeout wait
2022-06-29T11:18:14.5741613+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:15.0745775+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): timeout wait
2022-06-29T11:18:15.0747819+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:15.5753164+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): timeout wait
2022-06-29T11:18:15.5755453+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:16.0760885+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): timeout wait
2022-06-29T11:18:16.0763506+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:16.5771038+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): timeout wait
2022-06-29T11:18:16.5773719+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:17.0777013+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): timeout wait
2022-06-29T11:18:17.0779539+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:17.5784777+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): timeout wait
2022-06-29T11:18:17.5787394+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset
2022-06-29T11:18:18.0790355+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): timeout wait
2022-06-29T11:18:18.0791211+02:00 ThreadId: 1 RCLdotnet.SpinOnce(): add guard condition to waitset

Additional information

I'm not sure if this is a supported pattern to use guard_conditions in combination with waitsets.
Before further investigation I would like to ask if I am doing something wrong while adding guard conditions to rcldotnet? (see this commit: hoffmann-stefan/ros2_dotnet@b7713c5)
I didn't find documentation for this, so if I'm doing someting wrong maybe we can extend the header documentation?
@ivanpauno ivanpauno added the question Further information is requested label Aug 18, 2022
@ivanpauno
Copy link
Member

This repo is for rcl issues, not for rcldotnet.
If you believe an issue in rcldotnet is caused by an issue in rcl, please provide a minimal reproducible example of the bug written in C (or C++) using rcl directly.

Feel free to update the description and reopen or open a new issue when you have that.
Thanks!

@ivanpauno
Copy link
Member

I'm not sure if this is a supported pattern to use guard_conditions in combination with waitsets.

I have never used rcldotnet, but the example you provided seems like something that it should work if the client library is implemented correctly.

@ivanpauno
Copy link
Member

I have never used rcldotnet, but the example you provided seems like something that it should work if the client library is implemented correctly.

I don't know how async in dotnet works as well, so there may also be a problem with that ...

@hoffmann-stefan
Copy link
Author

Got this working with switching the ROS2 middleware to cyclonedds, so at least my branch for rcldotnet can't be completely wrong.

Was hoping maybe something obvious for people knowing rcl would be found while glimpsing over the linked source code, but It seems that there is no way around a c/c++ minimal example. Though I can't promise when/if I get to this.

As for C# async this should be like c++ promise/features with additional syntactic sugar to avoid callback hell. The code after the Task.Delay continues in a background thread that is managed by the dotnet runtime. Though I don't know exactly which implementation details this has that may interfere with the multi-threading synchronization used by rcl/rmw.

@hoffmann-stefan hoffmann-stefan mentioned this issue May 19, 2023
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@ivanpauno ivanpauno

Labels
question Further information is requested
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@ivanpauno @hoffmann-stefan