Voting: std.logger

Thu Sep 18 22:33:36 PDT 2014

Am Tue, 16 Sep 2014 21:22:36 +0000
schrieb "Robert burner Schadek" <rburners at gmail.com>:

> On Wednesday, 10 September 2014 at 16:54:14 UTC, Dicebot wrote:
> 
> so the current version has one template args log functions that 
> take __LINE__ and friends as normal parameter.
> 
> I think that was the last complaint, please correct me if I'm 
> wrong.

WAT?

> So next round?

Hell no!

Am Mon, 15 Sep 2014 22:33:45 +0000
schrieb "Robert burner Schadek" <rburners at gmail.com>:

> again, the idea of std.logger is not to give you everything, 
> because nobody knows what that even is, the idea is to make it 
> possible to do everything and have it understandable later and 
> use transparently

I understand that part Robert, and already made use of that
flexibility. But you use this to play down any concerns about
the thread safety of the infrastructure you wrote and finally
get std.logger accepted and merged.

> the threading behavior has been clarified in the api docs.

You can't just clarify it in the docs.
It requires actual code to work both ways.

> the (a)synchronicity guarantees is part of the concrete Logger 
> impl. the Logger api does not force synchronize or asynchronize 
> behavior, it allows both to be implemented by every subclass of 
> Logger.

All access to global state has to be synchronized before we
can safely do so, and std.logger doesn't even attempt to in its
current state! Some examples:

SITUATION:

isLoggingEnabled(LogLevel ll, LogLevel loggerLL, LogLevel
                 globalLL, lazy bool condition)
{
	…
	return ll >= globalLL
	    && ll >= loggerLL
	    && globalLL != LogLevel.off
	    && loggerLL != LogLevel.off
	    && condition
}

@property LogLevel globalLogLevel() @trusted @nogc
{
	return globalLogLevelImpl();
}

private ref LogLevel globalLogLevelImpl() @trusted @nogc
{
	static __gshared LogLevel ll = LogLevel.all;
	return ll;
}

is called like this:

isLoggingEnabled(stdlog.logLevel, stdlog.logLevel,
globalLogLevel,
                 condition);

Inside `isLoggingEnabled`, we can expect condition to be
evaluated in the context of the calling thread, but the three
log level variables passed in create a race condition.
Imagine another thread sets `stdlog.logLevel` from warning to
error during a logging call. Inside `isLoggingEnabled` you'd
now get:

	return LogLevel.warning >= globalLL
	    && LogLevel.warning >= LogLevel.error
	    && globalLL != LogLevel.off
	    && loggerLL != LogLevel.off
	    && condition

This will unconditionally return false of course. The `stdlog`
is now at log level warning AND error at the same time. WAT?

EFFECT:

Every blue moon a log message will be swallowed by std.logger.

SITUATION:

private Mutex __stdloggermutex;

static this() {
	__stdloggermutex = new Mutex;
}

@property ref Logger stdlog() @trusted
{
	static __gshared bool once;
	static __gshared Logger logger;
	static __gshared ubyte[__traits(classInstanceSize,
FileLogger)] buffer;

	__stdloggermutex.lock();
	scope(exit) __stdloggermutex.unlock();
	if (!once)
	{
		once = true;
		logger = emplace!FileLogger(buffer, stderr,
globalLogLevel()); }
	return logger;
}

Every thread will now create its own thread local mutex to
protect access to global state.

EFFECT:

** This protects exactly nothing. **

Write instead:

__gshared private Mutex __stdloggermutex;

shared static this() {
	__stdloggermutex = new Mutex;
}

If you need help with multi-threading please ask either here or
on IRC. I have found that we have some people in the community
that can explain even the fine details of atomic fences.

SITUATION:

We set the global log level through `globalLogLevel`:

@property void globalLogLevel(LogLevel ll) @trusted
{
	if (stdlog !is null)
	{
		stdlog.logLevel = ll;
	}
	globalLogLevelImpl = ll;
}

What you tried here, was to set the global log level in case
we don't have `stdlog` initialized already, because during its
creation it will pick up the global log level.
Now `globalLogLevelImpl = ll;` will never be executed, because
inside the `stdlog` property function, it is initialized and
thus `stdlog !is null` will always be true.
Unless the user sets `stdlog` to null, which I assume is
invalid, since it creates fuzzy semantics: The first time
`stdlog` is encountered to be null it is set to a FileLogger,
any other time it stays null.

