ARC: enhance debug for signing; explicitly init signing context
[exim.git] / src / src / arc.c
index 1323a451a530079a8ce656997f06c66f0728ac6f..5f51d614dbdcad49748c579ffd087c4205e104c5 100644 (file)
@@ -66,7 +66,7 @@ typedef struct arc_set {
   arc_line *           hdr_ams;
   arc_line *           hdr_as;
 
-  BOOL                 ams_verify_done;
+  const uschar *       ams_verify_done;
   BOOL                 ams_verify_passed;
 } arc_set;
 
@@ -96,9 +96,9 @@ Return 0 on error */
 static unsigned
 arc_instance_from_hdr(const arc_line * al)
 {
-uschar * s = al->i.data;
+const uschar * s = al->i.data;
 if (!s || !al->i.len) return 0;
-return (unsigned) atoi(s);
+return (unsigned) atoi(CCS s);
 }
 
 
@@ -186,7 +186,7 @@ static uschar *
 arc_parse_line(arc_line * al, header_line * h, unsigned off, BOOL instance_only)
 {
 uschar * s = h->text + off;
-uschar * r;
+uschar * r = NULL;     /* compiler-quietening */
 uschar c;
 
 al->complete = h;
@@ -482,7 +482,7 @@ static const uschar *
 arc_vfy_collect_hdrs(arc_ctx * ctx)
 {
 header_line * h;
-hdr_rlist * r, * rprev = NULL;
+hdr_rlist * r = NULL, * rprev = NULL;
 const uschar * e;
 
 DEBUG(D_acl) debug_printf("ARC: collecting arc sets\n");
@@ -495,7 +495,10 @@ for (h = header_list; h; h = h->next)
   rprev = r;
 
   if ((e = arc_try_header(ctx, h, FALSE)))
-    return e;
+    {
+    arc_state_reason = string_sprintf("collecting headers: %s", e);
+    return US"fail";
+    }
   }
 headers_rlist = r;
 
@@ -561,11 +564,11 @@ while ((hn = string_nextinlist(&headernames, &sep, NULL, 0)))
       break;
       }
 
-/* Finally add in the signature header (with the b= tag stripped) */
+/* Finally add in the signature header (with the b= tag stripped); no CRLF */
 
 s = ams->rawsig_no_b_val.data, len = ams->rawsig_no_b_val.len;
 if (relaxed)
-  len = Ustrlen(s = pdkim_relax_header_n(s, len, TRUE));
+  len = Ustrlen(s = pdkim_relax_header_n(s, len, FALSE));
 DEBUG(D_acl) pdkim_quoteprint(s, len);
 exim_sha_update(&hhash_ctx, s, len);
 
@@ -612,7 +615,7 @@ if (p->hashes)
   if (!ele)
     {
     DEBUG(D_acl) debug_printf("pubkey h=%s vs sig a=%.*s\n",
-                             p->hashes, al->a.len, al->a.data);
+                             p->hashes, (int)al->a.len, al->a.data);
     return NULL;
     }
   }
@@ -628,6 +631,7 @@ arc_ams_setup_vfy_bodyhash(arc_line * ams)
 int canon_head, canon_body;
 long bodylen;
 
+if (!ams->c.data) ams->c.data = US"simple";    /* RFC 6376 (DKIM) default */
 pdkim_cstring_to_canons(ams->c.data, ams->c.len, &canon_head, &canon_body);
 bodylen = ams->l.data
        ? strtol(CS string_copyn(ams->l.data, ams->l.len), NULL, 10) : -1;
