Support for logging via rcutils by dhood · Pull Request #102 · ros2/rclpy

dhood · 2017-08-19T01:33:08Z

connects to #103

Could I get some feedback on the direction this is going in? I add logging as an additional module of the rclpy package but it might belong in its own package or in the rclpy module itself.

wjwwood · 2017-08-19T01:51:59Z

Looks reasonable to me so far. It could either be its own module or part of the existing one. I don't think it needs to be in a separate package. Is there any downside to initializing it automatically?

dirk-thomas

A separate library within the same package looks good to me. We can always change it later if we see a reason to do so.

dirk-thomas · 2017-08-22T16:37:24Z

rclpy/CMakeLists.txt

+target_include_directories(${library_name}
+  PUBLIC
+  ${PythonExtra_INCLUDE_DIRS}
+)


Instead of duplicating the logic to update the target with various information this should be moved into a function for reuse.

dirk-thomas · 2017-08-22T16:41:14Z

rclpy/src/rclpy/_rclpy_logging.c

+static struct PyModuleDef _rclpy_logging_module = {
+  PyModuleDef_HEAD_INIT,
+  "_rclpy_logging",
+  "_rclpy_logging_doc",


Instead of a dummy this should be NULL or a actual docstring.

dirk-thomas · 2017-08-22T16:45:50Z

rclpy/test/test_logging.py

+    def setUpClass(cls):
+        rclpy.logging.initialize()
+
+    def test_set_get_severity_threshold(self):


Nitpick about the name: Use *_get_set_* (since that is the order used in the test) or just test_severity_threshold.

Just set and get severity level at the moment

This should be consistent with the C implementation of features in rcutils

In the C implementation in rcutils, all features are static.

@dirk-thomas

@dirk-thomas mentioned someone might want to import the module, use a custom logging configuration, and then initialise. If we always initialise then the custom initialisation won't have an effect.

… callers

Also, the object as the context key wasn't unique so go back to using pickle

In anticipation of the global threshold being replaced by ones specific to each logger.

It was originally templated to reduce the coupling between the python enum and the rcutils C enum, but the names were still coupled anyway.

Add an option to return the result of the log condition

dhood · 2017-09-07T01:51:13Z

To fix _find_caller on windows, I had to introduce pathlib.Path().resolve() wrappers to each of the filenames returned by inspect.getabsfile(). This is because inspect.getabsfile() appears to return paths as lowercase on windows (only). Using pathlib.Path().resolve() corrects the case somehow (not sure how it would deal with ambiguity?).

Another issue on Windows was that, surprisingly to me, the __file__ attribute of the module had a mix of forward and backwards slashes.. So I applied the same approach to the internal filenames.

Most of this was done in 6c6917f; if there's a cleaner way that avoids lower casing everything I'm interested.

Example usage on windows is:

[INFO] []: message (test_log_arguments() at C:\J\workspace\ci_windows\ws\src\ros2\rclpy\rclpy\test\test_logging.py:128)

and on linux:

[INFO] []: message (test_log_arguments() at /home/dhood/ros2_ws/src/ros2/rclpy/rclpy/test/test_logging.py:128)

dhood · 2017-09-07T01:54:50Z

there are still a few outstanding comments that I will respond to tomorrow

dirk-thomas

Regarding inspect.getabsfile(): since this function is not publically documented I was wondering if another approach to get the same information has the same case problem on Windows. Have you tried os.path.abspath(inspect.getframeinfo(frame).filename) instead?

dirk-thomas · 2017-09-07T17:17:33Z

rclpy/rclpy/impl/rcutils_logger.py

+    return frame
+
+
+class CallerId:


Maybe the class could use __slots__ if it is never intended to be extended with additional attributes.

That would also make the implementation of __hash__ and __eq__ easier by just iterating the slots and avoiding the repetition of the member names.

I made use of __slots__ as you suggested in d34a86c but then figured what we really want is a named tuple so switched to that in b4a8787

Even nicer! 🥇

dirk-thomas · 2017-09-07T17:18:23Z

rclpy/rclpy/impl/rcutils_logger.py

+        if not frame:
+            frame = _find_caller(inspect.currentframe())
+        self.function_name = frame.f_code.co_name
+        self.file_name = _normalize_path(inspect.getabsfile(frame))


For file_name I would only expect the name of the file but not its full path. Maybe rename to file_path?

yeah, fair call: renamed in 5507e4e

dirk-thomas · 2017-09-07T19:31:40Z

rclpy/rclpy/impl/rcutils_logger.py

+        # This has to be done from within a function to avoid cyclic module imports.
+        import rclpy.logging
+        # Extend the list to preserve any filenames that may have been added by third parties.
+        # Note: the call to `abspath` will also resolve mixed slashes that can result on Windows.


Using realpath will also resolve symlinks and therefore ensure that they compare equal even if one is a symlink of the other.

thanks! I changed it in c4ae7a7 but only for the _find_caller function. the file path that will displayed in the logging call is still using abspath because I thought that would be more what users are expecting (but maybe not)

This reverts commit 5cf9c54.

…ut while rebasing)

