Allow constomizing the log format produced by `Logging{Service,Client}`

[ikhoon]

The logs produced by LoggingService and LoggingClient are human-readable. However, this non-structured text is not good when users want to store the log file to Elastic Search or other key-value storage. We can give an extension API to users to customize the output format. For example:

interface LogFormat {
    static LogFormat ofText() {
        // return a log message formatted by the default formatter. 
    }

    static LogFormat ofJson() {
        // return a log message serialized to JSON format
    }

    String format(RequestLog log, LogSanitizers sanitizers);
}

class LogSanitizers {
    BiFunction<? super RequestContext, ? super RequestHeaders, ? extends @Nullable Object> requestHeadersSanitizer;
    BiFunction<? super RequestContext, Object, ? extends @Nullable Object> requestContentSanitizer;
    ...
}

LoggingService.builder()
              // Customize the log message format using LogFormat
              .format(LogFormat.ofJson())

[aserputov]

Hey, @ikhoon , I would like to work on this issue. Could you please assign me?

[ikhoon]

Sure! Thanks in advance. 😀

[aserputov]

Hey, @ikhoon. I started working on this issue, and I am not sure if I understood it correctly. Could you please provide an example or give a little more information, Thank you very much in advance.

[ikhoon]

If you add LoggingService to a server or LoggingClient to a client, we can see human-readable logs produced by slf4j. Let's say you've configured server and client like the follow.

class LoggingTest {
    @RegisterExtension
    static ServerExtension server = new ServerExtension() {
        @Override
        protected void configure(ServerBuilder sb) {
            sb.decorator(LoggingService.newDecorator());
            sb.service("/", (ctx, req) -> HttpResponse.of("OK"));
        }
    };

    @Test
    void testLog() {
        final WebClient client = WebClient.builder(server.httpUri())
                                          .decorator(LoggingClient.newDecorator())
                                          .build();
        final AggregatedHttpResponse response = client.get("/").aggregate().join();
    }
}

If execute the test, you can see request and response logs.

