Fix race condition causing interleaved logs

doc/developer-guide/api/functions/TSMimeHdrPrint.en.rst

@@ -28,10 +28,10 @@ Synopsis
 
     #include <ts/ts.h>
 
-.. function:: void TSMimeHdrPrint(TSMBuffer bufp, TSMLoc offset, TSIOBuffer iobufp)
+.. function:: void TSMimeHdrPrint(TSMLoc offset, TSIOBuffer iobufp)
 
 Description
 ===========
 
-Formats the MIME header located at :arg:`hdr_loc` within :arg:`bufp` into the
+Formats the MIME header located at :arg:`hdr_loc` into the
 :cpp:type:`TSIOBuffer` :arg:`iobufp`.

example/plugins/c-api/cache_scan/cache_scan.cc

@@ -144,7 +144,7 @@ handle_scan(TSCont contp, TSEvent event, void *edata)
     // print the response headers
     TSCacheHttpInfoRespGet(cache_infop, &resp_bufp, &resp_hdr_loc);
     cstate->total_bytes += TSMimeHdrLengthGet(resp_bufp, resp_hdr_loc);
-    TSMimeHdrPrint(resp_bufp, resp_hdr_loc, cstate->resp_buffer);
+    TSMimeHdrPrint(resp_hdr_loc, cstate->resp_buffer);
     TSHandleMLocRelease(resp_bufp, TS_NULL_MLOC, resp_hdr_loc);
 
     cstate->total_bytes += TSIOBufferWrite(cstate->resp_buffer, s2, sizeof(s2) - 1);

example/plugins/c-api/output_header/output_header.cc

@@ -74,7 +74,7 @@ handle_dns(TSHttpTxn txnp, TSCont contp ATS_UNUSED)
   /* This will print  just MIMEFields and not
      the http request line */
   Dbg(dbg_ctl, "Printing the hdrs ... ");
