logging: Structured logging reference PR

To convert the existing `gf_msg` to `gf_smsg`:

- Define `_STR` of respective Message ID as below(In `*-messages.h`)

  #define PC_MSG_REMOTE_OP_FAILED_STR "remote operation failed."

- Change `gf_msg` to use `gf_smsg`. Convert values into fields and
  add any missing fields. Note: `errno` and `error` fields will be
  added automatically to log message in case errnum is specified.

  Example:

  gf_smsg(
    this->name,                            // Name or log domain
    GF_LOG_WARNING,                        // Log Level
    rsp.op_errno,                          // Error number
    PC_MSG_REMOTE_OP_FAILED,               // Message ID
    "path=%s", local->loc.path,            // Key Value 1
    "gfid=%s", loc_gfid_utoa(&local->loc), // Key Value 2
    NULL                                   // Log End
  );

Key value pairs formatting Help:

  gf_slog(
    this->name,                               // Name or log domain
    GF_LOG_WARNING,                           // Log Level
    rsp.op_errno,                             // Error number
    PC_MSG_REMOTE_OP_FAILED,                  // Message ID
    "op=CREATE",                              // Static Key and Value
    "path=%s", local->loc.path,               // Format for Value
    "brick-%d-status=%s", brkidx, brkstatus,  // Use format for key and val
    NULL                                      // Log End
  );

Before:

[2019-07-03 08:16:18.226819] W [MSGID: 114031] [client-rpc-fops_v2.c \
:2633:client4_0_lookup_cbk] 0-gv3-client-0: remote operation failed. \
Path: / (00000000-0000-0000-0000-000000000001) [Transport endpoint   \
is not connected]

After:

[2019-07-29 07:50:15.773765] W [MSGID: 114031]                   \
[client-rpc-fops_v2.c:2633:client4_0_lookup_cbk] 0-gv1-client-0: \
remote operation failed. [{path=/f1},                            \
{gfid=00000000-0000-0000-0000-000000000000},                     \
{errno=107}, {error=Transport endpoint is not connected}]

To add new `gf_smsg`, Add a Message ID in respective `*-messages.h` file
and the follow the steps mentioned above.

Change-Id: I4e7d37f27f106ab398e991d931ba2ac7841a44b1
Updates: #657
Signed-off-by: Aravinda VK <avishwan@redhat.com>

2 files changed, 36 insertions, 44 deletions

