Fix race condition causing interleaved logs

The output of the `DUMP_HEADER` macro was being written in multiple calls to
fprintf() that raced with other logging, resulting in interleaved output that
intermittently failed the ja3_fingerprint AuTest on CI. Whether other AuTest
failures were related to the same issue is unknown at this point.

This fixes the race condition by batching the calls to a single fprintf() call.
This also refactors the macro to two inline functions. In a benchmark using an
expanded version of the headers in the HttpTransact tests, a 60% speedup was
measured over the macro if all the header data fit in the buffer. In the worst
case that the buffer could only hold a byte at a time, the speedup was 80%.
The benchmark was compiled with -O3 and stderr was piped to /dev/null.

These were the headers used for the benchmark:
```
  header input1[] = {
    {"AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA", "111111111111111111111111"},
    {"BBB",                               "222"                     },
    {"CCC",                               "333"                     },
    {"DDD",                               "333"                     },
    {"EEE",                               "333"                     },
    {"FFF",                               "333"                     },
    {"GGG",                               "333"                     },
    {"HHH",                               "333"                     },
    {"III",                               "333"                     },
    {"JJJ",                               "333"                     },
    {"KKK",                               "333"                     },
  };
```

This fixes #11431.

Author: JosiahWI

include/proxy/http/HttpTransact.h

@@ -25,6 +25,7 @@
 
 #include <cstddef>
 
+#include "tsutil/DbgCtl.h"
 #include "tscore/ink_assert.h"
 #include "tscore/ink_platform.h"
 #include "iocore/hostdb/HostDB.h"
@@ -45,31 +46,55 @@
 #include "proxy/ProxySession.h"
 #include "tscore/MgmtDefs.h"
 
+#include <cstdint>
+#include <cstdio>
+#include <string>
+#include <string_view>
+
 #define HTTP_OUR_VIA_MAX_LENGTH 1024 // 512-bytes for hostname+via string, 512-bytes for the debug info
 
 #define HTTP_RELEASE_ASSERT(X) ink_release_assert(X)
 
-#define DUMP_HEADER(C, H, I, S)                                 \
-  {                                                             \
-    if ((C).on()) {                                             \
-      fprintf(stderr, "+++++++++ %s +++++++++\n", S);           \
-      fprintf(stderr, "-- State Machine Id: %" PRId64 "\n", I); \
-      char b[4096];                                             \
-      int  used, tmp, offset;                                   \
-      int  done;                                                \
-      offset = 0;                                               \
-      if ((H)->valid()) {                                       \
-        do {                                                    \
-          used     = 0;                                         \
-          tmp      = offset;                                    \
-          done     = (H)->print(b, 4095, &used, &tmp);          \
-          offset  += used;                                      \
-          b[used]  = '\0';                                      \
-          fprintf(stderr, "%s", b);                             \
-        } while (!done);                                        \
-      }                                                         \
-    }                                                           \
+inline void
+s_dump_header(HTTPHdr const *hdr, std::string &out)
+{
+  int offset{0};
+  int done{0};
+  do {
+    int  used{0};
+    char b[4096];
+    // The buffer offset is taken non-const and it is apparently
+    // modified in some code path, but in my testing it does
+    // not change, it seems. Since we manually bump the offset,
+    // the use of tmp is precautionary to make sure our logic
+    // doesn't break in case it does change in some circumstance.
+    int tmp{offset};
+    done     = hdr->print(b, 4095, &used, &tmp);
+    offset  += used;
+    b[used]  = '\0';
+    out.append(b);
+  } while (0 == done);
+}
+
+inline void
+dump_header(DbgCtl const &ctl, HTTPHdr const *hdr, std::int64_t sm_id, std::string_view description)
+{
+  if (true) {
+    std::string output;
+    output.append("+++++++++ ");
+    output.append(description);
+    output.append(" +++++++++\n");
+    output.append("-- State Machine Id: ");
+    output.append(std::to_string(sm_id));
+    output.push_back('\n');
+    if (hdr->valid()) {
+      s_dump_header(hdr, output);
+    }
+    // We make a single call to fprintf so that the output does not get
+    // interleaved with output from other threads performing I/O.
+    fprintf(stderr, "%s", output.c_str());
   }
+}
 
 using ink_time_t = time_t;
 

src/proxy/http/HttpSM.cc

@@ -6599,7 +6599,7 @@ HttpSM::setup_server_send_request()
     t_state.hdr_info.server_request.value_set_int64(MIME_FIELD_CONTENT_LENGTH, MIME_LEN_CONTENT_LENGTH, msg_len);
   }
 
-  DUMP_HEADER(dbg_ctl_http_hdrs, &(t_state.hdr_info.server_request), sm_id, "Proxy's Request after hooks");
+  dump_header(dbg_ctl_http_hdrs, &(t_state.hdr_info.server_request), sm_id, "Proxy's Request after hooks");
 
   // We need a reader so bytes don't fall off the end of
   //  the buffer
