Postfix cannot connect to MariaDB after crash

Discussion in 'Server Operation' started by teer26, May 4, 2021.

  1. teer26

    teer26 New Member

    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?

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


    Additional Info
    • 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


    Logs
    Code:
    /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 [email protected]: Shutting down
        Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: auth: Debug: sql([email protected],173.73.24.88,<pXAtUQrBctCtSRhY>): Finished passdb lookup
        Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: auth: Debug: auth([email protected],173.73.24.88,<pXAtUQrBctCtSRhY>): Auth request finished
        Apr 28 15:51:02 hwsrv-123456 dovecot[120465]: auth: Debug: client passdb out: FAIL#0112#[email protected]#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=<[email protected]>, 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=<[email protected]>, 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([email protected],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([email protected],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
    
    Code:
    /var/log/mariadb/mariadb.log
    
        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)
    
    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)
    Omitted thousands of identical (save for the timestamp) lines of [Warning] Access denied for user 'postfix'@'localhost' (using password: YES)

    Config
    Code:
    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
        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
    
        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
    
    Code:
    /etc/postfix/sql/virtual_alias_maps.cf
    
        user = postfix
        password =
        hosts = localhost
        dbname = postfix_db
        table = alias
        select_field = goto
        where_field = address
    
    
    /etc/postfix/sql/virtual_domains_maps.cf
    
        user = postfix
        password =
        hosts = localhost
        dbname = postfix_db
        table = domain
        select_field = domain
        where_field = domain
    
    
    /etc/postfix/sql/virtual_mailbox_maps.cf
    
        user = postfix
        password =
        hosts = localhost
        dbname = postfix_db
        table = mailbox
        select_field = maildir
        where_field = username
    
    Code:
    doveconf -n
    
        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
    
    Code:
    /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
    
     
    Last edited: May 4, 2021
  2. Taleman

    Taleman Well-Known Member HowtoForge Supporter

    So you have no backups of databases you could restore?
     
  3. teer26

    teer26 New Member

    Not as recently as I would have liked.

    I had to eventually throw in the towel and just remake the tables.

    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). I've never seen anything quite like it.

    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.

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

Share This Page