Leave the final file path that gets displayed as-is for usability.

Hard-code the filter options for now

dhood · 2017-09-07T22:26:18Z

Indeed using os.path.abspath to get the absolute path instead of inspect.getabsfile prevents the case change, thanks @dirk-thomas. I switched to that in b028243 and 06367b0
I noted in the code comments that the abspath on the internal filenames is needed because otherwise __file__ can include a mix of slash directions on Windows e.g. (output as debug print from this job):

Internal callers: ['C:/J/workspace/ci_windows/ws/src/ros2/rclpy/rclpy\\rclpy\\impl\\rcutils_logger.py', 'C:/J/workspace/ci_windows/ws/src/ros2/rclpy/rclpy\\rclpy\\logging.py']

Update on the aforementioned todos:

Currently all loggers are using the global severity threshold from rcutils: this will stay until we have a way to set thresholds with more granularity in rcutils.
All of the convenience functions take the same set of filter options but none of them have been documented which inhibits autocompletion: I hard-coded documentation for the main log method and referenced it from the other callers in dea180d. We can avoid the hard-coding of filter options at a later date.
'function' and/or 'expression' filter support: post-PR enhancement.
Allow log calls to take a format string + args (currently only pre-formatted strings are supported): post-PR enhancement for ROS 1 compatibility.
Use rcutils instead of python time: post-PR enhancement.

With that, I'll put this back in review (I think I've addressed the comments to date, LMK if I missed something)

dirk-thomas

🚢 with green CI

dhood · 2017-09-08T00:03:57Z

🚢 🚢 🎉

Linux
Linux-aarch64
macOS
Windows

…tests-to-test-logger Fixed test that failed without ROS_PACKAGE_PATH being set, and add test_log

dhood added the in progress Actively being worked on (Kanban column) label Aug 19, 2017

dhood self-assigned this Aug 19, 2017

dhood force-pushed the rclpy_logging branch from 341797b to 60446c0 Compare August 19, 2017 01:35

dirk-thomas reviewed Aug 22, 2017

View reviewed changes

dhood force-pushed the rclpy_logging branch from 1470880 to ff28334 Compare August 31, 2017 18:34

dhood added 24 commits September 1, 2017 10:33

Initial support for logging via rcutils

8b5ff4a

Just set and get severity level at the moment

Factor out common cmake code for python c extensions

85a8fb7

proper module docstring

898eaa7

templated c extension and kwargs support

e3ea4f2

Call to rcutils_log() instead of logging macros

b74a091

Infer the caller frame; get the calling function name

1925cb9

Once one feature decides not to log, don't check the others

3d5761e

This should be consistent with the C implementation of features in rcutils

Pass location info through to rcutils

3040ae5

Prevent features from changing between log calls

09ddfab

In the C implementation in rcutils, all features are static.

Documentation

481c8fd

Update terminology (feature->filter)

75e13e7

Remove pickle usage (hashable fine without...)

