From b9df1829d6afa37ef6576d04fc8845c1d20269b0 Mon Sep 17 00:00:00 2001 From: Jeremy Harris Date: Sat, 25 Feb 2017 18:42:51 +0000 Subject: [PATCH] DKIM: rework error logging to pass strings back to caller for logging. Bug 966 --- doc/doc-txt/ChangeLog | 3 +++ src/src/dkim.c | 36 +++++++++++++------------- src/src/dkim.h | 2 +- src/src/functions.h | 2 +- src/src/pdkim/pdkim.c | 50 ++++++++++++++++++------------------- src/src/pdkim/pdkim.h | 6 ++--- src/src/transport.c | 14 +++++------ src/src/transports/smtp.c | 10 +++++--- test/log/4506 | 3 +++ test/scripts/4500-DKIM/4506 | 34 +++++++++++++++++++++++++ test/src/client.c | 2 +- 11 files changed, 103 insertions(+), 59 deletions(-) diff --git a/doc/doc-txt/ChangeLog b/doc/doc-txt/ChangeLog index 534dfd0ae..d73dd099b 100644 --- a/doc/doc-txt/ChangeLog +++ b/doc/doc-txt/ChangeLog @@ -16,6 +16,9 @@ JH/01 Rework error string handling in TLS interface so that the caller in PP/01 Allow PKG_CONFIG_PATH to be set in Local/Makefile and use it correctly during configuration. Wildcards are allowed and expanded. +JH/02 Rework error string handling in DKIM to pass more info back to callers. + This permits better logging. + Exim version 4.89 ----------------- diff --git a/src/src/dkim.c b/src/src/dkim.c index 2873eda53..a0a79a51a 100644 --- a/src/src/dkim.c +++ b/src/src/dkim.c @@ -18,7 +18,7 @@ int dkim_verify_oldpool; pdkim_ctx *dkim_verify_ctx = NULL; pdkim_signature *dkim_signatures = NULL; pdkim_signature *dkim_cur_sig = NULL; -static BOOL dkim_collect_error = FALSE; +static const uschar * dkim_collect_error = NULL; static int dkim_exim_query_dns_txt(char *name, char *answer) @@ -88,7 +88,7 @@ if (dkim_verify_ctx) dkim_verify_ctx = pdkim_init_verify(&dkim_exim_query_dns_txt, dot_stuffing); dkim_collect_input = !!dkim_verify_ctx; -dkim_collect_error = FALSE; +dkim_collect_error = NULL; /* Start feed up with any cached data */ receive_get_cache(); @@ -106,9 +106,9 @@ store_pool = POOL_PERM; if ( dkim_collect_input && (rc = pdkim_feed(dkim_verify_ctx, CS data, len)) != PDKIM_OK) { + dkim_collect_error = pdkim_errstr(rc); log_write(0, LOG_MAIN, - "DKIM: validation error: %.100s", pdkim_errstr(rc)); - dkim_collect_error = TRUE; + "DKIM: validation error: %.100s", dkim_collect_error); dkim_collect_input = FALSE; } store_pool = dkim_verify_oldpool; @@ -119,9 +119,8 @@ void dkim_exim_verify_finish(void) { pdkim_signature * sig = NULL; -int dkim_signers_size = 0; -int dkim_signers_ptr = 0; -int rc; +int dkim_signers_size = 0, dkim_signers_ptr = 0, rc; +const uschar * errstr; store_pool = POOL_PERM; @@ -133,8 +132,8 @@ dkim_signatures = NULL; if (dkim_collect_error) { log_write(0, LOG_MAIN, - "DKIM: Error while running this message through validation," - " disabling signature verification."); + "DKIM: Error during validation, disabling signature verification: %.100s", + dkim_collect_error); dkim_disable_verify = TRUE; goto out; } @@ -143,10 +142,11 @@ dkim_collect_input = FALSE; /* Finish DKIM operation and fetch link to signatures chain */ -if ((rc = pdkim_feed_finish(dkim_verify_ctx, &dkim_signatures)) != PDKIM_OK) +rc = pdkim_feed_finish(dkim_verify_ctx, &dkim_signatures, &errstr); +if (rc != PDKIM_OK) { - log_write(0, LOG_MAIN, - "DKIM: validation error: %.100s", pdkim_errstr(rc)); + log_write(0, LOG_MAIN, "DKIM: validation error: %.100s%s%s", pdkim_errstr(rc), + errstr ? ": " : "", errstr ? errstr : US""); goto out; } @@ -449,7 +449,7 @@ switch (what) uschar * -dkim_exim_sign(int dkim_fd, struct ob_dkim * dkim) +dkim_exim_sign(int dkim_fd, struct ob_dkim * dkim, const uschar ** errstr) { const uschar * dkim_domain; int sep = 0; @@ -596,13 +596,15 @@ while ((dkim_signing_domain = string_nextinlist(&dkim_domain, &sep, dkim_private_key_expanded = big_buffer; } - ctx = pdkim_init_sign(CS dkim_signing_domain, + if (!(ctx = pdkim_init_sign(CS dkim_signing_domain, CS dkim_signing_selector, CS dkim_private_key_expanded, PDKIM_ALGO_RSA_SHA256, dkim->dot_stuffed, - &dkim_exim_query_dns_txt - ); + &dkim_exim_query_dns_txt, + errstr + ))) + goto bad; dkim_private_key_expanded[0] = '\0'; pdkim_set_optional(ctx, CS dkim_sign_headers_expanded, @@ -624,7 +626,7 @@ while ((dkim_signing_domain = string_nextinlist(&dkim_domain, &sep, goto bad; } - if ((pdkim_rc = pdkim_feed_finish(ctx, &signature)) != PDKIM_OK) + if ((pdkim_rc = pdkim_feed_finish(ctx, &signature, errstr)) != PDKIM_OK) goto pk_bad; sigbuf = string_append(sigbuf, &sigsize, &sigptr, 2, diff --git a/src/src/dkim.h b/src/src/dkim.h index 8474962fc..bfdc7d42b 100644 --- a/src/src/dkim.h +++ b/src/src/dkim.h @@ -6,7 +6,7 @@ /* See the file NOTICE for conditions of use and distribution. */ void dkim_exim_init(void); -uschar *dkim_exim_sign(int, struct ob_dkim *); +uschar *dkim_exim_sign(int, struct ob_dkim *, const uschar **); void dkim_exim_verify_init(BOOL); void dkim_exim_verify_feed(uschar *, int); void dkim_exim_verify_finish(void); diff --git a/src/src/functions.h b/src/src/functions.h index 722fbf9d5..a7d9c1116 100644 --- a/src/src/functions.h +++ b/src/src/functions.h @@ -153,7 +153,7 @@ extern uschar *deliver_get_sender_address (uschar *id); extern BOOL directory_make(const uschar *, const uschar *, int, BOOL); #ifndef DISABLE_DKIM extern BOOL dkim_transport_write_message(int, transport_ctx *, - struct ob_dkim *); + struct ob_dkim *, const uschar ** errstr); #endif extern dns_address *dns_address_from_rr(dns_answer *, dns_record *); extern int dns_basic_lookup(dns_answer *, const uschar *, int); diff --git a/src/src/pdkim/pdkim.c b/src/src/pdkim/pdkim.c index f26b745af..5fc6045d0 100644 --- a/src/src/pdkim/pdkim.c +++ b/src/src/pdkim/pdkim.c @@ -142,19 +142,19 @@ switch(ext_status) } } -const char * +const uschar * pdkim_errstr(int status) { switch(status) { - case PDKIM_OK: return "OK"; - case PDKIM_FAIL: return "FAIL"; - case PDKIM_ERR_RSA_PRIVKEY: return "RSA_PRIVKEY"; - case PDKIM_ERR_RSA_SIGNING: return "RSA SIGNING"; - case PDKIM_ERR_LONG_LINE: return "RSA_LONG_LINE"; - case PDKIM_ERR_BUFFER_TOO_SMALL: return "BUFFER_TOO_SMALL"; - case PDKIM_SIGN_PRIVKEY_WRAP: return "PRIVKEY_WRAP"; - case PDKIM_SIGN_PRIVKEY_B64D: return "PRIVKEY_B64D"; + case PDKIM_OK: return US"OK"; + case PDKIM_FAIL: return US"FAIL"; + case PDKIM_ERR_RSA_PRIVKEY: return US"RSA_PRIVKEY"; + case PDKIM_ERR_RSA_SIGNING: return US"RSA SIGNING"; + case PDKIM_ERR_LONG_LINE: return US"RSA_LONG_LINE"; + case PDKIM_ERR_BUFFER_TOO_SMALL: return US"BUFFER_TOO_SMALL"; + case PDKIM_SIGN_PRIVKEY_WRAP: return US"PRIVKEY_WRAP"; + case PDKIM_SIGN_PRIVKEY_B64D: return US"PRIVKEY_B64D"; default: return "(unknown)"; } } @@ -1311,11 +1311,11 @@ return hdr; /* -------------------------------------------------------------------------- */ static pdkim_pubkey * -pdkim_key_from_dns(pdkim_ctx * ctx, pdkim_signature * sig, ev_ctx * vctx) +pdkim_key_from_dns(pdkim_ctx * ctx, pdkim_signature * sig, ev_ctx * vctx, + const uschar ** errstr) { uschar * dns_txt_name, * dns_txt_reply; pdkim_pubkey * p; -const uschar * errstr; /* Fetch public key for signing domain, from DNS */ @@ -1364,9 +1364,9 @@ DEBUG(D_acl) debug_printf( "PDKIM <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<\n"); /* Import public key */ -if ((errstr = exim_rsa_verify_init(&p->key, vctx))) +if ((*errstr = exim_rsa_verify_init(&p->key, vctx))) { - DEBUG(D_acl) debug_printf("verify_init: %s\n", errstr); + DEBUG(D_acl) debug_printf("verify_init: %s\n", *errstr); sig->verify_status = PDKIM_VERIFY_INVALID; sig->verify_ext_status = PDKIM_VERIFY_INVALID_PUBKEY_IMPORT; return NULL; @@ -1379,7 +1379,8 @@ return p; /* -------------------------------------------------------------------------- */ DLLEXPORT int -pdkim_feed_finish(pdkim_ctx *ctx, pdkim_signature **return_signatures) +pdkim_feed_finish(pdkim_ctx * ctx, pdkim_signature ** return_signatures, + const uschar ** err) { pdkim_signature *sig = ctx->sig; @@ -1560,12 +1561,11 @@ while (sig) if (ctx->flags & PDKIM_MODE_SIGN) { es_ctx sctx; - const uschar * errstr; /* Import private key */ - if ((errstr = exim_rsa_signing_init(US sig->rsa_privkey, &sctx))) + if ((*err = exim_rsa_signing_init(US sig->rsa_privkey, &sctx))) { - DEBUG(D_acl) debug_printf("signing_init: %s\n", errstr); + DEBUG(D_acl) debug_printf("signing_init: %s\n", *err); return PDKIM_ERR_RSA_PRIVKEY; } @@ -1577,9 +1577,9 @@ while (sig) hdata = hhash; #endif - if ((errstr = exim_rsa_sign(&sctx, is_sha1, &hdata, &sig->sighash))) + if ((*err = exim_rsa_sign(&sctx, is_sha1, &hdata, &sig->sighash))) { - DEBUG(D_acl) debug_printf("signing: %s\n", errstr); + DEBUG(D_acl) debug_printf("signing: %s\n", *err); return PDKIM_ERR_RSA_SIGNING; } @@ -1596,7 +1596,6 @@ while (sig) else { ev_ctx vctx; - const uschar * errstr; pdkim_pubkey * p; /* Make sure we have all required signature tags */ @@ -1630,13 +1629,13 @@ while (sig) goto NEXT_VERIFY; } - if (!(sig->pubkey = pdkim_key_from_dns(ctx, sig, &vctx))) + if (!(sig->pubkey = pdkim_key_from_dns(ctx, sig, &vctx, err))) goto NEXT_VERIFY; /* Check the signature */ - if ((errstr = exim_rsa_verify(&vctx, is_sha1, &hhash, &sig->sighash))) + if ((*err = exim_rsa_verify(&vctx, is_sha1, &hhash, &sig->sighash))) { - DEBUG(D_acl) debug_printf("headers verify: %s\n", errstr); + DEBUG(D_acl) debug_printf("headers verify: %s\n", *err); sig->verify_status = PDKIM_VERIFY_FAIL; sig->verify_ext_status = PDKIM_VERIFY_FAIL_MESSAGE; goto NEXT_VERIFY; @@ -1694,7 +1693,8 @@ return ctx; DLLEXPORT pdkim_ctx * pdkim_init_sign(char * domain, char * selector, char * rsa_privkey, int algo, - BOOL dot_stuffed, int(*dns_txt_callback)(char *, char *)) + BOOL dot_stuffed, int(*dns_txt_callback)(char *, char *), + const uschar ** errstr) { pdkim_ctx * ctx; pdkim_signature * sig; @@ -1734,7 +1734,7 @@ DEBUG(D_acl) ev_ctx vctx; debug_printf("PDKIM (checking verify key)<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<\n"); - if (!pdkim_key_from_dns(ctx, &s, &vctx)) + if (!pdkim_key_from_dns(ctx, &s, &vctx, errstr)) debug_printf("WARNING: bad dkim key in dns\n"); debug_printf("PDKIM (finished checking verify key)<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<\n"); } diff --git a/src/src/pdkim/pdkim.h b/src/src/pdkim/pdkim.h index 8b8b95032..8c477f744 100644 --- a/src/src/pdkim/pdkim.h +++ b/src/src/pdkim/pdkim.h @@ -287,7 +287,7 @@ void pdkim_init (void); DLLEXPORT pdkim_ctx *pdkim_init_sign (char *, char *, char *, int, - BOOL, int(*)(char *, char *)); + BOOL, int(*)(char *, char *), const uschar **); DLLEXPORT pdkim_ctx *pdkim_init_verify (int(*)(char *, char *), BOOL); @@ -301,13 +301,13 @@ int pdkim_set_optional (pdkim_ctx *, char *, char *,int, int, DLLEXPORT int pdkim_feed (pdkim_ctx *, char *, int); DLLEXPORT -int pdkim_feed_finish (pdkim_ctx *, pdkim_signature **); +int pdkim_feed_finish (pdkim_ctx *, pdkim_signature **, const uschar **); DLLEXPORT void pdkim_free_ctx (pdkim_ctx *); -const char * pdkim_errstr(int); +const uschar * pdkim_errstr(int); #ifdef __cplusplus } diff --git a/src/src/transport.c b/src/src/transport.c index b8a4636b6..2caf6e5f0 100644 --- a/src/src/transport.c +++ b/src/src/transport.c @@ -1062,18 +1062,16 @@ Returns: TRUE on success; FALSE (with errno) for any failure BOOL dkim_transport_write_message(int out_fd, transport_ctx * tctx, - struct ob_dkim * dkim) + struct ob_dkim * dkim, const uschar ** err) { int dkim_fd; int save_errno = 0; BOOL rc; uschar * dkim_spool_name; -int sread = 0; -int wwritten = 0; -uschar *dkim_signature = NULL; -int siglen = 0; +uschar * dkim_signature = NULL; +int sread = 0, wwritten = 0, siglen = 0, options; off_t k_file_size; -int options; +const uschar * errstr; /* If we can't sign, just call the original function. */ @@ -1088,6 +1086,7 @@ if ((dkim_fd = Uopen(dkim_spool_name, O_RDWR|O_CREAT|O_TRUNC, SPOOL_MODE)) < 0) /* Can't create spool file. Ugh. */ rc = FALSE; save_errno = errno; + *err = string_sprintf("dkim spoolfile create: %s", strerror(errno)); goto CLEANUP; } @@ -1109,7 +1108,7 @@ if (!rc) /* Rewind file and feed it to the goats^W DKIM lib */ dkim->dot_stuffed = !!(options & topt_end_dot); lseek(dkim_fd, 0, SEEK_SET); -if ((dkim_signature = dkim_exim_sign(dkim_fd, dkim))) +if ((dkim_signature = dkim_exim_sign(dkim_fd, dkim, &errstr))) siglen = Ustrlen(dkim_signature); else if (dkim->dkim_strict) { @@ -1122,6 +1121,7 @@ else if (dkim->dkim_strict) save_errno = EACCES; log_write(0, LOG_MAIN, "DKIM: message could not be signed," " and dkim_strict is set. Deferring message delivery."); + *err = errstr; rc = FALSE; goto CLEANUP; } diff --git a/src/src/transports/smtp.c b/src/src/transports/smtp.c index 02d1e671e..90ec87b30 100644 --- a/src/src/transports/smtp.c +++ b/src/src/transports/smtp.c @@ -2745,7 +2745,8 @@ else transport_count = 0; #ifndef DISABLE_DKIM - sx.ok = dkim_transport_write_message(sx.inblock.sock, &tctx, &sx.ob->dkim); + sx.ok = dkim_transport_write_message(sx.inblock.sock, &tctx, &sx.ob->dkim, + CUSS &message); #else sx.ok = transport_write_message(sx.inblock.sock, &tctx, 0); #endif @@ -2762,7 +2763,8 @@ else Or, when CHUNKING, it can be a protocol-detected failure. */ if (!sx.ok) - goto RESPONSE_FAILED; + if (message) goto SEND_FAILED; + else goto RESPONSE_FAILED; /* We used to send the terminating "." explicitly here, but because of buffering effects at both ends of TCP/IP connections, you don't gain @@ -3027,8 +3029,8 @@ if (!sx.ok) { save_errno = errno; code = '4'; - message = US string_sprintf("send() to %s [%s] failed: %s", - host->name, host->address, strerror(save_errno)); + message = string_sprintf("send() to %s [%s] failed: %s", + host->name, host->address, message ? message : strerror(save_errno)); sx.send_quit = FALSE; goto FAILED; } diff --git a/test/log/4506 b/test/log/4506 index 20e9c6b51..fb0f22567 100644 --- a/test/log/4506 +++ b/test/log/4506 @@ -10,3 +10,6 @@ 1999-03-02 09:44:33 10HmaZ-0005vi-00 DKIM: d=test.ex s=sel c=simple/simple a=rsa-sha1 b=1024 [verification failed - body hash mismatch (body probably modified in transit)] 1999-03-02 09:44:33 10HmaZ-0005vi-00 signer: test.ex bits: 1024 1999-03-02 09:44:33 10HmaZ-0005vi-00 <= CALLER@bloggs.com H=(xxx) [127.0.0.1] P=smtp S=sss id=qwerty1234@disco-zombie.net +1999-03-02 09:44:33 10HmbA-0005vi-00 DKIM: validation error: RSA_LONG_LINE +1999-03-02 09:44:33 10HmbA-0005vi-00 DKIM: Error during validation, disabling signature verification: RSA_LONG_LINE +1999-03-02 09:44:33 10HmbA-0005vi-00 <= CALLER@bloggs.com H=(xxx) [127.0.0.1] P=smtp S=sss id=qwerty1234@disco-zombie.net diff --git a/test/scripts/4500-DKIM/4506 b/test/scripts/4500-DKIM/4506 index 14bba8346..6eb81cc16 100644 --- a/test/scripts/4500-DKIM/4506 +++ b/test/scripts/4500-DKIM/4506 @@ -98,6 +98,40 @@ QUIT # # # +# This should refuse to do verification (over-long body line) +# The sig is bogus, but we don't verify it +write test-data 1x16386 +++++ +**** +# +client 127.0.0.1 PORT_D +??? 220 +HELO xxx +??? 250 +MAIL FROM: +??? 250 +RCPT TO: +??? 250 +DATA +??? 354 +DKIM-Signature: v=1; a=rsa-sha1; c=simple/simple; d=test.ex; h=from:to + :date:message-id:subject; s=sel; bh=OB9dZVu7+5/ufs3TH9leIcEpXSo=; b= + PeUA8iBGfStWv+9/BBKkvCEYj/AVMl4e9k+AqWOXKyuEUfHxqAnV+sPnOejpmvT8 + 41kuM4u0bICvK371YvB/yO61vtliRhyqU76Y2e55p2uvMADb3UyDhLyzpco4+yBo + 1w0AuIxu0VU4TK8UmOLyCw/1hxrh1DcEInbEMEKJ7kI= +From: mrgus@text.ex +To: bakawolf@yahoo.com +Date: Thu, 19 Nov 2015 17:00:07 -0700 +Message-ID: +Subject: simple test + +<<< test-data +another data line +. +??? 250 +QUIT +??? 221 +**** # # killdaemon diff --git a/test/src/client.c b/test/src/client.c index a5e9e9da2..2c90d565c 100644 --- a/test/src/client.c +++ b/test/src/client.c @@ -529,7 +529,7 @@ static void do_file(srv_ctx * srv, FILE * f, int timeout, unsigned char * inbuffer, unsigned bsiz, unsigned char * inptr) { -unsigned char outbuffer[10240]; +unsigned char outbuffer[1024 * 20]; while (fgets(CS outbuffer, sizeof(outbuffer), f) != NULL) { -- 2.25.1