Publish logs to Rosout

[nburek]

This pull request adds the rosout logging feature, which will forward logs from node loggers to the rosout topic on that node. This change is on top of other commits being reviewed in #327. This PR will currently contain the changes from both that review and this review. After that review is merged in this one should just show the last commit adding the rosout feature.

[nburek]

Hello OSRF team, what are the next steps for this and the related PR? I would love to try to get these in for the first Crystal patch if possible.

[jacobperron]

Some minor comments

[hidmic]

A few small comments too.

[hidmic]

@nburek nit: consider \param -> \param[in] for consistency with documentation above.

[nburek]

Done.

[hidmic]

@nburek nit: extra that at the end of the line?

[nburek]

Removed extra that

[hidmic]

@nburek consider [...]registers 'it' to be used [...].

[nburek]

Added 'it'

[hidmic]

@nburek just curious, why not calling rcl_logging_external_shutdown() if rcl_logging_rosout_fini() failed?

[nburek]

To prevent ambiguity in the case when both fail. My preference in this situation is to stop after the first failure as to not potentially mask it with another failure that might be related/caused by the first one.

[nburek]

Thanks for all the feedback. I've finished making updates based on your comments. There was only one that I pushed back on, so let me know what you think after you read my reasoning above.

[hidmic]

Running CI, including this PR and ros2/rcutils#131:

• Linux
• Linux-aarch64
• macOS
• Windows

[nuclearsandwich]

@nburek following up on @chapulina's comment ros2/rcutils#131 (comment) output from the Linux CI machines includes:

double free or corruption (fasttop)

with this test being one example of the above.

I'm less savvy with how Mac and Windows but I believe the test failures there stem from the same problem with differing system-specific output.

[nburek]

I'm digging into this now. It looks like something is not getting torn down correctly, which may be a result of the refactor to rcl that occurred while I was developing this that converted some portions of the rcl from being a single instance to being a context that gets initialized and torn down separate. While adjusting to the new lifecycle I probably missed a case in how something could be torn down. That's just my initial assumption at this point though, it still needs more investigation into what's going on.

[nburek]

This issue should now be fixed. A bug in the last commit I made introduced the bug that caused it to try to cleanup the rosout topic multiple times. This should now be fixed and all the tests from "test_rclcpp" were passing locally.

[nuclearsandwich]

• Linux
• Linux-aarch64
• macOS
• Windows

[nburek]

It looks like the Mac and Windows builds here failed because of a Jenkins issue:

07:05:00 FATAL: command execution failed
07:05:00 java.nio.channels.ClosedChannelException
07:05:00 	at org.jenkinsci.remoting.protocol.impl.ChannelApplicationLayer.onReadClosed(ChannelApplicationLayer.java:209)
07:05:00 	at org.jenkinsci.remoting.protocol.ApplicationLayer.onRecvClosed(ApplicationLayer.java:222)
07:05:00 	at org.jenkinsci.remoting.protocol.ProtocolStack$Ptr.onRecvClosed(ProtocolStack.java:816)

From the CI build that was run on the rcutils PR that includes this PR, the only issue is with a couple of Warnings on Windows. I'll work on getting those warnings fixed.
ros2/rcutils#131 (comment)

[nburek]

Can we try to get this PR merged into the next Crystal patch release?
ros2/ros2#647

[nuclearsandwich]

This is queued for patch release 2.

[chapulina]

It looks like this pull request broke backwards compatibility by throwing an error if there are multiple nodes with the same name. This is affecting downstream packages like navigation and rosbag (see issues referenced above) and has the potential to break many more packages.

@nburek, just a heads up that we're revisiting whether this will in fact go into patch 2, or if it should be retargeted for Dashing given all the downstream consequences. If your team can think of a more gentle transition, like printing a warning on Crystal and throwing the error on Dashing, that would make it easier to release this into Crystal.

[nburek]

The code could be modified to just print a warning, but it could explicitly break functionality because it would essentially cause two different node instances to share the same publisher attached to just one of the nodes. Destroying the one with the publisher would cause the other to break without additional complexity for maintaining both publishers and uniquely identifying which node they belong to so that they're torn down with the right node.

