audit_log/audit_log.c:522: audit_log_general_record: Assertion `errors == 0' failed

[Tomislav Plavcic]

mysqld: /home/tomislav.plavcic/workdir/percona-server/plugin/audit_log/audit_log.c:522: audit_log_general_record: Assertion `errors == 0' failed.
20:38:14 UTC - mysqld got signal 6 ;

GDB:
+bt
#0 0x00007f048855c771 in pthread_kill () from /lib64/libpthread.so.0
#1 0x00000000018ebcbf in my_write_core (sig=6) at /home/tomislav.plavcic/workdir/percona-server/mysys/stacktrace.c:247
#2 0x0000000000e7db5c in handle_fatal_signal (sig=6) at /home/tomislav.plavcic/workdir/percona-server/sql/signal_handler.cc:223
#3 <signal handler called>
#4 0x00007f04866e85d7 in raise () from /lib64/libc.so.6
#5 0x00007f04866e9cc8 in abort () from /lib64/libc.so.6
#6 0x00007f04866e1546 in __assert_fail_base () from /lib64/libc.so.6
#7 0x00007f04866e15f2 in __assert_fail () from /lib64/libc.so.6
#8 0x00007f0456d41385 in audit_log_general_record (buf=0x7f0488a4de30 "CREATE t \\217\\355ف?\\355ف?\\355\\335(\\217\\260\\241\\217\\260\\241\\217\\260\\241 char)DEFAULT CHARSET=ujis engine=TokuDBUDIT_RECORD\n NAME=\"Query\"\n RECORD=\"16_2016-08-18T08:49:44\"\n TIMESTAMP=\"2016-08-18T08:50:35 UTC\"\n COMMAND_CLASS=\"set_option\"\n CONNECTION_ID=\"6\"\n STATUS=\"0\"\n SQLTEXT=\"SET @@character_set_client=cp1256\"\n USER=\"root[root] @ localhost []\"\n HOST=\"localhost\"\n OS_USER=\"\"\n IP=\"\"\n DB=\"test\"\n/>\n", buflen=4096, name=0x2141d8f "Query", t=1471510235, status=1064, event=0x7f0488a4ef80, default_db=0x7f0452c3f42a "test", outlen=0x7f0488a4ddf8) at /home/tomislav.plavcic/workdir/percona-server/plugin/audit_log/audit_log.c:522
#9 0x00007f0456d43216 in audit_log_notify (thd=0x7f0452c06000, event_class=MYSQL_AUDIT_GENERAL_CLASS, event=0x7f0488a4ef80) at /home/tomislav.plavcic/workdir/percona-server/plugin/audit_log/audit_log.c:1170
#10 0x0000000000e7fc6b in plugins_dispatch (thd=0x7f0452c06000, plugin=0x7f045a3220f0, arg=0x7f0488a4ef10) at /home/tomislav.plavcic/workdir/percona-server/sql/sql_audit.cc:1231
#11 0x0000000000e7fddc in event_class_dispatch (thd=0x7f0452c06000, event_class=MYSQL_AUDIT_GENERAL_CLASS, event=0x7f0488a4ef80) at /home/tomislav.plavcic/workdir/percona-server/sql/sql_audit.cc:1294
#12 0x0000000000e7e37b in mysql_audit_notify (thd=0x7f0452c06000, subclass=MYSQL_AUDIT_GENERAL_STATUS, error_code=1064, msg=0x2141d8f "Query", msg_len=5) at /home/tomislav.plavcic/workdir/percona-server/sql/sql_audit.cc:327
#13 0x00000000015852c3 in mysql_audit_general (thd=0x7f0452c06000, event_subtype=MYSQL_AUDIT_GENERAL_STATUS, error_code=1064, msg=0x2141d8f "Query") at /home/tomislav.plavcic/workdir/percona-server/sql/sql_audit.h:93
#14 0x000000000158a7dd in dispatch_command (thd=0x7f0452c06000, com_data=0x7f0488a4fc90, command=COM_QUERY) at /home/tomislav.plavcic/workdir/percona-server/sql/sql_parse.cc:1874
#15 0x00000000015881c6 in do_command (thd=0x7f0452c06000) at /home/tomislav.plavcic/workdir/percona-server/sql/sql_parse.cc:1010
#16 0x00000000016d6629 in handle_connection (arg=0x7f045a3220d0) at /home/tomislav.plavcic/workdir/percona-server/sql/conn_handler/connection_handler_per_thread.cc:312
#17 0x0000000001d91cf2 in pfs_spawn_thread (arg=0x7f047a3f0120) at /home/tomislav.plavcic/workdir/percona-server/storage/perfschema/pfs.cc:2188
#18 0x00007f0488557df5 in start_thread () from /lib64/libpthread.so.0
#19 0x00007f04867a91ad in clone () from /lib64/libc.so.6

TESTCASE1:
# mysqld options required for replay: --init-file=/home/tomislav.plavcic/percona-qa-ps57/plugins_57.sql
DROP DATABASE test;
SET @@character_set_client=cp1256;
CREATE t \217\355ݏ\355ݏ\355\335(\217\260\241\217\260\241\217\260\241 char)DEFAULT CHARSET=ujis engine=TokuDB;

TESTCASE2:
# mysqld options required for replay: --init-file=/home/tomislav.plavcic/percona-qa-ps57/plugins_57.sql
DROP DATABASE test;
SET @@character_set_client=sjis;
CREATE t ｱｱｱ(ｶｶｶ char)DEFAULT CHARSET=utf0engine=InnoDB;

The plugins enabled are from:
https://github.com/tplavcic/percona-qa/blob/master/plugins_57.sql

[Tomislav Plavcic (tplavcic)]

I see a lot of this (almost every third or even second pquery run) and it's seen in 5.6 and 5.7.

[Sergei Glushchenko (sergei.glushchenko)]

The query "CREATE t \217\355ݏ\355ݏ\355\335(\217\260\241\217\260\241\217\260\241 char)DEFAULT CHARSET=ujis engine=TokuDB;"

becomes "CREATE t \217\355ف?\355ف?\355\335(\217\260\241\217\260\241\217\260\241 char)DEFAULT CHARSET=ujis engine=TokuDB" after encoding in utf8, and contains two "?" signs which means original had two errors.

It means that client can send query containing invalid character sequences for clients encoding and audit plugin will receive them "as is", which means "error == 0" is invalid assertion.

I suggest to remove it.

[Roel Van de Paar (roel11)]

Agree with Sergei & Laurynas on proposal to remove debug assert.

[Sergei Glushchenko (sergei.glushchenko)]

https://github.com/percona/percona-server/pull/865
https://github.com/percona/percona-server/pull/866

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-997