]> git.saurik.com Git - wxWidgets.git/blobdiff - src/common/log.cpp
fixing overrelease and out-of-bounds write, fixes #13725
[wxWidgets.git] / src / common / log.cpp
index f72beb9af9e4d5005594d5faa034f7519abcbb53..5135eadaa33799aa29055274cdba6870b0bbdb6a 100644 (file)
@@ -42,6 +42,7 @@
 #include "wx/msgout.h"
 #include "wx/textfile.h"
 #include "wx/thread.h"
+#include "wx/private/threadinfo.h"
 #include "wx/crt.h"
 #include "wx/vector.h"
 
 
 #include <stdlib.h>
 
-#ifndef __WXPALMOS5__
 #ifndef __WXWINCE__
 #include <time.h>
 #else
 #include "wx/msw/wince/time.h"
 #endif
-#endif /* ! __WXPALMOS5__ */
 
 #if defined(__WINDOWS__)
     #include "wx/msw/private.h" // includes windows.h
 #undef wxLOG_COMPONENT
 const char *wxLOG_COMPONENT = "";
 
+// this macro allows to define an object which will be initialized before any
+// other function in this file is called: this is necessary to allow log
+// functions to be used during static initialization (this is not advisable
+// anyhow but we should at least try to not crash) and to also ensure that they
+// are initialized by the time static initialization is done, i.e. before any
+// threads are created hopefully
+//
+// the net effect of all this is that you can use Get##name() function to
+// access the object without worrying about it being not initialized
+//
+// see also WX_DEFINE_GLOBAL_CONV2() in src/common/strconv.cpp
+#define WX_DEFINE_GLOBAL_VAR(type, name)                                      \
+    inline type& Get##name()                                                  \
+    {                                                                         \
+        static type s_##name;                                                 \
+        return s_##name;                                                      \
+    }                                                                         \
+                                                                              \
+    type *gs_##name##Ptr = &Get##name()
+
 #if wxUSE_THREADS
 
+wxTLS_TYPE(wxThreadSpecificInfo) wxThreadInfoVar;
+
 namespace
 {
 
@@ -77,42 +98,17 @@ namespace
 typedef wxVector<wxLogRecord> wxLogRecords;
 wxLogRecords gs_bufferedLogRecords;
 
-
-// define static functions providing access to the critical sections we use
-// instead of just using static critical section variables as log functions may
-// be used during static initialization and while this is certainly not
-// advisable it's still better to not crash (as we'd do if we used a yet
-// uninitialized critical section) if it happens
+#define WX_DEFINE_LOG_CS(name) WX_DEFINE_GLOBAL_VAR(wxCriticalSection, name##CS)
 
 // this critical section is used for buffering the messages from threads other
 // than main, i.e. it protects all accesses to gs_bufferedLogRecords above
-inline wxCriticalSection& GetBackgroundLogCS()
-{
-    static wxCriticalSection s_csBackground;
-
-    return s_csBackground;
-}
-
-inline wxCriticalSection& GetTraceMaskCS()
-{
-    static wxCriticalSection s_csTrace;
-
-    return s_csTrace;
-}
+WX_DEFINE_LOG_CS(BackgroundLog);
 
-inline wxCriticalSection& GetPreviousLogCS()
-{
-    static wxCriticalSection s_csPrev;
-
-    return s_csPrev;
-}
+// this one is used for protecting TraceMasks() from concurrent access
+WX_DEFINE_LOG_CS(TraceMask);
 
-inline wxCriticalSection& GetLevelsCS()
-{
-    static wxCriticalSection s_csLevels;
-
-    return s_csLevels;
-}
+// and this one is used for GetComponentLevels()
+WX_DEFINE_LOG_CS(Levels);
 
 } // anonymous namespace
 
@@ -165,7 +161,26 @@ PreviousLogInfo gs_prevLog;
 // map containing all components for which log level was explicitly set
 //
 // NB: all accesses to it must be protected by GetLevelsCS() critical section
