Newline is printed before log message if messages are colored and the output is a terminal

[deeenes]

To reproduce the issue:

library(logger)
log_layout(layout_glue_colors)
log_success('foo bar')
#
# SUCCESS [2021-03-21 03:34:20] foo bar>

Apparently it happens only if coloring is involved:

library(logger)
lo <- '{level} {msg}'
log_layout(layout_glue_generator(format = lo))
log_success('foo bar')
# > SUCCESS foo bar
lo <- '{colorize_by_log_level(level, levelr)} {msg}'
log_layout(layout_glue_generator(format = lo))
log_success('foo bar')
#
# SUCCESS foo bar>

It doesn't happen with appender_file, only appender_console. I tried with URxvt, Xterm, a QML/qterm based and the virtual tty console. All these behave the same way. Another interesting point: when the log messages are sent in a long process, the new lines are printed many seconds earlier, and the messages usually only at the very end. This issue appeared with version 0.2.0, the previous CRAN version was still working good.

[deeenes]

I could reproduce this without logger, just by writing crayon colored lines to stderr:

Without colors:

lines <- c('log line 1', 'log line 2', 'log line 3')
cat(lines, file = stderr(), sep = '\n')
# log line 1
# log line 2
# log line 3

With colors:

require(crayon)
lines <- c('log line 1', 'log line 2', 'log line 3')
clines <- sapply(lines, function(l){paste0(make_style('green4'), l, reset(''))}, USE.NAMES = FALSE)
cat(clines, file = stderr(), sep = '\n')
#
#
#
# log line 1log line 2log line 3>

And I found a possible solution, using stdout the console output is correct:

cat(clines, file = stdout(), sep = '\n')
# log line 1
# log line 2
# log line 3

[deeenes]

I see you changed appender_console from stdout to stderr in 46b4f1fc in relation to #28, I am wondering if there is a strong reason. For me seems to be the easiest solution to revert it.

[deeenes]

I found out this is actually a colorout issue: https://github.com/jalvesaq/colorout/issues/24

[daroczig]

I see you changed appender_console from stdout to stderr in 46b4f1f in relation to #28, I am wondering if there is a strong reason. For me seems to be the easiest solution to revert it.

Well, normal and diagnostic messages of an app should not mix -- as per my understanding, that's the idea behind stdout and stderr, so logs are ideally written to the latter. This is extremely useful when piping the output of a program to the other one, when the log messages should not interfere with the standard output of the first app. This has been also an industry practice in many logging packages as far as I know.

So yeah, I don't have plans to revert that change, it was very intentional.

On the other hand, if you need colored logging in console and this is causing issues, I guess you can simply update your appender to write to stdout via appender_stdout, no? I mean that would be the revert of the stderr update in your local environment.

[deeenes]

You are completely right, especially that it's an issue between two other packages (crayon & colorout). Still, maybe you can include the workaround above if you like it.

[daroczig]

Thanks, @deeenes -- but I'd rather not update appender_console with this by default. Hopefully folks, who might be affected by this, will be able to find this thread, and use your workaround in their appended, or just write to stdout instead.