Enh 34110068 - Request to get more timestamps into the output of ndb_restore

Maitrayi Sabaratnam · Maitrayi Sabaratnam · commit a359bce8c5b3 · 2022-12-07T22:40:34.000+01:00
Prefix the ndb_restore outputs with a timestamp, managed by the new bool option :
"--timestamp_printouts".

By default, it is 'false' in in 7.5/7.6.

So there is no changes to tests. However, one test
(ndb_restore_print_sql_log) is changed to use the option to 'true' in
order to test that it is working. The test is also changed to mask
timestamps from the restore output with 'X' to avoid tests running on
different dates give 'Result content mismatch'.

Reviewed by: Martin Skold &lt;Martin.Skold@oracle.com&gt;

Change-Id: Ic183206e4d0f1d065d6448d03172a04217d4f4a0
diff --git a/mysql-test/suite/ndb/r/ndb_restore_print_sql_log.result b/mysql-test/suite/ndb/r/ndb_restore_print_sql_log.result
@@ -81,6 +81,6 @@ insert into t7 values(1,'a');
 drop table t8;
 
 "Restore with --print-sql-log option"
-Found column of type blob with print-sql-log option set. Exiting...
+XXXX-XX-XX XX:XX:XX Found column of type blob with print-sql-log option set. Exiting...
 drop table t7;
 drop table if exists t8;
diff --git a/mysql-test/suite/ndb/t/ndb_restore_print_sql_log.test b/mysql-test/suite/ndb/t/ndb_restore_print_sql_log.test
@@ -238,8 +238,15 @@ while ($mysql_errno)
 --echo
 --echo "Restore with --print-sql-log option"
 --let ndb_restore_opts= --print-sql-log --verbose=0 --core-file=0
+
+# ndb_restore should now fail with
+#   "Found column of type blob with print-sql-log option set. Exiting..."
+# By using option '-t', the error msg will be prefixed with the timestamp.
+# Mask the digits of the timestamp with 'X's to avoid mtr test failing with
+#   'Result content mismatch'.
+--replace_regex /[0-9]*-[0-9]*-[0-9]* [0-9]*:[0-9]*:[0-9]*/XXXX-XX-XX XX:XX:XX/
 --error 1
---exec $NDB_RESTORE --no-defaults $ndb_restore_opts -b $the_backup_id -n 1 $NDB_BACKUPS-$the_backup_id 2>&1
+--exec $NDB_RESTORE --no-defaults $ndb_restore_opts -b $the_backup_id  --timestamp_printouts=true -n 1 $NDB_BACKUPS-$the_backup_id 2>&1
 
 drop table t7;
 --disable_warnings
diff --git a/storage/ndb/tools/restore/Restore.cpp b/storage/ndb/tools/restore/Restore.cpp
@@ -2316,6 +2316,8 @@ LogEntry::printSqlLog() const {
   ndbout << ";";
 }
 
+RestoreLogger::RestoreLogger():print_timestamp(false) {}
+
 void RestoreLogger::log_error(const char* fmt, ...)
 {
   va_list ap;
@@ -2324,6 +2326,10 @@ void RestoreLogger::log_error(const char* fmt, ...)
   vsnprintf(buf, sizeof(buf), fmt, ap);
   va_end(ap);
 
+  if (print_timestamp) {
+    Logger::format_timestamp(time(NULL), timestamp, sizeof(timestamp));
+    err << timestamp << " ";
+  }
   err << buf << endl;
 }
 
@@ -2335,6 +2341,10 @@ void RestoreLogger::log_info(const char* fmt, ...)
   vsnprintf(buf, sizeof(buf), fmt, ap);
   va_end(ap);
 
+  if (print_timestamp) {
+    Logger::format_timestamp(time(NULL), timestamp, sizeof(timestamp));
+    info << timestamp << " ";
+  }
   info << buf << endl;
 }
 
@@ -2346,9 +2356,23 @@ void RestoreLogger::log_debug(const char* fmt, ...)
   vsnprintf(buf, sizeof(buf), fmt, ap);
   va_end(ap);
 
+  if (print_timestamp) {
+    Logger::format_timestamp(time(NULL), timestamp, sizeof(timestamp));
+    debug << timestamp << " ";
+  }
   debug << buf << endl;
 }
 
