Assertion when concurrently using multiple LockedConnection

[CromFr]

When using a MySQLPool locked connection concurrently using Vibed HTTP server (using the following code), I randomly end up with an assertion in mysql-native/source/mysql/protocol/sockets.d:

Code:

import vibe.vibe;
import mysql;

MySQLPool connPool;

void main()
{
	connPool = new MySQLPool("host=localhost;port=3306;user=yourname;pwd=pass123;db=mysqln_testdb");

	auto settings = new HTTPServerSettings;
	settings.port = 8080;
	settings.bindAddresses = ["::1", "127.0.0.1"];

	auto router = new URLRouter;
	router.registerWebInterface(new WebInterface);

	listenHTTP(settings, router);

	logInfo("Please open http://127.0.0.1:8080/ in your browser.");
	runApplication();
}


class WebInterface {

	void index(HTTPServerResponse res)
	{
		auto conn = connPool.lockConnection();

		auto queryRes = conn.query("SELECT SLEEP(1)");
		queryRes.close();

		res.writeJsonBody("Success !");
	}
}

Full repo ready to compile: test-connpool.tar.gz

Result:
When stressed using simply curl 127.0.0.1:8080 &; curl 127.0.0.1:8080 & few times, it produces the following assertion:

core.exception.AssertError@../../.dub/packages/mysql-native-2.2.0/mysql-native/source/mysql/protocol/sockets.d(121): Assertion failure
----------------
??:? _d_assertp [0xd482e4bd]
??:? const void mysql.protocol.sockets.MySQLSocketVibeD.__invariant7() [0xd4601fc9]
??:? const void mysql.protocol.sockets.MySQLSocketVibeD.__invariant() [0xd4602180]
??:? const @property bool mysql.protocol.sockets.MySQLSocketVibeD.connected() [0xd4602010]
??:? void mysql.connection.Connection.kill() [0xd45f8f16]
??:? bool mysql.protocol.comms.execQueryImpl(mysql.connection.Connection, mysql.protocol.comms.ExecQueryImplInfo, out ulong) [0xd45fcd75]
??:? mysql.result.ResultRange mysql.commands.queryImpl(mysql.commands.ColumnSpecialization[], mysql.connection.Connection, mysql.protocol.comms.ExecQueryImplInfo) [0xd45f81da]
??:? mysql.result.ResultRange mysql.commands.query(mysql.connection.Connection, const(char[]), mysql.commands.ColumnSpecialization[]) [0xd45f815d]
??:? void app.WebInterface.index(vibe.http.server.HTTPServerResponse) [0xd45dd202]
... continues over vibed http stack

I honestly don't know why this happens, wether if it's

• bad mysql-native usage
• related to vibed 0.8.3
• related to dmd v2.079.0

[bausshf]

Don't call queryRes.close(); (I don't know if that's related.)

[CromFr]

I tried removing it, but it didn't solve the issue.

I noticed noticed that the assert always occurs when launching the double curl command the second time. I suspect something goes wrong when destroying/cleaning LockedConnections that have been used concurrently.

[Abscissa]

First, thanks for the excellent test case. That's a huge help.

Your code looks correct to me, so I did a little digging. So far, it looks like there's two parts to the problem here:

The immediate failure, the AssertError your getting, is from an invariant contract check in mysql-native. But the check itself (assert(!!socket)) seems to be going wrong somehow. I think it was intended to ensure the socket isn't null, but...well, something seems to be very weird there, as if it opened a portal to Alice's Wonderland or something...Still digging on that.

But, that AssertError is only a secondary failure. It's just an additional problem that's triggered while the stack is already unwinding from a different failure. If I remove that assert, the original problem is shown:

