Início / server / Perguntas / 990716
Accepted
TommyPeanuts
Asked: 2019-11-06 12:07:34 +0800 CST

Como depurar "conexão perdida após STARTTLS"?

  • 772

Temos um servidor web que envia e-mails através do nosso relé Postfix através de uma conexão LAN. Os usuários de fora da nossa rede também enviam e-mails via SMTP AUTH por meio desse retransmissor também.

No entanto, temos um aplicativo de webmail (Roundcube) no servidor web que não pode enviar e-mails através do relé pela LAN na porta 587. Está falhando com algum erro de TLS. Alguém tem alguma pista de onde começar a depurar isso?

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

A parte SMTP do 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

Nos logs do webmail, diz o seguinte:

    [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)

No lado do Postfix (com depuração ativada), ele diz o seguinte:

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
php

1 respostas

  1. Best Answer

    Isso foi causado por uma alteração na configuração do Postfix que tornou os usuários SASL não confiáveis ​​na rede local, a menos que pertencessem a um grupo específico.

    A pista estava em colocar as seguintes linhas no Roundcube's config.inc.php:

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

    Isso permitiu a conexão SASL correta com o servidor de e-mail, mas acionou um erro de autenticação que rastreamos à configuração de confiança zero implementada recentemente no servidor.

    Boomshanka.

    • 1

relate perguntas