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