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

Server crash on delete_table

Details

    Description

      Hello,

      If I execute these commands, mariadb server is crashed and restarted

      CREATE DATABASE test CHARACTER SET utf8mb4 COLLATE utf8mb4_unicode_ci;
      		 
      CREATE TABLE test.test (test varchar(100) NULL);
      		 
      DROP SCHEMA test;

      The table gets deleted, although the schema still exists (the crash occurs on the first "drop table", the remaining tables are kept).

      2024-11-30 09:43:28 2024-11-30  8:43:28 172 [ERROR] InnoDB: Operating system error number 5 in a file operation.
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 172 [ERROR] InnoDB: Error number 5 means 'Input/output error'
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 172 [Note] InnoDB: Some operating system error numbers are described at https://mariadb.com/kb/en/library/operating-system-error-codes/
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 172 [ERROR] InnoDB: File (unknown): 'close' returned OS error 205. Cannot continue operation
      		 
      2024-11-30 09:43:28 241130  8:43:28 [ERROR] mysqld got signal 6 ;
      		 
      2024-11-30 09:43:28 Sorry, we probably made a mistake, and this is a bug.
      		 
      2024-11-30 09:43:28 
      2024-11-30 09:43:28 Your assistance in bug reporting will enable us to fix this for the next release.
      		 
      2024-11-30 09:43:28 To report this bug, see https://mariadb.com/kb/en/reporting-bugs
      		 
      2024-11-30 09:43:28 
      2024-11-30 09:43:28 We will try our best to scrape up some info that will hopefully help
      		 
      2024-11-30 09:43:28 diagnose the problem, but since we have already crashed, 
      2024-11-30 09:43:28 something is definitely wrong and this may fail.
      		 
      2024-11-30 09:43:28 
      2024-11-30 09:43:28 Server version: 10.11.10-MariaDB-ubu2204 source revision: 3d0fb150289716ca75cd64d62823cf715ee47646
      		 
      2024-11-30 09:43:28 key_buffer_size=134217728
      		 
      2024-11-30 09:43:28 read_buffer_size=131072
      		 
      2024-11-30 09:43:28 max_used_connections=3
      		 
      2024-11-30 09:43:28 max_threads=153
      		 
      2024-11-30 09:43:28 thread_count=3
      		 
      2024-11-30 09:43:28 It is possible that mysqld could use up to 
      2024-11-30 09:43:28 key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 468074 K  bytes of memory
      		 
      2024-11-30 09:43:28 Hope that's ok; if not, decrease some variables in the equation.
      		 
      2024-11-30 09:43:28 
      2024-11-30 09:43:28 Thread pointer: 0xffff3c000c78
      		 
      2024-11-30 09:43:28 Attempting backtrace. You can use the following information to find out
      		 
      2024-11-30 09:43:28 where mysqld died. If you see no messages after this, something went
      		 
      2024-11-30 09:43:28 terribly wrong...
      		 
      2024-11-30 09:43:28 stack_bottom = 0xffff97f4c000 thread_stack 0x49000
      		 
      2024-11-30 09:43:28 Printing to addr2line failed
      		 
      2024-11-30 09:43:28 mariadbd(my_print_stacktrace+0x2c)[0xaaaad44e492c]
      		 
      2024-11-30 09:43:28 mariadbd(handle_fatal_signal+0x434)[0xaaaad40b7e48]
      		 
      2024-11-30 09:43:28 linux-vdso.so.1(__kernel_rt_sigreturn+0x0)[0xffff9f40b7a0]
      		 
      2024-11-30 09:43:28 /lib/aarch64-linux-gnu/libc.so.6(+0x7f200)[0xffff9eacf200]
      		 
      2024-11-30 09:43:28 /lib/aarch64-linux-gnu/libc.so.6(raise+0x1c)[0xffff9ea8a67c]
      		 
      2024-11-30 09:43:28 /lib/aarch64-linux-gnu/libc.so.6(abort+0xe4)[0xffff9ea77130]
      		 
      2024-11-30 09:43:28 mariadbd(+0xc9bfec)[0xaaaad438bfec]
      		 
      2024-11-30 09:43:28 mariadbd(+0xc33458)[0xaaaad4323458]
      		 
      2024-11-30 09:43:28 mariadbd(+0xc54728)[0xaaaad4344728]
      		 
      2024-11-30 09:43:28 mariadbd(+0x9c4998)[0xaaaad40b4998]
      		 
      2024-11-30 09:43:28 mariadbd(_Z15ha_delete_tableP3THDP10handlertonPKcPK25st_mysql_const_lex_stringS7_b+0x88)[0xaaaad40b4aac]
      		 
      2024-11-30 09:43:28 mariadbd(_Z23mysql_rm_table_no_locksP3THDP10TABLE_LISTPK25st_mysql_const_lex_stringP16st_ddl_log_statebbbbbb+0xce0)[0xaaaad3efb404]
      		 
      2024-11-30 09:43:28 mariadbd(+0x702d9c)[0xaaaad3df2d9c]
      		 
      2024-11-30 09:43:28 mariadbd(_Z21mysql_execute_commandP3THDb+0x28dc)[0xaaaad3e42c3c]
      		 
      2024-11-30 09:43:28 mariadbd(_Z11mysql_parseP3THDPcjP12Parser_state+0x19c)[0xaaaad3e44d1c]
      		 
      2024-11-30 09:43:28 mariadbd(_Z16dispatch_command19enum_server_commandP3THDPcjb+0xac0)[0xaaaad3e46610]
      		 
      2024-11-30 09:43:28 mariadbd(_Z10do_commandP3THDb+0x14c)[0xaaaad3e47a1c]
      		 
      2024-11-30 09:43:28 mariadbd(_Z24do_handle_one_connectionP7CONNECTb+0x290)[0xaaaad3f883a0]
      		 
      2024-11-30 09:43:28 mariadbd(handle_one_connection+0x18c)[0xaaaad3f88d8c]
      		 
      2024-11-30 09:43:28 mariadbd(+0xba802c)[0xaaaad429802c]
      		 
      2024-11-30 09:43:28 /lib/aarch64-linux-gnu/libc.so.6(+0x7d5c8)[0xffff9eacd5c8]
      		 
      2024-11-30 09:43:28 /lib/aarch64-linux-gnu/libc.so.6(+0xe5edc)[0xffff9eb35edc]
      		 
      2024-11-30 09:43:28 
      2024-11-30 09:43:28 Trying to get some variables.
      		 
      2024-11-30 09:43:28 Some pointers may be invalid and cause the dump to abort.
      		 
      2024-11-30 09:43:28 Query (0xffff3c010bc0): DROP SCHEMA `arena_demo123`
      		 
      2024-11-30 09:43:28 
      2024-11-30 09:43:28 Connection ID (thread ID): 172
      		 
      2024-11-30 09:43:28 Status: NOT_KILLED
      		 
      2024-11-30 09:43:28 
      2024-11-30 09:43:28 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=on,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on,condition_pushdown_for_subquery=on,rowid_filter=on,condition_pushdown_from_having=on,not_null_range_scan=off,hash_join_cardinality=off,cset_narrowing=off
      		 
      2024-11-30 09:43:28 
      2024-11-30 09:43:28 The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mariadbd/ contains
      		 
      2024-11-30 09:43:28 information that should help you find out what is causing the crash.
      		 
      2024-11-30 09:43:28 Writing a core file...
      		 
      2024-11-30 09:43:28 Working directory at /var/lib/mysql
      		 
      2024-11-30 09:43:28 Resource Limits:
      		 
      2024-11-30 09:43:28 Limit                     Soft Limit           Hard Limit           Units     
      2024-11-30 09:43:28 Max cpu time              unlimited            unlimited            seconds   
      2024-11-30 09:43:28 Max file size             unlimited            unlimited            bytes     
      2024-11-30 09:43:28 Max data size             unlimited            unlimited            bytes     
      2024-11-30 09:43:28 Max stack size            8388608              unlimited            bytes     
      2024-11-30 09:43:28 Max core file size        0                    unlimited            bytes     
      2024-11-30 09:43:28 Max resident set          unlimited            unlimited            bytes     
      2024-11-30 09:43:28 Max processes             unlimited            unlimited            processes 
      2024-11-30 09:43:28 Max open files            1048576              1048576              files     
      2024-11-30 09:43:28 Max locked memory         unlimited            unlimited            bytes     
      2024-11-30 09:43:28 Max address space         unlimited            unlimited            bytes     
      2024-11-30 09:43:28 Max file locks            unlimited            unlimited            locks     
      2024-11-30 09:43:28 Max pending signals       62864                62864                signals   
      2024-11-30 09:43:28 Max msgqueue size         819200               819200               bytes     
      2024-11-30 09:43:28 Max nice priority         0                    0                    
      2024-11-30 09:43:28 Max realtime priority     0                    0                    
      2024-11-30 09:43:28 Max realtime timeout      unlimited            unlimited            us        
      2024-11-30 09:43:28 Core pattern: core
      		 
      2024-11-30 09:43:28 
      2024-11-30 09:43:28 Kernel version: Linux version 6.10.14-linuxkit (root@buildkitsandbox) (gcc (Alpine 13.2.1_git20240309) 13.2.1 20240309, GNU ld (GNU Binutils) 2.42) #1 SMP Thu Oct 24 19:28:55 UTC 2024
      		 
      2024-11-30 09:43:28 
      2024-11-30 09:43:28 2024-11-30 08:43:28+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.11.10+maria~ubu2204 started.
      		 
      2024-11-30 09:43:28 2024-11-30 08:43:28+00:00 [Warn] [Entrypoint]: /sys/fs/cgroup///memory.pressure not writable, functionality unavailable to MariaDB
      		 
      2024-11-30 09:43:28 2024-11-30 08:43:28+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
      		 
      2024-11-30 09:43:28 2024-11-30 08:43:28+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.11.10+maria~ubu2204 started.
      		 
      2024-11-30 09:43:28 2024-11-30 08:43:28+00:00 [Note] [Entrypoint]: MariaDB upgrade not required
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Warning] Setting lower_case_table_names=2 because file system for /var/lib/mysql/ is case insensitive
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] Starting MariaDB 10.11.10-MariaDB-ubu2204 source revision 3d0fb150289716ca75cd64d62823cf715ee47646 server_uid Ryz2MTRM5HBXg59HG2vUa8EtyCA= as process 1
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] InnoDB: Number of transaction pools: 1
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] InnoDB: Using ARMv8 crc32 + pmull instructions
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] InnoDB: Using liburing
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] InnoDB: Initializing buffer pool, total size = 128.000MiB, chunk size = 2.000MiB
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] InnoDB: Completed initialization of buffer pool
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1659744920
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] InnoDB: End of log at LSN=1660125923
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] InnoDB: To recover: 324 pages
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] InnoDB: 128 rollback segments are active.
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] InnoDB: Removed temporary tablespace data file: "./ibtmp1"
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] InnoDB: log sequence number 1660125923; transaction id 16626
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] Plugin 'FEEDBACK' is disabled.
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Warning] You need to use --log-bin to make --expire-logs-days or --binlog-expire-logs-seconds work.
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] DDL_LOG: Crash recovery executed 1 entries
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] Server socket created on IP: '0.0.0.0'.
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] Server socket created on IP: '::'.
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] mariadbd: ready for connections.
      		 
      2024-11-30 09:43:28 Version: '10.11.10-MariaDB-ubu2204'  socket: '/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
      		 
      2024-11-30 09:43:28 2024-11-30  8:43:28 0 [Note] InnoDB: Buffer pool(s) load completed at 241130  8:43:28

      Any idea why this happens?

      Attachments

        Activity

          Ascending order - Click to sort in descending order
          danblack Daniel Black added a comment - - edited

          Is this a named volume or a path based volume mount?

          danblack Daniel Black added a comment - - edited Is this a named volume or a path based volume mount?
          cvirag Csaba Virag added a comment -

          Yes, the database files are under a path based volume mount.
          Btw, tested with named volume, it works fine with that setup.
          Is it a known issue I might missed?

          cvirag Csaba Virag added a comment - Yes, the database files are under a path based volume mount. Btw, tested with named volume, it works fine with that setup. Is it a known issue I might missed?
          danblack Daniel Black added a comment -

          As you see from the output, the container is a Linux container. The MacOS implementation of Docker Desktop runs a VM for the container. named volumes are created in this VM, and use quite well tested Linux API calls. Path based mounts go though some fileystem to MacOS layer.

          On Linux the system calls from the deleting of the table to the deleting of the datadir is:

          [pid 649829] unlink("./test/test.ibd")  = 0
          		 
          [pid 649829] unlink("./test/test.cfg")  = -1 ENOENT (No such file or directory)
          		 
          [pid 649829] close(43)                  = 0
          		 
          [pid 649829] access("./test/test.frm", F_OK) = 0
          		 
          [pid 649829] unlink("./test/test.frm")  = 0
          		 
          [pid 649829] pwrite64(3, "\1", 1, 12290) = 1
          		 
          [pid 649829] fdatasync(3)               = 0
          		 
          [pid 649829] access("./test/test.TRG", F_OK) = -1 ENOENT (No such file or directory)
          		 
          [pid 649829] pwrite64(3, "\2", 1, 12290) = 1
          		 
          [pid 649829] fdatasync(3)               = 0
          		 
          [pid 649829] pwrite64(3, "\2\v\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096, 16384) = 4096
          		 
          [pid 649829] fdatasync(3)               = 0
          		 
          [pid 649829] pwrite64(3, "\1\0\0\0\4\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096, 4096) = 4096
          		 
          [pid 649829] fdatasync(3)               = 0
          		 
          [pid 649829] mmap(0x529000080000, 262144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x529000080000
          		 
          [pid 649829] newfstatat(AT_FDCWD, "./test/db.opt", 0x7f47f06c8c20, AT_SYMLINK_NOFOLLOW) = -1 ENOENT (No such file or directory)
          		 
          [pid 649829] unlink("./test/db.opt")    = -1 ENOENT (No such file or directory)
          		 
          [pid 649829] readlink("./test", 0x7f47f0a222f0, 511) = -1 EINVAL (Invalid argument)
          		 
          [pid 649829] rmdir("./test")            = 0

          Per your logs, one of the close system calls is returning a EIO (5).

          I tried, but failed, in demangling the stack to work out which file it might be. Even if we did work out which file, I'm not sure we have a good way to handle the error (hence the fatal exit).

          From https://www.docker.com/blog/speed-boost-achievement-unlocked-on-docker-desktop-4-6-for-mac/ are you using virtiofs?

          danblack Daniel Black added a comment - As you see from the output, the container is a Linux container. The MacOS implementation of Docker Desktop runs a VM for the container. named volumes are created in this VM, and use quite well tested Linux API calls. Path based mounts go though some fileystem to MacOS layer. On Linux the system calls from the deleting of the table to the deleting of the datadir is: [pid 649829] unlink("./test/test.ibd") = 0 [pid 649829] unlink("./test/test.cfg") = -1 ENOENT (No such file or directory) [pid 649829] close(43) = 0 [pid 649829] access("./test/test.frm", F_OK) = 0 [pid 649829] unlink("./test/test.frm") = 0 [pid 649829] pwrite64(3, "\1", 1, 12290) = 1 [pid 649829] fdatasync(3) = 0 [pid 649829] access("./test/test.TRG", F_OK) = -1 ENOENT (No such file or directory) [pid 649829] pwrite64(3, "\2", 1, 12290) = 1 [pid 649829] fdatasync(3) = 0 [pid 649829] pwrite64(3, "\2\v\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096, 16384) = 4096 [pid 649829] fdatasync(3) = 0 [pid 649829] pwrite64(3, "\1\0\0\0\4\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096, 4096) = 4096 [pid 649829] fdatasync(3) = 0 [pid 649829] mmap(0x529000080000, 262144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x529000080000 [pid 649829] newfstatat(AT_FDCWD, "./test/db.opt", 0x7f47f06c8c20, AT_SYMLINK_NOFOLLOW) = -1 ENOENT (No such file or directory) [pid 649829] unlink("./test/db.opt") = -1 ENOENT (No such file or directory) [pid 649829] readlink("./test", 0x7f47f0a222f0, 511) = -1 EINVAL (Invalid argument) [pid 649829] rmdir("./test") = 0 Per your logs, one of the close system calls is returning a EIO (5). I tried, but failed, in demangling the stack to work out which file it might be. Even if we did work out which file, I'm not sure we have a good way to handle the error (hence the fatal exit). From https://www.docker.com/blog/speed-boost-achievement-unlocked-on-docker-desktop-4-6-for-mac/ are you using virtiofs?
          cvirag Csaba Virag added a comment -

          Yes, I have that enabled as default.

          cvirag Csaba Virag added a comment - Yes, I have that enabled as default.
          Gosselin Dave Gosselin added a comment -

          I can reproduce this crash on 10.11.10 under Docker with Docker VMM enabled. Under Apple Virtualization framework, I cannot reproduce this bug. I tried some other things outside of Docker too, running on both macOS and Linux bare-metal directly, such as deleting files from the database via the terminal before invoking DROP SCHEMA. I couldn't reproduce an EIO error that way, but was able to do so readily within Docker.

          Gosselin Dave Gosselin added a comment - I can reproduce this crash on 10.11.10 under Docker with Docker VMM enabled. Under Apple Virtualization framework, I cannot reproduce this bug. I tried some other things outside of Docker too, running on both macOS and Linux bare-metal directly, such as deleting files from the database via the terminal before invoking DROP SCHEMA . I couldn't reproduce an EIO error that way, but was able to do so readily within Docker.
          Gosselin Dave Gosselin added a comment -

          cvirag as a work-around, I suggest running under "Apple Virtualization framework" to avoid this crash (please see my prior comment on the ticket).

          Gosselin Dave Gosselin added a comment - cvirag as a work-around, I suggest running under "Apple Virtualization framework" to avoid this crash (please see my prior comment on the ticket).
          serg Sergei Golubchik added a comment - - edited

          Gosselin, I would guess that whatever the actual underlying reason for this issue is, the crash happens because the server gets an error from the OS where no error is expected? Then, perhaps the server should expect an error at that particular place?

          serg Sergei Golubchik added a comment - - edited Gosselin , I would guess that whatever the actual underlying reason for this issue is, the crash happens because the server gets an error from the OS where no error is expected? Then, perhaps the server should expect an error at that particular place?
          Gosselin Dave Gosselin added a comment -

          serg yes, I agree, just trying to get something helpful to the user ASAP. Will continue investigating.

          Gosselin Dave Gosselin added a comment - serg yes, I agree, just trying to get something helpful to the user ASAP. Will continue investigating.

          People

            Gosselin Dave Gosselin
            cvirag Csaba Virag
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

            Dates

              Created:
              Updated:

              Git Integration

                Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.