Setup : checking rcl_logging_syslog log setup and capture

[david-vexev]

Hey there. Thanks for your work on this project - we're keen to try it out. Would you be able to troubleshoot our installation of rcl_logging_syslog? We don't seem to persist ros2 logs in /var/log/ros or get them to surface into fluentbit as per the setup instructions.

Environment: Ubuntu 22.04.4
ROS2 version: Humble

Steps followed:

1. rsyslog already installed, checked with systemctl status rsyslog
2. fluentbit installed as per official docs
3. rcl_logging_syslog cloned into workspace repo, i.e. our_ros2_project/src/rcl_logging_syslog
4. export RCL_LOGGING_IMPLEMENTATION=rcl_logging_syslog
5. colcon build as per your docs
6. export RCL_LOGGING_SYSLOG_FACILITY="LOG_LOCAL2"
   6a) Also tried other LOCAL configurations 0 to 7 and all mentioned facilities
7. coppied ros2-logging to /etc/rsyslog.d/

Here is the file:

# Message Format Template
# See more details for https://www.rsyslog.com/doc/configuration/properties.html
$template TemplateName1,"%timereported% %hostname% %syslogfacility-text%.%syslogseverity-text%: %syslogtag%%msg:::sp-if-no-1st-sp%%msg:::drop-las>

# Directory and File Name Template
# See more details for https://www.rsyslog.com/doc/configuration/properties.html
### e.g) /var/log/ros/tomoyafujita/talker_428132_2024-09-04.log
$template TemplateName2,"/var/log/ros/%hostname%/%programname%_%procid%_%$now%.log"
### e.g) /var/log/ros/2024/09/04/tomoyafujita/talker_428151.log
$template TemplateName3,"/var/log/ros/%$year%/%$month%/%$day%/%hostname%/%programname%_%procid%.log"
### e.g) /var/log/ros/2024-09-04/tomoyafujita/info/talker-428214.log
$template TemplateName4,"/var/log/ros/%$now%/%hostname%/%syslogseverity-text%/%programname%-%procid%.log"

# Log locally with specified templated file name.
local1.* ?TemplateName2;TemplateName1
local2.* ?TemplateName3;TemplateName1
local3.* ?TemplateName4;TemplateName1

# For remote server, it also needs to set those templates
local1.* @@127.0.0.1:5140
local2.* @@127.0.0.1:5140
local3.* @@127.0.0.1:5140

8. rsyslogd -N1 confirms correct format
9. sudo systemctl restart rsyslog
10. coppied fluentbit conf file and modified:

[SERVICE]

    flush        1
    daemon       Off
    log_level    info

    # Parsers File
    # ============
    # specify an optional 'Parsers' configuration file
    parsers_file parsers.conf

    http_server  Off
    http_listen  0.0.0.0
    http_port    2020

    storage.metrics on

[INPUT]
    name syslog
    parser syslog-rfc3164
    listen 127.0.0.1
    port 5140
    mode tcp

[OUTPUT]
    name  stdout
    match *

11. fluentbit started with /opt/fluent-bit/bin/fluent-bit --config=./fluent-bit.conf
12. ros2 talker cpp started

No rsyslog forwarded logs observed in fluentbit and no ros2 logs appear in /var/log/ros locations

I'm not sure where rcl_logging_syslog wants to export logs to. Default log locations for ros2 were in the user home directory, so should the rsyslog locations such as /var/log/ros/2024/09/04/tomoyafujita/talker_428151.log actually point to /home/me/.ros/log/... instead? I can see my talker logs persisting to: talker_1443674_1726813326477.log after rcl_logging_syslog has been built and run, so I tried changing the rsyslog TemplateName2 to my home directory ros log location /home/me/.ros/log/%programname%_%procid%_%$now%.log but that didn't seem to help - no logs in /var/log, nothing in fluentbit.

Also, should RCL_LOGGING_SYSLOG_FACILITY and the local1 entries in the rsyslog.d config file match i.e. if we choose LOCAL1, it will match the local1 entry?

Any help is appreciated, thank you

[fujitatomoya]

@david-vexev thanks for creating issue, and trying this out with humble.

should the rsyslog locations such as /var/log/ros/2024/09/04/tomoyafujita/talker_428151.log actually point to /home/me/.ros/log/... instead?

depends on application and requirement. if you want the logging directory to be pointed to under home directory, that you can configure. those templates are just examples. i expect that once rsyslog receives the log data, that should be managed under rsyslog access permission, so i would not store the logging data under some user's home folder.

can see my talker logs persisting to: talker_1443674_1726813326477.log after rcl_logging_syslog has been built and run,

that means you are still using default logging backend which is rcl_logging_spdlog not rcl_logging_syslog.

a couple of questions,

