I tested in Hadoop test the AWS query logger (provided via Apache 2.0 license, very good) and it works nicely with little effort, but it doesn't seem log the query string:

Feb 05, 2021 9:10:23 AM com.amazonaws.QueryEventListener.QueryEventListener queryCreated
INFO: ---------------Query Created----------------------------
     Query ID: 20210205_091023_00001_rdk5q
     Query State: QUEUED
     User: elukey
     Create Time: 2021-02-05T09:10:23.308Z
     Principal: Optional[elukey@WIKIMEDIA]
     Remote Client Address: Optional[10.64.5.6]
     Source: Optional[presto-cli]
     User Agent: Optional[StatementClientV1/0.246-cbd542a]
     Catalog: Optional[analytics_test_hive]
     Schema: Optional.empty
     Server Address: an-test-coord1001.eqiad.wmnet
Feb 05, 2021 9:10:23 AM com.amazonaws.QueryEventListener.QueryEventListener queryCompleted
INFO: ---------------Query Completed----------------------------
     Query ID: 20210205_091023_00001_rdk5q
     Create Time: 2021-02-05T09:10:23.308Z
     User: elukey
     Complete: true
     Remote Client Address: Optional[10.64.5.6]

There might be some follow up to do with upstream, I was convinced that the plugin would have logged the query string. Without it the log is useful but not that much..

Another thing that I have discovered is the Presto UI on the coordinator:

This is way more useful, but it doesn't keep history of the queries after a restart. The info about the query execute is there, so Presto is surely logging it somewhere, it is a matter of finding where :)

The UI is available via https + Kerberos but it doesn't work for me (I tried multiple setups), and also via HTTP, that we have disabled. We could re-enable http only on the coordinator, and avoid opening any firewall port for it, so it would be available only via localhost (so we could use a ssh tunnel to inspect the status of Presto when needed).

I wonder if this would be useful: https://github.com/zz22394/presto-audit

This explains why we only have them in the UI: https://stackoverflow.com/questions/62386932/presto-hive-access-query-history
...and sets out the basics of how to get them in a different way.

This one gives an example of using fluentd to get the logs: https://stackoverflow.com/questions/47286733/logging-all-presto-queries

We chatted about this and decided that it would be really useful as a first step to try to get the Presto Web UI working.
https://prestodb.io/docs/current/admin/web-interface.html

We currently have the following set in /etc/presto/config.properties on both the coordinator and presto server roles.

http-server.http.enabled=false

We tested it and were able to get to the web UI over HTTP, using SSH forwarding, after enabling the http-server.http.enabled value manually on an-test-coord1001.

We still don't know how to get the kerberos enabled HTTPS version to work, but are working on it.

I made a subtask dedicated to enabling the presto UI: https://phabricator.wikimedia.org/T292087

Turns out Presto has a built-in query log in their internal table system.runtime.queries:

Example usage (remember to kinit first):

razzi@stat1005:/srv/home/razzi$ echo 'select state, user, source, query, started, "end" from queries limit 3;' | presto --catalog system --schema runtime

One limitation seems to be that queries are not retained for more than a few hours. There are currently 101 rows in the queries table and it looks like every new row drops an old one. I'm sure this is configurable, however.

On the "logging to disk" track, there seem to be a few promising java plugins that do this:

https://github.com/zz22394/presto-audit
https://github.com/rchukh/trino-querylog

Change 738987 had a related patch set uploaded (by Razzi; author: Razzi):

[schemas/event/secondary@master] [wip] Start of new presto query logger schema

https://gerrit.wikimedia.org/r/738987

I think that it might be useful to look first at getting the messages into rsyslog, then into logstash, before we go straight to eventgate.

How is the query logger likely to be executed? Will it run as a separate process, with its own stdout/stderr streams, or will it be running as a thread within the preso-server process?

If it is the former, so that we would e.g. start/stop is using systemctl then we could write to the process' own stdout/stderr streams.
https://wikitech.wikimedia.org/wiki/Logstash/Interface#Systemd_Journal_(stdout/stderr)

If it is the latter, then it might be preferable to write directly to /dev/log
https://wikitech.wikimedia.org/wiki/Logstash/Interface#UNIX_Socket_(/dev/log)

Ideally, rsyslog likes to work with JSON formatted messages, then we configure rsyslog to forward it to the kafka-logging cluster and it shows up in Logstash straight away.
https://wikitech.wikimedia.org/wiki/Logstash/Interface#Configuring_rsyslog_to_forward_your_logs

