Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Assert while running System.Net.Security tests #44689

Closed
wfurt opened this issue Nov 14, 2020 · 9 comments · Fixed by #66443
Closed

Assert while running System.Net.Security tests #44689

wfurt opened this issue Nov 14, 2020 · 9 comments · Fixed by #66443
Assignees
@rzikm
Labels
area-System.Net.Security bug os-linux Linux OS (any supported distro) test-run-core Test failures in .NET Core test runs
Milestone
7.0.0

Comments

@wfurt
Copy link
Member

wfurt commented Nov 14, 2020

I did MANY runs (Ubuntu 18.04) and this is first occurrence so it may be hard to reproduce. The assert is guarded by #if DEBUG so it should impact released product but it suggests that there was prior error we did not handle or there is some race condition with other thread.

Process terminated. Assertion failed.
OpenSsl error queue is not empty, run: 'openssl errstr 1409442E' for original error.
   at Interop.OpenSsl.Encrypt(SafeSslHandle context, ReadOnlySpan`1 input, Byte[]& output, SslErrorCode& errorCode) in /home/furt/github/wfurt-runtime/src/libraries/Common/src/Interop/Unix/System.Security.Cryptography.Native/Interop.OpenSsl.cs:line 301
   at System.Net.Security.SslStreamPal.EncryptDecryptHelper(SafeDeleteContext securityContext, ReadOnlyMemory`1 input, Int32 offset, Int32 size, Boolean encrypt, Byte[]& output, Int32& resultSize) in /home/furt/github/wfurt-runtime/src/libraries/System.Net.Security/src/System/Net/Security/SslStreamPal.Unix.cs:line 163
   at System.Net.Security.SslStreamPal.EncryptMessage(SafeDeleteContext securityContext, ReadOnlyMemory`1 input, Int32 headerSize, Int32 trailerSize, Byte[]& output, Int32& resultSize) in /home/furt/github/wfurt-runtime/src/libraries/System.Net.Security/src/System/Net/Security/SslStreamPal.Unix.cs:line 47
   at System.Net.Security.SecureChannel.Encrypt(ReadOnlyMemory`1 buffer, Byte[]& output, Int32& resultSize) in /home/furt/github/wfurt-runtime/src/libraries/System.Net.Security/src/System/Net/Security/SecureChannel.cs:line 873
   at System.Net.Security.SslStream.EncryptData(ReadOnlyMemory`1 buffer, Byte[]& outBuffer, Int32& outSize) in /home/furt/github/wfurt-runtime/src/libraries/System.Net.Security/src/System/Net/Security/SslStream.Implementation.cs:line 180
   at System.Net.Security.SslStream.WriteSingleChunk[TIOAdapter](TIOAdapter writeAdapter, ReadOnlyMemory`1 buffer) in /home/furt/github/wfurt-runtime/src/libraries/System.Net.Security/src/System/Net/Security/SslStream.Implementation.cs:line 644
   at System.Net.Security.SslStream.WriteAsyncInternal[TIOAdapter](TIOAdapter writeAdapter, ReadOnlyMemory`1 buffer) in /home/furt/github/wfurt-runtime/src/libraries/System.Net.Security/src/System/Net/Security/SslStream.Implementation.cs:line 986
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in /home/furt/github/wfurt-runtime/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/AsyncMethodBuilderCore.cs:line 42
   at System.Net.Security.SslStream.WriteAsyncInternal[TIOAdapter](TIOAdapter writeAdapter, ReadOnlyMemory`1 buffer)
   at System.Net.Security.SslStream.Write(Byte[] buffer, Int32 offset, Int32 count) in /home/furt/github/wfurt-runtime/src/libraries/System.Net.Security/src/System/Net/Security/SslStream.cs:line 769
   at System.IO.Stream.WriteByte(Byte value) in /home/furt/github/wfurt-runtime/src/libraries/System.Private.CoreLib/src/System/IO/Stream.cs:line 692
   at System.IO.Tests.WrappingConnectedStreamConformanceTests.<>c__DisplayClass9_1.<NestedWithinSelf_ReadWrite_Success>b__0() in /home/furt/github/wfurt-runtime/src/libraries/Common/tests/Tests/System/IO/StreamConformanceTests.cs:line 2757
   at System.Threading.Tasks.Task.InnerInvoke() in /home/furt/github/wfurt-runtime/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 2371
   at System.Threading.Tasks.Task.<>c.<.cctor>b__278_0(Object obj) in /home/furt/github/wfurt-runtime/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 2359
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state) in /home/furt/github/wfurt-runtime/src/libraries/System.Private.CoreLib/src/System/Threading/ExecutionContext.cs:line 275
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread) in /home/furt/github/wfurt-runtime/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 2321
   at System.Threading.Tasks.Task.ExecuteEntryUnsafe(Thread threadPoolThread) in /home/furt/github/wfurt-runtime/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 2255
   at System.Threading.Tasks.Task.ExecuteFromThreadPool(Thread threadPoolThread) in /home/furt/github/wfurt-runtime/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 2246
   at System.Threading.ThreadPoolWorkQueue.Dispatch() in /home/furt/github/wfurt-runtime/src/libraries/System.Private.CoreLib/src/System/Threading/ThreadPool.cs:line 705
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart() in /home/furt/github/wfurt-runtime/src/libraries/System.Private.CoreLib/src/System/Threading/PortableThreadPool.WorkerThread.cs:line 54
   at System.Threading.ThreadHelper.ThreadStart_Context(Object state) in /home/furt/github/wfurt-runtime/src/coreclr/src/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs:line 43
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) in /home/furt/github/wfurt-runtime/src/libraries/System.Private.CoreLib/src/System/Threading/ExecutionContext.cs:line 186
   at System.Threading.ThreadHelper.ThreadStart() in /home/furt/github/wfurt-runtime/src/coreclr/src/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs:line 92
