armeria icon indicating copy to clipboard operation
armeria copied to clipboard

[BUG]: LoggingService with JSON log writer fails for gRPC messages

Open Dogacel opened this issue 1 year ago • 4 comments

I am geetting the following error:

Unexpected exception while formatting a request log: {request log's string representation here}

No serializer found for class com.linecorp.armeria.common.DefaultRpcRequest and no properties discovered to create BeanSerializer (to avoid exception, disable SerializationFeature.FAIL_ON_EMPTY_BEANS)

All I am doing is adding the following to my server and calling some gRPC endpoints:

            .decorator(
                LoggingService
                    .builder()
                    .logWriter(
                        LogWriter
                            .builder()
                            .logFormatter(LogFormatter.ofJson()) // Log in JSON format
                            .successfulResponseLogLevel(LogLevel.DEBUG) // Log all responses as DEBUG
                            .failureResponseLogLevel(LogLevel.WARN) // Log all failures as warnings
                            .requestLogLevel(LogLevel.TRACE) // Request logs are not as important, thus trace
                            .build(),
                    ).newDecorator(),

test reprod under JsonLogFormatterTest,

    @Test
    void formatRpcRequest() {
        final LogFormatter logFormatter = LogFormatter.ofJson();
        final ServiceRequestContext ctx = ServiceRequestContext.of(HttpRequest.of(HttpMethod.POST, "/com.Foo"));
        final DefaultRequestLog log = (DefaultRequestLog) ctx.log();
        log.requestContent(RpcRequest.of(DefaultRequestLogTest.class, "service", "method"), null);
        log.endRequest();
        final String requestLog = logFormatter.formatRequest(log);
        System.out.println(requestLog);
        assertThat(requestLog)
                .matches("^\\{\"type\":\"request\",\"startTime\":\".+\",\"length\":\".+\"," +
                         "\"duration\":\".+\",\"scheme\":\".+\",\"name\":\".+\",\"headers\":\\{\".+\"}}$");
    }

Dogacel avatar Aug 12 '24 17:08 Dogacel

Is this still a problem? What was the culprit?

trustin avatar Aug 13 '24 02:08 trustin

Is this still a problem? What was the culprit?

I did not mean to complete this 😭 I have reverted this change in an internal repo and linked this issue, thus it automatically resolved.

Dogacel avatar Aug 13 '24 03:08 Dogacel

Is this still a problem? What was the culprit?

We have some options, my first attempt is this:

    private static <T> BiFunction<? super RequestContext, T, JsonNode>
    defaultContentSanitizer(ObjectMapper objectMapper) {
        return (requestContext, obj) -> {
            if (obj instanceof RpcRequest) {
                RpcRequest rpcRequest = (RpcRequest) obj;
                ObjectNode node = objectMapper.createObjectNode();
                node.put("method", rpcRequest.method());
                node.put("serviceName", rpcRequest.serviceName());
                node.set("params", objectMapper.valueToTree(rpcRequest.params()));

                return node;
            }
            return objectMapper.valueToTree(obj);
        };

This works somewhat fine, however JSON formatting of RPC based params is incorrect. Protobuf messages can't be serialized using Object Mappers, there is some kind of recursion happening.

I don't even know how to serialize other types such as Thrift. Maybe we can check params and if they extend Message proto type, we can use jsonPrinter?

Dogacel avatar Aug 13 '24 04:08 Dogacel

I have created a draft PR here: https://github.com/line/armeria/pull/5873

For whatever reason my test can't capture logger.info (even though it is being called 🤔)

Dogacel avatar Aug 13 '24 06:08 Dogacel