Add escape json for logging

doc/admin-guide/logging/formatting.en.rst

@@ -39,7 +39,8 @@ fairly simple: every format must contain a ``Format`` attribute, which is the
 string defining the contents of each line in the log, and may also contain an
 optional ``Interval`` attribute defining the log aggregation interval for
 any logs which use the format (see :ref:`admin-logging-type-summary` for more
-information).
+information). It may also contain an optional ``escape`` attribute defining the
+escape of log fields. Possible values for ``escape`` are ``json`` or ``none``.
 
 The return value from the ``format`` function is the log format object which
 may then be supplied to the appropriate ``log.*`` functions that define your
@@ -880,3 +881,8 @@ Some examples below ::
   '%<cqup[0:30]>' // the first 30 characters of <cqup>.
   '%<cqup[-10:]>' // the last 10 characters of <cqup>.
   '%<cqup[:-5]>'  // everything except the last 5 characters of <cqup>.
+
+Note when ``escape`` in ``format`` is set to ``json``, the start is the
+position before escaping JSON strings, and escaped values are sliced at
+the length (= end - start). If slicing cuts in the middle of escaped
+characters, the whole character is removed.

proxy/logging/LogAccess.cc

@@ -643,6 +643,141 @@ LogAccess::unmarshal_str(char **buf, char *dest, int len, LogSlice *slice)
   return -1;
 }
 
+namespace
+{
+class EscLookup
+{
+public:
+  static const char NO_ESCAPE{'\0'};
+  static const char LONG_ESCAPE{'\x01'};
+
+  static char
+  result(char c)
+  {
+    return _lu.table[static_cast<unsigned char>(c)];
+  }
+
+private:
+  struct _LUT {
+    _LUT();
+
+    char table[1 << 8];
+  };
+
+  inline static _LUT const _lu;
+};
+
+EscLookup::_LUT::_LUT()
+{
+  for (unsigned i = 0; i < ' '; ++i) {
+    table[i] = LONG_ESCAPE;
+  }
+  for (unsigned i = '\x7f'; i < sizeof(table); ++i) {
+    table[i] = LONG_ESCAPE;
+  }
+
+  // Short escapes.
+  //
+  table[static_cast<int>('\b')] = 'b';
+  table[static_cast<int>('\t')] = 't';
+  table[static_cast<int>('\n')] = 'n';
+  table[static_cast<int>('\f')] = 'f';
+  table[static_cast<int>('\r')] = 'r';
+  table[static_cast<int>('\\')] = '\\';
+  table[static_cast<int>('\"')] = '"';
+  table[static_cast<int>('/')]  = '/';
+}
+
+char
+nibble(int nib)
+{
+  return nib >= 0xa ? 'a' + (nib - 0xa) : '0' + nib;
+}
+
+} // end anonymous namespace
+
+static int
+escape_json(char *dest, const char *buf, int len)
+{
+  int escaped_len = 0;
+
+  for (int i = 0; i < len; i++) {
+    char c  = buf[i];
+    char ec = EscLookup::result(c);
+    if (__builtin_expect(EscLookup::NO_ESCAPE == ec, 1)) {
+      if (dest) {
+        if (escaped_len + 1 > len) {
+          break;
+        }
+        *dest++ = c;
+      }
+      escaped_len++;
+
+    } else if (EscLookup::LONG_ESCAPE == ec) {
+      if (dest) {
+        if (escaped_len + 6 > len) {
+          break;
+        }
+        *dest++ = '\\';
+        *dest++ = 'u';
+        *dest++ = '0';
+        *dest++ = '0';
+        *dest++ = nibble(static_cast<unsigned char>(c) >> 4);
+        *dest++ = nibble(c & 0x0f);
+      }
+      escaped_len += 6;
+
+    } else { // Short escape.
+      if (dest) {
+        if (escaped_len + 2 > len) {
+          break;
+        }
+        *dest++ = '\\';
+        *dest++ = ec;
+      }
+      escaped_len += 2;
+    }
+  } // end for
+  return escaped_len;
+}
+
+int
+LogAccess::unmarshal_str_json(char **buf, char *dest, int len, LogSlice *slice)
+{
+  Debug("log-escape", "unmarshal_str_json start, len=%d, slice=%p", len, slice);
+  ink_assert(buf != nullptr);
+  ink_assert(*buf != nullptr);
+  ink_assert(dest != nullptr);
+
+  char *val_buf   = *buf;
+  int val_len     = static_cast<int>(::strlen(val_buf));
+  int escaped_len = escape_json(nullptr, val_buf, val_len);
+
+  *buf += LogAccess::strlen(val_buf); // this is how it was stored
+
+  if (slice && slice->m_enable) {
+    int offset, n;
+
+    n = slice->toStrOffset(escaped_len, &offset);
+    Debug("log-escape", "unmarshal_str_json start, n=%d, offset=%d", n, offset);
+    if (n <= 0) {
+      return 0;
+    }
+
+    if (n >= len) {
+      return -1;
+    }
+
+    return escape_json(dest, (val_buf + offset), n);
+  }
+
+  if (escaped_len < len) {
+    escape_json(dest, val_buf, escaped_len);
+    return escaped_len;
+  }
+  return -1;
+}
+
 int
 LogAccess::unmarshal_ttmsf(char **buf, char *dest, int len)
 {
@@ -813,6 +948,34 @@ LogAccess::unmarshal_http_text(char **buf, char *dest, int len, LogSlice *slice)
   return res1 + res2 + res3 + 2;
 }
 
+int
+LogAccess::unmarshal_http_text_json(char **buf, char *dest, int len, LogSlice *slice)
+{
+  ink_assert(buf != nullptr);
+  ink_assert(*buf != nullptr);
+  ink_assert(dest != nullptr);
+
+  char *p = dest;
+
+  int res1 = unmarshal_str_json(buf, p, len);
+  if (res1 < 0) {
+    return -1;
+  }
+  p += res1;
+  *p++     = ' ';
+  int res2 = unmarshal_str_json(buf, p, len - res1 - 1, slice);
+  if (res2 < 0) {
+    return -1;
+  }
+  p += res2;
+  *p++     = ' ';
+  int res3 = unmarshal_http_version(buf, p, len - res1 - res2 - 2);
+  if (res3 < 0) {
+    return -1;
+  }
+  return res1 + res2 + res3 + 2;
+}
+
 /*-------------------------------------------------------------------------
   LogAccess::unmarshal_http_status
 

proxy/logging/LogAccess.h

@@ -305,12 +305,14 @@ class LogAccess
   static int unmarshal_int_to_str(char **buf, char *dest, int len);
   static int unmarshal_int_to_str_hex(char **buf, char *dest, int len);
   static int unmarshal_str(char **buf, char *dest, int len, LogSlice *slice = nullptr);
+  static int unmarshal_str_json(char **buf, char *dest, int len, LogSlice *slice = nullptr);
   static int unmarshal_ttmsf(char **buf, char *dest, int len);
   static int unmarshal_int_to_date_str(char **buf, char *dest, int len);
   static int unmarshal_int_to_time_str(char **buf, char *dest, int len);
   static int unmarshal_int_to_netscape_str(char **buf, char *dest, int len);
   static int unmarshal_http_version(char **buf, char *dest, int len);
   static int unmarshal_http_text(char **buf, char *dest, int len, LogSlice *slice = nullptr);
+  static int unmarshal_http_text_json(char **buf, char *dest, int len, LogSlice *slice = nullptr);
   static int unmarshal_http_status(char **buf, char *dest, int len);
   static int unmarshal_ip(char **buf, IpEndpoint *dest);
   static int unmarshal_ip_to_str(char **buf, char *dest, int len);

proxy/logging/LogBuffer.cc

@@ -445,7 +445,7 @@ LogBuffer::max_entry_bytes()
 int
 LogBuffer::resolve_custom_entry(LogFieldList *fieldlist, char *printf_str, char *read_from, char *write_to, int write_to_len,
                                 long timestamp, long timestamp_usec, unsigned buffer_version, LogFieldList *alt_fieldlist,
-                                char *alt_printf_str)
+                                char *alt_printf_str, LogEscapeType escape_type)
 {
   if (fieldlist == nullptr || printf_str == nullptr) {
     return 0;
@@ -501,7 +501,7 @@ LogBuffer::resolve_custom_entry(LogFieldList *fieldlist, char *printf_str, char
       ++markCount;
       if (field != nullptr) {
         char *to = &write_to[bytes_written];
-        res      = field->unmarshal(&read_from, to, write_to_len - bytes_written);
+        res      = field->unmarshal(&read_from, to, write_to_len - bytes_written, escape_type);
 
         if (res < 0) {
           SiteThrottledNote("%s", buffer_size_exceeded_msg);
@@ -549,7 +549,7 @@ LogBuffer::resolve_custom_entry(LogFieldList *fieldlist, char *printf_str, char
   -------------------------------------------------------------------------*/
 int
 LogBuffer::to_ascii(LogEntryHeader *entry, LogFormatType type, char *buf, int buf_len, const char *symbol_str, char *printf_str,
-                    unsigned buffer_version, const char *alt_format)
+                    unsigned buffer_version, const char *alt_format, LogEscapeType escape_type)
 {
   ink_assert(entry != nullptr);
   ink_assert(type == LOG_FORMAT_CUSTOM || type == LOG_FORMAT_TEXT);
@@ -642,7 +642,7 @@ LogBuffer::to_ascii(LogEntryHeader *entry, LogFormatType type, char *buf, int bu
   }
 
   int ret = resolve_custom_entry(fieldlist, printf_str, read_from, write_to, buf_len, entry->timestamp, entry->timestamp_usec,
-                                 buffer_version, alt_fieldlist, alt_printf_str);
+                                 buffer_version, alt_fieldlist, alt_printf_str, escape_type);
 
   delete alt_fieldlist;
   ats_free(alt_printf_str);