diff --git a/libglusterfs/src/glusterfs/logging.h b/libglusterfs/src/glusterfs/logging.h
index 31ecbfcbdb6..b3a6ac191f0 100644
--- a/libglusterfs/src/glusterfs/logging.h
+++ b/libglusterfs/src/glusterfs/logging.h
@@ -369,10 +369,6 @@ gf_log_disable_suppression_before_exit(struct _glusterfs_ctx *ctx);
     gf_log((xl)->name, GF_LOG_ERROR, format, ##args)
 
 int
-_gf_slog(const char *domain, const char *file, const char *function, int line,
-         gf_loglevel_t level, const char *event, ...);
-
-int
 _gf_smsg(const char *domain, const char *file, const char *function,
          int32_t line, gf_loglevel_t level, int errnum, int trace,
          uint64_t msgid, const char *event, ...);
@@ -381,12 +377,7 @@ _gf_smsg(const char *domain, const char *file, const char *function,
 #define gf_smsg(dom, level, errnum, msgid, event...)                           \
     do {                                                                       \
         _gf_smsg(dom, __FILE__, __FUNCTION__, __LINE__, level, errnum, 0,      \
-                 msgid, ##event);                                              \
-    } while (0)
-
-#define gf_slog(dom, level, event...)                                          \
-    do {                                                                       \
-        _gf_slog(dom, __FILE__, __FUNCTION__, __LINE__, level, ##event);       \
+                 msgid, msgid##_STR, ##event);                                 \
     } while (0)
 
 #endif /* __LOGGING_H__ */
diff --git a/libglusterfs/src/logging.c b/libglusterfs/src/logging.c
index 85bfaf0b3ef..a0f501ec739 100644
--- a/libglusterfs/src/logging.c
+++ b/libglusterfs/src/logging.c
@@ -2337,7 +2337,7 @@ out:
 }
 
 static int
-_do_slog_format(const char *event, va_list inp, char **msg)
+_do_slog_format(int errnum, const char *event, va_list inp, char **msg)
 {
     va_list valist_tmp;
     int i = 0;
@@ -2350,10 +2350,13 @@ _do_slog_format(const char *event, va_list inp, char **msg)
     char format_char = '%';
     char *tmp1 = NULL;
     char *tmp2 = NULL;
+    char temp_sep[3] = "";
 
-    ret = gf_asprintf(&tmp2, "%s", event);
-    if (ret == -1)
+    tmp2 = gf_strdup("");
+    if (!tmp2) {
+        ret = -1;
         goto out;
+    }
 
     /* Hardcoded value for max key value pairs, exits early */
     /* from loop if found NULL */
@@ -2401,22 +2404,45 @@ _do_slog_format(const char *event, va_list inp, char **msg)
                 (void)va_arg(inp, void *);
             }
 
-            ret = gf_asprintf(&tmp2, "%s\t%s", tmp1, buffer);
+            ret = gf_asprintf(&tmp2, "%s%s{%s}", tmp1, temp_sep, buffer);
             if (ret < 0)
                 goto out;
 
             GF_FREE(buffer);
             buffer = NULL;
         } else {
-            ret = gf_asprintf(&tmp2, "%s\t%s", tmp1, fmt);
+            ret = gf_asprintf(&tmp2, "%s%s{%s}", tmp1, temp_sep, fmt);
             if (ret < 0)
                 goto out;
         }
 
+        /* Set seperator for next iteration */
+        temp_sep[0] = ',';
+        temp_sep[1] = ' ';
+        temp_sep[2] = 0;
+
         GF_FREE(tmp1);
         tmp1 = NULL;
     }
 
+    tmp1 = gf_strdup(tmp2);
+    if (!tmp1) {
+        ret = -1;
+        goto out;
+    }
+    GF_FREE(tmp2);
+    tmp2 = NULL;
+
+    if (errnum) {
+        ret = gf_asprintf(&tmp2, "%s [%s%s{errno=%d}, {error=%s}]", event, tmp1,
+                          temp_sep, errnum, strerror(errnum));
+    } else {
+        ret = gf_asprintf(&tmp2, "%s [%s]", event, tmp1);
+    }
+
+    if (ret == -1)
+        goto out;
+
     *msg = gf_strdup(tmp2);
     if (!*msg)
         ret = -1;
@@ -2448,38 +2474,13 @@ _gf_smsg(const char *domain, const char *file, const char *function,
         return ret;
 
     va_start(valist, event);
-    ret = _do_slog_format(event, valist, &msg);
-    if (ret == -1)
-        goto out;
-
-    ret = _gf_msg(domain, file, function, line, level, errnum, trace, msgid,
-                  "%s", msg);
-
-out:
-    va_end(valist);
-    if (msg)
-        GF_FREE(msg);
-    return ret;
-}
-
-int
-_gf_slog(const char *domain, const char *file, const char *function, int line,
-         gf_loglevel_t level, const char *event, ...)
-{
-    va_list valist;
-    char *msg = NULL;
-    int ret = 0;
-    xlator_t *this = THIS;
-
-    if (skip_logging(this, level))
-        return ret;
-
-    va_start(valist, event);
-    ret = _do_slog_format(event, valist, &msg);
+    ret = _do_slog_format(errnum, event, valist, &msg);
     if (ret == -1)
         goto out;
 
-    ret = _gf_log(domain, file, function, line, level, "%s", msg);
+    /* Pass errnum as zero since it is already formated as required */
+    ret = _gf_msg(domain, file, function, line, level, 0, trace, msgid, "%s",
+                  msg);
 
 out:
     va_end(valist);