Following INSTALL-BINARY instructions,
scripts/mysql_install_db --user=mysql
failed:
$ sudo scripts/mysql_install_db --user=mysql
Installing MariaDB/MySQL system tables in './data' ...
2022-06-06 4:17:03 0 [Warning] InnoDB: Retry attempts for writing partial data failed.
2022-06-06 4:17:03 0 [ERROR] InnoDB: Write to file ./ibdata1 failed at offset 0, 1048576 bytes should have been written, only 0 were written. Operating system error number 22. Check that your OS and file system support files of this size. Check also that the disk is not full or a disk quota exceeded.
2022-06-06 4:17:03 0 [ERROR] InnoDB: Error number 22 means 'Invalid argument'
2022-06-06 4:17:03 0 [ERROR] InnoDB: Could not set the file size of './ibdata1'. Probably out of disk space
2022-06-06 4:17:03 0 [ERROR] InnoDB: Database creation was aborted with error Generic error. You may need to delete the ibdata1 file before trying to start up again.
2022-06-06 4:17:04 0 [ERROR] Plugin 'InnoDB' init function returned error.
2022-06-06 4:17:04 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
MariaDB 10.6.0 Release Notes say:
innodb_flush_method=O_DIRECT is enabled by default (MDEV-24854)
Perhaps the overlay filesystem does not support O_DIRECT ?
Thank you!
Daniel Lewart
Urbana, Illinois
Daniel Lewart
added a comment - - edited Sorry, Jira refuses to let me set the Priority to Normal.
I used strace and found the following difference:
10.5.16:
openat(AT_FDCWD, "./ibdata1", O_RDWR|O_CREAT|O_EXCL|O_CLOEXEC, 0660) = 9
fstat(9, \{st_mode=S_IFREG|0660, st_size=0, ...\}) = 0
fallocate(9, 0, 0, 12582912) = 0
close(9) = 0
10.6.8:
openat(AT_FDCWD, "./ibdata1", O_RDWR|O_CREAT|O_EXCL|O_CLOEXEC, 0660) = 9
*fcntl(9, F_SETFL, O_RDONLY|O_DIRECT) = 0*
fstat(9, \{st_mode=S_IFREG|0660, st_size=0, ...\}) = 0
fallocate(9, 0, 0, 12582912) = *-1 EINVAL (Invalid argument)*
MariaDB 10.6.0 Release Notes say:
innodb_flush_method=O_DIRECT is enabled by default ( MDEV-24854 )
Perhaps the overlay filesystem does not support O_DIRECT ?
Thank you!
Daniel Lewart
Urbana, Illinois
O_DIRECT is quite possibly a contributor to the error.
The fallocate failure isn't the fatal, beyond the point which you straced, there is a fallback to just writing blocks on the file.
What are the other filesystems involved to create the overlayfs mount? What kernel version? Can you strace further (mariadbd --no-defaults --bootstrap --datadir=/empty/dir/on/overlayfs is likely to be sufficient)?
Daniel Black
added a comment - O_DIRECT is quite possibly a contributor to the error.
The fallocate failure isn't the fatal, beyond the point which you straced , there is a fallback to just writing blocks on the file.
What are the other filesystems involved to create the overlayfs mount? What kernel version? Can you strace further ( mariadbd --no-defaults --bootstrap --datadir=/empty/dir/on/overlayfs is likely to be sufficient)?
2022-06-06 2:05:56 0 [Note] bin/mariadbd (server 10.6.8-MariaDB) starting as process 32544 ...
strace: decode_nlattr: [xlat 0x55ffeb8dc2c0, dflt "AF_???", decoders 0x7ffcde542120] size is zero (going to pass nla_type as decoder argument), but opaque data (0x7ffcde5421e0) is not - will be ignored
strace: decode_nlattr: [xlat 0x55ffeb8dc2c0, dflt "AF_???", decoders 0x7ffcde542120] size is zero (going to pass nla_type as decoder argument), but opaque data (0x7ffcde5421e0) is not - will be ignored
strace: decode_nlattr: [xlat 0x55ffeb8dc2c0, dflt "AF_???", decoders 0x7ffcde542120] size is zero (going to pass nla_type as decoder argument), but opaque data (0x7ffcde5421e0) is not - will be ignored
strace: decode_nlattr: [xlat 0x55ffeb8dc2c0, dflt "AF_???", decoders 0x7ffcde542120] size is zero (going to pass nla_type as decoder argument), but opaque data (0x7ffcde5421e0) is not - will be ignored
2022-06-06 2:05:56 0 [Note] InnoDB: The first data file './ibdata1' did not exist. A new tablespace will be created!
2022-06-06 2:05:56 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2022-06-06 2:05:56 0 [Note] InnoDB: Number of pools: 1
2022-06-06 2:05:56 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2022-06-06 2:05:56 0 [Note] InnoDB: Using Linux native AIO
2022-06-06 2:05:56 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728
2022-06-06 2:05:56 0 [Note] InnoDB: Completed initialization of buffer pool
2022-06-06 2:05:56 0 [Note] InnoDB: Setting file './ibdata1' size to 12 MB. Physically writing the file full; Please wait ...
2022-06-06 2:05:56 0 [Warning] InnoDB: Retry attempts for writing partial data failed.
2022-06-06 2:05:56 0 [ERROR] InnoDB: Write to file ./ibdata1 failed at offset 0, 1048576 bytes should have been written, only 0 were written. Operating system error number 22. Check that your OS and file system support files of this size. Check also that the disk is not full or a disk quota exceeded.
2022-06-06 2:05:56 0 [ERROR] InnoDB: Error number 22 means 'Invalid argument'
2022-06-06 2:05:56 0 [Note] InnoDB: Some operating system error numbers are described at https://mariadb.com/kb/en/library/operating-system-error-codes/
2022-06-06 2:05:56 0 [ERROR] InnoDB: Could not set the file size of './ibdata1'. Probably out of disk space
2022-06-06 2:05:56 0 [ERROR] InnoDB: Database creation was aborted with error Generic error. You may need to delete the ibdata1 file before trying to start up again.
By the way, changing datadir to /tmp/data (tmpfs) worked!
Thank you!
Dan
Daniel Lewart
added a comment - - edited Daniel,
$ findmnt -J /
{
"filesystems": [
{"target":"/", "source":"overlay", "fstype":"overlay", "options":"rw,noatime,lowerdir=/run/live/rootfs/filesystem.squashfs/,upperdir=/run/live/overlay/rw,workdir=/run/live/overlay/work"}
]
}
$ df -hT
Filesystem Type Size Used Avail Use% Mounted on
udev devtmpfs 1.9G 0 1.9G 0% /dev
tmpfs tmpfs 394M 452K 393M 1% /run
/dev/sr0 iso9660 1011M 1011M 0 100% /run/live/medium
/dev/loop0 squashfs 688M 688M 0 100% /run/live/rootfs/filesystem.squashfs
tmpfs tmpfs 2.0G 1.3G 724M 64% /run/live/overlay
overlay overlay 2.0G 1.3G 724M 64% /
tmpfs tmpfs 2.0G 0 2.0G 0% /dev/shm
tmpfs tmpfs 5.0M 0 5.0M 0% /run/lock
tmpfs tmpfs 2.0G 110M 1.9G 6% /tmp
tmpfs tmpfs 394M 4.0K 394M 1% /run/user/1000
How do I format this as monospace?
$ uname -a
Linux debian 5.10.0-13-amd64 #1 SMP Debian 5.10.106-1 (2022-03-17) x86_64 GNU/Linux
$ sudo strace -f -o /tmp/strace.log -s 255 bin/mariadbd --no-defaults --bootstrap --datadir=/usr/local/mysql/empty
2022-06-06 2:05:56 0 [Note] bin/mariadbd (server 10.6.8-MariaDB) starting as process 32544 ...
strace: decode_nlattr: [xlat 0x55ffeb8dc2c0, dflt "AF_???", decoders 0x7ffcde542120] size is zero (going to pass nla_type as decoder argument), but opaque data (0x7ffcde5421e0) is not - will be ignored
strace: decode_nlattr: [xlat 0x55ffeb8dc2c0, dflt "AF_???", decoders 0x7ffcde542120] size is zero (going to pass nla_type as decoder argument), but opaque data (0x7ffcde5421e0) is not - will be ignored
strace: decode_nlattr: [xlat 0x55ffeb8dc2c0, dflt "AF_???", decoders 0x7ffcde542120] size is zero (going to pass nla_type as decoder argument), but opaque data (0x7ffcde5421e0) is not - will be ignored
strace: decode_nlattr: [xlat 0x55ffeb8dc2c0, dflt "AF_???", decoders 0x7ffcde542120] size is zero (going to pass nla_type as decoder argument), but opaque data (0x7ffcde5421e0) is not - will be ignored
2022-06-06 2:05:56 0 [Note] InnoDB: The first data file './ibdata1' did not exist. A new tablespace will be created!
2022-06-06 2:05:56 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2022-06-06 2:05:56 0 [Note] InnoDB: Number of pools: 1
2022-06-06 2:05:56 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2022-06-06 2:05:56 0 [Note] InnoDB: Using Linux native AIO
2022-06-06 2:05:56 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728
2022-06-06 2:05:56 0 [Note] InnoDB: Completed initialization of buffer pool
2022-06-06 2:05:56 0 [Note] InnoDB: Setting file './ibdata1' size to 12 MB. Physically writing the file full; Please wait ...
2022-06-06 2:05:56 0 [Warning] InnoDB: Retry attempts for writing partial data failed.
2022-06-06 2:05:56 0 [ERROR] InnoDB: Write to file ./ibdata1 failed at offset 0, 1048576 bytes should have been written, only 0 were written. Operating system error number 22. Check that your OS and file system support files of this size. Check also that the disk is not full or a disk quota exceeded.
2022-06-06 2:05:56 0 [ERROR] InnoDB: Error number 22 means 'Invalid argument'
2022-06-06 2:05:56 0 [Note] InnoDB: Some operating system error numbers are described at https://mariadb.com/kb/en/library/operating-system-error-codes/
2022-06-06 2:05:56 0 [ERROR] InnoDB: Could not set the file size of './ibdata1'. Probably out of disk space
2022-06-06 2:05:56 0 [ERROR] InnoDB: Database creation was aborted with error Generic error. You may need to delete the ibdata1 file before trying to start up again.
2022-06-06 2:05:56 0 [Note] InnoDB: Starting shutdown...
2022-06-06 2:05:56 0 [ERROR] Plugin 'InnoDB' init function returned error.
2022-06-06 2:05:56 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2022-06-06 2:05:56 0 [Note] Plugin 'FEEDBACK' is disabled.
2022-06-06 2:05:56 0 [ERROR] Unknown/unsupported storage engine: InnoDB
2022-06-06 2:05:56 0 [ERROR] Aborting
strace.log.gz is attached.
By the way, changing datadir to /tmp/data (tmpfs) worked!
Thank you!
Dan
So it look like overlayfs is calmly accepting O_DIRECT however even writing 1M of 0's is EINVAL. man 2 write indicates EINVAL can be unaligned buffer, however its aligned to the page size (16k) in its allocation.
Daniel Black
added a comment - {noformat} for monospace blocks.
strace extract
32544 openat(AT_FDCWD, "./ibdata1", O_RDWR|O_CREAT|O_EXCL|O_CLOEXEC, 0660 <unfinished ...>
32548 mmap(NULL, 134217728, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0 <unfinished ...>
32544 <... openat resumed>) = 9
32544 fcntl(9, F_SETFL, O_RDONLY|O_DIRECT) = 0
32548 <... mmap resumed>) = 0x7f7cda5ff000
32544 write(2, "2022-06-06 2:05:56 0 [Note] InnoDB: Setting file './ibdata1' size to 12 MB. Physically writing the file full; Please wait ...\n", 127 <unfinished ...>
32548 munmap(0x7f7cda5ff000, 27267072) = 0
32548 munmap(0x7f7ce0000000, 39841792) = 0
32548 mprotect(0x7f7cdc000000, 135168, PROT_READ|PROT_WRITE) = 0
32544 <... write resumed>) = 127
32544 fstat(9, {st_mode=S_IFREG|0660, st_size=0, ...}) = 0
32548 futex(0x56292c1b2058, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1654499157, tv_nsec=452135000}, FUTEX_BITSET_MATCH_ANY <unfinished ...>
32544 fallocate(9, 0, 0, 12582912) = -1 EINVAL (Invalid argument)
32544 fstat(9, {st_mode=S_IFREG|0660, st_size=0, ...}) = 0
32544 brk(0x56292ec53000) = 0x56292ec53000
32544 pwrite64(9, "\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\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\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\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\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\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\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\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\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576, 0) = -1 EINVAL (Invalid argument)
So it look like overlayfs is calmly accepting O_DIRECT however even writing 1M of 0's is EINVAL . man 2 write indicates EINVAL can be unaligned buffer, however its aligned to the page size (16k) in its allocation.
I've you're able to compile/test/strace the simple MDEV-28100.c (in MDEV-28100) that would be useful. I'll look at doing the same on some very recent kernels.
Daniel Black
added a comment - I think like MDEV-28100 , I'll be just pushing this to the kernel (overlayfs) developers .
I've you're able to compile/test/strace the simple MDEV-28100 .c (in MDEV-28100 ) that would be useful. I'll look at doing the same on some very recent kernels.
Following INSTALL-BINARY instructions,
scripts/mysql_install_db --user=mysql
failed:
$ sudo scripts/mysql_install_db --user=mysql
Installing MariaDB/MySQL system tables in './data' ...
2022-06-06 4:17:03 0 [Warning] InnoDB: Retry attempts for writing partial data failed.
2022-06-06 4:17:03 0 [ERROR] InnoDB: Write to file ./ibdata1 failed at offset 0, 1048576 bytes should have been written, only 0 were written. Operating system error number 22. Check that your OS and file system support files of this size. Check also that the disk is not full or a disk quota exceeded.
2022-06-06 4:17:03 0 [ERROR] InnoDB: Error number 22 means 'Invalid argument'
2022-06-06 4:17:03 0 [ERROR] InnoDB: Could not set the file size of './ibdata1'. Probably out of disk space
2022-06-06 4:17:03 0 [ERROR] InnoDB: Database creation was aborted with error Generic error. You may need to delete the ibdata1 file before trying to start up again.
2022-06-06 4:17:04 0 [ERROR] Plugin 'InnoDB' init function returned error.
2022-06-06 4:17:04 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2022-06-06 4:17:04 0 [ERROR] Unknown/unsupported storage engine: InnoDB
2022-06-06 4:17:04 0 [ERROR] Aborting
Installation of system tables failed!
...
Following INSTALL-BINARY instructions,
scripts/mysql_install_db --user=mysql
failed:
{noformat}
$ sudo scripts/mysql_install_db --user=mysql
Installing MariaDB/MySQL system tables in './data' ...
2022-06-06 4:17:03 0 [Warning] InnoDB: Retry attempts for writing partial data failed.
2022-06-06 4:17:03 0 [ERROR] InnoDB: Write to file ./ibdata1 failed at offset 0, 1048576 bytes should have been written, only 0 were written. Operating system error number 22. Check that your OS and file system support files of this size. Check also that the disk is not full or a disk quota exceeded.
2022-06-06 4:17:03 0 [ERROR] InnoDB: Error number 22 means 'Invalid argument'
2022-06-06 4:17:03 0 [ERROR] InnoDB: Could not set the file size of './ibdata1'. Probably out of disk space
2022-06-06 4:17:03 0 [ERROR] InnoDB: Database creation was aborted with error Generic error. You may need to delete the ibdata1 file before trying to start up again.
2022-06-06 4:17:04 0 [ERROR] Plugin 'InnoDB' init function returned error.
2022-06-06 4:17:04 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2022-06-06 4:17:04 0 [ERROR] Unknown/unsupported storage engine: InnoDB
2022-06-06 4:17:04 0 [ERROR] Aborting
The command systemctl start mariadb fails, and below are the logs from the journal:
Aug 01 11:59:18 kali systemd[1]: Starting MariaDB 10.6.8 database server...
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [Note] /usr/sbin/mariadbd (server 10.6.8-MariaDB-1) starting as process 3957 ...
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [Note] InnoDB: Number of pools: 1
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [Note] InnoDB: Using liburing
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [Note] InnoDB: Completed initialization of buffer pool
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [ERROR] InnoDB: Plugin initialization aborted with error I/O error
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [Note] InnoDB: Starting shutdown...
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [ERROR] InnoDB: Operating system error number 22 in a file operation.
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [ERROR] InnoDB: Error number 22 means 'Invalid argument'
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [Note] InnoDB: Some operating system error numbers are described at https://mariadb.com/kb/en/library/operating-system-error-codes/
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [ERROR] InnoDB: File (unknown): 'close' returned OS error 222. Cannot continue operation
Aug 01 11:59:18 kali mariadbd[3957]: 220801 11:59:18 [ERROR] mysqld got signal 6 ;
Aug 01 11:59:18 kali mariadbd[3957]: This could be because you hit a bug. It is also possible that this binary
Aug 01 11:59:18 kali mariadbd[3957]: or one of the libraries it was linked against is corrupt, improperly built,
Aug 01 11:59:18 kali mariadbd[3957]: or misconfigured. This error can also be caused by malfunctioning hardware.
Aug 01 11:59:18 kali mariadbd[3957]: To report this bug, see https://mariadb.com/kb/en/reporting-bugs
Aug 01 11:59:18 kali mariadbd[3957]: We will try our best to scrape up some info that will hopefully help
Aug 01 11:59:18 kali mariadbd[3957]: diagnose the problem, but since we have already crashed,
Aug 01 11:59:18 kali mariadbd[3957]: something is definitely wrong and this may fail.
Aug 01 11:59:18 kali mariadbd[3957]: Server version: 10.6.8-MariaDB-1
Aug 01 11:59:18 kali mariadbd[3957]: key_buffer_size=134217728
Aug 01 11:59:18 kali mariadbd[3957]: read_buffer_size=131072
Aug 01 11:59:18 kali mariadbd[3957]: max_used_connections=0
Aug 01 11:59:18 kali mariadbd[3957]: max_threads=153
Aug 01 11:59:18 kali mariadbd[3957]: thread_count=0
Aug 01 11:59:18 kali mariadbd[3957]: It is possible that mysqld could use up to
Aug 01 11:59:18 kali mariadbd[3957]: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 467959 K bytes of memory
Aug 01 11:59:18 kali mariadbd[3957]: Hope that's ok; if not, decrease some variables in the equation.
Aug 01 11:59:18 kali mariadbd[3957]: Thread pointer: 0x0
Aug 01 11:59:18 kali mariadbd[3957]: Attempting backtrace. You can use the following information to find out
Aug 01 11:59:18 kali mariadbd[3957]: where mysqld died. If you see no messages after this, something went
Aug 01 11:59:18 kali mariadbd[3957]: terribly wrong...
Aug 01 11:59:18 kali mariadbd[3957]: stack_bottom = 0x0 thread_stack 0x49000
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(my_print_stacktrace)[0x564ff3aab3ce]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(handle_fatal_signal)[0x564ff35f6f78]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(__restore_rt)[0x7f9bf4f50200]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(gsignal)[0x7f9bf4a388c1]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(abort)[0x7f9bf4a22546]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(Wsrep_server_service::log_dummy_write_set(wsrep::client_state&, wsrep::ws_meta const&))[0x564ff3293b0d]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(std::unique_lock<std::mutex>::unlock())[0x564ff39116a5]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(void std::this_thread::sleep_for<long, std::ratio<1l, 1l> >(std::chrono::duration<long, std::ratio<1l, 1l> > const&))[0x564ff398010f]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(wsrep_notify_status(wsrep::server_state::state, wsrep::view const*))[0x564ff38c18d5]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(ha_initialize_handlerton(st_plugin_int*))[0x564ff35fa0ee]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(sys_var_pluginvar::sys_var_pluginvar(sys_var_chain*, char const*, st_plugin_int*, st_mysql_sys_var*, char const*))[0x564ff33f0ac6]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(plugin_init(int*, char**, int))[0x564ff33f1a88]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(unireg_abort)[0x564ff331baca]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(mysqld_main(int, char**))[0x564ff3321664]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(__libc_start_main)[0x7f9bf4a2381d]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(_start)[0x564ff3316bfa]
Aug 01 11:59:18 kali mariadbd[3957]: The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains
Aug 01 11:59:18 kali mariadbd[3957]: information that should help you find out what is causing the crash.
Aug 01 11:59:18 kali mariadbd[3957]: Writing a core file...
Aug 01 11:59:18 kali mariadbd[3957]: Working directory at /var/lib/mysql
Aug 01 11:59:18 kali mariadbd[3957]: Resource Limits:
Aug 01 11:59:18 kali mariadbd[3957]: Limit Soft Limit Hard Limit Units
Aug 01 11:59:18 kali mariadbd[3957]: Max cpu time unlimited unlimited seconds
Aug 01 11:59:18 kali mariadbd[3957]: Max file size unlimited unlimited bytes
Aug 01 11:59:18 kali mariadbd[3957]: Max data size unlimited unlimited bytes
Aug 01 11:59:18 kali mariadbd[3957]: Max stack size 8388608 unlimited bytes
Aug 01 11:59:18 kali mariadbd[3957]: Max core file size 0 unlimited bytes
Aug 01 11:59:18 kali mariadbd[3957]: Max resident set unlimited unlimited bytes
Aug 01 11:59:18 kali mariadbd[3957]: Max processes 15385 15385 processes
Aug 01 11:59:18 kali mariadbd[3957]: Max open files 32768 32768 files
Aug 01 11:59:18 kali mariadbd[3957]: Max locked memory 524288 524288 bytes
Aug 01 11:59:18 kali mariadbd[3957]: Max address space unlimited unlimited bytes
Aug 01 11:59:18 kali mariadbd[3957]: Max file locks unlimited unlimited locks
Aug 01 11:59:18 kali mariadbd[3957]: Max pending signals 15385 15385 signals
Aug 01 11:59:18 kali mariadbd[3957]: Max msgqueue size 819200 819200 bytes
Aug 01 11:59:18 kali mariadbd[3957]: Max nice priority 0 0
Aug 01 11:59:18 kali mariadbd[3957]: Max realtime priority 0 0
Aug 01 11:59:18 kali mariadbd[3957]: Max realtime timeout unlimited unlimited us
Aug 01 11:59:18 kali mariadbd[3957]: Core pattern: core
Aug 01 11:59:18 kali systemd[1]: mariadb.service: Main process exited, code=killed, status=6/ABRT
Aug 01 11:59:18 kali systemd[1]: mariadb.service: Failed with result 'signal'.
Aug 01 11:59:18 kali systemd[1]: Failed to start MariaDB 10.6.8 database server.
Aug 01 11:59:18 kali polkitd(authority=local)[1182]: Unregistered Authentication Agent for unix-process:3919:47143 (system bus name :1.56, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) (disconnected from bus)
Aug 01 11:59:23 kali systemd[1]: mariadb.service: Scheduled restart job, restart counter is at 1.
Aug 01 11:59:23 kali systemd[1]: Stopped MariaDB 10.6.8 database server.
The issue can be worked around by adding this config snippet:
└─$ cat /etc/mysql/mariadb.conf.d/90-live.cnf
[mysqld]
innodb_flush_method = fsync
In case it's of any interest, the kernel version:
└─$ uname -a
Linux kali 5.18.0-kali5-amd64 #1 SMP PREEMPT_DYNAMIC Debian 5.18.5-1kali6 (2022-07-07) x86_64 GNU/Linux
Arnaud R
added a comment - - edited Hello! Just for confirmation, we are seeing the same issue with the Kali Linux live image. Reported at https://bugs.kali.org/view.php?id=7823 .
The command systemctl start mariadb fails, and below are the logs from the journal:
Aug 01 11:59:18 kali systemd[1]: Starting MariaDB 10.6.8 database server...
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [Note] /usr/sbin/mariadbd (server 10.6.8-MariaDB-1) starting as process 3957 ...
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [Note] InnoDB: Number of pools: 1
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [Note] InnoDB: Using liburing
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [Note] InnoDB: Completed initialization of buffer pool
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [ERROR] InnoDB: Plugin initialization aborted with error I/O error
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [Note] InnoDB: Starting shutdown...
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [ERROR] InnoDB: Operating system error number 22 in a file operation.
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [ERROR] InnoDB: Error number 22 means 'Invalid argument'
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [Note] InnoDB: Some operating system error numbers are described at https://mariadb.com/kb/en/library/operating-system-error-codes/
Aug 01 11:59:18 kali mariadbd[3957]: 2022-08-01 11:59:18 0 [ERROR] InnoDB: File (unknown): 'close' returned OS error 222. Cannot continue operation
Aug 01 11:59:18 kali mariadbd[3957]: 220801 11:59:18 [ERROR] mysqld got signal 6 ;
Aug 01 11:59:18 kali mariadbd[3957]: This could be because you hit a bug. It is also possible that this binary
Aug 01 11:59:18 kali mariadbd[3957]: or one of the libraries it was linked against is corrupt, improperly built,
Aug 01 11:59:18 kali mariadbd[3957]: or misconfigured. This error can also be caused by malfunctioning hardware.
Aug 01 11:59:18 kali mariadbd[3957]: To report this bug, see https://mariadb.com/kb/en/reporting-bugs
Aug 01 11:59:18 kali mariadbd[3957]: We will try our best to scrape up some info that will hopefully help
Aug 01 11:59:18 kali mariadbd[3957]: diagnose the problem, but since we have already crashed,
Aug 01 11:59:18 kali mariadbd[3957]: something is definitely wrong and this may fail.
Aug 01 11:59:18 kali mariadbd[3957]: Server version: 10.6.8-MariaDB-1
Aug 01 11:59:18 kali mariadbd[3957]: key_buffer_size=134217728
Aug 01 11:59:18 kali mariadbd[3957]: read_buffer_size=131072
Aug 01 11:59:18 kali mariadbd[3957]: max_used_connections=0
Aug 01 11:59:18 kali mariadbd[3957]: max_threads=153
Aug 01 11:59:18 kali mariadbd[3957]: thread_count=0
Aug 01 11:59:18 kali mariadbd[3957]: It is possible that mysqld could use up to
Aug 01 11:59:18 kali mariadbd[3957]: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 467959 K bytes of memory
Aug 01 11:59:18 kali mariadbd[3957]: Hope that's ok; if not, decrease some variables in the equation.
Aug 01 11:59:18 kali mariadbd[3957]: Thread pointer: 0x0
Aug 01 11:59:18 kali mariadbd[3957]: Attempting backtrace. You can use the following information to find out
Aug 01 11:59:18 kali mariadbd[3957]: where mysqld died. If you see no messages after this, something went
Aug 01 11:59:18 kali mariadbd[3957]: terribly wrong...
Aug 01 11:59:18 kali mariadbd[3957]: stack_bottom = 0x0 thread_stack 0x49000
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(my_print_stacktrace)[0x564ff3aab3ce]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(handle_fatal_signal)[0x564ff35f6f78]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(__restore_rt)[0x7f9bf4f50200]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(gsignal)[0x7f9bf4a388c1]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(abort)[0x7f9bf4a22546]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(Wsrep_server_service::log_dummy_write_set(wsrep::client_state&, wsrep::ws_meta const&))[0x564ff3293b0d]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(std::unique_lock<std::mutex>::unlock())[0x564ff39116a5]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(void std::vector<unsigned long, std::allocator<unsigned long> >::_M_realloc_insert<unsigned long>(__gnu_cxx::__normal_iterator<unsigned long*, std::vector<unsigned long, std::allocator<unsigned long> > >, unsigned long&&))[0x564ff3a17ab8]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(void std::vector<unsigned long, std::allocator<unsigned long> >::_M_realloc_insert<unsigned long>(__gnu_cxx::__normal_iterator<unsigned long*, std::vector<unsigned long, std::allocator<unsigned long> > >, unsigned long&&))[0x564ff3a17b21]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(void std::vector<unsigned long, std::allocator<unsigned long> >::_M_realloc_insert<unsigned long>(__gnu_cxx::__normal_iterator<unsigned long*, std::vector<unsigned long, std::allocator<unsigned long> > >, unsigned long&&))[0x564ff3a1a1d0]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(void std::vector<unsigned long, std::allocator<unsigned long> >::_M_realloc_insert<unsigned long>(__gnu_cxx::__normal_iterator<unsigned long*, std::vector<unsigned long, std::allocator<unsigned long> > >, unsigned long&&))[0x564ff3a1b2f1]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(void std::this_thread::sleep_for<long, std::ratio<1l, 1l> >(std::chrono::duration<long, std::ratio<1l, 1l> > const&))[0x564ff398010f]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(wsrep_notify_status(wsrep::server_state::state, wsrep::view const*))[0x564ff38c18d5]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(ha_initialize_handlerton(st_plugin_int*))[0x564ff35fa0ee]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(sys_var_pluginvar::sys_var_pluginvar(sys_var_chain*, char const*, st_plugin_int*, st_mysql_sys_var*, char const*))[0x564ff33f0ac6]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(plugin_init(int*, char**, int))[0x564ff33f1a88]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(unireg_abort)[0x564ff331baca]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(mysqld_main(int, char**))[0x564ff3321664]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(__libc_start_main)[0x7f9bf4a2381d]
Aug 01 11:59:18 kali mariadbd[3957]: ??:0(_start)[0x564ff3316bfa]
Aug 01 11:59:18 kali mariadbd[3957]: The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains
Aug 01 11:59:18 kali mariadbd[3957]: information that should help you find out what is causing the crash.
Aug 01 11:59:18 kali mariadbd[3957]: Writing a core file...
Aug 01 11:59:18 kali mariadbd[3957]: Working directory at /var/lib/mysql
Aug 01 11:59:18 kali mariadbd[3957]: Resource Limits:
Aug 01 11:59:18 kali mariadbd[3957]: Limit Soft Limit Hard Limit Units
Aug 01 11:59:18 kali mariadbd[3957]: Max cpu time unlimited unlimited seconds
Aug 01 11:59:18 kali mariadbd[3957]: Max file size unlimited unlimited bytes
Aug 01 11:59:18 kali mariadbd[3957]: Max data size unlimited unlimited bytes
Aug 01 11:59:18 kali mariadbd[3957]: Max stack size 8388608 unlimited bytes
Aug 01 11:59:18 kali mariadbd[3957]: Max core file size 0 unlimited bytes
Aug 01 11:59:18 kali mariadbd[3957]: Max resident set unlimited unlimited bytes
Aug 01 11:59:18 kali mariadbd[3957]: Max processes 15385 15385 processes
Aug 01 11:59:18 kali mariadbd[3957]: Max open files 32768 32768 files
Aug 01 11:59:18 kali mariadbd[3957]: Max locked memory 524288 524288 bytes
Aug 01 11:59:18 kali mariadbd[3957]: Max address space unlimited unlimited bytes
Aug 01 11:59:18 kali mariadbd[3957]: Max file locks unlimited unlimited locks
Aug 01 11:59:18 kali mariadbd[3957]: Max pending signals 15385 15385 signals
Aug 01 11:59:18 kali mariadbd[3957]: Max msgqueue size 819200 819200 bytes
Aug 01 11:59:18 kali mariadbd[3957]: Max nice priority 0 0
Aug 01 11:59:18 kali mariadbd[3957]: Max realtime priority 0 0
Aug 01 11:59:18 kali mariadbd[3957]: Max realtime timeout unlimited unlimited us
Aug 01 11:59:18 kali mariadbd[3957]: Core pattern: core
Aug 01 11:59:18 kali systemd[1]: mariadb.service: Main process exited, code=killed, status=6/ABRT
Aug 01 11:59:18 kali systemd[1]: mariadb.service: Failed with result 'signal'.
Aug 01 11:59:18 kali systemd[1]: Failed to start MariaDB 10.6.8 database server.
Aug 01 11:59:18 kali polkitd(authority=local)[1182]: Unregistered Authentication Agent for unix-process:3919:47143 (system bus name :1.56, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) (disconnected from bus)
Aug 01 11:59:23 kali systemd[1]: mariadb.service: Scheduled restart job, restart counter is at 1.
Aug 01 11:59:23 kali systemd[1]: Stopped MariaDB 10.6.8 database server.
The issue can be worked around by adding this config snippet:
└─$ cat /etc/mysql/mariadb.conf.d/90-live.cnf
[mysqld]
innodb_flush_method = fsync
In case it's of any interest, the kernel version:
└─$ uname -a
Linux kali 5.18.0-kali5-amd64 #1 SMP PREEMPT_DYNAMIC Debian 5.18.5-1kali6 (2022-07-07) x86_64 GNU/Linux
I would personally also be keen to figure out how to make the MariaDB datadir be able to run off overlayfs or something similar so I can implement my long time idea to have shadow upgrades where the old mariadbd and old data is kept running and intact, and every new version mariadbd would first run off overlayfs with real data to simulate the upgrade before it is done for real.
Otto Kekäläinen
added a comment - I would personally also be keen to figure out how to make the MariaDB datadir be able to run off overlayfs or something similar so I can implement my long time idea to have shadow upgrades where the old mariadbd and old data is kept running and intact, and every new version mariadbd would first run off overlayfs with real data to simulate the upgrade before it is done for real.
Sorry, Jira refuses to let me set the Priority to Normal.
I used strace and found the following difference:
10.5.16:
openat(AT_FDCWD, "./ibdata1", O_RDWR|O_CREAT|O_EXCL|O_CLOEXEC, 0660) = 9
fstat(9, \{st_mode=S_IFREG|0660, st_size=0, ...\}) = 0
fallocate(9, 0, 0, 12582912) = 0
close(9) = 0
10.6.8:
openat(AT_FDCWD, "./ibdata1", O_RDWR|O_CREAT|O_EXCL|O_CLOEXEC, 0660) = 9
*fcntl(9, F_SETFL, O_RDONLY|O_DIRECT) = 0*
fstat(9, \{st_mode=S_IFREG|0660, st_size=0, ...\}) = 0
fallocate(9, 0, 0, 12582912) = *-1 EINVAL (Invalid argument)*
MariaDB 10.6.0 Release Notes say:
innodb_flush_method=O_DIRECT is enabled by default (MDEV-24854)
Perhaps the overlay filesystem does not support O_DIRECT ?
Thank you!
Daniel Lewart
Urbana, Illinois