feat: Add a --timestamps flag to prepend a timestamp per output line. (#1028)

This flag takes an optional argument, which is a format specification to strftime(3)...this allows for custom timestamp formats.  Based on a suggested implementation by @davidBar-On.  Towards #909.

6 files changed, 114 insertions, 2 deletions

diff --git a/src/iperf.h b/src/iperf.h
index 3e0edb6..6201a07 100644
--- a/src/iperf.h
+++ b/src/iperf.h
@@ -1,5 +1,5 @@
 /*
- * iperf, Copyright (c) 2014-2019, The Regents of the University of
+ * iperf, Copyright (c) 2014-2020, The Regents of the University of
  * California, through Lawrence Berkeley National Laboratory (subject
  * to receipt of any required approvals from the U.S. Dept. of
  * Energy).  All rights reserved.
@@ -301,6 +301,8 @@ struct iperf_test
     int       forceflush; /* --forceflush - flushing output at every interval */
     int	      multisend;
     int	      repeating_payload;                /* --repeating-payload */
+    int       timestamps;			/* --timestamps */
+    char     *timestamp_format;
 
     char     *json_output_string; /* rendered JSON output if json_output is set */
     /* Select related parameters */
@@ -393,6 +395,8 @@ struct iperf_test
 #define MAX_MSS (9 * 1024)
 #define MAX_STREAMS 128
 
+#define TIMESTAMP_FORMAT "%c "
+
 extern int gerror; /* error value from getaddrinfo(3), for use in internal error handling */
 
 #endif /* !__IPERF_H */
diff --git a/src/iperf3.1 b/src/iperf3.1
index aad6997..97d66ed 100644
--- a/src/iperf3.1
+++ b/src/iperf3.1
@@ -153,6 +153,14 @@ send output to a log file.
 force flushing output at every interval.
 Used to avoid buffering when sending output to pipe.
 .TP
+.BR --timestamps " [\fIformat\fR]"
+prepend a timestamp at the start of each output line.
+By default, timestamps have the format emitted by
+.BR ctime ( 1 ).
+Optionally, a format specification can be passed to customize the
+timestamps, see
+.BR strftime ( 3 ).
+.TP
 .BR -d ", " --debug " "
 emit debugging output.
 Primarily (perhaps exclusively) of use to developers.
diff --git a/src/iperf_api.c b/src/iperf_api.c
index 16e0b95..ad2453b 100644
--- a/src/iperf_api.c
+++ b/src/iperf_api.c
@@ -261,6 +261,18 @@ iperf_get_test_num_streams(struct iperf_test *ipt)
 }
 
 int
+iperf_get_test_timestamps(struct iperf_test *ipt)
+{
+    return ipt->timestamps;
+}
+
+const char *
+iperf_get_test_timestamp_format(struct iperf_test *ipt)
+{
+    return ipt->timestamp_format;
+}
+
+int
 iperf_get_test_repeating_payload(struct iperf_test *ipt)
 {
     return ipt->repeating_payload;
@@ -503,6 +515,18 @@ iperf_set_test_repeating_payload(struct iperf_test *ipt, int repeating_payload)
     ipt->repeating_payload = repeating_payload;
 }
 
