SelectiveLogConsumer - a way to reduce noise while still capturing important information

[beargiles]

Server logs are phenomal resources. In many cases your client might get a generic response that provides you little to no hints at what the actual problem is. Meanwhile, the server log spells it out - syntax error, lacking a specific permission, etc.

The default options seem to be "log everything" and "log nothing".

In my experience a reasonable compromise is to identify the difference in our needs between when the server is starting (often very verbose) and once it's fully up (often concise and limited to why specific client calls failed). Not all servers follow this pattern, of course, but this has been a good launching point.

A secondary issue is that many servers produce similar logs as the TestContainer. This is noisy and can cause confusion since the normal filtering, e.g., by log level, doesn't always work as expected.

The code below attempts to extract the logging level of the message and use it instead of the generic INFO and WARNING. This will let us filter by severity.

I've had some luck explicitly removing any timestamp, etc., from the logged message. It definitely reduces the visual clutter. I haven't included it below since I'm currently investigating what we see with different --log-driver values.

The best way to handle the switch appears to be extending waitForContainerStarted():

public class MyContainer<SELF extends MyContainer> extends ... {

    protected void waitUntilContainerStarted() {
        super();

        // use reflection to make 'logConsumers' visible

        for (Consumer<OutputFrame> consumer : logConsumers) {
            if (consumer instanceof SelectiveLogConsumer) {
                ((SelectiveLogConsumer) consumer).setIgnored(false);
            }
        }
    }

We still want to support both ALL and NONE since we'll often want the former option when we're first setting up the container (it tells us the actual configuration) and may want to use the latter in CI/CD in order to reduce log size since our tests should never fail by this point.

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.event.Level;
import org.testcontainers.containers.output.OutputFrame;
import org.testcontainers.utility.DockerImageName;

import java.util.function.Consumer;

// note: this specific implementation hasn't been fully tested - it's for discussion only

/**
 * Selective TestContainer log consumer.
 * <p>
 * The "ALL" and "NONE" logging levels are self-explanatory.
 * <p>
 * The "SOME" logging level attempts to skip log messages until the docker container is successfully started.
 * The "setIgnored()" method must be explicitly called.
 * <p>
 * Enhancement: add MDC containing basic information about the Docker Container.
 */
public class SelectiveLogConsumer implements Consumer<OutputFrame> {

    private static final Logger LOG = LoggerFactory.getLogger(SelectiveLogConsumer.class);

    /**
     * Logging levels
     */
    public enum LoggingLevel {
        /**
         * Log everything
         */
        ALL,
        /**
         * Only log messages after container is successfully started
         */
        SOME,
        /**
         * Log nothing
         */
        NONE,
    }

    private final String name;

    private LoggingLevel level = LoggingLevel.NONE;

    private boolean ignore = true;

    /**
     * Contructor
     *
     * @param name  container name
     * @param level logging level
     */
    public SelectiveLogConsumer(String name, LoggingLevel level) {
        this.name = name;
        this.level = level;
    }

    /**
     * Convenience constructor
     *
     * @param name container name
     */
    public SelectiveLogConsumer(String name) {
        this(name, LoggingLevel.SOME);
    }

    /**
     * Convenience constructor
     *
     * @param name  docker image name
     * @param level logging level
     */
    public SelectiveLogConsumer(DockerImageName name, LoggingLevel level) {
        this(name.asCanonicalNameString(), level);
    }

    /**
     * Get logging level
     *
     * @return LoggingLevel enum
     */
    public LoggingLevel getLoggingLevel() {
        return level;
    }

    /**
     * Set logging level
     *
     * @param level LoggingLevel enum
     */
    public void setLoggingLevel(LoggingLevel level) {
        this.level = level;
    }

    /**
     * {@inheritDoc}
     */
    @Override
    public void accept(OutputFrame frame) {
        if (level == LoggingLevel.NONE) {
            return;
        }

        // guess guest's loggging level. we remove the colons to simplify the pattern matching
        final Level slf4jLevel = guessLevel(frame.getType(), frame.getUtf8StringWithoutLineEnding().replace(":", " "));

        // enhancement: strip some of the common clutter
        final String content = frame.getUtf8StringWithoutLineEnding();

        // there doesn't seem to be a LOG.log(Level, String) method outside of LoggingEventBuilder. :-(
        switch (slf4jLevel) {
            case ERROR:
                LOG.error(content);
                break;
            case WARN:
                LOG.warn(content);
                break;
            case INFO:
                LOG.info(content);
                break;
            case DEBUG:
                LOG.debug(content);
                break;
            case TRACE:
                LOG.trace(content);
                break;
        }
    }

    /**
     * Are most messages are ignored?
     * @return true if most messages are ignored
     */
    public boolean isIgnore() {
        return ignore;
    }

    /**
     * Should most messages be ignored?
     * @param ignore true if most messages should be ignored
     */
    public void setIgnore(boolean ignore) {
        this.ignore = ignore;
    }

    /**
     * Make informed guess at proper Log level based on contents of message.
     * <p>
     * The tests check the most common patterns but we might need to limit
     * amount of the string checked. This would be easy to do with simple strings
     * since they usually start with date + level but I don't know where json
     * loggers put the level.
     * <p>
     * It wouldn't be hard to determine the content is json but that would
     * add a lot more work. Perhaps if the first character is "{"....
     *
     * @param type   log frame type
     * @param content contents of log frame
     * @return
     */
    Level guessLevel(OutputFrame.OutputType type, String content) {
        Level level;

        if (content.contains(" ERROR ") || content.contains("[ERROR]")) {
            level = Level.ERROR;
        } else if (content.contains(" WARN ") || content.contains("[WARN]")) {
            level = Level.WARN;
        } else if (content.contains(" INFO ") || content.contains("[INFO]")) { // both
            level = Level.INFO;
        } else if (content.contains(" DEBUG ") || content.contains("[DEBUG]")) {
            level = Level.DEBUG;
        } else if (content.contains(" TRACE ") || content.contains("[TRACE]")) {
            level = Level.TRACE;
        } else if (content.contains(" SEVERE ") || content.contains("[SEVERE]")) {
            level = Level.ERROR;
        } else if (content.contains(" WARNING ") || content.contains("[WARNING]")) {
            level = Level.WARN;
        } else if (content.contains(" FINE ") || content.contains("[FINE]")) {
            level = Level.DEBUG;
        } else if (content.contains(" FINER ") || content.contains("[FINER]")) {
            level = Level.TRACE;
        } else if (content.contains(" FINEST ") || content.contains("[FINEST]")) {
            level = Level.TRACE;
        } else {
            // fall back to what the frame provided
            switch (type) {
                case STDOUT:
                    level = Level.INFO;
                    break;
                case STDERR:
                    level = (ignore) ? Level.DEBUG : Level.WARN;
                    break;
                default:
                    level = Level.INFO;
            }
        }

        return level;
    }
}