Re: [exim] 4.95 RC0 - gnutls outgoing TLS cert verification …

Αρχική Σελίδα
Delete this message
Reply to this message
Συντάκτης: Andreas Metzler
Ημερομηνία:  
Προς: exim-users
Αντικείμενο: Re: [exim] 4.95 RC0 - gnutls outgoing TLS cert verification broken
On 2021-07-18 Jeremy Harris via Exim-users <exim-users@???> wrote:
> On 18/07/2021 14:09, Andreas Metzler via Exim-users wrote:
>> there seems to be some breakage in 4.95 RC0 with outgoing TLS, it fails
>> to verify the peer certificate:


> Since we're happily running the test-suite this must be either an
> environment difference or a build problem.


> Did you give both client and server debug output there?


Hello,

No, it is only the (breaking) client.

> It wasn't annotated... Part of it says "close on process exit"
> right after a TLS handshake starts up, and I don't see any
> reason given.


> Could you manage to get "all" debug output all the way from
> daemon startup? I'm hoping we'll see the PIDs, as well as
> the credentials cache load. And also "all" debug for the
> client?


I temporarily switched local exim (4.95) to queueonly mode and injected
a message. I changed the target remote port for the respective
transport to 587 and started a debugging server remote (4.94.2) -oX on
this port. Then I ran exim4 -d+all -M <Message-id> on the client-side.

I am attaching both server and client logs. (Timezones are different,
UTC vs. CEST).

cu Andreas
--
`What a good friend you are to him, Dr. Maturin. His other friends are
so grateful to you.'
`I sew his ears on from time to time, sure'
14:27:32 21827 Exim version 4.94.2 uid=0 gid=0 pid=21827 D=fff9ffff
Support for: crypteq iconv() IPv6 PAM Perl Expand_dlfunc GnuTLS move_frozen_messages Content_Scanning DANE DKIM DNSSEC Event I18N OCSP PIPE_CONNECT PRDR PROXY SOCKS TCP_Fast_Open
Lookups (built-in): lsearch wildlsearch nwildlsearch iplsearch cdb dbm dbmjz dbmnz dnsdb dsearch ldap ldapdn ldapm mysql nis nis0 passwd pgsql sqlite
Authenticators: cram_md5 cyrus_sasl dovecot plaintext spa tls
Routers: accept dnslookup ipliteral iplookup manualroute queryprogram redirect
Transports: appendfile/maildir/mailstore/mbx autoreply lmtp pipe smtp
Malware: f-protd f-prot6d drweb fsecure sophie clamd avast sock cmdline
Fixed never_users: 0
Configure owner: 0:0
Size of off_t: 8
Compiler: GCC [8.3.0]
Library version: Glibc: Compile: 2.28
                        Runtime: 2.28
Library version: BDB: Compile: Berkeley DB 5.3.28: (September  9, 2013)
                      Runtime: Berkeley DB 5.3.28: (September  9, 2013)
Library version: GnuTLS: Compile: 3.6.7
                         Runtime: 3.6.7
Library version: IDN2: Compile: 2.0.5
                       Runtime: 2.0.5
Library version: Stringprep: Compile: 1.33
                             Runtime: 1.33
Library version: Cyrus SASL: Compile: 2.1.27
                             Runtime: 2.1.27 [Cyrus SASL]
Library version: PCRE: Compile: 8.39
                       Runtime: 8.39 2016-06-14
14:27:32 21827 Total 20 lookups
Library version: MySQL: Compile: 100329 10.3.29 [mariadb-10.3]
                        Runtime: 100329 10.3.29
Library version: SQLite: Compile: 3.27.2
                         Runtime: 3.27.2
