• 11
name

A PHP Error was encountered

Severity: Notice

Message: Undefined index: userid

Filename: views/question.php

Line Number: 191

Backtrace:

File: /home/prodcxja/public_html/questions/application/views/question.php
Line: 191
Function: _error_handler

File: /home/prodcxja/public_html/questions/application/controllers/Questions.php
Line: 433
Function: view

File: /home/prodcxja/public_html/questions/index.php
Line: 315
Function: require_once

I am running Dovecot and Postfix on a CentOS 8 server, with Nginx and LetsEncrypt for SSL/TLS. I'm using the virtual user and domains configuration. OpenDKIM, OpenDMARC, ClamAV and SpamAssassin are also in play, as are Roundcube and PostfixAdmin for webmail/admin resp.

Problem: cannot retrieve OR send messages on Thunderbird. Attempting to download new messages results in 1-2 minutes of "Connected to pop.domain.com..." before getting alert "Connection timed out to server pop.domain.com". Thunderbird is configured to work on either imap.domain.com on port 993, or pop.domain.com on port 995. I have one test account on each, and neither one is working.

Interestingly, can view inbox and receive emails fine with Roundcube, but cannot send without getting "SMTP Error: [451] 4.7.1 Service unavailable - try again later".

Possible culprit(s):

  • Misconfigured config variable in Dovecot
    • Possibly stemming from version disparities: my CentOS 7 used 2.10.1 for Postfix, 2.2.36 for Dovecot.
      Whereas current setup uses 3.3.1 for Postifx, 2.3.8 for Dovecot.
  • SSL certificate problems?
  • Thunderbird config problems?

dovecot -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

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                    = 2
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
meta_directory                      = /etc/postfix
milter_default_action               = accept
milter_protocol                     = 2
mydestination                       = localhost
myorigin                            = localhost
newaliases_path                     = /usr/bin/newaliases.postfix
non_smtpd_milters                   = unix:/var/run/opendkim/opendkim.socket, 
                                      unix:/var/run/opendmarc/opendmarc.socket, 
                                      unix:/var/run/spamass-milter/spamass-milter.socket
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_loglevel                   = 2
smtp_tls_security_level             = may
smtp_use_tls                        = yes
smtpd_client_restrictions           = permit_mynetworks, permit_sasl_authenticated
smtpd_milters                       = unix:/var/run/opendkim/opendkim.socket, 
                                      unix:/var/run/opendmarc/opendmarc.socket, 
                                      unix:/var/run/spamass-milter/spamass-milter.socket
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_login_maps             = proxy:mysql:/etc/postfix/sql/virtual_domains_maps.cf
smtpd_sender_restrictions           = permit_mynetworks, reject_non_fqdn_sender, reject_unknown_sender_domain, permit
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                  = 2
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
unknown_local_recipient_reject_code = 550
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

