Really support milliseconds in wxLog

Although this was supposed to work, specifying "%l" in wxLog time stamp
format actually didn't because wxLog timestamps were stored as seconds.

Fix this by storing them as milliseconds and add a simple test (not
executed by default) showing that "%l" works correctly now.

Still keep the old wxLogRecordInfo::timestamp field for compatibility,
as it was documented.

See #13059.

include/wx/log.h

@@ -62,6 +62,7 @@ class WXDLLIMPEXP_FWD_BASE wxObject;
 #include "wx/dynarray.h"
 #include "wx/hashmap.h"
 #include "wx/msgout.h"
+#include "wx/time.h"
 
 #if wxUSE_THREADS
     #include "wx/thread.h"
@@ -160,9 +161,11 @@ public:
 
         // don't initialize the timestamp yet, we might not need it at all if
         // the message doesn't end up being logged and otherwise we'll fill it
-        // just before logging it, which won't change it by much and definitely
-        // less than a second resolution of the timestamp
+        // just before logging it, which won't change it by much
+        timestampMS = 0;
+#if WXWIN_COMPATIBILITY_3_0
         timestamp = 0;
+#endif // WXWIN_COMPATIBILITY_3_0
 
 #if wxUSE_THREADS
         threadId = wxThread::GetCurrentId();
@@ -208,8 +211,13 @@ public:
     // not set (i.e. wxLOG_COMPONENT not defined). It must be in ASCII.
     const char *component;
 
-    // time of record generation
+    // time of record generation in milliseconds since Epoch
+    wxLongLong_t timestampMS;
+
+#if WXWIN_COMPATIBILITY_3_0
+    // preserved for compatibility only, use timestampMS instead now
     time_t timestamp;
+#endif // WXWIN_COMPATIBILITY_3_0
 
 #if wxUSE_THREADS
     // id of the thread which logged this record
@@ -334,7 +342,12 @@ public:
 protected:
     // Override this method to change just the time stamp formatting. It is
     // called by default Format() implementation.
+    virtual wxString FormatTimeMS(wxLongLong_t msec) const;
+
+#if WXWIN_COMPATIBILITY_3_0
+    // Old function which only worked at second resolution.
     virtual wxString FormatTime(time_t t) const;
+#endif // WXWIN_COMPATIBILITY_3_0
 };
 
 
@@ -1166,7 +1179,11 @@ private:
         // As explained in wxLogRecordInfo ctor, we don't initialize its
         // timestamp to avoid calling time() unnecessary, but now that we are
         // about to log the message, we do need to do it.
-        m_info.timestamp = time(NULL);
+        m_info.timestampMS = wxGetUTCTimeMillis().GetValue();
+
+#if WXWIN_COMPATIBILITY_3_0
+        m_info.timestamp = m_info.timestampMS / 1000;
+#endif // WXWIN_COMPATIBILITY_3_0
 
         wxLog::OnLog(level, wxString::FormatV(format, argptr), m_info);
     }

interface/wx/log.h

@@ -54,7 +54,18 @@ public:
      */
     const char *func;
 