+void
+RestoreLogger::set_print_timestamp(bool print_TS) {
+  print_timestamp = print_TS;
+}
+
+bool
+RestoreLogger::get_print_timestamp() {
+  return print_timestamp;
+}
+
 NdbOut &
 operator<<(NdbOut& ndbout, const TableS & table)
 {
diff --git a/storage/ndb/tools/restore/Restore.hpp b/storage/ndb/tools/restore/Restore.hpp
@@ -526,12 +526,18 @@ class RestoreLogIterator : public BackupFile {
 
 class RestoreLogger {
 public:
+  RestoreLogger();
   void log_info(const char* fmt, ...)
          ATTRIBUTE_FORMAT(printf, 2, 3);
   void log_debug(const char* fmt, ...)
          ATTRIBUTE_FORMAT(printf, 2, 3);
   void log_error(const char* fmt, ...)
          ATTRIBUTE_FORMAT(printf, 2, 3);
+  void set_print_timestamp(bool print_TS);
+  bool get_print_timestamp();
+private:
+  char timestamp[64];
+  bool print_timestamp;
 };
 
 NdbOut& operator<<(NdbOut& ndbout, const TableS&);
diff --git a/storage/ndb/tools/restore/restore_main.cpp b/storage/ndb/tools/restore/restore_main.cpp
@@ -77,6 +77,7 @@ Vector<BaseString> g_include_databases, g_exclude_databases;
 Properties g_rewrite_databases;
 NdbRecordPrintFormat g_ndbrecord_print_format;
 unsigned int opt_no_binlog;
+static bool opt_timestamp_printouts;
 
 class RestoreOption
 {
@@ -146,6 +147,10 @@ static bool opt_restore_privilege_tables = false;
 static struct my_option my_long_options[] =
 {
   NDB_STD_OPTS("ndb_restore"),
+  { "timestamp_printouts", NDB_OPT_NOSHORT,
+    "Add a timestamp to the logger messages info, error and debug",
+    (uchar**) &opt_timestamp_printouts, (uchar**) &opt_timestamp_printouts, 0,
+    GET_BOOL, NO_ARG, false, 0, 0, 0, 0, 0 },
   { "connect", 'c', "same as --connect-string",
     (uchar**) &opt_ndb_connectstring, (uchar**) &opt_ndb_connectstring, 0,
     GET_STR, REQUIRED_ARG, 0, 0, 0, 0, 0, 0 },
@@ -603,6 +608,9 @@ readArguments(int *pargc, char*** pargv)
   {
     exit(NdbRestoreStatus::WrongArgs);
   }
+  if (opt_timestamp_printouts) {
+    restoreLogger.set_print_timestamp(true);
+  }
   if (ga_nodeId == 0)
   {
     err << "Backup file node ID not specified, please provide --nodeid" << endl;
@@ -1320,8 +1328,6 @@ main(int argc, char** argv)
 
   init_progress();
 
-  char timestamp[64];
-
   /**
    * we must always load meta data, even if we will only print it to stdout
    */
@@ -1336,8 +1342,7 @@ main(int argc, char** argv)
   }
 #endif 
 
-  Logger::format_timestamp(time(NULL), timestamp, sizeof(timestamp));
-  restoreLogger.log_info("%s [restore_metadata] Read meta data file header", timestamp);
+  restoreLogger.log_info("[restore_metadata] Read meta data file header");
 
   if (!metaData.readHeader())
   {
@@ -1390,8 +1395,7 @@ main(int argc, char** argv)
   }
 
   restoreLogger.log_debug("Load content");
-  Logger::format_timestamp(time(NULL), timestamp, sizeof(timestamp));
-  restoreLogger.log_info("%s [restore_metadata] Load content", timestamp);
+  restoreLogger.log_info("[restore_metadata] Load content");
 
   int res  = metaData.loadContent();
 
@@ -1404,8 +1408,7 @@ main(int argc, char** argv)
     exitHandler(NdbRestoreStatus::Failed);
   }
   restoreLogger.log_debug("Get number of Tables");
-  Logger::format_timestamp(time(NULL), timestamp, sizeof(timestamp));
-  restoreLogger.log_info("%s [restore_metadata] Get number of Tables", timestamp);
+  restoreLogger.log_info("[restore_metadata] Get number of Tables");
   if (metaData.getNoOfTables() == 0) 
   {
     restoreLogger.log_error("The backup contains no tables");
@@ -1453,8 +1456,7 @@ main(int argc, char** argv)
   }
 
   restoreLogger.log_debug("Validate Footer");
-  Logger::format_timestamp(time(NULL), timestamp, sizeof(timestamp));
-  restoreLogger.log_info("%s [restore_metadata] Validate Footer", timestamp);
+  restoreLogger.log_info("[restore_metadata] Validate Footer");
 
   if (!metaData.validateFooter()) 
   {
@@ -1481,8 +1483,7 @@ main(int argc, char** argv)
     g_consumers[i]->report_started(ga_backupId, ga_nodeId);
 
   restoreLogger.log_debug("Restore objects (tablespaces, ..)");
-  Logger::format_timestamp(time(NULL), timestamp, sizeof(timestamp));
-  restoreLogger.log_info("%s [restore_metadata] Restore objects (tablespaces, ..)", timestamp);
+  restoreLogger.log_info("[restore_metadata] Restore objects (tablespaces, ..)");
   for(i = 0; i<metaData.getNoOfObjects(); i++)
   {
     for(Uint32 j= 0; j < g_consumers.size(); j++)
@@ -1504,8 +1505,7 @@ main(int argc, char** argv)
 
   Vector<OutputStream *> table_output(metaData.getNoOfTables());
   restoreLogger.log_debug("Restoring tables");
-  Logger::format_timestamp(time(NULL), timestamp, sizeof(timestamp));
-  restoreLogger.log_info("%s [restore_metadata] Restoring tables", timestamp);
+  restoreLogger.log_info("[restore_metadata] Restoring tables");
 
   for(i = 0; i<metaData.getNoOfTables(); i++)
   {
@@ -1573,8 +1573,7 @@ main(int argc, char** argv)
   }
 
   restoreLogger.log_debug("Save foreign key info");
-  Logger::format_timestamp(time(NULL), timestamp, sizeof(timestamp));
-  restoreLogger.log_info("%s [restore_metadata] Save foreign key info", timestamp);
+  restoreLogger.log_info("[restore_metadata] Save foreign key info");
   for(i = 0; i<metaData.getNoOfObjects(); i++)
   {
     for(Uint32 j= 0; j < g_consumers.size(); j++)
@@ -1608,8 +1607,7 @@ main(int argc, char** argv)
     g_consumers[i]->report_meta_data(ga_backupId, ga_nodeId);
   }
   restoreLogger.log_debug("Iterate over data");
-  Logger::format_timestamp(time(NULL), timestamp, sizeof(timestamp));
-  restoreLogger.log_info("%s [restore_data] Start restoring table data", timestamp);
+  restoreLogger.log_info("[restore_data] Start restoring table data");
   if (ga_restore || ga_print) 
   {
     if(_restore_data || _print_data)
@@ -1675,9 +1673,8 @@ main(int argc, char** argv)
           restoreLogger.log_error("Unable to allocate memory for RestoreDataIterator constructor");
           exitHandler(NdbRestoreStatus::Failed);
       }
-      
-      Logger::format_timestamp(time(NULL), timestamp, sizeof(timestamp));
-      restoreLogger.log_info("%s [restore_data] Read data file header", timestamp);
+
+      restoreLogger.log_info("[restore_data] Read data file header");
 
       // Read data file header
       if (!dataIter.readHeader())
@@ -1686,9 +1683,8 @@ main(int argc, char** argv)
           "Failed to read header of data file. Exiting...");
 	exitHandler(NdbRestoreStatus::Failed);
       }
-      
-      Logger::format_timestamp(time(NULL), timestamp, sizeof(timestamp));
-      restoreLogger.log_info("%s [restore_data] Restore fragments", timestamp);
+
+      restoreLogger.log_info("[restore_data] Restore fragments");
 
       Uint32 fragmentId; 
       while (dataIter.readFragmentHeader(res= 0, &fragmentId))
@@ -1759,8 +1755,7 @@ main(int argc, char** argv)
     {
       RestoreLogIterator logIter(metaData);
 
-      Logger::format_timestamp(time(NULL), timestamp, sizeof(timestamp));
-      restoreLogger.log_info("%s [restore_log] Read log file header", timestamp);
+      restoreLogger.log_info("[restore_log] Read log file header");
 
       if (!logIter.readHeader())
       {
@@ -1771,8 +1766,7 @@ main(int argc, char** argv)
       
       const LogEntry * logEntry = 0;
 
-      Logger::format_timestamp(time(NULL), timestamp, sizeof(timestamp));
-      restoreLogger.log_info("%s [restore_log] Restore log entries", timestamp);
+      restoreLogger.log_info("[restore_log] Restore log entries");
 
       while ((logEntry = logIter.getNextLogEntry(res= 0)) != 0)
       {
@@ -1848,8 +1842,7 @@ main(int argc, char** argv)
   }
   if (ga_restore_epoch)
   {
-    Logger::format_timestamp(time(NULL), timestamp, sizeof(timestamp));
-    restoreLogger.log_info("%s [restore_epoch] Restoring epoch", timestamp);
+    restoreLogger.log_info("[restore_epoch] Restoring epoch");
     RestoreLogIterator logIter(metaData);
 
     if (!logIter.readHeader())
@@ -1882,8 +1875,7 @@ main(int argc, char** argv)
   if (ga_rebuild_indexes)
   {
     restoreLogger.log_debug("Rebuilding indexes");
-    Logger::format_timestamp(time(NULL), timestamp, sizeof(timestamp));
-    restoreLogger.log_info("%s [rebuild_indexes] Rebuilding indexes", timestamp);
+    restoreLogger.log_info("[rebuild_indexes] Rebuilding indexes");
 
     for(i = 0; i<metaData.getNoOfTables(); i++)
     {
