Time adjustments for VMs and 32-bit embedded (#177)

* in progress. now using std::chrono

* in progress, not working but defined how to fix it - broken unit tests

* working - verified on VM. Unit tests not yet updated accordintly

* fixed all tests

* fixed formatting

* adjusted timezone during testing

* adjusted test for timezone

src/filesink.cpp

@@ -9,6 +9,7 @@
 #include "g3log/filesink.hpp"
 #include "filesinkhelper.ipp"
 #include <cassert>
+#include <chrono>
 
 namespace g3 {
    using namespace internal;
@@ -41,7 +42,8 @@ namespace g3 {
 
    FileSink::~FileSink() {
       std::string exit_msg {"g3log g3FileSink shutdown at: "};
-      exit_msg.append(localtime_formatted(systemtime_now(), internal::time_formatted)).append("\n");
+      auto now = std::chrono::system_clock::now();
+      exit_msg.append(localtime_formatted(now, internal::time_formatted)).append("\n");
       filestream() << exit_msg << std::flush;
 
       exit_msg.append("Log file at: [").append(_log_file_with_path).append("]\n");
@@ -56,7 +58,7 @@ namespace g3 {
 
    std::string FileSink::changeLogFile(const std::string &directory, const std::string &logger_id) {
 
-      auto now = g3::systemtime_now();
+      auto now = std::chrono::system_clock::now();
       auto now_formatted = g3::localtime_formatted(now, {internal::date_formatted + " " + internal::time_formatted});
 
       std::string file_name = createLogFileName(_log_prefix_backup, logger_id);

src/filesinkhelper.ipp

@@ -79,7 +79,8 @@ namespace g3 {
       std::string header() {
          std::ostringstream ss_entry;
          //  Day Month Date Time Year: is written as "%a %b %d %H:%M:%S %Y" and formatted output as : Wed Sep 19 08:28:16 2012
-         ss_entry << "\t\tg3log created log at: " << g3::localtime_formatted(g3::systemtime_now(), "%a %b %d %H:%M:%S %Y") << "\n";
+         auto now = std::chrono::system_clock::now();
+         ss_entry << "\t\tg3log created log at: " << g3::localtime_formatted(now, "%a %b %d %H:%M:%S %Y") << "\n";
          ss_entry << "\t\tLOG format: [YYYY/MM/DD hh:mm:ss uuu* LEVEL FILE->FUNCTION:LINE] message";
          ss_entry << "\t\t(uuu*: microseconds fractions of the seconds value)\n\n";
          return ss_entry.str();
@@ -88,8 +89,11 @@ namespace g3 {
       std::string createLogFileName(const std::string &verified_prefix, const std::string &logger_id) {
          std::stringstream oss_name;
          oss_name << verified_prefix << ".";
-         if( logger_id != "" ) oss_name << logger_id << ".";
-         oss_name << g3::localtime_formatted(g3::systemtime_now(), file_name_time_formatted);
+         if( logger_id != "" ) {
+            oss_name << logger_id << ".";
+         }
+         auto now = std::chrono::system_clock::now();
+         oss_name << g3::localtime_formatted(now, file_name_time_formatted);
          oss_name << ".log";
          return oss_name.str();
       }

src/g3log.cpp

@@ -36,7 +36,7 @@
 
 namespace {
    std::once_flag g_initialize_flag;
-   g3::LogWorker *g_logger_instance = nullptr; // instantiated and OWNED somewhere else (main)
+   g3::LogWorker* g_logger_instance = nullptr; // instantiated and OWNED somewhere else (main)
    std::mutex g_logging_init_mutex;
 
    std::unique_ptr<g3::LogMessage> g_first_unintialized_msg = {nullptr};
@@ -59,7 +59,7 @@ namespace g3 {
    // several times...
    //                    for all other practical use, it shouldn't!
 
-   void initializeLogging(LogWorker *bgworker) {
+   void initializeLogging(LogWorker* bgworker) {
       std::call_once(g_initialize_flag, [] {
          installCrashHandler();
       });
@@ -139,7 +139,7 @@ namespace g3 {
        *         and the logging continues to be active.
        * @return true if the correct worker was given,. and shutDownLogging was called
        */
-      bool shutDownLoggingForActiveOnly(LogWorker *active) {
+      bool shutDownLoggingForActiveOnly(LogWorker* active) {
          if (isLoggingInitialized() && nullptr != active && (active != g_logger_instance)) {
             LOG(WARNING) << "\n\t\tAttempted to shut down logging, but the ID of the Logger is not the one that is active."
                          << "\n\t\tHaving multiple instances of the g3::LogWorker is likely a BUG"
@@ -156,8 +156,8 @@ namespace g3 {
 
       /** explicits copy of all input. This is makes it possibly to use g3log across dynamically loaded libraries
       * i.e. (dlopen + dlsym)  */
-      void saveMessage(const char *entry, const char *file, int line, const char *function, const LEVELS &level,
-                       const char *boolean_expression, int fatal_signal, const char *stack_trace) {
+      void saveMessage(const char* entry, const char* file, int line, const char* function, const LEVELS& level,
+                       const char* boolean_expression, int fatal_signal, const char* stack_trace) {
          LEVELS msgLevel {level};
          LogMessagePtr message {std2::make_unique<LogMessage>(file, line, function, msgLevel)};
          message.get()->write().append(entry);
@@ -209,7 +209,7 @@ namespace g3 {
                g_first_unintialized_msg = incoming.release();
                std::string err = {"LOGGER NOT INITIALIZED:\n\t\t"};
                err.append(g_first_unintialized_msg->message());
-               std::string &str = g_first_unintialized_msg->write();
+               std::string& str = g_first_unintialized_msg->write();
                str.clear();
                str.append(err); // replace content
                std::cerr << str << std::endl;

src/g3log/logmessage.hpp

@@ -87,7 +87,7 @@ namespace g3 {
       // Complete access to the raw data in case the helper functions above
       // are not enough.
       //
-      timespec _timestamp;
+      g3::system_time_point _timestamp;
       std::thread::id _call_thread_id;
       std::string _file;
       std::string _file_path;

src/g3log/time.hpp

@@ -22,10 +22,15 @@
 //          std::string put_time(const struct tm* tmb, const char* c_time_format)
 
 namespace g3 {
+   typedef std::chrono::time_point<std::chrono::system_clock>  system_time_point;
+   typedef std::chrono::milliseconds milliseconds;
+   typedef std::chrono::microseconds microseconds;
+
    namespace internal {
       enum class Fractional {Millisecond, Microsecond, Nanosecond, NanosecondDefault};
       Fractional getFractional(const std::string& format_buffer, size_t pos);
-      std::string to_string(const timespec& time_snapshot, Fractional fractional);
+      std::string to_string(const g3::system_time_point& ts, Fractional fractional);
+      std::string localtime_formatted_fractions(const g3::system_time_point& ts, std::string format_buffer);
       static const std::string date_formatted = "%Y/%m/%d";
       // %f: fractions of seconds (%f is nanoseconds)
       // %f3: milliseconds, 3 digits: 001
@@ -34,20 +39,6 @@ namespace g3 {
       static const std::string time_formatted = "%H:%M:%S %f6";
    } // internal
 
-   typedef std::chrono::time_point<std::chrono::system_clock>  system_time_point;
-   typedef std::chrono::milliseconds milliseconds;
-   typedef std::chrono::microseconds microseconds;
-
-
-
-   //  custom wrap for std::chrono::system_clock::now()but this one 
-   // returns timespec struct instead which is what we use in g3log
-   struct timespec systemtime_now();
-
-   // OSX, Windows needed wrapper for std::timespec_get(struct timespec *ts, int base)
-   //   OSX and Windows also lacks the POSIX clock_gettime(int base, struct timespec *ts)
-   //   so for that reason we go with the std::timespec_get(...) but wrap it
-   int timespec_get(struct timespec* ts/*, int base*/);
 
    // This mimics the original "std::put_time(const std::tm* tmb, const charT* fmt)"
    // This is needed since latest version (at time of writing) of gcc4.7 does not implement this library function yet.
@@ -63,7 +54,7 @@ namespace g3 {
    * WARNING: At time of writing there is only so-so compiler support for
    * std::put_time. A possible fix if your c++11 library is not updated is to
    * modify this to use std::strftime instead */
-   std::string localtime_formatted(const timespec& time_snapshot, const std::string& time_format) ;
+   std::string localtime_formatted(const system_time_point& ts, const std::string& time_format) ;
 }
 
 

src/logmessage.cpp

@@ -125,17 +125,13 @@ namespace g3 {
 
    LogMessage::LogMessage(const std::string& file, const int line,
                           const std::string& function, const LEVELS& level)
-      : _call_thread_id(std::this_thread::get_id())
+      : _timestamp(std::chrono::system_clock::now())
+      , _call_thread_id(std::this_thread::get_id())
       , _file(splitFileName(file))
       , _file_path(file)
       , _line(line)
       , _function(function)
-      , _level(level)
-   {
-      g3::timespec_get(&_timestamp/*, TIME_UTC*/);
-      // Another possibility could be to Falling back to clock_gettime as TIME_UTC 
-      // is not recognized by travis CI. 
-      // i.e. clock_gettime(CLOCK_REALTIME, &_timestamp);
+      , _level(level) {
    }
 
 
@@ -156,7 +152,7 @@ namespace g3 {
       , _message(other._message) {
    }
 
-   LogMessage::LogMessage(LogMessage &&other)
+   LogMessage::LogMessage(LogMessage&& other)
       : _timestamp(other._timestamp)
       , _call_thread_id(other._call_thread_id)
       , _file(std::move(other._file))

src/time.cpp

@@ -24,8 +24,6 @@ namespace g3 {
       const std::string kFractionalIdentier   = "%f";
       const size_t kFractionalIdentierSize = 2;
 
-
-
       Fractional getFractional(const std::string& format_buffer, size_t pos) {
          char  ch  = (format_buffer.size() > pos + kFractionalIdentierSize ? format_buffer.at(pos + kFractionalIdentierSize) : '\0');
          Fractional type = Fractional::NanosecondDefault;
@@ -38,13 +36,16 @@ namespace g3 {
          return type;
       }
 
-
       // Returns the fractional as a string with padded zeroes
       // 1 ms --> 001
       // 1 us --> 000001
       // 1 ns --> 000000001
-      std::string to_string(const timespec& time_snapshot, Fractional fractional) {
-         auto ns = time_snapshot.tv_nsec;
+      std::string to_string(const g3::system_time_point& ts, Fractional fractional) {
+         auto duration = ts.time_since_epoch();
+         auto sec_duration = std::chrono::duration_cast<std::chrono::seconds>(duration);
+         duration -= sec_duration;
+         auto ns = std::chrono::duration_cast<std::chrono::nanoseconds>(duration).count();
+
          auto zeroes = 9; // default ns
          auto digitsToCut = 1; // default ns, divide by 1 makes no change
          switch (fractional) {
@@ -67,62 +68,36 @@ namespace g3 {
          }
 
          ns /= digitsToCut;
-         // auto value = std::to_string(typeAdjustedValue);
-         // return value; // std::string(fractional_digit, '0') + value;
          auto value = std::string(std::to_string(ns));
          return std::string(zeroes - value.size(), '0') + value;
       }
-   } // internal
-} // g3
-
-
-
-namespace g3 {
-   struct timespec systemtime_now() {
-      struct timespec ts;
-      timespec_get(&ts);
-      return ts;
-   }
 
+      std::string localtime_formatted_fractions(const g3::system_time_point& ts, std::string format_buffer) {
+         // iterating through every "%f" instance in the format string
+         auto identifierExtraSize = 0;
+         for (size_t pos = 0;
+               (pos = format_buffer.find(g3::internal::kFractionalIdentier, pos)) != std::string::npos;
+               pos += g3::internal::kFractionalIdentierSize + identifierExtraSize) {
+            // figuring out whether this is nano, micro or milli identifier
+            auto type = g3::internal::getFractional(format_buffer, pos);
+            auto value = g3::internal::to_string(ts, type);
+            auto padding = 0;
+            if (type != g3::internal::Fractional::NanosecondDefault) {
+               padding = 1;
+            }
 
-   // std::timespec_get or posix clock_gettime)(...) are not
-   // implemented on OSX and ubuntu gcc5 has no support for std::timespec_get(...) as of yet
-   // so instead we roll our own.
-   int timespec_get(struct timespec* ts/*, int base*/) {
-      using namespace std::chrono;
-
-      // thanks @AndreasSchoenle for the implementation and the explanation:
-      // The time since epoch for the steady_clock is not necessarily really the time since 1970.
-      // It usually is the time since program start. Thus, here is calculated the offset between 
-      // the starting point and the real start of the epoch as reported by the system clock 
-      // with the precision of the system clock. 
-      // 
-      // Time stamps will later have system clock accuracy but relative times will have the precision
-      // of the high resolution clock.   
-      thread_local const auto os_system =
-         time_point_cast<nanoseconds>(system_clock::now()).time_since_epoch();
-      thread_local const auto os_high_resolution = 
-         time_point_cast<nanoseconds>(high_resolution_clock::now()).time_since_epoch();
-      thread_local auto os = os_system - os_high_resolution;
-
-      // 32-bit system work-around, where apparenetly the os correction above could sometimes 
-      // become negative. This correction will only be done once per thread
-      if (os.count() < 0 ) {
-         os =  os_system;
+            // replacing "%f[3|6|9]" with sec fractional part value
+            format_buffer.replace(pos, g3::internal::kFractionalIdentier.size() + padding, value);
+         }
+         return format_buffer;
       }
 
-      auto now_ns = (time_point_cast<nanoseconds>(high_resolution_clock::now()).time_since_epoch() + os).count();
-      const auto kNanos = 1000000000;
-      ts ->tv_sec = now_ns / kNanos;
-      ts ->tv_nsec = now_ns % kNanos;
-      #ifdef TIME_UTC
-         return TIME_UTC;
-      #endif
-      return 1;
-   }
+   } // internal
+} // g3
 
 
 
+namespace g3 {
    // This mimics the original "std::put_time(const std::tm* tmb, const charT* fmt)"
    // This is needed since latest version (at time of writing) of gcc4.7 does not implement this library function yet.
    // return value is SIMPLIFIED to only return a std::string
@@ -148,44 +123,27 @@ namespace g3 {
          assert((0 != success) && "strftime fails with illegal formatting");
          return c_time_format;
       }
-
       return buffer;
 #endif
    }
 
 
 
-   tm localtime(const std::time_t& time) {
+   tm localtime(const std::time_t& ts) {
       struct tm tm_snapshot;
 #if (defined(WIN32) || defined(_WIN32) || defined(__WIN32__) && !defined(__GNUC__))
-      localtime_s(&tm_snapshot, &time); // windsows
+      localtime_s(&tm_snapshot, &ts); // windsows
 #else
-      localtime_r(&time, &tm_snapshot); // POSIX
+      localtime_r(&ts, &tm_snapshot); // POSIX
 #endif
       return tm_snapshot;
    }
 
 
-
-
-   std::string localtime_formatted(const timespec& time_snapshot, const std::string& time_format) {
-      auto format_buffer = time_format;  // copying format string to a separate buffer
-
-      // iterating through every "%f" instance in the format string
-      auto identifierExtraSize = 0;
-      for (size_t pos = 0; (pos = format_buffer.find(g3::internal::kFractionalIdentier, pos)) != std::string::npos; pos += g3::internal::kFractionalIdentierSize + identifierExtraSize) {
-         // figuring out whether this is nano, micro or milli identifier
-         auto type = g3::internal::getFractional(format_buffer, pos);
-         auto value = g3::internal::to_string(time_snapshot, type);
-         auto padding = 0;
-         if (type != g3::internal::Fractional::NanosecondDefault) {
-            padding = 1;
-         }
-
-         // replacing "%f[3|6|9]" with sec fractional part value
-         format_buffer.replace(pos, g3::internal::kFractionalIdentier.size() + padding, value);
-      }
-      std::tm t = localtime(time_snapshot.tv_sec);   
+   std::string localtime_formatted(const g3::system_time_point& ts, const std::string& time_format) {
+      auto format_buffer = internal::localtime_formatted_fractions(ts, time_format);
+      auto time_point = std::chrono::system_clock::to_time_t(ts);
+      std::tm t = localtime(time_point);
       return g3::put_time(&t, format_buffer.c_str()); // format example: //"%Y/%m/%d %H:%M:%S");
    }
 } // g3