Skip to content

fix: make the test log handler coexist with rosout#656

Open
azerupi wants to merge 1 commit into
ros2-rust:mainfrom
azerupi:fix/logging-test-handler-isolation
Open

fix: make the test log handler coexist with rosout#656
azerupi wants to merge 1 commit into
ros2-rust:mainfrom
azerupi:fix/logging-test-handler-isolation

Conversation

@azerupi

@azerupi azerupi commented Jun 27, 2026

Copy link
Copy Markdown
Contributor

The test-only custom logging output handler (set_logging_output_handler, used by the rclrs logging tests) installed itself via rcutils_logging_set_output_handler, replacing the default rcl_logging_multiple_output_handler. While installed this had two process-global side effects:

  1. /rosout (and console/file) publishing was disabled, because the default handler that fans out to them was no longer called. A test running concurrently that relied on /rosout (e.g. the rosout publishing test) could silently lose its messages.
  2. Every log record emitted anywhere in the process was captured into the handler's buffer, so concurrent tests' logs polluted assertions such as last_message().

Under cargo's parallel test execution these made the logging tests intermittently fail.

Fix: the custom handler now

  • chains to rcl_logging_multiple_output_handler, so console/file/rosout keep working while it is installed, and
  • captures only records emitted on the thread that installed it (the test thread), so concurrently-running tests no longer pollute the captured output.

To keep the forwarded record printf-safe, impl_log now always calls rcutils_log with the "%s" + message form (instead of passing the message as the format string) and stashes the finished message in a thread-local that the handler reads back. This avoids parsing the C va_list in Rust while letting the record be forwarded to the default handler unchanged.

All changes are within #[cfg(test)] code, production logging is unchanged.

The test-only custom logging output handler (`set_logging_output_handler`,
used by the rclrs logging tests) installed itself via
`rcutils_logging_set_output_handler`, *replacing* the default
`rcl_logging_multiple_output_handler`. While installed this had two
process-global side effects:

- /rosout (and console/file) publishing was disabled, because the default
  handler that fans out to them was no longer called. A test running
  concurrently that relied on /rosout (e.g. the rosout publishing test) could
  silently lose its messages.
- Every log record emitted anywhere in the process was captured into the
  handler's buffer, so concurrent tests' logs polluted assertions such as
  `last_message()`.

Under cargo's parallel test execution these made the logging tests
intermittently fail.

Fix: the custom handler now
- chains to `rcl_logging_multiple_output_handler`, so console/file/rosout keep
  working while it is installed, and
- captures only records emitted on the thread that installed it (the test
  thread), so concurrently-running tests no longer pollute the captured output.

To keep the forwarded record printf-safe, `impl_log` now always calls
`rcutils_log` with the `"%s"` + message form (instead of passing the message
as the format string) and stashes the finished message in a thread-local that
the handler reads back. This avoids parsing the C `va_list` in Rust while
letting the record be forwarded to the default handler unchanged.

All changes are within `#[cfg(test)]` code; production logging is unchanged.
Comment on lines +270 to +271
// process-wide for the duration — breaking concurrently-running tests that
// rely on `/rosout`. The format string and `va_list` are passed through

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This change seems fine in of itself,

breaking concurrently-running tests that rely on /rosout

but to me this is the real issue. Unit tests that depend on system level properties are actually integration tests and I argue shouldn't be run concurrently.

Do you have a list of these tests that would break concurrently?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I believe it is only test_logging_macros because it replaces the logging out handler by calling set_logging_output_handler and this then intermittently breaks the other tests that subscribe to /rosout

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants