Voting: std.logger (page 20)

On 09/10/2014 06:54 PM, Dicebot wrote:
> On Wednesday, 10 September 2014 at 16:34:06 UTC, Andrei Alexandrescu wrote:
>> One possibility is to have the first function be a one-liner that
>> forwards to another. That way there will be less code bloating.
>>
>> void fun(uint l = __LINE__, A...)(A... as) {
>>   funImpl(l, as);
>> }
>>
>> private void funImpl(A...)(uint line, A...) {
>>   ... bulk of the code goes here ...
>> }
>
> Those are already small functions AFAIK (I was speaking about symbol
> bloat, not code bloat). It does not help with compilation issue though -
> each logging call creates a totally new template instance which means
> allocating new object for DMD internal representation and running
> semantic phase for it. And mature applications can have thousands of
> logging calls. I have yet to run tests to see actual impact but it
> concerns me from the pure DMD internals point of view.

Another possibility would be to fix this bug, but the mechanism isn't particularly elegant nor efficient:
https://issues.dlang.org/show_bug.cgi?id=13455 :o)

September 19, 2014

Re: Voting: std.logger

Posted by Marco Leise
in reply to Robert burner Schadek

Permalink

Marco Leise

Posted in reply to Robert burner Schadek

Permalink

Am Tue, 16 Sep 2014 21:22:36 +0000
schrieb "Robert burner Schadek" <rburners@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@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

Forums