-  TSMimeHdrPrint(bufp, hdr_loc, output_buffer);
+  TSMimeHdrPrint(hdr_loc, output_buffer);
 
   if (TSHandleMLocRelease(bufp, TS_NULL_MLOC, hdr_loc) == TS_ERROR) {
     Dbg(dbg_ctl, "non-fatal: error releasing MLoc");

include/proxy/hdrs/HTTP.h

@@ -428,7 +428,7 @@ void         http_hdr_init(HdrHeap *heap, HTTPHdrImpl *hh, HTTPType polarity, HT
 HTTPHdrImpl *http_hdr_clone(HTTPHdrImpl *s_hh, HdrHeap *s_heap, HdrHeap *d_heap);
 void         http_hdr_copy_onto(HTTPHdrImpl *s_hh, HdrHeap *s_heap, HTTPHdrImpl *d_hh, HdrHeap *d_heap, bool inherit_strs);
 
-int http_hdr_print(HdrHeap *heap, HTTPHdrImpl *hh, char *buf, int bufsize, int *bufindex, int *dumpoffset);
+int http_hdr_print(HTTPHdrImpl const *hh, char *buf, int bufsize, int *bufindex, int *dumpoffset);
 
 void http_hdr_describe(HdrHeapObjImpl *obj, bool recurse = true);
 
@@ -506,7 +506,7 @@ class HTTPHdr : public MIMEHdr
 
   int unmarshal(char *buf, int len, RefCountObj *block_ref);
 
-  int print(char *buf, int bufsize, int *bufindex, int *dumpoffset);
+  int print(char *buf, int bufsize, int *bufindex, int *dumpoffset) const;
 
   int length_get() const;
 
@@ -761,10 +761,10 @@ HTTPHdr::copy_shallow(const HTTPHdr *hdr)
   -------------------------------------------------------------------------*/
 
 inline int
-HTTPHdr::print(char *buf, int bufsize, int *bufindex, int *dumpoffset)
+HTTPHdr::print(char *buf, int bufsize, int *bufindex, int *dumpoffset) const
 {
   ink_assert(valid());
-  return http_hdr_print(m_heap, m_http, buf, bufsize, bufindex, dumpoffset);
+  return http_hdr_print(m_http, buf, bufsize, bufindex, dumpoffset);
 }
 
 /*-------------------------------------------------------------------------
@@ -1068,7 +1068,7 @@ HTTPHdr::url_set(const char *str, int length)
   -------------------------------------------------------------------------*/
 
 inline HTTPStatus
-http_hdr_status_get(HTTPHdrImpl *hh)
+http_hdr_status_get(HTTPHdrImpl const *hh)
 {
   ink_assert(hh->m_polarity == HTTP_TYPE_RESPONSE);
   return (HTTPStatus)hh->u.resp.m_status;

include/proxy/hdrs/MIME.h

@@ -903,13 +903,12 @@ ParseResult mime_parser_parse(MIMEParser *parser, HdrHeap *heap, MIMEHdrImpl *mh
 void mime_hdr_describe(HdrHeapObjImpl *raw, bool recurse);
 void mime_field_block_describe(HdrHeapObjImpl *raw, bool recurse);
 
-int mime_hdr_print(HdrHeap *heap, MIMEHdrImpl *mh, char *buf_start, int buf_length, int *buf_index_inout,
-                   int *buf_chars_to_skip_inout);
+int mime_hdr_print(MIMEHdrImpl const *mh, char *buf_start, int buf_length, int *buf_index_inout, int *buf_chars_to_skip_inout);
 int mime_mem_print(const char *src_d, int src_l, char *buf_start, int buf_length, int *buf_index_inout,
                    int *buf_chars_to_skip_inout);
 int mime_mem_print_lc(const char *src_d, int src_l, char *buf_start, int buf_length, int *buf_index_inout,
                       int *buf_chars_to_skip_inout);
-int mime_field_print(MIMEField *field, char *buf_start, int buf_length, int *buf_index_inout, int *buf_chars_to_skip_inout);
+int mime_field_print(MIMEField const *field, char *buf_start, int buf_length, int *buf_index_inout, int *buf_chars_to_skip_inout);
 
 const char *mime_str_u16_set(HdrHeap *heap, const char *s_str, int s_len, const char **d_str, uint16_t *d_len, bool must_copy);
 
@@ -1409,7 +1408,7 @@ MIMEHdr::presence(uint64_t mask) const
 inline int
 MIMEHdr::print(char *buf, int bufsize, int *bufindex, int *chars_to_skip)
 {
-  return mime_hdr_print(m_heap, m_mime, buf, bufsize, bufindex, chars_to_skip);
+  return mime_hdr_print(m_mime, buf, bufsize, bufindex, chars_to_skip);
 }
 
 /*-------------------------------------------------------------------------

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,56 @@
 #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, 4096, &used, &tmp);
+    offset += used;
+    out.append(b, used);
+  } while (0 == done);
+}
+
+inline void
+dump_header(DbgCtl const &ctl, HTTPHdr const *hdr, std::int64_t sm_id, std::string_view description)
+{
+  if (ctl.on()) {
+    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);
+    } else {
+      output.append("Invalid header!\n");
+    }
+    // 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;
 

include/ts/ts.h

@@ -879,16 +879,14 @@ TSReturnCode TSMimeHdrClone(TSMBuffer dest_bufp, TSMBuffer src_bufp, TSMLoc src_
 TSReturnCode TSMimeHdrCopy(TSMBuffer dest_bufp, TSMLoc dest_offset, TSMBuffer src_bufp, TSMLoc src_offset);
 
 /**
-    Formats the MIME header located at hdr_loc within bufp into the
+    Formats the MIME header located at hdr_loc into the
     TSIOBuffer iobufp.
 
-    @param bufp marshal buffer containing the header to be copied to
-      an TSIOBuffer.
-    @param offset
+    @param offset The offset of the header to be copied to a TSIOBuffer.
     @param iobufp target TSIOBuffer.
 
  */
-void TSMimeHdrPrint(TSMBuffer bufp, TSMLoc offset, TSIOBuffer iobufp);
+void TSMimeHdrPrint(TSMLoc offset, TSIOBuffer iobufp);
 
 /**
     Parses a MIME header. The MIME header must have already been

plugins/background_fetch/background_fetch.cc

@@ -388,7 +388,7 @@ cont_bg_fetch(TSCont contp, TSEvent event, void * /* edata ATS_UNUSED */)
         break;
       }
       Dbg(Bg_dbg_ctl, "Starting background fetch, replaying:");
-      dump_headers(data->mbuf, data->hdr_loc);
+      dump_headers(data->hdr_loc);
     }
 
     // Setup the NetVC for background fetch

plugins/background_fetch/headers.cc

@@ -95,14 +95,14 @@ set_header(TSMBuffer bufp, TSMLoc hdr_loc, const char *header, int len, const ch
 ///////////////////////////////////////////////////////////////////////////
 // Dump a header on stderr, useful together with Dbg().
 void
-dump_headers(TSMBuffer bufp, TSMLoc hdr_loc)
+dump_headers(TSMLoc hdr_loc)
 {
   TSIOBuffer       output_buffer = TSIOBufferCreate();
   TSIOBufferReader reader        = TSIOBufferReaderAlloc(output_buffer);
   int64_t          block_avail   = 0;
 
   /* This will print  just MIMEFields and not the http request line */
-  TSMimeHdrPrint(bufp, hdr_loc, output_buffer);
+  TSMimeHdrPrint(hdr_loc, output_buffer);
 
   /* We need to loop over all the buffer blocks, there can be more than 1 */
   TSIOBufferBlock block = TSIOBufferReaderStart(reader);

plugins/background_fetch/headers.h

@@ -26,4 +26,4 @@
 
 int  remove_header(TSMBuffer bufp, TSMLoc hdr_loc, const char *header, int len);
 bool set_header(TSMBuffer bufp, TSMLoc hdr_loc, const char *header, int len, const char *val, int val_len);
-void dump_headers(TSMBuffer bufp, TSMLoc hdr_loc);
+void dump_headers(TSMLoc hdr_loc);

plugins/experimental/cache_fill/background_fetch.cc

@@ -93,7 +93,7 @@ set_header(TSMBuffer bufp, TSMLoc hdr_loc, const char *header, int len, const ch
 ///////////////////////////////////////////////////////////////////////////
 // Dump a header on stderr, useful together with Dbg().
 static void
-dump_headers(TSMBuffer bufp, TSMLoc hdr_loc)
+dump_headers(TSMLoc hdr_loc)
 {
   TSIOBuffer       output_buffer;
   TSIOBufferReader reader;
@@ -104,7 +104,7 @@ dump_headers(TSMBuffer bufp, TSMLoc hdr_loc)
   reader        = TSIOBufferReaderAlloc(output_buffer);
 
   /* This will print  just MIMEFields and not the http request line */
-  TSMimeHdrPrint(bufp, hdr_loc, output_buffer);
+  TSMimeHdrPrint(hdr_loc, output_buffer);
 
   /* We need to loop over all the buffer blocks, there can be more than 1 */
   block = TSIOBufferReaderStart(reader);
@@ -241,7 +241,7 @@ cont_bg_fetch(TSCont contp, TSEvent event, void * /* edata ATS_UNUSED */)
         break;
       }
       Dbg(dbg_ctl, "Starting background fetch, replaying:");
-      dump_headers(data->mbuf, data->hdr_loc);
+      dump_headers(data->hdr_loc);
     }
 
     // Setup the NetVC for background fetch

plugins/experimental/stale_response/CacheUpdate.cc

@@ -44,7 +44,7 @@ const int  SERVER_INTERCEPT_HEADER_LEN = sizeof(SERVER_INTERCEPT_HEADER) - 1;
 
 /*-----------------------------------------------------------------------------------------------*/
 static char *
-convert_mime_hdr_to_string(TSMBuffer bufp, TSMLoc hdr_loc)
+convert_mime_hdr_to_string(TSMLoc hdr_loc)
 {
   TSIOBuffer       output_buffer;
   TSIOBufferReader reader;
@@ -67,7 +67,7 @@ convert_mime_hdr_to_string(TSMBuffer bufp, TSMLoc hdr_loc)
 
   /* This will print  just MIMEFields and not
      the http request line */
-  TSMimeHdrPrint(bufp, hdr_loc, output_buffer);
+  TSMimeHdrPrint(hdr_loc, output_buffer);
 
   /* Find out how the big the complete header is by
      seeing the total bytes in the buffer.  We need to
@@ -341,7 +341,7 @@ intercept_fetch_the_url(StateInfo *state)
   get_request.append(tmpStr, 8);
   get_request.append("\r\n");
 
-  char *allReqHeaders = convert_mime_hdr_to_string(state->req_info->http_hdr_buf, state->req_info->http_hdr_loc);
+  char *allReqHeaders = convert_mime_hdr_to_string(state->req_info->http_hdr_loc);
   get_request.append(allReqHeaders);
   TSfree(allReqHeaders);
   get_request.append("\r\n");

plugins/prefetch/fetch.cc

@@ -690,7 +690,7 @@ BgFetch::handler(TSCont contp, TSEvent event, void * /* edata ATS_UNUSED */)
         break;
       }
       PrefetchDebug("Starting background fetch.");
-      dumpHeaders(fetch->_mbuf, fetch->_headerLoc);
+      dumpHeaders(fetch->_headerLoc);
     }
 
     // Setup the NetVC for background fetch

plugins/prefetch/headers.cc

@@ -178,11 +178,10 @@ setHeader(TSMBuffer bufp, TSMLoc hdrLoc, const char *header, int headerlen, cons
  *
  * Useful together with Dbg().
  *
- * @param bufp request's buffer
  * @param hdrLoc request's header location
  */
 void
-dumpHeaders(TSMBuffer bufp, TSMLoc hdrLoc)
+dumpHeaders(TSMLoc hdrLoc)
 {
   TSIOBuffer       output_buffer;
   TSIOBufferReader reader;
@@ -194,7 +193,7 @@ dumpHeaders(TSMBuffer bufp, TSMLoc hdrLoc)
   reader        = TSIOBufferReaderAlloc(output_buffer);
 
   /* This will print  just MIMEFields and not the http request line */
-  TSMimeHdrPrint(bufp, hdrLoc, output_buffer);
+  TSMimeHdrPrint(hdrLoc, output_buffer);
 
   /* We need to loop over all the buffer blocks, there can be more than 1 */
   block = TSIOBufferReaderStart(reader);

plugins/prefetch/headers.h

@@ -28,4 +28,4 @@ bool  headerExist(TSMBuffer bufp, TSMLoc hdr_loc, const char *header, int len);
 char *getHeader(TSMBuffer bufp, TSMLoc hdr_loc, const char *header, int headerlen, char *value, int *valuelen);
 
 bool setHeader(TSMBuffer bufp, TSMLoc hdr_loc, const char *header, int len, const char *val, int val_len);
-void dumpHeaders(TSMBuffer bufp, TSMLoc hdr_loc);
+void dumpHeaders(TSMLoc hdr_loc);

src/api/InkAPI.cc

@@ -1516,19 +1516,17 @@ TSMimeHdrCopy(TSMBuffer dest_bufp, TSMLoc dest_obj, TSMBuffer src_bufp, TSMLoc s
 }
 
 void
-TSMimeHdrPrint(TSMBuffer bufp, TSMLoc obj, TSIOBuffer iobufp)
+TSMimeHdrPrint(TSMLoc obj, TSIOBuffer iobufp)
 {
-  sdk_assert(sdk_sanity_check_mbuffer(bufp) == TS_SUCCESS);
   sdk_assert((sdk_sanity_check_mime_hdr_handle(obj) == TS_SUCCESS) || (sdk_sanity_check_http_hdr_handle(obj) == TS_SUCCESS));
   sdk_assert(sdk_sanity_check_iocore_structure(iobufp) == TS_SUCCESS);
 
-  HdrHeap       *heap = ((HdrHeapSDKHandle *)bufp)->m_heap;
-  MIMEHdrImpl   *mh   = _hdr_mloc_to_mime_hdr_impl(obj);
-  MIOBuffer     *b    = (MIOBuffer *)iobufp;
-  IOBufferBlock *blk;
-  int            bufindex;
-  int            tmp, dumpoffset = 0;
-  int            done;
+  MIMEHdrImpl const *mh = _hdr_mloc_to_mime_hdr_impl(obj);
+  MIOBuffer         *b  = (MIOBuffer *)iobufp;
+  IOBufferBlock     *blk;
+  int                bufindex;
+  int                tmp, dumpoffset = 0;
+  int                done;
 
   do {
     blk = b->get_current_block();
@@ -1539,7 +1537,7 @@ TSMimeHdrPrint(TSMBuffer bufp, TSMLoc obj, TSIOBuffer iobufp)
 
     bufindex = 0;
     tmp      = dumpoffset;
-    done     = mime_hdr_print(heap, mh, blk->end(), blk->write_avail(), &bufindex, &tmp);
+    done     = mime_hdr_print(mh, blk->end(), blk->write_avail(), &bufindex, &tmp);
 
     dumpoffset += bufindex;
     b->fill(bufindex);