WHITELIST_D_MACROS: "OUTGOING"
TRUSTED_CONFIG_LIST: "/etc/exim4/trusted_configs"
14:27:32 21827 changed uid/gid: forcing real = effective
14:27:32 21827   uid=0 gid=0 pid=21827
14:27:32 21827   auxiliary group list: <none>
14:27:32 21827 seeking password data for user "uucp": cache not available
14:27:32 21827 getpwnam() succeeded uid=10 gid=10
14:27:32 21827 configuration file is /var/lib/exim4/config.autogenerated
14:27:32 21827 log selectors = 0000cffc 19005022 0000000f
14:27:32 21827 cwd=/root 5 args: exim4 -bd -d+all -oX 587
14:27:32 21827 trusted user
14:27:32 21827 admin user
14:27:32 21827 dropping to exim gid; retaining priv uid
14:27:32 21827 seeking password data for user "mail": cache not available
14:27:32 21827 getpwnam() succeeded uid=8 gid=8
14:27:32 21827  ╭considering: $1
14:27:32 21827  ├──expanding: $1
14:27:32 21827  ╰─────result: root
14:27:32 21827 user name "root" extracted from gecos field "root"
14:27:32 21827 originator: uid=0 gid=0 login=root name=root
14:27:32 21827 fresh-exec forking for cipher-validate
14:27:32 21827 fresh-exec forked for cipher-validate: 21829
14:27:32 21829 postfork: cipher-validate
14:27:32 21829 changed uid/gid: calling tls_validate_require_cipher
14:27:32 21829   uid=108 gid=111 pid=21829
14:27:32 21829   auxiliary group list: <none>
14:27:32 21829 >>>>>>>>>>>>>>>> Exim pid=21829 (cipher-validate) terminating with rc=0 >>>>>>>>>>>>>>>>
14:27:32 21827 tls_validate_require_cipher child 21829 ended: status=0x0
14:27:32 21827 daemon_smtp_port overridden by -oX:
14:27:32 21827   <: 587
14:27:32 21827 -oX used without -oP so not creating notifier socket
14:27:32 21827 listening on all interfaces (IPv6) port 587
14:27:32 21827 listening on all interfaces (IPv4) port 587
14:27:32 21827 changed uid/gid: running as a daemon
14:27:32 21827   uid=108 gid=111 pid=21827
14:27:32 21827   auxiliary group list: 111
14:27:32 21827 LOG: MAIN
14:27:32 21827   exim 4.94.2 daemon started: pid=21827, no queue runs, listening for SMTP on port 587 (IPv6 and IPv4)
14:27:32 21827 set_process_info: 21827 daemon(4.94.2): no queue runs, listening for SMTP on port 587 (IPv6 and IPv4)
14:27:32 21827 daemon running with uid=108 gid=111 euid=108 egid=111
14:27:32 21827 Listening...
14:28:34 21827 Connection request from 178.190.17.1 port 51640
14:28:34 21827 interface address=31.15.64.248 port=587
14:28:34 21827 search_tidyup called
14:28:34 21827 daemon forking for daemon-accept
14:28:34 21827 daemon forked for daemon-accept: 21831
14:28:34 21827 1 SMTP accept process running
14:28:34 21827 Listening...
14:28:34 21831 postfork: daemon-accept
14:28:34 21831 sender_fullhost = [178.190.17.1]
14:28:34 21831 sender_rcvhost = [178.190.17.1]
14:28:34 21831 Process 21831 is handling incoming connection from [178.190.17.1]
14:28:34 21831 host in host_lookup? yes (matched "*")
14:28:34 21831 looking up host name for 178.190.17.1
14:28:34 21831 Coerced resolver DNSSEC support on.
14:28:34 21831 DNS lookup of 1.17.190.178.in-addr.arpa (PTR) succeeded
14:28:34 21831 Reverse DNS security status: unverified
14:28:34 21831 IP address lookup yielded "178-190-17-1.adsl.highway.telekom.at"
14:28:34 21831 Coerced resolver DNSSEC support on.
14:28:34 21831 178-190-17-1.adsl.highway.telekom.at in dns_ipv4_lookup? yes (matched "*")
14:28:34 21831 DNS lookup of 178-190-17-1.adsl.highway.telekom.at (A) succeeded
14:28:34 21831 Actual local interface address is 127.0.0.1 (lo)
14:28:34 21831 Actual local interface address is 31.15.64.248 (eth0)
14:28:34 21831 Actual local interface address is ::1 (lo)
14:28:34 21831 Actual local interface address is fe80::216:3eff:fe00:5737 (eth0)
14:28:34 21831 178-190-17-1.adsl.highway.telekom.at 178.190.17.1 mx=-1 sort=-21 
14:28:34 21831 Coerced resolver DNSSEC support on.
14:28:34 21831 checking addresses for 178-190-17-1.adsl.highway.telekom.at
14:28:34 21831 Forward DNS security status: unverified
14:28:34 21831   178.190.17.1 OK
14:28:34 21831 sender_fullhost = 178-190-17-1.adsl.highway.telekom.at [178.190.17.1]
14:28:34 21831 sender_rcvhost = 178-190-17-1.adsl.highway.telekom.at ([178.190.17.1])
14:28:34 21831 set_process_info: 21831 handling incoming connection from 178-190-17-1.adsl.highway.telekom.at [178.190.17.1]
14:28:34 21831 host in host_reject_connection? no (option unset)
14:28:34 21831 host in sender_unqualified_hosts? no (option unset)
14:28:34 21831 host in recipient_unqualified_hosts? no (option unset)
14:28:34 21831 host in helo_verify_hosts? no (option unset)
14:28:34 21831 host in helo_try_verify_hosts? no (option unset)
14:28:34 21831 host in helo_accept_junk_hosts? no (option unset)
14:28:34 21831 host in hosts_proxy? no (option unset)
14:28:34 21831 using ACL "acl_local_connect"
14:28:34 21831 processing "deny" (/var/lib/exim4/config.autogenerated 553)
14:28:34 21831   message: AM sender IP $sender_host_address is locally blacklisted here.
14:28:34 21831 check hosts = ${if exists{/etc/exim4/am_local_connection_reject}{/etc/exim4/am_local_connection_reject}{}}
14:28:34 21831  ╭considering: ${if exists{/etc/exim4/am_local_connection_reject}{/etc/exim4/am_local_connection_reject}{}}
14:28:34 21831   ╭considering: /etc/exim4/am_local_connection_reject}{/etc/exim4/am_local_connection_reject}{}}
14:28:34 21831   ├──expanding: /etc/exim4/am_local_connection_reject
14:28:34 21831   ╰─────result: /etc/exim4/am_local_connection_reject
14:28:34 21831  ├──condition: exists{/etc/exim4/am_local_connection_reject}
14:28:34 21831  ├─────result: true
14:28:34 21831   ╭considering: /etc/exim4/am_local_connection_reject}{}}
14:28:34 21831   ├──expanding: /etc/exim4/am_local_connection_reject
14:28:34 21831   ╰─────result: /etc/exim4/am_local_connection_reject
14:28:34 21831   ╭───scanning: }}
14:28:34 21831   ├──expanding: 
14:28:34 21831   ├─────result: 
14:28:34 21831   ╰───skipping: result is not used
14:28:34 21831  ├──expanding: ${if exists{/etc/exim4/am_local_connection_reject}{/etc/exim4/am_local_connection_reject}{}}
14:28:34 21831  ╰─────result: /etc/exim4/am_local_connection_reject
14:28:34 21831 host in "/etc/exim4/am_local_connection_reject"? no (end of list)
14:28:34 21831 deny: condition test failed in ACL "acl_local_connect"
14:28:34 21831 processing "accept" (/var/lib/exim4/config.autogenerated 559)
14:28:34 21831 accept: condition test succeeded in ACL "acl_local_connect"
14:28:34 21831 end of ACL "acl_local_connect": ACCEPT
14:28:34 21831  ╭considering: $smtp_active_hostname ESMTP Exim $version_number $tod_full
14:28:34 21831  ├──expanding: $smtp_active_hostname ESMTP Exim $version_number $tod_full
14:28:34 21831  ╰─────result: vsrv21575.customer.vlinux.de ESMTP Exim 4.94.2 Sun, 18 Jul 2021 14:28:34 +0000
14:28:34 21831 host in pipelining_connect_advertise_hosts? yes (matched "*")
14:28:34 21831 SMTP>> 220 vsrv21575.customer.vlinux.de ESMTP Exim 4.94.2 Sun, 18 Jul 2021 14:28:34 +0000
14:28:34 21831 TCP_INFO getsockopt: Success
14:28:34 21831 Process 21831 is ready for new message
14:28:34 21831 smtp_setup_msg entered
14:28:34 21831 SMTP<< EHLO argenau.bebt.de
14:28:34 21831 sender_fullhost = 178-190-17-1.adsl.highway.telekom.at (argenau.bebt.de) [178.190.17.1]
14:28:34 21831 sender_rcvhost = 178-190-17-1.adsl.highway.telekom.at ([178.190.17.1] helo=argenau.bebt.de)
14:28:34 21831 set_process_info: 21831 handling incoming connection from 178-190-17-1.adsl.highway.telekom.at (argenau.bebt.de) [178.190.17.1]
14:28:34 21831 host in dsn_advertise_hosts? no (option unset)
14:28:34 21831 host in pipelining_advertise_hosts? yes (matched "*")
14:28:34 21831 host in auth_advertise_hosts? yes (matched "*")
14:28:34 21831 Evaluating advertise_condition for cram_md5_server CRAM-MD5 athenticator
14:28:34 21831 host in chunking_advertise_hosts? yes (matched "*")
14:28:34 21831 host in tls_advertise_hosts? yes (matched "*")
14:28:34 21831 host in smtputf8_advertise_hosts? no (end of list)
14:28:34 21831 SMTP>> 250-vsrv21575.customer.vlinux.de Hello 178-190-17-1.adsl.highway.telekom.at [178.190.17.1]
14:28:34 21831 250-SIZE 52428800
14:28:34 21831 250-8BITMIME
14:28:34 21831 250-PIPELINING
14:28:34 21831 250-PIPE_CONNECT
14:28:34 21831 250-AUTH CRAM-MD5
14:28:34 21831 250-CHUNKING
14:28:34 21831 250-STARTTLS
14:28:34 21831 250-PRDR
14:28:34 21831 250 HELP
14:28:35 21831 SMTP<< STARTTLS
14:28:35 21831 initialising GnuTLS as a server
14:28:35 21831 GnuTLS global init required.
14:28:35 21831 initialising GnuTLS server session
14:28:35 21831 Expanding various TLS configuration options for session credentials.
14:28:35 21831 certificate file = /etc/exim4/exim.crt : /etc/exim4/exim_rsa.cert
14:28:35 21831 key file = /etc/exim4/exim.key : /etc/exim4/exim_rsa.key
14:28:35 21831 GnuTLS<3>: ASSERT: ../../../lib/x509/x509_ext.c[gnutls_subject_alt_names_get]:110
14:28:35 21831 GnuTLS<3>: ASSERT: ../../../lib/x509/x509.c[get_alt_name]:1816
14:28:35 21831 GnuTLS<3>: ASSERT: ../../../lib/nettle/pk.c[_wrap_nettle_pk_sign]:782
14:28:35 21831 GnuTLS<2>: Security level of algorithm requires hash SHA384(48) or better
14:28:35 21831 GnuTLS<3>: ASSERT: ../../../lib/nettle/mpi.c[wrap_nettle_mpi_print]:60
14:28:35 21831 GnuTLS<3>: ASSERT: ../../../lib/nettle/mpi.c[wrap_nettle_mpi_print]:60
14:28:35 21831 TLS: cert/key 0 /etc/exim4/exim.crt registered
14:28:35 21831 GnuTLS<3>: ASSERT: ../../../lib/x509/x509_ext.c[gnutls_subject_alt_names_get]:110
14:28:35 21831 GnuTLS<3>: ASSERT: ../../../lib/x509/x509.c[get_alt_name]:1816
14:28:35 21831 GnuTLS<3>: ASSERT: ../../../lib/nettle/mpi.c[wrap_nettle_mpi_print]:60
14:28:35 21831 TLS: cert/key 1 /etc/exim4/exim_rsa.cert registered
14:28:35 21831  ╭considering: ${if exists{/etc/ssl/certs/ca-certificates.crt}{/etc/ssl/certs/ca-certificates.crt}{/dev/null}}
14:28:35 21831   ╭considering: /etc/ssl/certs/ca-certificates.crt}{/etc/ssl/certs/ca-certificates.crt}{/dev/null}}
14:28:35 21831   ├──expanding: /etc/ssl/certs/ca-certificates.crt
14:28:35 21831   ╰─────result: /etc/ssl/certs/ca-certificates.crt
14:28:35 21831  ├──condition: exists{/etc/ssl/certs/ca-certificates.crt}
14:28:35 21831  ├─────result: true
14:28:35 21831   ╭considering: /etc/ssl/certs/ca-certificates.crt}{/dev/null}}
14:28:35 21831   ├──expanding: /etc/ssl/certs/ca-certificates.crt
14:28:35 21831   ╰─────result: /etc/ssl/certs/ca-certificates.crt
14:28:35 21831   ╭───scanning: /dev/null}}
14:28:35 21831   ├──expanding: /dev/null
14:28:35 21831   ├─────result: /dev/null
14:28:35 21831   ╰───skipping: result is not used
14:28:35 21831  ├──expanding: ${if exists{/etc/ssl/certs/ca-certificates.crt}{/etc/ssl/certs/ca-certificates.crt}{/dev/null}}
14:28:35 21831  ╰─────result: /etc/ssl/certs/ca-certificates.crt
14:28:35 21831 verify certificates = /etc/ssl/certs/ca-certificates.crt size=213920
14:28:35 21831 GnuTLS<3>: ASSERT: ../../../lib/x509/common.c[_gnutls_x509_get_raw_field2]:1575
14:28:35 21831 GnuTLS<3>: ASSERT: ../../../lib/x509/x509.c[gnutls_x509_crt_get_subject_unique_id]:3902
14:28:35 21831 GnuTLS<3>: ASSERT: ../../../lib/x509/x509.c[gnutls_x509_crt_get_issuer_unique_id]:3952
14:28:35 21831 GnuTLS<3>: ASSERT: ../../../lib/x509/dn.c[_gnutls_x509_compare_raw_dn]:990
14:28:35 21831 GnuTLS<3>: ASSERT: ../../../lib/x509/dn.c[_gnutls_x509_compare_raw_dn]:990
14:28:35 21831 GnuTLS<3>: ASSERT: ../../../lib/x509/dn.c[_gnutls_x509_compare_raw_dn]:990
14:28:35 21831 GnuTLS<3>: ASSERT: ../../../lib/x509/dn.c[_gnutls_x509_compare_raw_dn]:990
14:28:35 21831 Added 137 certificate authorities.
14:28:35 21831 GnuTLS using default session cipher/priority "NORMAL"
14:28:35 21831 GnuTLS<2>: added 6 protocols, 29 ciphersuites, 18 sig algos and 9 groups into priority list
14:28:35 21831 host in tls_verify_hosts? no (option unset)
14:28:35 21831 host in tls_try_verify_hosts? no (option unset)
14:28:35 21831 TLS: a client certificate will not be requested.
14:28:35 21831 SMTP>> 220 TLS go ahead
14:28:35 21831 GnuTLS<3>: ASSERT: ../../lib/buffers.c[get_last_packet]:1171
14:28:35 21831 GnuTLS<3>: ASSERT: ../../../lib/ext/server_name.c[gnutls_server_name_get]:240
14:28:35 21831 TLS: no SNI presented in handshake.
14:28:35 21831 GnuTLS<3>: ASSERT: ../../../lib/ext/psk_ke_modes.c[psk_ke_modes_recv_params]:136
14:28:35 21831 GnuTLS<2>: checking 13.02 (GNUTLS_AES_256_GCM_SHA384) for compatibility
14:28:35 21831 GnuTLS<3>: ASSERT: ../../../lib/ext/server_name.c[gnutls_server_name_get]:240
14:28:35 21831 GnuTLS<1>: The hash size used in signature (32) is less than the expected (48)
14:28:35 21831 GnuTLS<3>: ASSERT: ../../lib/pubkey.c[pubkey_supports_sig]:1905
14:28:35 21831 GnuTLS<2>: Selected (EC/ECDSA) cert based on ciphersuite 13.2: GNUTLS_AES_256_GCM_SHA384
14:28:35 21831 GnuTLS<2>: EXT[0x5574930ab530]: server generated SECP256R1 shared key
14:28:35 21831 GnuTLS<1>: The hash size used in signature (32) is less than the expected (48)
14:28:35 21831 GnuTLS<3>: ASSERT: ../../lib/pubkey.c[pubkey_supports_sig]:1905
14:28:35 21831 GnuTLS<3>: ASSERT: ../../../lib/nettle/mpi.c[wrap_nettle_mpi_print]:60
14:28:35 21831 GnuTLS<3>: ASSERT: ../../../lib/nettle/mpi.c[wrap_nettle_mpi_print]:60
14:28:35 21831 GnuTLS<3>: ASSERT: ../../lib/constate.c[_gnutls_epoch_get]:923
14:28:35 21831 GnuTLS<3>: ASSERT: ../../lib/tls13/session_ticket.c[_gnutls13_send_session_ticket]:284
14:28:35 21831 GnuTLS<3>: ASSERT: ../../lib/buffers.c[get_last_packet]:1171
14:28:35 21831 (TLS1.3)-(ECDHE-SECP256R1)-(ECDSA-SECP384R1-SHA384)-(AES-256-GCM)
14:28:35 21831 To get keying info for TLS1.3 is hard:
14:28:35 21831  Set environment variable SSLKEYLOGFILE to a filename relative to the spool directory,
14:28:35 21831  and make sure it is writable by the Exim runtime user.
14:28:35 21831  Add SSLKEYLOGFILE to keep_environment in the exim config.
14:28:35 21831  Start Exim as root.
14:28:35 21831  If using sudo, add SSLKEYLOGFILE to env_keep in /etc/sudoers
14:28:35 21831  (works for TLS1.2 also, and saves cut-paste into file).
14:28:35 21831  Trying to use add_environment for this will not work
14:28:35 21831 TLS: checking peer certificate
14:28:35 21831 TLS: no certificate from peer ((nil) & 0)
14:28:35 21831 cipher: TLS1.3:ECDHE_SECP256R1__ECDSA_SECP384R1_SHA384__AES_256_GCM:256
14:28:35 21831 Have channel bindings cached for possible auth usage
14:28:35 21831 sender_fullhost = 178-190-17-1.adsl.highway.telekom.at [178.190.17.1]
14:28:35 21831 sender_rcvhost = 178-190-17-1.adsl.highway.telekom.at ([178.190.17.1])
14:28:35 21831 set_process_info: 21831 handling incoming TLS connection from 178-190-17-1.adsl.highway.telekom.at [178.190.17.1]
14:28:35 21831 TLS active
14:28:35 21831 Calling gnutls_record_recv(session=0x5574930ab530, buffer=0x5574933b8170, buffersize=4096)
14:28:35 21831 GnuTLS<3>: ASSERT: ../../lib/record.c[record_add_to_buffers]:878
14:28:35 21831 GnuTLS<3>: ASSERT: ../../lib/record.c[record_add_to_buffers]:885
14:28:35 21831 GnuTLS<3>: ASSERT: ../../lib/record.c[_gnutls_recv_in_buffers]:1577
14:28:35 21831 GnuTLS<3>: ASSERT: ../../lib/record.c[_gnutls_recv_int]:1775
14:28:35 21831 tls_refill: err from gnutls_record_recv
14:28:35 21831 LOG: MAIN
14:28:35 21831   TLS error on connection from 178-190-17-1.adsl.highway.telekom.at [178.190.17.1] (recv): A TLS fatal alert has been received: Certificate is bad
14:28:35 21831 SMTP>> 421 vsrv21575.customer.vlinux.de lost input connection
14:28:35 21831 LOG: smtp_connection MAIN
14:28:35 21831   SMTP connection from 178-190-17-1.adsl.highway.telekom.at [178.190.17.1] lost D=0s
14:28:35 21831 search_tidyup called
14:28:35 21831 SMTP>>(close on process exit)
14:28:35 21831 >>>>>>>>>>>>>>>> Exim pid=21831 (daemon-accept) terminating with rc=1 >>>>>>>>>>>>>>>>
14:28:35 21827 child 21831 ended: status=0x100
14:28:35 21827   normal exit, 1
14:28:35 21827 0 SMTP accept processes now running
14:28:35 21827 Listening...

16:28:34 134337 Exim version 4.95-RC0 uid=0 gid=0 pid=134337 D=fff9ffff
Support for: crypteq iconv() IPv6 GnuTLS TLS_resume move_frozen_messages DANE DKIM DNSSEC Event I18N OCSP PIPE_CONNECT PRDR Experimental_Queue_Ramp SOCKS SRS TCP_Fast_Open
Lookups (built-in): lsearch wildlsearch nwildlsearch iplsearch cdb dbm dbmjz dbmnz dnsdb dsearch nis nis0 passwd
Authenticators: cram_md5 plaintext
Routers: accept dnslookup ipliteral manualroute queryprogram redirect
Transports: appendfile/maildir/mailstore autoreply lmtp pipe smtp
Fixed never_users: 0
Configure owner: 0:0
Size of off_t: 8
Compiler: GCC [10.2.1 20210110]
Library version: Glibc: Compile: 2.31
                        Runtime: 2.31
Library version: BDB: Compile: Berkeley DB 5.3.28: (September  9, 2013)
                      Runtime: Berkeley DB 5.3.28: (September  9, 2013)
Library version: GnuTLS: Compile: 3.7.1
                         Runtime: 3.7.1
Library version: IDN2: Compile: 2.3.0
                       Runtime: 2.3.0
