Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improve logging for Optional<Duration> fields. #22

Open
alec-heif opened this issue Mar 19, 2021 · 3 comments · May be fixed by #23
Open

Improve logging for Optional<Duration> fields. #22

alec-heif opened this issue Mar 19, 2021 · 3 comments · May be fixed by #23

Comments

@alec-heif
Copy link
Contributor

alec-heif commented Mar 19, 2021

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
      }
@rchukh
Copy link
Owner

rchukh commented Mar 25, 2021

Thank you for reporting this @alec-heif .

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

@rchukh
Copy link
Owner

rchukh commented Mar 27, 2021

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"/>

@rchukh rchukh linked a pull request Mar 27, 2021 that will close this issue
@rchukh
Copy link
Owner

rchukh commented Mar 27, 2021

@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).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants