logging: localtime logging, cmdline, volume set option

Despite the fact that appliances generally use UTC, some
users really want log entries in localtime.

fixes gluster/glusterfs#272

feature page: https://review.gluster.org/17807

Backport from master https://review.gluster.org/#/c/16911/

Change-Id: I5fbf2c3eedd9eb128fb3f851dd67b2f4081c8bba
Signed-off-by: Kaleb S. KEITHLEY <kkeithle@redhat.com>
Reviewed-on: https://review.gluster.org/17928
CentOS-regression: Gluster Build System <jenkins@build.gluster.org>
Smoke: Gluster Build System <jenkins@build.gluster.org>
Reviewed-by: Shyamsundar Ranganathan <srangana@redhat.com>

17 files changed, 209 insertions, 6 deletions

diff --git a/doc/glusterd.8 b/doc/glusterd.8
index 04a43481eec..3ef7c2b72d1 100644
--- a/doc/glusterd.8
+++ b/doc/glusterd.8
@@ -30,6 +30,9 @@ File to use for logging.
 \fB\-L <LOGLEVEL>, \fB\-\-log\-level=<LOGLEVEL>\fR
 Logging severity.  Valid options are TRACE, DEBUG, INFO, WARNING, ERROR and CRITICAL (the default is INFO).
 .TP
+\fB\-L, \fB\-\-localtime\-logging=on|off\fR
+Enable or disable localtime log timestamps. Valid options are on and off (the default is off).
+.TP
 \fB\-\-debug\fR
 Run the program in debug mode. This option sets \fB\-\-no\-daemon\fR, \fB\-\-log\-level\fR to DEBUG
 and \fB\-\-log\-file\fR to console.
diff --git a/doc/glusterfs.8 b/doc/glusterfs.8
index fc28ef68be6..701c25ecfac 100644
--- a/doc/glusterfs.8
+++ b/doc/glusterfs.8
@@ -53,6 +53,9 @@ Maximum number of connect attempts to server. This option should be provided wit
 \fB\-\-acl\fR
 Mount the filesystem with POSIX ACL support.
 .TP
+\fB\-L, \fB\-\-localtime\-logging=on|off\fR
+Enable or disable localtime log timestamps. Valid options are on and off (the default is off).
+.TP
 \fB\-\-debug\fR
 Run in debug mode.  This option sets \fB\-\-no\-daemon\fR, \fB\-\-log\-level\fR to DEBUG,
 and \fB\-\-log\-file\fR to console.
diff --git a/doc/glusterfsd.8 b/doc/glusterfsd.8
index 956cb24bca3..c5a95d1611f 100644
--- a/doc/glusterfsd.8
+++ b/doc/glusterfsd.8
@@ -51,6 +51,9 @@ Server to get the volume from.  This option overrides \fB\-\-volfile option
 .PP
 .TP
 
+\fB\-L, \fB\-\-localtime\-logging=on|off\fR
+Enable or disable localtime log timestamps. Valid options are on and off (the default is off).
+.TP
 \fB\-\-debug\fR
 Run in debug mode.  This option sets \fB\-\-no\-daemon\fR, \fB\-\-log\-level\fR to DEBUG
 and \fB\-\-log\-file\fR to console
diff --git a/glusterfsd/src/glusterfsd.c b/glusterfsd/src/glusterfsd.c
index 204c617be6c..ebf58706107 100644
--- a/glusterfsd/src/glusterfsd.c
+++ b/glusterfsd/src/glusterfsd.c
@@ -240,6 +240,8 @@ static struct argp_option gf_options[] = {
          " [default: \"yes\"]"},
         {"secure-mgmt", ARGP_SECURE_MGMT_KEY, "BOOL", OPTION_ARG_OPTIONAL,
          "Override default for secure (SSL) management connections"},
+        {"localtime-logging", ARGP_LOCALTIME_LOGGING_KEY, 0, 0,
+         "Enable localtime logging"},
         {0, 0, 0, 0, "Miscellaneous Options:"},
         {0, }
 };
@@ -1271,6 +1273,10 @@ no_oom_api:
                 argp_failure (state, -1, 0,
                               "unknown secure-mgmt setting \"%s\"", arg);
                 break;
