Logging in org.eclipse.jetty.server.Response

[Mahoney]

I'm confused by this logic:

https://github.com/jetty/jetty.project/blob/eafc5be38d274ac713436b203e3ae595d3d1ed75/jetty-core/jetty-server/src/main/java/org/eclipse/jetty/server/Response.java#L643-L648

If debug is enabled, log at debug, but otherwise log at warn? That makes no sense - you log at the level you think you should log. The logger.isDebugEnabled() is a performance optimisation, to avoid calling logger.debug(...) if it would not do anything, not meant to be used to change behaviour.

The middle branch is completely pointless as it calls logger.debug(...) when it is guaranteed that logger.isDebugEnabled() == false, so it will be a no op.

[Mahoney]

I suspect the actual desired behaviour is something like:

if (cause != null && !(cause instanceof QuietException || cause instanceof TimeoutException))
    logger.warn("writeError: status={}, message={}, response={}", status, message, response, cause);
else if (logger.isDebugEnabled())
    if (cause == null)
        logger.debug("writeError: status={}, message={}, response={}", status, message, response);
    else
        logger.debug("writeError: status={}, message={}, response={} {}", status, message, response, cause.toString());

[joakime]

~It should be ...~ (This is wrong)

if (logger.isDebugEnabled()) 
{
    if (cause instanceof QuietException || cause instanceof TimeoutException) 
        logger.debug("writeError: status={}, message={}, response={} {}", status, message, response, cause.toString()); 
    else
        logger.debug("writeError: status={}, message={}, response={}", status, message, response, cause); 
}
else
{
    logger.warn("writeError: status={}, message={}, response={}", status, message, response, cause); 
}

[Mahoney]

That seems quite wrong to me. You should never change what level you log at based on what level is enabled on the logger.

You should be able to delete all calls to logger.isXxxEnabled() from your codebase and see no change in behaviour, it should only be used as a performance optimisation to avoid making redundant method calls. A compliant SLF4J implementation will be filtering them out anyway.

[joakime]

You might want to participate in the following PR (even if its just a review)

• #13884

[Mahoney]

There were a couple of cases of this anti-pattern in that PR, I've commented on them.

[Mahoney]

Updated my suggested code, previous version had a bug

[sbordet]

The original code is correct.

We want to suppress logging of client errors such as QuietExceptions

[Mahoney]

Perhaps I can make it clearer with a truth table.

	Logger Level	Exception Type	What Ought To Get Logged	What Actually Gets Logged
1	DEBUG	null	DEBUG: message	DEBUG: message
2	DEBUG	QuietException	DEBUG: QuietException without stacktrace	DEBUG: QuietException with full stacktrace
3	DEBUG	Exception	WARN: Exception with full stacktrace	DEBUG: Exception with full stacktrace
4	WARN	null	Nothing	Nothing
5	WARN	QuietException	Nothing	Nothing
6	WARN	Exception	WARN: Exception with full stacktrace	WARN: Exception with full stacktrace

It's really obvious to me cases 2 & 3 are wrong. Particularly 3 - you are logging non client errors at DEBUG level purely because debug is enabled.

[Mahoney]

I've written it up as a Spock test:

import ch.qos.logback.classic.LoggerContext
import ch.qos.logback.classic.spi.ILoggingEvent
import ch.qos.logback.core.read.ListAppender
import org.eclipse.jetty.http.BadMessageException
import spock.lang.Specification

import static ch.qos.logback.classic.Level.DEBUG
import static ch.qos.logback.classic.Level.WARN

class BrokenLoggerSpec extends Specification {

    def 'what gets logged'() {

        given:
            def loggerContext = new LoggerContext().tap { it.start() }
            def appender = new ListAppender<ILoggingEvent>().tap { it.start() }
            def logger = loggerContext.getLogger("test")
            logger.addAppender(appender)
            logger.setLevel(level)

        when:
            new BrokenLogger(logger).log(200, 'msg', 'resp', cause)

        then:
            appender.list.collect { [level: it.level, message: it.formattedMessage, throwable: it.throwableProxy?.className] } == expected

        where:
            level | cause                     || expected
            DEBUG | null                      || [[level: DEBUG, message: 'writeError: status=200, message=msg, response=resp', throwable: null]]
            DEBUG | new BadMessageException() || [[level: DEBUG, message: 'writeError: status=200, message=msg, response=resp org.eclipse.jetty.http.BadMessageException: 400: null', throwable: null]]
            DEBUG | new Exception()           || [[level: WARN,  message: 'writeError: status=200, message=msg, response=resp', throwable: 'java.lang.Exception']]
            WARN  | null                      || []
            WARN  | new BadMessageException() || []
            WARN  | new Exception()           || [[level: WARN,  message: 'writeError: status=200, message=msg, response=resp', throwable: 'java.lang.Exception']]
    }
}

My code is also buggy, I have amended it, it should be:

if (cause != null && !(cause instanceof QuietException || cause instanceof TimeoutException))
    logger.warn("writeError: status={}, message={}, response={}", status, message, response, cause);
else if (logger.isDebugEnabled())
    if (cause == null)
        logger.debug("writeError: status={}, message={}, response={}", status, message, response);
    else
        logger.debug("writeError: status={}, message={}, response={} {}", status, message, response, cause.toString());

[Mahoney]

It would be a lot simpler if you just left the checking of debug being enabled to the underlying logging system, then it would just be this:

if (cause == null)
    logger.debug("writeError: status={}, message={}, response={}", status, message, response);
else if (cause instanceof QuietException || cause instanceof TimeoutException)
    logger.debug("writeError: status={}, message={}, response={} {}", status, message, response, cause.toString());
else
    logger.warn("writeError: status={}, message={}, response={}", status, message, response, cause);

But it does mean doing the cause.toString() unnecessarily when debug is not enabled.