Author Topic: flush on every log messages  (Read 6540 times)

Offline ollydbg

  • Developer
  • Lives here!
  • *****
  • Posts: 5242
  • OpenCV and Robotics
    • Chinese OpenCV forum moderator
flush on every log messages
« on: June 13, 2014, 03:38:53 pm »
When debugging CC, I try to enable all the TRACE() macros. Also, I have pass the "--debug-log-to-file" on the C::B startup options. When C::B hit a BP, I try to see the file "codeblocks-debug.log", it contains some partial logs, not the full logs.

I dig it further, and found that
Code: [Select]
/** a logger which prints messages to a file */
class DLLIMPORT FileLogger : public Logger
{
protected:
    wxFFile f;
public:
    FileLogger(const wxString& filename) : f(filename, _T("wb")) {};
    FileLogger() {};

    virtual void Append(const wxString& msg, cb_unused Logger::level lv)
    {
        fputs(wxSafeConvertWX2MB(msg), f.fp());
        fputs(::newline_string.mb_str(), f.fp());
    };

    virtual void Open(const wxString& filename) { Close(); f.Open(filename, _T("wb")); };
    virtual void Close(){ if(f.IsOpened()) f.Close(); };
};

Look, it use the standard C function to output, but once a message is append to the log file, it does not call "flush()" function.

I noticed that Morten use some similar method to enforce the flush in cclogger.cpp, (he just call f.Close() to ensure the flush of log message), see:
Code: [Select]
#define TRACE_TO_FILE(msg)                                           \
    if (g_EnableDebugTraceFile && !g_DebugTraceFile.IsEmpty())       \
    {                                                                \
        wxTextFile f(g_DebugTraceFile);                              \
        if ((f.Exists() && f.Open()) || (!f.Exists() && f.Create())) \
        {                                                            \
            f.AddLine(msg);                                          \
            cbAssert(f.Write() && f.Close());                        \
        }                                                            \
    }                                                                \

#define TRACE_THIS_TO_FILE(msg)                                      \
    if (!g_DebugTraceFile.IsEmpty())                                 \
    {                                                                \
        wxTextFile f(g_DebugTraceFile);                              \
        if ((f.Exists() && f.Open()) || (!f.Exists() && f.Create())) \
        {                                                            \
            f.AddLine(msg);                                          \
            cbAssert(f.Write() && f.Close());                        \
        }                                                            \
    }  

For those who need to do real-time logging, flush() is needed, otherwise if C::B crashes/breaks, you only get some partial logs in codeblocks-debug.log file.

EDIT:
Even wx internally use buffer for logging, see: http://docs.wxwidgets.org/trunk/overview_log.html
Quote
Starting with wxWidgets 2.9.1, logging functions can be safely called from any thread. Messages logged from threads other than the main one will be buffered until wxLog::Flush() is called in the main thread (which usually happens during idle time, i.e. after processing all pending events) and will be really output only then. Notice that the default GUI logger already only output the messages when it is flushed, so by default messages from the other threads will be shown more or less at the same moment as usual. However if you define a custom log target, messages may be logged out of order, e.g. messages from the main thread with later timestamp may appear before messages with earlier timestamp logged from other threads. wxLog does however guarantee that messages logged by each thread will appear in order in which they were logged.

Also notice that wxLog::EnableLogging() and wxLogNull class which uses it only affect the current thread, i.e. logging messages may still be generated by the other threads after a call to EnableLogging(false).
« Last Edit: June 13, 2014, 03:41:37 pm by ollydbg »
If some piece of memory should be reused, turn them to variables (or const variables).
If some piece of operations should be reused, turn them to functions.
If they happened together, then turn them to classes.

Offline ollydbg

  • Developer
  • Lives here!
  • *****
  • Posts: 5242
  • OpenCV and Robotics
    • Chinese OpenCV forum moderator
Re: flush on every log messages
« Reply #1 on: June 14, 2014, 07:38:10 am »
Hi, the nice feature in the GDB is that it can run the inferior call, so when I hit a breakpoint in GDB, I can call debugee(inferior)'s fflush(0) function, which can let the debugee do a flush on all files. See: debugging - How to tell GDB to flush the stdio of the program being debugged - Stack Overflow
It works fine at least under WinXP + MinGW + GDB.  :)
If some piece of memory should be reused, turn them to variables (or const variables).
If some piece of operations should be reused, turn them to functions.
If they happened together, then turn them to classes.

Offline ollydbg

  • Developer
  • Lives here!
  • *****
  • Posts: 5242
  • OpenCV and Robotics
    • Chinese OpenCV forum moderator
Re: flush on every log messages
« Reply #2 on: June 17, 2014, 03:52:12 pm »
Here comes a question, is our Filelogger thread safe?
I just try to understand that whether fputs can be called from multiply thread in the same time.
I don't know, but on post in Stackoverflow has different answers: c - Is fwrite atomic? - Stack Overflow.

EDIT:
From fwrite, it looks like it is thread safe.
Quote
Because this function locks the calling thread, it is thread-safe. For a non-locking version, see _fwrite_nolock.
« Last Edit: June 17, 2014, 03:55:45 pm by ollydbg »
If some piece of memory should be reused, turn them to variables (or const variables).
If some piece of operations should be reused, turn them to functions.
If they happened together, then turn them to classes.

Offline oBFusCATed

  • Developer
  • Lives here!
  • *****
  • Posts: 12828
    • Travis build status
Re: flush on every log messages
« Reply #3 on: June 17, 2014, 08:52:04 pm »
Don't look at specific documentation from a vendor that is know to not follow standards or doing things in advance.

http://www.cplusplus.com/reference/cstdio/fwrite/ this is a better page and there is no mentioning of thread safety.

Why would you want to log something from multiple threads?
(most of the time I ignore long posts)
[strangers don't send me private messages, I'll ignore them; post a topic in the forum, but first read the rules!]

Offline ollydbg

  • Developer
  • Lives here!
  • *****
  • Posts: 5242
  • OpenCV and Robotics
    • Chinese OpenCV forum moderator
Re: flush on every log messages
« Reply #4 on: June 18, 2014, 08:13:15 am »
Don't look at specific documentation from a vendor that is know to not follow standards or doing things in advance.

http://www.cplusplus.com/reference/cstdio/fwrite/ this is a better page and there is no mentioning of thread safety.

Why would you want to log something from multiple threads?
OK. When debugging CodeCompletion, some log messages come from worker thread, some come from main GUI.

To show the logs, I have to use "--debug-log-to-file" (show the logs in "Code::Blocks Debug" panel is not an option, because some times CC just crashes, also if I'm debugging C::B, I can see the "Code::Blocks debug" panel if the debugee halt"), when I hit a BP in GDB, I want to see all the log messages before I hit the BP.

Our SDK supply a FileLogger to do the logging, so I can replace all the TRACE macro in CC to "Manager::Get()->GetLogManager()->DebugLog(msg)", which will call FileLogger::Append(), so that TRACEs are go to codeblocks-debug.log now. Since FileLogger use fputs(), I need to know whether it is thread safe. If not, I need to add  a locker to wrapper all the TRACE in CC.
If some piece of memory should be reused, turn them to variables (or const variables).
If some piece of operations should be reused, turn them to functions.
If they happened together, then turn them to classes.