From: Jeremy Harris Date: Fri, 29 Dec 2023 12:40:22 +0000 (+0000) Subject: DKIM: logging for signing in transport. Bug 3062 X-Git-Url: https://git.exim.org/exim.git/commitdiff_plain/80bacd22c5aaacd7fca966af7384ac6f2679cb21 DKIM: logging for signing in transport. Bug 3062 --- diff --git a/doc/doc-docbook/spec.xfpt b/doc/doc-docbook/spec.xfpt index ae3cc1748..2c90ec5f3 100644 --- a/doc/doc-docbook/spec.xfpt +++ b/doc/doc-docbook/spec.xfpt @@ -39061,7 +39061,7 @@ selection marked by asterisks: .irow &`deliver_time`&   "time taken to attempt delivery" .irow &`delivery_size`&   "add &`S=`&&'nnn'& to => lines" .irow &`dkim`& * "DKIM verified domain on <= lines" -.irow &`dkim_verbose`&   "separate full DKIM verification result line, per signature" +.irow &`dkim_verbose`&   "separate full DKIM verification result line, per signature; DKIM signing" .irow &`dnslist_defer`& * "defers of DNS list (aka RBL) lookups" .irow &`dnssec`&   "DNSSEC secured lookups" .irow &`etrn`& * "ETRN commands" @@ -39187,6 +39187,10 @@ verifies successfully a tag of DKIM is added, with one of the verified domains. .cindex log "DKIM verification" .cindex DKIM "verification logging" &%dkim_verbose%&: A log entry is written for each attempted DKIM verification. +.new +Also, on message delivery lines signing information (domain and selector) +is added, tagged with DKIM=. +.wen .next .cindex "log" "dnslist defer" .cindex "DNS list" "logging defer" diff --git a/doc/doc-txt/NewStuff b/doc/doc-txt/NewStuff index 6aef41e50..1a5dac27b 100644 --- a/doc/doc-txt/NewStuff +++ b/doc/doc-txt/NewStuff @@ -10,6 +10,8 @@ Version 4.98 ------------ 1. The dkim_status ACL condition may now be used in data ACLs + 2. The dkim_verbose logging control also enables logging of signing + Version 4.97 ------------ diff --git a/src/src/deliver.c b/src/src/deliver.c index e96733f73..2cef3d731 100644 --- a/src/src/deliver.c +++ b/src/src/deliver.c @@ -1245,6 +1245,14 @@ else g = string_catn(g, US" K", 2); } +#ifndef DISABLE_DKIM + if (addr->dkim_used && LOGGING(dkim_verbose)) + { + g = string_catn(g, US" DKIM=", 6); + g = string_cat(g, addr->dkim_used); + } +#endif + /* confirmation message (SMTP (host_used) and LMTP (driver_name)) */ if ( LOGGING(smtp_confirmation) @@ -3571,7 +3579,14 @@ while (!done) switch (*subid) { - case 3: /* explicit notification of continued-connection (non)use; +#ifndef DISABLE_DKIM + case '4': /* DKIM information */ + addr->dkim_used = string_copy(ptr); + while(*ptr++); + break; +#endif + + case '3': /* explicit notification of continued-connection (non)use; overrides caller's knowlege. */ if (*ptr & BIT(1)) setflag(addr, af_new_conn); else if (*ptr & BIT(2)) setflag(addr, af_cont_conn); @@ -4886,6 +4901,15 @@ all pipes, so I do not see a reason to use non-blocking IO here rmt_dlv_checked_write(fd, 'R', '0', big_buffer, ptr - big_buffer); } +#ifndef DISABLE_DKIM + if (addr->dkim_used && LOGGING(dkim_verbose)) + { + DEBUG(D_deliver) debug_printf("dkim used: %s\n", addr->dkim_used); + ptr = big_buffer + sprintf(CS big_buffer, "%.128s", addr->dkim_used) + 1; + rmt_dlv_checked_write(fd, 'A', '4', big_buffer, ptr - big_buffer); + } +#endif + if (testflag(addr, af_new_conn) || testflag(addr, af_cont_conn)) { DEBUG(D_deliver) debug_printf("%scontinued-connection\n", diff --git a/src/src/dkim.c b/src/src/dkim.c index ea82f34ea..59025608f 100644 --- a/src/src/dkim.c +++ b/src/src/dkim.c @@ -741,6 +741,9 @@ if (dkim_domain) if (!pdkim_set_sig_bodyhash(&dkim_sign_ctx, sig)) goto bad; + dkim_signing_record = string_append_listele(dkim_signing_record, ':', dkim_signing_domain); + dkim_signing_record = string_append_listele(dkim_signing_record, ':', dkim_signing_selector); + if (!dkim_sign_ctx.sig) /* link sig to context chain */ dkim_sign_ctx.sig = sig; else diff --git a/src/src/dkim_transport.c b/src/src/dkim_transport.c index fae2f4891..38f849af6 100644 --- a/src/src/dkim_transport.c +++ b/src/src/dkim_transport.c @@ -384,6 +384,8 @@ BOOL dkim_transport_write_message(transport_ctx * tctx, struct ob_dkim * dkim, const uschar ** err) { +BOOL yield; + /* If we can't sign, just call the original function. */ if ( !(dkim->dkim_private_key && dkim->dkim_domain && dkim->dkim_selector) @@ -398,12 +400,16 @@ if ( !transport_filter_argv || !*transport_filter_argv || !**transport_filter_argv ) - return dkt_direct(tctx, dkim, err); + yield = dkt_direct(tctx, dkim, err); + +else + /* Use the transport path to write a file, calculate a dkim signature, + send the signature and then send the file. */ -/* Use the transport path to write a file, calculate a dkim signature, -send the signature and then send the file. */ + yield = dkt_via_kfile(tctx, dkim, err); -return dkt_via_kfile(tctx, dkim, err); +tctx->addr->dkim_used = string_from_gstring(dkim_signing_record); +return yield; } #endif /* whole file */ diff --git a/src/src/globals.c b/src/src/globals.c index bb5bd6b1a..c535ea121 100644 --- a/src/src/globals.c +++ b/src/src/globals.c @@ -864,6 +864,7 @@ void *dkim_signatures = NULL; uschar *dkim_signers = NULL; uschar *dkim_signing_domain = NULL; uschar *dkim_signing_selector = NULL; +gstring *dkim_signing_record = NULL; uschar *dkim_verify_hashes = US"sha256:sha512"; uschar *dkim_verify_keytypes = US"ed25519:rsa"; uschar *dkim_verify_min_keysizes = US"rsa=1024 ed25519=250"; diff --git a/src/src/globals.h b/src/src/globals.h index fe4a1610a..ffc7150f2 100644 --- a/src/src/globals.h +++ b/src/src/globals.h @@ -541,6 +541,7 @@ extern uschar *dkim_cur_signer; /* Expansion variable, holds the current extern int dkim_key_length; /* Expansion variable, length of signing key in bits */ extern void *dkim_signatures; /* Actually a (pdkim_signature *) but most files do not need to know */ extern uschar *dkim_signers; /* Expansion variable, holds colon-separated list of domains and identities that have signed a message */ +extern gstring *dkim_signing_record; /* domains+selectors used */ extern uschar *dkim_signing_domain; /* Expansion variable, domain used for signing a message. */ extern uschar *dkim_signing_selector; /* Expansion variable, selector used for signing a message. */ extern uschar *dkim_verify_hashes; /* Preference order for signatures */ diff --git a/src/src/structs.h b/src/src/structs.h index 256560ef8..b16a8a3f2 100644 --- a/src/src/structs.h +++ b/src/src/structs.h @@ -586,6 +586,9 @@ typedef struct address_item { uschar *self_hostname; /* after self=pass */ uschar *shadow_message; /* info about shadow transporting */ + uid_t uid; /* uid for transporting */ + gid_t gid; /* gid for transporting */ + #ifndef DISABLE_TLS const uschar *tlsver; /* version used for transport */ uschar *cipher; /* Cipher used for transport */ @@ -608,9 +611,9 @@ typedef struct address_item { int dsn_flags; /* DSN flags */ int dsn_aware; /* DSN aware flag */ - uid_t uid; /* uid for transporting */ - gid_t gid; /* gid for transporting */ - +#ifndef DISABLE_DKIM + const uschar * dkim_used; /* DKIM info, or NULL */ +#endif /* flags */ struct { BOOL af_allow_file:1; /* allow file in generated address */ diff --git a/test/log/4510 b/test/log/4510 index 08f73d5b4..7632951d0 100644 --- a/test/log/4510 +++ b/test/log/4510 @@ -1,23 +1,23 @@ 1999-03-02 09:44:33 10HmaY-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for a@test.ex -1999-03-02 09:44:33 10HmaY-000000005vi-0000 => a@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] C="250 OK id=10HmaZ-000000005vi-0000" +1999-03-02 09:44:33 10HmaY-000000005vi-0000 => a@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] DKIM=test.ex:sel C="250 OK id=10HmaZ-000000005vi-0000" 1999-03-02 09:44:33 10HmaY-000000005vi-0000 Completed 1999-03-02 09:44:33 10HmbA-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for b@test.ex -1999-03-02 09:44:33 10HmbA-000000005vi-0000 => b@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] C="250 OK id=10HmbB-000000005vi-0000" +1999-03-02 09:44:33 10HmbA-000000005vi-0000 => b@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] DKIM=test.ex:sel C="250 OK id=10HmbB-000000005vi-0000" 1999-03-02 09:44:33 10HmbA-000000005vi-0000 Completed 1999-03-02 09:44:33 10HmbC-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for b10@test.ex -1999-03-02 09:44:33 10HmbC-000000005vi-0000 => b10@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] C="250 OK id=10HmbD-000000005vi-0000" +1999-03-02 09:44:33 10HmbC-000000005vi-0000 => b10@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] DKIM=test.ex:sel C="250 OK id=10HmbD-000000005vi-0000" 1999-03-02 09:44:33 10HmbC-000000005vi-0000 Completed 1999-03-02 09:44:33 10HmbE-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for b12@test.ex -1999-03-02 09:44:33 10HmbE-000000005vi-0000 => b12@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] C="250 OK id=10HmbF-000000005vi-0000" +1999-03-02 09:44:33 10HmbE-000000005vi-0000 => b12@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] DKIM=test.ex:sel C="250 OK id=10HmbF-000000005vi-0000" 1999-03-02 09:44:33 10HmbE-000000005vi-0000 Completed 1999-03-02 09:44:33 10HmbG-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for b20@test.ex -1999-03-02 09:44:33 10HmbG-000000005vi-0000 => b20@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] C="250 OK id=10HmbH-000000005vi-0000" +1999-03-02 09:44:33 10HmbG-000000005vi-0000 => b20@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] DKIM=test.ex:sel C="250 OK id=10HmbH-000000005vi-0000" 1999-03-02 09:44:33 10HmbG-000000005vi-0000 Completed 1999-03-02 09:44:33 10HmbI-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for b22@test.ex -1999-03-02 09:44:33 10HmbI-000000005vi-0000 => b22@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] C="250 OK id=10HmbJ-000000005vi-0000" +1999-03-02 09:44:33 10HmbI-000000005vi-0000 => b22@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] DKIM=test.ex:sel C="250 OK id=10HmbJ-000000005vi-0000" 1999-03-02 09:44:33 10HmbI-000000005vi-0000 Completed 1999-03-02 09:44:33 10HmbK-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for d@test.ex -1999-03-02 09:44:33 10HmbK-000000005vi-0000 => d@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] C="250 OK id=10HmbL-000000005vi-0000" +1999-03-02 09:44:33 10HmbK-000000005vi-0000 => d@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] DKIM=test.ex:sel_bad C="250 OK id=10HmbL-000000005vi-0000" 1999-03-02 09:44:33 10HmbK-000000005vi-0000 Completed 1999-03-02 09:44:33 10HmaX-000000005vi-0000 <= <> U=CALLER P=local S=sss for e0@test.ex 1999-03-02 09:44:33 10HmaX-000000005vi-0000 failed to expand dkim_timestamps: unknown variable in "${bogus}" @@ -31,7 +31,7 @@ 1999-03-02 09:44:33 10HmbM-000000005vi-0000 => e@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] C="250 OK id=10HmbN-000000005vi-0000" 1999-03-02 09:44:33 10HmbM-000000005vi-0000 Completed 1999-03-02 09:44:33 10HmbO-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for f@test.ex -1999-03-02 09:44:33 10HmbO-000000005vi-0000 => f@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] C="250 OK id=10HmbP-000000005vi-0000" +1999-03-02 09:44:33 10HmbO-000000005vi-0000 => f@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] DKIM=test.ex:sel C="250 OK id=10HmbP-000000005vi-0000" 1999-03-02 09:44:33 10HmbO-000000005vi-0000 Completed ******** SERVER ******** diff --git a/test/log/4511 b/test/log/4511 index b45c16fbb..2b6340344 100644 --- a/test/log/4511 +++ b/test/log/4511 @@ -1,8 +1,8 @@ 2017-07-30 18:51:05.712 10HmaX-000000005vi-0000 <= sender@testhost.test.ex U=sender Ci=p1234 P=local S=sss for a@test.ex -2017-07-30 18:51:05.712 10HmaX-000000005vi-0000 => a@test.ex R=to_server T=remote_smtp_dkim H=127.0.0.1 [127.0.0.1] K C="250- 6nn byte chunk, total 6nn\\n250 OK id=10HmaY-000000005vi-0000" +2017-07-30 18:51:05.712 10HmaX-000000005vi-0000 => a@test.ex R=to_server T=remote_smtp_dkim H=127.0.0.1 [127.0.0.1] K DKIM=test.ex:sel C="250- 6nn byte chunk, total 6nn\\n250 OK id=10HmaY-000000005vi-0000" 2017-07-30 18:51:05.712 10HmaX-000000005vi-0000 Completed 2017-07-30 18:51:05.712 10HmaZ-000000005vi-0000 <= sender@testhost.test.ex U=sender Ci=p1235 P=local S=sss for b@test.ex -2017-07-30 18:51:05.712 10HmaZ-000000005vi-0000 => b@test.ex R=to_server T=remote_smtp_dkim H=127.0.0.1 [127.0.0.1] K C="250- 8nn byte chunk, total 8nn\\n250 OK id=10HmbA-000000005vi-0000" +2017-07-30 18:51:05.712 10HmaZ-000000005vi-0000 => b@test.ex R=to_server T=remote_smtp_dkim H=127.0.0.1 [127.0.0.1] K DKIM=test.ex:sel C="250- 8nn byte chunk, total 8nn\\n250 OK id=10HmbA-000000005vi-0000" 2017-07-30 18:51:05.712 10HmaZ-000000005vi-0000 Completed ******** SERVER ******** diff --git a/test/log/4513 b/test/log/4513 index a3c53de81..c72693ca1 100644 --- a/test/log/4513 +++ b/test/log/4513 @@ -1,5 +1,5 @@ 1999-03-02 09:44:33 10HmaX-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for a@test.ex -1999-03-02 09:44:33 10HmaX-000000005vi-0000 => a@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] C="250 OK id=10HmaY-000000005vi-0000" +1999-03-02 09:44:33 10HmaX-000000005vi-0000 => a@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] DKIM=test.ex:sel C="250 OK id=10HmaY-000000005vi-0000" 1999-03-02 09:44:33 10HmaX-000000005vi-0000 Completed ******** SERVER ******** diff --git a/test/log/4514 b/test/log/4514 index 6d489fb99..619023da0 100644 --- a/test/log/4514 +++ b/test/log/4514 @@ -1,5 +1,5 @@ 1999-03-02 09:44:33 10HmaX-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for c@test.ex -1999-03-02 09:44:33 10HmaX-000000005vi-0000 => c@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] C="250 OK id=10HmaY-000000005vi-0000" +1999-03-02 09:44:33 10HmaX-000000005vi-0000 => c@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] DKIM=test.ex:ses:test.ex:sel C="250 OK id=10HmaY-000000005vi-0000" 1999-03-02 09:44:33 10HmaX-000000005vi-0000 Completed ******** SERVER ******** diff --git a/test/log/4519 b/test/log/4519 index 24aba0b1e..02ddaebff 100644 --- a/test/log/4519 +++ b/test/log/4519 @@ -11,11 +11,11 @@ 1999-03-02 09:44:33 10HmaX-000000005vi-0000 DKIM: d=test.ex s=sel c=relaxed/relaxed a=rsa-sha256 b=1024 [verification succeeded] 1999-03-02 09:44:33 10HmaX-000000005vi-0000 <= <> H=localhost (testhost.test.ex) [127.0.0.1] P=esmtp K S=sss DKIM=test.ex for z@test.ex 1999-03-02 09:44:33 10HmaX-000000005vi-0000 no immediate delivery: queued by ACL -1999-03-02 09:44:33 10HmaZ-000000005vi-0000 => z@test.ex R=to_server T=remote_smtp_dkim H=127.0.0.1 [127.0.0.1] K C="250- 6nn byte chunk, total 6nn\\n250 OK id=10HmaX-000000005vi-0000" +1999-03-02 09:44:33 10HmaZ-000000005vi-0000 => z@test.ex R=to_server T=remote_smtp_dkim H=127.0.0.1 [127.0.0.1] K DKIM=test.ex:sel C="250- 6nn byte chunk, total 6nn\\n250 OK id=10HmaX-000000005vi-0000" 1999-03-02 09:44:33 10HmaZ-000000005vi-0000 Completed 1999-03-02 09:44:33 10HmbA-000000005vi-0000 <= CALLER@bloggs.com H=(xxx) [127.0.0.1] P=esmtp K S=sss for y@test.ex 1999-03-02 09:44:33 10HmaY-000000005vi-0000 DKIM: d=test.ex s=sel c=relaxed/relaxed a=rsa-sha256 b=1024 [verification succeeded] 1999-03-02 09:44:33 10HmaY-000000005vi-0000 <= <> H=localhost (testhost.test.ex) [127.0.0.1] P=esmtp K S=sss DKIM=test.ex for y@test.ex 1999-03-02 09:44:33 10HmaY-000000005vi-0000 no immediate delivery: queued by ACL -1999-03-02 09:44:33 10HmbA-000000005vi-0000 => y@test.ex R=to_server T=remote_smtp_dkim H=127.0.0.1 [127.0.0.1] K C="250- 6nn byte chunk, total 6nn\\n250 OK id=10HmaY-000000005vi-0000" +1999-03-02 09:44:33 10HmbA-000000005vi-0000 => y@test.ex R=to_server T=remote_smtp_dkim H=127.0.0.1 [127.0.0.1] K DKIM=test.ex:sel C="250- 6nn byte chunk, total 6nn\\n250 OK id=10HmaY-000000005vi-0000" 1999-03-02 09:44:33 10HmbA-000000005vi-0000 Completed diff --git a/test/log/4530 b/test/log/4530 index bd0e40ae2..74713e09d 100644 --- a/test/log/4530 +++ b/test/log/4530 @@ -1,23 +1,23 @@ 1999-03-02 09:44:33 10HmaY-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for a@test.ex -1999-03-02 09:44:33 10HmaY-000000005vi-0000 => a@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes C="250 OK id=10HmaZ-000000005vi-0000" +1999-03-02 09:44:33 10HmaY-000000005vi-0000 => a@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DKIM=test.ex:sel C="250 OK id=10HmaZ-000000005vi-0000" 1999-03-02 09:44:33 10HmaY-000000005vi-0000 Completed 1999-03-02 09:44:33 10HmbA-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for b@test.ex -1999-03-02 09:44:33 10HmbA-000000005vi-0000 => b@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes C="250 OK id=10HmbB-000000005vi-0000" +1999-03-02 09:44:33 10HmbA-000000005vi-0000 => b@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DKIM=test.ex:sel C="250 OK id=10HmbB-000000005vi-0000" 1999-03-02 09:44:33 10HmbA-000000005vi-0000 Completed 1999-03-02 09:44:33 10HmbC-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for b10@test.ex -1999-03-02 09:44:33 10HmbC-000000005vi-0000 => b10@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes C="250 OK id=10HmbD-000000005vi-0000" +1999-03-02 09:44:33 10HmbC-000000005vi-0000 => b10@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DKIM=test.ex:sel C="250 OK id=10HmbD-000000005vi-0000" 1999-03-02 09:44:33 10HmbC-000000005vi-0000 Completed 1999-03-02 09:44:33 10HmbE-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for b12@test.ex -1999-03-02 09:44:33 10HmbE-000000005vi-0000 => b12@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes C="250 OK id=10HmbF-000000005vi-0000" +1999-03-02 09:44:33 10HmbE-000000005vi-0000 => b12@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DKIM=test.ex:sel C="250 OK id=10HmbF-000000005vi-0000" 1999-03-02 09:44:33 10HmbE-000000005vi-0000 Completed 1999-03-02 09:44:33 10HmbG-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for b20@test.ex -1999-03-02 09:44:33 10HmbG-000000005vi-0000 => b20@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes C="250 OK id=10HmbH-000000005vi-0000" +1999-03-02 09:44:33 10HmbG-000000005vi-0000 => b20@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DKIM=test.ex:sel C="250 OK id=10HmbH-000000005vi-0000" 1999-03-02 09:44:33 10HmbG-000000005vi-0000 Completed 1999-03-02 09:44:33 10HmbI-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for b22@test.ex -1999-03-02 09:44:33 10HmbI-000000005vi-0000 => b22@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes C="250 OK id=10HmbJ-000000005vi-0000" +1999-03-02 09:44:33 10HmbI-000000005vi-0000 => b22@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DKIM=test.ex:sel C="250 OK id=10HmbJ-000000005vi-0000" 1999-03-02 09:44:33 10HmbI-000000005vi-0000 Completed 1999-03-02 09:44:33 10HmbK-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for d@test.ex -1999-03-02 09:44:33 10HmbK-000000005vi-0000 => d@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes C="250 OK id=10HmbL-000000005vi-0000" +1999-03-02 09:44:33 10HmbK-000000005vi-0000 => d@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DKIM=test.ex:sel_bad C="250 OK id=10HmbL-000000005vi-0000" 1999-03-02 09:44:33 10HmbK-000000005vi-0000 Completed 1999-03-02 09:44:33 10HmaX-000000005vi-0000 <= <> U=CALLER P=local S=sss for e0@test.ex 1999-03-02 09:44:33 10HmaX-000000005vi-0000 failed to expand dkim_timestamps: unknown variable in "${bogus}" @@ -31,7 +31,7 @@ 1999-03-02 09:44:33 10HmbM-000000005vi-0000 => e@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes C="250 OK id=10HmbN-000000005vi-0000" 1999-03-02 09:44:33 10HmbM-000000005vi-0000 Completed 1999-03-02 09:44:33 10HmbO-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for f@test.ex -1999-03-02 09:44:33 10HmbO-000000005vi-0000 => f@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes C="250 OK id=10HmbP-000000005vi-0000" +1999-03-02 09:44:33 10HmbO-000000005vi-0000 => f@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DKIM=test.ex:sel C="250 OK id=10HmbP-000000005vi-0000" 1999-03-02 09:44:33 10HmbO-000000005vi-0000 Completed ******** SERVER ******** diff --git a/test/log/4531 b/test/log/4531 index bd642b51f..45994c751 100644 --- a/test/log/4531 +++ b/test/log/4531 @@ -1,8 +1,8 @@ 2017-07-30 18:51:05.712 10HmaX-000000005vi-0000 <= sender@testhost.test.ex U=sender Ci=p1234 P=local S=sss for a@test.ex -2017-07-30 18:51:05.712 10HmaX-000000005vi-0000 => a@test.ex R=to_server T=remote_smtp_dkim H=127.0.0.1 [127.0.0.1] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes K C="250- 6nn byte chunk, total 6nn\\n250 OK id=10HmaY-000000005vi-0000" +2017-07-30 18:51:05.712 10HmaX-000000005vi-0000 => a@test.ex R=to_server T=remote_smtp_dkim H=127.0.0.1 [127.0.0.1] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes K DKIM=test.ex:sel C="250- 6nn byte chunk, total 6nn\\n250 OK id=10HmaY-000000005vi-0000" 2017-07-30 18:51:05.712 10HmaX-000000005vi-0000 Completed 2017-07-30 18:51:05.712 10HmaZ-000000005vi-0000 <= sender@testhost.test.ex U=sender Ci=p1235 P=local S=sss for b@test.ex -2017-07-30 18:51:05.712 10HmaZ-000000005vi-0000 => b@test.ex R=to_server T=remote_smtp_dkim H=127.0.0.1 [127.0.0.1] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes K C="250- 8nn byte chunk, total 8nn\\n250 OK id=10HmbA-000000005vi-0000" +2017-07-30 18:51:05.712 10HmaZ-000000005vi-0000 => b@test.ex R=to_server T=remote_smtp_dkim H=127.0.0.1 [127.0.0.1] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes K DKIM=test.ex:sel C="250- 8nn byte chunk, total 8nn\\n250 OK id=10HmbA-000000005vi-0000" 2017-07-30 18:51:05.712 10HmaZ-000000005vi-0000 Completed ******** SERVER ******** diff --git a/test/log/4533 b/test/log/4533 index 3e8343539..0483ddc08 100644 --- a/test/log/4533 +++ b/test/log/4533 @@ -1,5 +1,5 @@ 1999-03-02 09:44:33 10HmaX-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for a@test.ex -1999-03-02 09:44:33 10HmaX-000000005vi-0000 => a@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes C="250 OK id=10HmaY-000000005vi-0000" +1999-03-02 09:44:33 10HmaX-000000005vi-0000 => a@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DKIM=test.ex:sel C="250 OK id=10HmaY-000000005vi-0000" 1999-03-02 09:44:33 10HmaX-000000005vi-0000 Completed ******** SERVER ******** diff --git a/test/log/4534 b/test/log/4534 index 4f386c95c..d80dc7154 100644 --- a/test/log/4534 +++ b/test/log/4534 @@ -1,5 +1,5 @@ 1999-03-02 09:44:33 10HmaX-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for c@test.ex -1999-03-02 09:44:33 10HmaX-000000005vi-0000 => c@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes C="250 OK id=10HmaY-000000005vi-0000" +1999-03-02 09:44:33 10HmaX-000000005vi-0000 => c@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DKIM=test.ex:ses:test.ex:sel C="250 OK id=10HmaY-000000005vi-0000" 1999-03-02 09:44:33 10HmaX-000000005vi-0000 Completed ******** SERVER ******** diff --git a/test/log/4539 b/test/log/4539 index 9b0269b6c..5f503f6b2 100644 --- a/test/log/4539 +++ b/test/log/4539 @@ -11,11 +11,11 @@ 1999-03-02 09:44:33 10HmaX-000000005vi-0000 DKIM: d=test.ex s=sel c=relaxed/relaxed a=rsa-sha256 b=1024 [verification succeeded] 1999-03-02 09:44:33 10HmaX-000000005vi-0000 <= <> H=localhost (testhost.test.ex) [127.0.0.1] P=esmtps X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=no K S=sss DKIM=test.ex for z@test.ex 1999-03-02 09:44:33 10HmaX-000000005vi-0000 no immediate delivery: queued by ACL -1999-03-02 09:44:33 10HmaZ-000000005vi-0000 => z@test.ex R=to_server T=remote_smtp_dkim H=127.0.0.1 [127.0.0.1] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes K C="250- 7nn byte chunk, total 7nn\\n250 OK id=10HmaX-000000005vi-0000" +1999-03-02 09:44:33 10HmaZ-000000005vi-0000 => z@test.ex R=to_server T=remote_smtp_dkim H=127.0.0.1 [127.0.0.1] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes K DKIM=test.ex:sel C="250- 7nn byte chunk, total 7nn\\n250 OK id=10HmaX-000000005vi-0000" 1999-03-02 09:44:33 10HmaZ-000000005vi-0000 Completed 1999-03-02 09:44:33 10HmbA-000000005vi-0000 <= CALLER@bloggs.com H=(xxx) [127.0.0.1] P=smtps X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=no K S=sss for y@test.ex 1999-03-02 09:44:33 10HmaY-000000005vi-0000 DKIM: d=test.ex s=sel c=relaxed/relaxed a=rsa-sha256 b=1024 [verification succeeded] 1999-03-02 09:44:33 10HmaY-000000005vi-0000 <= <> H=localhost (testhost.test.ex) [127.0.0.1] P=esmtps X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=no K S=sss DKIM=test.ex for y@test.ex 1999-03-02 09:44:33 10HmaY-000000005vi-0000 no immediate delivery: queued by ACL -1999-03-02 09:44:33 10HmbA-000000005vi-0000 => y@test.ex R=to_server T=remote_smtp_dkim H=127.0.0.1 [127.0.0.1] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes K C="250- 7nn byte chunk, total 7nn\\n250 OK id=10HmaY-000000005vi-0000" +1999-03-02 09:44:33 10HmbA-000000005vi-0000 => y@test.ex R=to_server T=remote_smtp_dkim H=127.0.0.1 [127.0.0.1] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes K DKIM=test.ex:sel C="250- 7nn byte chunk, total 7nn\\n250 OK id=10HmaY-000000005vi-0000" 1999-03-02 09:44:33 10HmbA-000000005vi-0000 Completed diff --git a/test/log/4541 b/test/log/4541 index bc998cc35..f2d4c325b 100644 --- a/test/log/4541 +++ b/test/log/4541 @@ -1,8 +1,8 @@ 1999-03-02 09:44:33 10HmaX-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for a@test.ex -1999-03-02 09:44:33 10HmaX-000000005vi-0000 => a@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] C="250 OK id=10HmaY-000000005vi-0000" +1999-03-02 09:44:33 10HmaX-000000005vi-0000 => a@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] DKIM=test.ex:sel:test.ex:sed C="250 OK id=10HmaY-000000005vi-0000" 1999-03-02 09:44:33 10HmaX-000000005vi-0000 Completed 1999-03-02 09:44:33 10HmaZ-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for b@test.ex -1999-03-02 09:44:33 10HmaZ-000000005vi-0000 => b@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] C="250 OK id=10HmbA-000000005vi-0000" +1999-03-02 09:44:33 10HmaZ-000000005vi-0000 => b@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] DKIM=test.ex:sel:test.ex:sed C="250 OK id=10HmbA-000000005vi-0000" 1999-03-02 09:44:33 10HmaZ-000000005vi-0000 Completed ******** SERVER ******** diff --git a/test/log/4545 b/test/log/4545 index cb1918b2f..c983a7a96 100644 --- a/test/log/4545 +++ b/test/log/4545 @@ -1,8 +1,8 @@ 1999-03-02 09:44:33 10HmaX-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for a@test.ex -1999-03-02 09:44:33 10HmaX-000000005vi-0000 => a@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] C="250 OK id=10HmaY-000000005vi-0000" +1999-03-02 09:44:33 10HmaX-000000005vi-0000 => a@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] DKIM=test.ex:sed C="250 OK id=10HmaY-000000005vi-0000" 1999-03-02 09:44:33 10HmaX-000000005vi-0000 Completed 1999-03-02 09:44:33 10HmaZ-000000005vi-0000 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for b@test.ex -1999-03-02 09:44:33 10HmaZ-000000005vi-0000 => b@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] C="250 OK id=10HmbA-000000005vi-0000" +1999-03-02 09:44:33 10HmaZ-000000005vi-0000 => b@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] DKIM=test.ex:sed:test.ex:sel C="250 OK id=10HmbA-000000005vi-0000" 1999-03-02 09:44:33 10HmaZ-000000005vi-0000 Completed ******** SERVER ******** diff --git a/test/log/4565 b/test/log/4565 index 4c74fc4d2..48efed49d 100644 --- a/test/log/4565 +++ b/test/log/4565 @@ -13,7 +13,7 @@ 1999-03-02 09:44:33 10HmaY-000000005vi-0000 arc_oldest_pass <1> 1999-03-02 09:44:33 10HmaY-000000005vi-0000 domains: 1999-03-02 09:44:33 10HmaY-000000005vi-0000 <= CALLER@bloggs.com H=localhost (test.ex) [127.0.0.1] P=esmtp S=sss DKIM=test.ex ARC id=qwerty1234@disco-zombie.net for a@test.ex -1999-03-02 09:44:33 10HmaX-000000005vi-0000 => a@test.ex R=fwd T=tsmtp H=127.0.0.1 [127.0.0.1] C="250 OK id=10HmaY-000000005vi-0000" +1999-03-02 09:44:33 10HmaX-000000005vi-0000 => a@test.ex R=fwd T=tsmtp H=127.0.0.1 [127.0.0.1] DKIM=test.ex:sel C="250 OK id=10HmaY-000000005vi-0000" 1999-03-02 09:44:33 10HmaX-000000005vi-0000 Completed 1999-03-02 09:44:33 End queue run: pid=p1235 1999-03-02 09:44:33 Start queue run: pid=p1236 diff --git a/test/runtest b/test/runtest index 8628ff299..3f4004cc1 100755 --- a/test/runtest +++ b/test/runtest @@ -1565,7 +1565,7 @@ RESET_AFTER_EXTRA_LINE_READ: next if / Berkeley DB error: /; # CHUNKING: exact sizes depend on hostnames in headers - s/(=>.* K C="250- \d)\d+ (byte chunk, total \d)\d+/$1nn $2nn/; + s/(=>.* K (?:DKIM=\S+ )?C="250- \d)\d+ (byte chunk, total \d)\d+/$1nn $2nn/; # OpenSSL version variances s/(TLS error on connection [^:]*: error:)[0-9A-F]{8}(:system library):(?:fopen|func\(4095\)|):(No such file or directory)$/$1xxxxxxxx$2:fopen:$3/; diff --git a/test/stderr/4510 b/test/stderr/4510 index 47bcef891..39224679a 100644 --- a/test/stderr/4510 +++ b/test/stderr/4510 @@ -56,7 +56,7 @@ cmd buf flush ddd bytes (more expected) SMTP(close)>> cmdlog: '220:EHLO:250-:MAIL|:RCPT|:DATA:250:250:354:.:QUIT+:250:221' LOG: MAIN - => d@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] C="250 OK id=10HmbL-000000005vi-0000" + => d@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] DKIM=test.ex:sel_bad C="250 OK id=10HmbL-000000005vi-0000" LOG: MAIN Completed >>>>>>>>>>>>>>>> Exim pid=p1236 (local-accept-delivery) terminating with rc=0 >>>>>>>>>>>>>>>> diff --git a/test/stderr/4530 b/test/stderr/4530 index b0126b584..eeeee68c8 100644 --- a/test/stderr/4530 +++ b/test/stderr/4530 @@ -66,7 +66,7 @@ cmd buf flush ddd bytes SMTP(close)>> cmdlog: '220:EHLO:250-:STARTTLS:220:EHLO:250-:MAIL|:RCPT|:DATA:250:250:354:.:QUIT:250:221' LOG: MAIN - => d@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes C="250 OK id=10HmbL-000000005vi-0000" + => d@test.ex R=client T=send_to_server H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DKIM=test.ex:sel_bad C="250 OK id=10HmbL-000000005vi-0000" LOG: MAIN Completed >>>>>>>>>>>>>>>> Exim pid=p1236 (local-accept-delivery) terminating with rc=0 >>>>>>>>>>>>>>>>