Logs are flushed when node stops

[oriolABB]

Hi,

I have some nodes running, and I can see all logs in the terminal. Also, a log file is created at $ROS_LOG_DIR per node. But, these log files are empty, until the node is stopped. It is not flushing each 5 seconds neither each 3 seconds.

Is there an option in rcl_logging to flush, almost in realtime or something like this?

Thanks,

[fujitatomoya]

Is there an option in rcl_logging to flush, almost in realtime or something like this?

assuming that you are using either humble or jazzy distro.
spdlog logger flushes periodically 5 seconds and on error level messages in default, unfortunately there is not configuration option at runtime is supported.

something you can do for now is to build the rcl_logging_spdlog with rcl, and change the following spdlog configuration in the implementation.

rcl_logging/rcl_logging_spdlog/src/rcl_logging_spdlog.cpp

Lines 202 to 203 in 2d5deed

	spdlog::flush_every(std::chrono::seconds(5));
	g_root_logger->flush_on(spdlog::level::err);

[oriolABB]

OK, thanks.

So, I was expecting to flush each 5 sec all level messages, except for debug level messages. So, it is only flushing error level messages.

Is there an explanation for that?

Regards

[fujitatomoya]

I was expecting to flush each 5 sec all level messages

actually it does.

except for debug level messages

including all log levels. (i am not sure if spdlog configuration allows us to exclude specific level like this)

it is only flushing error level messages.

i do not think this is correct.

IMO, what it does here is that the logger will flush all log data to the file system every 5 seconds. and it will also flush log data immediately when an error-level log message is logged.

after all, i think you have all you need? maybe flushing period needs to be adjusted?

note: there has been #92 to take advantage of configuration file to do this kind of configuration at runtime without code change. but it is not supported yet.

[oriolABB]

Now, I do not understand anything. If the logs are flushed every 5 seconds, could be right for me.

But, it is not the behaviour I have found, in c++ and python nodes. Log messages are only flushed to the log file when the node is stopped or killed.

When the node starts, the file is created but not a single line is written, I could wait forever, until node is killed or stops.

By the way, your assumption was right, I am using ros2 jazzy.

[fujitatomoya]

that does not happen to me...

it flushes every 5 seconds to flush the cached logging data to the file system.

### terminal-1
root@tomoyafujita:~/ros2_ws/colcon_ws# ros2 run demo_nodes_cpp talker
[INFO] [1737069338.763475334] [talker]: Publishing: 'Hello World: 1'
[INFO] [1737069339.763553187] [talker]: Publishing: 'Hello World: 2'
[INFO] [1737069340.763533728] [talker]: Publishing: 'Hello World: 3'
[INFO] [1737069341.763513610] [talker]: Publishing: 'Hello World: 4'
[INFO] [1737069342.763532563] [talker]: Publishing: 'Hello World: 5'
[INFO] [1737069343.763531528] [talker]: Publishing: 'Hello World: 6'
[INFO] [1737069344.763531288] [talker]: Publishing: 'Hello World: 7'
[INFO] [1737069345.763605210] [talker]: Publishing: 'Hello World: 8'
[INFO] [1737069346.763528636] [talker]: Publishing: 'Hello World: 9'
[INFO] [1737069347.763512919] [talker]: Publishing: 'Hello World: 10'
[INFO] [1737069348.763530897] [talker]: Publishing: 'Hello World: 11'
[INFO] [1737069349.763492066] [talker]: Publishing: 'Hello World: 12'
[INFO] [1737069350.763482345] [talker]: Publishing: 'Hello World: 13'
[INFO] [1737069351.763482753] [talker]: Publishing: 'Hello World: 14'
[INFO] [1737069352.763477084] [talker]: Publishing: 'Hello World: 15'
[INFO] [1737069353.763495838] [talker]: Publishing: 'Hello World: 16'
[INFO] [1737069354.763482375] [talker]: Publishing: 'Hello World: 17'
[INFO] [1737069355.763420706] [talker]: Publishing: 'Hello World: 18'
[INFO] [1737069356.763490976] [talker]: Publishing: 'Hello World: 19'

### terminal-2
root@tomoyafujita:~/.ros/log# cat talker_133112_1737069337749.log
[INFO] [1737069338.763475334] [talker]: Publishing: 'Hello World: 1'
[INFO] [1737069339.763553187] [talker]: Publishing: 'Hello World: 2'
[INFO] [1737069340.763533728] [talker]: Publishing: 'Hello World: 3'
[INFO] [1737069341.763513610] [talker]: Publishing: 'Hello World: 4'
[INFO] [1737069342.763532563] [talker]: Publishing: 'Hello World: 5'
[INFO] [1737069343.763531528] [talker]: Publishing: 'Hello World: 6'
[INFO] [1737069344.763531288] [talker]: Publishing: 'Hello World: 7'
[INFO] [1737069345.763605210] [talker]: Publishing: 'Hello World: 8'
[INFO] [1737069346.763528636] [talker]: Publishing: 'Hello World: 9'
[INFO] [1737069347.763512919] [talker]: Publishing: 'Hello World: 10'
[INFO] [1737069348.763530897] [talker]: Publishing: 'Hello World: 11'
[INFO] [1737069349.763492066] [talker]: Publishing: 'Hello World: 12'
[INFO] [1737069350.763482345] [talker]: Publishing: 'Hello World: 13'
[INFO] [1737069351.763482753] [talker]: Publishing: 'Hello World: 14'

[oriolABB]

Hi,

Here is what is happening to me.

Do you know what could be happening?

Thanks,

[fujitatomoya]

are you using container environment? or configure specific file system setting? since i do not have this problem on my local environment, it is hard to see what is going on, and it does not seem to be the problem with ROS?

what if use sync on the shell where your ROS 2 application is running?

[Achllle]

@oriolABB You're running tail cat and it's saying can't open file 'cat'. You can either tail -f /var/llog/.ros/some_file.log a file to follow it or cat it to print the entire file, but not both of course.