@wfurt wfurt added area-System.Net.Security os-linux Linux OS (any supported distro) labels Nov 14, 2020
@Dotnet-GitSync-Bot Dotnet-GitSync-Bot added the untriaged New issue has not been triaged by the area owner label Nov 14, 2020
@ghost
Copy link

ghost commented Nov 14, 2020

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

Issue Details
Description:

I did MANY runs (Ubuntu 18.04) and this is first occurrence so it may be hard to reproduce. The assert is guarded by #if DEBUG so it should impact released product but it suggests that there was prior error we did not handle or there is some race condition with other thread.

Process terminated. Assertion failed.
OpenSsl error queue is not empty, run: 'openssl errstr 1409442E' for original error.
   at Interop.OpenSsl.Encrypt(SafeSslHandle context, ReadOnlySpan`1 input, Byte[]& output, SslErrorCode& errorCode) in /home/furt/github/wfurt-runtime/src/libraries/Common/src/Interop/Unix/System.Security.Cryptography.Native/Interop.OpenSsl.cs:line 301
   at System.Net.Security.SslStreamPal.EncryptDecryptHelper(SafeDeleteContext securityContext, ReadOnlyMemory`1 input, Int32 offset, Int32 size, Boolean encrypt, Byte[]& output, Int32& resultSize) in /home/furt/github/wfurt-runtime/src/libraries/System.Net.Security/src/System/Net/Security/SslStreamPal.Unix.cs:line 163
   at System.Net.Security.SslStreamPal.EncryptMessage(SafeDeleteContext securityContext, ReadOnlyMemory`1 input, Int32 headerSize, Int32 trailerSize, Byte[]& output, Int32& resultSize) in /home/furt/github/wfurt-runtime/src/libraries/System.Net.Security/src/System/Net/Security/SslStreamPal.Unix.cs:line 47
   at System.Net.Security.SecureChannel.Encrypt(ReadOnlyMemory`1 buffer, Byte[]& output, Int32& resultSize) in /home/furt/github/wfurt-runtime/src/libraries/System.Net.Security/src/System/Net/Security/SecureChannel.cs:line 873
   at System.Net.Security.SslStream.EncryptData(ReadOnlyMemory`1 buffer, Byte[]& outBuffer, Int32& outSize) in /home/furt/github/wfurt-runtime/src/libraries/System.Net.Security/src/System/Net/Security/SslStream.Implementation.cs:line 180
   at System.Net.Security.SslStream.WriteSingleChunk[TIOAdapter](TIOAdapter writeAdapter, ReadOnlyMemory`1 buffer) in /home/furt/github/wfurt-runtime/src/libraries/System.Net.Security/src/System/Net/Security/SslStream.Implementation.cs:line 644
   at System.Net.Security.SslStream.WriteAsyncInternal[TIOAdapter](TIOAdapter writeAdapter, ReadOnlyMemory`1 buffer) in /home/furt/github/wfurt-runtime/src/libraries/System.Net.Security/src/System/Net/Security/SslStream.Implementation.cs:line 986
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in /home/furt/github/wfurt-runtime/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/AsyncMethodBuilderCore.cs:line 42
   at System.Net.Security.SslStream.WriteAsyncInternal[TIOAdapter](TIOAdapter writeAdapter, ReadOnlyMemory`1 buffer)
   at System.Net.Security.SslStream.Write(Byte[] buffer, Int32 offset, Int32 count) in /home/furt/github/wfurt-runtime/src/libraries/System.Net.Security/src/System/Net/Security/SslStream.cs:line 769
   at System.IO.Stream.WriteByte(Byte value) in /home/furt/github/wfurt-runtime/src/libraries/System.Private.CoreLib/src/System/IO/Stream.cs:line 692
   at System.IO.Tests.WrappingConnectedStreamConformanceTests.<>c__DisplayClass9_1.<NestedWithinSelf_ReadWrite_Success>b__0() in /home/furt/github/wfurt-runtime/src/libraries/Common/tests/Tests/System/IO/StreamConformanceTests.cs:line 2757
   at System.Threading.Tasks.Task.InnerInvoke() in /home/furt/github/wfurt-runtime/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 2371
   at System.Threading.Tasks.Task.<>c.<.cctor>b__278_0(Object obj) in /home/furt/github/wfurt-runtime/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 2359
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state) in /home/furt/github/wfurt-runtime/src/libraries/System.Private.CoreLib/src/System/Threading/ExecutionContext.cs:line 275
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread) in /home/furt/github/wfurt-runtime/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 2321
   at System.Threading.Tasks.Task.ExecuteEntryUnsafe(Thread threadPoolThread) in /home/furt/github/wfurt-runtime/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 2255
   at System.Threading.Tasks.Task.ExecuteFromThreadPool(Thread threadPoolThread) in /home/furt/github/wfurt-runtime/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 2246
   at System.Threading.ThreadPoolWorkQueue.Dispatch() in /home/furt/github/wfurt-runtime/src/libraries/System.Private.CoreLib/src/System/Threading/ThreadPool.cs:line 705
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart() in /home/furt/github/wfurt-runtime/src/libraries/System.Private.CoreLib/src/System/Threading/PortableThreadPool.WorkerThread.cs:line 54
   at System.Threading.ThreadHelper.ThreadStart_Context(Object state) in /home/furt/github/wfurt-runtime/src/coreclr/src/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs:line 43
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) in /home/furt/github/wfurt-runtime/src/libraries/System.Private.CoreLib/src/System/Threading/ExecutionContext.cs:line 186
   at System.Threading.ThreadHelper.ThreadStart() in /home/furt/github/wfurt-runtime/src/coreclr/src/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs:line 92