-wxStringToNumHashMap gs_componentLevels;
+WX_DEFINE_GLOBAL_VAR(wxStringToNumHashMap, ComponentLevels);
+
+// ----------------------------------------------------------------------------
+// wxLogOutputBest: wxLog wrapper around wxMessageOutputBest
+// ----------------------------------------------------------------------------
+
+class wxLogOutputBest : public wxLog
+{
+public:
+    wxLogOutputBest() { }
+
+protected:
+    virtual void DoLogText(const wxString& msg)
+    {
+        wxMessageOutputBest().Output(msg);
+    }
+
+private:
+    wxDECLARE_NO_COPY_CLASS(wxLogOutputBest);
+};
 
 } // anonymous namespace
 
@@ -187,6 +202,62 @@ void wxSafeShowMessage(const wxString& title, const wxString& text)
 #endif
 }
 
+// ----------------------------------------------------------------------------
+// wxLogFormatter class implementation
+// ----------------------------------------------------------------------------
+
+wxString
+wxLogFormatter::Format(wxLogLevel level,
+                       const wxString& msg,
+                       const wxLogRecordInfo& info) const
+{
+    wxString prefix;
+
+    // don't time stamp debug messages under MSW as debug viewers usually
+    // already have an option to do it
+#ifdef __WINDOWS__
+    if ( level != wxLOG_Debug && level != wxLOG_Trace )
+#endif // __WINDOWS__
+        prefix = FormatTime(info.timestamp);
+
+    switch ( level )
+    {
+    case wxLOG_Error:
+        prefix += _("Error: ");
+        break;
+
+    case wxLOG_Warning:
+        prefix += _("Warning: ");
+        break;
+
+        // don't prepend "debug/trace" prefix under MSW as it goes to the debug
+        // window anyhow and so can't be confused with something else
+#ifndef __WINDOWS__
+    case wxLOG_Debug:
+        // this prefix (as well as the one below) is intentionally not
+        // translated as nobody translates debug messages anyhow
+        prefix += "Debug: ";
+        break;
+
+    case wxLOG_Trace:
+        prefix += "Trace: ";
+        break;
+#endif // !__WINDOWS__
+    }
+
+    return prefix + msg;
+}
+
+wxString
+wxLogFormatter::FormatTime(time_t t) const
+{
+    wxString str;
+    wxLog::TimeStamp(&str, t);
+
+    return str;
+}
+
+
 // ----------------------------------------------------------------------------
 // wxLog class implementation
 // ----------------------------------------------------------------------------
