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.

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

changing default logging format to include timestamp #190

Merged
merged 3 commits into from Nov 22, 2019

Conversation

SteveMacenski
Copy link
Contributor

@SteveMacenski SteveMacenski commented Nov 13, 2019

Covers #189

Adds a timestamp to the default logging format. I think this is a reasonable default behavior.

Signed-off-by: stevemacenski <stevenmacenski@gmail.com>
@wjwwood
Copy link
Member

wjwwood commented Nov 21, 2019

Does anyone have time to summarize how it works in ROS 1? I want to say that the default for the console did not include the timestamps, but the timestamps were included in the file logging. So you could reduce clutter on the console (timestamp is slightly less necessary when you're observing it live), but you could always go to the file log for exact timestamps.

@SteveMacenski
Copy link
Contributor Author

SteveMacenski commented Nov 21, 2019

I want to say that the default for the console did not include the timestamps

ROS1 did have timestamps to screen. I've stared at alot of log files at Simbe 😆

Example: just launched something on my machine with base settings:

process[slam_toolbox-2]: started with pid [29493]
[ INFO] [1574379313.580597739]: CeresSolver: Using SCHUR_JACOBI preconditioner.
[ INFO] [1574379313.581772142]: Using plugin solver_plugins::CeresSolver

@wjwwood
Copy link
Member

wjwwood commented Nov 21, 2019

ROS1 did have timestamps to screen.

👍 Yeah, it's fine with me to add the timestamp by default.

src/logging.c Outdated Show resolved Hide resolved
Signed-off-by: stevemacenski <stevenmacenski@gmail.com>
@SteveMacenski
Copy link
Contributor Author

SteveMacenski commented Nov 22, 2019

Good point, done

@wjwwood
Copy link
Member

wjwwood commented Nov 22, 2019

CI:

  • Linux Build Status
  • Linux-aarch64 Build Status
  • macOS Build Status
  • Windows Build Status

Copy link
Member

@wjwwood wjwwood left a comment

lgtm, I'll ask the team to have a look again before merging it, maybe tomorrow (assuming CI is good)

@SteveMacenski
Copy link
Contributor Author

SteveMacenski commented Nov 22, 2019

assuming CI is good

If I've managed to mess up something to break CI with a 1 line string change, feel free to put me out to pasture

@wjwwood
Copy link
Member

wjwwood commented Nov 22, 2019

If I've managed to mess up something to break CI with a 1 line string change, feel free to put me out to pasture

It wouldn't be the first time for me. :)

My only real thought is that it might break some (imo fragile) tests that's expecting a certain output from the logger or something like that.

@SteveMacenski
Copy link
Contributor Author

SteveMacenski commented Nov 22, 2019

aaarg. Linux failed.

@dirk-thomas
Copy link
Member

dirk-thomas commented Nov 22, 2019

I would guess you need to rebase you branch on top of the latest state of the target branch.

@SteveMacenski
Copy link
Contributor Author

SteveMacenski commented Nov 22, 2019

16:13:14 /home/jenkins-agent/workspace/ci_linux/ws/src/ros2/rclcpp/rclcpp/resource/logging.hpp.em:80: error: <class 'TypeError'>: can only concatenate tuple (not "str") to tuple
16:13:14 CMakeFiles/rclcpp.dir/build.make:61: recipe for target 'include/rclcpp/logging.hpp' failed

Lets try that.

@SteveMacenski
Copy link
Contributor Author

SteveMacenski commented Nov 22, 2019

Yal are squashing this anyhow. Just pulled in.

@wjwwood
Copy link
Member

wjwwood commented Nov 22, 2019

Yeah, it's really a limitation of our CI when testing forks (it doesn't try to merge with target branch).

New CI:

  • Linux Build Status
  • Linux-aarch64 Build Status
  • macOS Build Status
  • Windows Build Status

@SteveMacenski
Copy link
Contributor Author

SteveMacenski commented Nov 22, 2019

phew saved by an updated target. I'm safe from the farm upstate for another day...

@wjwwood wjwwood merged commit 540d947 into ros2:master Nov 22, 2019
1 check passed
@wjwwood
Copy link
Member

wjwwood commented Nov 22, 2019