+void
+iperf_set_test_timestamps(struct iperf_test *ipt, int timestamps)
+{
+    ipt->timestamps = timestamps;
+}
+
+void
+iperf_set_test_timestamp_format(struct iperf_test *ipt, const char *tf)
+{
+    ipt->timestamp_format = strdup(tf);
+}
+
 static void
 check_sender_has_retransmits(struct iperf_test *ipt)
 {
@@ -878,6 +902,7 @@ iperf_parse_arguments(struct iperf_test *test, int argc, char **argv)
         {"omit", required_argument, NULL, 'O'},
         {"file", required_argument, NULL, 'F'},
         {"repeating-payload", no_argument, NULL, OPT_REPEATING_PAYLOAD},
+        {"timestamps", optional_argument, NULL, OPT_TIMESTAMPS},
 #if defined(HAVE_CPU_AFFINITY)
         {"affinity", required_argument, NULL, 'A'},
 #endif /* HAVE_CPU_AFFINITY */
@@ -1202,6 +1227,15 @@ iperf_parse_arguments(struct iperf_test *test, int argc, char **argv)
                 test->repeating_payload = 1;
                 client_flag = 1;
                 break;
+            case OPT_TIMESTAMPS:
+                iperf_set_test_timestamps(test, 1);
+		if (optarg) {
+		    iperf_set_test_timestamp_format(test, optarg);
+		}
+		else {
+		    iperf_set_test_timestamp_format(test, TIMESTAMP_FORMAT);
+		}
+                break;
             case 'O':
                 test->omit = atoi(optarg);
                 if (test->omit < 0 || test->omit > 60) {
@@ -2610,6 +2644,8 @@ iperf_free_test(struct iperf_test *test)
 	free(test->congestion_used);
     if (test->remote_congestion_used)
 	free(test->remote_congestion_used);
+    if (test->timestamp_format)
+	free(test->timestamp_format);
     if (test->omit_timer != NULL)
 	tmr_cancel(test->omit_timer);
     if (test->timer != NULL)
@@ -4269,11 +4305,24 @@ iperf_clearaffinity(struct iperf_test *test)
 #endif /* neither HAVE_SCHED_SETAFFINITY nor HAVE_CPUSET_SETAFFINITY nor HAVE_SETPROCESSAFFINITYMASK */
 }
 
+char iperf_timestr[100];
+
 int
 iperf_printf(struct iperf_test *test, const char* format, ...)
 {
     va_list argp;
     int r = -1;
+    time_t now;
+    struct tm *ltm = NULL;
+    char *ct = NULL;
+
+    /* Timestamp if requested */
+    if (iperf_get_test_timestamps(test)) {
+	time(&now);
+	ltm = localtime(&now);
+	strftime(iperf_timestr, sizeof(iperf_timestr), iperf_get_test_timestamp_format(test), ltm);
+	ct = iperf_timestr;
+    }
 
     /*
      * There are roughly two use cases here.  If we're the client,
@@ -4288,6 +4337,9 @@ iperf_printf(struct iperf_test *test, const char* format, ...)
      * to be buffered up anyway.
      */
     if (test->role == 'c') {
+	if (ct) {
+	    fprintf(test->outfile, "%s", ct);
+	}
 	if (test->title)
 	    fprintf(test->outfile, "%s:  ", test->title);
 	va_start(argp, format);
@@ -4296,8 +4348,12 @@ iperf_printf(struct iperf_test *test, const char* format, ...)
     }
     else if (test->role == 's') {
 	char linebuffer[1024];
+	int i = 0;
+	if (ct) {
+	    i = sprintf(linebuffer, "%s", ct);
+	}
 	va_start(argp, format);
-	r = vsnprintf(linebuffer, sizeof(linebuffer), format, argp);
+	r = vsnprintf(linebuffer + i, sizeof(linebuffer), format, argp);
 	va_end(argp);
 	fprintf(test->outfile, "%s", linebuffer);
 
diff --git a/src/iperf_api.h b/src/iperf_api.h
index 443f12f..63228d9 100644
--- a/src/iperf_api.h
+++ b/src/iperf_api.h
@@ -76,6 +76,7 @@ typedef uint64_t iperf_size_t;
 #define OPT_EXTRA_DATA 19
 #define OPT_BIDIRECTIONAL 20
 #define OPT_SERVER_BITRATE_LIMIT 21
+#define OPT_TIMESTAMPS 22
 
 /* states */
 #define TEST_START 1
@@ -116,6 +117,8 @@ double	iperf_get_test_reporter_interval( struct iperf_test* ipt );
 double	iperf_get_test_stats_interval( struct iperf_test* ipt );
 int	iperf_get_test_num_streams( struct iperf_test* ipt );
 int	iperf_get_test_repeating_payload( struct iperf_test* ipt );
+int	iperf_get_test_timestamps( struct iperf_test* ipt );
+const char* iperf_get_test_timestamp_format( struct iperf_test* ipt );
 int	iperf_get_test_server_port( struct iperf_test* ipt );
 char*	iperf_get_test_server_hostname( struct iperf_test* ipt );
 char*	iperf_get_test_template( struct iperf_test* ipt );
@@ -152,6 +155,8 @@ void	iperf_set_test_server_port( struct iperf_test* ipt, int server_port );
 void	iperf_set_test_socket_bufsize( struct iperf_test* ipt, int socket_bufsize );
 void	iperf_set_test_num_streams( struct iperf_test* ipt, int num_streams );
 void	iperf_set_test_repeating_payload( struct iperf_test* ipt, int repeating_payload );
+void	iperf_set_test_timestamps( struct iperf_test* ipt, int timestamps );
+void	iperf_set_test_timestamp_format( struct iperf_test*, const char *tf );
 void	iperf_set_test_role( struct iperf_test* ipt, char role );
 void	iperf_set_test_server_hostname( struct iperf_test* ipt, const char* server_hostname );
 void    iperf_set_test_template( struct iperf_test *ipt, const char *tmp_template );
diff --git a/src/iperf_error.c b/src/iperf_error.c
index 51445d5..b080540 100644
--- a/src/iperf_error.c
+++ b/src/iperf_error.c
@@ -35,12 +35,25 @@
 
 int gerror;
 
+char iperf_timestrerr[100];
+
 /* Do a printf to stderr. */
 void
 iperf_err(struct iperf_test *test, const char *format, ...)
 {
     va_list argp;
     char str[1000];
+    time_t now;
+    struct tm *ltm = NULL;
+    char *ct = NULL;
+
+    /* Timestamp if requested */
+    if (test != NULL && test->timestamps) {
+	time(&now);
+	ltm = localtime(&now);
+	strftime(iperf_timestrerr, sizeof(iperf_timestrerr), test->timestamp_format, ltm);
+	ct = iperf_timestrerr;
+    }
 
     va_start(argp, format);
     vsnprintf(str, sizeof(str), format, argp);
@@ -48,9 +61,15 @@ iperf_err(struct iperf_test *test, const char *format, ...)
 	cJSON_AddStringToObject(test->json_top, "error", str);
     else
 	if (test && test->outfile && test->outfile != stdout) {
+	    if (ct) {
+		fprintf(test->outfile, "%s", ct);
+	    }
 	    fprintf(test->outfile, "iperf3: %s\n", str);
 	}
 	else {
+	    if (ct) {
+		fprintf(stderr, "%s", ct);
+	    }
 	    fprintf(stderr, "iperf3: %s\n", str);
 	}
     va_end(argp);
@@ -62,6 +81,17 @@ iperf_errexit(struct iperf_test *test, const char *format, ...)
 {
     va_list argp;
     char str[1000];
+    time_t now;
+    struct tm *ltm = NULL;
+    char *ct = NULL;
+
+    /* Timestamp if requested */
+    if (test != NULL && test->timestamps) {
+	time(&now);
+	ltm = localtime(&now);
+	strftime(iperf_timestrerr, sizeof(iperf_timestrerr), "%c ", ltm);
+	ct = iperf_timestrerr;
+    }
 
     va_start(argp, format);
     vsnprintf(str, sizeof(str), format, argp);
@@ -70,9 +100,15 @@ iperf_errexit(struct iperf_test *test, const char *format, ...)
 	iperf_json_finish(test);
     } else
 	if (test && test->outfile && test->outfile != stdout) {
+	    if (ct) {
+		fprintf(test->outfile, "%s", ct);
+	    }
 	    fprintf(test->outfile, "iperf3: %s\n", str);
 	}
 	else {
+	    if (ct) {
+		fprintf(stderr, "%s", ct);
+	    }
 	    fprintf(stderr, "iperf3: %s\n", str);
 	}
     va_end(argp);
diff --git a/src/iperf_locale.c b/src/iperf_locale.c
index 8d6dd0b..d5a5354 100644
--- a/src/iperf_locale.c
+++ b/src/iperf_locale.c
@@ -109,6 +109,9 @@ const char usage_longstr[] = "Usage: iperf3 [-s|-c host] [options]\n"
                            "  -J, --json                output in JSON format\n"
                            "  --logfile f               send output to a log file\n"
                            "  --forceflush              force flushing output at every interval\n"
+                           "  --timestamps    <format>  emit a timestamp at the start of each output line\n"
+                           "                            (using optional format string as per strftime(3))\n"
+    
                            "  -d, --debug               emit debugging output\n"
                            "  -v, --version             show version information and quit\n"
                            "  -h, --help                show this message and quit\n"