Custom Formatter for airlift Log-manager used by presto

[ssanthanam185]

For ingesting logs into Kibana , would like presto logs to be spit out in a JSON format. User should be able to extend java.util.logging.Formatter with a custom implementation & configure Airlift to use this custom class instead of the StaticFormatter.

[electrum]

Do you have a specific format in mind? We’d prefer to have an option to logging in a standard JSON format rather than making it completely configurable.

[ssanthanam185]

Yes for JSON format. How ever Id like the flexibility in mapping some fields in the record to standard fields which have been defined in Kibana and have indexes built on it.

[electrum]

Can you give a specific example of what you’d like a log message to look like?

[ssanthanam185]

Example :
{ "ts" ="2019-10-29T23:47:40.63127",
"lvlname" ="WARN",
"name":"io.prestosql.server.remotetask.RequestErrorTracker",
"exc":"Error updating task 20191029_234709_13560_v23z9.21.22: java.util.concurrent.TimeoutException: Total timeout 10000 ms elapsed: http://10.46.223.209:8081/v1/task/20191029_234709_13560_v23z9.21.22"
}

Would be nice if users can add their custom Formatter & just define it as a config like:

log.custom-formatter=org.formmater.JsonFormatter

We should be able to add org.formmater.JsonFormatter classpath, so that Airlift can load it and inject it as the Formatter to be used in the OutputstreamHandler

[cccs-tom]

We have a similar stack and would very much appreciate this feature as well.

[lfrancke]

We stumbled across the logging in Trino today as well.
I know that - in the end - you redirect everything to java.util.logging (JUL) and we were able to get some customization using the jul-to-slf4j bridge but we weren't able to fix everything (e.g. bootstrap log and some artifacts coming from the StaticFormatter).

Before we do any more work on this I was wondering how open you would be to switch from JUL to SLF4J in Airlift?
Then we'd need to make a decision on which logging implementation to use in Trino (which could be JUL, Log4J, Logback, ...)
That would give us much more flexibility in terms of the logging format and destination.

It would not mean (m)any new dependencies because everything is already included.

We could work on a Pull Request for this but would only do so if there is consensus that this could be accepted.
I do know that JUL is "standard" as well, but from my experience SLF4J is in far more widespread use and allows more configurability.

I just went through all the libs (granted, in Trino) and wrote down where they come from and what they are. Posting it here mostly for my own reference.

Airlift:
log-219.jar
log-manager-219.jar

Log4J2:
log4j-api-2.17.1.jar (via log4j-to-slf4j)

SLF4J:
slf4j-api-1.7.36.jar (via jcl-over-slf4j)

SLF4J Binding:
slf4j-jdk14-1.7.36.jar (log all SLF4J things via JUL)

SLF4J Bridges:
log4j-over-slf4j-1.7.36.jar (Log4J1 -> SLF4J, via log-manager)
log4j-to-slf4j-2.17.1.jar (Log4J2 -> SLF4J, via log-manager)
jcl-over-slf4j-1.7.36.jar (commons-logging -> SLF4J, via Trino & log-manager)

Logback:
logback-core-1.2.11.jar (via http-client, http-server, log-manager)

[electrum]

We don't use SLF4J in Trino because of class loaders. If plugins log via JUL, then everything just works. If they use SLF4J, then the plugin has to bridge to JUL, or we would need to add SLF4J to the plugin SPI, and that's problematic for a variety of reasons.

We recently added a JSON logging format:

log.format=json

There is an optional annotations file which will be included as an annotations map in the JSON log record:

log.annotation-file=/path/to/annotations.properties

Finally, you can use a TCP destination for logging:

log.path=tcp://host:port

Note that both the logging configuration properties and the annotations file properties support the environment variable replacement that is described here, so you could do this:

log.path=tcp://${ENV:HOST_IP}:1234

[lfrancke]

Thanks for the detailed response.
That helps and I do understand the reasoning. It is a trade-off for sure.

Apache NiFi is also based on a plugin architecture and they made a different decision. They have a ComponentLog interface which can then be implemented in various ways.

As I said: I do understand your decision, it's a valid one.
Would you be up to reconsider that decision in any way or is it moot discussing the point (at the moment)?

[electrum]

Thanks for the pointer. We considered adding our own logging interface (and already use Airlift Logger directly in Trino), but using JUL didn't require changing existing code or writing new logging bridges.

Making logging completely pluggable has never been a goal for Trino, so I'd prefer to focus on the underlying problem you're trying to solve. What's your goal with customized logging?

If you change the Trino Server class to call doNotInitializeLogging() on Bootstrap, then it won't touch the JUL configuration, so you could have a custom JUL handler or JUL-to-SLF4J bridge. I think that should fix the issues you found in your attempt, but there might be another problem I'm not seeing.

[lfrancke]

Our goal is mostly consistency. All other Java tools we use (HBase, NiFi, Spark, Kafka....) are easily configurable to emit the exact same logging format. Trino is the only outlier which requires special handling as it uses "non-standard" logging. I put it into quotes as I do realize that you're using the only logging implementation that actually comes out of the box ;-)

It's not a huge deal, we just found this issue and thought we'd inquire.
We'd be willing to do the work as well but as I said: It only makes sense if you'd accept any changes here which doesn't seem to be the case and that's fine.

We did play around with JUL-to-SLF4J but that wouldn't work 100%. It would always emit a "header" anyway (we didn't dig too deep) and then our properly formatted log message - and that again would require special handling. Now we're using the JSON format instead.

Thank you for your answers, that already helps us. There is nothing that needs to be done here as far as we're concerned. I would suggest to leave this issue open to collect feedback from others.

[deigote]

It would always emit a "header" anyway (we didn't dig too deep) and then our properly formatted log message - and that again would require special handling. Now we're using the JSON format instead.

maybe it's something else in your case, but I had this issue with "special header + my message" too, which broke our logs. I found out that airlift does a global stdin redirect (which was a very big WTF moment for me, TBH... maybe there are good reasons), so that all output is processed by the logging system (so then something like System.out.println("some info") looks like a log). I'm right now undoing this in my plugins with System.setOut(new PrintStream(new FileOutputStream(FileDescriptor.out))); which is... oof. But not sure how else to go about it (I need my plugins to log as JSON and with lots of metadata, so I need JSON and MDC which airlift doesn't seem to support properly yet).