From 9730bd29422775908e5bae5c889da46d82d10d41 Mon Sep 17 00:00:00 2001 From: Vadim Zeitlin Date: Wed, 13 Jan 2021 18:45:44 +0100 Subject: [PATCH 1/3] Remove unnecessary #include from log.cpp This header is already included from wx/log.h. --- src/common/log.cpp | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/common/log.cpp b/src/common/log.cpp index 0084d0033b..15aed7924f 100644 --- a/src/common/log.cpp +++ b/src/common/log.cpp @@ -49,8 +49,6 @@ #include -#include - #if defined(__WINDOWS__) #include "wx/msw/private.h" // includes windows.h #endif From 89bc7b522f1871050d6c30956e650bb23c3d8d41 Mon Sep 17 00:00:00 2001 From: Vadim Zeitlin Date: Wed, 13 Jan 2021 02:04:44 +0100 Subject: [PATCH 2/3] Use standard timestamp format for debug messages in the tests Don't use the current locale format which doesn't provide all the information (e.g. never includes milliseconds) and explicitly set the format providing it instead when showing wxLogTrace() messages. --- tests/test.cpp | 2 ++ 1 file changed, 2 insertions(+) diff --git a/tests/test.cpp b/tests/test.cpp index f2b0d84ef7..4d6775430d 100644 --- a/tests/test.cpp +++ b/tests/test.cpp @@ -618,6 +618,8 @@ int TestApp::RunTests() // running the tests. if ( !wxGetEnv(wxASCII_STR("WXTRACE"), NULL) ) wxLog::EnableLogging(false); + else + wxLog::SetTimestamp("%Y-%m-%d %H:%M:%S.%l"); #endif // Cast is needed under MSW where Catch also provides an overload taking From e6cedf66499bfab448cd670ade1f24c68e1fb49a Mon Sep 17 00:00:00 2001 From: Vadim Zeitlin Date: Wed, 13 Jan 2021 23:50:44 +0100 Subject: [PATCH 3/3] 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 | 25 +++++++++++++++++++++---- interface/wx/log.h | 34 +++++++++++++++++++++++++++++++++- samples/thread/thread.cpp | 2 +- src/common/log.cpp | 33 ++++++++++++++++++++++++++++++--- src/generic/logg.cpp | 4 ++-- tests/log/logtest.cpp | 12 ++++++++++++ 6 files changed, 99 insertions(+), 11 deletions(-) diff --git a/include/wx/log.h b/include/wx/log.h index 5e59c76338..5e82ac232d 100644 --- a/include/wx/log.h +++ b/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); } diff --git a/interface/wx/log.h b/interface/wx/log.h index 7835e29f5e..f875709dba 100644 --- a/interface/wx/log.h +++ b/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 diff --git a/samples/thread/thread.cpp b/samples/thread/thread.cpp index 1aa1897b36..3921d968f6 100644 --- a/samples/thread/thread.cpp +++ b/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), diff --git a/src/common/log.cpp b/src/common/log.cpp index 15aed7924f..8978ca5f77 100644 --- a/src/common/log.cpp +++ b/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 diff --git a/src/generic/logg.cpp b/src/generic/logg.cpp index 57b5975497..f2076edbea 100644 --- a/src/generic/logg.cpp +++ b/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; diff --git a/tests/log/logtest.cpp b/tests/log/logtest.cpp index 1a1cd0db31..ebbfcc7481 100644 --- a/tests/log/logtest.cpp +++ b/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