Delay when piping Java logback output via rainbow

[perlun]

Hi,

Thanks for a nice tool. I've been using it for about a year and find it very useful.

There is a slight issue that I've noted though, and the problem is that sometimes my log output (coming from a standard OpenJDK JVM with the logback logging library) is slightly "delayed". It feels as if there is some stdout buffering going on.

I've looked at this at the Java side, and it seems like the output should be flushed immediately, from what I can tell in the OutputStreamAppender (reference: https://github.com/qos-ch/logback/blob/master/logback-core/src/main/java/ch/qos/logback/core/OutputStreamAppender.java). Just to be even more sure, I've enabled the immediateFlush setting in my logback.groovy config:

appender( "STDOUT", ConsoleAppender ) {
    encoder( PatternLayoutEncoder ) {
        pattern = "%d{yyyy-MM-dd HH:mm:ss.SSS} %-5p [%c{1}] :: %m%n"
    }

    // Change/comment out this in cases where you want DEBUG output on stdout.
    filter( ThresholdFilter ) {
        level = DEBUG
    }

    immediateFlush = true
}

However, the problem still persists.

I'm quite certain that this has something to do with the output being piped via rainbow, even though rainbow itself might not be at fault. I did try running my Java process without piping the output, and in this case, it worked as expected - I experienced no delays; the log output was printed to stdout immediately.

Any ideas/suggestions? As stated, I'm not at all sure the problem is with rainbow itself but if you have any ideas, please do tell. It could very well be Java changing the semantics of the underlying OutputStream when stdout is being redirected; I am yet to falsify or verify this theory though.

[perlun]

Interestingly enough, when piping to cat instead of rainbow (i.e. just outputting stdin to stdout), it does not exhibit a delay. This indicates that the problem is indeed on the receiving side. Very surprising!

I tested the --disable-stderr-filtering flag, doesn't seem to help. Python 2.7.15+ (default, Nov 28 2018, 16:27:22) . I tested briefly with Python 3 but got an error on startup.

[nicoulaj]

I don't have time to test this, but there is probably some sort of bufferization in the way we read stdin here: https://github.com/nicoulaj/rainbow/blob/master/rainbow/command/stdin.py#L40

Might also be a LF vs CRLF issue ? Is this on Windows ?

You could test wrapping the command with rainbow instead: rainbow java -jar ..., it uses a completely different logic with pseudo-terminals (https://github.com/nicoulaj/rainbow/blob/master/rainbow/command/execute.py#L34), and see how it goes.

[perlun]

Thanks for the suggestions. Will try what you suggested and report back.

Might also be a LF vs CRLF issue ? Is this on Windows ?

Ah, sorry, I should have mentioned. This is on my desktop PC which is a Debian GNU/Linux machine, so all line endings should be sane LF only.

[perlun]

You could test wrapping the command with rainbow instead: rainbow java -jar ..., it uses a completely different logic with pseudo-terminals (https://github.com/nicoulaj/rainbow/blob/master/rainbow/command/execute.py#L34), and see how it goes.

Interestingly enough, this works flawlessly. Thanks a lot! 👍 I think we can close this issue as we have a workaround. Feel free to reopen if you still feel that it would be good to investigate at some point.

(The issue should hopefully be possible to find if someone runs into the same problem at some point in the future.)

[nicoulaj]

Thanks for testing, I reopen this issue since it is still a bug in stdin.py that needs fixing.

[perlun]

Thanks for testing, I reopen this issue since it is still a bug in stdin.py that needs fixing.

Any idea of when this would be fixed? I've experienced some other issues with logback lately (more specifically, https://jira.qos.ch/browse/LOGBACK-1422) so it would in a way be interesting to be able to pipe the stdout to Rainbow again, to see if this helps. (I haven't seen the problem since yesterday, so maybe maybe it's resolved by other adjustments...)

[perlun]

@nicoulaj I ran into another issue when running Rainbow with a pseudo terminal, further described here: https://jira.qos.ch/browse/LOGBACK-1422?focusedCommentId=20252&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-20252. Since it blocked proper shutdown of my Java processes, it was a bit annoying since I had to go kill -9 <pid> quite often, which is not optimal.

My workaround for now is to pipe the log output to a file instead and tail -n0 -f the_log_file.log | rainbow -f catalina, to avoid Rainbow messing with the stdout of the Java process altogether. So far, this seems to work better but I think I might be back now to some of the log output not appearing immediately... (i.e. the "bug in stdin.py that needs fixing" 😂)

[senaranya]

I had the same buffering issue. With:

tail -f /var/log/app.log |  rainbow --config=tail_log.cfg

It buffers one line and only when the next one arrives, it prints both.

(I am not able to use the execute mode as I may have more filters, and I'm not sure how to provide a composite command to rainbow)

Excellent tool btw! Makes life on terminal so much easier!