@@ -8483,7 +8483,7 @@ HttpSM::redirect_request(const char *arg_redirect_url, const int arg_redirect_le
     }
   }
 
-  DUMP_HEADER(dbg_ctl_http_hdrs, &t_state.hdr_info.client_request, sm_id, "Framed Client Request..checking");
+  dump_header(dbg_ctl_http_hdrs, &t_state.hdr_info.client_request, sm_id, "Framed Client Request..checking");
 }
 
 void

src/proxy/http/HttpTransact.cc

@@ -1022,7 +1022,7 @@ HttpTransact::StartRemapRequest(State *s)
     TxnDbg(dbg_ctl_http_trans, "Before Remapping:");
     obj_describe(s->hdr_info.client_request.m_http, true);
   }
-  DUMP_HEADER(dbg_ctl_http_hdrs, &s->hdr_info.client_request, s->state_machine_id(), "Incoming Request");
+  dump_header(dbg_ctl_http_hdrs, &s->hdr_info.client_request, s->state_machine_id(), "Incoming Request");
 
   if (s->http_config_param->referer_filter_enabled) {
     s->filter_mask = URL_REMAP_FILTER_REFERER;
@@ -2264,9 +2264,9 @@ HttpTransact::HandlePushResponseHdr(State *s)
   s->hdr_info.server_request.method_set(HTTP_METHOD_GET, HTTP_LEN_GET);
   s->hdr_info.server_request.value_set("X-Inktomi-Source", 16, "http PUSH", 9);
 
-  DUMP_HEADER(dbg_ctl_http_hdrs, &s->hdr_info.server_response, s->state_machine_id(), "Pushed Response Header");
+  dump_header(dbg_ctl_http_hdrs, &s->hdr_info.server_response, s->state_machine_id(), "Pushed Response Header");
 
-  DUMP_HEADER(dbg_ctl_http_hdrs, &s->hdr_info.server_request, s->state_machine_id(), "Generated Request Header");
+  dump_header(dbg_ctl_http_hdrs, &s->hdr_info.server_request, s->state_machine_id(), "Generated Request Header");
 
   s->response_received_time = s->request_sent_time = ink_local_time();
 
@@ -2447,7 +2447,7 @@ HttpTransact::issue_revalidate(State *s)
     // the client has the right credentials
     // this cache action is just to get us into the hcoofsr function
     s->cache_info.action = CACHE_DO_UPDATE;
-    DUMP_HEADER(dbg_ctl_http_hdrs, &s->hdr_info.server_request, s->state_machine_id(), "Proxy's Request (Conditionalized)");
+    dump_header(dbg_ctl_http_hdrs, &s->hdr_info.server_request, s->state_machine_id(), "Proxy's Request (Conditionalized)");
     return;
   }
 
@@ -2520,7 +2520,7 @@ HttpTransact::issue_revalidate(State *s)
       if (str) {
         s->hdr_info.server_request.value_set(MIME_FIELD_IF_MODIFIED_SINCE, MIME_LEN_IF_MODIFIED_SINCE, str, length);
       }
-      DUMP_HEADER(dbg_ctl_http_hdrs, &s->hdr_info.server_request, s->state_machine_id(), "Proxy's Request (Conditionalized)");
+      dump_header(dbg_ctl_http_hdrs, &s->hdr_info.server_request, s->state_machine_id(), "Proxy's Request (Conditionalized)");
     }
     // if Etag exists, also add if-non-match header
     if (c_resp->presence(MIME_PRESENCE_ETAG) && (s->hdr_info.server_request.method_get_wksidx() == HTTP_WKSIDX_GET ||
@@ -2534,7 +2534,7 @@ HttpTransact::issue_revalidate(State *s)
         }
         s->hdr_info.server_request.value_set(MIME_FIELD_IF_NONE_MATCH, MIME_LEN_IF_NONE_MATCH, etag, length);
       }
-      DUMP_HEADER(dbg_ctl_http_hdrs, &s->hdr_info.server_request, s->state_machine_id(), "Proxy's Request (Conditionalized)");
+      dump_header(dbg_ctl_http_hdrs, &s->hdr_info.server_request, s->state_machine_id(), "Proxy's Request (Conditionalized)");
     }
     break;
   case HTTP_STATUS_NON_AUTHORITATIVE_INFORMATION: // 203
@@ -3430,7 +3430,7 @@ HttpTransact::HandleResponse(State *s)
   s->current.now = s->response_received_time;
 
   TxnDbg(dbg_ctl_http_trans, "response_received_time: %" PRId64, (int64_t)s->response_received_time);
