Open Simbiat opened 3 months ago
The primary cause appears to be:
2024-08-16 4:54:05 0 [ERROR] InnoDB: Operating system error number 13 in a file operation.
2024-08-16 4:54:05 0 [ERROR] InnoDB: The error means mariadbd does not have the access rights to the directory.
The volume mount of path leave it to the container to resolve the permissions. Despite the container started as root, where it should try to chown the container datadir to user mysql
, no-new-privileges might be preventing the transition to the mysql user.
I can't see a reason for 3 restarts. (or special ib_buffer_pool handling).
Indeed, removing no-new-privileges=true
from compose solves this. But why is there no issues with 11.4.3 then?
Logs without the option for reference:
2024-08-19 07:07:31 2024-08-19 04:07:31+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:11.5.2+maria~ubu2404 started.
2024-08-19 07:07:32 2024-08-19 04:07:32+00:00 [Warn] [Entrypoint]: /sys/fs/cgroup///memory.pressure not writable, functionality unavailable to MariaDB
2024-08-19 07:07:32 2024-08-19 04:07:32+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2024-08-19 07:07:32 2024-08-19 04:07:32+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:11.5.2+maria~ubu2404 started.
2024-08-19 07:07:32 2024-08-19 04:07:32+00:00 [Note] [Entrypoint]: MariaDB upgrade not required
2024-08-19 07:07:32 2024-08-19 4:07:32 0 [Warning] Setting lower_case_table_names=2 because file system for /var/lib/mysql/ is case insensitive
2024-08-19 4:07:32 0 [Note] Starting MariaDB 11.5.2-MariaDB-ubu2404 source revision ea75a0b6009b0251e83193cd38c3974e36b65e06 server_uid +4pM6y9U0t2AhkwKrue72/fmrSY= as process 28
2024-08-19 4:07:32 0 [Note] InnoDB: Compressed tables use zlib 1.3
2024-08-19 4:07:32 0 [Note] InnoDB: Number of transaction pools: 1
2024-08-19 4:07:32 0 [Note] InnoDB: Using AVX512 instructions
2024-08-19 4:07:32 0 [Note] mariadbd: O_TMPFILE is not supported on /tmp (disabling future attempts)
2024-08-19 4:07:32 0 [Note] InnoDB: Using liburing
2024-08-19 4:07:32 0 [Note] InnoDB: Initializing buffer pool, total size = 9.000GiB, chunk size = 144.000MiB
2024-08-19 4:07:33 0 [Note] InnoDB: Completed initialization of buffer pool
2024-08-19 4:07:33 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
2024-08-19 4:07:33 0 [Note] InnoDB: Resetting space id's in the doublewrite buffer
2024-08-19 4:07:34 0 [Note] InnoDB: End of log at LSN=811645509288
2024-08-19 4:07:34 0 [Note] InnoDB: Opened 3 undo tablespaces
2024-08-19 4:07:34 0 [Note] InnoDB: 128 rollback segments in 3 undo tablespaces are active.
2024-08-19 4:07:34 0 [Note] InnoDB: Removed temporary tablespace data file: "./ibtmp1"
2024-08-19 4:07:34 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
2024-08-19 4:07:34 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
2024-08-19 4:07:34 0 [Note] InnoDB: log sequence number 811645509288; transaction id 233174741
2024-08-19 4:07:34 0 [Note] Plugin 'FEEDBACK' is disabled.
2024-08-19 4:07:34 0 [Note] Plugin 'wsrep-provider' is disabled.
2024-08-19 4:07:34 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2024-08-19 4:07:34 0 [Note] Recovering after a crash using tc.log
2024-08-19 4:07:34 0 [Note] InnoDB: Buffer pool(s) load completed at 240819 4:07:34
2024-08-19 4:07:34 0 [Note] Starting table crash recovery...
2024-08-19 4:07:34 0 [Note] Crash table recovery finished.
2024-08-19 4:07:35 0 [Note] Server socket created on IP: '0.0.0.0'.
2024-08-19 4:07:35 0 [Note] Server socket created on IP: '::'.
2024-08-19 4:07:35 0 [Note] mariadbd: Event Scheduler: Loaded 0 events
2024-08-19 4:07:35 0 [Note] mariadbd: ready for connections.
Version: '11.5.2-MariaDB-ubu2404' socket: '/run/mysqld/mysqld.sock' port: 19913 mariadb.org binary distribution
Logs from 11.4.3 with no-new-priviileges:
2024-08-19 07:11:24 2024-08-19 04:11:24+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:11.4.3+maria~ubu2404 started.
2024-08-19 07:11:24 2024-08-19 04:11:24+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
2024-08-19 07:11:24 2024-08-19 04:11:24+00:00 [Note] [Entrypoint]: Entrypoint script for MariaDB Server 1:11.4.3+maria~ubu2404 started.
2024-08-19 07:11:25 2024-08-19 04:11:25+00:00 [Note] [Entrypoint]: MariaDB upgrade not required
2024-08-19 07:11:24 2024-08-19 04:11:24+00:00 [Warn] [Entrypoint]: /sys/fs/cgroup///memory.pressure not writable, functionality unavailable to MariaDB
2024-08-19 07:11:25 2024-08-19 4:11:25 0 [Warning] Setting lower_case_table_names=2 because file system for /var/lib/mysql/ is case insensitive
2024-08-19 4:11:25 0 [Note] Starting MariaDB 11.4.3-MariaDB-ubu2404 source revision 5ab81ffe0097a22a774957df28c5223cf0201de3 server_uid +4pM6y9U0t2AhkwKrue72/fmrSY= as process 28
2024-08-19 4:11:25 0 [Note] InnoDB: Compressed tables use zlib 1.3
2024-08-19 4:11:25 0 [Note] InnoDB: Number of transaction pools: 1
2024-08-19 4:11:25 0 [Note] InnoDB: Using AVX512 instructions
2024-08-19 4:11:25 0 [Note] mariadbd: O_TMPFILE is not supported on /tmp (disabling future attempts)
2024-08-19 4:11:25 0 [Note] InnoDB: Using liburing
2024-08-19 4:11:25 0 [Note] InnoDB: Initializing buffer pool, total size = 9.000GiB, chunk size = 144.000MiB
2024-08-19 4:11:25 0 [Note] InnoDB: Completed initialization of buffer pool
2024-08-19 4:11:25 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
2024-08-19 4:11:25 0 [Note] InnoDB: Resetting space id's in the doublewrite buffer
2024-08-19 4:11:27 0 [Note] InnoDB: End of log at LSN=811645509288
2024-08-19 4:11:27 0 [Note] InnoDB: Opened 3 undo tablespaces
2024-08-19 4:11:27 0 [Note] InnoDB: 128 rollback segments in 3 undo tablespaces are active.
2024-08-19 4:11:27 0 [Note] InnoDB: Removed temporary tablespace data file: "./ibtmp1"
2024-08-19 4:11:27 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
2024-08-19 4:11:27 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
2024-08-19 4:11:27 0 [Note] InnoDB: log sequence number 811645509288; transaction id 233174741
2024-08-19 4:11:27 0 [Note] Plugin 'FEEDBACK' is disabled.
2024-08-19 4:11:27 0 [Note] Plugin 'wsrep-provider' is disabled.
2024-08-19 4:11:27 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2024-08-19 4:11:27 0 [Note] Recovering after a crash using tc.log
2024-08-19 4:11:27 0 [Note] InnoDB: Buffer pool(s) load completed at 240819 4:11:27
2024-08-19 4:11:27 0 [Note] Starting table crash recovery...
2024-08-19 4:11:27 0 [Note] Crash table recovery finished.
2024-08-19 4:11:27 0 [Note] Server socket created on IP: '0.0.0.0'.
2024-08-19 4:11:27 0 [Note] Server socket created on IP: '::'.
2024-08-19 4:11:27 0 [Note] mariadbd: Event Scheduler: Loaded 0 events
2024-08-19 4:11:27 0 [Note] mariadbd: ready for connections.
Version: '11.4.3-MariaDB-ubu2404' socket: '/run/mysqld/mysqld.sock' port: 19913 mariadb.org binary distribution
Hm, that's interesting, I went back to 11.5.2 after getting above logs from 11.4.3 on my test environment and... the issue is gone on the rebuilt container 🤔
Changing ownership was made non-fatal - https://github.com/docker-library/official-images/pull/17344
Healthcheck also slightly reworked (but don't think that plays a part here).
but I tried updating after that release was merged, so not sure. also not sure what change of ownership would be at play here, too.
hm, I upgraded PROD and no issue there, but on test it returned once more. I wonder if this is somehow related to my test host being Windows
Ack, sorry I can't test all host environments. They, by the goals of containers, should result in something identical.
I am not saying you should 😅 My job here is small - report something abnormal I've noticed and all relevant information that may help solve it, if at all possible. It does not seem to be affecting actual data or the server as a whole, once it's running, so I'd say this is a low priority thing, too.
It looks like 11.5.2-noble starts entrypoint 3 times at once. Here's what I have in docker logs:
And here's what I have in my log file
My dockercompose service
My dockerfile
This behavior is not observed on 11.4.3-noble. Number of repeats seem to vary, too: sometimes it's 2, sometimes it's 3. It is possible that container is actually crashing (because MariaDB fails to start), but it's a bit unclear.