Always print raw values of time data fields

Refactor sprinttime: implement sprinttime_nsec and sprinttime_usec
that handle nanoseconds and microseconds, respectively.
Always print raw values of time data fields, format string
representations of time as comments.

* defs.h (sprinttime): Change argument type from time_t to long long.
(sprinttime_nsec, sprinttime_usec): New prototypes.
* util.c (sprinttime_ex, sprinttime_nsec, sprinttime_usec): New
functions.
(sprinttime): Turn into a thin wrapper around sprinttime_ex.
* stat.h (struct strace_stat): Add has_nsec field.
* fetch_struct_stat.c (HAVE_NSEC): New macro.
(fetch_struct_stat): Initialize has_nsec field with HAVE_NSEC.
* fetch_struct_stat64.c (HAVE_NSEC): New macro.
(fetch_struct_stat64): Initialize has_nsec field with HAVE_NSEC.
* print_struct_stat.c (print_struct_stat) <PRINT_ST_TIME>:
Print raw values of time fields, use sprinttime_nsec to format a string
representation of time, use tprints_comment to print it as a comment.
* statx.c (SYS_FUNC(statx)) <PRINT_FIELD_TIME>: Likewise.
* utime.c (SYS_FUNC(utime)): Print raw values of struct utimbuf.actime
and struct utimbuf.modtime fields, use sprinttime to format a string
representation of time, use tprints_comment to print it as a comment.
* tests/tests.h (print_time_t_nsec): Add int argument.
* tests/print_time.c (print_time_t_ex): New function.
(print_time_t_nsec): Add int argument, turn into a thin wrapper around
print_time_t_ex.
* tests/utime.c (main): Update expected output.
* tests/xstatx.c [!IS_STATX] (HAVE_NSEC): New macro.
[!IS_STATX] (PRINT_ST_TIME), [IS_STATX] (PRINT_FIELD_TIME): Update
expected output.
* NEWS: Mention this timestamps representation improvement.

Co-authored-by: Dmitry V. Levin <ldv@altlinux.org>

NEWS

@@ -8,6 +8,7 @@ Noteworthy changes in release ?.?? (????-??-??)
 
 * Improvements
   * Optimized syscall filtering.
+  * Improved representation of timestamps.
   * Enhanced decoding of sched_setattr syscall.
   * Added -e trace=%stat option for tracing variants of stat syscall.
   * Added -e trace=%lstat option for tracing variants of lstat syscall.

defs.h

@@ -547,7 +547,9 @@ extern int printargs_d(struct tcb *);
 extern void addflags(const struct xlat *, uint64_t);
 extern int printflags64(const struct xlat *, uint64_t, const char *);
 extern const char *sprintflags(const char *, const struct xlat *, uint64_t);
-extern const char *sprinttime(time_t);
+extern const char *sprinttime(long long sec);
+extern const char *sprinttime_nsec(long long sec, unsigned long long nsec);
+extern const char *sprinttime_usec(long long sec, unsigned long long usec);
 extern void print_symbolic_mode_t(unsigned int);
 extern void print_numeric_umode_t(unsigned short);
 extern void print_numeric_long_umask(unsigned long);

fetch_struct_stat.c

@@ -65,8 +65,10 @@ typedef struct stat struct_stat;
 
 #ifdef HAVE_STRUCT_STAT_ST_MTIME_NSEC
 # define TIME_NSEC(arg) zero_extend_signed_to_ull(arg)
+# define HAVE_NSEC true
 #else
 # define TIME_NSEC(arg) 0
