MySQL InnoDB: Unable to lock ./ibdata1 error: 11

chriscroome commented 4 years ago

[X] I understand that not following below instructions might result in immediate closing and deletion of my issue.
[X] I have understood that answers are voluntary and community-driven, and not commercial support.
[X] I have verified that my issue has not been already answered in the past. I also checked previous issues.

After upgrading Docker on Debian Buster running on Xen to Docker version 19.03.4, build 9013bf583a the MySQL container fails to start without errors.

mysql-mailcow_1      | 2019-10-19  7:51:18 0 [ERROR] InnoDB: Unable to lock ./ibdata1 error: 11                                                                                                                 
mysql-mailcow_1      | 2019-10-19  7:51:18 0 [Note] InnoDB: Check that you do not already have another mysqld process using the same InnoDB d                                                                   ata or log files.                                                                                                                                                                                               
mysql-mailcow_1      | 2019-10-19  7:51:18 0 [Note] InnoDB: Unable to open the first data file                                                                                                                  
mysql-mailcow_1      | 2019-10-19  7:51:18 0 [ERROR] InnoDB: Operating system error number 11 in a file operation.                                                                                              
mysql-mailcow_1      | 2019-10-19  7:51:18 0 [ERROR] InnoDB: Error number 11 means 'Resource temporarily unavailable'                                                                                           
mysql-mailcow_1      | 2019-10-19  7:51:18 0 [Note] InnoDB: Some operating system error numbers are described at https://mariadb.com/kb/en/li                                                                   brary/operating-system-error-codes/                                                                                                                                                                             
mysql-mailcow_1      | 2019-10-19  7:51:18 0 [ERROR] InnoDB: Cannot open datafile './ibdata1'                                                                                                                   
mysql-mailcow_1      | 2019-10-19  7:51:18 0 [ERROR] InnoDB: Could not open or create the system tablespace. If you tried to add new data fil                                                                   es to the system tablespace, and it failed here, you should now edit innodb_data_file_path in my.cnf back to what it was, and remove the new                                                                    ibdata files InnoDB created in this failed attempt. InnoDB only wrote those files full of zeros, but did not yet use them in any way. But be                                                                    careful: do not remove old data files which contain your precious data!                                                                                                                                         
mysql-mailcow_1      | 2019-10-19  7:51:18 0 [ERROR] InnoDB: Plugin initialization aborted with error Cannot open a file                                                                                        
mysql-mailcow_1      | 2019-10-19  7:51:18 0 [Note] InnoDB: Starting shutdown...                                                                                                                                
mysql-mailcow_1      | 2019-10-19  7:51:18 0 [ERROR] Plugin 'InnoDB' init function returned error.                                                                                                              
mysql-mailcow_1      | 2019-10-19  7:51:18 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.                                                                                                   
mysql-mailcow_1      | 2019-10-19  7:51:18 0 [ERROR] Unknown/unsupported storage engine: InnoDB                                                                                                                 
mysql-mailcow_1      | 2019-10-19  7:51:18 0 [ERROR] Aborting

I have connected to the container with a view to debugging the issue but I only got as far as stopping MySQL and then the container exits:

 docker-compose exec mysql-mailcow /bin/bash
# service mysql stop
 * Stopping MariaDB database server mysqld

Further information (where applicable):

Question	Answer
My operating system	Buster
Is Apparmor, SELinux or similar active?	Apparmor
Virtualization technlogy (KVM, VMware, Xen, etc)	Xen
Server/VM specifications (Memory, CPU Cores)	47G RAM 14 CPU cores
Docker Version (`docker version`)	19.03.4
Docker-Compose Version (`docker-compose version`)	1.24.1
Reverse proxy (custom solution)	N/A

Further notes:

Output of git diff origin/master, any other changes to the code? If so, please post them.

The output of the requested diff appears to contain hashed passwords? The key change is that one bug fix from a while ago was added manually:

 git status
On branch master
Your branch is ahead of 'origin/master' by 63 commits.
  (use "git push" to publish your local commits)

Changes not staged for commit:
  (use "git add <file>..." to update what will be committed)
  (use "git checkout -- <file>..." to discard changes in working directory)

        modified:   data/web/inc/functions.inc.php

Untracked files:
  (use "git add <file>..." to include in what will be committed)

        .swp

no changes added to commit (use "git add" and/or "git commit -a")

