Setting audit_log_rotate_on_size audit_log_flush & audit_log_rotate_on_size hangs server
Affects | Status | Importance | Assigned to | Milestone | ||
---|---|---|---|---|---|---|
Percona Server moved to https://jira.percona.com/projects/PS | Status tracked in 5.7 | |||||
5.5 |
Triaged
|
High
|
Sergei Glushchenko | |||
5.6 |
Triaged
|
High
|
Sergei Glushchenko | |||
5.7 |
Triaged
|
High
|
Sergei Glushchenko |
Bug Description
I have problem with audit_log.so, and tested it on
Ubuntu 12.04 LTS:
- Percona 5.6
- Percona 5.7
Ubuntu 16.04 LTS:
- Percona 5.6
- Percona 5.7
The issue is around audit_log_flush variable, not sure yet if it's just when setting it dynamically or always, but it's making mysql server unresponsive.
How to reproduce problem
Install ubuntu (possible the same issue on other systems)
just for check, do 10 000 queries to mysql.user
for i in `seq 10000`; do mysql -e 'select * from mysql.user limit 1'; done
Everything should work now.
Now login to mysql, and do:
>INSTALL PLUGIN audit_log SONAME "audit_log.so";
>set global audit_log_
And do the same
for i in `seq 10000`; do mysql -e 'select * from mysql.user limit 1'; done
This will hang, and you cannot open mysql connection anymore.
I tried to do strace on mysqld, and one pid reporting that:
set_robust_
clock_gettime(
futex(0x350fd1c, FUTEX_WAIT_
futex(0x350fcb0, FUTEX_WAKE_PRIVATE, 1) = 0
write(21, "<AUDIT_RECORD\n NAME=\"Audit\"\n R"..., 194) = 194
clock_gettime(
futex(0x350fd1c, FUTEX_WAIT_
clock_gettime(
futex(0x350fcb0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x350fd1c, FUTEX_WAIT_
clock_gettime(
futex(0x350fcb0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x350fd1c, FUTEX_WAIT_
clock_gettime(
futex(0x350fcb0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x350fd1c, FUTEX_WAIT_
clock_gettime(
futex(0x350fcb0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x350fd1c, FUTEX_WAIT_
clock_gettime(
futex(0x350fcb0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x350fd1c, FUTEX_WAIT_
futex(0x350fcb0, FUTEX_WAKE_PRIVATE, 1) = 0
write(21, "<AUDIT_RECORD\n NAME=\"Connect\"\n "..., 539) = 539
clock_gettime(
futex(0x350fd1c, FUTEX_WAIT_
clock_gettime(
futex(0x350fcb0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x350fd1c, FUTEX_WAIT_
clock_gettime(
futex(0x350fcb0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x350fd1c, FUTEX_WAIT_
clock_gettime(
futex(0x350fcb0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x350fd1c, FUTEX_WAIT_
futex(0x350fcb0, FUTEX_WAKE_PRIVATE, 1) = 0
write(21, "<AUDIT_RECORD\n NAME=\"Query\"\n R"..., 943) = 943
lseek(21, 0, SEEK_CUR) = 8162
access(
access(
access(
access(
access(
access(
access(
...
and another 700 000 logs like that audit.log.timestamp = no such file or directory
It looks like some weird loop somewhere :)
# date ; grep 'audit.log' ./strace.5753 | grep 'No such file' | wc -l
Tue Dec 13 04:42:38 UTC 2016
8185527
# date ; grep 'audit.log' ./strace.5753 | grep 'No such file' | wc -l
Tue Dec 13 04:42:47 UTC 2016
8513283
Thanks for attantion, hopefully it can be resolved .
It looks like it could be related to: https:/
but there is not much informations in there :)
Changed in percona-server: | |
assignee: | nobody → Muhammad Irfan (muhammad-irfan) |
summary: |
- audit_log.so bug + Setting audit_log_rotate_on_size audit_log_flush & + audit_log_rotate_on_size hangs server |
I'm able to reproduce with mentioned steps.
mysql> set global audit_log_ rotate_ on_size= 524288000; SET GLOBAL audit_log_flush = ON;
Query OK, 0 rows affected (0.04 sec)
Query OK, 0 rows affected (0.00 sec)
mysql> show variables like '%audit%'; ------- ------- ------- --+---- ------- ----+ ------- ------- ------- --+---- ------- ----+ buffer_ size | 1048576 | exclude_ accounts | | exclude_ commands | | exclude_ databases | | include_ accounts | | include_ commands | | include_ databases | | rotate_ on_size | 524288000 | syslog_ facility | LOG_USER | syslog_ ident | percona-audit | syslog_ priority | LOG_INFO | ------- ------- ------- --+---- ------- ----+
+------
| Variable_name | Value |
+------
| audit_log_
| audit_log_
| audit_log_
| audit_log_
| audit_log_file | audit.log |
| audit_log_flush | OFF |
| audit_log_format | OLD |
| audit_log_handler | FILE |
| audit_log_
| audit_log_
| audit_log_
| audit_log_policy | ALL |
| audit_log_
| audit_log_rotations | 0 |
| audit_log_strategy | ASYNCHRONOUS |
| audit_log_
| audit_log_
| audit_log_
+------
18 rows in set (0.00 sec)
$ for i in `seq 10000`; do mysql -e 'select * from mysql.user limit 1'; done
And it just hanged and I can't connect to MySQL server.
However, audit_log_flush shows OFF which is turned ON dynamically. This doesn't seems dynamic variable but doc mentions it's dynamic https:/ /www.percona. com/doc/ percona- server/ 5.6/management/ audit_log_ plugin. html#audit_ log_flush
Interestingly, when I enabled audit_log_flush & audit_log_ rotate_ on_size from my.cnf after restarting instance I couldn't reproduce same problem.
$ for i in `seq 10000`; do mysql -e 'select * from mysql.user limit 1'; done
This completed absolutely fine. It could be related to audit_log_flush handling.