+
+        case ARGP_LOCALTIME_LOGGING_KEY:
+                cmd_args->localtime_logging = 1;
+                break;
 	}
 
         return 0;
@@ -1635,6 +1641,8 @@ logging_init (glusterfs_ctx_t *ctx, const char *progpath)
         /* finish log set parameters before init */
         gf_log_set_loglevel (cmd_args->log_level);
 
+        gf_log_set_localtime (cmd_args->localtime_logging);
+
         gf_log_set_logger (cmd_args->logger);
 
         gf_log_set_logformat (cmd_args->log_format);
diff --git a/glusterfsd/src/glusterfsd.h b/glusterfsd/src/glusterfsd.h
index 3461d6d01f0..c1d5dc08405 100644
--- a/glusterfsd/src/glusterfsd.h
+++ b/glusterfsd/src/glusterfsd.h
@@ -96,6 +96,7 @@ enum argp_option_keys {
 #ifdef GF_LINUX_HOST_OS
         ARGP_OOM_SCORE_ADJ_KEY            = 176,
 #endif
+        ARGP_LOCALTIME_LOGGING_KEY        = 177,
 };
 
 struct _gfd_vol_top_priv {
diff --git a/libglusterfs/src/common-utils.h b/libglusterfs/src/common-utils.h
index 1d7f09dbc82..022a2a70ff0 100644
--- a/libglusterfs/src/common-utils.h
+++ b/libglusterfs/src/common-utils.h
@@ -687,12 +687,15 @@ gf_time_fmt (char *dst, size_t sz_dst, time_t utime, unsigned int fmt)
         static gf_timefmts timefmt_last = (gf_timefmts) - 1;
         static const char **fmts;
         static const char **zeros;
-        struct tm tm;
+        struct tm tm, *res;
+        int localtime = 0;
 
         if (timefmt_last == (gf_timefmts) - 1)
                 _gf_timestuff (&timefmt_last, &fmts, &zeros);
         if (timefmt_last < fmt) fmt = gf_timefmt_default;
-        if (utime && gmtime_r (&utime, &tm) != NULL) {
+        localtime = gf_log_get_localtime ();
+        res = localtime ? localtime_r (&utime, &tm) : gmtime_r (&utime, &tm);
+        if (utime && res != NULL) {
                 strftime (dst, sz_dst, fmts[fmt], &tm);
         } else {
                 strncpy (dst, "N/A", sz_dst);
diff --git a/libglusterfs/src/glusterfs.h b/libglusterfs/src/glusterfs.h
index bb925c3d78d..b009b94493d 100644
--- a/libglusterfs/src/glusterfs.h
+++ b/libglusterfs/src/glusterfs.h
@@ -292,6 +292,7 @@
 #define GF_LOG_FLUSH_TIMEOUT_MAX 300
 #define GF_LOG_FLUSH_TIMEOUT_MIN_STR "30"
 #define GF_LOG_FLUSH_TIMEOUT_MAX_STR "300"
+#define GF_LOG_LOCALTIME_DEFAULT 0
 
 #define GF_BACKTRACE_LEN        4096
 #define GF_BACKTRACE_FRAME_COUNT 7
@@ -416,6 +417,7 @@ struct _cmd_args {
          * functions that prevent valgrind from working correctly, like
          * dlclose(). */
         int                valgrind;
+        int                localtime_logging;
 };
 typedef struct _cmd_args cmd_args_t;
 
diff --git a/libglusterfs/src/logging.c b/libglusterfs/src/logging.c
index c09adecc4f1..0f238d00738 100644
--- a/libglusterfs/src/logging.c
+++ b/libglusterfs/src/logging.c
@@ -141,6 +141,31 @@ gf_log_set_loglevel (gf_loglevel_t level)
                 ctx->log.loglevel = level;
 }
 
+int
+gf_log_get_localtime (void)
+{
+        glusterfs_ctx_t *ctx = NULL;
+
+        ctx = THIS->ctx;
+
+        if (ctx)
+                return ctx->log.localtime;
+        else
+                /* return global defaults (see gf_log_globals_init) */
+                return 0;
+}
+
+void
+gf_log_set_localtime (int on_off)
+{
+        glusterfs_ctx_t *ctx = NULL;
+
+        ctx = THIS->ctx;
+
+        if (ctx)
+                ctx->log.localtime = on_off;
+}
+
 void
 gf_log_flush (void)
 {
@@ -655,6 +680,7 @@ gf_log_globals_init (void *data, gf_loglevel_t level)
         ctx->log.logformat        = gf_logformat_withmsgid;
         ctx->log.lru_size         = GF_LOG_LRU_BUFSIZE_DEFAULT;
         ctx->log.timeout          = GF_LOG_FLUSH_TIMEOUT_DEFAULT;
+        ctx->log.localtime        = GF_LOG_LOCALTIME_DEFAULT;
 
         pthread_mutex_init (&ctx->log.log_buf_lock, NULL);
 
diff --git a/libglusterfs/src/logging.h b/libglusterfs/src/logging.h
index a7f252acf67..fd9a36d15c2 100644
--- a/libglusterfs/src/logging.h
+++ b/libglusterfs/src/logging.h
@@ -116,6 +116,7 @@ typedef struct gf_log_handle_ {
         uint32_t          timeout;
         pthread_mutex_t   log_buf_lock;
         struct _gf_timer *log_flush_timer;
+        int               localtime;
 } gf_log_handle_t;
 
 
@@ -280,6 +281,8 @@ void gf_log_disable_syslog (void);
 void gf_log_enable_syslog (void);
 gf_loglevel_t gf_log_get_loglevel (void);
 void gf_log_set_loglevel (gf_loglevel_t level);
+int gf_log_get_localtime (void);
+void gf_log_set_localtime (int);
 void gf_log_flush (void);
 gf_loglevel_t gf_log_get_xl_loglevel (void *xl);
 void gf_log_set_xl_loglevel (void *xl, gf_loglevel_t level);
diff --git a/xlators/mgmt/glusterd/src/glusterd-handler.c b/xlators/mgmt/glusterd/src/glusterd-handler.c
index ba6f4afa94d..523e9d51bec 100644
--- a/xlators/mgmt/glusterd/src/glusterd-handler.c
+++ b/xlators/mgmt/glusterd/src/glusterd-handler.c
@@ -4585,6 +4585,7 @@ gd_is_global_option (char *opt_key)
                 strcmp (opt_key, GLUSTERD_QUORUM_RATIO_KEY) == 0 ||
                 strcmp (opt_key, GLUSTERD_GLOBAL_OP_VERSION_KEY) == 0 ||
                 strcmp (opt_key, GLUSTERD_BRICK_MULTIPLEX_KEY) == 0 ||
+                strcmp (opt_key, GLUSTERD_LOCALTIME_LOGGING_KEY) == 0 ||
                 strcmp (opt_key, GLUSTERD_MAX_OP_VERSION_KEY) == 0);
 
 out:
diff --git a/xlators/mgmt/glusterd/src/glusterd-messages.h b/xlators/mgmt/glusterd/src/glusterd-messages.h
index 2caa16c2eda..36d1408965f 100644
--- a/xlators/mgmt/glusterd/src/glusterd-messages.h
+++ b/xlators/mgmt/glusterd/src/glusterd-messages.h
@@ -41,7 +41,7 @@
 
 #define GLUSTERD_COMP_BASE      GLFS_MSGID_GLUSTERD
 
-#define GLFS_NUM_MESSAGES       606
+#define GLFS_NUM_MESSAGES       610
 
 #define GLFS_MSGID_END          (GLUSTERD_COMP_BASE + GLFS_NUM_MESSAGES + 1)
 /* Messaged with message IDs */
@@ -4909,6 +4909,30 @@
  */
 #define GD_MSG_STATVFS_FAILED  (GLUSTERD_COMP_BASE + 607)
 
+/*!
+ * @messageid
+ * @diagnosis
+ * @recommendedaction
+ *
+ */
+#define GD_MSG_LOCALTIME_LOGGING_VOL_OPT_VALIDATE_FAIL (GLUSTERD_COMP_BASE + 608)
+
+/*!
+ * @messageid
+ * @diagnosis
+ * @recommendedaction
+ *
+ */
+#define GD_MSG_LOCALTIME_LOGGING_ENABLE (GLUSTERD_COMP_BASE + 609)
+
+/*!
+ * @messageid
+ * @diagnosis
+ * @recommendedaction
+ *
+ */
+#define GD_MSG_LOCALTIME_LOGGING_DISABLE (GLUSTERD_COMP_BASE + 610)
+
 /*------------*/
 
 #define glfs_msg_end_x GLFS_MSGID_END, "Invalid: End of messages"
diff --git a/xlators/mgmt/glusterd/src/glusterd-op-sm.c b/xlators/mgmt/glusterd/src/glusterd-op-sm.c
index 6be92d8ad7e..7bb3d537097 100644
--- a/xlators/mgmt/glusterd/src/glusterd-op-sm.c
+++ b/xlators/mgmt/glusterd/src/glusterd-op-sm.c
@@ -85,6 +85,7 @@ glusterd_all_vol_opts valid_all_vol_opts[] = {
          * TBD: Discuss the default value for this. Maybe this should be a
          * dynamic value depending on the memory specifications per node */
         { GLUSTERD_BRICKMUX_LIMIT_KEY,          "0"},
+        { GLUSTERD_LOCALTIME_LOGGING_KEY,       "disable"},
         { NULL },
 };
 
@@ -870,6 +871,60 @@ out:
 }
 
 static int
+glusterd_validate_localtime_logging (char *key, char *value, char *errstr)
+{
+        int32_t            ret                      = -1;
+        xlator_t          *this                     = NULL;
+        glusterd_conf_t   *conf                     = NULL;
+        int                already_enabled          = 0;
+
+        this = THIS;
+        GF_VALIDATE_OR_GOTO ("glusterd", this, out);
+
+        conf = this->private;
+        GF_VALIDATE_OR_GOTO (this->name, conf, out);
+
+        GF_VALIDATE_OR_GOTO (this->name, key, out);
+        GF_VALIDATE_OR_GOTO (this->name, value, out);
+        GF_VALIDATE_OR_GOTO (this->name, errstr, out);
+
+        ret = 0;
+
+        if (strcmp (key, GLUSTERD_LOCALTIME_LOGGING_KEY)) {
+                goto out;
+        }
+
+        if ((strcmp (value, "enable")) &&
+            (strcmp (value, "disable"))) {
+                snprintf (errstr, PATH_MAX,
+                          "Invalid option(%s). Valid options "
+                          "are 'enable' and 'disable'", value);
+                gf_msg (this->name, GF_LOG_ERROR, EINVAL,
+                        GD_MSG_INVALID_ENTRY, "%s", errstr);
+                ret = -1;
+        }
+
+        already_enabled = gf_log_get_localtime ();
+
+        if (strcmp (value, "enable") == 0) {
+                gf_log_set_localtime (1);
+                if (!already_enabled)
+                        gf_msg (this->name, GF_LOG_INFO, 0,
+                                GD_MSG_LOCALTIME_LOGGING_ENABLE,
+                                "localtime logging enable");
+        } else if (strcmp (value, "disable") == 0) {
+                gf_log_set_localtime (0);
+                if (already_enabled)
+                        gf_msg (this->name, GF_LOG_INFO, 0,
+                                GD_MSG_LOCALTIME_LOGGING_DISABLE,
+                                "localtime logging disable");
+        }
+
+out:
+        return ret;
+}
+
+static int
 glusterd_op_stage_set_volume (dict_t *dict, char **op_errstr)
 {
         int                   ret                         = -1;
@@ -1253,6 +1308,14 @@ glusterd_op_stage_set_volume (dict_t *dict, char **op_errstr)
                         goto out;
                 }
 
+                ret = glusterd_validate_localtime_logging (key, value, errstr);
+                if (ret) {
+                        gf_msg (this->name, GF_LOG_ERROR, 0,
+                                GD_MSG_LOCALTIME_LOGGING_VOL_OPT_VALIDATE_FAIL,
+                                "Failed to validate localtime "
+                                "logging volume options");
+                        goto out;
+                }
 
                 if (volinfo) {
                         ret = glusterd_volinfo_get (volinfo,
@@ -2639,6 +2702,7 @@ out:
         return ret;
 }
 
+
 int
 glusterd_op_get_max_opversion (char **op_errstr, dict_t *rsp_dict)
 {
@@ -2658,6 +2722,7 @@ out:
         return ret;
 }
 
+
 static int
 glusterd_set_shared_storage (dict_t *dict, char *key, char *value,
                              char **op_errstr)
@@ -2735,7 +2800,6 @@ out:
 }
 
 
-
 static int
 glusterd_op_set_volume (dict_t *dict, char **errstr)
 {
diff --git a/xlators/mgmt/glusterd/src/glusterd-utils.c b/xlators/mgmt/glusterd/src/glusterd-utils.c
index f1627df688f..9dcb4f78089 100644
--- a/xlators/mgmt/glusterd/src/glusterd-utils.c
+++ b/xlators/mgmt/glusterd/src/glusterd-utils.c
@@ -1937,6 +1937,7 @@ glusterd_volume_start_glusterfs (glusterd_volinfo_t  *volinfo,
         int                     port = 0;
         int                     rdma_port = 0;
         char                    *bind_address = NULL;
+        char                    *localtime_logging = NULL;
         char                    socketpath[PATH_MAX] = {0};
         char                    glusterd_uuid[1024] = {0,};
         char                    valgrind_logfile[PATH_MAX] = {0};
@@ -2056,6 +2057,12 @@ retry:
                          "--xlator-option", glusterd_uuid,
                          NULL);
 
+        if (dict_get_str (priv->opts, GLUSTERD_LOCALTIME_LOGGING_KEY,
+                          &localtime_logging) == 0) {
+                if (strcmp (localtime_logging, "enable") == 0)
+                        runner_add_arg (&runner, "--localtime-logging");
+        }
+
         runner_add_arg (&runner, "--brick-port");
         if (volinfo->transport_type != GF_TRANSPORT_BOTH_TCP_RDMA) {
                 runner_argprintf (&runner, "%d", port);
diff --git a/xlators/mgmt/glusterd/src/glusterd-volgen.c b/xlators/mgmt/glusterd/src/glusterd-volgen.c
index 1ada7232f3e..d82e0f1ae86 100644
--- a/xlators/mgmt/glusterd/src/glusterd-volgen.c
+++ b/xlators/mgmt/glusterd/src/glusterd-volgen.c
@@ -1310,6 +1310,25 @@ log_format_option_handler (volgen_graph_t *graph, struct volopt_map_entry *vme,
 }
 
 static int
+log_localtime_logging_option_handler (volgen_graph_t *graph, struct volopt_map_entry *vme,
+                                      void *param)
+{
+        char  *role = NULL;
+        struct volopt_map_entry vme2 = {0,};
+
+        role = (char *) param;
+
+        if (strcmp (vme->option, "!cluster.localtime-logging") != 0 ||
+            !strstr (vme->key, role))
+                return 0;
+
+        memcpy (&vme2, vme, sizeof (vme2));
+        vme2.option = GLUSTERD_LOCALTIME_LOGGING_KEY;
+
+        return basic_option_handler (graph, &vme2, NULL);
+}
+
+static int
 log_buf_size_option_handler (volgen_graph_t *graph,
                              struct volopt_map_entry *vme,
                              void *param)
@@ -1414,6 +1433,9 @@ server_spec_option_handler (volgen_graph_t *graph,
         if (!ret)
                 ret = log_flush_timeout_option_handler (graph, vme, "brick");
 
+        if (!ret)
+                ret = log_localtime_logging_option_handler (graph, vme, "brick");
+
         return ret;
 }
 
@@ -3974,6 +3996,14 @@ graph_set_generic_options (xlator_t *this, volgen_graph_t *graph,
                         GD_MSG_GRAPH_SET_OPT_FAIL,
                         "Failed to change "
                         "log-flush-timeout option");
+
+        ret = volgen_graph_set_options_generic (graph, set_dict, "client",
+                                                &log_localtime_logging_option_handler);
+        if (ret)
+                gf_msg (this->name, GF_LOG_WARNING, 0,
+                        GD_MSG_GRAPH_SET_OPT_FAIL,
+                        "Failed to change "
+                        "log-localtime-logging option");
         return 0;
 }
 
diff --git a/xlators/mgmt/glusterd/src/glusterd-volume-set.c b/xlators/mgmt/glusterd/src/glusterd-volume-set.c
index 2983484d12e..5eabd5e6481 100644
--- a/xlators/mgmt/glusterd/src/glusterd-volume-set.c
+++ b/xlators/mgmt/glusterd/src/glusterd-volume-set.c
@@ -3515,7 +3515,12 @@ struct volopt_map_entry glusterd_volopt_map[] = {
           .op_version = GD_OP_VERSION_3_11_0,
           .flags      = OPT_FLAG_CLIENT_OPT
         },
-
+        { .key         = GLUSTERD_LOCALTIME_LOGGING_KEY,
+          .voltype     = "mgmt/glusterd",
+          .type        = GLOBAL_DOC,
+          .op_version  = GD_OP_VERSION_3_12_0,
+          .validate_fn = validate_boolean
+        },
         { .key         = NULL
         }
 };
diff --git a/xlators/mgmt/glusterd/src/glusterd.c b/xlators/mgmt/glusterd/src/glusterd.c
index f8a38f965a6..68998f0a877 100644
--- a/xlators/mgmt/glusterd/src/glusterd.c
+++ b/xlators/mgmt/glusterd/src/glusterd.c
@@ -1401,6 +1401,7 @@ init (xlator_t *this)
         int32_t            workers                    = 0;
         gf_boolean_t       upgrade                    = _gf_false;
         gf_boolean_t       downgrade                  = _gf_false;
+        char              *localtime_logging          = NULL;
 
 #ifndef GF_DARWIN_HOST_OS
         {
@@ -1846,6 +1847,25 @@ init (xlator_t *this)
         if (ret < 0)
                 goto out;
 
+        if (dict_get_str (conf->opts, GLUSTERD_LOCALTIME_LOGGING_KEY,
+                          &localtime_logging) == 0) {
+                int already_enabled = gf_log_get_localtime ();
+
+                if (strcmp (localtime_logging, "enable") == 0) {
+                        gf_log_set_localtime (1);
+                        if (!already_enabled)
+                                gf_msg (this->name, GF_LOG_INFO, 0,
+                                        GD_MSG_LOCALTIME_LOGGING_ENABLE,
+                                        "localtime logging enable");
+                } else if (strcmp (localtime_logging, "disable") == 0) {
+                        gf_log_set_localtime (0);
+                        if (already_enabled)
+                                gf_msg (this->name, GF_LOG_INFO, 0,
+                                        GD_MSG_LOCALTIME_LOGGING_DISABLE,
+                                        "localtime logging disable");
+                }
+        }
+
         conf->blockers = 0;
         /* If the peer count is less than 2 then this would be the best time to
          * spawn process/bricks that may need (re)starting since last time
diff --git a/xlators/mgmt/glusterd/src/glusterd.h b/xlators/mgmt/glusterd/src/glusterd.h
index 3226ec24c0f..228a3454c1b 100644
--- a/xlators/mgmt/glusterd/src/glusterd.h
+++ b/xlators/mgmt/glusterd/src/glusterd.h
@@ -54,8 +54,8 @@
 #define GLUSTER_SHARED_STORAGE          "gluster_shared_storage"
 #define GLUSTERD_SHARED_STORAGE_KEY     "cluster.enable-shared-storage"
 #define GLUSTERD_BRICK_MULTIPLEX_KEY    "cluster.brick-multiplex"
-
 #define GLUSTERD_BRICKMUX_LIMIT_KEY     "cluster.max-bricks-per-process"
+#define GLUSTERD_LOCALTIME_LOGGING_KEY  "cluster.localtime-logging"
 
 #define GLUSTERD_SNAPS_MAX_HARD_LIMIT 256
 #define GLUSTERD_SNAPS_DEF_SOFT_LIMIT_PERCENT 90