Mailcow-dockerized: MySQL InnoDB: Unable to lock ./ibdata1 error: 11

Created on 19 Oct 2019 · 4Comments · Source: mailcow/mailcow-dockerized

[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.

Source

chriscroome

Most helpful comment

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.

burntout on 19 Oct 2019

👍2 ❤1

All 4 comments

Can you post docker ps -a output?

andryyy on 19 Oct 2019

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

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.