search

mailcow / mailcow-dockerized

mailcow: dockerized - 🐮 + 🐋 = 💕
https://mailcow.email
GNU General Public License v3.0
8.75k stars 1.17k forks source link

Cannot access mailcow UI and mailserver stopped working after Ubuntu package update #2923

Closed Triscuit47 closed 5 years ago

Triscuit47 commented 5 years ago

Hi everyone,

I have been hosting a mailcow instance for a while now and all the issues I faced were fixed. However, today I ran into a problem that has been giving me headaches. I'm running on Ubuntu 18.04.3 LTS and, as I did numerous times before, today I've updated some packages and rebooted the system. After the reboot I could not access the mailcow UI (502 Bad Gateway) and my mail client returns the error "Could not connect to mail server; the connection was refused".

telnet localhost 25 returns: 

Trying ::1...
Connected to localhost.
Escape character is '^]'.
Connection closed by foreign host.

I can access the server just fine from outside on SSH so it's not a port forwarding problem. I am not using UFW.

Upon looking into docker logs I found these lines:

postfix-mailcow_1    | Waiting for database to come up...
sogo-mailcow_1       | Waiting for database to come up...
php-fpm-mailcow_1    | Waiting for SQL...
dovecot-mailcow_1    | Waiting for database to come up...

However, trying to do anything mysql related returns: "Access Denied". I've also updated using the update.sh but to no avail. I have no idea what to do or check next and any suggestions are much appreciated.

barry-smithjr commented 5 years ago

Is the mysql container running? What happens when you run a docker-compose up -d in the mailcow-dockerized folder? What about when you run docker logs -f mailcowdockerized_mysql-mailcow_1 ?

andryyy commented 5 years ago

The SQL logs are important indeed.

Triscuit47 commented 5 years ago

docker-compose up -d returns:

mailcowdockerized_redis-mailcow_1 is up-to-date
mailcowdockerized_memcached-mailcow_1 is up-to-date
mailcowdockerized_clamd-mailcow_1 is up-to-date
mailcowdockerized_solr-mailcow_1 is up-to-date
mailcowdockerized_watchdog-mailcow_1 is up-to-date
mailcowdockerized_sogo-mailcow_1 is up-to-date
mailcowdockerized_unbound-mailcow_1 is up-to-date
mailcowdockerized_dockerapi-mailcow_1 is up-to-date
mailcowdockerized_postfix-mailcow_1 is up-to-date
mailcowdockerized_mysql-mailcow_1 is up-to-date
mailcowdockerized_olefy-mailcow_1 is up-to-date
mailcowdockerized_dovecot-mailcow_1 is up-to-date
mailcowdockerized_php-fpm-mailcow_1 is up-to-date
mailcowdockerized_nginx-mailcow_1 is up-to-date
mailcowdockerized_netfilter-mailcow_1 is up-to-date
mailcowdockerized_rspamd-mailcow_1 is up-to-date
mailcowdockerized_acme-mailcow_1 is up-to-date
mailcowdockerized_ipv6nat-mailcow_1 is up-to-date

And docker logs -f mailcowdockerized_mysql-mailcow_1:

