Audit_log - Logging questions

Good Morning,

I have a few queries about the what is being logged when I’m using audit_log.

Some background:

We are logging all queries made on one of our DBs and then sending that information to an ELK stack so that we can see it visually. Im not sure if this has any baring on my below questions but i felt as though this was important to mention

1 - Alot of the queries that we appear to be logging seem to be giving us:

audit_record.user - (empty)

My instinct tells me that this is filebeat check that there is a connection that can be made but i dont see why this would be marked as empty? Surely queries should never be empty

I came to this conclusion because agent.type = filebeat but i could be wrong

2 - We seem to be getting an awful lot of root user queries being logged despite nobody being logged in as user the majority of the time. Some root user logging is explainable but most of it isnt. Is there a way that i can debug this? I have tried checking the processlist but there is nothing being run as root. The major concern is that something seems to be logging as root every few seconds and i cant seem to debug where its coming from

3 - When a client runs a query it would appear that the log seems to be being filled up with hundreds of records? As an example a client ran a query and it populate 152 new records in ELK. Am i correct in assuming that each log record equates to 1 line i.e. If i ran show databases; and it gave 200 records it would therefore populate 200 log entries?

4 - This is a relatively softer questions as i just need clarification on the formatting of some log entries are showing:

root[root] @ localhost

What do the square brackets indicate? and what if they are empty? Sometimes the square brackets are not there at all and will simply be root @ localhost

If you require any further information about the any of the questions please let me know and i will provide more information and context

Hi @simonnutsey98 welcome back to the Percona forums!

Your best course of action would be to enable the general or slow log in order to complement the audit log, and look to correlate log events. You could pass a day’s worth of general/slow logs via pt-query-digest and use a filter to look for just the root user like this: --filter ‘($event->{user} || “”) =~ m/root/’. This should address your first and second questions.

Regarding your third question, each audit record should be one complete query. So I would assume your client is connecting and executing 152 different queries.

Finally the square brackets from your fourth question indicate no query was executed, that the root user connected and then disconnected. Do you have a cron job or other such task enabled?

Hi Michael,

Thanks for the response but im still a bit hazy on few things and i’ve just head back from our external client who are using this system.

Ill take a look at using the pt-query-digest but ill need to look at docs as im not too sure exactly how to use it at the moment haha

On some good news i do believe we have figured out why there are so many queries being logged and this is because all their queries are being run through MySQL workbench so its likely logging loads of other stuff that isn’t needed but thats neither here nor there. Happy to mark that one as solved :slight_smile:

I am still a bit hazy on the square brackets though. As an example:

Jul 14, 2023 @ 09:09:34.957 adam 
Jul 14, 2023 @ 09:09:34.957 adam[adam] @ localhost [] 
Jul 14, 2023 @ 09:09:34.957 adam[adam] @ localhost []

Why does the first entry simply say adam and the following to entries have adam[adam] and then localhost with the empty brackets?

Can you please clarify a little further of how it displays queries?

Thanks
Simon

Hi Simon,

It seems you have gripped the user from the logs.
But most probably, the line with only the user should be from “Connect” record. While connecting it will display just the user name and not the mapping with hostname.

<AUDIT_RECORD
  NAME="Connect"
  RECORD="34582_2023-07-25T02:34:59"
  TIMESTAMP="2023-07-25T05:54:50Z"
  CONNECTION_ID="19"
  STATUS="0"
  USER="root"
  PRIV_USER="root"
  OS_LOGIN=""
  PROXY_USER=""
  HOST="localhost"
  IP=""
  DB=""
/>

While when it will log the query, it will show the proper mapping of the user. That means which user it used for connection with hostname mapping. [root]@[localhost]. Here is an example,

<AUDIT_RECORD
  NAME="Query"
  RECORD="34583_2023-07-25T02:34:59"
  TIMESTAMP="2023-07-25T05:54:50Z"
  COMMAND_CLASS="select"
  CONNECTION_ID="19"
  STATUS="0"
  SQLTEXT="select @@version_comment limit 1"
  USER="root[root] @ localhost []"
  HOST="localhost"
  OS_USER=""
  IP=""
  DB=""
/>
<AUDIT_RECORD
  NAME="Query"
  RECORD="34584_2023-07-25T02:34:59"
  TIMESTAMP="2023-07-25T05:54:56Z"
  COMMAND_CLASS="select"
  CONNECTION_ID="19"
  STATUS="0"
  SQLTEXT="select * from test.t1"
  USER="root[root] @ localhost []"
  HOST="localhost"
  OS_USER=""
  IP=""
  DB=""
/>

Hope that helps you.

Thanks,
Yunus Shaikh