ConnectionPool broken with async logger

[tchaloupka]

When vibe-core is used with asynchronnous logger (ie using async DB driver to log) it can broke at least in ConnectionPool.

Here is a little sample to reproduce it:

import std.stdio;

import core.time;
import std.datetime.systime;
import std.random;
import vibe.core.connectionpool;
import vibe.core.core;
import vibe.core.log;
import vibe.http.common;
import vibe.http.client;
import vibe.stream.operations;

@safe final class YieldLogger : Logger {
	override void beginLine(ref LogLine msg) {}
	override void put(scope const(char)[] text) {}
	override void endLine() { yield; }
}

final class TestConnection {
	bool isWorking;
	void doWork() {
		assert(!isWorking, "Oops, connection already in use!");
		isWorking = true;
		scope (exit) isWorking = false;
		sleep(uniform(0,200).msecs);
	}
}

void main() {
	auto logger = cast(shared)new YieldLogger();
	registerLogger(logger);

	auto pool = new ConnectionPool!TestConnection({
		return new TestConnection();
	});

	foreach (i; 0..10) {
		runTask((int i) {
			logDiagnostic("Starting %s", i);
			scope (exit) logDiagnostic("Terminating %s", i);
			while (true)
			{
				auto c = pool.lockConnection;
				c.doWork();
				sleep(uniform(0,10).msecs);
			}
		}, i);
	}

	runApplication();
}

Problem is here: https://github.com/vibe-d/vibe-core/blob/master/source/vibe/core/connectionpool.d#L90

When logger causes switch to another fiber, new one can access same connection pool and as the first fiber hasn't marked selected connection yet, it is selected again in other fiber and oops, we got 2 fibers using the same connection.

It should be easy to fix this concrete case by some code reordering, but I'm really afraid of what other places this can silently and randomly break. To be safe, one should probably use only sync loggers - but that's unfortunate.

Any other idea?

Can be maybe related with https://github.com/vibe-d/vibe.d/issues/2367 as it seems to be also related to logger (and should probably be moved to vibe-core issue list too).

[s-ludwig]

A logger that yields is extremely dangerous, as there are logging calls all over the place, also in low-level code. I'll add a yieldLock in doLog to make sure such cases are detected.

Any logger which does this kind of I/O should use a separate writer thread together with a queue and ordinary blocking synchronization primitives. I didn't really realize it at the time, but SyslogLogger of course also falls into this category.

[tchaloupka]

Yeah I figured ;-) So this should probably be fixed with:

• fix the SyslogLogger to use "sync queue" approach
• warning in the Logger docs for custom loggers that they can't be async during the log operation and mention SyslogLogger as an example how it works