line/armeria

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

Dogacel opened this issue · 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\":\\{\".+\"}}$");
    }

Is this still a problem? What was the culprit?

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.

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?

I have created a draft PR here: #5873

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