Thanks @SteveMacenski!

@dirk-thomas
Copy link
Member

dirk-thomas commented Nov 22, 2019

This should be documented on the release page (currently for F-turtle) to mentioned the change.

@wjwwood
Copy link
Member

wjwwood commented Nov 22, 2019

Good point, I'll keep this tab open until we've announced the new name and have an F-turtle release page on ros2/ros2_documentation.

@wjwwood
Copy link
Member

wjwwood commented Nov 23, 2019

@wjwwood
Copy link
Member

wjwwood commented Dec 6, 2019

@SteveMacenski do you have time to look at the above test regressions that @ivanpauno pointed out?

I'll have a look next week if you can't, but we'd appreciate it.

@SteveMacenski
Copy link
Contributor Author

SteveMacenski commented Dec 7, 2019

@wjwwood I hadn't looked at it.

Maybe I'm missing the punchline, but I don't see anything in those links that makes me think there's an issue (except the CLI PR already merged), can you point out specific lines or what you're referencing?

I'll help fix issues from logging changes, but I'm pretty shocked there are tests created based on a logging format

@wjwwood
Copy link
Member

wjwwood commented Dec 7, 2019

It's checking the output of the commands and they don't match anymore.

can you point out specific lines or what you're referencing?

https://ci.ros2.org/view/nightly/job/nightly_linux_repeated/1705/testReport/junit/test_rclcpp/TestExecutableOutputAfterShutdown/test_signal_handler_before_shutdown/

That link has an assert error that the expected output did not match the actual output.

I'll help fix issues from logging changes, but I'm pretty shocked there are tests created based on a logging format

Well, it could be improved by the tests manually setting the log output to ensure it doesn't deviate due to changes in the system default. Or the output matching can be relaxed to match any logging format (it can use regex).

@SteveMacenski
Copy link
Contributor Author

SteveMacenski commented Dec 7, 2019

AssertionError: Did not find '['Registered custom signal handler.', 'Called rclcpp::init.', 'Waiting to give an opportunity for interrupt...', '[INFO] [rclcpp]: signal_handler(signal_value=2)', 'Custom sigint handler called.', 'Calling rclcpp::shutdown...', 'Called rclcpp::shutdown.', 'Waiting to give an opportunity for interrupt...', 'Exiting.']' in output for any of the matching processes: test_signal_handler-1

Thats... a little esoteric to pick up on the fact that that's a formatting error 😆. I'll add to my queue to look at next week.

@nuclearsandwich
Copy link
Member

nuclearsandwich commented Dec 7, 2019

I started updating some tests in ros2/demos#420. I chose to specify a logging format in the test to prevent future changes to the defaults from breaking the tests again.

@SteveMacenski
Copy link
Contributor Author

SteveMacenski commented Dec 9, 2019

OK so traced down that link and looks like @nuclearsandwich got to it here.

First time pushing something this low into the ROS2 stack. Trying to think about future PRs how I can avoid these issues or fix things proactively on failure rather than making yal come to the rescue -- so where was the starting point that led you to problems being introduced here? If I know where to look, I can follow through down to these myself. I'm assuming it started with the nightly build, I see a bunch of options (release, debug, repeated, with specific RMWs) is there one you're looking at as a default?

@nuclearsandwich
Copy link
Member

nuclearsandwich commented Dec 9, 2019

I have slightly different workflows depending on the situation but if a failure is in an environment I can easily reproduce like nightly_linux_{debug,release} I'll usually start there since I can work locally as well as with CI. https://index.ros.org/doc/ros2/Contributing/Build-Cop-and-Build-Farmer-Guide/ is our doc on being the build farmer but I can't recall when it was last touched. It would be a good idea for us to document the current nightly platforms and job variants for contributors.


The test failures weren't caught by Pull request CI because of the tight scoping for the branch builds to limit resource usage and time spent on CI. We try to limit CI to packages which are directly affected by the change. Because of the way tests were written, more packages were affected than tested.

@SteveMacenski
Copy link
Contributor Author

SteveMacenski commented Dec 9, 2019

Got it, thanks!

ferranm99 added a commit to ferranm99/ferran-ros that referenced this pull request May 20, 2022
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.

None yet

7 participants