features/libgfchangelog: Structured logging support

Structured logging infra is available in logging library with
issue #240. Log messages with dynamic content are identified and
converted to structured logging format(`gf_msg` to `gf_smsg` and
`gf_log` to `gf_slog`)

BUG: 1501054
Change-Id: I99b35396455a634f5267eb1379d481ea981e5494
Signed-off-by: Aravinda VK <avishwan@redhat.com>

5 files changed, 150 insertions, 104 deletions

diff --git a/xlators/features/changelog/lib/src/gf-changelog-api.c b/xlators/features/changelog/lib/src/gf-changelog-api.c
index 71312f4ce95..372550c7acf 100644
--- a/xlators/features/changelog/lib/src/gf-changelog-api.c
+++ b/xlators/features/changelog/lib/src/gf-changelog-api.c
@@ -55,10 +55,12 @@ gf_changelog_done (char *file)
                       "moving %s to processed directory", file);
         ret = sys_rename (buffer, to_path);
         if (ret) {
-                gf_msg (this->name, GF_LOG_ERROR, errno,
-                        CHANGELOG_LIB_MSG_RENAME_FAILED,
-                        "cannot move %s to %s",
-                        file, to_path);
+                gf_smsg (this->name, GF_LOG_ERROR, errno,
+                         CHANGELOG_LIB_MSG_RENAME_FAILED,
+                         "cannot move changelog file",
+                         "from=%s", file,
+                         "to=%s", to_path,
+                         NULL);
                 goto out;
         }
 
diff --git a/xlators/features/changelog/lib/src/gf-changelog-journal-handler.c b/xlators/features/changelog/lib/src/gf-changelog-journal-handler.c
index a2d75cbbbfd..46f9bdae92c 100644
--- a/xlators/features/changelog/lib/src/gf-changelog-journal-handler.c
+++ b/xlators/features/changelog/lib/src/gf-changelog-journal-handler.c
@@ -555,10 +555,11 @@ gf_changelog_publish (xlator_t *this,
 
         ret = sys_rename (to_path, dest);
         if (ret) {
-                gf_msg (this->name, GF_LOG_ERROR, errno,
-                        CHANGELOG_LIB_MSG_RENAME_FAILED,
-                        "error moving %s to processing dir",
-                        to_path);
+                gf_smsg (this->name, GF_LOG_ERROR, errno,
+                         CHANGELOG_LIB_MSG_RENAME_FAILED,
+                         "error moving changelog to processing dir",
+                         "path=%s", to_path,
+                         NULL);
         }
 
 out:
@@ -581,18 +582,21 @@ gf_changelog_consume (xlator_t *this,
         ret = sys_stat (from_path, &stbuf);
         if (ret || !S_ISREG(stbuf.st_mode)) {
                 ret = -1;
-                gf_msg (this->name, GF_LOG_ERROR, errno,
-                        CHANGELOG_LIB_MSG_STAT_FAILED,
-                        "stat failed on changelog file: %s", from_path);
+                gf_smsg (this->name, GF_LOG_ERROR, errno,
+                         CHANGELOG_LIB_MSG_STAT_FAILED,
+                         "stat failed on changelog file",
+                         "path=%s", from_path,
+                         NULL);
                 goto out;
         }
 
         fd1 = open (from_path, O_RDONLY);
         if (fd1 < 0) {
-                gf_msg (this->name, GF_LOG_ERROR, errno,
-                        CHANGELOG_LIB_MSG_OPEN_FAILED,
-                        "cannot open changelog file: %s",
-                        from_path);
+                gf_smsg (this->name, GF_LOG_ERROR, errno,
+                         CHANGELOG_LIB_MSG_OPEN_FAILED,
+                         "cannot open changelog file",
+                         "path=%s", from_path,
+                         NULL);
                 goto out;
         }
 
@@ -604,10 +608,11 @@ gf_changelog_consume (xlator_t *this,
         fd2 = open (to_path, O_CREAT | O_TRUNC | O_RDWR,
                     S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH);
         if (fd2 < 0) {
-                gf_msg (this->name, GF_LOG_ERROR, errno,
-                        CHANGELOG_LIB_MSG_OPEN_FAILED,
-                        "cannot create ascii changelog file %s",
-                        to_path);
+                gf_smsg (this->name, GF_LOG_ERROR, errno,
+                         CHANGELOG_LIB_MSG_OPEN_FAILED,
+                         "cannot create ascii changelog file",
+                         "path=%s", to_path,
+                         NULL);
                 goto close_fd;
         } else {
                 ret = gf_changelog_decode (this, jnl, fd1,
@@ -622,10 +627,11 @@ gf_changelog_consume (xlator_t *this,
                                 goto close_fd;
                         ret = sys_rename (to_path, dest);
                         if (ret)
-                                gf_msg (this->name, GF_LOG_ERROR, errno,
-                                        CHANGELOG_LIB_MSG_RENAME_FAILED,
-                                        "error moving %s to processing dir",
-                                        to_path);
+                                gf_smsg (this->name, GF_LOG_ERROR, errno,
+                                         CHANGELOG_LIB_MSG_RENAME_FAILED,
+                                         "error moving changelog to processing dir",
+                                         "path=%s", to_path,
+                                         NULL);
                 }
 
                 /* remove it from .current if it's an empty file */
@@ -633,10 +639,11 @@ gf_changelog_consume (xlator_t *this,
                         /* zerob changelogs must be unlinked */
                         ret = sys_unlink (to_path);
                         if (ret)
-                                gf_msg (this->name, GF_LOG_ERROR, errno,
-                                        CHANGELOG_LIB_MSG_UNLINK_FAILED,
-                                        "could not unlink %s",
-                                        to_path);
+                                gf_smsg (this->name, GF_LOG_ERROR, errno,
+                                         CHANGELOG_LIB_MSG_UNLINK_FAILED,
+                                         "could not unlink empty changelog",
+                                         "path=%s", to_path,
+                                         NULL);
                 }
         }
 
@@ -855,10 +862,11 @@ gf_changelog_open_dirs (xlator_t *this, gf_changelog_journal_t *jnl)
                          jnl->jnl_working_dir);
         ret = recursive_rmdir (jnl->jnl_current_dir);
         if (ret) {
-                gf_msg (this->name, GF_LOG_ERROR, errno,
-                        CHANGELOG_LIB_MSG_FAILED_TO_RMDIR,
-                        "Failed to rmdir: %s",
-                        jnl->jnl_current_dir);
+                gf_smsg (this->name, GF_LOG_ERROR, errno,
+                         CHANGELOG_LIB_MSG_FAILED_TO_RMDIR,
+                         "Failed to rmdir",
+                         "path=%s", jnl->jnl_current_dir,
+                         NULL);
                 goto out;
         }
         ret = mkdir_p (jnl->jnl_current_dir, 0600, _gf_false);
@@ -879,10 +887,11 @@ gf_changelog_open_dirs (xlator_t *this, gf_changelog_journal_t *jnl)
                          jnl->jnl_working_dir);
         ret = recursive_rmdir (jnl->jnl_processing_dir);
         if (ret) {
-                gf_msg (this->name, GF_LOG_ERROR, errno,
-                        CHANGELOG_LIB_MSG_FAILED_TO_RMDIR,
-                        "Failed to rmdir: %s",
-                        jnl->jnl_processing_dir);
+                gf_smsg (this->name, GF_LOG_ERROR, errno,
+                         CHANGELOG_LIB_MSG_FAILED_TO_RMDIR,
+                         "Failed to rmdir",
+                         "path=%s", jnl->jnl_processing_dir,
+                         NULL);
                 goto out;
         }
 
diff --git a/xlators/features/changelog/lib/src/gf-changelog-reborp.c b/xlators/features/changelog/lib/src/gf-changelog-reborp.c
index 4337d2575a9..d1b3059a60c 100644
--- a/xlators/features/changelog/lib/src/gf-changelog-reborp.c
+++ b/xlators/features/changelog/lib/src/gf-changelog-reborp.c
@@ -55,9 +55,11 @@ gf_changelog_connection_janitor (void *arg)
                 drained = 0;
                 ev = &entry->event;
 
-                gf_msg (this->name, GF_LOG_INFO, 0,
-                        CHANGELOG_LIB_MSG_CLEANING_BRICK_ENTRY_INFO,
-                        "Cleaning brick entry for brick %s", entry->brick);
+                gf_smsg (this->name, GF_LOG_INFO, 0,
+                         CHANGELOG_LIB_MSG_CLEANING_BRICK_ENTRY_INFO,
+                         "Cleaning brick entry for brick",
+                         "brick=%s", entry->brick,
+                         NULL);
 
                 /* 0x0: disbale rpc-clnt */
                 rpc_clnt_disable (RPC_PROBER (entry));
@@ -71,23 +73,29 @@ gf_changelog_connection_janitor (void *arg)
                 while (!list_empty (&ev->events)) {
                         event = list_first_entry (&ev->events,
                                                   struct gf_event, list);
-                        gf_msg (this->name, GF_LOG_INFO, 0,
-                                CHANGELOG_LIB_MSG_DRAINING_EVENT_INFO,
-                                "Draining event [Seq: %lu, Payload: %d]",
-                                event->seq, event->count);
+                        gf_smsg (this->name, GF_LOG_INFO, 0,
+                                 CHANGELOG_LIB_MSG_DRAINING_EVENT_INFO,
+                                 "Draining event",
+                                 "seq=%lu", event->seq,
+                                 "payload=%d", event->count,
+                                 NULL);
 
                         GF_FREE (event);
                         drained++;
                 }
 
-                gf_msg (this->name, GF_LOG_INFO, 0,
-                        CHANGELOG_LIB_MSG_DRAINING_EVENT_INFO,
-                        "Drained %lu events", drained);
+                gf_smsg (this->name, GF_LOG_INFO, 0,
+                         CHANGELOG_LIB_MSG_DRAINING_EVENT_INFO,
+                         "Drained events",
+                         "num=%lu", drained,
+                         NULL);
 
                 /* 0x3: freeup brick entry */
-                gf_msg (this->name, GF_LOG_INFO, 0,
-                        CHANGELOG_LIB_MSG_FREEING_ENTRY_INFO,
-                        "freeing entry %p", entry);
+                gf_smsg (this->name, GF_LOG_INFO, 0,
+                         CHANGELOG_LIB_MSG_FREEING_ENTRY_INFO,
+                         "freeing entry",
+                         "entry=%p", entry,
+                         NULL);
                 LOCK_DESTROY (&entry->statelock);
                 GF_FREE (entry);
         }
@@ -114,10 +122,12 @@ gf_changelog_reborp_rpcsvc_notify (rpcsvc_t *rpc, void *mydata,
         case RPCSVC_EVENT_ACCEPT:
                 ret = sys_unlink (RPC_SOCK(entry));
                 if (ret != 0)
-                        gf_msg (this->name, GF_LOG_WARNING, errno,
-                                CHANGELOG_LIB_MSG_UNLINK_FAILED,
-                                "failed to unlink "
-                                "reverse socket %s", RPC_SOCK (entry));
+                        gf_smsg (this->name, GF_LOG_WARNING, errno,
+                                 CHANGELOG_LIB_MSG_UNLINK_FAILED,
+                                 "failed to unlink "
+                                 "reverse socket",
+                                 "path=%s", RPC_SOCK (entry),
+                                 NULL);
                 if (entry->connected)
                         GF_CHANGELOG_INVOKE_CBK (this, entry->connected,
                                                  entry->brick, entry->ptr);
diff --git a/xlators/features/changelog/lib/src/gf-changelog.c b/xlators/features/changelog/lib/src/gf-changelog.c
index e4ad045599a..6ee87b1414e 100644
--- a/xlators/features/changelog/lib/src/gf-changelog.c
+++ b/xlators/features/changelog/lib/src/gf-changelog.c
@@ -554,10 +554,12 @@ gf_changelog_register_generic (struct gf_brick_spec *bricks, int count,
 
         brick = bricks;
         while (count--) {
-                gf_msg (this->name, GF_LOG_INFO, 0,
-                        CHANGELOG_LIB_MSG_NOTIFY_REGISTER_INFO,
-                        "Registering brick: %s [notify filter: %d]",
-                        brick->brick_path, brick->filter);
+                gf_smsg (this->name, GF_LOG_INFO, 0,
+                         CHANGELOG_LIB_MSG_NOTIFY_REGISTER_INFO,
+                         "Registering brick",
+                         "brick=%s", brick->brick_path,
+                         "notify_filter=%d", brick->filter,
+                         NULL);
 
                 ret = gf_changelog_register_brick (this, brick, need_order, xl);
                 if (ret != 0) {
diff --git a/xlators/features/changelog/lib/src/gf-history-changelog.c b/xlators/features/changelog/lib/src/gf-history-changelog.c
index 736237219f4..0bf130a0883 100644
--- a/xlators/features/changelog/lib/src/gf-history-changelog.c
+++ b/xlators/features/changelog/lib/src/gf-history-changelog.c
@@ -77,10 +77,12 @@ gf_history_changelog_done (char *file)
                       "moving %s to processed directory", file);
         ret = sys_rename (buffer, to_path);
         if (ret) {
-                gf_msg (this->name, GF_LOG_ERROR, errno,
-                        CHANGELOG_LIB_MSG_RENAME_FAILED,
-                        "cannot move %s to %s",
-                        file, to_path);
+                gf_smsg (this->name, GF_LOG_ERROR, errno,
+                         CHANGELOG_LIB_MSG_RENAME_FAILED,
+                         "cannot move changelog file",
+                         "from=%s", file,
+                         "to=%s", to_path,
+                         NULL);
                 goto out;
         }
 
@@ -529,10 +531,11 @@ gf_changelog_consume_wrap (void* data)
                 ret = gf_changelog_consume (ccd->this,
                                             ccd->jnl, ccd->changelog, _gf_true);
                 if (ret) {
-                        gf_msg (this->name, GF_LOG_ERROR,
-                                0, CHANGELOG_LIB_MSG_PARSE_ERROR,
-                                "could not parse changelog: %s",
-                                ccd->changelog);
+                        gf_smsg (this->name, GF_LOG_ERROR,
+                                 0, CHANGELOG_LIB_MSG_PARSE_ERROR,
+                                 "could not parse changelog",
+                                 "name=%s", ccd->changelog,
+                                 NULL);
                         goto out;
                 }
         }
@@ -726,10 +729,11 @@ gf_changelog_extract_min_max (const char *dname, const char *htime_dir,
         ret = sys_stat (htime_file, &stbuf);
         if (ret) {
                 ret = -1;
-                gf_msg (this->name, GF_LOG_ERROR, errno,
-                        CHANGELOG_LIB_MSG_HTIME_ERROR,
-                        "stat() failed on htime file %s",
-                        htime_file);
+                gf_smsg (this->name, GF_LOG_ERROR, errno,
+                         CHANGELOG_LIB_MSG_HTIME_ERROR,
+                         "stat() failed on htime file",
+                         "path=%s", htime_file,
+                         NULL);
                 goto out;
         }
 
@@ -742,10 +746,11 @@ gf_changelog_extract_min_max (const char *dname, const char *htime_dir,
         *fd = open (htime_file, O_RDONLY);
         if (*fd < 0) {
                 ret = -1;
-                gf_msg (this->name, GF_LOG_ERROR, errno,
-                        CHANGELOG_LIB_MSG_HTIME_ERROR,
-                        "open() failed for htime %s",
-                        htime_file);
+                gf_smsg (this->name, GF_LOG_ERROR, errno,
+                         CHANGELOG_LIB_MSG_HTIME_ERROR,
+                         "open() failed for htime file",
+                         "path=%s", htime_file,
+                         NULL);
                 goto out;
         }
 
@@ -753,18 +758,22 @@ gf_changelog_extract_min_max (const char *dname, const char *htime_dir,
         ret = sys_fgetxattr (*fd, HTIME_KEY, x_value, sizeof (x_value));
         if (ret < 0) {
                 ret = -1;
-                gf_msg (this->name, GF_LOG_ERROR, errno,
-                        CHANGELOG_LIB_MSG_GET_XATTR_FAILED,
-                        "error extracting max timstamp from htime file"
-                        " %s", htime_file);
+                gf_smsg (this->name, GF_LOG_ERROR, errno,
+                         CHANGELOG_LIB_MSG_GET_XATTR_FAILED,
+                         "error extracting max timstamp from htime file"
+                         "path=%s", htime_file,
+                         NULL);
                 goto out;
         }
 
         sscanf (x_value, "%lu:%lu", max_ts, total);
-        gf_msg (this->name, GF_LOG_INFO, 0,
-                CHANGELOG_LIB_MSG_TOTAL_LOG_INFO,
-                "MIN: %lu, MAX: %lu, TOTAL CHANGELOGS: %lu",
-                *min_ts, *max_ts, *total);
+        gf_smsg (this->name, GF_LOG_INFO, 0,
+                 CHANGELOG_LIB_MSG_TOTAL_LOG_INFO,
+                 "changelogs min max",
+                 "min=%lu", *min_ts,
+                 "max=%lu", *max_ts,
+                 "total_changelogs=%lu", *total,
+                 NULL);
 
         ret = 0;
 
@@ -830,10 +839,12 @@ gf_history_changelog (char* changelog_dir, unsigned long start,
 
         /* basic sanity check */
         if (start > end || n_parallel <= 0) {
-                gf_msg (this->name, GF_LOG_ERROR, errno,
-                        CHANGELOG_LIB_MSG_HIST_FAILED, "Sanity check failed. "
-                        "START - %lu END - %lu THREAD_COUNT - %d",
-                        start, end, n_parallel);
+                gf_smsg (this->name, GF_LOG_ERROR, errno,
+                         CHANGELOG_LIB_MSG_HIST_FAILED, "Sanity check failed",
+                         "start=%lu", start,
+                         "end=%lu", end,
+                         "thread_count=%d", n_parallel,
+                         NULL);
                 ret = -1;
                 goto out;
         }
@@ -846,10 +857,11 @@ gf_history_changelog (char* changelog_dir, unsigned long start,
 
         dirp = sys_opendir (htime_dir);
         if (dirp == NULL) {
-                gf_msg (this->name, GF_LOG_ERROR, errno,
-                        CHANGELOG_LIB_MSG_HTIME_ERROR,
-                        "open dir on htime failed : %s",
-                        htime_dir);
+                gf_smsg (this->name, GF_LOG_ERROR, errno,
+                         CHANGELOG_LIB_MSG_HTIME_ERROR,
+                         "open dir on htime failed",
+                         "path=%s", htime_dir,
+                         NULL);
                 ret = -1;
                 goto out;
         }
@@ -897,10 +909,12 @@ gf_history_changelog (char* changelog_dir, unsigned long start,
                         /* ensuring correctness of gf_b_search */
                         if (gf_history_check (fd, from, start, len) != 0) {
                                 ret = -1;
-                                gf_msg (this->name, GF_LOG_ERROR, 0,
-                                        CHANGELOG_LIB_MSG_GET_TIME_ERROR,
-                                        "wrong result for start: %lu idx: %lu",
-                                        start, from);
+                                gf_smsg (this->name, GF_LOG_ERROR, 0,
+                                         CHANGELOG_LIB_MSG_GET_TIME_ERROR,
+                                         "wrong result for start",
+                                         "start=%lu", start,
+                                         "idx=%lu", from,
+                                         NULL);
                                 goto out;
                         }
 
@@ -914,10 +928,12 @@ gf_history_changelog (char* changelog_dir, unsigned long start,
 
                         if (gf_history_check (fd, to, end2, len) != 0) {
                                 ret = -1;
-                                gf_msg (this->name, GF_LOG_ERROR, 0,
-                                        CHANGELOG_LIB_MSG_GET_TIME_ERROR,
-                                        "wrong result for start: %lu idx: %lu",
-                                        end2, to);
+                                gf_smsg (this->name, GF_LOG_ERROR, 0,
+                                         CHANGELOG_LIB_MSG_GET_TIME_ERROR,
+                                         "wrong result for start",
+                                         "start=%lu", end2,
+                                         "idx=%lu", to,
+                                         NULL);
                                 goto out;
                         }
 
@@ -929,10 +945,13 @@ gf_history_changelog (char* changelog_dir, unsigned long start,
                         if (ret == -1)
                                 goto out;
 
-                        gf_msg (this->name, GF_LOG_INFO, 0,
-                                CHANGELOG_LIB_MSG_TOTAL_LOG_INFO,
-                                "FINAL: from: %lu, to: %lu, changes: %lu",
-                                ts1, ts2, (to - from + 1));
+                        gf_smsg (this->name, GF_LOG_INFO, 0,
+                                 CHANGELOG_LIB_MSG_TOTAL_LOG_INFO,
+                                 "FINAL",
+                                 "from=%lu", ts1,
+                                 "to=%lu", ts2,
+                                 "changes=%lu", (to - from + 1),
+                                 NULL);
 
                         hist_data =  GF_CALLOC (1,
                                      sizeof (gf_changelog_history_data_t),
@@ -972,10 +991,14 @@ gf_history_changelog (char* changelog_dir, unsigned long start,
                         goto out;
 
                 } else {/* end of range check */
-                        gf_msg (this->name, GF_LOG_ERROR, errno,
-                        CHANGELOG_LIB_MSG_HIST_FAILED, "Requested changelog "
-                        "range is not available. START - %lu CHLOG_MIN - %lu "
-                        "CHLOG_MAX - %lu", start, min_ts, max_ts);
+                        gf_smsg (this->name, GF_LOG_ERROR, errno,
+                                 CHANGELOG_LIB_MSG_HIST_FAILED,
+                                 "Requested changelog "
+                                 "range is not available.",
+                                 "start=%lu", start,
+                                 "chlog_min=%lu", min_ts,
+                                 "chlog_max=%lu", max_ts,
+                                 NULL);
                         ret = -2;
                         goto out;
                 }