c0b3fb7

Autoinit for each log call instead of initialising on module import

4c8e37b

@dirk-thomas mentioned someone might want to import the module, use a custom logging configuration, and then initialise. If we always initialise then the custom initialisation won't have an effect.

Determine non-rclpy calling frame using full filenames of known rclpy…

b278fba

… callers

more rename

ffa5c8f

Store Filter param values in context and don't allow them to change

937fb0e

Also, the object as the context key wasn't unique so go back to using pickle

More variable renames to avoid builtin of filter

d4bce53

Ensure that the ordered dict contains the order that we want..

1ad3c3f

Raise un unknown keyword args; remove name from kwargs

fd61920

Add _sec to throttle_duration keyword to match spin args

de96bbc

Filter based on severity threshold in python instead of C extension

908f83b

In anticipation of the global threshold being replaced by ones specific to each logger.

Pass severity as argument instead of templating functions

45ec482

It was originally templated to reduce the coupling between the python enum and the rcutils C enum, but the names were still coupled anyway.

Make the logging C extension not an empy template (no need anymore)

ede7e55

Programmatically test the functionality

d0d6556

Add an option to return the result of the log condition

dhood force-pushed the rclpy_logging branch from 873dd37 to 3090835 Compare September 7, 2017 16:52

Ensure that severity that gets passed to C is LoggingSeverity enum

9895ca8

dhood force-pushed the rclpy_logging branch from 3090835 to 9895ca8 Compare September 7, 2017 16:55

Allow CallerId to be dict key to remove pickle usage

80042de

dirk-thomas reviewed Sep 7, 2017

View reviewed changes

dhood added 6 commits September 7, 2017 11:39

Use slots for CallerId storage

d34a86c

Make CallerId inherit from namedtuple to avoid reimplementing hash etc

b4a8787

Use os.path.abspath instead of inspect.getabsfile

b028243

Narrower scope for global declaration

5cf9c54

Rename file name to path where appropriate

5507e4e

Add false to once message that is expected multiple times

df71ac3

dirk-thomas reviewed Sep 7, 2017

View reviewed changes

dhood added 5 commits September 7, 2017 12:59

Revert "Narrower scope for global declaration"

e6396b2

This reverts commit 5cf9c54.

Replace inspect.getabsfile with inspect.getframeinfo (this got left o…

06367b0

…ut while rebasing)

Use os.realpath instead of os.abspath for symlinks during comparisons

c4ae7a7

Leave the final file path that gets displayed as-is for usability.

linter version updated

767bfc0

Add one main docstring and link to it from other log calls

dea180d

Hard-code the filter options for now

dirk-thomas approved these changes Sep 7, 2017

View reviewed changes

dhood merged commit 48b632f into master Sep 8, 2017

dhood deleted the rclpy_logging branch September 8, 2017 00:12

dhood removed the in review Waiting for review (Kanban column) label Sep 8, 2017

This was referenced Sep 8, 2017

Expose logging macros in rclpy #103

Closed

default to c11 #118

Merged

define docstring as in logging module #119

Merged

dhood mentioned this pull request Nov 20, 2017

Give nodes a logger #148

Merged

YuanYuYuan pushed a commit to YuanYuYuan/rclpy that referenced this pull request Nov 12, 2025

Merge pull request ros2#102 from Carter12s/fix-test-and-move-codegen-…

56c425d

…tests-to-test-logger Fixed test that failed without ROS_PACKAGE_PATH being set, and add test_log

Conversation

dhood commented Aug 19, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

wjwwood commented Aug 19, 2017

Uh oh!

dirk-thomas left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

dhood commented Sep 7, 2017

Uh oh!

dhood commented Sep 7, 2017

Uh oh!

dirk-thomas left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

dhood commented Sep 7, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

dirk-thomas left a comment

Choose a reason for hiding this comment

Uh oh!

dhood commented Sep 8, 2017

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

dhood commented Aug 19, 2017 •

edited

Loading

dhood commented Sep 7, 2017 •

edited

Loading