Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-4935

Audit: MariaDB crashes when a remote DDL/DML query is sent

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 5.5.32
    • Fix Version/s: None
    • Component/s: None
    • Labels:
      None
    • Environment:
      MariaDB installed via RPMs, CentOS 6 in a VM environment. Remote server running MariaDB 5.5.32.

      Description

      When executing any DML/DDL query remotely, MariaDB crashes.

      Configuration:

      server_audit_events=CONNECT,TABLE,QUERY
      server_audit_output_type=FILE
      server_audit_file_path=audit.log
      server_audit_file_rotate_size=100000
      server_audit_logging=OFF
      
      [wfong@mariaref ~]$ mysql -h 192.168.7.174 -u will 
      Welcome to the MariaDB monitor.  Commands end with ; or \g.
      Your MariaDB connection id is 5
      Server version: 5.5.32-MariaDB-log MariaDB Server
      
      Copyright (c) 2000, 2013, Oracle, Monty Program Ab and others.
      
      Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
      
      MariaDB [(none)]> SELECT VERSION(), CURRENT_USER();
      +--------------------+----------------+
      | VERSION()          | CURRENT_USER() |
      +--------------------+----------------+
      | 5.5.32-MariaDB-log | will@%         |
      +--------------------+----------------+
      1 row in set (0.00 sec)
      
      MariaDB [(none)]> SHOW GLOBAL VARIABLES LIKE 'server_audit_%';
      +-------------------------------+-----------------------+
      | Variable_name                 | Value                 |
      +-------------------------------+-----------------------+
      | server_audit_events           | CONNECT,QUERY,TABLE   |
      | server_audit_excl_users       |                       |
      | server_audit_file_path        | audit.log             |
      | server_audit_file_rotate_size | 100000                |
      | server_audit_incl_users       |                       |
      | server_audit_logging          | OFF                   |
      | server_audit_mode             | 1                     |
      | server_audit_output_type      | file                  |
      | server_audit_rotate           | OFF                   |
      | server_audit_rotations        | 9                     |
      | server_audit_syslog_facility  | LOG_USER              |
      | server_audit_syslog_ident     | mysql-server_auditing |
      | server_audit_syslog_info      |                       |
      | server_audit_syslog_priority  | LOG_INFO              |
      +-------------------------------+-----------------------+
      14 rows in set (0.00 sec)
      
      MariaDB [(none)]> INSERT INTO test.foo VALUES ( 2 );
      Query OK, 1 row affected (0.00 sec)
      
      MariaDB [(none)]> SET GLOBAL server_audit_logging = ON;
      Query OK, 0 rows affected (0.00 sec)
      
      MariaDB [(none)]> INSERT INTO test.foo VALUES ( 3 );
      ERROR 2013 (HY000): Lost connection to MySQL server during query
      MariaDB [(none)]> 
      

      Stack Trace:

      130822  7:43:39 [Warning] IP address '192.168.7.172' could not be resolved: Name or service not known
      130822  7:45:53 server_audit: logging was enabled.
      130822  7:45:55 [ERROR] mysqld got signal 11 ;
      This could be because you hit a bug. It is also possible that this binary
      or one of the libraries it was linked against is corrupt, improperly built,
      or misconfigured. This error can also be caused by malfunctioning hardware.
      
      To report this bug, see http://kb.askmonty.org/en/reporting-bugs
      
      We will try our best to scrape up some info that will hopefully help
      diagnose the problem, but since we have already crashed, 
      something is definitely wrong and this may fail.
      
      Server version: 5.5.32-MariaDB-log
      key_buffer_size=134217728
      read_buffer_size=131072
      max_used_connections=2
      max_threads=153
      thread_count=2
      It is possible that mysqld could use up to 
      key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 466714 K  bytes of memory
      Hope that's ok; if not, decrease some variables in the equation.
      
      Thread pointer: 0x0x3cecbe0
      Attempting backtrace. You can use the following information to find out
      where mysqld died. If you see no messages after this, something went
      terribly wrong...
      stack_bottom = 0x7f85442c1d78 thread_stack 0x48000
      ??:0(my_print_stacktrace)[0xa8631e]
      ??:0(handle_fatal_signal)[0x6cdd0b]
      ??:0(??)[0x3bc6a0f500]
      ??:0(??)[0x3bc6732d5f]
      ??:0(??)[0x7f85444d3e9f]
      ??:0(??)[0x7f85444d44df]
      ??:0(table_class_handler(THD*, unsigned int, __va_list_tag*))[0x6454ba]
      ??:0(mysql_audit_notify(THD*, unsigned int, unsigned int, ...))[0x644f74]
      ??:0(handler::ha_external_lock(THD*, int))[0x6ceb47]
      ??:0(mysql_lock_tables(THD*, st_mysql_lock*, unsigned int))[0x78c3dd]
      ??:0(mysql_lock_tables(THD*, TABLE**, unsigned int, unsigned int))[0x78c783]
      ??:0(lock_tables(THD*, TABLE_LIST*, unsigned int, unsigned int))[0x546f35]
      ??:0(open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*))[0x54c202]
      ??:0(mysql_insert(THD*, TABLE_LIST*, List<Item>&, List<List<Item> >&, List<Item>&, List<Item>&, enum_duplicates, bool))[0x5765a3]
      ??:0(mysql_execute_command(THD*))[0x58b160]
      ??:0(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x58e369]
      ??:0(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x58f790]
      ??:0(do_handle_one_connection(THD*))[0x647cdf]
      ??:0(handle_one_connection)[0x647d7c]
      ??:0(??)[0x3bc6a07851]
      ??:0(??)[0x3bc66e890d]
      
      Trying to get some variables.
      Some pointers may be invalid and cause the dump to abort.
      Query (0x7f8508004c88): is an invalid pointer
      Connection ID (thread ID): 5
      Status: NOT_KILLED
      
      Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=off
      
      The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
      information that should help you find out what is causing the crash.
      130822 07:45:55 mysqld_safe Number of processes running now: 0
      130822 07:45:55 mysqld_safe mysqld restarted
      130822  7:45:55 InnoDB: The InnoDB memory heap is disabled
      130822  7:45:55 InnoDB: Mutexes and rw_locks use GCC atomic builtins
      130822  7:45:55 InnoDB: Compressed tables use zlib 1.2.3
      130822  7:45:55 InnoDB: Using Linux native AIO
      130822  7:45:55 InnoDB: Initializing buffer pool, size = 128.0M
      130822  7:45:55 InnoDB: Completed initialization of buffer pool
      130822  7:45:55 InnoDB: highest supported file format is Barracuda.
      InnoDB: The log sequence number in ibdata files does not match
      InnoDB: the log sequence number in the ib_logfiles!
      130822  7:45:55  InnoDB: Database was not shut down normally!
      InnoDB: Starting crash recovery.
      InnoDB: Reading tablespace information from the .ibd files...
      InnoDB: Restoring possible half-written data pages from the doublewrite
      InnoDB: buffer...
      130822  7:45:55  InnoDB: Waiting for the background threads to start
      130822  7:45:56 Percona XtraDB (http://www.percona.com) 5.5.32-MariaDB-30.2 started; log sequence number 1601509
      130822  7:45:56 [Note] Plugin 'FEEDBACK' is disabled.
      130822  7:45:56 server_audit: STARTED
      130822  7:45:56 server_audit: Output was redirected to 'file'
      130822  7:45:56 server_audit: logging is disabled.
      130822  7:45:56 [Note] Server socket created on IP: '0.0.0.0'.
      130822  7:45:56 [Note] Event Scheduler: Loaded 0 events
      130822  7:45:56 [Note] /usr/sbin/mysqld: ready for connections.
      Version: '5.5.32-MariaDB-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server
      

      General Query Log:

      130822  7:44:41	    5 Connect	will@192.168.7.172 as anonymous on 
      		    5 Query	select @@version_comment limit 1
      130822  7:44:57	    5 Query	SELECT VERSION(), CURRENT_USER()
      130822  7:45:15	    5 Query	SHOW GLOBAL VARIABLES LIKE 'server_audit_%'
      130822  7:45:25	    5 Query	INSERT INTO test.foo VALUES ( 2 )
      130822  7:45:53	    5 Query	SET GLOBAL server_audit_logging = ON
      130822  7:45:55	    5 Query	INSERT INTO test.foo VALUES ( 3 )
      /usr/sbin/mysqld, Version: 5.5.32-MariaDB-log (MariaDB Server). started with:
      

        Gliffy Diagrams

          Attachments

            Activity

            Hide
            holyfoot Alexey Botchkov added a comment -

            Cannot repeat right now. Should've been fixed somewhere along the way.

            Show
            holyfoot Alexey Botchkov added a comment - Cannot repeat right now. Should've been fixed somewhere along the way.

              People

              • Assignee:
                holyfoot Alexey Botchkov
                Reporter:
                wfong Will Fong
              • Votes:
                0 Vote for this issue
                Watchers:
                3 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: