Add default timestamps for TAP library (diag/ok)

- Adds config option with microseconds resolution, ON by default.
- Preserves TAP convention for messages to prevent tooling breaking.

test/tap/tap/tap.cpp

@@ -20,16 +20,20 @@
 
 #include "tap.h"
 
-//#include "my_global.h"
 typedef char my_bool;
 
 #include <stdlib.h>
 #include <stdarg.h>
 #include <stdio.h>
 #include <string.h>
 #include <signal.h>
+#include <time.h>
 #include <unistd.h>
 
+#include <sys/time.h>
+
+using std::size_t;
+
 static ulong start_timer(void);
 static void end_timer(ulong start_time,char *buff);
 static void nice_time(double sec,char *buff,my_bool part_second);
@@ -68,6 +72,34 @@ static TEST_DATA g_test = { NO_PLAN, 0, 0, "" };
  */
 #define tapout stdout
 
+/**
+  @brief Writes current time ("%Y-%m-%d %H:%M:%S") in the supplied buffer.
+
+  @param tm_buf Buffer to be written.
+  @param us True for enabling microseconds in log output.
+  @param len Buffer len.
+ */
+size_t get_fmt_time(char* tm_buf, size_t len, bool us=false) {
+  time_t __timer;
+  time(&__timer);
+  struct tm __tm_info {};
+  localtime_r(&__timer, &__tm_info);
+  size_t rc = strftime(tm_buf, len, "%Y-%m-%d %H:%M:%S", &__tm_info);
+
+  if (rc == 0) {
+    return rc;
+  } else if (us) {
+    struct timeval tv;
+    struct tm *tm_info;
+
+    gettimeofday(&tv, NULL);
+    tm_info = localtime(&tv.tv_sec);
+    rc = snprintf(tm_buf + rc, len - rc, ".%06ld", tv.tv_usec);
+  }
+
+  return rc;
+}
+
 /**
   Emit the beginning of a test line, that is: "(not) ok", test number,
   and description.
@@ -85,9 +117,12 @@ static TEST_DATA g_test = { NO_PLAN, 0, 0, "" };
 static void
 vemit_tap(int pass, char const *fmt, va_list ap)
 {
-  fprintf(tapout, "%sok %d%s",
+  char tm_buf[28] = { 0 };
+  get_fmt_time(tm_buf, sizeof(tm_buf), __sync_add_and_fetch(&tap_log_us, 0));
+  fprintf(tapout, "%sok %d - %s%s",
           pass ? "" : "not ",
           __sync_add_and_fetch(&g_test.last, 1),
+          tm_buf,
           (fmt && *fmt) ? " - " : "");
   if (fmt && *fmt)
     vfprintf(tapout, fmt, ap);
@@ -156,7 +191,9 @@ diag(char const *fmt, ...)
 {
   va_list ap;
   va_start(ap, fmt);
-  fprintf(tapout, "# ");
+  char tm_buf[28] = { 0 };
+  get_fmt_time(tm_buf, sizeof(tm_buf), __sync_add_and_fetch(&tap_log_us, 0));
+  fprintf(tapout, "# %s  ", tm_buf);
   vfprintf(tapout, fmt, ap);
   emit_endl();
   va_end(ap);
@@ -192,6 +229,7 @@ static signal_entry install_signal[]= {
 };
 
 int skip_big_tests= 1;
+volatile int tap_log_us = 1;
 ulong start_time= 0;
 
 void

test/tap/tap/tap.h

@@ -78,6 +78,10 @@ extern "C" {
    @see SKIP_BIG_TESTS
 */
 extern int skip_big_tests;