I'm curious what the long term stance is going to be on having multiple nodes with the same name. My understanding was that ROS1 explicitly disallows this and while ROS2 didn't explicitly disallow it until now that the recommendation was not to rely on it. If it's going to be allowed then this needs to be fixed regardless and if it's not going to be allowed then it feels like we're just adding an exception for a use case that we say shouldn't be supported but unofficially is. My worry in this case is that it won't be a temporary patch and I'd almost prefer to miss patch 2 and break the interface with Dashing.

[chapulina]

I'm curious what the long term stance is going to be on having multiple nodes with the same name.

I believe the long term plan is to explicitly disallow duplicate names.

the recommendation was not to rely on it

Correct, and the fact that it hasn't been enforced so far was just an oversight. However, there's a big difference between recommending against it and enforcing it.

we're just adding an exception for a use case that we say shouldn't be supported but unofficially is

There's nothing preventing downstream users from creating multiple nodes with the same name right now, and it looks like it's been working for them. So even though it is not recommended, we shouldn't break those users' code without a strong reason, like a security risk or a critical bug. A new feature is not a reason to break existing code in a patch release.

The code could be modified to just print a warning, but it could explicitly break functionality

It would just break the new functionality being added by this PR, right? Which is something that the preexisting packages and users wouldn't be counting on anyway. A warning would raise awareness without breaking existing code. It would be up to downstream developers whether they want to address the warnings on a future Crystal patch (as I believe navigation and rosbag are planning to do) or they could wait until Dashing to adapt to the new strict requirements.

I'd almost prefer to miss patch 2 and break the interface with Dashing

I've talked to the team and we agree that we shouldn't break existing functionality. So I'll leave it up to you if you want to follow the warning route, or just keep the functionality on master so it goes into Dashing.

[dirk-thomas]

I believe the long term plan is to explicitly disallow duplicate names.

That has not been decided yet.

[nburek]

A new feature is not a reason to break existing code in a patch release.

I totally agree. I don't think it can go into the patch as is since it breaks the interface by adding the explicit exclusion.

I believe the long term plan is to explicitly disallow duplicate names.

That has not been decided yet.

I was hoping that this decision had already been made. While just making this exception a warning right now would mean that logging has weird behavior in the case where you violate the policy it's at least telling people that they shouldn't be doing that. It would be something in ROS2 core that is explicitly telling people not to use the same name inside the same process, even if it's not enforced yet. If it's not going to be the policy that unique names are enforced within a process then making it a warning becomes a bit of a contradiction in my opinion between what a feature in ROS core is telling people and what the design says is allowed. In that case I'd rather fix the rosout feature to work with non-unique names in a way that makes sense, though that is probably more work and means it may slip past patch 2.

[chapulina]

That has not been decided yet.

I wasn't aware of that. @nburek is right that in that case, a warning may be misleading.

[dirk-thomas]

I'd rather fix the rosout feature to work with non-unique names in a way that makes sense

That sounds like the best alternative at the moment 👍

[nburek]

@dirk-thomas Do we have any line of site on when/if a decision is going to be made on unique naming within a process? Is there any previous conversation around it I could read up on?

[dirk-thomas]

Do we have any line of site on when/if a decision is going to be made on unique naming within a process?

It is currently not planned to work on that conceptional question within this release cycle.

Is there any previous conversation around it I could read up on?

I am not aware of a specific thread about the topic but it appear in multiple discussions where identifying nodes is a topic: e.g. http://design.ros2.org/articles/static_remapping.html

[wjwwood]

I believe the long term plan is to explicitly disallow duplicate names.

That has not been decided yet.

But we have many places where that's the assumption. My understanding is that unique names is the preferred route, but we're just missing the enforcement. If we were to go the other way and allow duplicate node names we'd have lots of refactoring to do.

I'd rather fix the rosout feature to work with non-unique names in a way that makes sense

That sounds like the best alternative at the moment 👍

Again, I disagree. I think the simplest and safest approach is to assume node names need to be unique, but add a check if duplicates are detected and warn against them.

Is there any previous conversation around it I could read up on?

I am not aware of a specific thread about the topic but it appear in multiple discussions where identifying nodes is a topic: e.g. http://design.ros2.org/articles/static_remapping.html

ros2/design#187

[dirk-thomas]

Since the description in that design ticket says explicitly:

We need a design document that states node names need to be unique (or not) with rationale why and if unique then how to enforce it and if not unique how to deal with existing features that assume and rely on unique node names.

I would highly recommend to not go further down a path which we have not settled on. We might lean towards requiring unique node names but if we decide not to for whatever reason this would add one more thing which needs to be revisited.

