Custom access logger never logs requests with 4xx http codes

[rickyma]

I add a custom access log writer:

// Write access log after completing a request.
builder.accessLogWriter(new CustomAccessLogWriter(), true);

CustomAccessLogWriter:

package com.rickyma.uc.server.config;

import com.linecorp.armeria.common.RequestContext;
import com.linecorp.armeria.common.logging.RequestLog;
import com.linecorp.armeria.server.logging.AccessLogWriter;
import com.rickyma.uc.server.util.DateUtils;
import java.net.InetAddress;
import java.net.InetSocketAddress;
import java.util.Optional;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class CustomAccessLogWriter implements AccessLogWriter {

    private static final Logger ACCESS_LOGGER = LogManager.getLogger("AccessLogger");
    private static final String ACCESS_DATE_TIME_FORMAT = "yyyy-MM-dd HH:mm:ss.SSS";
    private static final String HEALTH_CHECK_PATH = "/actuator/healthcheck/";

    @Override
    public void log(RequestLog log) {
        String clientIp =
                Optional.ofNullable(log.context().remoteAddress())
                        .map(InetSocketAddress::getAddress)
                        .map(InetAddress::getHostAddress)
                        .orElse("-");
        String method = log.requestHeaders().method().name();
        String path = log.requestHeaders().path();
        String protocol = log.sessionProtocol().uriText();
        int statusCode = log.responseHeaders().status().code();
        long contentLength = log.responseHeaders().contentLength();
        String userAgent = log.requestHeaders().get("user-agent", "-");
        String referer = log.requestHeaders().get("referer", "-");
        String timestamp =
                DateUtils.getDateStrByMillis(log.requestStartTimeMillis(), ACCESS_DATE_TIME_FORMAT);
        String clientAuthInfo = getClientAuthInfo(log);
        String userId = getUserId(log.context());
        String logMessage =
                String.format(
                        "%s %s %s [%s] \"%s %s %s\" %d %d \"%s\" \"%s\"",
                        clientIp,
                        clientAuthInfo,
                        userId,
                        timestamp,
                        method,
                        path,
                        protocol,
                        statusCode,
                        contentLength,
                        referer,
                        userAgent);

        if (ACCESS_LOGGER.isDebugEnabled()) {
            ACCESS_LOGGER.debug(logMessage);
        } else if (!path.contains(HEALTH_CHECK_PATH)) {
            ACCESS_LOGGER.info(logMessage);
        }
    }

    private String getClientAuthInfo(RequestLog log) {
        return "-";
    }

    private String getUserId(RequestContext ctx) {
        return "-";
    }
}

This is log4j2.xml：

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN" monitorInterval="30">
  <Appenders>
    <Console name="Console" target="SYSTEM_OUT">
      <PatternLayout pattern="[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%t] [%p] %c{1} - %m%n%ex"/>
    </Console>
    <RollingFile name="RollingAppender" fileName="aaa.log" filePattern="aaa.log.%i">
      <PatternLayout pattern="[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%t] [%p] %c{1} - %m%n%ex"/>
      <Policies>
        <SizeBasedTriggeringPolicy size="2GB"/>
      </Policies>
      <DefaultRolloverStrategy max="10"/>
    </RollingFile>
    <RollingFile name="AccessLogAppender" fileName="access.log" filePattern="access.log.%i">
      <PatternLayout pattern="%m%n"/>
      <Policies>
        <SizeBasedTriggeringPolicy size="100MB"/>
      </Policies>
      <DefaultRolloverStrategy max="10"/>
    </RollingFile>
  </Appenders>
  <Loggers>
    <Root level="info">
      <AppenderRef ref="Console"/>
      <AppenderRef ref="RollingAppender"/>
    </Root>
    <Logger name="AccessLogger" level="info" additivity="false">
      <AppenderRef ref="AccessLogAppender"/>
    </Logger>
  </Loggers>
</Configuration>

In access.log, I found out there are only requests with 2xx / 5xx codes. The 4xx requests are never logged in access.log.
What am I missing here?

[rickyma]

