HttpClient fails to initialize SSL.

[meareindel]

Hey! We've got some strange issue with ssl initializing after upgrading to .net 6.0 from .net 5.0.

We have multiple microservices deployed on our own Kubernetes. There are 4 physical nodes on Debian Buster, each of node has several virtual machines as Kubernetes nodes. The microservices images are based on mcr.microsoft.com/dotnet/aspnet:6.0 with some debugging/servicing appendings like apt-get install curl and so on. We've also tried :6.0-focal and it was like it helped but I'll describe it below.

The microservices mainly exchanges data with each other by plain http through their internal hostnames, but for some specific reason sometimes they are connecting to each other through global network by https (in general it may be some external data provider which is not under our control).

The thing is sometimes when the https connection is starting it fails to initialize the openssl library with some strange errors - error:04067084:rsa routines:rsa_ossl_public_decrypt:data too large for modulus and (or) error:04067072:rsa routines:rsa_ossl_public_decrypt:padding check failed. As far as I know, there is no calls of routines:rsa_ossl_public_decrypt:data in openssl initialization. It fails randomly on different pods, different nodes etc. If one connection on one pod didn't fail, it won't fail ever. If one connection on one pod failed - it'll be failing again and again until pod restart, and then it repeats, meaning it can fail or not again. Is seems like there is some threading issue here, but it is just by suggestion. I've tried to figure out the ssl initialization process by reading the sources of System.Net.Security and Crypto.Native wrapper but no luck so far.

I still cannot reproduce this on some simple application, environment or test. It is not reproducing on windows and on local wsl2 docker - only in our Kubernetes environment so far (we have some other environments, but that one mentioned is our dev and we cannot upgrade others while dev is failing).

The other thing I've found that it happens only if we have /etc/ssl/openssl.cnf with some non-empty system default settings (system_default_sect, like described in #46271). If we leave system_default_sect empty or just provide no config file at all (that is the case of :6.0-focal, it has no openssl config file by default) - everything works fine. If we put there just the ciphers that are already default as described here (https://docs.microsoft.com/en-us/dotnet/core/compatibility/cryptography/5.0/default-cipher-suites-for-tls-on-linux) - it starts failing. And we need this config defaults (just like in :6.0 image) because we still need to connect to the sites with some obsolete weak ciphers.

It worked fine on .net 5.0.

Could you please suggest something or direct me to the way I can investigate it further?

Two exception stack examples attached.
modulus.txt
padding.txt

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

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

Issue Details

---

Hey! We've got some strange issue with ssl initializing after upgrading to .net 6.0 from .net 5.0.

We have multiple microservices deployed on our own Kubernetes. There are 4 physical nodes on Debian Buster, each of node has several virtual machines as Kubernetes nodes. The microservices images are based on mcr.microsoft.com/dotnet/aspnet:6.0 with some debugging/servicing appendings like apt-get install curl and so on. We've also tried :6.0-focal and it was like it helped but I'll describe it below.

The microservices mainly exchanges data with each other by plain http through their internal hostnames, but for some specific reason sometimes they are connecting to each other through global network by https (in general it may be some external data provider which is not under our control).

The thing is sometimes when the https connection is starting it fails to initialize the openssl library with some strange errors - error:04067084:rsa routines:rsa_ossl_public_decrypt:data too large for modulus and (or) error:04067072:rsa routines:rsa_ossl_public_decrypt:padding check failed. As far as I know, there is no calls of routines:rsa_ossl_public_decrypt:data in openssl initialization. It fails randomly on different pods, different nodes etc. If one connection on one pod didn't fail, it won't fail ever. If one connection on one pod failed - it'll be failing again and again until pod restart, and then it repeats, meaning it can fail or not again. Is seems like there is some threading issue here, but it is just by suggestion. I've tried to figure out the ssl initialization process by reading the sources of System.Net.Security and Crypto.Native wrapper but no luck so far.

I still cannot reproduce this on some simple application, environment or test. It is not reproducing on windows and on local wsl2 docker - only in our Kubernetes environment so far (we have some other environments, but that one mentioned is our dev and we cannot upgrade others while dev is failing).

The other thing I've found that it happens only if we have /etc/ssl/openssl.cnf with some non-empty system default settings (system_default_sect, like described in #46271). If we leave system_default_sect empty or just provide no config file at all (that is the case of :6.0-focal, it has no openssl config file by default) - everything works fine. If we put there just the ciphers that are already default as described here (https://docs.microsoft.com/en-us/dotnet/core/compatibility/cryptography/5.0/default-cipher-suites-for-tls-on-linux) - it starts failing. And we need this config defaults (just like in :6.0 image) because we still need to connect to the sites with some obsolete weak ciphers.

