[MDEV-29551] InnoDB: Plugin initialization aborted with error I/O error - EINVAL, O_DIRECT, overlayfs Created: 2022-09-15  Updated: 2022-09-23  Resolved: 2022-09-19

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.9.2
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Rick Ferreira Assignee: Daniel Black
Resolution: Not a Bug Votes: 0
Labels: None
Environment:

Singularity container.
Ubuntu 22.04 Jammy

Attachments: File mariadbd.strace    
Issue Links:
Relates
relates to MDEV-29617 MariaDB server crashes on startup aft... Closed

 Description   

I get the following error when I try to run the following in a singularity Ubuntu 22.04 containers:

sudo mysqld --verbose --user=root --innodb_use_native_aio=0 --innodb_force_recovery=1

ERRORS:

2022-09-15 18:54:43 0 [Note] mysqld (server 10.9.2-MariaDB-1:10.9.2+maria~ubu2204) starting as process 162465 ...
2022-09-15 18:54:43 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2022-09-15 18:54:43 0 [Note] InnoDB: Number of transaction pools: 1
2022-09-15 18:54:43 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2022-09-15 18:54:43 0 [Note] InnoDB: Initializing buffer pool, total size = 128.000MiB, chunk size = 2.000MiB
2022-09-15 18:54:43 0 [Note] InnoDB: Completed initialization of buffer pool
2022-09-15 18:54:43 0 [ERROR] InnoDB: Plugin initialization aborted with error I/O error
2022-09-15 18:54:43 0 [Note] InnoDB: Starting shutdown...
2022-09-15 18:54:43 0 [ERROR] InnoDB: Operating system error number 22 in a file operation.
2022-09-15 18:54:43 0 [ERROR] InnoDB: Error number 22 means 'Invalid argument'
2022-09-15 18:54:43 0 [Note] InnoDB: Some operating system error numbers are described at https://mariadb.com/kb/en/library/operating-system-error-codes/
2022-09-15 18:54:43 0 [ERROR] InnoDB: File (unknown): 'close' returned OS error 222. Cannot continue operation
220915 18:54:43 [ERROR] mysqld got signal 6 ;
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 https://mariadb.com/kb/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: 10.9.2-MariaDB-1:10.9.2+maria~ubu2204
key_buffer_size=134217728
read_buffer_size=131072
max_used_connections=0
max_threads=153
thread_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 468006 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0
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 = 0x0 thread_stack 0x49000
2022-09-15 18:54:43 0 [ERROR] InnoDB: Operating system error number 9 in a file operation.
2022-09-15 18:54:43 0 [ERROR] InnoDB: Error number 9 means 'Bad file descriptor'
2022-09-15 18:54:43 0 [Note] InnoDB: Some operating system error numbers are described at https://mariadb.com/kb/en/library/operating-system-error-codes/
2022-09-15 18:54:43 0 [ERROR] InnoDB: File (unknown): 'close' returned OS error 209. Cannot continue operation
Printing to addr2line failed
mysqld(my_print_stacktrace+0x32)[0x55c61b027f12]
mysqld(handle_fatal_signal+0x478)[0x55c61aafbfa8]
2022-09-15 18:54:43 0 [ERROR] InnoDB: Operating system error number 9 in a file operation.
2022-09-15 18:54:43 0 [ERROR] InnoDB: Error number 9 means 'Bad file descriptor'
2022-09-15 18:54:43 0 [Note] InnoDB: Some operating system error numbers are described at https://mariadb.com/kb/en/library/operating-system-error-codes/
2022-09-15 18:54:43 0 [ERROR] InnoDB: File (unknown): 'close' returned OS error 209. Cannot continue operation
/lib/x86_64-linux-gnu/libc.so.6(+0x42520)[0x7f4e68c11520]
/lib/x86_64-linux-gnu/libc.so.6(pthread_kill+0x12c)[0x7f4e68c65a7c]
/lib/x86_64-linux-gnu/libc.so.6(raise+0x16)[0x7f4e68c11476]
/lib/x86_64-linux-gnu/libc.so.6(abort+0xd3)[0x7f4e68bf77f3]
2022-09-15 18:54:43 0 [ERROR] InnoDB: Operating system error number 9 in a file operation.
2022-09-15 18:54:43 0 [ERROR] InnoDB: Error number 9 means 'Bad file descriptor'
2022-09-15 18:54:43 0 [Note] InnoDB: Some operating system error numbers are described at https://mariadb.com/kb/en/library/operating-system-error-codes/
2022-09-15 18:54:43 0 [ERROR] InnoDB: File (unknown): 'close' returned OS error 209. Cannot continue operation
mysqld(+0x65e4a9)[0x55c61a7124a9]
mysqld(+0xd91315)[0x55c61ae45315]
mysqld(+0xec8038)[0x55c61af7c038]
mysqld(+0xecabb0)[0x55c61af7ebb0]
mysqld(+0xecbe05)[0x55c61af7fe05]
mysqld(+0xe0d73f)[0x55c61aec173f]
mysqld(+0xd32335)[0x55c61ade6335]
mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0x82)[0x55c61aafedd2]
mysqld(+0x812b36)[0x55c61a8c6b36]
mysqld(_Z11plugin_initPiPPci+0x91d)[0x55c61a8c7d0d]
mysqld(+0x6ea389)[0x55c61a79e389]
mysqld(_Z11mysqld_mainiPPc+0x424)[0x55c61a7a3b14]
2022-09-15 18:54:43 0 [ERROR] InnoDB: Operating system error number 9 in a file operation.
2022-09-15 18:54:43 0 [ERROR] InnoDB: Error number 9 means 'Bad file descriptor'
2022-09-15 18:54:43 0 [Note] InnoDB: Some operating system error numbers are described at https://mariadb.com/kb/en/library/operating-system-error-codes/
2022-09-15 18:54:43 0 [ERROR] InnoDB: File (unknown): 'close' returned OS error 209. Cannot continue operation
/lib/x86_64-linux-gnu/libc.so.6(+0x29d90)[0x7f4e68bf8d90]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x80)[0x7f4e68bf8e40]
2022-09-15 18:54:43 0 [ERROR] InnoDB: Operating system error number 9 in a file operation.
2022-09-15 18:54:43 0 [ERROR] InnoDB: Error number 9 means 'Bad file descriptor'
2022-09-15 18:54:43 0 [Note] InnoDB: Some operating system error numbers are described at https://mariadb.com/kb/en/library/operating-system-error-codes/
2022-09-15 18:54:43 0 [ERROR] InnoDB: File (unknown): 'close' returned OS error 209. Cannot continue operation
mysqld(_start+0x25)[0x55c61a7985d5]
The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains
information that should help you find out what is causing the crash.
Writing a core file...
Working directory at /var/lib/mysql
Resource Limits:
Limit Soft Limit Hard Limit Units
Max cpu time unlimited unlimited seconds
Max file size unlimited unlimited bytes
Max data size unlimited unlimited bytes
Max stack size 8388608 unlimited bytes
Max core file size 0 0 bytes
Max resident set unlimited unlimited bytes
Max processes 30721 30721 processes
Max open files 32190 32190 files
Max locked memory 1021026304 1021026304 bytes
Max address space unlimited unlimited bytes
Max file locks unlimited unlimited locks
Max pending signals 30721 30721 signals
Max msgqueue size 819200 819200 bytes
Max nice priority 0 0
Max realtime priority 0 0
Max realtime timeout unlimited unlimited us
Core pattern: |/usr/share/apport/apport -p%p -s%s -c%c -d%d -P%P -u%u -g%g – %E