@@ -644,7 +648,7 @@ return pdkim_set_bodyhash(dkim_verify_ctx,
 and without a DKIM v= tag.
 */
 
-static uschar *
+static const uschar *
 arc_ams_verify(arc_ctx * ctx, arc_set * as)
 {
 arc_line * ams = as->hdr_ams;
@@ -656,7 +660,7 @@ ev_ctx vctx;
 int hashtype;
 const uschar * errstr;
 
-as->ams_verify_done = TRUE;
+as->ams_verify_done = US"in-progress";
 
 /* Check the AMS has all the required tags:
    "a="  algorithm
@@ -668,21 +672,27 @@ as->ams_verify_done = TRUE;
 */
 if (  !ams->a.data || !ams->b.data || !ams->bh.data || !ams->d.data
    || !ams->h.data || !ams->s.data)
+  {
+  as->ams_verify_done = arc_state_reason = US"required tag missing";
   return US"fail";
+  }
 
 
 /* The bodyhash should have been created earlier, and the dkim code should
 have managed calculating it during message input.  Find the reference to it. */
 
 if (!(b = arc_ams_setup_vfy_bodyhash(ams)))
+  {
+  as->ams_verify_done = arc_state_reason = US"internal hash setup error";
   return US"fail";
+  }
 
 DEBUG(D_acl)
   {
   debug_printf("ARC i=%d AMS   Body bytes hashed: %lu\n"
               "              Body %.*s computed: ",
               as->instance, b->signed_body_bytes,
-              ams->a_hash.len, ams->a_hash.data);
+              (int)ams->a_hash.len, ams->a_hash.data);
   pdkim_hexprint(CUS b->bh.data, b->bh.len);
   }
 
@@ -699,7 +709,7 @@ if (  !ams->bh.data
     pdkim_hexprint(sighash.data, sighash.len);
     debug_printf("ARC i=%d AMS Body hash did NOT match\n", as->instance);
     }
-  return US"body hash compare mismatch";
+  return as->ams_verify_done = arc_state_reason = US"AMS body hash miscompare";
   }
 
 DEBUG(D_acl) debug_printf("ARC i=%d AMS Body hash compared OK\n", as->instance);
@@ -707,7 +717,7 @@ DEBUG(D_acl) debug_printf("ARC i=%d AMS Body hash compared OK\n", as->instance);
 /* Get the public key from DNS */
 
 if (!(p = arc_line_to_pubkey(ams)))
-  return US"pubkey problem";
+  return as->ams_verify_done = arc_state_reason = US"pubkey problem";
 
 /* We know the b-tag blob is of a nul-term string, so safe as a string */
 pdkim_decode_base64(ams->b.data, &sighash);
@@ -719,6 +729,7 @@ arc_get_verify_hhash(ctx, ams, &hhash);
 if ((errstr = exim_dkim_verify_init(&p->key, KEYFMT_DER, &vctx)))
   {
   DEBUG(D_acl) debug_printf("ARC verify init: %s\n", errstr);
+  as->ams_verify_done = arc_state_reason = US"internal sigverify init error";
   return US"fail";
   }
 
@@ -728,7 +739,7 @@ if ((errstr = exim_dkim_verify(&vctx,
          pdkim_hashes[hashtype].exim_hashmethod, &hhash, &sighash)))
   {
   DEBUG(D_acl) debug_printf("ARC i=%d AMS verify %s\n", as->instance, errstr);
-  return US"ams sig verify fail";
+  return as->ams_verify_done = arc_state_reason = US"AMS sig nonverify";
   }
 
 DEBUG(D_acl) debug_printf("ARC i=%d AMS verify pass\n", as->instance);
@@ -761,9 +772,10 @@ for(inst = 0; as; as = as->next)
      || arc_cv_match(as->hdr_as, US"fail")
      )
     {
-    DEBUG(D_acl) debug_printf("ARC i=%d fail"
-      " (cv, sequence or missing header)\n", as->instance);
-    ret = US"fail";
+    arc_state_reason = string_sprintf("i=%d"
+      " (cv, sequence or missing header)", as->instance);
+    DEBUG(D_acl) debug_printf("ARC chain fail at %s\n", arc_state_reason);
+    return US"fail";
     }
 
   /* Evaluate the oldest-pass AMS validation while we're here.
@@ -775,6 +787,7 @@ for(inst = 0; as; as = as->next)
       ams_fail_found = TRUE;
     else
       arc_oldest_pass = inst;
+  arc_state_reason = NULL;
   }
 
 arc_received = ctx->arcset_chain_last;
@@ -785,7 +798,12 @@ if (ret)
 /* We can skip the latest-AMS validation, if we already did it. */
 
 as = ctx->arcset_chain_last;