proxy/logging/LogBuffer.h

@@ -189,10 +189,10 @@ class LogBuffer
   // static functions
   static size_t max_entry_bytes();
   static int to_ascii(LogEntryHeader *entry, LogFormatType type, char *buf, int max_len, const char *symbol_str, char *printf_str,
-                      unsigned buffer_version, const char *alt_format = nullptr);
+                      unsigned buffer_version, const char *alt_format = nullptr, LogEscapeType escape_type = LOG_ESCAPE_NONE);
   static int resolve_custom_entry(LogFieldList *fieldlist, char *printf_str, char *read_from, char *write_to, int write_to_len,
                                   long timestamp, long timestamp_us, unsigned buffer_version, LogFieldList *alt_fieldlist = nullptr,
-                                  char *alt_printf_str = nullptr);
+                                  char *alt_printf_str = nullptr, LogEscapeType escape_type = LOG_ESCAPE_NONE);
 
   static void
   destroy(LogBuffer *&lb)

proxy/logging/LogField.cc

@@ -592,12 +592,19 @@ LogField::marshal_agg(char *buf)
   string that represents the ASCII value of the field.
   -------------------------------------------------------------------------*/
 unsigned
-LogField::unmarshal(char **buf, char *dest, int len)
+LogField::unmarshal(char **buf, char *dest, int len, LogEscapeType escape_type)
 {
   if (!m_alias_map) {
     if (m_unmarshal_func == reinterpret_cast<UnmarshalFunc>(LogAccess::unmarshal_str) ||
         m_unmarshal_func == reinterpret_cast<UnmarshalFunc>(LogAccess::unmarshal_http_text)) {
       UnmarshalFuncWithSlice func = reinterpret_cast<UnmarshalFuncWithSlice>(m_unmarshal_func);
+      if (escape_type == LOG_ESCAPE_JSON) {
+        if (m_unmarshal_func == reinterpret_cast<UnmarshalFunc>(LogAccess::unmarshal_str)) {
+          func = reinterpret_cast<UnmarshalFuncWithSlice>(LogAccess::unmarshal_str_json);
+        } else if (m_unmarshal_func == reinterpret_cast<UnmarshalFunc>(LogAccess::unmarshal_http_text)) {
+          func = reinterpret_cast<UnmarshalFuncWithSlice>(LogAccess::unmarshal_http_text_json);
+        }
+      }
       return (*func)(buf, dest, len, &m_slice);
     }
     return (*m_unmarshal_func)(buf, dest, len);

proxy/logging/LogField.h

@@ -32,6 +32,8 @@
 #include "LogFieldAliasMap.h"
 #include "Milestones.h"
 
+enum LogEscapeType { LOG_ESCAPE_NONE, LOG_ESCAPE_JSON };
+
 class LogAccess;
 
 struct LogSlice {
@@ -133,7 +135,7 @@ class LogField
   unsigned marshal_len(LogAccess *lad);
   unsigned marshal(LogAccess *lad, char *buf);
   unsigned marshal_agg(char *buf);
-  unsigned unmarshal(char **buf, char *dest, int len);
+  unsigned unmarshal(char **buf, char *dest, int len, LogEscapeType escape_type = LOG_ESCAPE_NONE);
   void display(FILE *fd = stdout);
   bool operator==(LogField &rhs);
   void updateField(LogAccess *lad, char *val, int len);

proxy/logging/LogFile.cc

@@ -63,9 +63,10 @@
   -------------------------------------------------------------------------*/
 
 LogFile::LogFile(const char *name, const char *header, LogFileFormat format, uint64_t signature, size_t ascii_buffer_size,
-                 size_t max_line_size, int pipe_buffer_size)
+                 size_t max_line_size, int pipe_buffer_size, LogEscapeType escape_type)
   : m_file_format(format),
     m_name(ats_strdup(name)),
+    m_escape_type(escape_type),
     m_header(ats_strdup(header)),
     m_signature(signature),
     m_max_line_size(max_line_size),
@@ -83,7 +84,7 @@ LogFile::LogFile(const char *name, const char *header, LogFileFormat format, uin
   m_fd                = -1;
   m_ascii_buffer_size = (ascii_buffer_size < max_line_size ? max_line_size : ascii_buffer_size);
 
-  Debug("log-file", "exiting LogFile constructor, m_name=%s, this=%p", m_name, this);
+  Debug("log-file", "exiting LogFile constructor, m_name=%s, this=%p, escape_type=%d", m_name, this, escape_type);
 }
 
 /*-------------------------------------------------------------------------
@@ -627,7 +628,7 @@ LogFile::write_ascii_logbuffer3(LogBufferHeader *buffer_header, const char *alt_
       }
 
       int bytes = LogBuffer::to_ascii(entry_header, format_type, &ascii_buffer[fmt_buf_bytes], m_max_line_size - 1, fieldlist_str,
-                                      printf_str, buffer_header->version, alt_format);
+                                      printf_str, buffer_header->version, alt_format, get_escape_type());
 
       if (bytes > 0) {
         fmt_buf_bytes += bytes;

proxy/logging/LogFile.h

@@ -43,7 +43,7 @@ class LogFile : public LogBufferSink, public RefCountObj
 {
 public:
   LogFile(const char *name, const char *header, LogFileFormat format, uint64_t signature, size_t ascii_buffer_size = 4 * 9216,
-          size_t max_line_size = 9216, int pipe_buffer_size = 0);
+          size_t max_line_size = 9216, int pipe_buffer_size = 0, LogEscapeType escape_type = LOG_ESCAPE_NONE);
   LogFile(const LogFile &);
   ~LogFile() override;
 
@@ -83,6 +83,12 @@ class LogFile : public LogBufferSink, public RefCountObj
     return m_file_format;
   }
 
+  LogEscapeType
+  get_escape_type() const
+  {
+    return m_escape_type;
+  }
+
   const char *
   get_format_name() const
   {
@@ -120,6 +126,7 @@ class LogFile : public LogBufferSink, public RefCountObj
 
 private:
   char *m_name;
+  LogEscapeType m_escape_type;
 
 public:
   BaseLogFile *m_log; // BaseLogFile backs the actual file on disk

proxy/logging/LogFormat.cc

@@ -177,7 +177,7 @@ LogFormat::init_variables(const char *name, const char *fieldlist_str, const cha
   form %<symbol>.
   -------------------------------------------------------------------------*/
 
-LogFormat::LogFormat(const char *name, const char *format_str, unsigned interval_sec)
+LogFormat::LogFormat(const char *name, const char *format_str, unsigned interval_sec, LogEscapeType escape_type)
   : m_interval_sec(0),
     m_interval_next(0),
     m_agg_marshal_space(nullptr),
@@ -189,7 +189,8 @@ LogFormat::LogFormat(const char *name, const char *format_str, unsigned interval
     m_field_count(0),
     m_printf_str(nullptr),
     m_aggregate(false),
-    m_format_str(nullptr)
+    m_format_str(nullptr),
+    m_escape_type(escape_type)
 {
   setup(name, format_str, interval_sec);
 
@@ -218,7 +219,8 @@ LogFormat::LogFormat(const LogFormat &rhs)
     m_printf_str(nullptr),
     m_aggregate(false),
     m_format_str(nullptr),
-    m_format_type(rhs.m_format_type)
+    m_format_type(rhs.m_format_type),
+    m_escape_type(rhs.m_escape_type)
 {
   if (m_valid) {
     if (m_format_type == LOG_FORMAT_TEXT) {