It worked fine on .net 5.0.

Could you please suggest something or direct me to the way I can investigate it further?

Two exception stack examples attached.
modulus.txt
padding.txt

Author:	meareindel
Assignees:	-
Labels:	area-System.Net.Security, untriaged
Milestone:	-

[wfurt]

cc: @bartonjs

[meareindel]

Any ideas? At least if it is bug or some configuration/behavior breaking changes etc?

[vcsjones]

The other thing I've found that it happens only if we have /etc/ssl/openssl.cnf with some non-empty system default settings (system_default_sect, like described in #46271). If we leave system_default_sect empty or just provide no config file at all (that is the case of :6.0-focal, it has no openssl config file by default) - everything works fine

A few questions:

First, Can you include the exact openssl.cnf that you are using?

The thing is sometimes when the https connection is starting it fails to initialize the openssl library with some strange errors

Do you have an estimate for how often is "sometimes"?

[meareindel]

First, Can you include the exact openssl.cnf that you are using?

Well we are not using it explicitly, it was just a part of investigation. We just use the aspnet:6.0 image with no modifications of openssl.cnf - and by the way it is the very same of aspnet:5.0 image. Anyway, attached it for convenience (but with .txt extension because github doesn't know .cnf) - openssl.txt

Do you have an estimate for how often is "sometimes"?

Well we have a deploy job in our gitlab ci which deploys every microservice we're using at our dev environment. There are about 20 microservices, but some of them are scaled and some of them don't make a https connections at all. In summary there are about 12 pods deployed which make https connections. and at least 5 of them are affected with that problem every deploy, meaning that there are 5 pods right after deploy which cannot make https requests until restart (but pod restart has the same probability to fix or not to fix) or next deploy (where we will just have another 5 pods or even the very same).

[am11]

Found a similar-looking conversation on the internets: https://www.mail-archive.com/openssl-users@openssl.org/msg89470.html.

(based on which I have a guess) Maybe we just need to move this ERR_clear_error():

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

Line 104 in 53d5288

ERR_clear_error();

out of the if/else block (so it runs in both cases)?

One thing jumped out at me (perhaps intentional?) is we end up p/invoking CryptoNative_EnsureLibSslInitialized twice:

runtime/src/libraries/Common/src/Interop/Unix/System.Net.Security.Native/Interop.Initialization.cs

Lines 23 to 26 in 57bfe47

	CryptoInitializer.Initialize();
	//Call ssl specific initializer
	Ssl.EnsureLibSslInitialized();

once from CryptoInitializer's cctor and then again from line 26. On native side, CryptoNative_EnsureOpenSslInitialized is called by CryptoNative_EnsureLibSslInitialized

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

Lines 126 to 128 in 53d5288

	void CryptoNative_EnsureLibSslInitialized()
	{
	CryptoNative_EnsureOpenSslInitialized();

which has pthread_once call, but rest of this function's body (including DetectCiphersuiteConfiguration()) will run for each call to CryptoNative_EnsureLibSslInitialized. If first call encountered an error and error list wasn't cleared, the next time we can end up having state errors (per the conversation in linked thread).

[bartonjs]

I don't think it's a double/concurrency problem (even though apparently both System.Net.Http and System.Net.Security will call EnsureLibSslInitialized), but a tainted error queue problem.

The SSL initializer throws if there's any error in the error queue after it calls the P/Invoke. What it means by that is "if any error was raised during initialization"... but if the error was left over by some previous operation (which perhaps hit the error and considered it skippable/part of a fallback without throwing) at just the core crypto layer, then we'll think SSL failed to initialize.

Alternatively, it could be that the error is coming from inside our configuration code itself... but if that's the case then it probably just means we're reporting the wrong error (the last one from a cascade instead of the first/correct one for the operation... which is a problem we're already looking to systematically address for vNext).

If you can get a repro under a debugger, doing something like call ERR_print_errors_fp(stdout) at the end of CryptoNative_EnsureLibSslInitialized might reveal something more interesting going on.

[meareindel]

If you can get a repro under a debugger, doing something like call ERR_print_errors_fp(stdout)

Could you please elaborate? Does it mean I can attach to dotnet-process on affected pod with some debugger like gdb/SOS, put a breakpoint somehow at the right place and then call some code within it? Or should it be some part of runtime (System.Net.Security in particular) or the whole runtime be rebuilt with that call ERR_print_errors_fp(stdout)? Can I find some additional info about it somewhere, in particular how exactly I can do such a thing?

[bartonjs]

SOS isn't required, since no managed code is involved.

For LLDB it'd be something like

$ lldb dotnet -- bin/Debug/netcoreapp6.0/HttpClientStartupBug.dll
Added Microsoft public symbol server
(lldb) target create "/usr/bin/dotnet"
Current executable set to '/usr/bin/dotnet' (x86_64).
(lldb) settings set -- target.run-args  "bin/Debug/netcoreapp6.0/HttpClientStartupBug.dll"
(lldb) b CryptoNative_EnsureLibSslInitialized
Breakpoint 1: no locations (pending).
WARNING:  Unable to resolve breakpoint to any actual locations.
(lldb) run
Process 21619 launched: '/usr/bin/dotnet' (x86_64)
1 location added to breakpoint 1
Process 21619 stopped
* thread #14, name = '.NET ThreadPool', stop reason = breakpoint 1.1
    frame #0: 0x00007ffff4134bf0 libSystem.Security.Cryptography.Native.OpenSsl.so`CryptoNative_EnsureLibSslInitialized
libSystem.Security.Cryptography.Native.OpenSsl.so`CryptoNative_EnsureLibSslInitialized:
->  0x7ffff4134bf0 <+0>: pushq  %rbp
    0x7ffff4134bf1 <+1>: pushq  %r15
    0x7ffff4134bf3 <+3>: pushq  %r14
    0x7ffff4134bf5 <+5>: pushq  %r13
(lldb) finish
Process 21619 stopped
* thread #14, name = '.NET ThreadPool', stop reason = step out
    frame #0: 0x00007fff7dce2a1f
->  0x7fff7dce2a1f: leaq   -0x80(%rbp), %rdi
    0x7fff7dce2a23: callq  *0x835af(%rip)
    0x7fff7dce2a29: leaq   -0x80(%rbp), %rdi
    0x7fff7dce2a2d: callq  *0x8359d(%rip)
(lldb) call (void)ERR_print_errors_fp(stdout);
(lldb)

Mine did nothing, because there were no errors in the queue. Had there been, it'd look like

(lldb) call (void)ERR_print_errors_fp(stdout);
140737353987904:error:0406706C:rsa routines:rsa_ossl_public_decrypt:data greater than mod len:../crypto/rsa/rsa_ossl.c:539:
(lldb)

[meareindel]

Thanks for such a detailed explanation! I've managed to debug our apps with similar way but still no luck. It seems that attached debugger affects somehow how app works, and the bug doesn't reproduce.

I've made a script for gdb(not lldb for it can't 'finish' and 'call' in one breakpoint command) to attach to dotnet process in a running kubernetes pod and I run it just after the container start to catch ssl initialization routine. And I've changed the method for breakpoint to CryptoNative_ErrPeekLastError to be sure that thread will suspend right after initialization so there will be less debug affect. However, everything works fine with it. If I don't attach a debugger, the error comes back.

There also were some thread suspends because of SIG34 and SIGPIPE, maybe these also take part somehow, but I don't know. Added ignore of these in script.

I'll try to run applications with just an attached debugger (without breakpoints, just attach and continue) to see if it helps, and if it will, it probably would be some workaround (very odd though), but I wonder if attached debugger will affect overall performance of application. And as far as I understood if I run the dotnet process with gdb (define entrypoint of docker image with something like 'gdb run dotnet ...') I won't be able to detach gdb after breakpoint hit to ensure there is no performance hit at least right after ssl initialization.

Maybe some other ideas?

Gdb script I've used (the whole shell command which runs it):

cat << EOF > script && gdb --pid 1 -iex 'set pagination off' -x script -q
set logging on
handle SIG34 nostop noprint pass noignore
handle SIGPIPE nostop noprint pass noignore

define ssl_trace
call (void)ERR_print_errors_fp(stdout)
continue
end

b CryptoNative_ErrPeekLastError
commands
ssl_trace
end
continue
EOF

[bartonjs]

Well, the idea/hope is that hitting the error once will let the full error queue be displayed, and that from there it'll be "obvious" what's wrong.

[meareindel]

If I remove that 'call (void)ERR_print_errors_fp(stdout)' from script, the error comes back. It seems that it actually do the trick, because it pops all the errors from queue, and then the execution continue as if there were no errors. But for some reason it does not print these errors to the stdout neither to gdb log or lldb stdout. Tested by 'call fprintf(stdout, "test")'. It seems that there is no tty for dotnet process (ps aux shows question mark). Will try to figure it out. At least maybe changing the image entrypoint to 'gdb run dotnet...' will probably work.