Bug Stories: The Memory Ownership in Timeout

We are running a lot of tests right now on RavenDB, in all sort of interesting configurations. Some of the more interesting results came from testing wildly heterogeneous systems. Put a node on a fast Windows machine, connect it to a couple of Raspberry PIs, a cheap Windows tablet over WiFi, and a slow Linux machine and see how that kind of cluster is handling high load.

This has turned out a number of bugs, the issue with the TCP read buffer corruption is one such example, but another is the reason for this post. In one of our test runs, the RavenDB process crashed with invalid memory access. That was interesting to see. Tracking down the issue led us to the piece of code that is handling incoming replication. In particular, the issue was possible if the following happened:

• Node A is significantly slower than Node B, primarily with regards to disk I/O.
• Node B is being hit with enough load that it sends large requests to Node A.
• There is a Node C that is also trying to replicate the same information (because it noticed that Node A isn’t catching fast enough and is trying to help).

The root cause was that we had a bit of code that looked like this:

using (stats.For(ReplicationOperation.Incoming.Storage))
{
    var replicationCommand = new MergedDocumentReplicationCommand(this, buffer, totalSize, lastEtag);
    var task = _database.TxMerger.Enqueue(replicationCommand);
    if (task.Wait(_database.Configuration.Replication.ActiveConnectionTimeout.AsTimeSpan) == false)
    {
        var message = $"Could not commit replication batch with size {totalSize/1024:#,#}kb after {_database.Configuration.Replication.ActiveConnectionTimeout.AsTimeSpan}, aborting";
        if (_log.IsInfoEnabled)
            _log.Info(message);
        throw new TimeoutException(message);
    }
}

Basically, we read the data from the network into a buffer, and now we hand it off to the transaction merger to run. However, if there is a lot of load on the server, it is possible that the transaction merger will not have a chance to return in time. We try to abort the connection here, since something is obviously wrong, and we do just that. The problem is that we sent a buffer to the transaction merger, and while it might not have gotten to processing our request yet (or completed it, at least), there is no way for us to actually be able to pull the request out (it might have already started executing, after all).

The code didn’t consider that, and what happened when we did get a timeout is that the buffer was returned to the pool, and if it was freed in time we would get an access violation exception if we were lucky, or just garbage in the buffer (that we previously validated, so we didn’t check again) that would likely also cause a crash.

The solution was to wait for the task to complete but ping the other host to let it know that we are still alive and that the connection shouldn’t be aborted.