+/**
+ * @brief Specifies if time logging should include microseconds; either 1 or 0.
+ */
+extern volatile int tap_log_us;
 
 /**
   @defgroup MyTAP_API MyTAP API

test/tap/tests/max_connections_ff-t.cpp

@@ -18,14 +18,12 @@
 
 #include <cstring>
 #include <chrono>
-#include <iostream>
 #include <string>
 #include <stdio.h>
 #include <vector>
 #include <unistd.h>
 
 #include "mysql.h"
-#include "mysqld_error.h"
 
 #include "json.hpp"
 
@@ -66,10 +64,10 @@ int set_max_conns(MYSQL* proxy_admin, int max_conns, int hg_id) {
 	string max_conn_query {};
 	string_format("UPDATE mysql_servers SET max_connections=%d WHERE hostgroup_id=%d", max_conn_query, max_conns, hg_id);
 
-	diag("%s: Executing query `%s`...", tap_curtime().c_str(), max_conn_query.c_str());
+	diag("Executing query `%s`...", max_conn_query.c_str());
 	MYSQL_QUERY(proxy_admin, max_conn_query.c_str());
 
-	diag("%s: Executing query `%s`...", tap_curtime().c_str(), "LOAD MYSQL SERVERS TO RUNTIME");
+	diag("Executing query `%s`...", "LOAD MYSQL SERVERS TO RUNTIME");
 	MYSQL_QUERY(proxy_admin, "LOAD MYSQL SERVERS TO RUNTIME");
 
 	return EXIT_SUCCESS;
@@ -79,10 +77,10 @@ int set_srv_conn_to(MYSQL* proxy_admin, int connect_to) {
 	string srv_conn_to_query {};
 	string_format("SET mysql-connect_timeout_server_max=%d", srv_conn_to_query, connect_to);
 
-	diag("%s: Executing query `%s`...", tap_curtime().c_str(), srv_conn_to_query.c_str());
+	diag("Executing query `%s`...", srv_conn_to_query.c_str());
 	MYSQL_QUERY(proxy_admin, srv_conn_to_query.c_str());
 
-	diag("%s: Executing query `%s`...", tap_curtime().c_str(), "LOAD MYSQL VARIABLES TO RUNTIME");
+	diag("Executing query `%s`...", "LOAD MYSQL VARIABLES TO RUNTIME");
 	MYSQL_QUERY(proxy_admin, "LOAD MYSQL VARIABLES TO RUNTIME");
 
 	return EXIT_SUCCESS;
@@ -93,10 +91,10 @@ int set_ff_for_user(MYSQL* proxy_admin, const string& user, bool ff) {
 	string upd_ff_query {};
 	string_format("UPDATE mysql_users SET fast_forward=%d WHERE username='%s'", upd_ff_query, ff, user.c_str());
 
-	diag("%s: Executing query `%s`...", tap_curtime().c_str(), upd_ff_query.c_str());
+	diag("Executing query `%s`...", upd_ff_query.c_str());
 	MYSQL_QUERY(proxy_admin, upd_ff_query.c_str());
 
-	diag("%s: Executing query `%s`...", tap_curtime().c_str(), "LOAD MYSQL VARIABLES TO RUNTIME");
+	diag("Executing query `%s`...", "LOAD MYSQL VARIABLES TO RUNTIME");
 	MYSQL_QUERY(proxy_admin, "LOAD MYSQL USERS TO RUNTIME");
 
 	return EXIT_SUCCESS;
@@ -264,9 +262,9 @@ int test_ff_sess_exceeds_max_conns(const CommandLine& cl, MYSQL* proxy_admin, lo
 
 	string reset_conn_to_srv {};
 	string_format("SET mysql-connect_timeout_server_max=%s", reset_conn_to_srv, str_connect_timeout_server_max.c_str());
-	diag("%s: Executing query `%s`...", tap_curtime().c_str(), reset_conn_to_srv.c_str());
+	diag("Executing query `%s`...", reset_conn_to_srv.c_str());
 	MYSQL_QUERY(proxy_admin, reset_conn_to_srv.c_str());
-	diag("%s: Executing query `%s`...", tap_curtime().c_str(), "LOAD MYSQL VARIABLES TO RUNTIME");
+	diag("Executing query `%s`...", "LOAD MYSQL VARIABLES TO RUNTIME");
 	MYSQL_QUERY(proxy_admin, "LOAD MYSQL VARIABLES TO RUNTIME");
 
 	return EXIT_SUCCESS;
@@ -313,7 +311,7 @@ int test_ff_only_one_free_conn(const CommandLine& cl, MYSQL* proxy_admin, int ma
 
 	// Reset all the current stats for 'stats_mysql_connection_pool'
 	my_err = mysql_query(proxy_admin, reset_connpool_stats);
-	diag("%s: Executing query `%s` in new 'fast_forward' conn...", tap_curtime().c_str(), reset_connpool_stats);
+	diag("Executing query `%s` in new 'fast_forward' conn...", reset_connpool_stats);
 	if (my_err) {
 		diag("Query '%s' failed", reset_connpool_stats);
 		res = EXIT_FAILURE;
@@ -333,7 +331,7 @@ int test_ff_only_one_free_conn(const CommandLine& cl, MYSQL* proxy_admin, int ma
 		MYSQL* trx_conn = trx_conns.back();
 
 		diag("Freeing ONE connection by committing the transaction...");
-		diag("%s: Executing query `%s`...", tap_curtime().c_str(), "COMMIT");
+		diag("Executing query `%s`...", "COMMIT");
 		my_err = mysql_query(trx_conn, "COMMIT");
 		if (my_err) {
 			diag(
@@ -375,7 +373,7 @@ int test_ff_only_one_free_conn(const CommandLine& cl, MYSQL* proxy_admin, int ma
 		}
 
 		// 3.1 Issue a simple query into the new 'fast_forward' connection
-		diag("%s: Executing query `%s` in new 'fast_forward' conn...", tap_curtime().c_str(), "DO 1");
+		diag("Executing query `%s` in new 'fast_forward' conn...", "DO 1");
 		int q_my_err = mysql_query(proxy_ff, "DO 1");
 		if (q_my_err) {
 			diag(

test/tap/tests/reg_test_3223-restapi_return_codes-t.cpp

@@ -172,7 +172,7 @@ int main(int argc, char** argv) {
 			for (const string& params : req.params) {
 				const string ept { join_path(base_address, req.ept_info.name) };
 				diag(
-					"%s: Checking valid '%s' request - ept: '%s', params: '%s'", tap_curtime().c_str(),
+					"Checking valid '%s' request - ept: '%s', params: '%s'",
 					req.ept_info.method.c_str(), ept.c_str(), params.c_str()
 				);
 				std::chrono::nanoseconds duration;
@@ -308,7 +308,7 @@ int main(int argc, char** argv) {
 
 			const string ept { join_path(base_address, req.ept_info.name) };
 			diag(
-				"%s: Checking valid '%s' request - ept: '%s', params: '%s'", tap_curtime().c_str(),
+				"Checking valid '%s' request - ept: '%s', params: '%s'",
 				req.ept_info.method.c_str(), ept.c_str(), ept_pl.params.c_str()
 			);
 

test/tap/tests/reg_test_3765_ssl_pollout-t.cpp

@@ -68,7 +68,7 @@ int get_idle_conns_cpu_usage(CommandLine& cl, uint64_t mode, double& no_conns_cp
 	// get ProxySQL idle cpu usage
 	int idle_err = get_proxysql_cpu_usage(cl, REPORT_INTV_SEC, no_conns_cpu);
 	if (idle_err) {
-	    diag("Unable to get 'idle_cpu' usage.");
+	    diag("Unable to get 'no_conns_cpu' usage.");
 		return idle_err;
 	}
 
@@ -92,7 +92,7 @@ int get_idle_conns_cpu_usage(CommandLine& cl, uint64_t mode, double& no_conns_cp
 
 	int final_err = get_proxysql_cpu_usage(cl, REPORT_INTV_SEC, idle_conns_cpu);
 	if (final_err) {
-	    diag("Unable to get 'final_cpu' usage.");
+	    diag("Unable to get 'idle_conns_cpu' usage.");
 		return idle_err;
 	}
 

test/tap/tests/reg_test_sql_calc_found_rows-t.cpp

@@ -13,7 +13,6 @@
 #include <unistd.h>
 
 #include "mysql.h"
-#include "mysqld_error.h"
 
 #include "json.hpp"
 
@@ -74,7 +73,7 @@ int main(int argc, char** argv) {
 	// 1. Prepare the 'SQL_CALC_FOUND_ROWS' stmt in a connection
 	MYSQL* proxy_mysql = mysql_init(NULL);
 
-	diag("%s: Openning initial connection...", tap_curtime().c_str());
+	diag("Openning initial connection...");
 	if (!mysql_real_connect(proxy_mysql, cl.host, cl.username, cl.password, NULL, cl.port, NULL, 0)) {
 		fprintf(stderr, "File %s, line %d, Error: %s\n", __FILE__, __LINE__, mysql_error(proxy_mysql));
 		return EXIT_FAILURE;
@@ -84,7 +83,7 @@ int main(int argc, char** argv) {
 	MYSQL_STMT* stmt_2 = mysql_stmt_init(proxy_mysql);
 	MYSQL_STMT* stmt_3 = nullptr;
 
-	diag("%s: Issuing the prepare for `%s` in init conn", tap_curtime().c_str(), Q_CALC_FOUND_ROWS_1);
+	diag("Issuing the prepare for `%s` in init conn", Q_CALC_FOUND_ROWS_1);
 	int my_err = mysql_stmt_prepare(stmt_1, Q_CALC_FOUND_ROWS_1, strlen(Q_CALC_FOUND_ROWS_1));
 	if (my_err) {
 		diag(
@@ -94,7 +93,7 @@ int main(int argc, char** argv) {
 		goto cleanup;
 	}
 
-	diag("%s: Issuing the prepare for `%s` in init conn", tap_curtime().c_str(), Q_CALC_FOUND_ROWS_2);
+	diag("Issuing the prepare for `%s` in init conn", Q_CALC_FOUND_ROWS_2);
 	my_err = mysql_stmt_prepare(stmt_2, Q_CALC_FOUND_ROWS_2, strlen(Q_CALC_FOUND_ROWS_2));
 	if (my_err) {
 		diag(
@@ -107,13 +106,13 @@ int main(int argc, char** argv) {
 	mysql_stmt_close(stmt_1);
 	mysql_stmt_close(stmt_2);
 
-	diag("%s: Closing initial connection...", tap_curtime().c_str());
+	diag("Closing initial connection...");
 	mysql_close(proxy_mysql);
 
 	// 2. Open a new connection and prepare the stmts it again in a new connection
 	proxy_mysql = mysql_init(NULL);
 
-	diag("%s: Openning new connection for testing 'Multiplex' disabling", tap_curtime().c_str());
+	diag("Openning new connection for testing 'Multiplex' disabling");
 	if (!mysql_real_connect(proxy_mysql, cl.host, cl.username, cl.password, NULL, cl.port, NULL, 0)) {
 		fprintf(stderr, "File %s, line %d, Error: %s\n", __FILE__, __LINE__, mysql_error(proxy_mysql));
 		return EXIT_FAILURE;
@@ -123,7 +122,7 @@ int main(int argc, char** argv) {
 	stmt_2 = mysql_stmt_init(proxy_mysql);
 	stmt_3 = mysql_stmt_init(proxy_mysql);
 
-	diag("%s: Issuing the prepare for `%s` in new conn", tap_curtime().c_str(), Q_CALC_FOUND_ROWS_1);
+	diag("Issuing the prepare for `%s` in new conn", Q_CALC_FOUND_ROWS_1);
 	my_err = mysql_stmt_prepare(stmt_1, Q_CALC_FOUND_ROWS_1, strlen(Q_CALC_FOUND_ROWS_1));
 	if (my_err) {
 		diag(
@@ -134,7 +133,7 @@ int main(int argc, char** argv) {
 	}
 
 	{
-		diag("%s: Issuing execute for `%s` in new conn", tap_curtime().c_str(), Q_CALC_FOUND_ROWS_1);
+		diag("Issuing execute for `%s` in new conn", Q_CALC_FOUND_ROWS_1);
 		my_err = mysql_stmt_execute(stmt_1);
 		if (my_err) {
 			diag("'mysql_stmt_execute' at line %d failed: %s", __LINE__, mysql_stmt_error(stmt_1));
@@ -149,7 +148,7 @@ int main(int argc, char** argv) {
 		}
 	}
 	{
-		diag("%s: Issuing the prepare for `%s` in new conn", tap_curtime().c_str(), Q_CALC_FOUND_ROWS_2);
+		diag("Issuing the prepare for `%s` in new conn", Q_CALC_FOUND_ROWS_2);
 		my_err = mysql_stmt_prepare(stmt_2, Q_CALC_FOUND_ROWS_2, strlen(Q_CALC_FOUND_ROWS_2));
 		if (my_err) {
 			diag(
@@ -160,7 +159,7 @@ int main(int argc, char** argv) {
 		}
 
 		{
-			diag("%s: Issuing execute for `%s` in new conn", tap_curtime().c_str(), Q_CALC_FOUND_ROWS_2);
+			diag("Issuing execute for `%s` in new conn", Q_CALC_FOUND_ROWS_2);
 			my_err = mysql_stmt_execute(stmt_2);
 			if (my_err) {
 				diag("'mysql_stmt_execute' at line %d failed: %s", __LINE__, mysql_stmt_error(stmt_2));
@@ -175,7 +174,7 @@ int main(int argc, char** argv) {
 			}
 		}
 
-		diag("%s: Issuing the prepare for `%s` in new conn", tap_curtime().c_str(), Q_FOUND_ROWS);
+		diag("Issuing the prepare for `%s` in new conn", Q_FOUND_ROWS);
 		my_err = mysql_stmt_prepare(stmt_3, Q_FOUND_ROWS, strlen(Q_FOUND_ROWS));
 		if (my_err) {
 			diag(