summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorCsaba Henk <csaba@redhat.com>2020-03-12 08:20:31 +0100
committerXavi Hernandez <xhernandez@redhat.com>2020-06-15 12:41:10 +0000
commit9a4f91abc07e77165baa7f0499a4887ec9f3e4fe (patch)
tree95b8f0d685674b85283a9f683f716d95b5636c50
parent71dd19f710b81136f318b3a95ae430971198ee70 (diff)
Indicate timezone offsets in timestamps
Logs and other output carrying timestamps will have now timezone offsets indicated, eg.: [2020-03-12 07:01:05.584482 +0000] I [MSGID: 106143] [glusterd-pmap.c:388:pmap_registry_remove] 0-pmap: removing brick (null) on port 49153 To this end, - gf_time_fmt() now inserts timezone offset via %z strftime(3) template. - A new utility function has been added, gf_time_fmt_tv(), that takes a struct timeval pointer (*tv) instead of a time_t value to specify the time. If tv->tv_usec is negative, gf_time_fmt_tv(... tv ...) is equivalent to gf_time_fmt(... tv->tv_sec ...) Otherwise it also inserts tv->tv_usec to the formatted string. - Building timestamps of usec precision has been converted to gf_time_fmt_tv, which is necessary because the method of appending a period and the usec value to the end of the timestamp does not work if the timestamp has zone offset, but it's also beneficial in terms of eliminating repetition. - The buffer passed to gf_time_fmt/gf_time_fmt_tv has been unified to be of GF_TIMESTR_SIZE size (256). We need slightly larger buffer space to accommodate the zone offset and it's preferable to use a buffer which is undisputedly large enough. This change does *not* do the following: - Retaining a method of timestamp creation without timezone offset. As to my understanding we don't need such backward compatibility as the code just emits timestamps to logs and other diagnostic texts, and doesn't do any later processing on them that would rely on their format. An exception to this, ie. a case where timestamp is built for internal use, is graph.c:fill_uuid(). As far as I can see, what matters in that case is the uniqueness of the produced string, not the format. - Implementing a single-token (space free) timestamp format. While some timestamp formats used to be single-token, now all of them will include a space preceding the offset indicator. Again, I did not see a use case where this could be significant in terms of representation. - Moving the codebase to a single unified timestamp format and dropping the fmt argument of gf_time_fmt/gf_time_fmt_tv. While the gf_timefmt_FT format is almost ubiquitous, there are a few cases where different formats are used. I'm not convinced there is any reason to not use gf_timefmt_FT in those cases too, but I did not want to make a decision in this regard. Change-Id: I0af73ab5d490cca7ed8d07a2ce7ac22a6df2920a Updates: #837 Signed-off-by: Csaba Henk <csaba@redhat.com>
-rw-r--r--cli/src/cli-rpc-ops.c4
-rw-r--r--cli/src/cli-xml-output.c17
-rw-r--r--glusterfsd/src/glusterfsd.c2
-rw-r--r--libglusterfs/src/common-utils.c2
-rw-r--r--libglusterfs/src/glusterfs/common-utils.h33
-rw-r--r--libglusterfs/src/graph.c9
-rw-r--r--libglusterfs/src/logging.c131
-rw-r--r--libglusterfs/src/stack.c4
-rw-r--r--libglusterfs/src/statedump.c12
-rw-r--r--rpc/rpc-lib/src/rpc-clnt.c19
-rwxr-xr-xtests/bugs/logging/bug-823081.t8
-rw-r--r--xlators/debug/io-stats/src/io-stats.c36
-rw-r--r--xlators/debug/trace/src/trace.c20
-rw-r--r--xlators/features/bit-rot/src/bitd/bit-rot-scrub.c12
-rw-r--r--xlators/features/locks/src/posix.c8
-rw-r--r--xlators/features/trash/src/trash.c2
-rw-r--r--xlators/mgmt/glusterd/src/glusterd-handler.c2
-rw-r--r--xlators/mgmt/glusterd/src/glusterd-snapshot.c2
-rw-r--r--xlators/mgmt/glusterd/src/glusterd-utils.c2
-rw-r--r--xlators/mount/fuse/src/fuse-bridge.c6
-rw-r--r--xlators/performance/io-cache/src/io-cache.c8
-rw-r--r--xlators/performance/quick-read/src/quick-read.c7
-rw-r--r--xlators/storage/posix/src/posix-helpers.c2
23 files changed, 158 insertions, 190 deletions
diff --git a/cli/src/cli-rpc-ops.c b/cli/src/cli-rpc-ops.c
index 09d7d52..7a97798 100644
--- a/cli/src/cli-rpc-ops.c
+++ b/cli/src/cli-rpc-ops.c
@@ -5728,7 +5728,7 @@ gf_cli_top_volume_cbk(struct rpc_req *req, struct iovec *iov, int count,
double time = 0;
int32_t time_sec = 0;
long int time_usec = 0;
- char timestr[256] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
char *openfd_str = NULL;
@@ -7818,7 +7818,7 @@ cmd_heal_volume_brick_out(dict_t *dict, int brick)
char *status = NULL;
uint64_t i = 0;
uint32_t time = 0;
- char timestr[32] = {0};
+ char timestr[GF_TIMESTR_SIZE] = {0};
char *shd_status = NULL;
snprintf(key, sizeof key, "%d-hostname", brick);
diff --git a/cli/src/cli-xml-output.c b/cli/src/cli-xml-output.c
index 01dd22b..069de75 100644
--- a/cli/src/cli-xml-output.c
+++ b/cli/src/cli-xml-output.c
@@ -1661,15 +1661,15 @@ cli_xml_output_vol_top_rw_perf(xmlTextWriterPtr writer, dict_t *dict,
int ret = -1;
char *filename = NULL;
uint64_t throughput = 0;
- long int time_sec = 0;
- long int time_usec = 0;
- char timestr[256] = {
+ struct timeval tv = {
+ 0,
+ };
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
char key[1024] = {
0,
};
- int len;
/* <file> */
ret = xmlTextWriterStartElement(writer, (xmlChar *)"file");
@@ -1692,19 +1692,16 @@ cli_xml_output_vol_top_rw_perf(xmlTextWriterPtr writer, dict_t *dict,
XML_RET_CHECK_AND_GOTO(ret, out);
snprintf(key, sizeof(key), "%d-time-sec-%d", brick_index, member_index);
- ret = dict_get_int32(dict, key, (int32_t *)&time_sec);
+ ret = dict_get_int32(dict, key, (int32_t *)&tv.tv_sec);
if (ret)
goto out;
snprintf(key, sizeof(key), "%d-time-usec-%d", brick_index, member_index);
- ret = dict_get_int32(dict, key, (int32_t *)&time_usec);
+ ret = dict_get_int32(dict, key, (int32_t *)&tv.tv_usec);
if (ret)
goto out;
- gf_time_fmt(timestr, sizeof timestr, time_sec, gf_timefmt_FT);
- len = strlen(timestr);
- snprintf(timestr + len, sizeof(timestr) - len, ".%" GF_PRI_SUSECONDS,
- time_usec);
+ gf_time_fmt_tv(timestr, sizeof timestr, &tv, gf_timefmt_FT);
ret = xmlTextWriterWriteFormatElement(writer, (xmlChar *)"time", "%s",
timestr);
XML_RET_CHECK_AND_GOTO(ret, out);
diff --git a/glusterfsd/src/glusterfsd.c b/glusterfsd/src/glusterfsd.c
index 44c6c41..f36ce2b 100644
--- a/glusterfsd/src/glusterfsd.c
+++ b/glusterfsd/src/glusterfsd.c
@@ -1975,7 +1975,7 @@ parse_cmdline(int argc, char *argv[], glusterfs_ctx_t *ctx)
struct stat stbuf = {
0,
};
- char timestr[32];
+ char timestr[GF_TIMESTR_SIZE];
char tmp_logfile[1024] = {0};
char *tmp_logfile_dyn = NULL;
char *tmp_logfilebase = NULL;
diff --git a/libglusterfs/src/common-utils.c b/libglusterfs/src/common-utils.c
index 585952d..899d579 100644
--- a/libglusterfs/src/common-utils.c
+++ b/libglusterfs/src/common-utils.c
@@ -889,7 +889,7 @@ gf_print_trace(int32_t signum, glusterfs_ctx_t *ctx)
char msg[1024] = {
0,
};
- char timestr[64] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
call_stack_t *stack = NULL;
diff --git a/libglusterfs/src/glusterfs/common-utils.h b/libglusterfs/src/glusterfs/common-utils.h
index 13e413c..69c258d 100644
--- a/libglusterfs/src/glusterfs/common-utils.h
+++ b/libglusterfs/src/glusterfs/common-utils.h
@@ -148,6 +148,9 @@ trap(void);
#define GF_THREAD_NAME_LIMIT 16
#define GF_THREAD_NAME_PREFIX "glfs_"
+/* Advisory buffer size for formatted timestamps (see gf_time_fmt) */
+#define GF_TIMESTR_SIZE 256
+
/*
* we could have initialized these as +ve values and treated
* them as negative while comparing etc.. (which would have
@@ -790,7 +793,7 @@ typedef enum {
} gf_timefmts;
static inline char *
-gf_time_fmt(char *dst, size_t sz_dst, time_t utime, unsigned int fmt)
+gf_time_fmt_tv(char *dst, size_t sz_dst, struct timeval *tv, unsigned int fmt)
{
extern void _gf_timestuff(const char ***, const char ***);
static gf_timefmts timefmt_last = (gf_timefmts)-1;
@@ -798,6 +801,8 @@ gf_time_fmt(char *dst, size_t sz_dst, time_t utime, unsigned int fmt)
static const char **zeros;
struct tm tm, *res;
int localtime = 0;
+ int len = 0;
+ int pos = 0;
if (timefmt_last == ((gf_timefmts)-1)) {
_gf_timestuff(&fmts, &zeros);
@@ -807,15 +812,35 @@ gf_time_fmt(char *dst, size_t sz_dst, time_t utime, unsigned int fmt)
fmt = gf_timefmt_default;
}
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);
+ res = localtime ? localtime_r(&tv->tv_sec, &tm)
+ : gmtime_r(&tv->tv_sec, &tm);
+ if (tv->tv_sec && (res != NULL)) {
+ len = strftime(dst, sz_dst, fmts[fmt], &tm);
+ if (len == 0)
+ return dst;
+ pos += len;
+ if (tv->tv_usec >= 0) {
+ len = snprintf(dst + pos, sz_dst - pos, ".%" GF_PRI_SUSECONDS,
+ tv->tv_usec);
+ if (len >= sz_dst - pos)
+ return dst;
+ pos += len;
+ }
+ strftime(dst + pos, sz_dst - pos, " %z", &tm);
} else {
strncpy(dst, "N/A", sz_dst);
}
return dst;
}
+static inline char *
+gf_time_fmt(char *dst, size_t sz_dst, time_t utime, unsigned int fmt)
+{
+ struct timeval tv = {utime, -1};
+
+ return gf_time_fmt_tv(dst, sz_dst, &tv, fmt);
+}
+
/* This function helps us use gfid (unique identity) to generate inode's unique
* number in glusterfs.
*/
diff --git a/libglusterfs/src/graph.c b/libglusterfs/src/graph.c
index 64e77e0..13f298e 100644
--- a/libglusterfs/src/graph.c
+++ b/libglusterfs/src/graph.c
@@ -41,7 +41,7 @@ _gf_dump_details (int argc, char **argv)
{
extern FILE *gf_log_logfile;
int i = 0;
- char timestr[64];
+ char timestr[GF_TIMESTR_SIZE];
time_t utime = 0;
pid_t mypid = 0;
struct utsname uname_buf = {{0, }, };
@@ -482,7 +482,7 @@ fill_uuid(char *uuid, int size, struct timeval tv)
char hostname[50] = {
0,
};
- char now_str[64];
+ char now_str[GF_TIMESTR_SIZE];
if (gethostname(hostname, sizeof(hostname) - 1) != 0) {
gf_msg("graph", GF_LOG_ERROR, errno, LG_MSG_GETHOSTNAME_FAILED,
@@ -490,9 +490,8 @@ fill_uuid(char *uuid, int size, struct timeval tv)
hostname[sizeof(hostname) - 1] = '\0';
}
- gf_time_fmt(now_str, sizeof now_str, tv.tv_sec, gf_timefmt_dirent);
- snprintf(uuid, size, "%s-%d-%s:%" GF_PRI_SUSECONDS, hostname, getpid(),
- now_str, tv.tv_usec);
+ gf_time_fmt_tv(now_str, sizeof now_str, &tv, gf_timefmt_dirent);
+ snprintf(uuid, size, "%s-%d-%s", hostname, getpid(), now_str);
return;
}
diff --git a/libglusterfs/src/logging.c b/libglusterfs/src/logging.c
index 3d7d317..a930d3e 100644
--- a/libglusterfs/src/logging.c
+++ b/libglusterfs/src/logging.c
@@ -35,7 +35,6 @@
#define GF_LOG_CONTROL_FILE "/etc/glusterfs/logger.conf"
#define GF_LOG_BACKTRACE_DEPTH 5
#define GF_LOG_BACKTRACE_SIZE 4096
-#define GF_LOG_TIMESTR_SIZE 256
#define GF_MAX_SLOG_PAIR_COUNT 100
#include "glusterfs/logging.h"
@@ -760,7 +759,7 @@ _gf_log_callingfn(const char *domain, const char *file, const char *function,
xlator_t *this = THIS;
char *logline = NULL;
char *msg = NULL;
- char timestr[GF_LOG_TIMESTR_SIZE] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
char *callstr = NULL;
@@ -820,12 +819,12 @@ _gf_log_callingfn(const char *domain, const char *file, const char *function,
if (-1 == ret)
goto out;
- gf_time_fmt(timestr, sizeof timestr, tv.tv_sec, gf_timefmt_FT);
+ gf_time_fmt_tv(timestr, sizeof timestr, &tv, gf_timefmt_FT);
- ret = gf_asprintf(
- &logline, "[%s.%" GF_PRI_SUSECONDS "] %c [%s:%d:%s] %s %d-%s: %s\n",
- timestr, tv.tv_usec, gf_level_strings[level], basename, line, function,
- callstr, ((this->graph) ? this->graph->id : 0), domain, msg);
+ ret = gf_asprintf(&logline, "[%s] %c [%s:%d:%s] %s %d-%s: %s\n", timestr,
+ gf_level_strings[level], basename, line, function,
+ callstr, ((this->graph) ? this->graph->id : 0), domain,
+ msg);
if (-1 == ret) {
goto out;
}
@@ -1088,7 +1087,7 @@ _gf_msg_nomem(const char *domain, const char *file, const char *function,
char msg[2048] = {
0,
};
- char timestr[GF_LOG_TIMESTR_SIZE] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
glusterfs_ctx_t *ctx = NULL;
@@ -1116,20 +1115,20 @@ _gf_msg_nomem(const char *domain, const char *file, const char *function,
ret = gettimeofday(&tv, NULL);
if (-1 == ret)
goto out;
- gf_time_fmt(timestr, sizeof timestr, tv.tv_sec, gf_timefmt_FT);
+ gf_time_fmt_tv(timestr, sizeof timestr, &tv, gf_timefmt_FT);
/* TODO: Currently we print in the enhanced format, with a message ID
* of 0. Need to enhance this to support format as configured */
wlen = snprintf(
msg, sizeof msg,
- "[%s.%" GF_PRI_SUSECONDS "] %c [MSGID: %" PRIu64
+ "[%s] %c [MSGID: %" PRIu64
"]"
" [%s:%d:%s] %s: no memory "
"available for size (%" GF_PRI_SIZET
") current memory usage in kilobytes %ld"
" [call stack follows]\n",
- timestr, tv.tv_usec, gf_level_strings[level], (uint64_t)0, basename,
- line, function, domain, size,
+ timestr, gf_level_strings[level], (uint64_t)0, basename, line, function,
+ domain, size,
(!getrusage(RUSAGE_SELF, &r_usage) ? r_usage.ru_maxrss : 0));
if (-1 == wlen) {
ret = -1;
@@ -1275,7 +1274,7 @@ gf_log_glusterlog(glusterfs_ctx_t *ctx, const char *domain, const char *file,
int errnum, uint64_t msgid, char **appmsgstr, char *callstr,
struct timeval tv, int graph_id, gf_log_format_t fmt)
{
- char timestr[GF_LOG_TIMESTR_SIZE] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
char *header = NULL;
@@ -1286,7 +1285,7 @@ gf_log_glusterlog(glusterfs_ctx_t *ctx, const char *domain, const char *file,
gf_log_rotate(ctx);
/* format the time stamp */
- gf_time_fmt(timestr, sizeof timestr, tv.tv_sec, gf_timefmt_FT);
+ gf_time_fmt_tv(timestr, sizeof timestr, &tv, gf_timefmt_FT);
/* generate footer */
if (errnum) {
@@ -1302,40 +1301,35 @@ gf_log_glusterlog(glusterfs_ctx_t *ctx, const char *domain, const char *file,
if (fmt == gf_logformat_traditional) {
if (!callstr) {
ret = gf_asprintf(&header,
- "[%s.%" GF_PRI_SUSECONDS
- "] %c [%s:%d:%s]"
+ "[%s] %c [%s:%d:%s]"
" %d-%s: %s",
- timestr, tv.tv_usec, gf_level_strings[level],
- file, line, function, graph_id, domain,
- *appmsgstr);
+ timestr, gf_level_strings[level], file, line,
+ function, graph_id, domain, *appmsgstr);
} else {
ret = gf_asprintf(&header,
- "[%s.%" GF_PRI_SUSECONDS
- "] %c [%s:%d:%s] %s"
+ "[%s] %c [%s:%d:%s] %s"
" %d-%s: %s",
- timestr, tv.tv_usec, gf_level_strings[level],
- file, line, function, callstr, graph_id, domain,
- *appmsgstr);
+ timestr, gf_level_strings[level], file, line,
+ function, callstr, graph_id, domain, *appmsgstr);
}
} else { /* gf_logformat_withmsgid */
/* CEE log format unsupported in logger_glusterlog, so just
* print enhanced log format */
if (!callstr) {
ret = gf_asprintf(&header,
- "[%s.%" GF_PRI_SUSECONDS "] %c [MSGID: %" PRIu64
+ "[%s] %c [MSGID: %" PRIu64
"]"
" [%s:%d:%s] %d-%s: %s",
- timestr, tv.tv_usec, gf_level_strings[level],
- msgid, file, line, function, graph_id, domain,
- *appmsgstr);
+ timestr, gf_level_strings[level], msgid, file,
+ line, function, graph_id, domain, *appmsgstr);
} else {
ret = gf_asprintf(&header,
- "[%s.%" GF_PRI_SUSECONDS "] %c [MSGID: %" PRIu64
+ "[%s] %c [MSGID: %" PRIu64
"]"
" [%s:%d:%s] %s %d-%s: %s",
- timestr, tv.tv_usec, gf_level_strings[level],
- msgid, file, line, function, callstr, graph_id,
- domain, *appmsgstr);
+ timestr, gf_level_strings[level], msgid, file,
+ line, function, callstr, graph_id, domain,
+ *appmsgstr);
}
}
if (-1 == ret) {
@@ -1386,39 +1380,36 @@ gf_syslog_log_repetitions(const char *domain, const char *file,
int graph_id)
{
int priority;
- char timestr_latest[GF_LOG_TIMESTR_SIZE] = {
+ char timestr_latest[GF_TIMESTR_SIZE] = {
0,
};
- char timestr_oldest[GF_LOG_TIMESTR_SIZE] = {
+ char timestr_oldest[GF_TIMESTR_SIZE] = {
0,
};
SET_LOG_PRIO(level, priority);
- gf_time_fmt(timestr_latest, sizeof timestr_latest, latest.tv_sec,
- gf_timefmt_FT);
- gf_time_fmt(timestr_oldest, sizeof timestr_oldest, oldest.tv_sec,
- gf_timefmt_FT);
+ gf_time_fmt_tv(timestr_latest, sizeof timestr_latest, &latest,
+ gf_timefmt_FT);
+ gf_time_fmt_tv(timestr_oldest, sizeof timestr_oldest, &oldest,
+ gf_timefmt_FT);
if (errnum) {
- syslog(
- priority,
- "The message \"[MSGID: %" PRIu64
- "] [%s:%d:%s] "
- "%d-%s: %s [%s] \" repeated %d times between %s.%" GF_PRI_SUSECONDS
- " and %s.%" GF_PRI_SUSECONDS,
- msgid, file, line, function, graph_id, domain, *appmsgstr,
- strerror(errnum), refcount, timestr_oldest, oldest.tv_usec,
- timestr_latest, latest.tv_usec);
+ syslog(priority,
+ "The message \"[MSGID: %" PRIu64
+ "] [%s:%d:%s] "
+ "%d-%s: %s [%s] \" repeated %d times between %s"
+ " and %s",
+ msgid, file, line, function, graph_id, domain, *appmsgstr,
+ strerror(errnum), refcount, timestr_oldest, timestr_latest);
} else {
syslog(priority,
"The message \"[MSGID: %" PRIu64
"] [%s:%d:%s] "
- "%d-%s: %s \" repeated %d times between %s.%" GF_PRI_SUSECONDS
- " and %s.%" GF_PRI_SUSECONDS,
+ "%d-%s: %s \" repeated %d times between %s"
+ " and %s",
msgid, file, line, function, graph_id, domain, *appmsgstr,
- refcount, timestr_oldest, oldest.tv_usec, timestr_latest,
- latest.tv_usec);
+ refcount, timestr_oldest, timestr_latest);
}
return 0;
}
@@ -1432,10 +1423,10 @@ gf_glusterlog_log_repetitions(glusterfs_ctx_t *ctx, const char *domain,
struct timeval latest, int graph_id)
{
int ret = 0;
- char timestr_latest[GF_LOG_TIMESTR_SIZE] = {
+ char timestr_latest[GF_TIMESTR_SIZE] = {
0,
};
- char timestr_oldest[GF_LOG_TIMESTR_SIZE] = {
+ char timestr_oldest[GF_TIMESTR_SIZE] = {
0,
};
char errstr[256] = {
@@ -1459,21 +1450,17 @@ gf_glusterlog_log_repetitions(glusterfs_ctx_t *ctx, const char *domain,
goto err;
}
- gf_time_fmt(timestr_latest, sizeof timestr_latest, latest.tv_sec,
- gf_timefmt_FT);
+ gf_time_fmt_tv(timestr_latest, sizeof timestr_latest, &latest,
+ gf_timefmt_FT);
- gf_time_fmt(timestr_oldest, sizeof timestr_oldest, oldest.tv_sec,
- gf_timefmt_FT);
+ gf_time_fmt_tv(timestr_oldest, sizeof timestr_oldest, &oldest,
+ gf_timefmt_FT);
if (errnum)
snprintf(errstr, sizeof(errstr) - 1, " [%s]", strerror(errnum));
- ret = gf_asprintf(&footer,
- "%s\" repeated %d times between"
- " [%s.%" GF_PRI_SUSECONDS "] and [%s.%" GF_PRI_SUSECONDS
- "]",
- errstr, refcount, timestr_oldest, oldest.tv_usec,
- timestr_latest, latest.tv_usec);
+ ret = gf_asprintf(&footer, "%s\" repeated %d times between [%s] and [%s]",
+ errstr, refcount, timestr_oldest, timestr_latest);
if (-1 == ret) {
ret = -1;
goto err;
@@ -2013,7 +2000,7 @@ _gf_log(const char *domain, const char *file, const char *function, int line,
const char *basename = NULL;
FILE *new_logfile = NULL;
va_list ap;
- char timestr[GF_LOG_TIMESTR_SIZE] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
struct timeval tv = {
@@ -2100,12 +2087,11 @@ log:
if (-1 == ret)
goto out;
- gf_time_fmt(timestr, sizeof timestr, tv.tv_sec, gf_timefmt_FT);
+ gf_time_fmt_tv(timestr, sizeof timestr, &tv, gf_timefmt_FT);
- ret = gf_asprintf(
- &logline, "[%s.%" GF_PRI_SUSECONDS "] %c [%s:%d:%s] %d-%s: %s\n",
- timestr, tv.tv_usec, gf_level_strings[level], basename, line, function,
- ((this->graph) ? this->graph->id : 0), domain, msg);
+ ret = gf_asprintf(&logline, "[%s] %c [%s:%d:%s] %d-%s: %s\n", timestr,
+ gf_level_strings[level], basename, line, function,
+ ((this->graph) ? this->graph->id : 0), domain, msg);
if (-1 == ret) {
goto err;
}
@@ -2225,7 +2211,7 @@ int
gf_cmd_log(const char *domain, const char *fmt, ...)
{
va_list ap;
- char timestr[64];
+ char timestr[GF_TIMESTR_SIZE];
struct timeval tv = {
0,
};
@@ -2258,10 +2244,9 @@ gf_cmd_log(const char *domain, const char *fmt, ...)
goto out;
}
- gf_time_fmt(timestr, sizeof timestr, tv.tv_sec, gf_timefmt_FT);
+ gf_time_fmt_tv(timestr, sizeof timestr, &tv, gf_timefmt_FT);
- ret = gf_asprintf(&logline, "[%s.%" GF_PRI_SUSECONDS "] %s : %s\n", timestr,
- tv.tv_usec, domain, msg);
+ ret = gf_asprintf(&logline, "[%s] %s : %s\n", timestr, domain, msg);
if (ret == -1) {
goto out;
}
diff --git a/libglusterfs/src/stack.c b/libglusterfs/src/stack.c
index 371f60c..1531f0d 100644
--- a/libglusterfs/src/stack.c
+++ b/libglusterfs/src/stack.c
@@ -92,7 +92,7 @@ gf_proc_dump_call_frame(call_frame_t *call_frame, const char *key_buf, ...)
};
int ret = -1;
- char timestr[256] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
int len;
@@ -162,7 +162,7 @@ gf_proc_dump_call_stack(call_stack_t *call_stack, const char *key_buf, ...)
va_list ap;
call_frame_t *trav;
int32_t i = 1, cnt = 0;
- char timestr[256] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
int len;
diff --git a/libglusterfs/src/statedump.c b/libglusterfs/src/statedump.c
index 2d44c92..9eed0b2 100644
--- a/libglusterfs/src/statedump.c
+++ b/libglusterfs/src/statedump.c
@@ -782,7 +782,7 @@ gf_proc_dump_info(int signum, glusterfs_ctx_t *ctx)
char brick_name[PATH_MAX] = {
0,
};
- char timestr[256] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
char sign_string[512] = {
@@ -861,10 +861,7 @@ gf_proc_dump_info(int signum, glusterfs_ctx_t *ctx)
// continue even though gettimeofday() has failed
ret = gettimeofday(&tv, NULL);
if (0 == ret) {
- gf_time_fmt(timestr, sizeof timestr, tv.tv_sec, gf_timefmt_FT);
- len = strlen(timestr);
- snprintf(timestr + len, sizeof timestr - len, ".%" GF_PRI_SUSECONDS,
- tv.tv_usec);
+ gf_time_fmt_tv(timestr, sizeof timestr, &tv, gf_timefmt_FT);
}
len = snprintf(sign_string, sizeof(sign_string), "DUMP-START-TIME: %s\n",
@@ -913,10 +910,7 @@ gf_proc_dump_info(int signum, glusterfs_ctx_t *ctx)
ret = gettimeofday(&tv, NULL);
if (0 == ret) {
- gf_time_fmt(timestr, sizeof timestr, tv.tv_sec, gf_timefmt_FT);
- len = strlen(timestr);
- snprintf(timestr + len, sizeof timestr - len, ".%" GF_PRI_SUSECONDS,
- tv.tv_usec);
+ gf_time_fmt_tv(timestr, sizeof timestr, &tv, gf_timefmt_FT);
}
len = snprintf(sign_string, sizeof(sign_string), "\nDUMP-END-TIME: %s",
diff --git a/rpc/rpc-lib/src/rpc-clnt.c b/rpc/rpc-lib/src/rpc-clnt.c
index 04b7750..2b0ec29 100644
--- a/rpc/rpc-lib/src/rpc-clnt.c
+++ b/rpc/rpc-lib/src/rpc-clnt.c
@@ -97,7 +97,7 @@ call_bail(void *data)
struct saved_frame *saved_frame = NULL;
struct saved_frame *trav = NULL;
struct saved_frame *tmp = NULL;
- char frame_sent[256] = {
+ char frame_sent[GF_TIMESTR_SIZE] = {
0,
};
struct timespec timeout = {
@@ -105,7 +105,6 @@ call_bail(void *data)
};
char peerid[UNIX_PATH_MAX] = {0};
gf_boolean_t need_unref = _gf_false;
- int len;
GF_VALIDATE_OR_GOTO("client", data, out);
@@ -165,11 +164,8 @@ call_bail(void *data)
list_for_each_entry_safe(trav, tmp, &list, list)
{
- gf_time_fmt(frame_sent, sizeof frame_sent, trav->saved_at.tv_sec,
- gf_timefmt_FT);
- len = strlen(frame_sent);
- snprintf(frame_sent + len, sizeof(frame_sent) - len,
- ".%" GF_PRI_SUSECONDS, trav->saved_at.tv_usec);
+ gf_time_fmt_tv(frame_sent, sizeof frame_sent, &trav->saved_at,
+ gf_timefmt_FT);
gf_log(conn->name, GF_LOG_ERROR,
"bailing out frame type(%s), op(%s(%d)), xid = 0x%x, "
@@ -317,20 +313,15 @@ saved_frames_unwind(struct saved_frames *saved_frames)
{
struct saved_frame *trav = NULL;
struct saved_frame *tmp = NULL;
- char timestr[1024] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
- int len;
list_splice_init(&saved_frames->lk_sf.list, &saved_frames->sf.list);
list_for_each_entry_safe(trav, tmp, &saved_frames->sf.list, list)
{
- gf_time_fmt(timestr, sizeof timestr, trav->saved_at.tv_sec,
- gf_timefmt_FT);
- len = strlen(timestr);
- snprintf(timestr + len, sizeof(timestr) - len, ".%" GF_PRI_SUSECONDS,
- trav->saved_at.tv_usec);
+ gf_time_fmt_tv(timestr, sizeof timestr, &trav->saved_at, gf_timefmt_FT);
if (!trav->rpcreq || !trav->rpcreq->prog)
continue;
diff --git a/tests/bugs/logging/bug-823081.t b/tests/bugs/logging/bug-823081.t
index 0ed8f4c..bd1965d 100755
--- a/tests/bugs/logging/bug-823081.t
+++ b/tests/bugs/logging/bug-823081.t
@@ -22,20 +22,20 @@ function set_tail ()
set_tail $V0;
TEST $CLI volume create $V0 $H0:$B0/${V0}{1,2};
-tail=`tail -n 1 $logdir/$cmd_log_history | cut -d " " -f 5-`
+tail=`tail -n 1 $logdir/$cmd_log_history | cut -d " " -f 6-`
TEST [[ \"$tail\" == \"$tail_success\" ]]
TEST ! $CLI volume create $V0 $H0:$B0/${V0}{1,2};
-tail=`tail -n 1 $logdir/$cmd_log_history | cut -d " " -f 5-`
+tail=`tail -n 1 $logdir/$cmd_log_history | cut -d " " -f 6-`
TEST [[ \"$tail\" == \"$tail_failure\" ]]
set_tail $V1;
TEST gluster volume create $V1 $H0:$B0/${V1}{1,2} force;
-tail=`tail -n 1 $logdir/$cmd_log_history | cut -d " " -f 5-`
+tail=`tail -n 1 $logdir/$cmd_log_history | cut -d " " -f 6-`
TEST [[ \"$tail\" == \"$tail_success_force\" ]]
TEST ! gluster volume create $V1 $H0:$B0/${V1}{1,2} force;
-tail=`tail -n 1 $logdir/$cmd_log_history | cut -d " " -f 5-`
+tail=`tail -n 1 $logdir/$cmd_log_history | cut -d " " -f 6-`
TEST [[ \"$tail\" == \"$tail_failure_force\" ]]
cleanup;
diff --git a/xlators/debug/io-stats/src/io-stats.c b/xlators/debug/io-stats/src/io-stats.c
index 4e1f6e5..345dbe7 100644
--- a/xlators/debug/io-stats/src/io-stats.c
+++ b/xlators/debug/io-stats/src/io-stats.c
@@ -678,10 +678,7 @@ ios_dump_throughput_stats(struct ios_stat_head *list_head, xlator_t *this,
FILE *logfp, ios_stats_thru_t type)
{
struct ios_stat_list *entry = NULL;
- struct timeval time = {
- 0,
- };
- char timestr[256] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
@@ -689,12 +686,9 @@ ios_dump_throughput_stats(struct ios_stat_head *list_head, xlator_t *this,
{
list_for_each_entry(entry, &list_head->iosstats->list, list)
{
- gf_time_fmt(timestr, sizeof timestr,
- entry->iosstat->thru_counters[type].time.tv_sec,
- gf_timefmt_FT);
- snprintf(timestr + strlen(timestr),
- sizeof timestr - strlen(timestr), ".%" GF_PRI_SUSECONDS,
- time.tv_usec);
+ gf_time_fmt_tv(timestr, sizeof timestr,
+ &entry->iosstat->thru_counters[type].time,
+ gf_timefmt_FT);
ios_log(this, logfp, "%s \t %-10.2f \t %s", timestr, entry->value,
entry->iosstat->filename);
@@ -1216,7 +1210,7 @@ io_stats_dump_global_to_logfp(xlator_t *this, struct ios_global_stats *stats,
int index = 0;
struct ios_stat_head *list_head = NULL;
struct ios_conf *conf = NULL;
- char timestr[256] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
char str_header[128] = {0};
@@ -1325,11 +1319,8 @@ io_stats_dump_global_to_logfp(xlator_t *this, struct ios_global_stats *stats,
if (interval == -1) {
LOCK(&conf->lock);
{
- gf_time_fmt(timestr, sizeof timestr,
- conf->cumulative.max_openfd_time.tv_sec, gf_timefmt_FT);
- snprintf(timestr + strlen(timestr),
- sizeof timestr - strlen(timestr), ".%" GF_PRI_SUSECONDS,
- conf->cumulative.max_openfd_time.tv_usec);
+ gf_time_fmt_tv(timestr, sizeof timestr,
+ &conf->cumulative.max_openfd_time, gf_timefmt_FT);
ios_log(this, logfp,
"Current open fd's: %" PRId64 " Max open fd's: %" PRId64
" time %s",
@@ -1808,7 +1799,7 @@ io_stats_dump_stats_to_dict(xlator_t *this, dict_t *resp,
struct ios_stat_list *entry = NULL;
int ret = -1;
ios_stats_thru_t index = IOS_STATS_THRU_MAX;
- char timestr[256] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
char *dict_timestr = NULL;
@@ -1827,14 +1818,9 @@ io_stats_dump_stats_to_dict(xlator_t *this, dict_t *resp,
ret = dict_set_uint64(resp, "max-open",
conf->cumulative.max_nr_opens);
- gf_time_fmt(timestr, sizeof timestr,
- conf->cumulative.max_openfd_time.tv_sec,
- gf_timefmt_FT);
- if (conf->cumulative.max_openfd_time.tv_sec)
- snprintf(timestr + strlen(timestr),
- sizeof timestr - strlen(timestr),
- ".%" GF_PRI_SUSECONDS,
- conf->cumulative.max_openfd_time.tv_usec);
+ gf_time_fmt_tv(timestr, sizeof timestr,
+ &conf->cumulative.max_openfd_time,
+ gf_timefmt_FT);
dict_timestr = gf_strdup(timestr);
if (!dict_timestr)
diff --git a/xlators/debug/trace/src/trace.c b/xlators/debug/trace/src/trace.c
index 3db2e26..6ed0ca0 100644
--- a/xlators/debug/trace/src/trace.c
+++ b/xlators/debug/trace/src/trace.c
@@ -22,13 +22,13 @@
static void
trace_stat_to_str(struct iatt *buf, char *str, size_t len)
{
- char atime_buf[200] = {
+ char atime_buf[GF_TIMESTR_SIZE] = {
0,
};
- char mtime_buf[200] = {
+ char mtime_buf[GF_TIMESTR_SIZE] = {
0,
};
- char ctime_buf[200] = {
+ char ctime_buf[GF_TIMESTR_SIZE] = {
0,
};
@@ -64,7 +64,7 @@ trace_stat_to_str(struct iatt *buf, char *str, size_t len)
int
dump_history_trace(circular_buffer_t *cb, void *data)
{
- char timestr[256] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
@@ -72,9 +72,7 @@ dump_history_trace(circular_buffer_t *cb, void *data)
gettimeofday () fails, it's safe to check tm and then dump the time
at which the entry was added to the buffer */
- 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_time_fmt_tv(timestr, sizeof timestr, &cb->tv, gf_timefmt_Ymd_T);
gf_proc_dump_write("TIME", "%s", timestr);
gf_proc_dump_write("FOP", "%s\n", (char *)cb->data);
@@ -2209,10 +2207,10 @@ int
trace_setattr(call_frame_t *frame, xlator_t *this, loc_t *loc,
struct iatt *stbuf, int32_t valid, dict_t *xdata)
{
- char actime_str[256] = {
+ char actime_str[GF_TIMESTR_SIZE] = {
0,
};
- char modtime_str[256] = {
+ char modtime_str[GF_TIMESTR_SIZE] = {
0,
};
trace_conf_t *conf = NULL;
@@ -2278,10 +2276,10 @@ int
trace_fsetattr(call_frame_t *frame, xlator_t *this, fd_t *fd,
struct iatt *stbuf, int32_t valid, dict_t *xdata)
{
- char actime_str[256] = {
+ char actime_str[GF_TIMESTR_SIZE] = {
0,
};
- char modtime_str[256] = {
+ char modtime_str[GF_TIMESTR_SIZE] = {
0,
};
trace_conf_t *conf = NULL;
diff --git a/xlators/features/bit-rot/src/bitd/bit-rot-scrub.c b/xlators/features/bit-rot/src/bitd/bit-rot-scrub.c
index 10c0478..c460765 100644
--- a/xlators/features/bit-rot/src/bitd/bit-rot-scrub.c
+++ b/xlators/features/bit-rot/src/bitd/bit-rot-scrub.c
@@ -601,7 +601,7 @@ br_fsscan_deactivate(xlator_t *this)
static void
br_scrubber_log_time(xlator_t *this, const char *sfx)
{
- char timestr[1024] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
struct timeval tv = {
@@ -628,7 +628,7 @@ br_scrubber_log_time(xlator_t *this, const char *sfx)
static void
br_fsscanner_log_time(xlator_t *this, br_child_t *child, const char *sfx)
{
- char timestr[1024] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
struct timeval tv = {
@@ -922,7 +922,7 @@ br_fsscan_schedule(xlator_t *this)
struct timeval tv = {
0,
};
- char timestr[1024] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
struct br_scrubber *fsscrub = NULL;
@@ -975,7 +975,7 @@ int32_t
br_fsscan_activate(xlator_t *this)
{
uint32_t timo = 0;
- char timestr[1024] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
struct timeval now = {
@@ -1020,7 +1020,7 @@ br_fsscan_reschedule(xlator_t *this)
{
int32_t ret = 0;
uint32_t timo = 0;
- char timestr[1024] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
struct timeval now = {
@@ -1073,7 +1073,7 @@ br_fsscan_ondemand(xlator_t *this)
{
int32_t ret = 0;
uint32_t timo = 0;
- char timestr[1024] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
struct timeval now = {
diff --git a/xlators/features/locks/src/posix.c b/xlators/features/locks/src/posix.c
index 8b57627..6a71284 100644
--- a/xlators/features/locks/src/posix.c
+++ b/xlators/features/locks/src/posix.c
@@ -3502,10 +3502,10 @@ pl_dump_lock(char *str, int size, struct gf_flock *flock, gf_lkowner_t *owner,
time_t *blkd_time, gf_boolean_t active)
{
char *type_str = NULL;
- char granted[256] = {
+ char granted[GF_TIMESTR_SIZE] = {
0,
};
- char blocked[256] = {
+ char blocked[GF_TIMESTR_SIZE] = {
0,
};
@@ -3556,10 +3556,10 @@ __dump_entrylks(pl_inode_t *pl_inode)
{
pl_dom_list_t *dom = NULL;
pl_entry_lock_t *lock = NULL;
- char blocked[256] = {
+ char blocked[GF_TIMESTR_SIZE] = {
0,
};
- char granted[256] = {
+ char granted[GF_TIMESTR_SIZE] = {
0,
};
int count = 0;
diff --git a/xlators/features/trash/src/trash.c b/xlators/features/trash/src/trash.c
index f44b11c..a28aa1e 100644
--- a/xlators/features/trash/src/trash.c
+++ b/xlators/features/trash/src/trash.c
@@ -212,7 +212,7 @@ void
append_time_stamp(char *name, size_t name_size)
{
int i;
- char timestr[64] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
diff --git a/xlators/mgmt/glusterd/src/glusterd-handler.c b/xlators/mgmt/glusterd/src/glusterd-handler.c
index 6e6593e..96a2f01 100644
--- a/xlators/mgmt/glusterd/src/glusterd-handler.c
+++ b/xlators/mgmt/glusterd/src/glusterd-handler.c
@@ -5146,7 +5146,7 @@ glusterd_print_snapinfo_by_vol(FILE *fp, glusterd_volinfo_t *volinfo,
glusterd_volinfo_t *tmp_vol = NULL;
glusterd_snap_t *snapinfo = NULL;
int snapcount = 0;
- char timestr[64] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
char snap_status_str[STATUS_STRLEN] = {
diff --git a/xlators/mgmt/glusterd/src/glusterd-snapshot.c b/xlators/mgmt/glusterd/src/glusterd-snapshot.c
index 6294951..c7f147b 100644
--- a/xlators/mgmt/glusterd/src/glusterd-snapshot.c
+++ b/xlators/mgmt/glusterd/src/glusterd-snapshot.c
@@ -3221,7 +3221,7 @@ glusterd_snapshot_get_snap_detail(dict_t *dict, glusterd_snap_t *snap,
int volcount = 0;
char key[32] = ""; /* keyprefix is quite small, up to 16 bytes */
int keylen;
- char timestr[64] = "";
+ char timestr[GF_TIMESTR_SIZE] = "";
char *value = NULL;
glusterd_volinfo_t *snap_vol = NULL;
glusterd_volinfo_t *tmp_vol = NULL;
diff --git a/xlators/mgmt/glusterd/src/glusterd-utils.c b/xlators/mgmt/glusterd/src/glusterd-utils.c
index a0b436d..98e4506 100644
--- a/xlators/mgmt/glusterd/src/glusterd-utils.c
+++ b/xlators/mgmt/glusterd/src/glusterd-utils.c
@@ -8075,7 +8075,7 @@ glusterd_sm_tr_log_transition_add_to_dict(dict_t *dict,
int ret = -1;
char key[64] = "";
int keylen;
- char timestr[64] = "";
+ char timestr[GF_TIMESTR_SIZE] = "";
char *str = NULL;
GF_ASSERT(dict);
diff --git a/xlators/mount/fuse/src/fuse-bridge.c b/xlators/mount/fuse/src/fuse-bridge.c
index 041caf5..f198b8f 100644
--- a/xlators/mount/fuse/src/fuse-bridge.c
+++ b/xlators/mount/fuse/src/fuse-bridge.c
@@ -6332,14 +6332,12 @@ out:
int
dump_history_fuse(circular_buffer_t *cb, void *data)
{
- char timestr[256] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
- gf_time_fmt(timestr, sizeof timestr, cb->tv.tv_sec, gf_timefmt_F_HMS);
+ gf_time_fmt_tv(timestr, sizeof timestr, &cb->tv, gf_timefmt_F_HMS);
- 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", (char *)cb->data);
diff --git a/xlators/performance/io-cache/src/io-cache.c b/xlators/performance/io-cache/src/io-cache.c
index c007e0a..2fefaef 100644
--- a/xlators/performance/io-cache/src/io-cache.c
+++ b/xlators/performance/io-cache/src/io-cache.c
@@ -1945,7 +1945,7 @@ __ioc_cache_dump(ioc_inode_t *ioc_inode, char *prefix)
char key[GF_DUMP_MAX_BUF_LEN] = {
0,
};
- char timestr[256] = {
+ char timestr[GF_TIMESTR_SIZE] = {
0,
};
@@ -1956,10 +1956,8 @@ __ioc_cache_dump(ioc_inode_t *ioc_inode, char *prefix)
table = ioc_inode->table;
if (ioc_inode->cache.tv.tv_sec) {
- gf_time_fmt(timestr, sizeof timestr, ioc_inode->cache.tv.tv_sec,
- gf_timefmt_FT);
- snprintf(timestr + strlen(timestr), sizeof timestr - strlen(timestr),
- ".%" GF_PRI_SUSECONDS, ioc_inode->cache.tv.tv_usec);
+ gf_time_fmt_tv(timestr, sizeof timestr, &ioc_inode->cache.tv,
+ gf_timefmt_FT);
gf_proc_dump_write("last-cache-validation-time", "%s", timestr);
}
diff --git a/xlators/performance/quick-read/src/quick-read.c b/xlators/performance/quick-read/src/quick-read.c
index 4f16d14..640c9ac 100644
--- a/xlators/performance/quick-read/src/quick-read.c
+++ b/xlators/performance/quick-read/src/quick-read.c
@@ -1034,7 +1034,7 @@ qr_inodectx_dump(xlator_t *this, inode_t *inode)
char key_prefix[GF_DUMP_MAX_BUF_LEN] = {
0,
};
- char buf[256] = {
+ char buf[GF_TIMESTR_SIZE] = {
0,
};
@@ -1050,10 +1050,7 @@ qr_inodectx_dump(xlator_t *this, inode_t *inode)
qr_inode->data ? "yes" : "no");
if (qr_inode->last_refresh.tv_sec) {
- gf_time_fmt(buf, sizeof buf, qr_inode->last_refresh.tv_sec,
- gf_timefmt_FT);
- snprintf(buf + strlen(buf), sizeof buf - strlen(buf),
- ".%" GF_PRI_SUSECONDS, qr_inode->last_refresh.tv_usec);
+ gf_time_fmt_tv(buf, sizeof buf, &qr_inode->last_refresh, gf_timefmt_FT);
gf_proc_dump_write("last-cache-validation-time", "%s", buf);
}
diff --git a/xlators/storage/posix/src/posix-helpers.c b/xlators/storage/posix/src/posix-helpers.c
index 24466c4..73443a6 100644
--- a/xlators/storage/posix/src/posix-helpers.c
+++ b/xlators/storage/posix/src/posix-helpers.c
@@ -1924,7 +1924,7 @@ posix_fs_health_check(xlator_t *this, char *file_path)
{
struct posix_private *priv = NULL;
int ret = -1;
- char timestamp[256] = {
+ char timestamp[GF_TIMESTR_SIZE] = {
0,
};
int fd = -1;