Logging different channels to different files

Hi Greg/all,

I would like to add a feature to the log system that allows multiple channels to write to a single file. This will be incredibly useful for correlating messages between channels. We can also add a log option for adding the channel name to each log line, which would allow filtering based on channel name.

Do you want to retain the ability to log different channels to separate files?

Sincerely,

Vince

Sorry, I must be missing something here. If you just specify the same file when you do "log enable -f /tmp/lldb-log.txt channel type" then they will all go to the same file. What are you adding?

Jim

I’ve never wanted to send different logs to different files.

Sean

I’ve never tried logging to the same file because I stepped through the code and (IIRC) different “log enable” commands to the same file path open separate file descriptors without the append flag, so I expected that they would stomp on each other. Maybe I misunderstood. I’ll try it now.

To tell the truth, I've never looked at the implementation of this too closely, but it does seem to work. You have to use the -t option if you are going to do any complex logging since you will probably get multiple threads logging simultaneously.

Jim

My experience was the same; using the same file for different log
channels resulted in an inconsistent set of log entries in the file.

Okay, I don’t know what I was thinking.

Debugger.cpp:1317
It’s re-using an existing stream if the filename is identical.

The stomping that Ed is seeing might be solvable by using the -t flag as Jim suggests.

Possibly - I only looked into this when I was first getting started
with LLDB and enabled a large set of log channels to try to understand
how everything worked. I distinctly recall that log entries were
completely missing though, not just "interweaved" as the help for -t
suggests.

Ah, this seems a bit bizarre:

    if (log_options == 0)
        log_options = LLDB_LOG_OPTION_PREPEND_THREAD_NAME |
LLDB_LOG_OPTION_THREADSAFE;

so by default we get the thread name and threadsafe logging, but if
any options are set then they are not automatically set.

Oh, but I don't see anywhere LLDB_LOG_OPTION_THREADSAFE is checked.

void
Log::VAPrintf(const char *format, va_list args)
{
// Make a copy of our stream shared pointer in case someone disables our
// log while we are logging and releases the stream
StreamSP stream_sp(m_stream_sp);
if (stream_sp)
{
static uint32_t g_sequence_id = 0;
StreamString header;
// Enabling the thread safe logging actually deadlocks right now.
// Need to fix this at some point.
// static Mutex g_LogThreadedMutex(Mutex::eMutexTypeRecursive);
// Mutex::Locker locker (g_LogThreadedMutex);

Incidentally doing a git blame and looking at the commit, it appears totally unrelated to logging (it was just something that snuck into a large unrelated change), so it’s hard to know what the actual deadlock was, or if it’s still an issue. The code was commented out about 4 years ago, so there’s a good chance it’s not still a problem.

It must be due to a deadlock during a signal handler. That is the only way this can deadlock. We can also localize the mutex locker solely around one "stream_sp->Write()" call and have everything go into the local "StreamString header" stream first and then have a:

static Mutex g_LogThreadedMutex(Mutex::eMutexTypeRecursive);

// Scope for locker
{
    Mutex::Locker locker (g_LogThreadedMutex);
    stream_sp->Write(header.GetString().data(), header.GetString().size());
}

We just need to avoid writing anything directly into "stream_sp" except for the above stream_sp->Write() call and we can reduce the