@@ -199,12 +270,24 @@ unsigned wxLog::LogLastRepeatIfNeeded()
     {
         wxString msg;
 #if wxUSE_INTL
-        msg.Printf(wxPLURAL("The previous message repeated once.",
-                            "The previous message repeated %lu times.",
-                            gs_prevLog.numRepeated),
-                   gs_prevLog.numRepeated);
+        if ( gs_prevLog.numRepeated == 1 )
+        {
+            // We use a separate message for this case as "repeated 1 time"
+            // looks somewhat strange.
+            msg = _("The previous message repeated once.");
+        }
+        else
+        {
+            // Notice that we still use wxPLURAL() to ensure that multiple
+            // numbers of times are correctly formatted, even though we never
+            // actually use the singular string.
+            msg.Printf(wxPLURAL("The previous message repeated %lu time.",
+                                "The previous message repeated %lu times.",
+                                gs_prevLog.numRepeated),
+                       gs_prevLog.numRepeated);
+        }
 #else
-        msg.Printf(wxS("The previous message was repeated %lu times."),
+        msg.Printf(wxS("The previous message was repeated %lu time(s)."),
                    gs_prevLog.numRepeated);
 #endif
         gs_prevLog.numRepeated = 0;
@@ -223,11 +306,22 @@ wxLog::~wxLog()
     {
         wxMessageOutputDebug().Printf
         (
-            wxS("Last repeated message (\"%s\", %lu times) wasn't output"),
+#if wxUSE_INTL
+            wxPLURAL
+            (
+                "Last repeated message (\"%s\", %lu time) wasn't output",
+                "Last repeated message (\"%s\", %lu times) wasn't output",
+                gs_prevLog.numRepeated
+            ),
+#else
+            wxS("Last repeated message (\"%s\", %lu time(s)) wasn't output"),
+#endif
             gs_prevLog.msg,
             gs_prevLog.numRepeated
         );
     }
+
+    delete m_formatter;
 }
 
 // ----------------------------------------------------------------------------
@@ -259,43 +353,54 @@ wxLog::OnLog(wxLogLevel level,
     {
         wxSafeShowMessage(wxS("Fatal Error"), msg);
 
-#ifdef __WXWINCE__
-        ExitThread(3);
-#else
-        abort();
-#endif
+        wxAbort();
     }
 
-    wxLog *pLogger = GetActiveTarget();
-    if ( !pLogger )
-        return;
+    wxLog *logger;
 
 #if wxUSE_THREADS
     if ( !wxThread::IsMain() )
     {
-        wxCriticalSectionLocker lock(GetBackgroundLogCS());
+        logger = wxThreadInfo.logger;
+        if ( !logger )
+        {
+            if ( ms_pLogger )
+            {
+                // buffer the messages until they can be shown from the main
+                // thread
+                wxCriticalSectionLocker lock(GetBackgroundLogCS());
 
-        gs_bufferedLogRecords.push_back(wxLogRecord(level, msg, info));
+                gs_bufferedLogRecords.push_back(wxLogRecord(level, msg, info));
 
-        // ensure that our Flush() will be called soon
-        wxWakeUpIdle();
+                // ensure that our Flush() will be called soon
+                wxWakeUpIdle();
+            }
+            //else: we don't have any logger at all, there is no need to log
+            //      anything
 
-        return;
+            return;
+        }
+        //else: we have a thread-specific logger, we can send messages to it
+        //      directly
     }
+    else
 #endif // wxUSE_THREADS
+    {
+        logger = GetMainThreadActiveTarget();
+        if ( !logger )
+            return;
+    }
 
-    pLogger->OnLogInMainThread(level, msg, info);
+    logger->CallDoLogNow(level, msg, info);
 }
 
 void
-wxLog::OnLogInMainThread(wxLogLevel level,
-                         const wxString& msg,
-                         const wxLogRecordInfo& info)
+wxLog::CallDoLogNow(wxLogLevel level,
+                    const wxString& msg,
+                    const wxLogRecordInfo& info)
 {
     if ( GetRepetitionCounting() )
     {
-        wxCRIT_SECT_LOCKER(lock, GetPreviousLogCS());
-
         if ( msg == gs_prevLog.msg )
         {
             gs_prevLog.numRepeated++;
@@ -318,9 +423,7 @@ wxLog::OnLogInMainThread(wxLogLevel level,
     wxUIntPtr num = 0;
     if ( info.GetNumValue(wxLOG_KEY_SYS_ERROR_CODE, &num) )
     {
-        long err = static_cast<long>(num);
-        if ( !err )
-            err = wxSysErrorCode();
+        const long err = static_cast<long>(num);
 
         suffix.Printf(_(" (error %ld: %s)"), err, wxSysErrorMsg(err));
     }
@@ -349,49 +452,12 @@ void wxLog::DoLogRecord(wxLogLevel level,
     // but to call both of them
     DoLog(level, (const char*)msg.mb_str(), info.timestamp);
     DoLog(level, (const wchar_t*)msg.wc_str(), info.timestamp);
-#endif // WXWIN_COMPATIBILITY_2_8
-
-
-    // TODO: it would be better to extract message formatting in a separate
-    //       wxLogFormatter class but for now we hard code formatting here
-
-    wxString prefix;
-
-    // don't time stamp debug messages under MSW as debug viewers usually
-    // already have an option to do it
-#ifdef __WXMSW__
-    if ( level != wxLOG_Debug && level != wxLOG_Trace )
-#endif // __WXMSW__
-        TimeStamp(&prefix);
-
-    // TODO: use the other wxLogRecordInfo fields
-
-    switch ( level )
-    {
-        case wxLOG_Error:
-            prefix += _("Error: ");
-            break;
-
-        case wxLOG_Warning:
-            prefix += _("Warning: ");
-            break;
+#else // !WXWIN_COMPATIBILITY_2_8
+    wxUnusedVar(info);
+#endif // WXWIN_COMPATIBILITY_2_8/!WXWIN_COMPATIBILITY_2_8
 
-        // don't prepend "debug/trace" prefix under MSW as it goes to the debug
-        // window anyhow and so can't be confused with something else
-#ifndef __WXMSW__
-        case wxLOG_Debug:
-            // this prefix (as well as the one below) is intentionally not
-            // translated as nobody translates debug messages anyhow
-            prefix += "Debug: ";
-            break;
-
-        case wxLOG_Trace:
-            prefix += "Trace: ";
-            break;
-#endif // !__WXMSW__
-    }
-
-    DoLogTextAtLevel(level, prefix + msg);
+    // Use wxLogFormatter to format the message
+    DoLogTextAtLevel(level, m_formatter->Format (level, msg, info));
 }
 
 void wxLog::DoLogTextAtLevel(wxLogLevel level, const wxString& msg)
@@ -437,6 +503,25 @@ void wxLog::DoLog(wxLogLevel WXUNUSED(level), const wchar_t *wzString, time_t t)
 // ----------------------------------------------------------------------------
 
 wxLog *wxLog::GetActiveTarget()
+{
+#if wxUSE_THREADS
+    if ( !wxThread::IsMain() )
+    {
+        // check if we have a thread-specific log target
+        wxLog * const logger = wxThreadInfo.logger;
+
+        // the code below should be only executed for the main thread as
+        // CreateLogTarget() is not meant for auto-creating log targets for
+        // worker threads so skip it in any case
+        return logger ? logger : ms_pLogger;
+    }
+#endif // wxUSE_THREADS
+
+    return GetMainThreadActiveTarget();
+}
+
+/* static */
+wxLog *wxLog::GetMainThreadActiveTarget()
 {
     if ( ms_bAutoCreate && ms_pLogger == NULL ) {
         // prevent infinite recursion if someone calls wxLogXXX() from
@@ -449,7 +534,7 @@ wxLog *wxLog::GetActiveTarget()
             if ( wxTheApp != NULL )
                 ms_pLogger = wxTheApp->GetTraits()->CreateLogTarget();
             else
-                ms_pLogger = new wxLogStderr;
+                ms_pLogger = new wxLogOutputBest;
 
             s_bInGetActiveTarget = false;
 
@@ -474,6 +559,22 @@ wxLog *wxLog::SetActiveTarget(wxLog *pLogger)
     return pOldLogger;
 }
 
+#if wxUSE_THREADS
+/* static */
+wxLog *wxLog::SetThreadActiveTarget(wxLog *logger)
+{
+    wxASSERT_MSG( !wxThread::IsMain(), "use SetActiveTarget() for main thread" );
+
+    wxLog * const oldLogger = wxThreadInfo.logger;
+    if ( oldLogger )
+        oldLogger->Flush();
+
+    wxThreadInfo.logger = logger;
+
+    return oldLogger;
+}
+#endif // wxUSE_THREADS
+
 void wxLog::DontCreateOnDemand()
 {
     ms_bAutoCreate = false;
@@ -504,7 +605,7 @@ void wxLog::SetComponentLevel(const wxString& component, wxLogLevel level)
     {
         wxCRIT_SECT_LOCKER(lock, GetLevelsCS());
 
-        gs_componentLevels[component] = level;
+        GetComponentLevels()[component] = level;
     }
 }
 
@@ -513,11 +614,12 @@ wxLogLevel wxLog::GetComponentLevel(wxString component)
 {
     wxCRIT_SECT_LOCKER(lock, GetLevelsCS());
 
+    const wxStringToNumHashMap& componentLevels = GetComponentLevels();
     while ( !component.empty() )
     {
         wxStringToNumHashMap::const_iterator
-            it = gs_componentLevels.find(component);
-        if ( it != gs_componentLevels.end() )
+            it = componentLevels.find(component);
+        if ( it != componentLevels.end() )
             return static_cast<wxLogLevel>(it->second);
 
         component = component.BeforeLast('/');
@@ -530,36 +632,67 @@ wxLogLevel wxLog::GetComponentLevel(wxString component)
 // wxLog trace masks
 // ----------------------------------------------------------------------------
 
+namespace
+{
+
+// because IsAllowedTraceMask() may be called during static initialization
+// (this is not recommended but it may still happen, see #11592) we can't use a
+// simple static variable which might be not initialized itself just yet to
+// store the trace masks, but need this accessor function which will ensure
+// that the variable is always correctly initialized before being accessed
+//
+// notice that this doesn't make accessing it MT-safe, of course, you need to
+// serialize accesses to it using GetTraceMaskCS() for this
+wxArrayString& TraceMasks()
+{
+    static wxArrayString s_traceMasks;
+
+    return s_traceMasks;
+}
+
+} // anonymous namespace
+
+/* static */ const wxArrayString& wxLog::GetTraceMasks()
+{
+    // because of this function signature (it returns a reference, not the
+    // object), it is inherently MT-unsafe so there is no need to acquire the
+    // lock here anyhow
+
+    return TraceMasks();
+}
+
 void wxLog::AddTraceMask(const wxString& str)
 {
     wxCRIT_SECT_LOCKER(lock, GetTraceMaskCS());
 
-    ms_aTraceMasks.push_back(str);
+    TraceMasks().push_back(str);
 }
 
 void wxLog::RemoveTraceMask(const wxString& str)
 {
     wxCRIT_SECT_LOCKER(lock, GetTraceMaskCS());
 
-    int index = ms_aTraceMasks.Index(str);
+    int index = TraceMasks().Index(str);
     if ( index != wxNOT_FOUND )
-        ms_aTraceMasks.RemoveAt((size_t)index);
+        TraceMasks().RemoveAt((size_t)index);
 }
 
 void wxLog::ClearTraceMasks()
 {
     wxCRIT_SECT_LOCKER(lock, GetTraceMaskCS());
 
-    ms_aTraceMasks.Clear();
+    TraceMasks().Clear();
 }
 
 /*static*/ bool wxLog::IsAllowedTraceMask(const wxString& mask)
 {
     wxCRIT_SECT_LOCKER(lock, GetTraceMaskCS());
 
-    for ( wxArrayString::iterator it = ms_aTraceMasks.begin(),
-                                  en = ms_aTraceMasks.end();
-         it != en; ++it )
+    const wxArrayString& masks = GetTraceMasks();
+    for ( wxArrayString::const_iterator it = masks.begin(),
+                                        en = masks.end();
+          it != en;
+          ++it )
     {
         if ( *it == mask)
             return true;
@@ -572,31 +705,42 @@ void wxLog::ClearTraceMasks()
 // wxLog miscellaneous other methods
 // ----------------------------------------------------------------------------
 
+#if wxUSE_DATETIME
+
 void wxLog::TimeStamp(wxString *str)
 {
-#if wxUSE_DATETIME
     if ( !ms_timestamp.empty() )
     {
-        wxChar buf[256];
-        time_t timeNow;
-        (void)time(&timeNow);
-
-        struct tm tm;
-        wxStrftime(buf, WXSIZEOF(buf),
-                    ms_timestamp, wxLocaltime_r(&timeNow, &tm));
+        *str = wxDateTime::UNow().Format(ms_timestamp);
+        *str += wxS(": ");
+    }
+}
 
-        str->Empty();
-        *str << buf << wxS(": ");
+void wxLog::TimeStamp(wxString *str, time_t t)
+{
+    if ( !ms_timestamp.empty() )
+    {
+        *str = wxDateTime(t).Format(ms_timestamp);
+        *str += wxS(": ");
     }
-#endif // wxUSE_DATETIME
 }
 
-void wxLog::Flush()
+#else // !wxUSE_DATETIME
+
+void wxLog::TimeStamp(wxString*)
+{
+}
+
+void wxLog::TimeStamp(wxString*, time_t)
 {
+}
+
+#endif // wxUSE_DATETIME/!wxUSE_DATETIME
+
 #if wxUSE_THREADS
-    wxASSERT_MSG( wxThread::IsMain(),
-                  "should be called from the main thread only" );
 
+void wxLog::FlushThreadMessages()
+{
     // check if we have queued messages from other threads
     wxLogRecords bufferedLogRecords;
 
@@ -614,14 +758,58 @@ void wxLog::Flush()
               it != bufferedLogRecords.end();
               ++it )
         {
-            OnLogInMainThread(it->level, it->msg, it->info);
+            CallDoLogNow(it->level, it->msg, it->info);
         }
     }
+}
+
+/* static */
+bool wxLog::IsThreadLoggingEnabled()
+{
+    return !wxThreadInfo.loggingDisabled;
+}
+
+/* static */
+bool wxLog::EnableThreadLogging(bool enable)
+{
+    const bool wasEnabled = !wxThreadInfo.loggingDisabled;
+    wxThreadInfo.loggingDisabled = !enable;
+    return wasEnabled;
+}
+
 #endif // wxUSE_THREADS
 
+wxLogFormatter *wxLog::SetFormatter(wxLogFormatter* formatter)
+{
+    wxLogFormatter* formatterOld = m_formatter;
+    m_formatter = formatter ? formatter : new wxLogFormatter;
+
+    return formatterOld;
+}
+
+void wxLog::Flush()
+{
     LogLastRepeatIfNeeded();
 }
 
+/* static */
+void wxLog::FlushActive()
+{
+    if ( ms_suspendCount )
+        return;
+
+    wxLog * const log = GetActiveTarget();
+    if ( log )
+    {
+#if wxUSE_THREADS
+        if ( wxThread::IsMain() )
+            log->FlushThreadMessages();
+#endif // wxUSE_THREADS
+
+        log->Flush();
+    }
+}
+
 // ----------------------------------------------------------------------------
 // wxLogBuffer implementation
 // ----------------------------------------------------------------------------
@@ -719,7 +907,7 @@ wxLogChain::wxLogChain(wxLog *logger)
 
 wxLogChain::~wxLogChain()
 {
-    delete m_logOld;
+    wxLog::SetActiveTarget(m_logOld);
 
     if ( m_logNew != this )
         delete m_logNew;
@@ -752,8 +940,15 @@ void wxLogChain::DoLogRecord(wxLogLevel level,
         m_logOld->LogRecord(level, msg, info);
 
     // and also send it to the new one
-    if ( m_logNew && m_logNew != this )
-        m_logNew->LogRecord(level, msg, info);
+    if ( m_logNew )
+    {
+        // don't call m_logNew->LogRecord() to avoid infinite recursion when
+        // m_logNew is this object itself
+        if ( m_logNew != this )
+            m_logNew->LogRecord(level, msg, info);
+        else
+            wxLog::DoLogRecord(level, msg, info);
+    }
 }
 
 #ifdef __VISUALC__
@@ -809,8 +1004,6 @@ wxString        wxLog::ms_timestamp(wxS("%X"));  // time only, no date
 wxTraceMask     wxLog::ms_ulTraceMask  = (wxTraceMask)0;
 #endif // wxDEBUG_LEVEL
 
-wxArrayString   wxLog::ms_aTraceMasks;
-
 // ----------------------------------------------------------------------------
 // stdout error logging helper
 // ----------------------------------------------------------------------------
@@ -855,7 +1048,7 @@ static void wxLogWrap(FILE *f, const char *pszPrefix, const char *psz)
 // get error code from syste
 unsigned long wxSysErrorCode()
 {
-#if defined(__WXMSW__) && !defined(__WXMICROWIN__)
+#if defined(__WINDOWS__) && !defined(__WXMICROWIN__)
     return ::GetLastError();
 #else   //Unix
     return errno;
@@ -868,7 +1061,7 @@ const wxChar *wxSysErrorMsg(unsigned long nErrCode)
     if ( nErrCode == 0 )
         nErrCode = wxSysErrorCode();
 
-#if defined(__WXMSW__) && !defined(__WXMICROWIN__)
+#if defined(__WINDOWS__) && !defined(__WXMICROWIN__)
     static wxChar s_szBuf[1024];
 
     // get error message from system
@@ -916,7 +1109,7 @@ const wxChar *wxSysErrorMsg(unsigned long nErrCode)
     }
 
     return s_szBuf;
-#else // !__WXMSW__
+#else // !__WINDOWS__
     #if wxUSE_UNICODE
         static wchar_t s_wzBuf[1024];
         wxConvCurrent->MB2WC(s_wzBuf, strerror((int)nErrCode),
@@ -925,7 +1118,7 @@ const wxChar *wxSysErrorMsg(unsigned long nErrCode)
     #else
         return strerror((int)nErrCode);
     #endif
-#endif  // __WXMSW__/!__WXMSW__
+#endif  // __WINDOWS__/!__WINDOWS__
 }
 
 #endif // wxUSE_LOG