core: use gf_time_fmt() instead of localtime()+strftime()

gf_time_fmt() has existed since 3.3; it provides consistent timestamps
(i.e. UTC times) throughout the implementation. (BTW, the other name for UTC
is GMT.)

N.B. many (all?) commercial storage solutions use UTC time for logging.
This makes for easier debugging across geographically distributed systems.

Also adding a "%s" fmt for portably printing time as simple numeric
value on systems regardless of whether 32-bit or 64-bit time_t. Plus a
minor tweak to return a ptr to the dest-string to allow gf_time_fmt()
to be passed as a param in a *printf().

Someday we should pick the "one true" timestamp format and revise all
calls to gf_time_fmt() to use it instead of the five or six different
formats.

Change-Id: I78202ae14b7246fa424efeea56bf2463e14abfb0
BUG: 1109917
Signed-off-by: Kaleb S. KEITHLEY <kkeithle@redhat.com>
Reviewed-on: http://review.gluster.org/8085
Tested-by: Gluster Build System <jenkins@build.gluster.com>
Reviewed-by: Niels de Vos <ndevos@redhat.com>
Reviewed-by: Vijay Bellur <vbellur@redhat.com>

7 files changed, 50 insertions, 78 deletions

diff --git a/libglusterfs/src/common-utils.c b/libglusterfs/src/common-utils.c
index 1318c4d49a6..b1afa082844 100644
--- a/libglusterfs/src/common-utils.c
+++ b/libglusterfs/src/common-utils.c
@@ -2470,6 +2470,7 @@ static const char *__gf_timefmts[] = {
         "%b %d %T",
         "%F %H%M%S",
 	"%Y-%m-%d-%T",
+        "%s",
 };
 
 static const char *__gf_zerotimes[] = {
@@ -2478,6 +2479,7 @@ static const char *__gf_zerotimes[] = {
         "xxx 00 00:00:00",
         "0000-00-00 000000",
 	"0000-00-00-00:00:00",
+        "0",
 };
 
 void
diff --git a/libglusterfs/src/common-utils.h b/libglusterfs/src/common-utils.h
index d2bc42b9662..2493ba10816 100644
--- a/libglusterfs/src/common-utils.h
+++ b/libglusterfs/src/common-utils.h
@@ -486,13 +486,14 @@ typedef enum {
         gf_timefmt_default = 0,
         gf_timefmt_FT = 0,  /* YYYY-MM-DD hh:mm:ss */
         gf_timefmt_Ymd_T,   /* YYYY/MM-DD-hh:mm:ss */
-        gf_timefmt_bdT,     /* ddd DD hh:mm:ss */
+        gf_timefmt_bdT,     /* MMM DD hh:mm:ss */
         gf_timefmt_F_HMS,   /* YYYY-MM-DD hhmmss */
 	gf_timefmt_dirent,
+        gf_timefmt_s,
         gf_timefmt_last
 } gf_timefmts;
 
-static inline void
+static inline char *
 gf_time_fmt (char *dst, size_t sz_dst, time_t utime, unsigned int fmt)
 {
         extern void _gf_timestuff (gf_timefmts *, const char ***, const char ***);
@@ -509,6 +510,7 @@ gf_time_fmt (char *dst, size_t sz_dst, time_t utime, unsigned int fmt)
         } else {
                 strncpy (dst, "N/A", sz_dst);
         }
+        return dst;
 }
 
 int
diff --git a/xlators/debug/trace/src/trace.c b/xlators/debug/trace/src/trace.c
index c1293127495..88a41ae480f 100644
--- a/xlators/debug/trace/src/trace.c
+++ b/xlators/debug/trace/src/trace.c
@@ -25,21 +25,18 @@ trace_stat_to_str(struct iatt *buf, char *str, size_t len)
         char     atime_buf[256]    = {0,};
         char     mtime_buf[256]    = {0,};
         char     ctime_buf[256]    = {0,};
-        uint64_t ia_time           = 0;
 
         if (!buf)
                 return;
 