As long as there is no technical reason why this specific issue can't be resolved without relying on unique node names I think implementing it in a way that it does support non-unique names is the more flexible way to go.

[wjwwood]

As long as there is no technical reason why this specific issue can't be resolved without relying on unique node names I think implementing it in a way that it does support non-unique names is the more flexible way to go.

If it is easy to make it work without assuming node names are unique then that's fine, but we shouldn't go out of our way to make this feature work with non-unique node names. Because in my experience it is often harder to assume they are not unique, e.g. setting parameter values with services which are namespaced by node name.

I'm not up to speed on this issue enough to say which is the case this time, but if it is at all difficult to implement with non-unique node names, then I stand by my assertion that detecting and warning is a better route for now, because I would wager we end up going with enforced unique node names eventually, mostly because there are cases were we need the names to be unique and I don't see a reasonable way to implement those cases without unique names.

[nuclearsandwich]

@nburek from the discussion above it seems that our immediate path forward will be informed by your estimate of the work involved to allow logging to function without node-name uniqueness. If you have any initial estimates on what's involved that would help us come to a decision for how to handle the upcoming Crystal patch release.

[nburek]

To just switch this over to a warning I would estimate it would take someone on my team 4-6 hours to make the change, thoroughly test it, and send a PR for it.

To add some support for non-unique node names the simplest solution I can think of for now would be to change the map to allow for a list of publishers for a node name instead of just a single one. It would have to rely on the node->impl pointer value for uniqueness as I don't know of any other unique identifiers for a node. This would at least allow the rosout code to properly track and deconstruct publishers as nodes are created/destroyed. This would not solve the issue of actually sending the logs for different nodes with the same name over their distinct publishers. It would just have to pick one and all logs generated by node loggers with that name would go out over the first publisher in the list. That may be slightly odd behavior if you're looking at composition use case, because the code for one node could impact another based on the amount of logging it is doing. For a random developer from my team to pick this up I would estimate roughly 5 days to implement, test, and post the PR.

Any solution to actually keep track of which node loggers should use which node publishers when there is no unique naming would require changes to the interfaces for logging and how rclcpp/rclpy loggers track information. That would almost require another design review for the changes.

I think it would be really valuable to get the rosout feature into the crystal patch because it'll allow people to start using it and we'll actually get some good feedback on how it's working before Dashing. However, I think the only way our team would be able to get it ready in time for the second patch is to accept either a warning or a silent assumption with undefined behavior like many other parts of the code. Then we could have a discussion around what the right solution is and get it implemented for Dashing.

[adam-dunc]

The way I see it we have 3 options forward, please correct me:

1. Hold this feature until Dashing, after we have a decision on node uniqueness
2. Modify the node to throw a warning and include it in this patch
3. Modify this to work with non-unique nodes and push in a future patch

My recommendation would be # 2 at this stage. We discussed Crystal not being LTS so we could get feedback on all the new features from users. I'm glad we are dealing with this discussion now and not right in front of the Dashing release or we may have ended up without rosout logging in Dashing at all. If we hold this off until the full decision is made we'll realistically get no functional feedback from users on it until Dashing which defeats some of the purpose that we discussed with Crystal not being LTS. By logging warning it would work in most cases and can be modified once a decision is made on node uniqueness.

I'm happy to have Amazon help facilitate the long term approach discussions if it offloads some of the program management, design and decision matrix burden. If an owner isn't needed, we'd also be happy to participate.

-Adam

[nuclearsandwich]

@wjwwood, @dirk-thomas, @chapulina and I just had an offline discussion. We also agree that a issuing a warning is the preferred path forward. And we're going to determine at our ROS 2 meeting next Tuesday which future release we want to have settled the node name uniqueness constraints (ros2/design#187) for.

Two technical notes that came up for the immediate PR:

1. Please target master with the pull request as we'd like Crystal and master to behave consistently until we have an explicit design goal stating otherwise. Once it has been reviewed and merged we'll backport it to crystal.
2. When submitting the PR please describe the side effects of non-unique node names and summarize the description in the printed warning so that those who receive the warning know what to expect.

@nburek thanks very much for the estimates they were a big help in informing our decision making. Thanks also to @Karsten1987 and @chapulina for finding and reporting this issue before it got into a release and to everyone for their input. 💛

[nburek]

Followup PR for changing this to a warning: #384