0

I am running a mail server on CentOS 8 using Postfix, Dovecot (virtual users) with MariaDB.

~1 week ago, Mariadb seemingly crashed and deleted most (?!) of the users, but failed "softly" and restarted itself (albeit in a nonfunctioning state). Strangely the data tables were left intact. No idea how this happened, but it took place at or around 21 April: 2 days after updating certs with certbot.

TL;DR Why can't postfix et al connect to MariaDB? And what happened to cause it in the first place? And how?

I would be eternally thankful for any information to be able to access my email!

Additional Info

System:

  • Postfix (3.3.1)
  • Dovecot (2.3.8)
  • MariaDB (10.3.28)
  • ClamAV, Nginx, OpenDKIM, OpenDMARC, php-fpm, postfixadmin, spamassassin

Did the following:

  1. Had to reset root password for MariaDB (couldn't login to see what was wrong because users deleted).
  2. Saw most users gone; recreated mysql users (postfix, dovecot, postfixadmin) in Mariadb with new passwords
  3. Granted pertinent privileges to table postfix_db, postfixadmin_db
  4. Updated relevant postfix, dovecot config files with new passwords
  5. Commented out the only line plugin-load-add=auth_gssapi.so in /etc/my.cnf.d/auth_gssapi.cnf
    • this cut down on a lot of warnings/errors

Logs

/var/log/maillog

Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: auth: Warning: Killed with signal 15 (by pid=1 uid=0 code=kill)
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: auth: Error: auth worker: Aborted PASSV request for admin@domain3.com: Shutting down
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: auth: Debug: sql(admin@domain3.com,173.73.24.88,<pXAtUQrBctCtSRhY>): Finished passdb lookup
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: auth: Debug: auth(admin@domain3.com,173.73.24.88,<pXAtUQrBctCtSRhY>): Auth request finished
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: auth: Debug: client passdb out: FAIL#0112#011user=admin@domain3.com#011code=temp_fail
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: auth: Warning: Timeout leak: 0x55fc0325ba70 (auth-request-handler.c:598)
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: auth: Warning: Raw backtrace for leaks: /usr/lib64/dovecot/libdovecot.so.0(io_loop_destroy+0x21c) [0x7f973b94f9dc] -> /usr/lib64/dovecot/libdovecot.so.0(master_service_deinit+0xee) [0x7f973b8c772e] -> dovecot/auth(main+0x53d) [0x55fc0324d80d] -> /lib64/libc.so.6(__libc_start_main+0xf3) [0x7f973a6e87b3] -> dovecot/auth(_start+0x2e) [0x55fc0324d88e]
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: auth: Warning: Event 0x55fc03eab910 leaked (parent=0x55fc03ed4350): auth-request.c:880
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: auth: Warning: Event 0x55fc03eb9380 leaked (parent=0x55fc03ed4350): auth-request.c:113
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: auth: Warning: Event 0x55fc03ed4350 leaked (parent=0x55fc03ed3ef0): auth-request.c:112
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: auth: Warning: Event 0x55fc03ed3ef0 leaked (parent=(nil)): auth-client-connection.c:338
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: imap-login: Debug: Ignoring unknown passdb extra field: temp
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: imap-login: Warning: auth-client: conn unix:login: Auth connection closed with 1 pending requests (max 31 secs, pid=121695, EOF)
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: imap-login: Disconnected: Shutting down (auth process communication failure): user=<admin@domain6.com>, method=LOGIN, rip=173.73.24.88, lip=142.11.253.50, TLS, session=<YeZhTwrBb9CtSRhY>
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: imap-login: Debug: SSL alert: close notify
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: imap-login: Disconnected: Shutting down (auth service reported temporary failure): user=<admin@domain3.com>, method=LOGIN, rip=173.73.24.88, lip=142.11.253.50, TLS, session=<pXAtUQrBctCtSRhY>
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: imap-login: Debug: SSL alert: close notify
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: anvil: Warning: Killed with signal 15 (by pid=1 uid=0 code=kill)
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: auth-worker(121991): Error: sql(admin@domain3.com,173.73.24.88,<pXAtUQrBctCtSRhY>): Password query failed: Not connected to database
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: auth-worker(121991): Debug: sql(admin@domain3.com,173.73.24.88,<pXAtUQrBctCtSRhY>): Finished passdb lookup
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: auth-worker(121991): Debug: conn unix:auth-worker (pid=120471,uid=0): auth-worker<1>: Finished
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: auth-worker(121991): Debug: conn unix:auth-worker (pid=120471,uid=0): Disconnected: Connection closed (fd=-1)
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: stats: Warning: Killed with signal 15 (by pid=1 uid=0 code=kill)
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: log(120465): Warning: Killed with signal 15 (by pid=1 uid=0 code=kill)
Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: log(120465): Warning: Shutting down logging for 'auth-worker: ' with 1 clients
Apr 28 15:51:02 hwsrv-123456 dovecot[122140]: master: Dovecot v2.3.8 (9df20d2db) starting up for imap, lmtp, pop3
Apr 28 15:51:02 hwsrv-123456 dovecot[122144]: auth: Debug: Loading modules from directory: /usr/lib64/dovecot/auth
Apr 28 15:51:02 hwsrv-123456 dovecot[122144]: auth: Debug: Module loaded: /usr/lib64/dovecot/auth/lib20_auth_var_expand_crypt.so
Apr 28 15:51:02 hwsrv-123456 dovecot[122144]: auth: Debug: Module loaded: /usr/lib64/dovecot/auth/libdriver_mysql.so
Apr 28 15:51:02 hwsrv-123456 dovecot[122144]: auth: Debug: Module loaded: /usr/lib64/dovecot/auth/libdriver_sqlite.so
Apr 28 15:51:02 hwsrv-123456 dovecot[122144]: auth: Debug: Read auth token secret from /var/run/dovecot/auth-token-secret.dat
Apr 28 15:51:02 hwsrv-123456 dovecot[122144]: auth: Warning: sql: Ignoring changed user_query in /etc/dovecot/dovecot-sql.conf, because userdb sql not used. (If this is intentional, set userdb_warning_disable=yes)
Apr 28 15:51:02 hwsrv-123456 dovecot[122144]: auth: Debug: auth client connected (pid=122141)
Apr 28 15:51:02 hwsrv-123456 dovecot[122144]: auth: Debug: auth client connected (pid=122142)
Apr 28 15:51:30 hwsrv-123456 postfix/smtpd[122160]: connect from unknown[203.159.80.219]
Apr 28 15:51:30 hwsrv-123456 postfix/smtpd[122160]: warning: connect to Milter service unix:/var/run/spamassassin/spamassassin-milter.sock: No such file or directory
Apr 28 15:51:30 hwsrv-123456 postfix/smtpd[122160]: lost connection after AUTH from unknown[203.159.80.219]
Apr 28 15:51:30 hwsrv-123456 postfix/smtpd[122160]: disconnect from unknown[203.159.80.219] ehlo=1 auth=0/1 commands=1/2
Apr 28 15:52:02 hwsrv-123456 postfix/pickup[122110]: warning: B2486900008E: message has been queued for 6 days
Apr 28 15:52:02 hwsrv-123456 postfix/pickup[122110]: B2486900008E: uid=0 from=<root>
Apr 28 15:52:02 hwsrv-123456 opendmarc[4021861]: ignoring connection from localhost
Apr 28 15:52:02 hwsrv-123456 postfix/cleanup[122112]: warning: connect to Milter service unix:/var/run/spamassassin/spamassassin-milter.sock: No such file or directory
Apr 28 15:52:02 hwsrv-123456 postfix/cleanup[122112]: warning: proxy:mysql:/etc/postfix/sql/virtual_alias_maps.cf lookup error for "root@localhost"
Apr 28 15:52:02 hwsrv-123456 postfix/cleanup[122112]: warning: B2486900008E: virtual_alias_maps map lookup problem for root@localhost -- message not accepted, try again later
Apr 28 15:52:02 hwsrv-123456 postfix/pickup[122110]: warning: B3391900008E: message has been queued for 5 days
Apr 28 15:52:02 hwsrv-123456 postfix/pickup[122110]: B3391900008E: uid=0 from=<root>
Apr 28 15:52:02 hwsrv-123456 opendmarc[4021861]: ignoring connection from localhost
Apr 28 15:52:02 hwsrv-123456 postfix/cleanup[122112]: warning: connect to Milter service unix:/var/run/spamassassin/spamassassin-milter.sock: No such file or directory
Apr 28 15:52:02 hwsrv-123456 postfix/cleanup[122112]: warning: proxy:mysql:/etc/postfix/sql/virtual_alias_maps.cf lookup error for "root@localhost"
Apr 28 15:52:02 hwsrv-123456 postfix/cleanup[122112]: warning: B3391900008E: virtual_alias_maps map lookup problem for root@localhost -- message not accepted, try again later
Apr 28 15:52:02 hwsrv-123456 postfix/pickup[122110]: warning: B3B59900008E: message has been queued for 4 days
Apr 28 15:52:02 hwsrv-123456 postfix/pickup[122110]: B3B59900008E: uid=0 from=<root>
Apr 28 15:52:02 hwsrv-123456 opendmarc[4021861]: ignoring connection from localhost

/var/log/mariadb/mariadb.log

Note: mariadb.log files have a gap from 2021-03-08 16:47:32 to 2021-04-21 6:24:43 (which is probably very telling in and of itself)

2021-04-21  6:24:43 0 [Note] /usr/libexec/mysqld (initiated by: unknown): Normal shutdown
2021-04-21  6:24:43 0 [Note] InnoDB: FTS optimize thread exiting.
2021-04-21  6:24:43 0 [Note] Event Scheduler: Purging the queue. 0 events
2021-04-21  6:24:43 0 [Note] InnoDB: Starting shutdown...
2021-04-21  6:24:43 0 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
2021-04-21  6:24:43 0 [Note] InnoDB: Buffer pool(s) dump completed at 210421  6:24:43
2021-04-21  6:24:45 0 [Note] InnoDB: Shutdown completed; log sequence number 8327780; transaction id 9783
2021-04-21  6:24:45 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2021-04-21  6:24:45 0 [Note] /usr/libexec/mysqld: Shutdown complete

2021-04-21  6:24:45 0 [Note] InnoDB: Using Linux native AIO
2021-04-21  6:24:45 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2021-04-21  6:24:45 0 [Note] InnoDB: Uses event mutexes
2021-04-21  6:24:45 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2021-04-21  6:24:45 0 [Note] InnoDB: Number of pools: 1
2021-04-21  6:24:45 0 [Note] InnoDB: Using SSE2 crc32 instructions
2021-04-21  6:24:45 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2021-04-21  6:24:45 0 [Note] InnoDB: Completed initialization of buffer pool
2021-04-21  6:24:45 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2021-04-21  6:24:45 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=10405217
2021-04-21  6:24:45 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2021-04-21  6:24:45 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2021-04-21  6:24:45 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2021-04-21  6:24:45 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2021-04-21  6:24:45 0 [Note] InnoDB: 10.3.28 started; log sequence number 10405226; transaction id 6978
2021-04-21  6:24:45 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2021-04-21  6:24:45 0 [Note] InnoDB: Buffer pool(s) load completed at 210421  6:24:45
2021-04-21  6:24:45 0 [Note] Plugin 'FEEDBACK' is disabled.
2021-04-21  6:24:45 0 [Warning] mysqld: GSSAPI plugin : default principal 'mariadb/hwsrv-123456.hostwindsdns.com@' not found in keytab
2021-04-21  6:24:45 0 [ERROR] mysqld: Server GSSAPI error (major 851968, minor 2529639093) : gss_acquire_cred failed -Unspecified GSS failure.  Minor code may provide more information. Keytab FILE:/etc/krb5.keytab is nonexistent or empty. 
2021-04-21  6:24:45 0 [ERROR] Plugin 'gssapi' init function returned error.
2021-04-21  6:24:45 0 [Note] Server socket created on IP: '::'.
2021-04-21  6:24:45 0 [Note] Reading of all Master_info entries succeeded
2021-04-21  6:24:45 0 [Note] Added new Master_info '' to hash table
2021-04-21  6:24:45 0 [Note] /usr/libexec/mysqld: ready for connections.
Version: '10.3.28-MariaDB'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server
2021-04-21  6:52:59 8 [Warning] Access denied for user 'postfix'@'localhost' (using password: YES)
2021-04-21  7:48:19 9 [Warning] Access denied for user 'postfix'@'localhost' (using password: YES)
2021-04-21  9:07:23 10 [Warning] Access denied for user 'postfix'@'localhost' (using password: YES)

Omitted: thousands of identical (save for the timestamp) lines of [Warning] Access denied for user 'postfix'@'localhost' (using password: YES)

Config

postconf -n

alias_database                      = $alias_maps
alias_maps                          = hash:/etc/postfix/aliases
biff                                = no
broken_sasl_auth_clients            = yes
command_directory                   = /usr/sbin
compatibility_level                 = 2
daemon_directory                    = /usr/libexec/postfix
data_directory                      = /var/lib/postfix
debug_peer_level                    = 10
debugger_command                    = PATH=/bin:/usr/bin:/usr/local/bin:/usr/X11R6/bin
                                      ddd $daemon_directory/$process_name $process_id & sleep 5
html_directory                      = no
inet_interfaces                     = all
inet_protocols                      = ipv4
mail_owner                          = postfix
mailq_path                          = /usr/bin/mailq.postfix
manpage_directory                   = /usr/share/man
milter_default_action               = accept
milter_protocol                     = 2
meta_directory                      = /etc/postfix
mydestination                       = localhost
myorigin                            = localhost

non_smtpd_milters                   = $smtpd_milters
                                  
newaliases_path                     = /usr/bin/newaliases.postfix
queue_directory                     = /var/spool/postfix
readme_directory                    = /usr/share/doc/postfix-2.10.1/README_FILES
relay_domains                       = *
sample_directory                    = /usr/share/doc/postfix-2.10.1/samples
sendmail_path                       = /usr/sbin/sendmail.postfix
setgid_group                        = postdrop
shlib_directory                     = no

smtp_tls_security_level             = may
smtp_tls_loglevel                   = 1
smtp_use_tls                        = yes
smtpd_milters                       = unix:/var/run/opendkim/opendkim.sock,
                                      unix:/var/run/opendmarc/opendmarc.sock, 
                                      unix:/var/run/spamassassin/spamassassin-milter.sock

smtpd_client_restrictions           = permit_mynetworks, permit_sasl_authenticated
smtpd_recipient_restrictions        = permit_mynetworks, permit_sasl_authenticated, reject_unauth_destination
smtpd_relay_restrictions            = permit_mynetworks, permit_sasl_authenticated, reject_unauth_destination
smtpd_sasl_auth_enable              = yes
smtpd_sasl_local_domain             = $mydomain
smtpd_sasl_path                     = /var/spool/postfix/private/auth
smtpd_sasl_security_options         = noanonymous
smtpd_sasl_tls_security_options     = $smtpd_sasl_security_options
smtpd_sasl_type                     = dovecot

smtpd_sender_restrictions           = permit_mynetworks, reject_non_fqdn_sender, reject_unknown_sender_domain, permit
smtpd_sender_login_maps             = proxy:mysql:/etc/postfix/sql/virtual_domains_maps.cf

smtpd_tls_auth_only                 = yes
smtpd_tls_cert_file                 = /etc/ssl/private/fullchain.pem
smtpd_tls_key_file                  = /etc/ssl/private/privkey.pem
smtpd_tls_loglevel                  = 1
smtpd_tls_received_header           = yes
smtpd_tls_security_level            = may
smtpd_tls_session_cache_database    = btree:${data_directory}/smtpd_scache
smtpd_tls_session_cache_timeout     = 3600s
smtpd_use_tls                       = yes

tls_random_source                   = dev:/dev/urandom

virtual_alias_maps                  = proxy:mysql:/etc/postfix/sql/virtual_alias_maps.cf
virtual_gid_maps                    = static:2000
virtual_mailbox_base                = /var/www/mail/vmail
virtual_mailbox_domains             = proxy:mysql:/etc/postfix/sql/virtual_domains_maps.cf
virtual_mailbox_maps                = proxy:mysql:/etc/postfix/sql/virtual_mailbox_maps.cf
virtual_minimum_uid                 = 2000
virtual_transport                   = lmtp:unix:private/dovecot-lmtp
virtual_uid_maps                    = static:2000

unknown_local_recipient_reject_code = 550

/etc/postfix/sql/virtual_alias_maps.cf

/etc/postfix/sql/virtual_domains_maps.cf

/etc/postfix/sql/virtual_mailbox_maps.cf

user = postfix
password = abcdefg12345
hosts = localhost
dbname = postfix_db
table = alias
select_field = goto
where_field = address


user = postfix
password = abcdefg12345
hosts = localhost
dbname = postfix_db
table = domain
select_field = domain
where_field = domain


user = postfix
password = abcdefg12345
hosts = localhost
dbname = postfix_db
table = mailbox
select_field = maildir
where_field = username

doveconf -n

# 2.3.8 (9df20d2db): /etc/dovecot/dovecot.conf
# OS: Linux 4.18.0-240.10.1.el8_3.x86_64 x86_64 CentOS Linux release 8.3.2011 xfs
# Hostname: hwsrv-123456.hostwindsdns.com

auth_debug                    = yes
auth_mechanisms               = plain login
auth_verbose                  = yes
default_login_user            = vmail
first_valid_gid               = 2000
first_valid_uid               = 2000
listen                        = *
log_timestamp                 = "%Y-%m-%d %H:%M:%S "
mail_access_groups            = vmail
mail_debug                    = yes
mail_location                 = maildir:/var/www/mail/vmail/%d/%n

namespace inbox {
  inbox = yes
  location =
  mailbox Drafts {
    auto = subscribe
    special_use = \Drafts
  }
  mailbox Junk {
    auto = subscribe
    special_use = \Junk
  }
  mailbox Sent {
    auto = subscribe
    special_use = \Sent
  }
  mailbox Trash {
    auto = subscribe
    special_use = \Trash
  }
  prefix =
  separator = /
  type = private
}
passdb {
  args = /etc/dovecot/dovecot-sql.conf
  driver = sql
}
protocols = imap lmtp pop3
service auth {
  unix_listener /var/spool/postfix/private/auth {
    group = postfix
    mode = 0600
    user = postfix
  }
  user = root
}
service imap-login {
  inet_listener imaps {
    port = 993
  }
  process_min_avail = 1
  user = vmail
}
service lmtp {
  unix_listener /var/spool/postfix/private/dovecot-lmtp {
    group = postfix
    mode = 0600
    user = postfix
  }
}
service pop3-login {
  inet_listener pop3s {
    port = 995
  }
  process_min_avail = 1
  user = vmail
}
ssl = required
ssl_cert = </etc/ssl/private/fullchain.pem
ssl_dh = # hidden, use -P to show it
ssl_key = # hidden, use -P to show it
ssl_prefer_server_ciphers = yes
userdb {
  args = /etc/dovecot/dovecot-sql.conf
  driver = static
}
verbose_ssl = yes

/etc/my.cnf

[mysqld]
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock

#symbolic-links=0

skip-networking

[mysqld_safe]
log-error=/var/log/mariadb/mariadb.log
pid-file=/var/run/mariadb/mariadb.pid

#
# include all files from the config directory
#
!includedir /etc/my.cnf.d

#bind-address=127.0.0.1

innodb_flush_log_at_trx_commit=1
sync_binlog=1

[client]

socket=/var/lib/mysql/mysql.sock

Guess?

Given that

  • MariaDB crashed (somewhat catestrophically),

followed by

  1. inability to connect to mariadb,

  2. numerous faulty configuration-based errors (e.g. gssapi option), and

  3. no log file for that time segment (possibly overwritten),

...it would logically follow that MariaDB crashed with possible corruption/clobbering? And reverted to either a recovery or default state with some nonsensical settings.

SKNB
  • 25
  • 1
  • 10

1 Answers1

0

TL;DR: moral of the story is backup your databases regularly (more regularly than I did). Had to eventually throw in the towel and just remake the tables.

This is my personal email server, and while the data loss was minimal the time loss was not. Something I did not take into account when I postponed updating my backup scripts to make them more specific all-encompassing.

The database was more corrupted than my initial findings as of this posting may have indicated. All the databases and tables were present, but upon closer inspection there were no rows in them. Call it the 'neutron bomb' -- left the database "structures" standing but wiped out all the "inhabitants" (data).

Would give my right thumb to know what precipitated this...

SKNB
  • 25
  • 1
  • 10