2019-09-08 22:58:50 139622329066816 [Note] mysqld (mysqld 10.2.26-MariaDB-1:10.2.26+maria~bionic) starting as process 1 ...
2019-09-08 22:58:50 139622329066816 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-09-08 22:58:50 139622329066816 [Note] InnoDB: Uses event mutexes
2019-09-08 22:58:50 139622329066816 [Note] InnoDB: Compressed tables use zlib 1.2.11
2019-09-08 22:58:50 139622329066816 [Note] InnoDB: Using Linux native AIO
2019-09-08 22:58:50 139622329066816 [Note] InnoDB: Number of pools: 1
2019-09-08 22:58:50 139622329066816 [Note] InnoDB: Using SSE2 crc32 instructions
2019-09-08 22:58:50 139622329066816 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
2019-09-08 22:58:50 139622329066816 [Note] InnoDB: Completed initialization of buffer pool
2019-09-08 22:58:50 139621603968768 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2019-09-08 22:58:51 139622329066816 [Note] InnoDB: Highest supported file format is Barracuda.
2019-09-08 22:58:51 139622329066816 [Note] InnoDB: Starting crash recovery from checkpoint LSN=2504332
2019-09-08 22:58:55 139622329066816 [Note] InnoDB: 128 out of 128 rollback segments are active.
2019-09-08 22:58:55 139622329066816 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2019-09-08 22:58:55 139622329066816 [Note] InnoDB: Creating shared tablespace for temporary tables
2019-09-08 22:58:55 139622329066816 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2019-09-08 22:58:55 139622329066816 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2019-09-08 22:58:55 139622329066816 [Note] InnoDB: Waiting for purge to start
2019-09-08 22:58:55 139622329066816 [Note] InnoDB: 5.7.27 started; log sequence number 2504341
2019-09-08 22:58:55 139621434373888 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2019-09-08 22:58:57 139622329066816 [Note] Recovering after a crash using tc.log
2019-09-08 22:58:57 139622329066816 [Note] Starting crash recovery...
2019-09-08 22:58:57 139622329066816 [Note] Crash recovery finished.
2019-09-08 22:58:58 139622329066816 [Note] Server socket created on IP: '::'.
2019-09-08 22:59:01 139622329066816 [Warning] 'proxies_priv' entry '@% root@899cc5704c53' ignored in --skip-name-resolve mode.
2019-09-08 22:59:04 139621434373888 [Note] InnoDB: Buffer pool(s) load completed at 190908 22:59:04
2019-09-08 22:59:04 139622034724608 [Note] Event Scheduler: scheduler thread started with id 6
2019-09-08 22:59:04 139622329066816 [Note] mysqld: ready for connections.
Version: '10.2.26-MariaDB-1:10.2.26+maria~bionic'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
2019-09-08 22:59:44 139621537265408 [Note] mysqld (initiated by: unknown): Normal shutdown
2019-09-08 22:59:44 139621551494912 [Note] InnoDB: FTS optimize thread exiting.
2019-09-08 22:59:44 139621537265408 [Note] Event Scheduler: Killing the scheduler thread, thread id 6
2019-09-08 22:59:44 139621537265408 [Note] Event Scheduler: Waiting for the scheduler thread to reply
2019-09-08 22:59:44 139621537265408 [Note] Event Scheduler: Stopped
2019-09-08 22:59:44 139621537265408 [Note] Event Scheduler: Purging the queue. 0 events
2019-09-08 22:59:44 139621537265408 [Note] InnoDB: Starting shutdown...
2019-09-08 22:59:44 139621434373888 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
2019-09-08 22:59:45 139621434373888 [Note] InnoDB: Buffer pool(s) dump completed at 190908 22:59:44
2019-09-08 22:59:46 139621537265408 [Note] InnoDB: Shutdown completed; log sequence number 2504659
2019-09-08 22:59:46 139621537265408 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2019-09-08 22:59:46 139621537265408 [Note] mysqld: Shutdown complete

EDIT: Found these after a reboot

2019-09-08 23:44:20 140598390347072 [ERROR] Fatal error: Can't open and lock privilege tables: Incorrect file format 'user'
2019-09-08 23:45:25 139791350031680 [Note] mysqld (mysqld 10.2.26-MariaDB-1:10.2.26+maria~bionic) starting as process 1 ...
2019-09-08 23:45:25 139791350031680 [ERROR] Could not open mysql.plugin table. Some plugins may be not loaded
Triscuit47 commented 5 years ago

Ok this is weird, while trying to fix this I stumbled upon #2904 which also reproduced for me and by installing kernel 5.0 using the line provided in the comments by @unixfox (thanks a lot for that) it somehow magically fixed it. The only problem is all the emails disappeared even though SOGo and web UI show the mailboxes aren't empty. Hopefully it's just a sync issue.