DEBUG c.l.a.client.logging.LoggingClient - [creqId=fd9b44b1, chanId=16139b85, laddr=127.0.0.1:64606, raddr=127.0.0.1:64604][http://127.0.0.1:64604/#GET] Request: {startTime=2021-11-12T08:30:47.625Z(1636705847625000), length=0B, duration=201ms(201985644ns), scheme=none+h2c, name=GET, headers=[:method=GET, :path=/, :scheme=http, :authority=127.0.0.1:64604]}
DEBUG c.l.a.server.logging.LoggingService - [sreqId=1f4fecab, chanId=17eb907f, raddr=127.0.0.1:64606, laddr=127.0.0.1:64604][h2c://ihi.local/#GET] Request: {startTime=2021-11-12T08:30:47.836Z(1636705847836000), length=0B, duration=31272µs(31272404ns), scheme=none+h2c, name=GET, headers=[EOS, :method=GET, :path=/, :scheme=http, :authority=127.0.0.1:64604, user-agent=armeria/1.14.0-SNAPSHOT]}
DEBUG c.l.a.server.logging.LoggingService - [sreqId=1f4fecab, chanId=17eb907f, raddr=127.0.0.1:64606, laddr=127.0.0.1:64604][h2c://ihi.local/#GET] Response: {startTime=2021-11-12T08:30:47.857Z(1636705847857000), length=2B, duration=11254µs(11254624ns), totalDuration=32223µs(32223728ns), headers=[:status=200, content-type=text/plain; charset=utf-8, content-length=2]}
DEBUG c.l.a.client.logging.LoggingClient - [creqId=fd9b44b1, chanId=16139b85, laddr=127.0.0.1:64606, raddr=127.0.0.1:64604][http://127.0.0.1:64604/#GET] Response: {startTime=2021-11-12T08:30:47.863Z(1636705847863000), length=2B, duration=5586µs(5586456ns), totalDuration=246ms(246110184ns), headers=[:status=200, content-type=text/plain; charset=utf-8, server=Armeria/1.14.0-SNAPSHOT, date=Fri, 12 Nov 2021 08:30:47 GMT, content-length=2]}

The logs are easy to read but the format of logs is hard-coded and has no extension points. The aim of this issue is to provide an extension point to customize log formats for both LoggingClient and LoggingService.

[aserputov]

@ikhoon Thanks.

[ikhoon]

Duplicate of #3040

[ikhoon]

I realized that we need two kinds of API for LogFormat.

interface LogFormat {
    String formatRequest(RequestLog log, LogSanitizers sanitizers);

    String formatResponse(RequestLog log, LogSanitizers sanitizers);
}

[aserputov]

@ikhoon, I started working on this issue and read through all of the comments. What exactly are your ideas to do that? Something like that https://github.com/line/armeria/issues/3040#issuecomment-685042991? Also, I feel like we need to add an "Enhancement" label 🙂

[ikhoon]

What exactly are your ideas to do that?

Requests and responses are formatted with the following methods. https://github.com/line/armeria/blob/e08b6eabcf9f8ddf231b8744026dd5dbd6342271/core/src/main/java/com/linecorp/armeria/common/logging/DefaultRequestLog.java#L1414 https://github.com/line/armeria/blob/e08b6eabcf9f8ddf231b8744026dd5dbd6342271/core/src/main/java/com/linecorp/armeria/common/logging/DefaultRequestLog.java#L1530

Armeria provides the default format and users cannot customize the output format. If users want to log output with JSON, we can provide LogForamt.json().

// Defalut version.
Request: {startTime=2021-11-12T08:30:47.625Z(1636705847625000), length=0B, duration=201ms(201985644ns), scheme=none+h2c, name=GET, headers=[:method=GET, :path=/, :scheme=http, :authority=127.0.0.1:64604]}
// JSON version
{"startTime":"2021-11-12T08:30:47.625Z", "length":0, "duration":"201ms", "scheme":"none+h2c", "name"="GET", "headers": { ":method": "GET", ":path":"/", ":scheme": "http", ":authority":"127.0.0.1:64604"}}

[ta7uw]

May I work on this issue?

[ikhoon]

Sure ❤️

[ta7uw]

@ikhoon How about setting DefaultRequestLog as the argument of LogFormat#format to handle flags, etc.?

interface LogFormat {
    String format(DefaultRequestLog log, LogSanitizers sanitizers);
}

In the current implementation, the log generation mechanism uses the flags as follows.

https://github.com/line/armeria/blob/e08b6eabcf9f8ddf231b8744026dd5dbd6342271/core/src/main/java/com/linecorp/armeria/common/logging/DefaultRequestLog.java#L1475-L1478

I think it would be difficult to make changes while maintaining compatibility with the current log format as it is when using RequestLog as the argument of LogFormat#format.

[ikhoon]

We can use RequestLog.isAvailable(RequestLogProperty.REQUEST_LENGTH) for this purpose.

[ta7uw]

Should we need to check the value of flags in DefaultRequestLog?

https://github.com/line/armeria/blob/e08b6eabcf9f8ddf231b8744026dd5dbd6342271/core/src/main/java/com/linecorp/armeria/common/logging/DefaultRequestLog.java#L230-L232

[ikhoon]

hasInterestedFlags(flags, RequestLogProperty.REQUEST_LENGTH) must be the same with RequestLog.isAvailable(RequestLogProperty.REQUEST_LENGTH). By the way, flags is a volatile value. So it is bad to access it repeatedly. How about adding an API that returns all available RequestLogPropertys?

interface RequestLogAccess {
    Set<RequestLogProperty> availableProperties();
}

[KazankovMarch]

Hello everybody. I need to sanitize request path (it contains a secret token), but currently I can't do it, because logs have format {context} Request: {log} and all the sanitizers are applied to the {log}, while {context} contains raddr with request path.

Will this feature allow me remove the secret token in request paths from logs?