core.exception.AssertError@../../../.dub/packages/eventcore-0.8.29/eventcore/source/eventcore/drivers/posix/driver.d(243): Overwriting notification callback.
----------------
??:? _d_assert_msg [0x4cbb24ba]
??:? nothrow @nogc @safe void eventcore.drivers.posix.driver.PosixEventLoop.setNotifyCallback!(0).setNotifyCallback(eventcore.driver.Handle!("fd", ulong, -1uL).Handle, void delegate(eventcore.driver.Handle!("fd", ulong, -1uL).Handle) nothrow @safe) [0x4cb85b15]
??:? _D9eventcore7drivers5posix7sockets__T23PosixEventDriverSocketsHTCQClQCeQBz5epoll14EpollEventLoopZQCi4readMFNbNfSQEg6driver__T6HandleVAyaa12_73747265616d536f636b6574TSQGiQCc__TQByVQBua6_736f636b6574TSQHpQDj__TQDfVQDba2_6664TmVmN1ZQEaVQBjS1N1ZQEmVQDcS1S1N1ZQFaAhEQJzQFt6IOModeDFNbNfQGnEQKwQGq8IOStatusmZvZv [0x4cb73e01]
??:? _D4vibe4core3net13TCPConnection11waitForDataMFNfSQBq4time8DurationZ__T9__lambda2TDFNbNfS9eventcore6driver__T6HandleVAyaa12_73747265616d536f636b6574TSQCjQCc__TQByVQBua6_736f636b6574TSQDqQDj__TQDfVQDba2_6664TmVmN1ZQEaVQBjS1N1ZQEmVQDcS1S1N1ZQFaEQFyQFr8IOStatusmZvZQHjMFNbNfQHhZv [0x4cb679ae]
??:? _D4vibe8internal5async__T13asyncAwaitAnyVbi1SQBrQBpQBj__T8WaitableTDFNbNfS9eventcore6driver__T6HandleVAyaa12_73747265616d536f636b6574TSQCjQCc__TQByVQBua6_736f636b6574TSQDqQDj__TQDfVQDba2_6664TmVmN1ZQEaVQBjS1N1ZQEmVQDcS1S1N1ZQFaEQFyQFr8IOStatusmZvSQJl4core3net13TCPConnection11waitForDataMFNfSQBq4time8DurationZ9__lambda2SQMhQCwQCuQCtQChMFNfQBxZ9__lambda3SQNpQEeQEcQEbQDpMFNfQDfZ9__lambda4ZZQObMFNfQLjZv [0x4cb3913d]
??:? _D4vibe8internal5async__T13asyncAwaitAnyVbi1SQBrQBpQBj__T8WaitableTDFNbNfS9eventcore6driver__T6HandleVAyaa12_73747265616d536f636b6574TSQCjQCc__TQByVQBua6_736f636b6574TSQDqQDj__TQDfVQDba2_6664TmVmN1ZQEaVQBjS1N1ZQEmVQDcS1S1N1ZQFaEQFyQFr8IOStatusmZvSQJl4core3net13TCPConnection11waitForDataMFNfSQBq4time8DurationZ9__lambda2SQMhQCwQCuQCtQChMFNfQBxZ9__lambda3SQNpQEeQEcQEbQDpMFNfQDfZ9__lambda4ZZQObMFNfQEcQLmZv [0x4cb38fbd]
??:? @safe bool vibe.core.net.TCPConnection.waitForData(core.time.Duration) [0x4cb3804d]
??:? @safe bool vibe.core.net.TCPConnection.read(scope ubyte[], eventcore.driver.IOMode).__lambda3!(core.time.Duration).__lambda3(core.time.Duration) [0x4cb397b9]
??:? @safe void vibe.core.net.loopWithTimeout!(vibe.core.net.TCPConnection.read(scope ubyte[], eventcore.driver.IOMode).__lambda3, Exception).loopWithTimeout(core.time.Duration) [0x4cb3965e]
??:? @safe ulong vibe.core.net.TCPConnection.read(scope ubyte[], eventcore.driver.IOMode) [0x4cb3825a]
??:? @safe void vibe.core.net.TCPConnection.read(scope ubyte[]) [0x4cb38298]
??:? void mysql.protocol.sockets.MySQLSocketVibeD.read(ubyte[]) [0x4c985228]
??:? ubyte[] mysql.protocol.comms.getPacket(mysql.connection.Connection) [0x4c98013e]
??:? bool mysql.protocol.comms.execQueryImpl(mysql.connection.Connection, mysql.protocol.comms.ExecQueryImplInfo, out ulong) [0x4c97fdaa]
??:? mysql.result.ResultRange mysql.commands.queryImpl(mysql.commands.ColumnSpecialization[], mysql.connection.Connection, mysql.protocol.comms.ExecQueryImplInfo) [0x4c97b46a]
??:? mysql.result.ResultRange mysql.commands.query(mysql.connection.Connection, const(char[]), mysql.commands.ColumnSpecialization[]) [0x4c97b3ed]
??:? void app.WebInterface.index(vibe.http.server.HTTPServerResponse) [0x4c960492]
??:? void vibe.web.web.handleRequest!("index", app.WebInterface.index(vibe.http.server.HTTPServerResponse), app.WebInterface).handleRequest(vibe.http.server.HTTPServerRequest, vibe.http.server.HTTPServerResponse, app.WebInterface, vibe.web.web.WebInterfaceSettings) [0x4c96b111]
??:? @trusted void vibe.web.web.registerWebInterface!(app.WebInterface, 5).registerWebInterface(vibe.http.router.URLRouter, app.WebInterface, vibe.web.web.WebInterfaceSettings).__lambda4(vibe.http.server.HTTPServerRequest, vibe.http.server.HTTPServerResponse) [0x4c96a608]
??:? @safe bool vibe.http.router.URLRouter.handleRequest(vibe.http.server.HTTPServerRequest, vibe.http.server.HTTPServerResponse).__lambda4!(ulong, immutable(char)[][]).__lambda4(ulong, scope immutable(char)[][]) [0x4ca4a4a7]
??:? const @safe bool vibe.http.router.MatchTree!(vibe.http.router.Route).MatchTree.doMatch(immutable(char)[], scope bool delegate(ulong, scope immutable(char)[][]) @safe) [0x4ca4cbd5]
??:? @safe bool vibe.http.router.MatchTree!(vibe.http.router.Route).MatchTree.match(immutable(char)[], scope bool delegate(ulong, scope immutable(char)[][]) @safe) [0x4ca4c4d7]
??:? @safe void vibe.http.router.URLRouter.handleRequest(vibe.http.server.HTTPServerRequest, vibe.http.server.HTTPServerResponse) [0x4ca4a168]
??:? @safe bool vibe.http.server.handleRequest(vibe.internal.interfaceproxy.InterfaceProxy!(vibe.core.stream.Stream).InterfaceProxy, vibe.core.net.TCPConnection, vibe.http.server.HTTPServerContext, ref vibe.http.server.HTTPServerSettings, ref bool, scope stdx.allocator.IAllocator) [0x4cad024d]
??:? @trusted void vibe.http.server.handleHTTPConnection(vibe.core.net.TCPConnection, vibe.http.server.HTTPServerContext).__lambda3() [0x4cace7d0]
??:? @safe void vibe.http.server.handleHTTPConnection(vibe.core.net.TCPConnection, vibe.http.server.HTTPServerContext) [0x4cace57b]
??:? nothrow @safe void vibe.http.server.listenHTTPPlain(vibe.http.server.HTTPServerSettings, void delegate(vibe.http.server.HTTPServerRequest, vibe.http.server.HTTPServerResponse) @safe).doListen(vibe.http.server.HTTPServerContext, bool, bool).__lambda4(vibe.core.net.TCPConnection) [0x4ca56771]
??:? void vibe.core.task.TaskFuncInfo.set!(void delegate(vibe.core.net.TCPConnection) @safe, vibe.core.net.TCPConnection).set(ref void delegate(vibe.core.net.TCPConnection) @safe, ref vibe.core.net.TCPConnection).callDelegate(ref vibe.core.task.TaskFuncInfo) [0x4cb69a64]
??:? void vibe.core.task.TaskFuncInfo.call() [0x4cb4b3d9]
??:? nothrow void vibe.core.task.TaskFiber.run() [0x4cb4a9e1]
??:? void core.thread.Fiber.run() [0x4cc041c3]
??:? fiber_entryPoint [0x4cc04092]
??:? [0xffffffff]
Program exited with code -6