-if (as->ams_verify_done ? !as->ams_verify_passed : !!arc_ams_verify(ctx, as))
+if (as->ams_verify_done && !as->ams_verify_passed)
+  {
+  arc_state_reason = as->ams_verify_done;
+  return US"fail";
+  }
+if (!!arc_ams_verify(ctx, as))
   return US"fail";
 
 return NULL;
@@ -822,7 +840,10 @@ DEBUG(D_acl) debug_printf("ARC: AS vfy i=%d\n", as->instance);
 if (  as->instance == 1 && !arc_cv_match(hdr_as, US"none")
    || arc_cv_match(hdr_as, US"none") && as->instance != 1
    )
+  {
+  arc_state_reason = US"seal cv state";
   return US"fail";
+  }
 
 /*
        3.  Initialize a hash function corresponding to the "a" tag of
@@ -835,6 +856,7 @@ if (!exim_sha_init(&hhash_ctx, pdkim_hashes[hashtype].exim_hashmethod))
   {
   DEBUG(D_acl)
       debug_printf("ARC: hash setup error, possibly nonhandled hashtype\n");
+  arc_state_reason = US"seal hash setup error";
   return US"fail";
   }
 
@@ -844,6 +866,8 @@ if (!exim_sha_init(&hhash_ctx, pdkim_hashes[hashtype].exim_hashmethod))
            header canonicalization defined in Section 3.4.2 of
            [RFC6376].  Pass the canonicalized result to the hash
            function.
+
+Headers are CRLF-separated, but the last one is not crlf-terminated.
 */
 
 DEBUG(D_acl) debug_printf("ARC: AS header data for verification:\n");
@@ -874,7 +898,7 @@ for (as2 = ctx->arcset_chain;
   al = as2->hdr_as;
   if (as2->instance == as->instance)
     s = pdkim_relax_header_n(al->rawsig_no_b_val.data,
-                                       al->rawsig_no_b_val.len, TRUE);
+                                       al->rawsig_no_b_val.len, FALSE);
   else if (!(s = al->relaxed))
     al->relaxed = s = pdkim_relax_header_n(al->complete->text,
                                            al->complete->slen, TRUE);
@@ -891,7 +915,7 @@ exim_sha_finish(&hhash_ctx, &hhash_computed);
 DEBUG(D_acl)
   {
   debug_printf("ARC i=%d AS Header %.*s computed: ",
-    as->instance, hdr_as->a_hash.len, hdr_as->a_hash.data);
+    as->instance, (int)hdr_as->a_hash.len, hdr_as->a_hash.data);
   pdkim_hexprint(hhash_computed.data, hhash_computed.len);
   }
 
