Rfc2898DeriveBytes.Pbkdf2 holding threads

[ecrocombe]

Description

Using Npgsql with EfCore locks up application, with pretty much all active threads held by System.Security.Cryptography.Rfc2898DeriveBytes.Pbkdf2, with the remaining active threads working on logging timeouts.

Reproduction Steps

This is something that is intermittent, and I'm unsure of the reproduction steps precisely, but i'll have a go:

1. Build dotnet application with EfCore DbContextPool, using Postgres Data Provider.
2. Run application anywhere from 1 to 10 hours witnessing 3% CPU usage on average and around 1,400 queries p/second
3. Experience application lock up, with 6400% CPU usage (Dual CPU server with 64 cores in total).

Sorry i cannot be more specific on this.

Expected behavior

Application to perform whatever task is in Rfc2898DeriveBytes.Pbkdf2 at a reasonable time.

Actual behavior

Rfc2898DeriveBytes.Pbkdf2 either does not return or returns after it has read the newspaper and had its coffee.

Regression?

We have had this issue for a long time (couple of months) and only just now cracking down the source of it to here.

Known Workarounds

None Known. Currently moved to a different authentication scheme which does not utilize Rfc2898DeriveBytes.Pbkdf2 at all.

Configuration

Docker configuration: Swarm
Runtime Docker image: mcr.microsoft.com/dotnet/runtime:9.0-alpine
Build Docker image: mcr.microsoft.com/dotnet/sdk:9.0-alpine
Docker Image additional packages (apk add): openssl icu-libs icu-data-full tzdata fontconfig ttf-dejavu mtr
Architecture: linux-musl-x64

Other information

Original issue created in Npgsql repo npgsql/npgsql#6029

[dotnet-policy-service]

Tagging subscribers to this area: @dotnet/area-system-security, @bartonjs, @vcsjones
See info in area-owners.md if you want to be subscribed.

[vcsjones]

This is going to be difficult to diagnose, but a couple of notes and observations

1. PBKDF2 is intentionally a very CPU intensive thing. I don't know enough about the PostgresQL protocol to say how many iterations are used typically. However, if you are profiling the auth protocol, it is likely that 95% of the compute time is spent in PBKDF2.

2. What is not clear to me is:

   • Is a single call to Rfc2898DeriveBytes.Pbkdf2 taking a long time?
   • Is the application making a lot of calls to Pbkdf2?

3. The actual implementation of Pbkdf2 on Linux is really just

   1. Do some input validations (no negative iteration counts, valid hash algorithm)
   2. Call PKCS5_PBKDF2_HMAC from OpenSSL.

   That's it.

   runtime/src/native/libs/System.Security.Cryptography.Native/pal_evp.c

   Lines 434 to 435 in 0473604

   	return PKCS5_PBKDF2_HMAC(
   	password, passwordLength, salt, saltLength, iterations, digest, destinationLength, destination);

   There really isn't all that much in the way here for us to improve on. No locks are taken, no state, no loops, nada.

4. I don't know much about Npgsql, but this jumped out at me:

   https://github.com/npgsql/npgsql/blob/3146bcda307d49ecd21d9e73c87a142dd1ee8cba/src/Npgsql/Internal/NpgsqlConnector.Auth.cs#L21-L23

   Which is in your call graph. I can't quickly understand the intent behind this, but I am immediately suspicious of while (true) around AuthenticateSASL, which is the part that does PBKDF2. Is there a chance your application is getting stuck in this loop?

Ultimately it would be helpful to

1. Get additional information about why Pbkdf2 is appearing in your call graph. Is it a lot of calls to it (which maybe means point 4 is a concern) or is it that individual calls to Pbkdf2 are taking a very long time.
2. As far as I can see in Ngpsql, there doesn't seem to be much telemetry emitted that could help here. If there were ETW or Event Pipe data emitted during the authentication step, perhaps that would be useful. And perhaps the Ngpsql folks know a way to figure out how to collect this information.

[vonzshik]

Which is in your call graph. I can't quickly understand the intent behind this, but I am immediately suspicious of while (true) around AuthenticateSASL, which is the part that does PBKDF2. Is there a chance your application is getting stuck in this loop?

That was done in npgsql/npgsql#5006 because in some cases (in particular, having a proxy in between) postgresql might require multiple authentication messages (I guess one for the proxy and one for PG, not completely sure to be honest). But overall in 99.9% cases it's only going to enter the loop once (since PG only authenticates once and if we break the protocol the connection will immediately be broken by PG itself), so IMO it's unlikely there is an issue with the loop in particular.

Get additional information about why Pbkdf2 is appearing in your call graph. Is it a lot of calls to it (which maybe means point 4 is a concern) or is it that individual calls to Pbkdf2 are taking a very long time.

According to the original issue, they have up to 2k concurrent connections, and with pool prunning/connection lifetime it's not really impossible for a case where immediate increase in traffic will result in many connections to be open concurrently.
Also another thing I noticed, in the graph other than multiple Rfc2898DeriveBytes calls there is also a single HMACSHA256 call. Is it somehow possible that they deadlock each other?