EFFECT:

There is no synchronization around the access to the stdlog.
D as far as I know doesn't require that machine word
reads/writes are atomic, so in theory you could get a
`stdlog` where one half is an old value and the other a new
one. That won't happen on ARM and x86, but I thought I'd
mention. Much more importantly though another thread could
change `stdlog` between `stdlog !is null` and
`stdlog.logLevel = ll;`. Assuming you want to protect all
of the global state with `__stdloggermutex`:

@property void globalLogLevel(LogLevel ll) @trusted
{
	synchronized(__stdloggermutex)
	{
		// TODO: stdlog will always initialize itself.
		//       So remove the check?
		if (stdlog !is null)
		{
			stdlog.logLevel = ll;
		}
		globalLogLevelImpl = ll;
	}
}

SITUATION:

There are 12(!) log methods in the Logger class that
call `beginLogMsg` and `finishLogMsg`, which are not
thread-safe.
We could either override all 12 log methods, which have a
complex signature and a lot of boiler plate code or just
those two plus `logMsgPart`. The implementations would look
very similar if all they want to be is thread safe:

protected void beginLogMsg(string file, int line, string
                           funcName, string prettyFuncName,
                           string moduleName, LogLevel
                           logLevel, Tid threadId, SysTime
                           timestamp, Logger logger) @trusted
{
	// Don't lock anything if we statically disabled logs
	static if (isLoggingActive())
	{
		// no 2nd thread may begin logging
		this.mutex.lock();
		// something may go wrong in super's method
		scope (failure) this.mutex.unlock();

		super.beginLogMsg(file, line, funcName,
		                  prettyFuncName, moduleName,
		                  logLevel, threadId,
		                  timestamp, logger);
	}
}

protected void logMsgPart(const(char)[] msg)
{
	// don't mess with the mutex outside of enabled logging
	static if (isLoggingActive())
        {
		// something may go wrong in super's method
		scope (failure) this.mutex.unlock();
		super.logMsgPart(msg);
	}
}

protected void finishLogMsg()
{
	// don't mess with the mutex outside of enabled logging
	static if (isLoggingActive())
	{
		// in any case unlock the mutex afterwards
		scope (exit) this.mutex.unlock();
		super.finishLogMsg()
	}
}

EFFECT:

The above is a minimum requirement to make Logger thread
safe and I think it is easy to forget a static-if or the
conditions under which to unlock the mutex. It would be nicer
if std.logger was already thread safe to begin with, because
it is today common to deal with more than one thread.

Also the implementation above has two issues:
1) It cannot be used as a base class, because as an
   implementation detail it already encapsulates the use of
   `Appender` which will use the GC.
2) I think it is bad to split up locking and unlocking a mutex
   over the course of three methods if it is avoidable.

So my conclusion is to be able to have a reusable thread safe
Logger, which doesn't depend on the GC, it is necessary to
pull the thread safety code one level up into the 12 log
methods.

HINT: Since the 3 methods are protected, it might be
  an idea to also move the static-if outside of them, so they
  wont get compiled in at all when logging is statically
  disabled. That's sort of DRY and will force any call to them
  to also be statically checked for
  `static if (isLoggingEnabled())`.)

HINT: Maybe the abstract base class should not contain
  `protected Appender!string msgAppender;` ?

SITUATION:

abstract class Logger
{
	…
	void delegate() fatalHandler;
}

EFFECT:

Since a delegate consists of two pointers, it will always be
set in two memory operations, no matter the architecture.
If it is called in one thread while being set in another, it
can have a context that doesn't match the function pointer.
E.g. you might be calling car.explode(); instead of
string.explode();

This is not guaranteed to be a complete list of the issues,
but you get the idea. Even if the likelihood of some things I
mentioned that could happen is small, they are still errors
in the design. And since I am very pedantic about thread
safety and want to see these addressed.
The other thing is that since you didn't put thought into how
std.logger will work in a multi-threaded environment, it is
likely the API doesn't make it particularly easy to build on.
(See above for suggestions to move thread safety up one level).

Also I'm still missing a statement on recursion. How does
std.logger deal with e.g. error/warning/... recursively
calling itself?

P.S.: This was my most thorough review of any Phobos code yet.
I guess that means that I'm actually interested in it and feel
that it is sorely missing! So thank you for designing this.
It is a nice and simple single-threaded standard logging
framework aside from the threading issues.

-- 
Marco