As @Ottomata mentioned there is a common schema for log messages called ECS (Elastic Common Schema), which the observability team have settled upon as a preferred standard. We are currently using version 1.7.0 of the ECS.

See: https://doc.wikimedia.org/ecs/
...and: https://wikitech.wikimedia.org/wiki/Logstash/Common_Logging_Schema

It it's not convenient to emit ECS format logs, there is an rsyslog configuration already in place that will attempt to parse and transform them for you. You can trigger this if needed by adding an ecs_170 tag to the rsyslog lookup table.
Here's an example of where that is used, converting plain syslog format line output to ECS compatible format.
https://gerrit.wikimedia.org/r/c/operations/puppet/+/729957

Sounds good @BTullis; I'm available to help as well. Repository is at https://gitlab.wikimedia.org/razzi/presto-query-logger, lmk if you need any sort of write access.

In T269832#7553437, @BTullis wrote:

I'm going to see if I can do a little work on this if that's OK with you @razzi. I will almost certainly need some help with the Java side, possibly from @JAllemandou or @mforns if that's convenient.

Happy to help as needed!

In T269832#7553450, @razzi wrote:

Sounds good @BTullis; I'm available to help as well. Repository is at https://gitlab.wikimedia.org/razzi/presto-query-logger, lmk if you need any sort of write access.

@razzi - Are you able to move the project to our shared sub-group https://gitlab.wikimedia.org/repos/data-engineering ?
I think that as the current project owner you can go to Settings -> General -> Advanced -> Transfer project -> Then select repos/data-engineering

It's possible that it might only show people/wmf-team-data-engineering when you drop it down but even that would be a good step. Maybe it would take two steps to change it to the repos/data-engineering path.
Failing that, I can always re-create it using this project as an initial source. Thanks.

Good call @btulis. Imported the project into https://gitlab.wikimedia.org/repos/data-engineering/presto-query-logger, I'll keep a fork in case I want to play around with gitlab etc but that can be the main repo.

One more thing that may be useful @BTullis: @JAllemandou and I started writing a schema for the events that the query logger will produce at https://gerrit.wikimedia.org/r/c/schemas/event/secondary/+/738987/

I've made a little more progress on this, although for the time being I have just decided to write to files and to base my work on the AWS example here:
https://aws.amazon.com/blogs/big-data/custom-log-presto-query-events-on-amazon-emr-for-auditing-and-performance-insights/

As @elukey mentioned, the version of the plugin provided in the AWS version does not log the query text itself.
However, I started building upon the source files and found this comment in the page.

I built the jar file with mvn package and then transferred this to an-test-coord1001.

I put the file in a new directory: /usr/lib/presto/plugin/presto-query-logger

btullis@an-test-coord1001:/etc/presto$ tree /usr/lib/presto/plugin/presto-query-logger/
/usr/lib/presto/plugin/presto-query-logger/
└── presto-query-logger-1.0-SNAPSHOT.jar

0 directories, 1 file

I get a message that the plugin has loaded successfully:

INFO        main        com.facebook.presto.server.PluginManager        -- Loading plugin /srv/presto/plugin/presto-query-logger --
INFO        main        com.facebook.presto.server.PluginManager        Installing org.wikimedia.presto.QueryEventListenerPlugin
INFO        main        com.facebook.presto.server.PluginManager        Registering event listener event-listener

I then create a configuraiton file to enable the event-listener:

btullis@an-test-coord1001:/etc/presto$ cat event-listener.properties 
event-listener.name=event-listener

...and restart the presto-server service again.

...and now I've got a log file containing the query.

btullis@an-test-coord1001:/var/log/presto$ cat queries-2021-12-10T18:17:21.0.log
Dec 10, 2021 6:21:07 PM org.wikimedia.presto.QueryEventListener queryCreated
INFO: ---------------Query Created----------------------------
     Query ID: 20211210_182106_00000_6xzqj
     Query State: QUEUED
     User: btullis
     Create Time: 2021-12-10T18:21:07.260Z
     Principal: Optional[btullis@WIKIMEDIA]
     Remote Client Address: Optional[10.64.5.6]
     Source: Optional[presto-cli]
     User Agent: Optional[StatementClientV1/0.246-cbd542a]
     Catalog: Optional[analytics_test_hive]
     Schema: Optional.empty
     Server Address: an-test-coord1001.eqiad.wmnet
     Query Text:  SHOW TABLES FROM event
Dec 10, 2021 6:21:08 PM org.wikimedia.presto.QueryEventListener splitCompleted
INFO: ---------------Split Completed----------------------------
     Query ID: 20211210_182106_00000_6xzqj
     Stage ID: 20211210_182106_00000_6xzqj.2
     Task ID: 0