[bartonjs]

Is it somehow possible that they deadlock each other?

No. (At least I've never ever heard of a deadlock problem in the algorithm primitives before).

Is a single call to Rfc2898DeriveBytes.Pbkdf2 taking a long time?

It looks like you read an iteration count from the wire and run it. Do you have a sense of what order of magnitude the numbers are? Numbers vary per machine, of course, but the iteration count scales the work linearly (once you get past some startup overhead):

100k => 500k: 5 times as long.

100k iters of SHA1: 106.0154ms
500k iters of SHA1: 518.5746ms
100k iters of SHA256: 77.7878ms
500k iters of SHA256: 382.1404ms
100k iters of SHA384: 87.9954ms
500k iters of SHA384: 438.2405ms
100k iters of SHA512: 89.0553ms
500k iters of SHA512: 443.5017ms
100k iters of SHA1: 102.6152ms
500k iters of SHA1: 512.1994ms
100k iters of SHA256: 75.7675ms
500k iters of SHA256: 383.7376ms
100k iters of SHA384: 88.2551ms
500k iters of SHA384: 437.5755ms
100k iters of SHA512: 89.0364ms
500k iters of SHA512: 443.0613ms

If you are being harassed by being given int.MaxValue, that'll take you a long time to compute.

[vcsjones]

That was done in npgsql/npgsql#5006 because in some cases (in particular, having a proxy in between) postgresql might require multiple authentication messages (I guess one for the proxy and one for PG, not completely sure to be honest). But overall in 99.9% cases it's only going to enter the loop once

I suppose my concern is that there might be an issue in the logic of Ngpsql where it is not advancing some state and keeps trying to process the same message over and over again. Overall I would consider adding some kind of limit here, just from a "cover your butt" perspective. Is it realistic that it needs to do the loop 1,000 times? If not, then I would add a limit of a 1000 to the loop.

[vonzshik]

I suppose my concern is that there might be an issue in the logic of Ngpsql where it is not advancing some state and keeps trying to process the same message over and over again.

That's pretty much impossible.

1. Each time we loop we exchange messages with postgres, there is no other way to implement auth. So in case we send wrong message PG will just terminate the connection.
2. Even if for some inexplicable reason PG will decide to run a few thousand auth loops, we'll still exit early because at the start of each loop we check for timeout (essentially it's DateTime.UtcNow >= expiration) and throw if needed.

It looks like you read an iteration count from the wire and run it. Do you have a sense of what order of magnitude the numbers are?

Should be a constant 4096 (that's what I get with a local instance), at least according to PG repo.

@bartonjs I've made a small example which attempts to repro the issue. Is it possible for you to run it for a bit on failing machines (if the issue is with a specific OpenSSL version, then just ensuring than another machine uses the exact same version should do the trick).

using System.Security.Cryptography;
using System.Text;

const int Threads = 20;

var completed = 0;

var saltBytes = Convert.FromBase64String("KMUNCBwjf5FXsYQepyktLA==");
var passwd = "SomePassword".Normalize(NormalizationForm.FormKC);
var dataBytes = "Client Key"u8.ToArray();

var tasks = new List<Task>(Threads);
for (var i = 0; i < Threads; i++)
{
    tasks.Add(Task.Factory.StartNew(() =>
    {
        while (true)
        {
            var saltedPassword = Rfc2898DeriveBytes.Pbkdf2(passwd, saltBytes, 4096, HashAlgorithmName.SHA256, 256 / 8);
            HMACSHA256.HashData(saltedPassword, dataBytes);
            Interlocked.Increment(ref completed);
        }
    }, TaskCreationOptions.LongRunning));
}

_ = Task.Run(async () =>
{
    while (true)
    {
        await Task.Delay(1000);
        var current = Interlocked.Exchange(ref completed, 0);
        Console.WriteLine($"Completed: {current}/s");
    }
});

await Task.WhenAll(tasks);

[ecrocombe]

FYI, issue was found whilst using "OpenSSL 3.3.3" in docker image mcr.microsoft.com/dotnet/runtime:9.0-alpine@sha256:d5557c9bf579701537a3790a2a0f549e6356a7352e1430717c3e233de1e66173

[ecrocombe]

I have been able to create a reproduction using @vonzshik supplied test case above:
https://github.com/ecrocombe/openssl-repro-112898

It appears as though the issue lives in the alpine release of dotnet 9 docker image.

"Docker_Bad"

• mcr.microsoft.com/dotnet/runtime:9.0-alpine@sha256:d5557c9bf579701537a3790a2a0f549e6356a7352e1430717c3e233de1e66173
• ~200 p/seconds and my CPU remains idling.
• OpenSSL 3.3.3

"Docker_Good"

• mcr.microsoft.com/dotnet/runtime:9.0@sha256:f50efa2ae5fdb6c100d691b599dae5b1265520371bf79850ec46cf43cd73810d
• ~11,000 p/second and it maxes out my CPU
• OpenSSL 3.0.15

EDIT: tbh, even though i have called these "Good" and "Bad", im not sure which is which 😕