git diff data/web/inc/functions.inc.php
diff --git a/data/web/inc/functions.inc.php b/data/web/inc/functions.inc.php
index 93b8d968..2c1a38dc 100644
--- a/data/web/inc/functions.inc.php
+++ b/data/web/inc/functions.inc.php
@@ -714,9 +714,11 @@ function is_valid_domain_name($domain_name) {
                return false;
        }
        $domain_name = idn_to_ascii($domain_name, 0, INTL_IDNA_VARIANT_UTS46);
-       return (preg_match("/^([a-z\d](-*[a-z\d])*)\.(([a-z\d](-*[a-z\d])*))*$/i", $domain_name)
+       //return (preg_match("/^([a-z\d](-*[a-z\d])*)\.(([a-z\d](-*[a-z\d])*))*$/i", $domain_name)^M
+       return (preg_match("/^([a-z\d](-*[a-z\d])*)(\.([a-z\d](-*[a-z\d])*))*$/i", $domain_name)^M
                   && preg_match("/^.{1,253}$/", $domain_name)
-                  && preg_match("/^[^\.]{1,63}\.([^\.]{1,63})*$/", $domain_name));
+                  //&& preg_match("/^[^\.]{1,63}\.([^\.]{1,63})*$/", $domain_name));^M
+                  && preg_match("/^[^\.]{1,63}(\.[^\.]{1,63})*$/", $domain_name));^M
 }
 function set_tfa($_data) {

All third-party firewalls and custom iptables rules are unsupported. Please check the Docker docs about how to use Docker with your own ruleset. Nevertheless, iptabels output can help us to help you: iptables -L -vn, ip6tables -L -vn, iptables -L -vn -t nat and ip6tables -L -vn -t nat

This problem isn't firewall related.

Check docker exec -it $(docker ps -qf name=acme-mailcow) dig +short stackoverflow.com @172.22.1.254 (set the IP accordingly, if you changed the internal mailcow network) and docker exec -it $(docker ps -qf name=acme-mailcow) dig +short stackoverflow.com @1.1.1.1 - output? Timeout?

This problem isn't DNS related.

General logs:

Please take a look at the official documentation.

andryyy commented 4 years ago

Can you post docker ps -a output?

chriscroome commented 4 years ago

CONTAINER ID        IMAGE                    COMMAND                  CREATED             STATUS              PORTS                                                                                                                                        NAMES
a2579990cae6        robbertkl/ipv6nat        "/docker-ipv6nat-com…"   52 minutes ago      Up 52 minutes                                                                                                                                                    mailcow_ipv6nat-mailcow_1
8b513a69803a        mailcow/rspamd:1.46      "/docker-entrypoint.…"   52 minutes ago      Up 52 minutes                                                                                                                                                    mailcow_rspamd-mailcow_1
54303a4be85b        mailcow/acme:1.61        "/sbin/tini -g -- /s…"   52 minutes ago      Up 52 minutes                                                                                                                                                    mailcow_acme-mailcow_1
331868734e14        nginx:mainline-alpine    "/bin/sh -c 'envsubs…"   52 minutes ago      Up 52 minutes       0.0.0.0:80->80/tcp, 0.0.0.0:443->443/tcp                                                                                                     mailcow_nginx-mailcow_1
ecca40511452        mailcow/netfilter:1.29   "python3 -u /server.…"   52 minutes ago      Up 52 minutes                                                                                                                                                    mailcow_netfilter-mailcow_1
259d1da85ad7        mailcow/phpfpm:1.44      "/docker-entrypoint.…"   52 minutes ago      Up 52 minutes       9000/tcp                                                                                                                                     mailcow_php-fpm-mailcow_1
f2e01d3fc48d        mariadb:10.3             "docker-entrypoint.s…"   53 minutes ago      Up 17 seconds       127.0.0.1:13306->3306/tcp                                                                                                                    mailcow_mysql-mailcow_1
f697f8a629f1        mailcow/postfix:1.40     "/bin/sh -c 'exec /u…"   53 minutes ago      Up 52 minutes       0.0.0.0:25->25/tcp, 0.0.0.0:465->465/tcp, 0.0.0.0:587->587/tcp, 588/tcp                                                                      mailcow_postfix-mailcow_1
2b63f2d2f4a7        mailcow/dovecot:1.89     "/docker-entrypoint.…"   53 minutes ago      Up 52 minutes       0.0.0.0:110->110/tcp, 0.0.0.0:143->143/tcp, 0.0.0.0:993->993/tcp, 0.0.0.0:995->995/tcp, 0.0.0.0:4190->4190/tcp, 127.0.0.1:19991->12345/tcp   mailcow_dovecot-mailcow_1
15e20de9fdeb        mailcow/watchdog:1.58    "/bin/sh -c '/watchd…"   53 minutes ago      Up 52 minutes                                                                                                                                                    mailcow_watchdog-mailcow_1
72474fb33ea3        mailcow/clamd:1.28       "/sbin/tini -g -- /b…"   53 minutes ago      Up 52 minutes                                                                                                                                                    mailcow_clamd-mailcow_1
0aa7196a3034        mailcow/dockerapi:1.32   "python3 -u /app/ser…"   53 minutes ago      Up 52 minutes                                                                                                                                                    mailcow_dockerapi-mailcow_1
0cdc27ce552b        mailcow/unbound:1.8      "/docker-entrypoint.…"   53 minutes ago      Up 52 minutes       53/tcp, 53/udp                                                                                                                               mailcow_unbound-mailcow_1
7a800af54c20        mailcow/solr:1.6         "/docker-entrypoint.…"   53 minutes ago      Up 52 minutes       127.0.0.1:18983->8983/tcp                                                                                                                    mailcow_solr-mailcow_1
57e258f68530        redis:5-alpine           "docker-entrypoint.s…"   53 minutes ago      Up 52 minutes       6379/tcp                                                                                                                                     mailcow_redis-mailcow_1
e96c1c3eaaf8        mailcow/olefy:1.1        "python3 -u /app/ole…"   53 minutes ago      Up 52 minutes                                                                                                                                                    mailcow_olefy-mailcow_1
41c21969ad71        mailcow/sogo:1.61        "/bin/sh -c 'exec /u…"   53 minutes ago      Up 52 minutes                                                                                                                                                    mailcow_sogo-mailcow_1
3db91c984fd8        memcached:alpine         "docker-entrypoint.s…"   53 minutes ago      Up 52 minutes       11211/tcp                                                                                                                                    mailcow_memcached-mailcow_1

We are considering rolling back to a snapshot of the VM prior to the Docker upgrade. I did try a docker-compose down and docker-compose up -d after the Docker upgrade.

chriscroome commented 4 years ago

We stopped all the containers, found that a process was still running with ps uax | grep mysql then killed the process and restarted all the containers and this appears to have solved the issue:

mysql-mailcow_1      | 2019-10-19  8:40:28 0 [Note] Recovering after a crash using tc.log
mysql-mailcow_1      | 2019-10-19  8:40:28 0 [Note] Starting crash recovery...
mysql-mailcow_1      | 2019-10-19  8:40:28 0 [Note] Crash recovery finished.
mysql-mailcow_1      | 2019-10-19  8:40:28 0 [Note] Server socket created on IP: '::'.
...
mysql-mailcow_1      | 2019-10-19  8:40:29 0 [Note] mysqld: ready for connections.

Sorry for the noise.

burntout commented 4 years ago

The issue was a process locking a file still.

The mysql error was

mysql-mailcow_1      | 2019-10-19  8:21:13 0 [ERROR] mysqld: Can't lock aria control file '/var/lib/mysql/aria_log_control' for exclusive use, error: 11. Will retry for 30 seconds
mysql-mailcow_1      | 2019-10-19  8:21:44 0 [ERROR] mysqld: Got error 'Could not get an exclusive lock; file is probably in use by another process' when trying to use aria control file '/var/lib/mysql/aria_log_control'

We downed all the containers using docker-compose down

We identified a process locking the file

lsof aria_log_control 
lsof: no pwd entry for UID 999
COMMAND   PID     USER   FD   TYPE DEVICE SIZE/OFF     NODE NAME
lsof: no pwd entry for UID 999
mysqld  30515      999    3uW  REG  202,5       52 27787285 aria_log_control

We killed process 30515 kill -9 30515

then restarted the containers ..

mysql started now.

jvdbrink-netpulse commented 3 years ago

For me docker ps revealed another instance of the container with the same name, created with the docker-compose file before moving the docker-compose file to a sub directory. I forgot to do a docker-compose down before moving the file and since I had the restart: always on this instance was locking the mysql data file. A simple stop and docker rm fixed the issue for me.

mailcow / mailcow-dockerized

MySQL InnoDB: Unable to lock ./ibdata1 error: 11 #3057