Dec 10, 2021 6:21:09 PM org.wikimedia.presto.QueryEventListener queryCompleted
INFO: ---------------Query Completed----------------------------
     Query ID: 20211210_182106_00000_6xzqj
     Create Time: 2021-12-10T18:21:07.260Z
     User: btullis
     Complete: true
     Remote Client Address: Optional[10.64.5.6]

Very cool!

If you end up wanting to produce this as an event on Event Platform, https://gerrit.wikimedia.org/r/plugins/gitiles/wikimedia-event-utilities/#generate-an-event-prior-sending-it-to-kafka will help you do so in Java.

Thanks @Ottomata - Having given this some thought, I believe that my preferred course of action would be to send the events to Logstash, rather than to the Events Platform.
I can see the potential benefits of both schemes, but ultimately I think that we're going to get more immediate utility from the system if the events are in logstash. Creating events from presto queries themselves seems a bit self-referential.

So I think that the best course of action would be to generate ECS compatible logs within the presto-query-logger plugin and send them through rsyslog, via the kafka-logging cluster, into Opensearch and Logstash, where we can make dashboards to help troubleshoot long queries and track usage patterns.

I thin kthat we can either use the /dev/log interface for rsyslog, or we can use a dedicated log file and tail it.
https://wikitech.wikimedia.org/wiki/Logstash/Interface#UNIX_Socket_(/dev/log)
https://wikitech.wikimedia.org/wiki/Logstash/Interface#Tailing_Log_Files

I've also been looking at ECS logging libraries for java, to see whether immediately look suitable.
This one looks fine: https://github.com/elastic/ecs-logging-java

...but I don't really know what to do in terms of going forward with logback, or log4j2, or log4j or java.util.logging or slf4j.

I guess that the first course of action is to map our events fields to the ECS schema and work out which fields we should include/omit.
I think that the query itself is likely to end up as the message field.

Super-useful meeting with @JAllemandou about this.

It seems that there are several threads of what we need to do here, all of which are under way.

1. Ascertain which of the available properties and metrics are of interest to us and in which form, because we could easily overload ourselves with very low-level metrics.
2. Work out how best to log these in an ECS compatible way.
3. Figure out the details of the rsyslog pipeline and whether we use an intermediate file on the coordinator host, or whether we simply log to /dev/log.

For 1) the most useful set of statistics is that already made available via the QueryStatistics class. There is already an example of how to access this in the current version of the code, but the only statistic exposed is complete - when in fact many of the available statistics would be valuable.

Okay, sounds good! Just FYI: T291645: Produce ECS formatted logstash logs to Event Platform, allowing them to be queried in the WMF Data Lake with SQL

Taking this out of kanban for now, although we still want to do it.

@BTullis
Good afternoon.
I found this forum by accident and I need your help.
I work in security and would like to log Presto requests in particular:
the SQL query itself from the user and the number of bytes processed. On this information, it would be possible to build various analytics for security and see abnormally large data requests.
The problem is that I did not find a ready-made built-in mechanism in Presto for my needs. Presto stores the information I need at runtime and it can only be obtained by "select * from system.runtime.queries" and "select * from system.runtime.tasks" requests, and I need to receive this information in the form of a structured file so that I can redirect it in splunk and further analysis there.
While researching this problem on google, I found this forum and saw that the plugin developed here most suits my needs, but it is tied to the Presto version and does not work with Trino now. Tell me how to modify it so that I can collect logs in Trino?

I'm adding T325809: Presto is unstable with more than 5 worker nodes as a parent ticket of this, since we may wish to return to this work on logging presto queries as part of the investigation into the the cause of that problem.

It may well be that @nfraison picks up this ticket and continues to work on https://gitlab.wikimedia.org/repos/data-engineering/presto-query-logger to help isolate the cause of the increasing instability with greater worker count.

@Spaceliberty - Thanks for reaching out and apologies for the long delay in replying. Unfortunately, I don't think that we can offer much help to your question, as we do not currently run Trino ourselves.

I did come across this project which may help you: https://github.com/rchukh/trino-querylog

That code seems to take a very similar approach to the one we have started in https://gitlab.wikimedia.org/repos/data-engineering/presto-query-logger and has already been adapted from being a Presto plugin to a Trino plugin.

Added to previous sprint because we were failing to add nodes and to find root cause for adding them.
As the root cause has been identified without it + the load could still be high from presto to kdc removing this ticker from the sprint in favor of https://phabricator.wikimedia.org/T330119