From fae8655e4084e8f4df4b32b7e7ead5f5656e4f60 Mon Sep 17 00:00:00 2001 From: Vsevolod Stakhov Date: Thu, 6 Feb 2020 16:03:52 +0000 Subject: [PATCH] [Minor] Improve dkim failures logging --- src/libserver/dkim.c | 54 ++++++++++++++++++++++++++++++++++++++------ 1 file changed, 47 insertions(+), 7 deletions(-) diff --git a/src/libserver/dkim.c b/src/libserver/dkim.c index 6b8262ee2..503347544 100644 --- a/src/libserver/dkim.c +++ b/src/libserver/dkim.c @@ -104,15 +104,18 @@ struct rspamd_dkim_common_ctx { rspamd_mempool_t *pool; guint64 sig_hash; gsize len; - gint header_canon_type; - gint body_canon_type; - gboolean is_sign; GPtrArray *hlist; GHashTable *htable; /* header -> count mapping */ EVP_MD_CTX *headers_hash; EVP_MD_CTX *body_hash; enum rspamd_dkim_type type; guint idx; + gint header_canon_type; + gint body_canon_type; + guint body_canonicalised; + guint headers_canonicalised; + gboolean is_sign; + }; enum rspamd_arc_seal_cv { @@ -1673,6 +1676,7 @@ rspamd_dkim_relaxed_body_step (struct rspamd_dkim_common_ctx *ctx, EVP_MD_CTX *c gsize cklen = MIN(t - buf, *remain + added); EVP_DigestUpdate (ck, buf, cklen); + ctx->body_canonicalised += cklen; *remain = *remain - (cklen - added); msg_debug_dkim ("update signature with body buffer " "(%z size, %ud remain, %ud added)", @@ -1723,6 +1727,7 @@ rspamd_dkim_simple_body_step (struct rspamd_dkim_common_ctx *ctx, gsize cklen = MIN(t - buf, *remain + added); EVP_DigestUpdate (ck, buf, cklen); + ctx->body_canonicalised += cklen; *remain = *remain - (cklen - added); msg_debug_dkim ("update signature with body buffer " "(%z size, %ud remain, %ud added)", @@ -1915,6 +1920,7 @@ rspamd_dkim_canonize_body (struct rspamd_dkim_common_ctx *ctx, /* Empty body */ if (ctx->body_canon_type == DKIM_CANON_SIMPLE) { EVP_DigestUpdate (ctx->body_hash, CRLF, sizeof (CRLF) - 1); + ctx->body_canonicalised += sizeof (CRLF) - 1; } else { EVP_DigestUpdate (ctx->body_hash, "", 0); @@ -1930,6 +1936,7 @@ rspamd_dkim_canonize_body (struct rspamd_dkim_common_ctx *ctx, /* Empty body */ if (ctx->body_canon_type == DKIM_CANON_SIMPLE) { EVP_DigestUpdate (ctx->body_hash, CRLF, sizeof (CRLF) - 1); + ctx->body_canonicalised += sizeof (CRLF) - 1; } else { EVP_DigestUpdate (ctx->body_hash, "", 0); @@ -2026,6 +2033,7 @@ rspamd_dkim_signature_update (struct rspamd_dkim_common_ctx *ctx, msg_debug_dkim ("initial update hash with signature part: %*s", (gint)(p - c + 2), c); + ctx->headers_canonicalised += p - c + 2; rspamd_dkim_hash_update (ctx->headers_hash, c, p - c + 2); skip = TRUE; } @@ -2051,6 +2059,7 @@ rspamd_dkim_signature_update (struct rspamd_dkim_common_ctx *ctx, if (p - c + 1 > 0) { msg_debug_dkim ("final update hash with signature part: %*s", (gint)(p - c + 1), c); + ctx->headers_canonicalised += p - c + 1; rspamd_dkim_hash_update (ctx->headers_hash, c, p - c + 1); } } @@ -2206,6 +2215,7 @@ rspamd_dkim_canonize_header (struct rspamd_dkim_common_ctx *ctx, rspamd_dkim_hash_update (ctx->headers_hash, (const gchar *)&random_cookie, sizeof (random_cookie)); + ctx->headers_canonicalised += sizeof (random_cookie); return FALSE; } @@ -2224,6 +2234,7 @@ rspamd_dkim_canonize_header (struct rspamd_dkim_common_ctx *ctx, if (ctx->header_canon_type == DKIM_CANON_SIMPLE) { rspamd_dkim_hash_update (ctx->headers_hash, sel->raw_value, sel->raw_len); + ctx->headers_canonicalised += sel->raw_len; msg_debug_dkim ("update signature with header (idx=%d): %*s", count, (gint)sel->raw_len, sel->raw_value); } @@ -2433,11 +2444,14 @@ rspamd_dkim_check (rspamd_dkim_context_t *ctx, /* Check bh field */ if (memcmp (ctx->bh, cached_bh->digest_normal, ctx->bhlen) != 0) { + msg_info_dkim ( + "dkim: bh value mismatch: got %*Bs, expected %*Bs; " + "body length %d->%d; d=%s; s=%s", + (gint)dlen, cached_bh->digest_normal, + (gint)dlen, ctx->bh, + (gint)(body_end - body_start), ctx->common.body_canonicalised, + ctx->domain, ctx->selector); if (cpy_ctx) { - msg_debug_dkim ( - "bh value mismatch: %*xs versus %*xs, try add CRLF", - (gint)dlen, ctx->bh, - (gint)dlen, cached_bh->digest_normal); /* Try add CRLF */ #if OPENSSL_VERSION_NUMBER < 0x10100000L || defined(LIBRESSL_VERSION_NUMBER) EVP_MD_CTX_cleanup (cpy_ctx); @@ -2565,11 +2579,28 @@ rspamd_dkim_check (rspamd_dkim_context_t *ctx, msg_debug_dkim ("rsa verify failed"); res->rcode = DKIM_REJECT; res->fail_reason = "rsa verify failed"; + + msg_info_dkim ( + "dkim: RSA verification failure: got %*Bs, expected %*Bs; " + "body length %d->%d; headers length %d; d=%s; s=%s", + (gint)dlen, raw_digest, + (gint)dlen, ctx->b, + (gint)(body_end - body_start), ctx->common.body_canonicalised, + ctx->common.headers_canonicalised, + ctx->domain, ctx->selector); } break; case RSPAMD_DKIM_KEY_ECDSA: if (ECDSA_verify (nid, raw_digest, dlen, ctx->b, ctx->blen, key->key.key_ecdsa) != 1) { + msg_info_dkim ( + "dkim: ECDSA verification failure: got %*Bs, expected %*Bs; " + "body length %d->%d; headers length %d; d=%s; s=%s", + (gint)dlen, raw_digest, + (gint)dlen, ctx->b, + (gint)(body_end - body_start), ctx->common.body_canonicalised, + ctx->common.headers_canonicalised, + ctx->domain, ctx->selector); msg_debug_dkim ("ecdsa verify failed"); res->rcode = DKIM_REJECT; res->fail_reason = "ecdsa verify failed"; @@ -2578,6 +2609,14 @@ rspamd_dkim_check (rspamd_dkim_context_t *ctx, case RSPAMD_DKIM_KEY_EDDSA: if (!rspamd_cryptobox_verify (ctx->b, ctx->blen, raw_digest, dlen, key->key.key_eddsa, RSPAMD_CRYPTOBOX_MODE_25519)) { + msg_info_dkim ( + "dkim: EDDSA verification failure: got %*Bs, expected %*Bs; " + "body length %d->%d; headers length %d; d=%s; s=%s", + (gint)dlen, raw_digest, + (gint)dlen, ctx->b, + (gint)(body_end - body_start), ctx->common.body_canonicalised, + ctx->common.headers_canonicalised, + ctx->domain, ctx->selector); msg_debug_dkim ("eddsa verify failed"); res->rcode = DKIM_REJECT; res->fail_reason = "eddsa verify failed"; @@ -3152,6 +3191,7 @@ rspamd_dkim_sign (struct rspamd_task *task, const gchar *selector, /* Will likely have issues with folding */ rspamd_dkim_hash_update (ctx->common.headers_hash, hdr->str, hdr->len); + ctx->common.headers_canonicalised += hdr->len; msg_debug_task ("update signature with header: %*s", (gint)hdr->len, hdr->str); } -- 2.39.5