rchukh/trino-querylog

Improve logging for `Optional<Duration>` fields.

alec-heif opened this issue · 3 comments

There seems to be a bug in the logging for fields of type Optional<Duration> in at least the fields for QueryStatistics.

When examining the logs for a query I see that the Duration fields cpuTime, wallTime, and queuedTime are all logged correctly as

      "cpuTime": {
        "seconds": 123,
        "units": [
          "SECONDS",
          "NANOS"
        ],
        "zero": false,
        "negative": false,
        "nano": 123456789
      },
      "wallTime": {
        "seconds": 123,
        "units": [
          "SECONDS",
          "NANOS"
        ],
        "zero": false,
        "negative": false,
        "nano": 123456789
      },
      "queuedTime": {
        "seconds": 123,
        "units": [
          "SECONDS",
          "NANOS"
        ],
        "zero": false,
        "negative": false,
        "nano": 123456789
      }

but the Optional<Duration> fields seem to have the contained value dropped:

      "scheduledTime": {
        "empty": false,
        "present": true
      },
      "analysisTime": {
        "empty": false,
        "present": true
      },
      "planningTime": {
        "empty": false,
        "present": true
      },
      "executionTime": {
        "empty": false,
        "present": true
      }

Thank you for reporting this @alec-heif .

I'll try to take a look into it this weekend.

I thought that it would be as simple as adding custom module/serializers to change the ObjectMapper that is used internally in Log4j2.... but it looks like it is not possible to do this at the time - https://issues.apache.org/jira/browse/LOG4J2-2670

One way around that would be to serialize Trino events to JSON manually and then output them using the PatternLayout (instead of JsonLayout), with only the message and a line separator:

<PatternLayout pattern="%m%n"/>

@alec-heif
Could you take a look if the #23 solves those issues?
Seems to work fine in the test, but I did not check how it behaves in Trino.

It also does not log logging metadata now (e.g. log level, thread, etc.) and things like "cpuTime" are logged as a timestamp with millisecond precision (instead of nested JSON object).