Debug: enhance output from smtp transport entry
[exim.git] / src / src / receive.c
index 4fb0c26cbc3f2026aeda3653db3a785e889d9c5d..2b6143a3244889d56f720040a5a8b9e70bea70fe 100644 (file)
@@ -190,7 +190,7 @@ if (STATVFS(CS path, &statbuf) != 0)
     log_write(0, LOG_MAIN|LOG_PANIC, "cannot accept message: failed to stat "
       "%s directory %s: %s", name, path, strerror(errno));
     smtp_closedown(US"spool or log directory problem");
-    exim_exit(EXIT_FAILURE);
+    exim_exit(EXIT_FAILURE, NULL);
     }
 
 *inodeptr = (statbuf.F_FILES > 0)? statbuf.F_FAVAIL : -1;
@@ -343,7 +343,7 @@ if (!already_bombing_out)
 
 /* Exit from the program (non-BSMTP cases) */
 
-exim_exit(EXIT_FAILURE);
+exim_exit(EXIT_FAILURE, NULL);
 }
 
 
@@ -1023,7 +1023,8 @@ int ch;
 
 /* Remember that this message uses wireformat. */
 
-DEBUG(D_receive) debug_printf("CHUNKING: writing spoolfile in wire format\n");
+DEBUG(D_receive) debug_printf("CHUNKING: %s\n",
+       fout ? "writing spoolfile in wire format" : "flushing input");
 spool_file_wireformat = TRUE;
 
 for (;;)
@@ -1077,9 +1078,10 @@ Returns:     nothing
 void
 receive_swallow_smtp(void)
 {
-/*XXX CHUNKING: not enough.  read chunks until RSET? */
 if (message_ended >= END_NOTENDED)
-  message_ended = read_message_data_smtp(NULL);
+  message_ended = chunking_state <= CHUNKING_OFFERED
+     ? read_message_data_smtp(NULL)
+     : read_message_bdat_smtp_wire(NULL);
 }
 
 
@@ -1142,7 +1144,7 @@ if (error_handling == ERRORS_SENDER)
 else
   fprintf(stderr, "exim: %s%s\n", text2, text1);  /* Sic */
 (void)fclose(f);
-exim_exit(error_rc);
+exim_exit(error_rc, US"");
 }
 
 
@@ -1810,8 +1812,8 @@ for (;;)
   (and sometimes lunatic messages can have ones that are 100s of K long) we
   call store_release() for strings that have been copied - if the string is at
   the start of a block (and therefore the only thing in it, because we aren't
-  doing any other gets), the block gets freed. We can only do this because we
-  know there are no other calls to store_get() going on. */
+  doing any other gets), the block gets freed. We can only do this release if
+  there were no allocations since the once that we want to free. */
 
   if (ptr >= header_size - 4)
     {
@@ -1819,12 +1821,7 @@ for (;;)
     /* header_size += 256; */
     header_size *= 2;
     if (!store_extend(next->text, oldsize, header_size))
-      {
-      uschar *newtext = store_get(header_size);
-      memcpy(newtext, next->text, ptr);
-      store_release(next->text);
-      next->text = newtext;
-      }
+      next->text = store_newblock(next->text, header_size, ptr);
     }
 
   /* Cope with receiving a binary zero. There is dispute about whether
@@ -1864,7 +1861,7 @@ for (;;)
   prevent further reading), and break out of the loop, having freed the
   empty header, and set next = NULL to indicate no data line. */
 