Appears to be something going wrong in vibe-d/eventcore (maybe due to something mysql-native is doing?). I will file a ticket there and hopefully we can get this resolved.

[Abscissa]

Interesting. On vibe.d v0.8.2, this results in neither mysql/protocol/sockets.d(121): Assertion failure nor eventcore/drivers/posix/driver.d(243): Overwriting notification callback. Instead, it just results in the old spectre: vibe/core/drivers/libevent2_tcp.d(414): Acquiring reader of already owned connection:

core.exception.AssertError@../../../.dub/packages/vibe-d-0.8.2/vibe-d/core/vibe/core/drivers/libevent2_tcp.d(414): Acquiring reader of already owned connection.
----------------
??:? _d_assert_msg [0x94e47c62]
??:? @safe void vibe.core.drivers.libevent2_tcp.Libevent2TCPConnection.checkReader() [0x94dc60e7]
??:? @safe void vibe.core.drivers.libevent2_tcp.Libevent2TCPConnection.acquireReader() [0x94dc6104]
??:? @safe ulong vibe.core.drivers.libevent2_tcp.Libevent2TCPConnection.read(scope ubyte[], vibe.core.stream.IOMode) [0x94dc5632]
??:? @safe void vibe.core.stream.InputStream.read(scope ubyte[]) [0x94de26ea]
??:? void mysql.protocol.sockets.MySQLSocketVibeD.read(ubyte[]) [0x94c42735]
??:? ubyte[] mysql.protocol.comms.getPacket(mysql.connection.Connection) [0x94c3d6fe]
??:? bool mysql.protocol.comms.execQueryImpl(mysql.connection.Connection, mysql.protocol.comms.ExecQueryImplInfo, out ulong) [0x94c3d36c]
??:? mysql.result.ResultRange mysql.commands.queryImpl(mysql.commands.ColumnSpecialization[], mysql.connection.Connection, mysql.protocol.comms.ExecQueryImplInfo) [0x94c3862c]
??:? mysql.result.ResultRange mysql.commands.query(mysql.connection.Connection, const(char[]), mysql.commands.ColumnSpecialization[]) [0x94c385b3]
??:? void app.WebInterface.index(vibe.http.server.HTTPServerResponse) [0x94c20642]
??:? void vibe.web.web.handleRequest!("index", app.WebInterface.index(vibe.http.server.HTTPServerResponse), app.WebInterface).handleRequest(vibe.http.server.HTTPServerRequest, vibe.http.server.HTTPServerResponse, app.WebInterface, vibe.web.web.WebInterfaceSettings) [0x94c2aabb]
??:? @trusted void vibe.web.web.registerWebInterface!(app.WebInterface, 5).registerWebInterface(vibe.http.router.URLRouter, app.WebInterface, vibe.web.web.WebInterfaceSettings).__lambda4(vibe.http.server.HTTPServerRequest, vibe.http.server.HTTPServerResponse) [0x94c29d38]
??:? @safe bool vibe.http.router.URLRouter.handleRequest(vibe.http.server.HTTPServerRequest, vibe.http.server.HTTPServerResponse).__lambda4!(ulong, immutable(char)[][]).__lambda4(ulong, scope immutable(char)[][]) [0x94d17fab]
??:? const @safe bool vibe.http.router.MatchTree!(vibe.http.router.Route).MatchTree.doMatch(immutable(char)[], scope bool delegate(ulong, scope immutable(char)[][]) @safe) [0x94d18a82]
??:? @safe bool vibe.http.router.MatchTree!(vibe.http.router.Route).MatchTree.match(immutable(char)[], scope bool delegate(ulong, scope immutable(char)[][]) @safe) [0x94d18367]
??:? @safe void vibe.http.router.URLRouter.handleRequest(vibe.http.server.HTTPServerRequest, vibe.http.server.HTTPServerResponse) [0x94d17c6d]
??:? @safe bool vibe.http.server.handleRequest(vibe.core.stream.Stream, vibe.core.net.TCPConnection, vibe.http.server.HTTPServerContext, ref vibe.http.server.HTTPServerSettings, ref bool, scope std.experimental.allocator.IAllocator) [0x94d5f33c]
??:? @trusted void vibe.http.server.handleHTTPConnection(vibe.core.net.TCPConnection, vibe.http.server.HTTPServerContext).__lambda3() [0x94d5dc58]
??:? @safe void vibe.http.server.handleHTTPConnection(vibe.core.net.TCPConnection, vibe.http.server.HTTPServerContext) [0x94d5daf9]
??:? nothrow @safe void vibe.http.server.listenHTTPPlain(vibe.http.server.HTTPServerSettings, void delegate(vibe.http.server.HTTPServerRequest, vibe.http.server.HTTPServerResponse) @safe).doListen(vibe.http.server.HTTPServerContext, bool, bool).__lambda4(vibe.core.net.TCPConnection) [0x94d1e83c]
??:? void vibe.core.drivers.libevent2_tcp.ClientTask.execute() [0x94e11feb]
??:? void vibe.core.core.makeTaskFuncInfo!(void delegate()).makeTaskFuncInfo(ref void delegate()).callDelegate(vibe.core.core.TaskFuncInfo*) [0x94dba2af]
??:? void vibe.core.core.CoreTask.run() [0x94db6b3e]
??:? void core.thread.Fiber.run() [0x94e8d97f]
??:? fiber_entryPoint [0x94e8d6d2]
??:? [0xffffffff]
Program exited with code 1