+# define HAVE_NSEC false
 #endif
 
 MPERS_PRINTER_DECL(bool, fetch_struct_stat,
@@ -94,6 +96,7 @@ MPERS_PRINTER_DECL(bool, fetch_struct_stat,
 	dst->atime_nsec = TIME_NSEC(buf.st_atime_nsec);
 	dst->ctime_nsec = TIME_NSEC(buf.st_ctime_nsec);
 	dst->mtime_nsec = TIME_NSEC(buf.st_mtime_nsec);
+	dst->has_nsec = HAVE_NSEC;
 	return true;
 #else /* !HAVE_STRUCT_STAT */
 	printaddr(addr);

fetch_struct_stat64.c

@@ -63,8 +63,10 @@ typedef struct stat64 struct_stat64;
 
 #ifdef HAVE_STRUCT_STAT64_ST_MTIME_NSEC
 # define TIME_NSEC(arg) zero_extend_signed_to_ull(arg)
+# define HAVE_NSEC true
 #else
 # define TIME_NSEC(arg) 0
+# define HAVE_NSEC false
 #endif
 
 MPERS_PRINTER_DECL(bool, fetch_struct_stat64,
@@ -92,6 +94,7 @@ MPERS_PRINTER_DECL(bool, fetch_struct_stat64,
 	dst->atime_nsec = TIME_NSEC(buf.st_atime_nsec);
 	dst->ctime_nsec = TIME_NSEC(buf.st_ctime_nsec);
 	dst->mtime_nsec = TIME_NSEC(buf.st_mtime_nsec);
+	dst->has_nsec = HAVE_NSEC;
 	return true;
 #else /* !HAVE_STRUCT_STAT64 */
 	printaddr(addr);

print_struct_stat.c

@@ -65,11 +65,16 @@ print_struct_stat(struct tcb *tcp, const struct strace_stat *const st)
 	}
 
 	if (!abbrev(tcp)) {
-#define PRINT_ST_TIME(field)				\
-	tprints(", st_" #field "=");			\
-	tprints(sprinttime(st->field));			\
-	if (st->field ## _nsec)				\
-		tprintf(".%09llu", st->field ## _nsec)
+#define PRINT_ST_TIME(field)						\
+	do {								\
+		tprintf(", st_" #field "=%lld", (long long) st->field);	\
+		tprints_comment(sprinttime_nsec(st->field,		\
+			zero_extend_signed_to_ull(st->field ## _nsec)));\
+		if (st->has_nsec)					\
+			tprintf(", st_" #field "_nsec=%llu",		\
+				zero_extend_signed_to_ull(		\
+					st->field ## _nsec));		\
+	} while (0)
 
 		PRINT_ST_TIME(atime);
 		PRINT_ST_TIME(mtime);

stat.h

@@ -45,6 +45,7 @@ struct strace_stat {
 	unsigned long long	atime_nsec;
 	unsigned long long	ctime_nsec;
 	unsigned long long	mtime_nsec;
+	bool			has_nsec;
 };
 
 #endif /* !STRACE_STAT_H */

statx.c

@@ -59,10 +59,11 @@ SYS_FUNC(statx)
 
 #define PRINT_FIELD_TIME(field)						\
 	do {								\
-		tprints(", " #field "=");				\
-		tprints(sprinttime(stx.field.sec));			\
-		if (stx.field.nsec)					\
-			tprintf(".%09" PRId32, stx.field.nsec);		\
+		tprintf(", " #field "={tv_sec=%" PRId64			\
+			", tv_nsec=%" PRIu32 "}",			\
+			stx.field.sec, stx.field.nsec);			\
+		tprints_comment(sprinttime_nsec(stx.field.sec,		\
+			zero_extend_signed_to_ull(stx.field.nsec)));	\
 	} while (0)
 
 		struct_statx stx;

tests/print_time.c

@@ -31,24 +31,39 @@
 #include <stdio.h>
 #include <time.h>
 
-void
-print_time_t_nsec(const time_t t, const unsigned long long nsec)
+static void
+print_time_t_ex(const time_t t, const unsigned long long part_sec,
+		const unsigned int max_part_sec, const int width,
+		const int comment)
 {
-	if (t) {
-		const struct tm *const p = localtime(&t);
-		char buf[256];
 
-		if (!p) {
-			perror_msg_and_fail("localtime");
-		}
+	if ((!t && !part_sec) || part_sec > max_part_sec)
+		return;
 
-		strftime(buf, sizeof(buf), "%FT%T%z", p);
+	const struct tm *const p = localtime(&t);
+	char buf[256];
+	if (!p || !strftime(buf, sizeof(buf), "%FT%T", p))
+		return;
+
+	if (comment)
+		fputs(" /* ", stdout);
+
+	fputs(buf, stdout);
+
+	if (part_sec)
+		printf(".%0*llu", width, part_sec);
+
+	if (strftime(buf, sizeof(buf), "%z", p))
 		fputs(buf, stdout);
-	} else {
-		putchar('0');
-	}
 
-	if (nsec) {
-		printf(".%09llu", nsec);
-	}
+	if (comment)
+		fputs(" */", stdout);
+
+	return;
+}
+
+void
+print_time_t_nsec(const time_t t, const unsigned long long nsec, int comment)
+{
+	print_time_t_ex(t, nsec, 999999999, 9, comment);
 }

tests/tests.h

@@ -123,7 +123,7 @@ void print_quoted_string(const char *);
 void print_quoted_memory(const char *, size_t);
 
 /* Print time_t and nanoseconds in symbolic format. */
-void print_time_t_nsec(time_t, unsigned long long);
+void print_time_t_nsec(time_t, unsigned long long, int);
 
 /* Read an int from the file. */
 int read_int_from_file(const char *, int *);

tests/utime.c

@@ -68,10 +68,10 @@ main(void)
 
 	rc = k_utime("utime\nfilename", tail_u);
 	const char *errstr = sprintrc(rc);
-	printf("utime(\"utime\\nfilename\", {actime=");
-	print_time_t_nsec(t, 0);
-	printf(", modtime=");
-	print_time_t_nsec(t, 0);
+	printf("utime(\"utime\\nfilename\", {actime=%lld", (long long) t);
+	print_time_t_nsec(t, 0, 1);
+	printf(", modtime=%lld", (long long) t);
+	print_time_t_nsec(t, 0, 1);
 	printf("}) = %s\n", errstr);
 
 	puts("+++ exited with 0 +++");

tests/xstatx.c

@@ -171,14 +171,20 @@ print_stat(const STRUCT_STAT *st)
 
 #  if defined(HAVE_STRUCT_STAT_ST_MTIME_NSEC) && !OLD_STAT
 #   define TIME_NSEC(val)	zero_extend_signed_to_ull(val)
+#   define HAVE_NSEC		1
 #  else
-#   define TIME_NSEC(val)	0
+#   define TIME_NSEC(val)	0ULL
+#   define HAVE_NSEC		0
 #  endif
 
-#  define PRINT_ST_TIME(field)						\
-	printf(", st_" #field "=");					\
+#define PRINT_ST_TIME(field)						\
+	printf(", st_" #field "=%lld",					\
+	       sign_extend_unsigned_to_ll(st->st_ ## field));		\
 	print_time_t_nsec(sign_extend_unsigned_to_ll(st->st_ ## field),	\
-			  TIME_NSEC(st->st_ ## field ## _nsec))
+			  TIME_NSEC(st->st_ ## field ## _nsec), 1);	\
+	if (HAVE_NSEC)							\
+		printf(", st_" #field "_nsec=%llu",			\
+		       TIME_NSEC(st->st_ ## field ## _nsec))
 
 	PRINT_ST_TIME(atime);
 	PRINT_ST_TIME(mtime);
@@ -200,10 +206,12 @@ print_stat(const STRUCT_STAT *st)
 	else \
 		printf(", %s=%llu", #field, (unsigned long long) st->field)
 
-#  define PRINT_FIELD_TIME(field)				\
-	printf(", %s=", #field);				\
-	print_time_t_nsec(st->field.tv_sec,			\
-			  zero_extend_signed_to_ull(st->field.tv_nsec))
+#  define PRINT_FIELD_TIME(field)					\
+	printf(", %s={tv_sec=%lld, tv_nsec=%u}",			\
+	       #field, (long long) st->field.tv_sec,			\
+	       (unsigned) st->field.tv_nsec);				\
+	print_time_t_nsec(st->field.tv_sec,				\
+			  zero_extend_signed_to_ull(st->field.tv_nsec), 1);
 
 	printf("{stx_mask=");
 	printflags(statx_masks, st->stx_mask, "STATX_???");

util.c

@@ -541,21 +541,62 @@ printnum_addr_klong_int(struct tcb *tcp, const kernel_ulong_t addr)
 }
 #endif /* !current_klongsize */
 
-const char *
-sprinttime(time_t t)
+/**
+ * Prints time to a (static internal) buffer and returns pointer to it.
+ *
+ * @param sec		Seconds since epoch.
+ * @param part_sec	Amount of second parts since the start of a second.
+ * @param max_part_sec	Maximum value of a valid part_sec.
+ * @param width		1 + floor(log10(max_part_sec)).
+ */
+static const char *
+sprinttime_ex(const long long sec, const unsigned long long part_sec,
+	      const unsigned int max_part_sec, const int width)
 {
-	struct tm *tmp;
-	static char buf[sizeof(int) * 3 * 6 + sizeof("+0000")];
+	static char buf[sizeof(int) * 3 * 6 + sizeof(part_sec) * 3
+			+ sizeof("+0000")];
 
-	if (t == 0)
-		return "0";
-	tmp = localtime(&t);
-	if (tmp)
-		strftime(buf, sizeof(buf), "%FT%T%z", tmp);
-	else
-		snprintf(buf, sizeof(buf), "%lu", (unsigned long) t);
+	if ((sec == 0 && part_sec == 0) || part_sec > max_part_sec)
+		return NULL;
 
-	return buf;
+	time_t t = (time_t) sec;
+	struct tm *tmp = (sec == t) ? localtime(&t) : NULL;
+	if (!tmp)
+		return NULL;
+
+	size_t pos = strftime(buf, sizeof(buf), "%FT%T", tmp);
+	if (!pos)
+		return NULL;
+
+	if (part_sec > 0) {
+		int ret = snprintf(buf + pos, sizeof(buf) - pos, ".%0*llu",
+				   width, part_sec);
+
+		if (ret < 0 || (size_t) ret >= sizeof(buf) - pos)
+			return NULL;
+
+		pos += ret;
+	}
+
+	return strftime(buf + pos, sizeof(buf) - pos, "%z", tmp) ? buf : NULL;
+}
+
+const char *
+sprinttime(long long sec)
+{
+	return sprinttime_ex(sec, 0, 0, 0);
+}
+
+const char *
+sprinttime_usec(long long sec, unsigned long long usec)
+{
+	return sprinttime_ex(sec, usec, 999999, 6);
+}
+
+const char *
+sprinttime_nsec(long long sec, unsigned long long nsec)
+{
+	return sprinttime_ex(sec, nsec, 999999999, 9);
 }
 
 enum sock_proto

utime.c

@@ -15,8 +15,11 @@ SYS_FUNC(utime)
 	printpath(tcp, tcp->u_arg[0]);
 	tprints(", ");
 	if (!umove_or_printaddr(tcp, tcp->u_arg[1], &u)) {
-		tprintf("{actime=%s,", sprinttime(u.actime));
-		tprintf(" modtime=%s}", sprinttime(u.modtime));
+		tprintf("{actime=%lld", (long long) u.actime);
+		tprints_comment(sprinttime(u.actime));
+		tprintf(", modtime=%lld", (long long) u.modtime);
+		tprints_comment(sprinttime(u.modtime));
+		tprints("}");
 	}
 
 	return RVAL_DECODED;