Kernel version: Linux version 5.15.0-47-generic (buildd@lcy02-amd64-060) (gcc (Ubuntu 11.2.0-19ubuntu1) 11.2.0, GNU ld (GNU Binutils for Ubuntu) 2.38) #51-Ubuntu SMP Thu Aug 11 07:51:15 UTC 2022

 Comments   
Comment by Daniel Black [ 2022-09-15 ]

Are you able to sudo strace -f -o /tmp/mariadbd.strace -- mariadbd --verbose --user=root --innodb_use_native_aio=0 --innodb_force_recovery=1 }} inside the container and attach the file {{/tmp/mariadbd.strace here. This will most likely need the capability CAP_SYS_PTRACE in starting the container.

Also what are the characteristics of the /var/lib/mysql datadir?

I'm assuming you are on a jammy host too based on the kernel version.

Comment by Rick Ferreira [ 2022-09-16 ]

.

Okay here is the file :

mariadbd.strace

I also tried the following commands::

mkdir /run/mysqld
sudo mysqld --verbose --user=root --innodb_flush_method=fsync

However it ends up hanging after showing the following lines

sudo mysqld --verbose --user=root --innodb_flush_method=fsync
2022-09-15 23:03:57 0 [Note] mysqld (server 10.9.2-MariaDB-1:10.9.2+maria~ubu2204) starting as process 71106 ...
2022-09-15 23:03:57 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2022-09-15 23:03:57 0 [Note] InnoDB: Number of transaction pools: 1
2022-09-15 23:03:57 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2022-09-15 23:03:57 0 [Note] InnoDB: Initializing buffer pool, total size = 128.000MiB, chunk size = 2.000MiB
2022-09-15 23:03:57 0 [Note] InnoDB: Completed initialization of buffer pool
2022-09-15 23:03:57 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
2022-09-15 23:03:57 0 [Note] InnoDB: 128 rollback segments are active.
2022-09-15 23:03:57 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
2022-09-15 23:03:57 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
2022-09-15 23:03:57 0 [Note] InnoDB: log sequence number 46483; transaction id 14
2022-09-15 23:03:57 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2022-09-15 23:03:57 0 [Note] Plugin 'FEEDBACK' is disabled.
2022-09-15 23:03:57 0 [Warning] You need to use --log-bin to make --expire-logs-days or --binlog-expire-logs-seconds work.
2022-09-15 23:03:57 0 [Note] InnoDB: Buffer pool(s) load completed at 220915 23:03:57
2022-09-15 23:03:57 0 [Note] Server socket created on IP: '127.0.0.1'.
2022-09-15 23:03:57 0 [Note] mysqld: ready for connections.
Version: '10.9.2-MariaDB-1:10.9.2+maria~ubu2204' socket: '/run/mysqld/mysqld.sock' port: 3306 mariadb.org binary distribution

Comment by Daniel Black [ 2022-09-16 ]

strace extract

 
70071 openat(AT_FDCWD, "./ibdata1", O_RDWR|O_CLOEXEC) = 10
 
70071 fcntl(10, F_SETFL, O_RDONLY|O_DIRECT) = 0
 
70071 fcntl(10, F_SETLK, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=0} <unfinished ...>
 
70074 rseq(0x7f3bacffffe0, 0x20, 0, 0x53053053 <unfinished ...>
 
70071 <... fcntl resumed>)              = 0
 
70071 newfstatat(10, "", {st_mode=S_IFREG|0660, st_size=12582912, ...}, AT_EMPTY_PATH) = 0
 
70071 pread64(10,  <unfinished ...>
 
70074 <... rseq resumed>)               = 0
 
70071 <... pread64 resumed>0x561aa6a70000, 65536, 0) = -1 EINVAL (Invalid argument)
 
70071 write(2, "2022-09-15 22:45:23 0 [ERROR] In"..., 89) = 89

So this is showing the pread returning EINVAL under the O_DIRECT mode, which is why --innodb_flush_method=fsync avoided it by not setting O_DIRECT.

So this looks like MDEV-15779 behaviour wise.

What filesytem and mount options are used for your datadir?

--innodb_flush_method=fsync isn't hanging, that's a complete startup.

Comment by Rick Ferreira [ 2022-09-18 ]

.
I am using the following file system:

sudo singularity shell --net --writable-tmpfs test2.sif

Data directory is in the tmpfs at this location

Singularity> mysqld --help --verbose | grep 'datadir' | tail -1
datadir /var/lib/mysql/

I modified my 50-server.cnf configuration file to have the following line under [server].

innodb_flush_method=fsync

It was working for a while, however now

sudo service mariadb start

fails, however the following command works

sudo mysqld --verbose --user=root &

I still want to figure out how to solve the sudo service mariadb start not working. Is there a way of getting error messages and to print it's default settings?

Comment by Rick Ferreira [ 2022-09-18 ]

Turns out mysqld wasn't hanging when putting &.

It's just that mysqld couldn't be escaped without it and when I did add a & to the end, the singularity prompt didn't update the cursor location so it looked like it hanged.

Comment by Rick Ferreira [ 2022-09-18 ]

Now I can't seem to create a wait or sleep bash script that waits for the mysql queries to run when creating a singularity instance before running sql commands.

mysqld --user=root &

#this works but could fail if it takes long and it wastes time
#sleep 3s

#for some reason this works after running mysqld, but not sure why
sudo service mariadb start

#If I remove the service mariadb start and try this code it doesn't work on the singularity %startscript
while [[ "$(/usr/sbin/service mariadb status)" == " * MariaDB is stopped." ]]; do
sleep 1s
done

mysql -u root --password=root -e 'CREATE DATABASE test;'

Comment by Daniel Black [ 2022-09-19 ]

The default singularity filesytem is overlay FS which fails to support O_DIRECT.

$ sudo singularity shell --net --writable-tmpfs docker://docker.io/library/mariadb
 
INFO:    Converting OCI blobs to SIF format
 
WARNING: 'nodev' mount option set on /tmp, it could be a source of failure during build process
 
INFO:    Starting build...
 
Getting image source signatures
 
...
 
INFO:    Creating SIF file...
 
Apptainer> mount 
overlay on / type overlay (rw,nodev,relatime,seclabel,lowerdir=/var/apptainer/mnt/session/overlay-lowerdir:/var/apptainer/mnt/session/rootfs,upperdir=/var/apptainer/mnt/session/tmpfs/upper,workdir=/var/apptainer/mnt/session/tmpfs/work)
 
...

I think I'll need to take this up with kernel devs on failing fcntl(10, F_SETFL, O_RDONLY|O_DIRECT) early rather than accepting it and failing on pread/write.

In the mean time, to pull a mariadb container and run under singularity requires an explicit volume (for storage, that supports O_DIRECT, or use --innodb_flush_method=fsync) and --scratch option are needed. There's a few more options I put on this github issue. Note this omits the need for --writable-tmpfs.

$ singularity exec --bind ~/mariadb-datadir/:/var/lib/mysql --env MARIADB_ROOT_PASSWORD=bob  --scratch=/run/mysqld docker://docker.io/library/mariadb docker-entrypoint.sh mariadbd
 
2022-09-19 15:27:42+10:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:10.9.2+maria~ubu2204 started.
 
2022-09-19 15:27:42+10:00 [Note] [Entrypoint]: MariaDB upgrade not required
 
2022-09-19 15:27:42 0 [Note] mariadbd (server 10.9.2-MariaDB-1:10.9.2+maria~ubu2204) starting as process 106222 ...
 
2022-09-19 15:27:42 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
2022-09-19 15:27:42 0 [Note] InnoDB: Number of transaction pools: 1
 
2022-09-19 15:27:42 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
 
2022-09-19 15:27:42 0 [Note] InnoDB: Using liburing
 
2022-09-19 15:27:42 0 [Note] InnoDB: Initializing buffer pool, total size = 128.000MiB, chunk size = 2.000MiB
 
2022-09-19 15:27:42 0 [Note] InnoDB: Completed initialization of buffer pool
 
2022-09-19 15:27:42 0 [Note] InnoDB: File system buffers for log disabled (block size=512 bytes)
 
2022-09-19 15:27:42 0 [Note] InnoDB: 128 rollback segments are active.
 
2022-09-19 15:27:42 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
 
2022-09-19 15:27:42 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
 
2022-09-19 15:27:42 0 [Note] InnoDB: log sequence number 46617; transaction id 14
 
2022-09-19 15:27:42 0 [Note] InnoDB: Loading buffer pool(s) from /home/dan/mariadb-datadir/ib_buffer_pool
 
2022-09-19 15:27:42 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2022-09-19 15:27:42 0 [Note] InnoDB: Buffer pool(s) load completed at 220919 15:27:42
 
2022-09-19 15:27:42 0 [Warning] You need to use --log-bin to make --expire-logs-days or --binlog-expire-logs-seconds work.
 
2022-09-19 15:27:42 0 [Note] Server socket created on IP: '0.0.0.0'.
 
2022-09-19 15:27:42 0 [Note] Server socket created on IP: '::'.
 
2022-09-19 15:27:42 0 [Warning] 'user' entry 'root@localhost.localdomain' ignored in --skip-name-resolve mode.
 
2022-09-19 15:27:42 0 [Warning] 'proxies_priv' entry '@% root@localhost.localdomain' ignored in --skip-name-resolve mode.
 
2022-09-19 15:27:42 0 [Note] mariadbd: ready for connections.
 
Version: '10.9.2-MariaDB-1:10.9.2+maria~ubu2204'  socket: '/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution

Comment by Daniel Black [ 2022-09-19 ]

Closing as "Not a bug" but really not our bug.

Generated at Thu Feb 08 10:09:29 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.