maillog (after clicking "Get Messages" in Thunderbird

Jul 19 21:41:50 hwsrv-579344 dovecot[359560]: pop3-login: Debug: SSL: where=0x10, ret=1: before SSL initialization
Jul 19 21:41:50 hwsrv-579344 dovecot[359560]: pop3-login: Debug: SSL: where=0x2001, ret=1: before SSL initialization
Jul 19 21:41:50 hwsrv-579344 dovecot[359560]: pop3-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization
Jul 19 21:41:50 hwsrv-579344 dovecot[359560]: auth: Debug: auth client connected (pid=359812)
Jul 19 21:41:50 hwsrv-579344 dovecot[359560]: imap-login: Debug: SSL: where=0x10, ret=1: before SSL initialization
Jul 19 21:41:50 hwsrv-579344 dovecot[359560]: imap-login: Debug: SSL: where=0x2001, ret=1: before SSL initialization
Jul 19 21:41:50 hwsrv-579344 dovecot[359560]: imap-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization
Jul 19 21:41:50 hwsrv-579344 dovecot[359560]: auth: Debug: auth client connected (pid=359813)
Jul 19 21:42:25 hwsrv-579344 dovecot[359560]: pop3-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization
Jul 19 21:42:25 hwsrv-579344 dovecot[359560]: pop3-login: Debug: SSL error: Connection closed
Jul 19 21:42:25 hwsrv-579344 dovecot[359560]: pop3-login: Disconnected (no auth attempts in 35 secs): user=<>, rip=173.73.24.88, lip=142.11.253.50, TLS handshaking: Connection closed, session=<dBsQRNKqWS2tSRhY>
Jul 19 21:42:25 hwsrv-579344 dovecot[359560]: pop3-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization
Jul 19 21:42:25 hwsrv-579344 dovecot[359560]: pop3-login: Debug: SSL error: Connection closed
Jul 19 21:42:25 hwsrv-579344 dovecot[359560]: imap-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization
Jul 19 21:42:25 hwsrv-579344 dovecot[359560]: imap-login: Debug: SSL error: Connection closed
Jul 19 21:42:25 hwsrv-579344 dovecot[359560]: imap-login: Disconnected (no auth attempts in 35 secs): user=<>, rip=173.73.24.88, lip=142.11.253.50, TLS handshaking: Connection closed, session=<jkUWRNKqXC2tSRhY>
Jul 19 21:42:25 hwsrv-579344 dovecot[359560]: imap-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization
Jul 19 21:42:25 hwsrv-579344 dovecot[359560]: imap-login: Debug: SSL error: Connection closed
Jul 19 21:42:28 hwsrv-579344 dovecot[359560]: pop3-login: Debug: SSL: where=0x10, ret=1: before SSL initialization
Jul 19 21:42:28 hwsrv-579344 dovecot[359560]: pop3-login: Debug: SSL: where=0x2001, ret=1: before SSL initialization
Jul 19 21:42:28 hwsrv-579344 dovecot[359560]: pop3-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization
Jul 19 21:42:28 hwsrv-579344 dovecot[359560]: imap-login: Debug: SSL: where=0x10, ret=1: before SSL initialization
Jul 19 21:42:28 hwsrv-579344 dovecot[359560]: imap-login: Debug: SSL: where=0x2001, ret=1: before SSL initialization
Jul 19 21:42:28 hwsrv-579344 dovecot[359560]: imap-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization
Jul 19 21:42:28 hwsrv-579344 dovecot[359560]: auth: Debug: auth client connected (pid=359824)
Jul 19 21:42:28 hwsrv-579344 dovecot[359560]: auth: Debug: auth client connected (pid=359825)

maillog (after trying to send mail through Roundcube from foo@domain.com to bar@domain.com)

Jul 19 22:20:54 hwsrv-579344 postfix/submission/smtpd[360356]: disconnect from 12345.localhostname.com[111.222.222.222] ehlo=2 starttls=1 auth=1 mail=1 rcpt=1 data=0/1 rset=1 quit=1 commands=8/9
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: connect from 12345.localhostname.com[111.222.222.222]
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: warning: connect to Milter service unix:/var/run/spamass-milter/spamass-milter.socket: Permission denied
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: setting up TLS connection from 12345.localhostname.com[111.222.222.222]
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: 12345.localhostname.com[111.222.222.222]: TLS cipher list "aNULL:-aNULL:HIGH:MEDIUM:+RC4:@STRENGTH"
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: SSL_accept:before SSL initialization
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: SSL_accept:before SSL initialization
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: SSL_accept:SSLv3/TLS read client hello
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: SSL_accept:SSLv3/TLS write server hello
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: SSL_accept:SSLv3/TLS write change cipher spec
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: SSL_accept:TLSv1.3 write encrypted extensions
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: SSL_accept:SSLv3/TLS write certificate
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: SSL_accept:TLSv1.3 write server certificate verify
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: SSL_accept:SSLv3/TLS write finished
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: SSL_accept:TLSv1.3 early data
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: SSL_accept:TLSv1.3 early data
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: SSL_accept:SSLv3/TLS read finished
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: 12345.localhostname.com[111.222.222.222]: Issuing session ticket, key expiration: 1595199052
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: 12345.localhostname.com[111.222.222.222]: save session E3966DA0AAC8A87053F861169C752EF9248773F52ED7C23B345072D992E4D4A8&s=submission&l=269488191 to smtpd cache
Jul 19 22:21:36 hwsrv-579344 postfix/tlsmgr[360358]: put smtpd session id=E3966DA0AAC8A87053F861169C752EF9248773F52ED7C23B345072D992E4D4A8&s=submission&l=269488191 [data 136 bytes]
Jul 19 22:21:36 hwsrv-579344 postfix/tlsmgr[360358]: write smtpd TLS cache entry E3966DA0AAC8A87053F861169C752EF9248773F52ED7C23B345072D992E4D4A8&s=submission&l=269488191: time=1595197296 [data 136 bytes]
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: SSL_accept:SSLv3/TLS write session ticket
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: 12345.localhostname.com[111.222.222.222]: Issuing session ticket, key expiration: 1595199052
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: 12345.localhostname.com[111.222.222.222]: save session 21BE69B853D66629D76AF0565BAF12FD3D4EF1BBAC38F329D3EC61D53AF95953&s=submission&l=269488191 to smtpd cache
Jul 19 22:21:36 hwsrv-579344 postfix/tlsmgr[360358]: put smtpd session id=21BE69B853D66629D76AF0565BAF12FD3D4EF1BBAC38F329D3EC61D53AF95953&s=submission&l=269488191 [data 137 bytes]
Jul 19 22:21:36 hwsrv-579344 postfix/tlsmgr[360358]: write smtpd TLS cache entry 21BE69B853D66629D76AF0565BAF12FD3D4EF1BBAC38F329D3EC61D53AF95953&s=submission&l=269488191: time=1595197296 [data 137 bytes]
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: SSL_accept:SSLv3/TLS write session ticket
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: Anonymous TLS connection established from 12345.localhostname.com[111.222.222.222]: TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)
Jul 19 22:21:36 hwsrv-579344 dovecot[359560]: auth: Debug: client in: AUTH#0112#011LOGIN#011service=smtp#011nologin#011lip=111.222.222.222#011rip=111.222.222.222#011secured
Jul 19 22:21:36 hwsrv-579344 dovecot[359560]: auth: Debug: client passdb out: CONT#0112#011VXNlcm5hbWU6
Jul 19 22:21:36 hwsrv-579344 dovecot[359560]: auth: Debug: client in: CONT<hidden>
Jul 19 22:21:36 hwsrv-579344 dovecot[359560]: auth: Debug: client passdb out: CONT#0112#011UGFzc3dvcmQ6
Jul 19 22:21:36 hwsrv-579344 dovecot[359560]: auth: Debug: client in: CONT<hidden>
Jul 19 22:21:36 hwsrv-579344 dovecot[359560]: auth: Debug: sql(foo@domain.com,111.222.222.222): Performing passdb lookup
Jul 19 22:21:36 hwsrv-579344 dovecot[359560]: auth-worker(360335): Debug: conn unix:auth-worker (pid=359563,uid=0): auth-worker<8>: Handling PASSV request
Jul 19 22:21:36 hwsrv-579344 dovecot[359560]: auth-worker(360335): Debug: sql(foo@domain.com,111.222.222.222): Performing passdb lookup
Jul 19 22:21:36 hwsrv-579344 dovecot[359560]: auth-worker(360335): Debug: sql(foo@domain.com,111.222.222.222): query: SELECT username as user, password, '/var/www/mail/vmail/domain.com/foo' as userdb_home, 'maildir:/var/www/mail/vmail/domain.com/foo' as userdb_mail, 2000 as userdb_uid, 2000 as userdb_gid FROM mailbox WHERE username = 'foo@domain.com' AND active = '1'
Jul 19 22:21:36 hwsrv-579344 dovecot[359560]: auth-worker(360335): Debug: sql(foo@domain.com,111.222.222.222): Finished passdb lookup
Jul 19 22:21:36 hwsrv-579344 dovecot[359560]: auth-worker(360335): Debug: conn unix:auth-worker (pid=359563,uid=0): auth-worker<8>: Finished
Jul 19 22:21:36 hwsrv-579344 dovecot[359560]: auth: Debug: sql(foo@domain.com,111.222.222.222): Finished passdb lookup
Jul 19 22:21:36 hwsrv-579344 dovecot[359560]: auth: Debug: auth(foo@domain.com,111.222.222.222): Auth request finished
Jul 19 22:21:36 hwsrv-579344 dovecot[359560]: auth: Debug: client passdb out: OK#0112#011user=foo@domain.com
Jul 19 22:21:36 hwsrv-579344 postfix/submission/smtpd[360356]: 3A3D790001A4: client=12345.localhostname.com[111.222.222.222], sasl_method=LOGIN, sasl_username=foo@domain.com
Jul 19 22:21:36 hwsrv-579344 postfix/cleanup[360363]: 3A3D790001A4: message-id=<d464501c9c553acad309b6f6eb935fda@domain.com>
Jul 19 22:21:36 hwsrv-579344 opendkim[80314]: default._domainkey.domain.com: key data is not secure: /etc/opendkim/keys/domain.com/default is in group 0 which has multiple users (e.g. "sync")
Jul 19 22:21:36 hwsrv-579344 opendkim[80314]: 3A3D790001A4: error loading key 'default._domainkey.domain.com'
Jul 19 22:21:36 hwsrv-579344 postfix/cleanup[360363]: 3A3D790001A4: milter-reject: END-OF-MESSAGE from 12345.localhostname.com[111.222.222.222]: 4.7.1 Service unavailable - try again later; from=<FH@domain.com> to=<bar@domain.com> proto=ESMTP helo=<webmail.domain.com>

