0

We have a web server which sends mail out via our Postfix relay over a LAN connection. Users from outside our network also send mail out via SMTP AUTH though that relay too.

However, we have a webmail application (Roundcube) on the web server that can't send mail out through the relay over the LAN on port 587. It's failing with some TLS error. Does anyone have any clues as where to start debugging this?

main.cf

smtpd_banner = $myhostname ESMTP $mail_name (Debian/GNU)
debug_peer_list = 10.10.10.102
biff = no
relay_domains = $mydestination
compatibility_level = 2
mail_owner = postfix
append_dot_mydomain = no
smtpd_sasl_type = dovecot
smtpd_sasl_path = private/auth
smtpd_sasl_local_domain =
smtpd_sasl_security_options = noanonymous
broken_sasl_auth_clients = yes
smtpd_sasl_auth_enable = yes
smtp_tls_security_level = may
smtpd_tls_security_level = may
smtp_tls_note_starttls_offer = yes
smtpd_tls_loglevel = 0
smtpd_tls_received_header = yes
smtp_tls_session_cache_database = btree:${data_directory}/smtp_scache
smtpd_tls_mandatory_ciphers = high
smtpd_tls_mandatory_exclude_ciphers = aNULL, DES, 3DES, MD5, DES+MD5, RC4
smtpd_tls_exclude_ciphers = aNULL, DES, 3DES, MD5, DES+MD5, RC4
smtpd_tls_protocols=!SSLv2,!SSLv3
smtpd_tls_mandatory_protocols=!SSLv2,!SSLv3
smtp_tls_protocols=!SSLv2,!SSLv3
smtp_tls_mandatory_protocols=!SSLv2,!SSLv3
smtpd_tls_key_file = /etc/letsencrypt/live/smtp.xxxx.xx.uk/privkey.pem
smtpd_tls_cert_file = /etc/letsencrypt/live/smtp.xxxx.xx.uk/fullchain.pem
myhostname = mx0.xxxx.xx.uk
alias_maps = hash:/etc/postfix/aliases
alias_database = hash:/etc/postfix/aliases
virtual_maps = hash:/etc/postfix/virtusertable
transport_maps = hash:/etc/postfix/transport
myorigin = $mydomain
mydestination = $myhostname, lorina.$mydomain, alice.$mydomain, localhost.$mydomain, localhost, lists.xxxx.xxxx.uk, /etc/postfix/hatters/localdomains
relayhost =
mynetworks = 127.0.0.1/32 185.x.x.x/32 10.10.10.0/24 [::1]/128 [2001:xxxx::3c]/128 [fe80::xxx:c90f]/128 [fe80::xxx:6181]/128
home_mailbox = Maildir/
message_size_limit = 262144000
mailbox_size_limit = 0
mailbox_command = procmail -a "$EXTENSION"
recipient_delimiter = +
owner_request_special = no
unknown_local_recipient_reject_code = 550
smtpd_client_restrictions =
    check_client_access hash:/etc/postfix/blacklist,
    permit_mynetworks
smtpd_sender_restrictions =
    check_client_access cidr:/etc/postfix/internal_clients_filter,
    permit_mynetworks,
    reject_unknown_sender_domain
smtpd_helo_required = yes
disable_vrfy_command = yes
smtpd_recipient_restrictions =
        permit_mynetworks,
        check_policy_service inet:127.0.0.1:10040,
        permit_sasl_authenticated,
        reject_invalid_helo_hostname,
        reject_unknown_recipient_domain,
        reject_non_fqdn_sender,
        reject_non_fqdn_recipient,
        reject_unknown_sender_domain,
        reject_unlisted_recipient,
        reject_unauth_destination,
        check_policy_service unix:private/senderCheck,
        permit_mx_backup,
        permit
smtpd_data_restrictions =
    reject_unauth_pipelining,
    permit