-    /// Time when the log message was generated.
+    /**
+        Time in milliseconds since Epoch when the log message was generated.
+
+        @since 3.1.5
+     */
+    wxLongLong_t timestampMS;
+
+    /**
+        Time when the log message was generated.
+
+        @deprecated Please use timestampMS instead.
+     */
     time_t timestamp;
 
     /**
@@ -148,9 +159,30 @@ public:
                             const wxLogRecordInfo& info) const;
 
 protected:
+    /**
+        This function formats the time stamp part of the log message including
+        milliseconds.
+
+        Override this function if you need to customize just the time stamp
+        formatting in the log messages.
+
+        @param msec
+            Time to format as the number of milliseconds since
+            1970-01-01T00:00:00.
+
+        @return
+            The formatted time string, may be empty.
+
+        @since 3.1.5
+    */
+    virtual wxString FormatTimeMS(wxLongLong_t msec) const;
+
     /**
         This function formats the time stamp part of the log message.
 
+        @deprecated This function only exists for compatibility, please
+        override FormatTimeMS() in the new code.
+
         Override this function if you need to customize just the time stamp.
 
         @param time

samples/thread/thread.cpp

@@ -471,7 +471,7 @@ MyFrame::DoLogRecord(wxLogLevel level,
     DoLogLine
     (
         m_txtctrl,
-        wxDateTime(info.timestamp).FormatISOTime(),
+        wxDateTime(wxLongLong(info.timestampMS)).FormatISOTime(),
         info.threadId == wxThread::GetMainId()
             ? wxString("main")
             : wxString::Format("%lx", info.threadId),

src/common/log.cpp

@@ -194,6 +194,21 @@ void wxSafeShowMessage(const wxString& title, const wxString& text)
 // wxLogFormatter class implementation
 // ----------------------------------------------------------------------------
 
+#if WXWIN_COMPATIBILITY_3_0
+
+// Special string used to check if FormatTime() is overridden: hopefully
+// different from anything that could be reasonably returned by the overridden
+// version without being as long as a GUID.
+static const char* DEFAULT_FORMAT_TIME = "??";
+
+wxString
+wxLogFormatter::FormatTime(time_t WXUNUSED(t)) const
+{
+    return wxString::FromAscii(DEFAULT_FORMAT_TIME);
+}
+
+#endif // WXWIN_COMPATIBILITY_3_0
+
 wxString
 wxLogFormatter::Format(wxLogLevel level,
                        const wxString& msg,
@@ -206,7 +221,15 @@ wxLogFormatter::Format(wxLogLevel level,
 #ifdef __WINDOWS__
     if ( level != wxLOG_Debug && level != wxLOG_Trace )
 #endif // __WINDOWS__
+    {
+#if WXWIN_COMPATIBILITY_3_0
+        // Another backwards compatibility hack: check if FormatTime() was
+        // overridden in the user code.
         prefix = FormatTime(info.timestamp);
+        if ( prefix == DEFAULT_FORMAT_TIME )
+#endif // WXWIN_COMPATIBILITY_3_0
+            prefix = FormatTimeMS(info.timestampMS);
+    }
 
     switch ( level )
     {
@@ -237,10 +260,14 @@ wxLogFormatter::Format(wxLogLevel level,
 }
 
 wxString
-wxLogFormatter::FormatTime(time_t t) const
+wxLogFormatter::FormatTimeMS(wxLongLong_t msec) const
 {
     wxString str;
-    wxLog::TimeStamp(&str, t);
+
+#if wxUSE_DATETIME
+    str = wxDateTime(wxLongLong(msec)).Format(wxLog::GetTimestamp());
+    str += wxS(": ");
+#endif // wxUSE_DATETIME
 
     return str;
 }
@@ -321,7 +348,7 @@ void
 wxLog::OnLog(wxLogLevel level, const wxString& msg, time_t t)
 {
     wxLogRecordInfo info;
-    info.timestamp = t;
+    info.timestampMS = 1000*t;
 #if wxUSE_THREADS
     info.threadId = wxThread::GetCurrentId();
 #endif // wxUSE_THREADS

src/generic/logg.cpp

@@ -342,7 +342,7 @@ void wxLogGui::DoLogRecord(wxLogLevel level,
             {
                 m_aMessages.Add(msg);
                 m_aSeverity.Add(wxLOG_Message);
-                m_aTimes.Add((long)info.timestamp);
+                m_aTimes.Add((long)(info.timestampMS / 1000));
                 m_bHasMessages = true;
             }
             break;
@@ -395,7 +395,7 @@ void wxLogGui::DoLogRecord(wxLogLevel level,
 
             m_aMessages.Add(msg);
             m_aSeverity.Add((int)level);
-            m_aTimes.Add((long)info.timestamp);
+            m_aTimes.Add((long)(info.timestampMS / 1000));
             m_bHasMessages = true;
             break;
 

tests/log/logtest.cpp

@@ -454,4 +454,16 @@ void macroCompilabilityTest()
         wxLogDebug("hello debug %d", 42);
 }
 
+// This allows to check wxLogTrace() interactively by running this test with
+// WXTRACE=logtest.
+TEST_CASE("wxLog::Trace", "[log][.]")
+{
+    // Running this test without setting WXTRACE is useless.
+    REQUIRE( wxGetEnv("WXTRACE", NULL) );
+
+    wxLogTrace("logtest", "Starting test");
+    wxMilliSleep(250);
+    wxLogTrace("logtest", "Ending test 1/4s later");
+}
+
 #endif // wxUSE_LOG