Library version: Stringprep: Compile: 1.33
                             Runtime: 1.33
Library version: PCRE: Compile: 8.39
                       Runtime: 8.39 2016-06-14
16:28:34 134337 Total 14 lookups
WHITELIST_D_MACROS: "OUTGOING"
TRUSTED_CONFIG_LIST: "/etc/exim4/trusted_configs"
16:28:34 134337 changed uid/gid: forcing real = effective
16:28:34 134337   uid=0 gid=0 pid=134337
16:28:34 134337   auxiliary group list: <none>
16:28:34 134337 seeking password data for user "uucp": cache not available
16:28:34 134337 getpwnam() succeeded uid=10 gid=10
16:28:34 134337 configuration file is /var/lib/exim4/config.autogenerated
16:28:34 134337 log selectors = 0000cffc 64205022 0000003c
16:28:34 134337 cwd=/dev/shm/EXIM4 4 args: exim4 -d+all -M 1m57j9-000Yw2-Ms
16:28:34 134337 trusted user
16:28:34 134337 admin user
16:28:34 134337 dropping to exim gid; retaining priv uid
16:28:34 134337 seeking password data for user "mail": cache not available
16:28:34 134337 getpwnam() succeeded uid=8 gid=8
16:28:34 134337 set_process_info: 134337 delivering specified messages
16:28:34 134337 set_process_info: 134337 delivering 1m57j9-000Yw2-Ms
16:28:34 134337 Trying spool file /var/spool/exim4//input//1m57j9-000Yw2-Ms-D
16:28:34 134337 reading spool file 1m57j9-000Yw2-Ms-H
16:28:34 134337 user=Debian-exim uid=109 gid=117 sender=ametzler@???
16:28:34 134337 sender_fullhost = localhost (argenau.bebt.de) [::1]
16:28:34 134337 sender_rcvhost = localhost ([::1] helo=argenau.bebt.de)
16:28:34 134337 sender_local=0 ident=unset
16:28:34 134337 Non-recipients:
16:28:34 134337  Empty Tree
16:28:34 134337 ---- End of tree ----
16:28:34 134337 recipients_count=1
16:28:34 134337 **** SPOOL_IN - No additional fields
16:28:34 134337 body_linecount=3 message_linecount=12
16:28:34 134337 DSN: set orcpt:   flags: 0x0
16:28:34 134337 Delivery address list:
16:28:34 134337   ametzler@??? 
16:28:34 134337  locking /var/spool/exim4/db/retry.lockfile
16:28:34 134337  locked  /var/spool/exim4/db/retry.lockfile
16:28:34 134337  EXIM_DBOPEN: file </var/spool/exim4/db/retry> dir </var/spool/exim4/db> flags=O_RDONLY
16:28:34 134337  returned from EXIM_DBOPEN: 0x563b5fb09300
16:28:34 134337  opened hints database /var/spool/exim4/db/retry: flags=O_RDONLY
16:28:34 134337 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
16:28:34 134337 Considering: ametzler@???
16:28:34 134337 unique = ametzler@???
16:28:34 134337  dbfn_read: key=R:bebt.de
16:28:34 134337  dbfn_read: key=R:ametzler@???
16:28:34 134337  dbfn_read: key=R:ametzler@???:<ametzler@???>
16:28:34 134337 no   domain  retry record
16:28:34 134337 no   address retry record
16:28:34 134337 ametzler@???: queued for routing
16:28:34 134337  EXIM_DBCLOSE(0x563b5fb09300)
16:28:34 134337  closed hints database and lockfile
16:28:34 134337 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
16:28:34 134337 routing ametzler@???
16:28:34 134337 --------> ametzler_special router <--------
16:28:34 134337 local_part=ametzler domain=bebt.de
16:28:34 134337 checking domains
16:28:34 134337 bebt.de in "ssltest.argenau"? no (end of list)
16:28:34 134337 ametzler_special router skipped: domains mismatch
16:28:34 134337 --------> hubbed_hosts router <--------
16:28:34 134337 local_part=ametzler domain=bebt.de
16:28:34 134337 checking domains
16:28:34 134337  ╭considering: ${if exists{/etc/exim4/hubbed_hosts}{partial-lsearch;/etc/exim4/hubbed_hosts}fail}
16:28:34 134337   ╭considering: /etc/exim4/hubbed_hosts}{partial-lsearch;/etc/exim4/hubbed_hosts}fail}
16:28:34 134337   ├──expanding: /etc/exim4/hubbed_hosts
16:28:34 134337   ╰─────result: /etc/exim4/hubbed_hosts
16:28:34 134337  ├──condition: exists{/etc/exim4/hubbed_hosts}
16:28:34 134337  ├─────result: false
16:28:34 134337   ╭───scanning: partial-lsearch;/etc/exim4/hubbed_hosts}fail}
16:28:34 134337   ├──expanding: partial-lsearch;/etc/exim4/hubbed_hosts
16:28:34 134337   ├─────result: partial-lsearch;/etc/exim4/hubbed_hosts
16:28:34 134337   ╰───skipping: result is not used
16:28:34 134337  ├failed to expand: ${if exists{/etc/exim4/hubbed_hosts}{partial-lsearch;/etc/exim4/hubbed_hosts}fail}
16:28:34 134337  ├───error message: "if" failed and "fail" requested
16:28:34 134337  ╰failure was forced
16:28:34 134337 expansion of "${if exists{/etc/exim4/hubbed_hosts}{partial-lsearch;/etc/exim4/hubbed_hosts}fail}" forced failure: assume not in this list
16:28:34 134337 hubbed_hosts router skipped: domains mismatch
16:28:34 134337 --------> smarthost router <--------
16:28:34 134337 local_part=ametzler domain=bebt.de
16:28:34 134337 checking domains
16:28:34 134337 bebt.de in "@:localhost"? no (end of list)
16:28:34 134337 bebt.de in "! +local_domains"? yes (end of list)
16:28:34 134337  ╭considering: R: smarthost for $local_part@$domain
16:28:34 134337  ├──expanding: R: smarthost for $local_part@$domain
16:28:34 134337  ╰─────result: R: smarthost for ametzler@???
16:28:34 134337             ╰──(tainted)
16:28:34 134337 R: smarthost for ametzler@???
16:28:34 134337 calling smarthost router
16:28:34 134337 smarthost router called for ametzler@???
16:28:34 134337   domain = bebt.de
16:28:34 134337 route_item = * vsrv21575.customer.vlinux.de byname
16:28:34 134337 bebt.de in "*"? yes (matched "*")
16:28:34 134337 original list of hosts = 'vsrv21575.customer.vlinux.de' options = 'byname'
16:28:34 134337 expanded list of hosts = 'vsrv21575.customer.vlinux.de' options = 'byname'
16:28:34 134337 set transport remote_smtp_smarthost
16:28:34 134337 finding IP address for vsrv21575.customer.vlinux.de
16:28:34 134337 calling host_find_byname
16:28:34 134337 Coerced resolver DNSSEC support on.
16:28:34 134337 gethostbyname2(af=inet6) returned 4 (NO_DATA)
16:28:34 134337 Configured local interface: address=127.0.0.1
16:28:34 134337 Configured local interface: address=::1
16:28:34 134337 fully qualified name = vsrv21575.customer.vlinux.de
16:28:34 134337 gethostbyname2 looked up these IP addresses:
16:28:34 134337   name=vsrv21575.customer.vlinux.de address=31.15.64.248
16:28:34 134337 queued for remote_smtp_smarthost transport: local_part = ametzler
16:28:34 134337 domain = bebt.de
16:28:34 134337   errors_to=NULL
16:28:34 134337   domain_data=NULL local_part_data=NULL
16:28:34 134337 routed by smarthost router
16:28:34 134337   envelope to: ametzler@???
16:28:34 134337   transport: remote_smtp_smarthost
16:28:34 134337   host vsrv21575.customer.vlinux.de [31.15.64.248]
16:28:34 134337 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
16:28:34 134337 After routing:
16:28:34 134337   Local deliveries:
16:28:34 134337   Remote deliveries:
16:28:34 134337     ametzler@???
16:28:34 134337   Failed addresses:
16:28:34 134337   Deferred addresses:
16:28:34 134337 search_tidyup called
16:28:34 134337 >>>>>>>>>>>>>>>> Remote deliveries >>>>>>>>>>>>>>>>
16:28:34 134337 --------> ametzler@??? <--------
16:28:34 134337 search_tidyup called
16:28:34 134337 fresh-exec forking for transport
16:28:34 134337 fresh-exec forked for transport: 134339
16:28:34 134337 set_process_info: 134337 delivering 1m57j9-000Yw2-Ms: waiting for a remote delivery subprocess to finish
16:28:34 134337 selecting on subprocess pipes
16:28:34 134339 postfork: transport
16:28:34 134339 changed uid/gid: remote delivery to ametzler@??? with transport=remote_smtp_smarthost
16:28:34 134339   uid=109 gid=117 pid=134339
16:28:34 134339   auxiliary group list: <none>
16:28:34 134339 set_process_info: 134339 delivering 1m57j9-000Yw2-Ms using remote_smtp_smarthost
16:28:34 134339  ╭considering: T: remote_smtp_smarthost for $local_part@$domain
16:28:34 134339  ├──expanding: T: remote_smtp_smarthost for $local_part@$domain
16:28:34 134339  ╰─────result: T: remote_smtp_smarthost for ametzler@???
16:28:34 134339             ╰──(tainted)
16:28:34 134339 T: remote_smtp_smarthost for ametzler@???
16:28:34 134339 remote_smtp_smarthost transport entered
16:28:34 134339   ametzler@???
16:28:34 134339 hostlist:
16:28:34 134339   'vsrv21575.customer.vlinux.de' IP 31.15.64.248 port -1
16:28:34 134339 checking status of vsrv21575.customer.vlinux.de
16:28:34 134339  locking /var/spool/exim4/db/retry.lockfile
16:28:34 134339  locked  /var/spool/exim4/db/retry.lockfile
16:28:34 134339  EXIM_DBOPEN: file </var/spool/exim4/db/retry> dir </var/spool/exim4/db> flags=O_RDONLY
16:28:34 134339  returned from EXIM_DBOPEN: 0x563b5fb149e0
16:28:34 134339  opened hints database /var/spool/exim4/db/retry: flags=O_RDONLY
16:28:34 134339  dbfn_read: key=T:vsrv21575.customer.vlinux.de:31.15.64.248:587
16:28:34 134339  dbfn_read: key=T:vsrv21575.customer.vlinux.de:31.15.64.248:587:1m57j9-000Yw2-Ms
16:28:34 134339  EXIM_DBCLOSE(0x563b5fb149e0)
16:28:34 134339  closed hints database and lockfile
16:28:34 134339 no host retry record
16:28:34 134339 no message retry record
16:28:34 134339 vsrv21575.customer.vlinux.de [31.15.64.248]:587 retry-status = usable
16:28:34 134339 31.15.64.248 in serialize_hosts? no (option unset)
16:28:34 134339 delivering 1m57j9-000Yw2-Ms to vsrv21575.customer.vlinux.de [31.15.64.248] (ametzler@???)
16:28:34 134339 set_process_info: 134339 delivering 1m57j9-000Yw2-Ms to vsrv21575.customer.vlinux.de [31.15.64.248]:587 (ametzler@???)
16:28:34 134339 31.15.64.248 in hosts_require_dane? no (option unset)
16:28:34 134339 31.15.64.248 in hosts_pipe_connect? no (option unset)
16:28:34 134339 Connecting to vsrv21575.customer.vlinux.de [31.15.64.248]:587 ... 31.15.64.248 in hosts_try_fastopen? yes (matched "*")
16:28:34 134339  TFO mode sendto, no data: EINPROGRESS
16:28:34 134339  connected
16:28:34 134339  ╭considering: $primary_hostname
16:28:34 134339  ├──expanding: $primary_hostname
16:28:34 134339  ╰─────result: argenau.bebt.de
16:28:34 134339 read response data: size=84
16:28:34 134339   SMTP<< 220 vsrv21575.customer.vlinux.de ESMTP Exim 4.94.2 Sun, 18 Jul 2021 14:28:34 +0000
16:28:34 134339 31.15.64.248 in hosts_avoid_esmtp? no (option unset)
16:28:34 134339   SMTP>> EHLO argenau.bebt.de
16:28:34 134339 cmd buf flush 22 bytes
16:28:34 134339 read response data: size=226
16:28:34 134339   SMTP<< 250-vsrv21575.customer.vlinux.de Hello 178-190-17-1.adsl.highway.telekom.at [178.190.17.1]
16:28:34 134339          250-SIZE 52428800
16:28:34 134339          250-8BITMIME
16:28:34 134339          250-PIPELINING
16:28:34 134339          250-PIPE_CONNECT
16:28:34 134339          250-AUTH CRAM-MD5
16:28:34 134339          250-CHUNKING
16:28:34 134339          250-STARTTLS
16:28:34 134339          250-PRDR
16:28:34 134339          250 HELP
16:28:34 134339 31.15.64.248 in hosts_avoid_tls? no (option unset)
16:28:34 134339   SMTP>> STARTTLS
16:28:34 134339 cmd buf flush 10 bytes
16:28:35 134339 read response data: size=18
16:28:35 134339   SMTP<< 220 TLS go ahead
16:28:35 134339 31.15.64.248 in hosts_require_ocsp? no (option unset)
16:28:35 134339 31.15.64.248 in hosts_request_ocsp? yes (matched "*")
16:28:35 134339 initialising GnuTLS as a client on fd 7
16:28:35 134339 GnuTLS global init required
16:28:35 134339 initialising GnuTLS client session
16:28:35 134339 Expanding various TLS configuration options for session credentials
16:28:35 134339 TLS: basic cred init, client
16:28:35 134339 TLS: no client certificate specified; okay
16:28:35 134339 TLS: tls_verify_certificates not set or empty, ignoring
16:28:35 134339 GnuTLS using default session cipher/priority "NORMAL"
16:28:35 134339 Setting D-H prime minimum acceptable bits to 1024
16:28:35 134339 31.15.64.248 in tls_verify_hosts? yes (matched "*")
16:28:35 134339 31.15.64.248 in tls_verify_cert_hostnames? yes (matched "*")
16:28:35 134339 TLS: server cert verification includes hostname: "vsrv21575.customer.vlinux.de"
16:28:35 134339 TLS: server certificate verification required
16:28:35 134339 TLS: will request OCSP stapling
16:28:35 134339 31.15.64.248 in tls_resumption_hosts? no (option unset)
16:28:35 134339 about to gnutls_handshake
16:28:35 134339 (TLS1.3)-(ECDHE-SECP256R1)-(ECDSA-SECP384R1-SHA384)-(AES-256-GCM)
16:28:35 134339 To get keying info for TLS1.3 is hard:
16:28:35 134339  Set environment variable SSLKEYLOGFILE to a filename relative to the spool directory,
16:28:35 134339  and make sure it is writable by the Exim runtime user.
16:28:35 134339  Add SSLKEYLOGFILE to keep_environment in the exim config.
16:28:35 134339  Start Exim as root.
16:28:35 134339  If using sudo, add SSLKEYLOGFILE to env_keep in /etc/sudoers
16:28:35 134339  (works for TLS1.2 also, and saves cut-paste into file).
16:28:35 134339  Trying to use add_environment for this will not work
16:28:35 134339 TLS: checking peer certificate
16:28:35 134339 The certificate is NOT trusted. The certificate issuer is unknown. 
16:28:35 134339 TLS certificate verification failed (certificate invalid): peerdn="CN=vsrv21575.customer.vlinux.de"
16:28:35 134339 TLS session fail: (certificate verification failed): certificate invalid
16:28:35 134339   SMTP(close)>>