header_checks = regexp:/etc/postfix/header_checks
body_checks = regexp:/etc/postfix/body_checks
bounce_queue_lifetime = 0
smtpd_error_sleep_time = 1s
smtpd_soft_error_limit = 10
smtpd_hard_error_limit = 20
smtpd_client_connection_count_limit = 60
smtpd_client_connection_rate_limit = 200
smtp_destination_concurrency_limit = 2
smtp_destination_rate_delay = 1s
smtp_extra_recipient_limit = 10
milter_default_action = accept
milter_protocol = 6
smtpd_milters = inet:localhost:8891
non_smtpd_milters = inet:localhost:8891

The SMTP part of master.cf

smtp      inet  n       -       n       -       -       smtpd
  -o smtpd_sasl_auth_enable=no
  -o smtpd_discard_ehlo_keywords=silent-discard,dsn
submission inet n       -       n       -       -       smtpd
  -o syslog_name=postfix/submission
  -o smtpd_tls_security_level=encrypt
  -o smtpd_sasl_auth_enable=yes
  -o smtpd_tls_key_file=/etc/letsencrypt/live/smtp.xxxx.xx.uk/privkey.pem
  -o smtpd_tls_cert_file=/etc/letsencrypt/live/smtp.xxxx.xx.uk/fullchain.pem
  -o smtpd_relay_restrictions=permit_sasl_authenticated,reject
  -o milter_macro_daemon_name=ORIGINATING
smtps     inet  n       -       n       -       -       smtpd
  -o syslog_name=postfix/smtps
  -o smtpd_tls_wrappermode=yes
  -o smtpd_sasl_auth_enable=yes
  -o smtpd_tls_security_level=may
  -o smtpd_tls_key_file=/etc/letsencrypt/live/smtp.xxx.xxx.uk/privkey.pem
  -o smtpd_tls_cert_file=/etc/letsencrypt/live/smtp.xxx.xxx.uk/fullchain.pem
  -o smtpd_relay_restrictions=permit_sasl_authenticated,reject
  -o milter_macro_daemon_name=ORIGINATING

In the webmail logs, it says this:

    [05-Nov-2019 11:13:21 UTC] ERROR: STARTTLS failed ()
    [05-Nov-2019 11:13:21 UTC] ERROR: Invalid response code received from server (-1)
    [05-Nov-2019 11:13:21 UTC] ERROR: Failed to write to socket: unknown error ()
    [05-Nov-2019 11:13:21 +0000]: <h6hj0vtt> SMTP Error: Authentication failure: STARTTLS failed (Code: ) in /usr/share/roundcube/program/lib/Roundcube/rcube.php on line 1667 (POST /roundcube/?_task=mail&_unlock=loading1572952401252&_lang=undefined&_framed=1&_action=send)