• are you building all packages with source build? https://docs.ros.org/en/humble/Installation/Alternatives/Ubuntu-Development-Setup.html (my guess is no for this, you have base humble-desktop package installed, and you are building your applications within your workspace only, right?)
• did you build the rcl package aligned with rcl_logging_syslog, via colcon build --symlink-install --cmake-clean-cache --packages-select rcl_logging_syslog rcl and source that workspace? this is unclear from the documentation so that i need to update, the thing is that we cannot select the logging backend at runtime (see [FR] select the logger implementation without rebuilding ros2/rcl#1178). that said, logging backend is bound with rcl during the build time, and rcl release package (means not source building on your own) always uses rcl_logging_spdlog. so i am expecting that you just DID build rcl_logging_syslog but not using that. can you try the following with your own workspace?

cd <your workspace>/src
git clone https://github.com/fujitatomoya/rcl_logging_syslog.git
git clone -b humble [email protected]:ros2/rcl.git
cd <your workspace>/

export RCL_LOGGING_IMPLEMENTATION=rcl_logging_syslog
colcon build --symlink-install --cmake-clean-cache --packages-select rcl_logging_syslog rcl
source install/setup.bash

the procedure and configuration files look just fine for me.

[fujitatomoya]

@david-vexev friendly ping.

[david-vexev]

Thank you for your patient and thorough reply! You are right - I used the humble-desktop Ubuntu deb package for my workspace and did not clone in ros2/rcl.git. I will attempt now to install ros2 humble from source and symlink-install both the rcl and logging libraries together, then report back.

[fujitatomoya]

@david-vexev thanks, the reason i did not realize this situation is that i always work on the mainline and build the source code. but as you reported here, that is not the situation for application perspective. if you share the result that would be really appreciated.

[david-vexev]

I downloaded and installed ros2 humble from source following these instructions. I then made an empty workspace called test_logger and cloned rcl and rcl_logging_syslog in there. With sourcing my locally-build ros2, exporting the LOG build-time command and running colcon build I get this error:

[my system]:~/test_logger$ colcon build --symlink-install --cmake-clean-cache --packages-select rcl_logging_syslog rcl

[0.329s] WARNING:colcon.colcon_core.package_selection:Some selected packages are already built in one or more underlay workspaces:
	'rcl' is in: /home/me/ros2_humble/install/rcl
If a package in a merged underlay workspace is overridden and it installs headers, then all packages in the overlay must sort their include directories by workspace order. Failure to do so may result in build failures or undefined behavior at run time.
If the overridden package is used by another package in any underlay, then the overriding package in the overlay must be API and ABI compatible or undefined behavior at run time may occur.

If you understand the risks and want to override a package anyways, add the following to the command line:
	--allow-overriding rcl

This may be promoted to an error in a future release of colcon-override-check.
Starting >>> rcl_logging_syslog
Finished <<< rcl_logging_syslog [1.49s]                     
Starting >>> rcl
[1.829s] WARNING:colcon.colcon_core.shell:The following packages are in the workspace but haven't been built:
- rcl_yaml_param_parser
They are being used from the following locations instead:
- /home/vexev/ros2_humble/install/rcl_yaml_param_parser
To suppress this warning ignore these packages in the workspace:
--packages-ignore rcl_yaml_param_parser
--- stderr: rcl                               
/usr/bin/ld: ../librcl.so: undefined reference to `rcl_logging_external_initialize'
collect2: error: ld returned 1 exit status
gmake[2]: *** [test/CMakeFiles/test_rmw_impl_id_check_exe.dir/build.make:129: test/test_rmw_impl_id_check_exe] Error 1
gmake[1]: *** [CMakeFiles/Makefile2:422: test/CMakeFiles/test_rmw_impl_id_check_exe.dir/all] Error 2
gmake[1]: *** Waiting for unfinished jobs....
gmake: *** [Makefile:146: all] Error 2
---
Failed   <<< rcl [10.1s, exited with code 2]

Summary: 1 package finished [11.8s]
  1 package failed: rcl
  1 package had stderr output: rcl

I also tried to un-source my local ros2 humble and rerun the colcon build in a new terminal. I suspect I'm not doing something right with the ros2 sourcing as it's warning about an underlay override in my local build. This rcl_logging_external_initialize also appears when I try to colcon build with my deb package sourced version of ros2 in opt

Happy to help out with more testing - sorry if these logs are not quite pointing in the right direction.

[fujitatomoya]

So with rolling the following procedure just works.

tomoyafujita@~/DVT >docker run -it --rm ros:rolling
root@cbb36102a87b:/# apt update && apt upgrade -y
root@5fbbf9b8346c:~# apt install ros-rolling-ros-base
root@5fbbf9b8346c:~# apt install -y ros-dev-tools
root@5fbbf9b8346c:~# cd && mkdir -p workspace/src/ && cd workspace/src/
root@5fbbf9b8346c:~/workspace/src# git clone https://github.com/fujitatomoya/rcl_logging_syslog.git
root@5fbbf9b8346c:~/workspace/src# git clone -b rolling https://github.com/ros2/rcl.git
root@5fbbf9b8346c:~/workspace/src# git clone -b rolling https://github.com/ros2/rcl_logging.git
root@353e28a50105:~/workspace/src# cd ../
root@353e28a50105:~/workspace/src# apt install -y ros-rolling-mimick-vendor ros-rolling-test-msgs ros-rolling-demo-nodes-cpp ros-rolling-demo-nodes-py ros-rolling-osrf-testing-tools-cpp ros-rolling-performance-test-fixture
root@353e28a50105:~/workspace/src# source /opt/ros/rolling/setup.bash
root@353e28a50105:~/workspace/src# export RCL_LOGGING_IMPLEMENTATION=rcl_logging_syslog
root@353e28a50105:~/workspace/src# colcon build --symlink-install --cmake-clean-cache

log messages in the file system via rsyslog,

root@1ebd9147068c:/var/log# find ros/
ros/
ros/1ebd9147068c
ros/1ebd9147068c/talker_8759_2024-09-24.log
root@1ebd9147068c:/var/log# cat ros/1ebd9147068c/talker_8759_2024-09-24.log
Sep 24 23:10:20 1ebd9147068c local1.info: talker[8759]: [INFO] [1727219420.266692525] [talker]: Publishing: 'Hello World: 1'
Sep 24 23:10:21 1ebd9147068c local1.info: talker[8759]: [INFO] [1727219421.266661300] [talker]: Publishing: 'Hello World: 2'
Sep 24 23:10:22 1ebd9147068c local1.info: talker[8759]: [INFO] [1727219422.266745949] [talker]: Publishing: 'Hello World: 3'
Sep 24 23:10:23 1ebd9147068c local1.info: talker[8759]: [INFO] [1727219423.266779083] [talker]: Publishing: 'Hello World: 4'
Sep 24 23:10:24 1ebd9147068c local1.info: talker[8759]: [INFO] [1727219424.266700325] [talker]: Publishing: 'Hello World: 5'
Sep 24 23:10:25 1ebd9147068c local1.info: talker[8759]: [INFO] [1727219425.266680812] [talker]: Publishing: 'Hello World: 6'
Sep 24 23:10:26 1ebd9147068c local1.info: talker[8759]: [INFO] [1727219426.266697324] [talker]: Publishing: 'Hello World: 7'
Sep 24 23:10:27 1ebd9147068c local1.info: talker[8759]: [INFO] [1727219427.266764715] [talker]: Publishing: 'Hello World: 8'
Sep 24 23:10:28 1ebd9147068c local1.info: talker[8759]: [INFO] [1727219428.266691083] [talker]: Publishing: 'Hello World: 9'
Sep 24 23:10:29 1ebd9147068c local1.info: talker[8759]: [INFO] [1727219429.266762235] [talker]: Publishing: 'Hello World: 10'
Sep 24 23:10:30 1ebd9147068c local1.info: talker[8759]: [INFO] [1727219430.266693370] [talker]: Publishing: 'Hello World: 11'
Sep 24 23:10:31 1ebd9147068c local1.info: talker[8759]: [INFO] [1727219431.266688295] [talker]: Publishing: 'Hello World: 12'
Sep 24 23:10:32 1ebd9147068c local1.info: talker[8759]: [INFO] [1727219432.266742917] [talker]: Publishing: 'Hello World: 13'
Sep 24 23:10:33 1ebd9147068c local1.info: talker[8759]: [INFO] [1727219433.266660773] [talker]: Publishing: 'Hello World: 14'
Sep 24 23:10:34 1ebd9147068c local1.info: talker[8759]: [INFO] [1727219434.266736714] [talker]: Publishing: 'Hello World: 15'

but with humble, i can reproduce the following error.

--- stderr: rcl
/usr/bin/ld: ../librcl.so: undefined reference to `rcl_logging_external_initialize'
collect2: error: ld returned 1 exit status
gmake[2]: *** [test/CMakeFiles/test_rmw_impl_id_check_exe.dir/build.make:129: test/test_rmw_impl_id_check_exe] Error 1
gmake[1]: *** [CMakeFiles/Makefile2:306: test/CMakeFiles/test_rmw_impl_id_check_exe.dir/all] Error 2
gmake[1]: *** Waiting for unfinished jobs....
/usr/bin/ld: ../librcl.so: undefined reference to `rcl_logging_external_initialize'
/usr/bin/ld: ../librcl.so: undefined reference to `rcl_logging_external_initialize'
...

i think that we have ABI/API incompatible issue here. 1st i will check that with source build with humble.

[fujitatomoya]

@david-vexev can you try with humble branch, https://github.com/fujitatomoya/rcl_logging_syslog/tree/humble? as far as i tested, it works no problem.

[david-vexev]

Thanks @fujitatomoya - I checked out the humble branch into my test_logger project (with rcl and rcl_logging_syslog cloned into it), then export RCL_LOGGING_IMPLEMENTATION=rcl_logging_syslog and I was able to build successfully. Then, sourcing my test_logger/install/setup.bash environment and running talker, I observed that the talker logs were no longer populating into ~/.ros/log - that's a good first step! However, I can't see a ros folder in my /var/log directory. I'll continue to look for the location of the exported logs

[fujitatomoya]

@david-vexev that works as expected, if you are good, can you close this issue?

[david-vexev]

Thanks for your help!