DKIM: rework error logging to pass strings back to caller for logging. Bug 966

diff --git a/doc/doc-txt/ChangeLog b/doc/doc-txt/ChangeLog
index 534dfd0aea8325a304690123fdf3efc6705fd27c..d73dd099b4b8d98cbad31cfae1304b552bdff4fa 100644 (file)
--- 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 2873eda5310095674e8a8c021a8d09bf53517977..a0a79a51ab3da60dd19bc5e3eedd54b621572b80 100644 (file)
--- 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 8474962fc931b0d94c5e2a0935e1304ced0615c3..bfdc7d42b519275ecfd9b27a0cc4675b59c9d1ab 100644 (file)
--- 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 722fbf9d52348ce901f52c17c6f5d441b951f4d3..a7d9c1116cd0cebf4046ed0d70bcd20fecc5064b 100644 (file)
--- 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 f26b745af31a84af274579eaeb18282526d49ef0..5fc6045d0b49995a74bfffe62ca1bad58aecdcc4 100644 (file)
--- 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 8b8b95032e244cde94a55550fa4610a35fbd13e7..8c477f744cbd3f49b6ba0a7b05af71c15d27ba0d 100644 (file)
--- 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 b8a4636b60818fe2cc4220d5ff8de4ebb7ab2cec..2caf6e5f08e4cf33df16e2bf1a73bbe108c5afbb 100644 (file)
--- 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 02d1e671edfa2a376ca242498a189892e04c8aae..90ec87b301c06558dd30a2b62e20f3b1a54f865b 100644 (file)
--- 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 20e9c6b51c0595e116edcf71ed1718101dba03ca..fb0f2256784fa7d304b5039d00ac583686fbc84c 100644 (file)
--- 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 14bba834680d815c6a94ef3e5a5526fe65452292..6eb81cc16ee1c805cbca918cf1d2ccaf98979972 100644 (file)
--- 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:<CALLER@bloggs.com>
+??? 250
+RCPT TO:<a@test.ex>
+??? 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: <qwerty1234@disco-zombie.net>
+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 a5e9e9da2c607deb39245ed5aa78f51ee195c122..2c90d565c1818ae91154c0c4a45ceca672b5070b 100644 (file)
--- 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)
   {