Author: wfurt
Assignees: -
Labels:

area-System.Net.Security, os-linux
Milestone: -

@karelz karelz added bug and removed untriaged New issue has not been triaged by the area owner labels Nov 24, 2020
@karelz karelz added this to the 6.0.0 milestone Nov 24, 2020
@karelz
Copy link
Member

karelz commented Nov 24, 2020 •
edited
Loading

Triage: Add code to dump the content of the error when we hit this -- then see if we can get more useful info

@karelz karelz added the test-run-core Test failures in .NET Core test runs label May 4, 2021
@karelz karelz modified the milestones: 6.0.0, Future May 4, 2021
@jeffhandley jeffhandley mentioned this issue May 11, 2021
Merged
@tarekgh tarekgh mentioned this issue May 19, 2021
Merged
@akoeplinger
Copy link
Member

akoeplinger commented Jun 11, 2021 •
edited
Loading

Just hit this in https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-53808-merge-00beadfa06ad47ee82/System.Net.Security.Tests/console.e87a3360.log?sv=2019-07-07&se=2021-07-01T09%3A29%3A53Z&sr=c&sp=rl&sig=TJKWwOo70AYRz5SicBpXmxFtD3nCVhvJixxPDXwWLBs%3D

OpenSsl error queue is not empty, run: 'openssl errstr 1409442E' for original error.
   at Interop.OpenSsl.Decrypt(SafeSslHandle context, Span`1 buffer, SslErrorCode& errorCode) in /_/src/libraries/Common/src/Interop/Unix/System.Security.Cryptography.Native/Interop.OpenSsl.cs:line 355
   at System.Net.Security.SslStreamPal.DecryptMessage(SafeDeleteSslContext securityContext, Byte[] buffer, Int32& offset, Int32& count) in /_/src/libraries/System.Net.Security/src/System/Net/Security/SslStreamPal.Unix.cs:line 69
   at System.Net.Security.SecureChannel.Decrypt(Byte[] payload, Int32& offset, Int32& count) in /_/src/libraries/System.Net.Security/src/System/Net/Security/SecureChannel.cs:line 920
   at System.Net.Security.SslStream.PrivateDecryptData(Byte[] buffer, Int32& offset, Int32& count) in /_/src/libraries/System.Net.Security/src/System/Net/Security/SslStream.Implementation.cs:line 194
   at System.Net.Security.SslStream.DecryptData() in /_/src/libraries/System.Net.Security/src/System/Net/Security/SslStream.Implementation.cs:line 189
   at System.Net.Security.SslStream.ReadAsyncInternal[TIOAdapter](TIOAdapter adapter, Memory`1 buffer, Boolean renegotiation) in /_/src/libraries/System.Net.Security/src/System/Net/Security/SslStream.Implementation.cs:line 902
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/ExecutionContext.cs:line 183
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread) in /_/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/AsyncTaskMethodBuilderT.cs:line 324
   at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/TaskContinuation.cs:line 795
   at System.Threading.Tasks.Task.RunContinuations(Object continuationObject) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 3368
   at System.Threading.Tasks.Task`1.TrySetResult(TResult result) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Future.cs:line 400
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetExistingTaskResult(Task`1 task, TResult result) in /_/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/AsyncTaskMethodBuilderT.cs:line 446
   at System.IO.StreamBuffer.ReadAsync(Memory`1 buffer, CancellationToken cancellationToken) in /_/src/libraries/Common/src/System/Net/StreamBuffer.cs:line 264
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/ExecutionContext.cs:line 268
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread) in /_/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/AsyncTaskMethodBuilderT.cs:line 328
   at System.Threading.ThreadPoolWorkQueue.Dispatch() in /_/src/libraries/System.Private.CoreLib/src/System/Threading/ThreadPoolWorkQueue.cs:line 708
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart() in /_/src/libraries/System.Private.CoreLib/src/System/Threading/PortableThreadPool.WorkerThread.cs:line 63
   at System.Threading.Thread.StartCallback() in /_/src/coreclr/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs:line 105

The error message is:

$ openssl errstr 1409442E
error:1409442E:SSL routines:func(148):tlsv1 alert protocol version

Seems to be an issue with some TLSv1 case.

@ViktorHofer
Copy link
Member

Happened again in https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-54544-merge-903469bafa7e4ef79e/System.Net.Security.Tests/console.6bf1e633.log?sv=2019-07-07&se=2021-07-19T18%3A22%3A24Z&sr=c&sp=rl&sig=WwNcr5jSXUj4REx2K6nU2rlsyoIiqha8rSNHIIIN61s%3D

Configuration: net6.0-Linux-Debug-x64-Mono_release-(Debian.10.Amd64.Open)ubuntu.1604.amd64.open@mcr.microsoft.com/dotnet-buildtools/prereqs:debian-10-helix-amd64-bfcd90a-20200121150006

@ViktorHofer ViktorHofer mentioned this issue Jun 29, 2021
Merged
@hoyosjs
Copy link
Member

hoyosjs commented Aug 10, 2021

@wfurt I just saw this in https://dev.azure.com/dnceng/public/_build/results?buildId=1286120&view=ms.vss-test-web.build-test-results-tab&runId=37973086&resultId=194107&paneView=dotnet-dnceng.dnceng-build-release-tasks.helix-test-information-tab and it has a dump attached.

@hoyosjs hoyosjs mentioned this issue Aug 10, 2021
Merged
@rzikm
Copy link
Member

rzikm commented Mar 9, 2022

Is the assert still necessary? What's the bad thing that happens if there is some error left in the queue?.

From my understanding, All Crypto operations that care about errors clear the error queue beforehand (as of #65148), so IMO this should not have any impact.

Thoughts, @wfurt, @bartonjs?

@rzikm rzikm assigned rzikm and unassigned wfurt Mar 9, 2022
@bartonjs
Copy link
Member

bartonjs commented Mar 9, 2022

I think it can/should be deleted. The SslRead call calls ERR_clear_error() to ensure it has a pristine state.

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

Lines 399 to 403 in 4e75015

int32_t CryptoNative_SslRead(SSL* ssl, void* buf, int32_t num, int32_t* error)
{
ERR_clear_error();
int32_t result = SSL_read(ssl, buf, num);

@wfurt
Copy link
Member Author

wfurt commented Mar 9, 2022

It was there for a reason. But it seems like we changed strategy how we go about errors. We should make sure we do it consistent as for example we may call handshake after Read() in case of renegotiation.
The intend of the assert was to guard agains cases where we leak error to wrong operations.

@bartonjs
Copy link
Member

The intend of the assert was to guard agains cases where we leak error to wrong operations.

Yeah, that's what the ERR_clear_error() is for in CryptoNative_SslRead. Given that we've always been supportive of other libraries calling into OpenSSL (otherwise we wouldn't have had the SafeHandle-accepting RSAOpenSsl/etc ctors) it has always been possible that this assert tripped because of something a third-party library did. The new approach of "make it clean, do work, keep it tidy if you know there was an error you ignored" leads to the error always being relevant (or throwing a very generic exception because something failed with no populated error code).

rzikm added a commit to rzikm/dotnet-runtime that referenced this issue Mar 10, 2022
@rzikm
Remove asserts checking OpenSSL error queues
490ba16 
Fixes dotnet#44689

As of dotnet#65148, libraries use different approach to handling OpenSSL errors. The original assert which would be hit if a previous operation left errors in the queue is no longer necessary as all OpenSSL calls are prepended by `ERR_clear_error()` to make sure the latest (and most relevant) error is reported.
@rzikm rzikm mentioned this issue Mar 10, 2022
Merged
@ghost ghost added the in-pr There is an active PR which will close this issue when it is merged label Mar 10, 2022
rzikm added a commit that referenced this issue Mar 10, 2022
@rzikm
Remove asserts checking OpenSSL error queues (#66443)
5c0c317 
Fixes #44689

As of #65148, libraries use different approach to handling OpenSSL errors. The original assert which would be hit if a previous operation left errors in the queue is no longer necessary as all OpenSSL calls are prepended by `ERR_clear_error()` to make sure the latest (and most relevant) error is reported.
@ghost ghost removed the in-pr There is an active PR which will close this issue when it is merged label Mar 10, 2022
@karelz karelz modified the milestones: Future, 7.0.0 Apr 8, 2022
@ghost ghost locked as resolved and limited conversation to collaborators May 8, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@rzikm rzikm

Labels
area-System.Net.Security bug os-linux Linux OS (any supported distro) test-run-core Test failures in .NET Core test runs
Projects
None yet
Milestone
7.0.0
Development

Successfully merging a pull request may close this issue.

Remove asserts checking OpenSSL error queues rzikm/dotnet-runtime
8 participants
@akoeplinger @karelz @ViktorHofer @bartonjs @wfurt @hoyosjs @rzikm @Dotnet-GitSync-Bot