I have an authentication decorator, which could block requests and return 4xx http code if authentication failed. I don't know if this is the issue? How do I log every requests regardless of its http codes?

[jrhee17]

In access.log, I found out there are only requests with 2xx / 5xx codes. The 4xx requests are never logged in access.log.
What am I missing here?

Hi, I was unable to reproduce missing 400 codes.
Is there a specific condition where the 400 status code was omitted?

I have an authentication decorator, which could block requests and return 4xx http code if authentication failed. I don't know if this is the issue? How do I log every requests regardless of its http codes?

accessLog is expected to log all requests/responses regardless of the decorator chain.

[rickyma]

After further investigation, I found out it's not Armeria's issue. There is a potential NPE when writing access logs. I'll close this. Thanks @jrhee17

[rickyma]

There is one thing I need to mention: the NPE Exception was not thrown from my CustomAccessLogWriter, and it is not visible in the logs. I only discovered this issue through debugging. Is this expected behavior? @jrhee17

[minwoox]

Is this expected behavior?

That is correct. The customized logger shouldn't throw any exception.

the NPE Exception was not thrown

The NPE raised because Armeria server doesn't call the log(RequestLog) with null RequestLog? If so, we should fix that.

[rickyma]

The NPE was thrown from my getClientAuthInfo method. I didn't upload the full codes.

[ikhoon]

We may add a warning log if AccessLogWriter.log() raises an exception for easier debugging.

armeria/core/src/main/java/com/linecorp/armeria/server/AbstractHttpResponseHandler.java

Lines 232 to 234 in 9a29b39

	try (SafeCloseable ignored = reqCtx.push()) {
	config.accessLogWriter().log(log);
	}

[minwoox]

Or, we can probably use UnloggedExceptionsReporter.

[ikhoon]

Either way is fine to me if users can figure out the problem.

[rickyma]

I am not sure if my approach is officially recommended by Armeria. I have customized a log4j2 logger for AccessLog to record access logs and excluded the /actuator/healthcheck/ endpoint, which is always accessed by the health check. If you have a more elegant implementation, please let me know. Thank you.

[minwoox]

I assumed that you're using the Armeria Spring Actuator integration module. If so, yeah, that's the recommended approach.
If you want to exclude an Armeria service, you can use TransientHttpService.newDecorator().

armeria/core/src/main/java/com/linecorp/armeria/server/TransientHttpService.java

Line 49 in ccff172

static Function<? super HttpService, SimpleDecoratingHttpService> newDecorator(

[rickyma]

I assumed that you're using the Armeria Spring Actuator integration module

Yeah, I am using it.

My application.yml:

armeria:
  ports:
    - port: 8080
      protocols:
        - http
management:
  server.port: 8081
  endpoints:
    web:
      exposure.include:
        - health
        - beans
      path-mapping:
        health: healthcheck

you can use TransientHttpService.newDecorator()

It will be nice if I can use TransientHttpService.newDecorator() or something else in Armeria to exclude recording access log for Spring Actuator's healthcheck.

Because something like this is a little bit weird:

if (ACCESS_LOGGER.isDebugEnabled()) {
    ACCESS_LOGGER.debug(logMessage);
} else if (!path.contains(HEALTH_CHECK_PATH)) {
    ACCESS_LOGGER.info(logMessage);
}

[minwoox]

@rickyma, You can probably do this:

final AccessLogWriter writer = AccessLogWriter.common();
serverBuilder.accessLogWriter(log -> {
    if (!log.context().path().equals(HEALTH_CHECK_PATH)) {
        writer.log(log);
    }
}, false);

[rickyma]

Thanks. I'll have a try. Another thing is, why do you set shutdownOnStop to false? In what condition should we set it to true?

[ikhoon]

shutdownOnStop = true could be used when you have a custom access writer that needs to be closed.

armeria/kafka/src/main/java/com/linecorp/armeria/server/logging/kafka/KafkaAccessLogWriter.java

Lines 102 to 104 in 5b384fb

	public CompletableFuture<Void> shutdown() {
	return CompletableFuture.runAsync(producer::close);
	}