Thanks in advance for you help. I've been racking my brain trying to figure out the problem.

EDIT: Added Thunderbird log

2020-07-20 20:29:25.582000 UTC - [(null) 3344: Unnamed thread 1A1DF190]: D/IMAP ImapThreadMainLoop entering [this=1A155000]
2020-07-20 20:29:25.670000 UTC - [(null) 3344: Main Thread]: I/IMAP 1A155000:imap.domain.com:NA:SetupWithUrlCallback: clearing IMAP_CONNECTION_IS_OPEN
2020-07-20 20:29:25.670000 UTC - [(null) 3344: Unnamed thread 1A1DF190]: I/IMAP 1A155000:imap.domain.com:NA:ProcessCurrentURL: entering
2020-07-20 20:29:25.670000 UTC - [(null) 3344: Unnamed thread 1A1DF190]: I/IMAP 1A155000:imap.domain.com:NA:ProcessCurrentURL:imap://bar%40domain%2Ecom@imap.domain.com:993/select%3E/INBOX:  = currentUrl
2020-07-20 20:31:05.721000 UTC - [(null) 3344: Unnamed thread 1A1DF190]: D/IMAP ReadNextLine [stream=1A1E0060 nb=0 needmore=1]
2020-07-20 20:31:05.739000 UTC - [(null) 3344: Unnamed thread 1A1DF190]: I/IMAP 1A155000:imap.domain.com:NA:CreateNewLineFromSocket: clearing IMAP_CONNECTION_IS_OPEN - rv = 804b000e
2020-07-20 20:31:05.742000 UTC - [(null) 3344: Unnamed thread 1A1DF190]: I/IMAP 1A155000:imap.domain.com:NA:TellThreadToDie: close socket connection
2020-07-20 20:31:05.742000 UTC - [(null) 3344: Unnamed thread 1A1DF190]: I/IMAP 1A155000:imap.domain.com:NA:CreateNewLineFromSocket: (null)
2020-07-20 20:31:05.768000 UTC - [(null) 3344: Unnamed thread 1A1DF190]: I/IMAP 1A155000:imap.domain.com:NA:ProcessCurrentURL: aborting queued urls
2020-07-20 20:31:05.768000 UTC - [(null) 3344: Unnamed thread 1A1DF190]: D/IMAP ImapThreadMainLoop leaving [this=1A155000]
2020-07-20 20:36:24.186000 UTC - [(null) 3344: Unnamed thread 17C36190]: D/IMAP ImapThreadMainLoop entering [this=05026800]
2020-07-20 20:36:24.192000 UTC - [(null) 3344: Main Thread]: I/IMAP 05026800:imap.domain.com:NA:SetupWithUrlCallback: clearing IMAP_CONNECTION_IS_OPEN
2020-07-20 20:36:24.193000 UTC - [(null) 3344: Unnamed thread 17C36190]: I/IMAP 05026800:imap.domain.com:NA:ProcessCurrentURL: entering
2020-07-20 20:36:24.193000 UTC - [(null) 3344: Unnamed thread 17C36190]: I/IMAP 05026800:imap.domain.com:NA:ProcessCurrentURL:imap://bar%40domain%2Ecom@imap.domain.com:993/select%3E/INBOX:  = currentUrl
2020-07-20 20:38:04.230000 UTC - [(null) 3344: Unnamed thread 17C36190]: D/IMAP ReadNextLine [stream=1A1EADD0 nb=0 needmore=1]
2020-07-20 20:38:04.236000 UTC - [(null) 3344: Unnamed thread 17C36190]: I/IMAP 05026800:imap.domain.com:NA:CreateNewLineFromSocket: clearing IMAP_CONNECTION_IS_OPEN - rv = 804b000e
2020-07-20 20:38:04.236000 UTC - [(null) 3344: Unnamed thread 17C36190]: I/IMAP 05026800:imap.domain.com:NA:TellThreadToDie: close socket connection
2020-07-20 20:38:04.236000 UTC - [(null) 3344: Unnamed thread 17C36190]: I/IMAP 05026800:imap.domain.com:NA:CreateNewLineFromSocket: (null)
2020-07-20 20:38:04.252000 UTC - [(null) 3344: Unnamed thread 17C36190]: I/IMAP 05026800:imap.domain.com:NA:ProcessCurrentURL: aborting queued urls
2020-07-20 20:38:04.261000 UTC - [(null) 3344: Unnamed thread 17C36190]: D/IMAP ImapThreadMainLoop leaving [this=05026800]

Trending Tags