-        ia_time = buf->ia_atime;
-        strftime (atime_buf, 256, "[%b %d %H:%M:%S]",
-                  localtime ((time_t *)&ia_time));
-        ia_time = buf->ia_mtime;
-        strftime (mtime_buf, 256, "[%b %d %H:%M:%S]",
-                  localtime ((time_t *)&ia_time));
+        gf_time_fmt (atime_buf, sizeof atime_buf, buf->ia_atime,
+                     gf_timefmt_dirent);
 
-        ia_time = buf->ia_ctime;
-        strftime (ctime_buf, 256, "[%b %d %H:%M:%S]",
-                  localtime ((time_t *)&ia_time));
+        gf_time_fmt (mtime_buf, sizeof mtime_buf, buf->ia_mtime,
+                     gf_timefmt_dirent);
+
+        gf_time_fmt (ctime_buf, sizeof ctime_buf, buf->ia_ctime,
+                     gf_timefmt_dirent);
 
         snprintf (str, len,
                   "gfid=%s ino=%"PRIu64", mode=%o, "
@@ -60,24 +57,18 @@ trace_stat_to_str(struct iatt *buf, char *str, size_t len)
 int
 dump_history_trace (circular_buffer_t *cb, void *data)
 {
-        char    *string      = NULL;
-        struct  tm      *tm  = NULL;
-        char    timestr[256] = {0,};
-
-        string = (char *)cb->data;
-        tm    = localtime (&cb->tv.tv_sec);
+        char     timestr[256] = {0,};
 
         /* Since we are continuing with adding entries to the buffer even when
            gettimeofday () fails, it's safe to check tm and then dump the time
            at which the entry was added to the buffer */
-        if (tm) {
-                strftime (timestr, 256, "%Y-%m-%d %H:%M:%S", tm);
-                snprintf (timestr + strlen (timestr), 256 - strlen (timestr),
-                          ".%"GF_PRI_SUSECONDS, cb->tv.tv_usec);
-                gf_proc_dump_write ("TIME", "%s", timestr);
-        }
 
-        gf_proc_dump_write ("FOP", "%s\n", string);
+        gf_time_fmt (timestr, sizeof timestr, cb->tv.tv_sec, gf_timefmt_Ymd_T);
+        snprintf (timestr + strlen (timestr), 256 - strlen (timestr),
+                  ".%"GF_PRI_SUSECONDS, cb->tv.tv_usec);
+        gf_proc_dump_write ("TIME", "%s", timestr);
+
+        gf_proc_dump_write ("FOP", "%s\n", cb->data);
 
         return 0;
 }
@@ -2033,7 +2024,6 @@ int
 trace_setattr (call_frame_t *frame, xlator_t *this, loc_t *loc,
                struct iatt *stbuf, int32_t valid, dict_t *xdata)
 {
-        uint64_t     ia_time          = 0;
         char         actime_str[256]  = {0,};
         char         modtime_str[256] = {0,};
         trace_conf_t *conf            = NULL;
@@ -2070,13 +2060,11 @@ trace_setattr (call_frame_t *frame, xlator_t *this, loc_t *loc,
                 }
 
                 if (valid & (GF_SET_ATTR_ATIME | GF_SET_ATTR_MTIME)) {
-                        ia_time = stbuf->ia_atime;
-                        strftime (actime_str, 256, "[%b %d %H:%M:%S]",
-                                  localtime ((time_t *)&ia_time));
+                        gf_time_fmt (actime_str, sizeof actime_str,
+                                     stbuf->ia_atime, gf_timefmt_bdT);
 
-                        ia_time = stbuf->ia_mtime;
-                        strftime (modtime_str, 256, "[%b %d %H:%M:%S]",
-                                  localtime ((time_t *)&ia_time));
+                        gf_time_fmt (modtime_str, sizeof modtime_str,
+                                     stbuf->ia_mtime, gf_timefmt_bdT);
 
                         snprintf (string, sizeof (string),
                                   "%"PRId64": gfid=%s path=%s "
@@ -2104,7 +2092,6 @@ int
 trace_fsetattr (call_frame_t *frame, xlator_t *this, fd_t *fd,
                 struct iatt *stbuf, int32_t valid, dict_t *xdata)
 {
-        uint64_t       ia_time          = 0;
         char           actime_str[256]  = {0,};
         char           modtime_str[256] = {0,};
         trace_conf_t   *conf            = NULL;
@@ -2139,13 +2126,11 @@ trace_fsetattr (call_frame_t *frame, xlator_t *this, fd_t *fd,
                 }
 
                 if (valid & (GF_SET_ATTR_ATIME | GF_SET_ATTR_MTIME)) {
-                        ia_time = stbuf->ia_atime;
-                        strftime (actime_str, 256, "[%b %d %H:%M:%S]",
-                                  localtime ((time_t *)&ia_time));
+                        gf_time_fmt (actime_str, sizeof actime_str,
+                                     stbuf->ia_atime, gf_timefmt_bdT);
 
-                        ia_time = stbuf->ia_mtime;
-                        strftime (modtime_str, 256, "[%b %d %H:%M:%S]",
-                                  localtime ((time_t *)&ia_time));
+                        gf_time_fmt (modtime_str, sizeof modtime_str,
+                                     stbuf->ia_mtime, gf_timefmt_bdT);
 
                         snprintf (string, sizeof (string),
                                   "%"PRId64": gfid=%s fd=%p "
diff --git a/xlators/mgmt/glusterd/src/glusterd-snapshot.c b/xlators/mgmt/glusterd/src/glusterd-snapshot.c
index bb98cb806e3..097613184a0 100644
--- a/xlators/mgmt/glusterd/src/glusterd-snapshot.c
+++ b/xlators/mgmt/glusterd/src/glusterd-snapshot.c
@@ -2852,9 +2852,8 @@ glusterd_snapshot_get_snap_detail (dict_t *dict, glusterd_snap_t *snap,
         int                 ret           = -1;
         int                 volcount      = 0;
         char                key[PATH_MAX] = {0,};
+        char                timestr[64]   = {0,};
         char               *value         = NULL;
-        char               *timestr       = NULL;
-        struct tm          *tmptr         = NULL;
         glusterd_volinfo_t *snap_vol      = NULL;
         glusterd_volinfo_t *tmp_vol       = NULL;
         xlator_t           *this          = NULL;
@@ -2894,36 +2893,23 @@ glusterd_snapshot_get_snap_detail (dict_t *dict, glusterd_snap_t *snap,
         }
         value = NULL;
 
-        tmptr = localtime (&(snap->time_stamp));
-        if (NULL == tmptr) {
-                gf_log (this->name, GF_LOG_ERROR, "Failed to convert "
-                                "time_t to *tm");
-                ret = -1;
-                goto out;
-        }
+        gf_time_fmt (timestr, sizeof timestr, snap->time_stamp,
+                     gf_timefmt_FT);
+        value = gf_strdup (timestr);
 
-        timestr = GF_CALLOC (1, PATH_MAX, gf_gld_mt_char);
-        if (NULL == timestr) {
-                ret = -1;
-                goto out;
-        }
-
-        ret = strftime (timestr, PATH_MAX, "%Y-%m-%d %H:%M:%S", tmptr);
-        if (0 == ret) {
-                gf_log (this->name, GF_LOG_ERROR, "Failed to convert time_t "
-                        "to string");
+        if (NULL == value) {
                 ret = -1;
                 goto out;
         }
 
         snprintf (key, sizeof (key), "%s.snap-time", keyprefix);
-        ret = dict_set_dynstr (dict, key, timestr);
+        ret = dict_set_dynstr (dict, key, value);
         if (ret) {
                 gf_log (this->name, GF_LOG_ERROR, "Failed to set "
                                 "snap time stamp in dictionary");
                 goto out;
         }
-        timestr = NULL;
+        value = NULL;
 
         /* If snap description is provided then add that into dictionary */
         if (NULL != snap->description) {
@@ -3012,9 +2998,6 @@ out:
         if (value)
                 GF_FREE (value);
 
-        if (timestr)
-                GF_FREE(timestr);
-
         return ret;
 }
 
diff --git a/xlators/mount/fuse/src/fuse-bridge.c b/xlators/mount/fuse/src/fuse-bridge.c
index 380093a9a7a..6290d0a783f 100644
--- a/xlators/mount/fuse/src/fuse-bridge.c
+++ b/xlators/mount/fuse/src/fuse-bridge.c
@@ -5003,21 +5003,15 @@ out:
 int
 dump_history_fuse (circular_buffer_t *cb, void *data)
 {
-        char       *string   =  NULL;
-        struct tm  *tm       =  NULL;
         char       timestr[256] = {0,};
 
-        string = (char *)cb->data;
-        tm = localtime (&cb->tv.tv_sec);
+        gf_time_fmt (timestr, sizeof timestr, cb->tv.tv_sec, gf_timefmt_F_HMS);
 
-        if (tm) {
-                strftime (timestr, 256, "%Y-%m-%d %H:%M:%S", tm);
-                snprintf (timestr + strlen (timestr), 256 - strlen (timestr),
-                          ".%"GF_PRI_SUSECONDS, cb->tv.tv_usec);
-                gf_proc_dump_write ("TIME", "%s", timestr);
-        }
+        snprintf (timestr + strlen (timestr), 256 - strlen (timestr),
+                  ".%"GF_PRI_SUSECONDS, cb->tv.tv_usec);
+        gf_proc_dump_write ("TIME", "%s", timestr);
 
-        gf_proc_dump_write ("message", "%s\n", string);
+        gf_proc_dump_write ("message", "%s\n", cb->data);
 
         return 0;
 }
diff --git a/xlators/protocol/client/src/client.c b/xlators/protocol/client/src/client.c
index 546b8b8f376..fbd0ff22737 100644
--- a/xlators/protocol/client/src/client.c
+++ b/xlators/protocol/client/src/client.c
@@ -2476,6 +2476,7 @@ int
 client_init_grace_timer (xlator_t *this, dict_t *options,
                          clnt_conf_t *conf)
 {
+        char      timestr[64]    = {0,};
         char     *lk_heal        = NULL;
         int32_t   ret            = -1;
         int32_t   grace_timeout  = -1;
@@ -2501,8 +2502,10 @@ client_init_grace_timer (xlator_t *this, dict_t *options,
 
         conf->grace_ts.tv_nsec  = 0;
 
-        gf_log (this->name, GF_LOG_DEBUG, "Client grace timeout "
-                "value = %"GF_PRI_SECOND, conf->grace_ts.tv_sec);
+        gf_time_fmt (timestr, sizeof timestr, conf->grace_ts.tv_sec,
+                     gf_timefmt_s);
+        gf_log (this->name, GF_LOG_DEBUG, "Client grace timeout value = %s",
+                timestr);
 
         ret = 0;
 out:
diff --git a/xlators/protocol/server/src/server.c b/xlators/protocol/server/src/server.c
index a511540cac6..6f6be52ab15 100644
--- a/xlators/protocol/server/src/server.c
+++ b/xlators/protocol/server/src/server.c
@@ -632,6 +632,7 @@ int
 server_init_grace_timer (xlator_t *this, dict_t *options,
                          server_conf_t *conf)
 {
+        char      timestr[64]    = {0,};
         int32_t   ret            = -1;
         int32_t   grace_timeout  = -1;
         char     *lk_heal        = NULL;
@@ -655,8 +656,10 @@ server_init_grace_timer (xlator_t *this, dict_t *options,
         else
                 conf->grace_ts.tv_sec = 10;
 
-        gf_log (this->name, GF_LOG_DEBUG, "Server grace timeout "
-                "value = %"GF_PRI_SECOND, conf->grace_ts.tv_sec);
+        gf_time_fmt (timestr, sizeof timestr, conf->grace_ts.tv_sec,
+                     gf_timefmt_s);
+        gf_log (this->name, GF_LOG_DEBUG, "Server grace timeout value = %s",
+                timestr);
 
         conf->grace_ts.tv_nsec  = 0;