On the Postfix side (with debugging on), it says this:

Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: connect from lan-host[10.10.10.102]
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: smtp_stream_setup: maxtime=300 enable_deadline=0
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: match_hostname: smtpd_client_event_limit_exceptions: lan-host ~? 127.0.0.1/32
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: match_hostaddr: smtpd_client_event_limit_exceptions: 10.10.10.102 ~? 127.0.0.1/32
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: match_hostname: smtpd_client_event_limit_exceptions: lan-host ~? 185.73.44.60/32
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: match_hostaddr: smtpd_client_event_limit_exceptions: 10.10.10.102 ~? 185.73.44.60/32
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: match_hostname: smtpd_client_event_limit_exceptions: lan-host ~? 10.10.10.0/24
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: match_hostaddr: smtpd_client_event_limit_exceptions: 10.10.10.102 ~? 10.10.10.0/24
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: report connect to all milters
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter_macro_lookup: "j"
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter_macro_lookup: result "mx0.xxxxx.org.uk"
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter_macro_lookup: "{daemon_name}"
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter_macro_lookup: result "ORIGINATING"
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter_macro_lookup: "v"
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter_macro_lookup: result "Postfix 3.1.0"
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter8_connect: non-protocol events for protocol version 6:
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter8_connect: transport=inet endpoint=localhost:8891
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: trying... [::1]
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: Connection refused
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: trying... [127.0.0.1]
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: vstream_tweak_tcp: TCP_MAXSEG 21845
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: fd=22: stream buffer size old=0 new=43690
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter8_connect: my_version=0x6
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter8_connect: my_actions=0x1ff SMFIF_ADDHDRS SMFIF_CHGBODY SMFIF_ADDRCPT SMFIF_DELRCPT SMFIF_CHGHDRS SMFIF_QUARANTINE SMFIF_CHGFROM SMFIF_ADDRCPT_PAR SMFIF_SETSYMLIST
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter8_connect: my_events=0x1fffff SMFIP_NOCONNECT SMFIP_NOHELO SMFIP_NOMAIL SMFIP_NORCPT SMFIP_NOBODY SMFIP_NOHDRS SMFIP_NOEOH SMFIP_NR_HDR SMFIP_NOUNKNOWN SMFIP_NODATA SMFIP_SKIP SMFIP_RCPT_REJ SMFIP_NR_CONN SMFIP_NR_HELO SMFIP_NR_MAIL SMFIP_NR_RCPT SMFIP_NR_DATA SMFIP_NR_UNKN SMFIP_NR_EOH SMFIP_NR_BODY SMFIP_HDR_LEADSPC
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter8_connect: milter inet:localhost:8891 version 6
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter8_connect: events SMFIP_NOHELO SMFIP_NOUNKNOWN SMFIP_NODATA SMFIP_SKIP SMFIP_HDR_LEADSPC
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter8_connect: requests SMFIF_ADDHDRS SMFIF_CHGHDRS SMFIF_SETSYMLIST
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter8_conn_event: milter inet:localhost:8891: connect lan-host/10.10.10.102
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: event: SMFIC_CONNECT; macros: {j}=mx0.xxxxx.org.uk {daemon_name}=ORIGINATING {v}=Postfix 3.1.0
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: reply: SMFIR_CONTINUE data 0 bytes
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: > lan-host[10.10.10.102]: 220 mx0.xxxxx.org.uk ESMTP Postfix (Debian/GNU)
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: watchdog_pat: 0x5565d5a3eca0
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: < lan-host[10.10.10.102]: EHLO www.xxxxx.org.uk
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: report helo to all milters
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter_macro_lookup: "{tls_version}"
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter_macro_lookup: "{cipher}"
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter_macro_lookup: "{cipher_bits}"
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter_macro_lookup: "{cert_subject}"
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter_macro_lookup: "{cert_issuer}"
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter8_helo_event: milter inet:localhost:8891: helo www.xxxxx.org.uk
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: event: SMFIC_HELO; macros: (none)
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: skipping event SMFIC_HELO for milter inet:localhost:8891
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: match_list_match: lan-host: no match
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: match_list_match: 10.10.10.102: no match
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: > lan-host[10.10.10.102]: 250-mx0.xxxxx.org.uk
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: > lan-host[10.10.10.102]: 250-PIPELINING
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: > lan-host[10.10.10.102]: 250-SIZE 262144000
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: > lan-host[10.10.10.102]: 250-ETRN
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: > lan-host[10.10.10.102]: 250-STARTTLS
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: > lan-host[10.10.10.102]: 250-ENHANCEDSTATUSCODES
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: > lan-host[10.10.10.102]: 250-8BITMIME
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: > lan-host[10.10.10.102]: 250-DSN
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: > lan-host[10.10.10.102]: 250 SMTPUTF8
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: watchdog_pat: 0x5565d5a3eca0
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: < lan-host[10.10.10.102]: STARTTLS
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: query milter states for other event
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter8_other_event: milter inet:localhost:8891
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: > lan-host[10.10.10.102]: 220 2.0.0 Ready to start TLS
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: abort all milters
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter8_abort: abort milter inet:localhost:8891
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: send attr request = seed
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: send attr size = 32
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: private/tlsmgr: wanted attribute: status
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: input attribute name: status
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: input attribute value: 0
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: private/tlsmgr: wanted attribute: seed
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: input attribute name: seed
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: input attribute value: olrmf0HDZWe9eEMY4alXsy2Cg/Np2qUD3JOAnPfejf0=
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: private/tlsmgr: wanted attribute: (list terminator)
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: input attribute name: (end)
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: send attr request = tktkey
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: send attr keyname = [data 0 bytes]
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: private/tlsmgr: wanted attribute: status
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: input attribute name: status
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: input attribute value: 0
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: private/tlsmgr: wanted attribute: keybuf
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: input attribute name: keybuf
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: input attribute value: 0KfXUorb0BaA3xpE3ACqMX4PjMBEX3Dmal1Uz0sVl1ODyCLQTdBwVTf3u8DbqnwRIxttyY9Di/TXl9Ph45lpnqxkIObdN3JOMJAAGrjtrg2TPMFdAAAAAA==
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: private/tlsmgr: wanted attribute: (list terminator)
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: input attribute name: (end)
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: xsasl_dovecot_server_create: SASL service=smtp, realm=(null)
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: name_mask: noanonymous
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: xsasl_dovecot_server_connect: Connecting
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: xsasl_dovecot_server_connect: auth reply: VERSION?1?1
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: xsasl_dovecot_server_connect: auth reply: MECH?PLAIN?plaintext
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: name_mask: plaintext
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: xsasl_dovecot_server_connect: auth reply: MECH?LOGIN?plaintext
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: name_mask: plaintext
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: xsasl_dovecot_server_connect: auth reply: SPID?12321
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: xsasl_dovecot_server_connect: auth reply: CUID?378
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: xsasl_dovecot_server_connect: auth reply: COOKIE?78955ca7ca16619ba44cdfbbce08a84d
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: xsasl_dovecot_server_connect: auth reply: DONE
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: xsasl_dovecot_server_mech_filter: keep mechanism: PLAIN
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: xsasl_dovecot_server_mech_filter: keep mechanism: LOGIN
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: watchdog_pat: 0x5565d5a3eca0
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: smtp_get: EOF
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: match_hostname: smtpd_client_event_limit_exceptions: lan-host ~? 127.0.0.1/32
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: match_hostaddr: smtpd_client_event_limit_exceptions: 10.10.10.102 ~? 127.0.0.1/32
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: match_hostname: smtpd_client_event_limit_exceptions: lan-host ~? 185.73.44.60/32
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: match_hostaddr: smtpd_client_event_limit_exceptions: 10.10.10.102 ~? 185.73.44.60/32
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: match_hostname: smtpd_client_event_limit_exceptions: lan-host ~? 10.10.10.0/24
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: match_hostaddr: smtpd_client_event_limit_exceptions: 10.10.10.102 ~? 10.10.10.0/24
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: lost connection after STARTTLS from lan-host[10.10.10.102]
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: disconnect event to all milters
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: milter8_disc_event: quit milter inet:localhost:8891
Nov  5 08:40:44 lorina postfix/submission/smtpd[17200]: disconnect from lan-host[10.10.10.102] ehlo=1 starttls=1 commands=2
1

This was caused by a change to the Postfix config that made SASL users untrusted on the local network unless they belonged to a specific group.

The clue was in putting the following lines in Roundcube's config.inc.php:

$config['smtp_conn_options'] = array(
   'ssl' => array(
   'verify_peer' => false,
   'verify_peer_name' => false,
  ),
);

This then allowed the correct SASL connection to the mail server, but triggered an authentication error which we traced to the recently implemented zero trust configuration on the server.

Boomshanka.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.