-  DUMP_HEADER(dbg_ctl_http_hdrs, &s->hdr_info.server_response, s->state_machine_id(), "Incoming O.S. Response");
+  dump_header(dbg_ctl_http_hdrs, &s->hdr_info.server_response, s->state_machine_id(), "Incoming O.S. Response");
 
   Metrics::Counter::increment(http_rsb.incoming_responses);
 
@@ -4074,7 +4074,7 @@ HttpTransact::build_response_copy(State *s, HTTPHdr *base_response, HTTPHdr *out
   HttpTransactHeaders::convert_response(outgoing_version, outgoing_response); // http version conversion
   HttpTransactHeaders::add_server_header_to_response(s->txn_conf, outgoing_response);
 
-  DUMP_HEADER(dbg_ctl_http_hdrs, outgoing_response, s->state_machine_id(), "Proxy's Response");
+  dump_header(dbg_ctl_http_hdrs, outgoing_response, s->state_machine_id(), "Proxy's Response");
 }
 
 //////////////////////////////////////////////////////////////////////////
@@ -4616,7 +4616,7 @@ HttpTransact::handle_cache_operation_on_forward_server_response(State *s)
                                                  warn_text, strlen(warn_text));
     }
 
-    DUMP_HEADER(dbg_ctl_http_hdrs, &s->hdr_info.client_response, s->state_machine_id(), "Proxy's Response (Client Conditionals)");
+    dump_header(dbg_ctl_http_hdrs, &s->hdr_info.client_response, s->state_machine_id(), "Proxy's Response (Client Conditionals)");
     return;
   }
   // all other responses (not 304, 412, 416) are handled here
@@ -4839,7 +4839,7 @@ HttpTransact::handle_transform_ready(State *s)
   s->pre_transform_source = s->source;
   s->source               = SOURCE_TRANSFORM;
 
-  DUMP_HEADER(dbg_ctl_http_hdrs, &s->hdr_info.transform_response, s->state_machine_id(), "Header From Transform");
+  dump_header(dbg_ctl_http_hdrs, &s->hdr_info.transform_response, s->state_machine_id(), "Header From Transform");
 
   build_response(s, &s->hdr_info.transform_response, &s->hdr_info.client_response, s->client_info.http_version);
 
@@ -4887,7 +4887,7 @@ HttpTransact::set_header_for_transform(State *s, HTTPHdr *base_header)
   //   in the chain
   s->hdr_info.transform_response.field_delete(MIME_FIELD_CONTENT_LENGTH, MIME_LEN_CONTENT_LENGTH);
 
-  DUMP_HEADER(dbg_ctl_http_hdrs, &s->hdr_info.transform_response, s->state_machine_id(), "Header To Transform");
+  dump_header(dbg_ctl_http_hdrs, &s->hdr_info.transform_response, s->state_machine_id(), "Header To Transform");
 }
 
 void
@@ -4947,7 +4947,7 @@ HttpTransact::set_headers_for_cache_write(State *s, HTTPInfo *cache_info, HTTPHd
     cache_info->response_get()->field_delete(MIME_FIELD_WWW_AUTHENTICATE, MIME_LEN_WWW_AUTHENTICATE);
   }
 
-  DUMP_HEADER(dbg_ctl_http_hdrs, cache_info->request_get(), s->state_machine_id(), "Cached Request Hdr");
+  dump_header(dbg_ctl_http_hdrs, cache_info->request_get(), s->state_machine_id(), "Cached Request Hdr");
 }
 
 void
@@ -7770,7 +7770,7 @@ HttpTransact::build_request(State *s, HTTPHdr *base_request, HTTPHdr *outgoing_r
   ink_assert(s->request_sent_time >= s->response_received_time);
 
   TxnDbg(dbg_ctl_http_trans, "request_sent_time: %" PRId64, (int64_t)s->request_sent_time);
-  DUMP_HEADER(dbg_ctl_http_hdrs, outgoing_request, s->state_machine_id(), "Proxy's Request");
+  dump_header(dbg_ctl_http_hdrs, outgoing_request, s->state_machine_id(), "Proxy's Request");
 
   Metrics::Counter::increment(http_rsb.outgoing_requests);
 }
@@ -7943,10 +7943,10 @@ HttpTransact::build_response(State *s, HTTPHdr *base_response, HTTPHdr *outgoing
 
   if (dbg_ctl_http_hdrs.on()) {
     if (base_response) {
-      DUMP_HEADER(dbg_ctl_http_hdrs, base_response, s->state_machine_id(), "Base Header for Building Response");
+      dump_header(dbg_ctl_http_hdrs, base_response, s->state_machine_id(), "Base Header for Building Response");
     }
 
-    DUMP_HEADER(dbg_ctl_http_hdrs, outgoing_response, s->state_machine_id(), "Proxy's Response 2");
+    dump_header(dbg_ctl_http_hdrs, outgoing_response, s->state_machine_id(), "Proxy's Response 2");
   }
 
   return;