-  if (ptr == 0 && ch == '.' && (smtp_input || dot_ends))
+  if (ptr == 0 && ch == '.' && dot_ends)
     {
     ch = (receive_getc)(GETC_BUFFER_UNLIMITED);
     if (ch == '\r')
@@ -2051,32 +2048,30 @@ for (;;)
   these lines in SMTP messages. There is now an option to ignore them from
   specified hosts or networks. Sigh. */
 
-  if (header_last == header_list &&
-       (!smtp_input
-         ||
-         (sender_host_address != NULL &&
-           verify_check_host(&ignore_fromline_hosts) == OK)
-         ||
-         (sender_host_address == NULL && ignore_fromline_local)
-       ) &&
-       regex_match_and_setup(regex_From, next->text, 0, -1))
+  if (  header_last == header_list
+     && (  !smtp_input
+        || (  sender_host_address
+          && verify_check_host(&ignore_fromline_hosts) == OK
+          )
+        || (!sender_host_address && ignore_fromline_local)
+        )
+     && regex_match_and_setup(regex_From, next->text, 0, -1)
+     )
     {
     if (!sender_address_forced)
       {
       uschar *uucp_sender = expand_string(uucp_from_sender);
-      if (uucp_sender == NULL)
-        {
+      if (!uucp_sender)
         log_write(0, LOG_MAIN|LOG_PANIC,
           "expansion of \"%s\" failed after matching "
           "\"From \" line: %s", uucp_from_sender, expand_string_message);
-        }
       else
         {
         int start, end, domain;
         uschar *errmess;
         uschar *newsender = parse_extract_address(uucp_sender, &errmess,
           &start, &end, &domain, TRUE);
-        if (newsender != NULL)
+        if (newsender)
           {
           if (domain == 0 && newsender[0] != 0)
             newsender = rewrite_address_qualify(newsender, FALSE);
@@ -2171,13 +2166,11 @@ for (;;)
         }
 
       else
-        {
         give_local_error(ERRMESS_VLONGHDRLINE,
           string_sprintf("message header line longer than %d characters "
            "received: message not accepted", header_line_maxsize), US"",
            error_rc, stdin, header_list->next);
         /* Does not return */
-        }
       }
 
     /* Note if any resent- fields exist. */
@@ -2620,8 +2613,9 @@ letter and it is not used internally.
 NOTE: If ever the format of message ids is changed, the regular expression for
 checking that a string is in this format must be updated in a corresponding
 way. It appears in the initializing code in exim.c. The macro MESSAGE_ID_LENGTH
-must also be changed to reflect the correct string length. Then, of course,
-other programs that rely on the message id format will need updating too. */
+must also be changed to reflect the correct string length. The queue-sort code
+needs to know the layout. Then, of course, other programs that rely on the
+message id format will need updating too. */
 
 Ustrncpy(message_id, string_base62((long int)(message_id_tv.tv_sec)), 6);
 message_id[6] = '-';
@@ -3323,7 +3317,7 @@ if (extract_recip && (bad_addresses != NULL || recipients_count == 0))
     {
     Uunlink(spool_name);
     (void)fclose(data_file);
-    exim_exit(error_rc);
+    exim_exit(error_rc, US"receiving");
     }
   }
 
@@ -3387,99 +3381,96 @@ else
 #ifndef DISABLE_DKIM
     if (!dkim_disable_verify)
       {
-      /* Finish verification, this will log individual signature results to
-         the mainlog */
+      /* Finish verification */
       dkim_exim_verify_finish();
 
       /* Check if we must run the DKIM ACL */
       if (acl_smtp_dkim && dkim_verify_signers && *dkim_verify_signers)
         {
-        uschar *dkim_verify_signers_expanded =
+        uschar * dkim_verify_signers_expanded =
           expand_string(dkim_verify_signers);
-        if (!dkim_verify_signers_expanded)
+       gstring * results = NULL;
+       int signer_sep = 0;
+       const uschar * ptr;
+       uschar * item;
+       gstring * seen_items = NULL;
+       int old_pool = store_pool;
+
+       store_pool = POOL_PERM;   /* Allow created variables to live to data ACL */
+
+        if (!(ptr = dkim_verify_signers_expanded))
           log_write(0, LOG_MAIN|LOG_PANIC,
             "expansion of dkim_verify_signers option failed: %s",
             expand_string_message);
 
-        else
-          {
-          int sep = 0;
-          const uschar *ptr = dkim_verify_signers_expanded;
-          uschar *item = NULL;
-          gstring * seen_items = NULL;
-
-          /* Default to OK when no items are present */
-          rc = OK;
-          while ((item = string_nextinlist(&ptr, &sep, NULL, 0)))
-            {
-            /* Prevent running ACL for an empty item */
-            if (!item || !*item) continue;
-
-            /* Only run ACL once for each domain or identity,
-           no matter how often it appears in the expanded list. */
-            if (seen_items)
-              {
-              uschar *seen_item;
-              const uschar *seen_items_list = string_from_gstring(seen_items);
-              BOOL seen_this_item = FALSE;
-
-              while ((seen_item = string_nextinlist(&seen_items_list, &sep,
-                                                    NULL, 0)))
-               if (Ustrcmp(seen_item,item) == 0)
-                 {
-                 seen_this_item = TRUE;
-                 break;
-                 }
-
-              if (seen_this_item)
-                {
-                DEBUG(D_receive)
-                  debug_printf("acl_smtp_dkim: skipping signer %s, "
-                   "already seen\n", item);
-                continue;
-                }
-
-              seen_items = string_cat(seen_items, ":");
-              }
-
-            seen_items = string_cat(seen_items, item);
-
-            DEBUG(D_receive)
-              debug_printf("calling acl_smtp_dkim for dkim_cur_signer=%s\n",
-               item);
-
-            dkim_exim_acl_setup(item);
-            rc = acl_check(ACL_WHERE_DKIM, NULL, acl_smtp_dkim,
-                 &user_msg, &log_msg);
-
-            if (rc != OK)
+       /* Default to OK when no items are present */
+       rc = OK;
+       while ((item = string_nextinlist(&ptr, &signer_sep, NULL, 0)))
+         {
+         /* Prevent running ACL for an empty item */
+         if (!item || !*item) continue;
+
+         /* Only run ACL once for each domain or identity,
+         no matter how often it appears in the expanded list. */
+         if (seen_items)
+           {
+           uschar * seen_item;
+           const uschar * seen_items_list = string_from_gstring(seen_items);
+           int seen_sep = ':';
+           BOOL seen_this_item = FALSE;
+
+           while ((seen_item = string_nextinlist(&seen_items_list, &seen_sep,
+                                                 NULL, 0)))
+             if (Ustrcmp(seen_item,item) == 0)
+               {
+               seen_this_item = TRUE;
+               break;
+               }
+
+           if (seen_this_item)
              {
              DEBUG(D_receive)
-               debug_printf("acl_smtp_dkim: acl_check returned %d on %s, "
-                 "skipping remaining items\n", rc, item);
-             cancel_cutthrough_connection(TRUE, US"dkim acl not ok");
-             break;
+               debug_printf("acl_smtp_dkim: skipping signer %s, "
+                 "already seen\n", item);
+             continue;
              }
-            }
-          add_acl_headers(ACL_WHERE_DKIM, US"DKIM");
-          if (rc == DISCARD)
-            {
-            recipients_count = 0;
-            blackholed_by = US"DKIM ACL";
-            if (log_msg != NULL)
-              blackhole_log_msg = string_sprintf(": %s", log_msg);
-            }
-          else if (rc != OK)
-            {
-            Uunlink(spool_name);
-            if (smtp_handle_acl_fail(ACL_WHERE_DKIM, rc, user_msg, log_msg) != 0)
-              smtp_yield = FALSE;    /* No more messages after dropped connection */
-            smtp_reply = US"";       /* Indicate reply already sent */
-            message_id[0] = 0;       /* Indicate no message accepted */
-            goto TIDYUP;             /* Skip to end of function */
-            }
-          }
+
+           seen_items = string_catn(seen_items, US":", 1);
+           }
+         seen_items = string_cat(seen_items, item);
+
+         rc = dkim_exim_acl_run(item, &results, &user_msg, &log_msg);
+         if (rc != OK)
+           {
+           DEBUG(D_receive)
+             debug_printf("acl_smtp_dkim: acl_check returned %d on %s, "
+               "skipping remaining items\n", rc, item);
+           cancel_cutthrough_connection(TRUE, US"dkim acl not ok");
+           break;
+           }
+         }
+       dkim_verify_status = string_from_gstring(results);
+       store_pool = old_pool;
+       add_acl_headers(ACL_WHERE_DKIM, US"DKIM");
+       if (rc == DISCARD)
+         {
+         recipients_count = 0;
+         blackholed_by = US"DKIM ACL";
+         if (log_msg)
+           blackhole_log_msg = string_sprintf(": %s", log_msg);
+         }
+       else if (rc != OK)
+         {
+         Uunlink(spool_name);
+         if (smtp_handle_acl_fail(ACL_WHERE_DKIM, rc, user_msg, log_msg) != 0)
+           smtp_yield = FALSE;    /* No more messages after dropped connection */
+         smtp_reply = US"";       /* Indicate reply already sent */
+         message_id[0] = 0;       /* Indicate no message accepted */
+         goto TIDYUP;             /* Skip to end of function */
+         }
         }
+      else
+       dkim_exim_verify_log_all();
       }
 #endif /* DISABLE_DKIM */
 
@@ -3776,32 +3767,32 @@ else
   switch(rc)
     {
     default:
-    log_write(0, LOG_MAIN, "invalid return %d from local_scan(). Temporary "
-      "rejection given", rc);
-    goto TEMPREJECT;
+      log_write(0, LOG_MAIN, "invalid return %d from local_scan(). Temporary "
+       "rejection given", rc);
+      goto TEMPREJECT;
 
     case LOCAL_SCAN_REJECT_NOLOGHDR:
-    BIT_CLEAR(log_selector, log_selector_size, Li_rejected_header);
-    /* Fall through */
+      BIT_CLEAR(log_selector, log_selector_size, Li_rejected_header);
+      /* Fall through */
 
     case LOCAL_SCAN_REJECT:
-    smtp_code = US"550";
-    if (errmsg == NULL) errmsg =  US"Administrative prohibition";
-    break;
+      smtp_code = US"550";
+      if (!errmsg) errmsg =  US"Administrative prohibition";
+      break;
 
     case LOCAL_SCAN_TEMPREJECT_NOLOGHDR:
-    BIT_CLEAR(log_selector, log_selector_size, Li_rejected_header);
-    /* Fall through */
+      BIT_CLEAR(log_selector, log_selector_size, Li_rejected_header);
+      /* Fall through */
 
     case LOCAL_SCAN_TEMPREJECT:
     TEMPREJECT:
-    smtp_code = US"451";
-    if (errmsg == NULL) errmsg = US"Temporary local problem";
-    istemp = US"temporarily ";
-    break;
+      smtp_code = US"451";
+      if (!errmsg) errmsg = US"Temporary local problem";
+      istemp = US"temporarily ";
+      break;
     }
 
-  g = string_append(g, 2, US"F=",
+  g = string_append(NULL, 2, US"F=",
     sender_address[0] == 0 ? US"<>" : sender_address);
   g = add_host_info_for_log(g);