Logs are all sent to stderr

[isabelle-dr]

Issue by AntoineAugusti
Feb 22, 2022
Originally opened as CUTR-at-USF#413

---

Summary:
When running the program on the CLI in batch mode, all logs are sent to stderr even without errors.

Steps to reproduce:
Run a command like
java -jar /usr/local/bin/gtfs-realtime-validator-lib-1.0.0-SNAPSHOT.jar -gtfs file.zip -gtfsRealtimePath /tmp/path

Expected behavior:
Logs should be logged to stdout and errors should be logged to stderr

Observed behavior:
All logs, including info are sent to stderr.

This is the default behaviour of this library https://www.slf4j.org/api/org/slf4j/impl/SimpleLogger.html

org.slf4j.simpleLogger.logFile - The output target which can be the path to a file, or the special values "System.out" and "System.err". Default is "System.err".

Platform:
macOS
JDK 8

[barbeau]

@AntoineAugusti I looked at the logging implementation in the project and it seems like the log statements are sent to the appropriate channel.

For example, looking at Main.java for the batch processor:

        try {
            List<IterationStatistics> stats = processor.processFeeds();
            if (returnStats) {
                _log.info("-------------------------");
                _log.info("  Validation Statistics");
                _log.info("-------------------------");
                for (IterationStatistics stat : stats) {
                    _log.info(stat.toString());
                }
            }
        } catch (IOException | NoSuchAlgorithmException e) {
            _log.error("Error running batch processor: " + e);
        }

This is what I would expect, as the _log.info() is used in normal execution and _log.error() is used in the catch block.

Did you find specific examples you could share where you noticed the issue? Am I missing something when I look at the code?

[barbeau]

@AntoineAugusti Actually, I think I see what you're saying now. Here's the output from IntelliJ:

It looks like even though we're specifying the different logging levels within the application (which is why we see the WARN and INFO tags before the log message), at the system level SimpleLogger is still sending everything to System.err (because as you say that's the library default, and which is why we see all the application logs in red vs. white).

From a quick look I'm not sure it's possible to split SimpleLogger output at the system level to System.out AND System.err depending on the level we specify within the application (but correct me if I'm wrong). That seems silly and not the way that a logging library should work.

I do recall us having issues with slf4j previously:

• Issue - slf4j version conflict CUTR-at-USF/gtfs-realtime-validator#76
• PR that updated logging to the current state - Fix #76 (hopefully) - Overhaul logging CUTR-at-USF/gtfs-realtime-validator#81

IIRC it took some work to get the underlying components like the onebusaway-gtfs-modules and Hibernate to all be configured and output logs using the same framework. Some config info is here:
https://github.com/MobilityData/gtfs-realtime-validator/blob/master/CONFIG.md#logging

The gtfs-validator is using Flogger:
https://github.com/google/flogger

...so it might be useful to switch to Flogger here too.

LogBack also seems like a useful alternative:
https://logback.qos.ch/reasonsToSwitch.html

...although if the goal is output split between System.out and System.err we should make sure those frameworks are capable of that functionality, and that they play nicely with the logging in other libraries used in the validator. Both Flogger and Logback seem to support SLF4j. Here's the config for Flogger:
https://www.baeldung.com/flogger-logging#1-flogger-with-slf4j

@AntoineAugusti Could you say more about your use case of splitting between System.out and System.err? Is this preventing you from sending logs to the right places in your deployment of the batch validator?

[AntoineAugusti]

SimpleLogger is still sending everything to System.err

Exactly, this is why I opened this issue. Logs have different levels but they are all sent to stderr.

Could you say more about your use case of splitting between System.out and System.err?

When an error occurs during validation, we would like to display only errors to the end-user and not info logs. At the moment we are forced to display the full stack trace (validator starting up, executing and then error messages) because logs are not sent to stdout and stderr.