@@ -931,6 +955,7 @@ if ((errstr = exim_dkim_verify(&vctx,
   {
   DEBUG(D_acl)
     debug_printf("ARC i=%d AS headers verify: %s\n", as->instance, errstr);
+  arc_state_reason = US"seal sigverify error";
   return US"fail";
   }
 
@@ -969,6 +994,12 @@ acl_verify_arc(void)
 arc_ctx ctx = { NULL };
 const uschar * res;
 
+if (!dkim_verify_ctx)
+  {
+  DEBUG(D_acl) debug_printf("ARC: no DKIM verify context\n");
+  return NULL;
+  }
+
 /* AS evaluation, per
 https://tools.ietf.org/html/draft-ietf-dmarc-arc-protocol-10#section-6
 */
@@ -1072,8 +1103,7 @@ return r;
 
 
 /* Walk the given headers strings identifying each header, and construct
-a reverse-order list.  Also parse ARC-chain headers and build the chain
-struct, retaining pointers into the string.
+a reverse-order list.
 */
 
 static hdr_rlist *
@@ -1085,7 +1115,7 @@ hdr_rlist * rheaders = NULL;
 s = sigheaders ? sigheaders->s : NULL;
 if (s) while (*s)
   {
-  uschar * s2;
+  const uschar * s2 = s;
 
   /* This works for either NL or CRLF lines; also nul-termination */
   while (*++s2)
@@ -1306,10 +1336,8 @@ if (g->s[g->ptr - 1] == ':') g->ptr--;
 g = string_catn(g, US";\r\n\tb=;", 7);
 
 /* Include the pseudo-header in the accumulation */
-/*XXX should that be prepended rather than appended? */
-/*XXX also need to include at the verify stage */
 
-s = pdkim_relax_header_n(g->s + ams_off, g->ptr - ams_off, TRUE);
+s = pdkim_relax_header_n(g->s + ams_off, g->ptr - ams_off, FALSE);
 hdata = string_cat(hdata, s);
 
 /* Calculate the signature from the accumulation */
@@ -1353,7 +1381,7 @@ while ((methodspec = string_nextinlist(&resinfo, &sep, NULL, 0)))
          (c = *s) && c != ';' && c != ' ' && c != '\r' && c != '\n'; ) s++;
     return string_copyn(methodspec, s - methodspec);
     }
-return NULL;
+return US"none";
 }
 
 
@@ -1370,7 +1398,6 @@ arc_set * as;
 uschar * status = arc_ar_cv_status(ar);
 arc_line * al = store_get(sizeof(header_line) + sizeof(arc_line));
 header_line * h = (header_line *)(al+1);
-uschar * s;
 
 gstring * hdata = NULL;
 int hashtype = pdkim_hashname_to_hashtype(US"sha256", 6);      /*XXX hardwired */
@@ -1395,7 +1422,7 @@ arcset = string_append(NULL, 10,
          ARC_HDR_AS,
          US" i=", string_sprintf("%d", instance),
          US"; cv=", status,
-         US"; a=rsa-sha256; c=relaxed; d=", identity,          /*XXX hardwired */
+         US"; a=rsa-sha256; d=", identity,                     /*XXX hardwired */
          US"; s=", selector,                                   /*XXX same as AMS */
          US";\r\n\t b=;");
 
@@ -1419,7 +1446,7 @@ for (as = Ustrcmp(status, US"fail") == 0
   h = as->hdr_ams->complete;
   hdata = string_cat(hdata, pdkim_relax_header_n(h->text, h->slen, TRUE));
   h = as->hdr_as->complete;
-  hdata = string_cat(hdata, pdkim_relax_header_n(h->text, h->slen, TRUE));
+  hdata = string_cat(hdata, pdkim_relax_header_n(h->text, h->slen, !!as->next));
   }
 
 /* Calculate the signature from the accumulation */
@@ -1459,6 +1486,14 @@ return pdkim_set_bodyhash(&dkim_sign_ctx,
 
 
 
+void
+arc_sign_init(void)
+{
+memset(&arc_sign_ctx, 0, sizeof(arc_sign_ctx));
+}
+
+
+
 /* A "normal" header line, identified by DKIM processing.  These arrive before
 the call to arc_sign(), which carries any newly-created DKIM headers - and
 those go textually before the normal ones in the message.
@@ -1515,7 +1550,8 @@ selector = string_nextinlist(&signspec, &sep, NULL, 0);
 if (  !*identity | !*selector
    || !(privkey = string_nextinlist(&signspec, &sep, NULL, 0)) || !*privkey)
   {
-  log_write(0, LOG_MAIN|LOG_PANIC, "ARC: bad signing-specification");
+  log_write(0, LOG_MAIN|LOG_PANIC, "ARC: bad signing-specification (%s)",
+    !*identity ? "identity" : !*selector ? "selector" : "private-key");
   return NULL;
   }
 if (*privkey == '/' && !(privkey = expand_file_big_buffer(privkey)))
@@ -1523,12 +1559,8 @@ if (*privkey == '/' && !(privkey = expand_file_big_buffer(privkey)))
 
 DEBUG(D_transport) debug_printf("ARC: sign for %s\n", identity);
 
-/*
-- scan headers for existing ARC chain & A-R (with matching system-identfier)
-  - paniclog & skip on problems (no A-R)
-*/
-
-/* Make an rlist of any new DKIM headers, then add the "normals" rlist to it */
+/* Make an rlist of any new DKIM headers, then add the "normals" rlist to it.
+Then scan the list for an A-R header. */
 
 string_from_gstring(sigheaders);
 if ((rheaders = arc_sign_scan_headers(&arc_sign_ctx, sigheaders)))
@@ -1540,16 +1572,15 @@ if ((rheaders = arc_sign_scan_headers(&arc_sign_ctx, sigheaders)))
   }
 else
   rheaders = headers_rlist;
+
 /* Finally, build a normal-order headers list */
 /*XXX only needed for hunt-the-AR? */
-{
-header_line * hnext = NULL;
-for (; rheaders; hnext = rheaders->h, rheaders = rheaders->prev)
-  rheaders->h->next = hnext;
-headers = hnext;
-}
-
-instance = arc_sign_ctx.arcset_chain_last ? arc_sign_ctx.arcset_chain_last->instance + 1 : 1;
+  {
+  header_line * hnext = NULL;
+  for (; rheaders; hnext = rheaders->h, rheaders = rheaders->prev)
+    rheaders->h->next = hnext;
+  headers = hnext;
+  }
 
 if (!(arc_sign_find_ar(headers, identity, &ar)))
   {
@@ -1557,6 +1588,19 @@ if (!(arc_sign_find_ar(headers, identity, &ar)))
   return sigheaders ? sigheaders : string_get(0);
   }
 
+/* We previously built the data-struct for the existing ARC chain, if any, using a headers
+feed from the DKIM module.  Use that to give the instance number for the ARC set we are
+about to build. */
+
+DEBUG(D_transport)
+  if (arc_sign_ctx.arcset_chain_last)
+    debug_printf("ARC: existing chain highest instance: %d\n",
+      arc_sign_ctx.arcset_chain_last->instance);
+  else
+    debug_printf("ARC: no existing chain\n");
+
+instance = arc_sign_ctx.arcset_chain_last ? arc_sign_ctx.arcset_chain_last->instance + 1 : 1;
+
 /*
 - Generate AAR
   - copy the A-R; prepend i= & identity
@@ -1684,14 +1728,17 @@ authres_arc(gstring * g)
 if (arc_state)
   {
   arc_line * highest_ams;
-  int start;
+  int start = 0;               /* Compiler quietening */
   DEBUG(D_acl) start = g->ptr;
 
   g = string_append(g, 2, US";\n\tarc=", arc_state);
   if (arc_received_instance > 0)
     {
     g = string_append(g, 3, US" (i=",
-      string_sprintf("%d", arc_received_instance), US") header.s=");
+      string_sprintf("%d", arc_received_instance), US")");
+    if (arc_state_reason)
+      g = string_append(g, 3, US"(", arc_state_reason, US")");
+    g = string_catn(g, US" header.s=", 10);
     highest_ams = arc_received->hdr_ams;
     g = string_catn(g, highest_ams->s.data, highest_ams->s.len);
 
@@ -1701,6 +1748,8 @@ if (arc_state)
     if (sender_host_address)
       g = string_append(g, 2, US" smtp.client-ip=", sender_host_address);
     }
+  else if (arc_state_reason)
+    g = string_append(g, 3, US" (", arc_state_reason, US")");
   DEBUG(D_acl) debug_printf("ARC:  authres '%.*s'\n",
                  g->ptr - start - 3, g->s + start + 3);
   }