[Abscissa]

By adding this to the test case's WebInterface.index function:

import std.stdio;
writeln("*cast(void**)&conn: ", *cast(void**)&conn);

I can see that ConnectionPool is handing out the same connection to two different tasks before the first task has completed.

[s-ludwig]

Both, the old "aquiring reader" and the new "overwriting notification callback" assertions, have the same cause - reading or writing concurrently on the same connection. I had a look at the source and I think the bug lies here:

mysql-native/source/mysql/pool.d

Line 174 in 249c122

Connection conn = m_pool.lockConnection();

Due to the (awful) implicit casting that is possible through the alias this in LockedConnection!T, it is possible to silently extract the underlying connection object. Changing the variable declaration to LockedConnection!Connection or auto should fix the issue.

[s-ludwig]

Maybe LockedConnection should simply use opDot instead of alias this for now. With DIP1000 it could annotate the __conn getter as scope.

[Abscissa]

Thanks a ton! That does indeed fix it! A stupid mistake in mysql-native and clearly I was just spinning in circles with it (and my code to output the address of the Connection object must've been wrong too.)

Expect a fix and new release after I get some sleep, fading fast here...

(BTW, one unfortunate problem I've found with opDot in the past is that it conflicts pretty badly with...uhh, one other major D feature...I think it might've been UFCS, IIRC).

[Abscissa]

Speaking of this, mysql-native may need updated to optionally support LockedConnection!Connection throughout. Currently, it just assumes a connection object is always Connection, which clearly isn't the case when using the connection pool. One little problem though is how to handle ResultRange/Row: Currently, they're the only remaining part of mysql-native that still holds a reference to a connection. Not real clear what I can do to eliminate that while still being able to detect a ResultRange being invalidated though, and I wouldn't want stored references to a ResultsRange to prevent connections from being reclaimed back to the pool.

[Abscissa]

Putting together a fix, regression test, and new release right now.

Summary:

Ultimately, MySQLPool.lockConnection was returning a connection that was already in use.

How it happened:

After a change made for v2.1.0, MySQLPool.lockConnection was accidentally returning a Connection instead of a LockedConnection!Connection. This meant the LockedConnection went out-of-scope and returned the connection to the pool as soon as MySQLPool.lockConnection returned. So the Connection returned was no longer locked and got handed out again to the next fiber which requested it, even if the first fiber was still using it.

[Abscissa]

Also, the other part of this issue is that mysql-native's socket wrappers had an invariant check that was incompatible with vibe-core (as opposed to vibe-d:core), used by vibe v0.8.3.