Private.InternalDiagnostics.System.Net.Security.RemoteCertificateError TraceEvent Does Not Include the Underline TLS Error from macOS

[TingluoHuang]

Description

#1513 supposes to help us identify underline TLS error when macOS verify server TLS cert.

I have a customer on macOS getting RemoteCertificateNameMismatch when making request to https://api.github.com.

The customer has proxy in their network to decrypt TLS traffic with self-signed CAs.

2023-08-02T13:51:34.9513820Z [START Private.InternalDiagnostics.System.Net.Security - ErrorMessage]
2023-08-02T13:51:34.9513850Z SafeDeleteSslContext#3038911
2023-08-02T13:51:34.9513850Z VerifyCertificateProperties
2023-08-02T13:51:34.9513860Z Cert name validation for 'api.github.com' failed with status '0'
2023-08-02T13:51:34.9513860Z [END Private.InternalDiagnostics.System.Net.Security - ErrorMessage]
2023-08-02T13:51:34.9515520Z [START Private.InternalDiagnostics.System.Net.Security - RemoteCertificateError]
2023-08-02T13:51:34.9515540Z 66166301
2023-08-02T13:51:34.9515550Z Remote certificate has errors:
2023-08-02T13:51:34.9515550Z [END Private.InternalDiagnostics.System.Net.Security - RemoteCertificateError]
2023-08-02T13:51:34.9515590Z [START Private.InternalDiagnostics.System.Net.Security - RemoteCertificateError]
2023-08-02T13:51:34.9515640Z 66166301
2023-08-02T13:51:34.9515640Z Certificate name mismatch.
2023-08-02T13:51:34.9515640Z [END Private.InternalDiagnostics.System.Net.Security - RemoteCertificateError]
2023-08-02T13:51:34.9525100Z [START System.Net.Security - HandshakeFailed]
2023-08-02T13:51:34.9525130Z False
2023-08-02T13:51:34.9525190Z 124.1869
2023-08-02T13:51:34.9525190Z The remote certificate is invalid according to the validation procedure: RemoteCertificateNameMismatch
2023-08-02T13:51:34.9525200Z [END System.Net.Security - HandshakeFailed]

I checked the self-signed cert, the CN seems match:

2023-08-02T13:51:34.9422770Z [Subject]
2023-08-02T13:51:34.9422770Z   CN=*.github.com, O="GitHub, Inc.", L=San Francisco, S=California, C=US
2023-08-02T13:51:34.9422770Z   Simple Name: *.github.com
2023-08-02T13:51:34.9422780Z   DNS Name: *.github.com

I think the issue might be caused by the customer's CA doesn't meet Apple requirement for TLS CA cert.
The intermediate CA doesn't have Server Authentication ( 1.3.6.1.5.5.7.3.1 )
Similar to #666

It would be nice that we can get some status code to tell us the issue with #1513
But right now we only get Cert name validation for 'api.github.com' failed with status '0', so i can't confirm the problem.

I am wondering whether #1513 can properly handle the case when there are a CA chain, ex: ROOT CA->Intermediate CA-> TLS cert

Reproduction Steps

N/A

Expected behavior

The trace message give back a non-zero code, so we can check Apple doc to match the error code.

ex: Cert name validation for 'api.github.com' failed with status '-2147408889'

Actual behavior

Cert name validation for 'api.github.com' failed with status '0'

Regression?

No response

Known Workarounds

No response

Configuration

Dotnet SDK: 6.0.405
OS: macOS 13.5

Other information

No response

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

Issue Details

---

Description

#1513 supposes to help us identify underline TLS error when macOS verify server TLS cert.

I have a customer on macOS getting RemoteCertificateNameMismatch when making request to https://api.github.com.

The customer has proxy in their network to decrypt TLS traffic with self-signed CAs.

2023-08-02T13:51:34.9513820Z [START Private.InternalDiagnostics.System.Net.Security - ErrorMessage]
2023-08-02T13:51:34.9513850Z SafeDeleteSslContext#3038911
2023-08-02T13:51:34.9513850Z VerifyCertificateProperties
2023-08-02T13:51:34.9513860Z Cert name validation for 'api.github.com' failed with status '0'
2023-08-02T13:51:34.9513860Z [END Private.InternalDiagnostics.System.Net.Security - ErrorMessage]
2023-08-02T13:51:34.9515520Z [START Private.InternalDiagnostics.System.Net.Security - RemoteCertificateError]
2023-08-02T13:51:34.9515540Z 66166301
2023-08-02T13:51:34.9515550Z Remote certificate has errors:
2023-08-02T13:51:34.9515550Z [END Private.InternalDiagnostics.System.Net.Security - RemoteCertificateError]
2023-08-02T13:51:34.9515590Z [START Private.InternalDiagnostics.System.Net.Security - RemoteCertificateError]
2023-08-02T13:51:34.9515640Z 66166301
2023-08-02T13:51:34.9515640Z Certificate name mismatch.
2023-08-02T13:51:34.9515640Z [END Private.InternalDiagnostics.System.Net.Security - RemoteCertificateError]
2023-08-02T13:51:34.9525100Z [START System.Net.Security - HandshakeFailed]
2023-08-02T13:51:34.9525130Z False
2023-08-02T13:51:34.9525190Z 124.1869
2023-08-02T13:51:34.9525190Z The remote certificate is invalid according to the validation procedure: RemoteCertificateNameMismatch
2023-08-02T13:51:34.9525200Z [END System.Net.Security - HandshakeFailed]

I checked the self-signed cert, the CN seems match:

2023-08-02T13:51:34.9422770Z [Subject]
2023-08-02T13:51:34.9422770Z   CN=*.github.com, O="GitHub, Inc.", L=San Francisco, S=California, C=US
2023-08-02T13:51:34.9422770Z   Simple Name: *.github.com
2023-08-02T13:51:34.9422780Z   DNS Name: *.github.com

I think the issue might be caused by the customer's CA doesn't meet Apple requirement for TLS CA cert.
The intermediate CA doesn't have Server Authentication ( 1.3.6.1.5.5.7.3.1 )
Similar to #666

It would be nice that we can get some status code to tell us the issue with #1513
But right now we only get Cert name validation for 'api.github.com' failed with status '0', so i can't confirm the problem.

I am wondering whether #1513 can properly handle the case when there are a CA chain, ex: ROOT CA->Intermediate CA-> TLS cert

Reproduction Steps

N/A

Expected behavior

The trace message give back a non-zero code, so we can check Apple doc to match the error code.

ex: Cert name validation for 'api.github.com' failed with status '-2147408889'

Actual behavior

Cert name validation for 'api.github.com' failed with status '0'

Regression?

No response

Known Workarounds

No response

Configuration

Dotnet SDK: 6.0.405
OS: macOS 13.5

Other information

No response

Author:	TingluoHuang
Assignees:	-
Labels:	area-System.Net.Security
Milestone:	-

[wfurt]

the messages seems misled up somehow. The 66166301 makes no sense to me. It may be some other reason.
You can trey to run log stream | grep securityd while running the code - you may see more from OS side.

As far as the hierarchy: .NET basically passes everything to OS and the extra log would record OSStatus from that call.

[karelz]

Triage: We should improve diagnostic here. Moving to Future.

[TingluoHuang]

@wfurt thanks, here is the output i got from my customer

2023-08-04 19:09:53.599592+0000 0x318fc8   Default     0x0                  69064  0    Runner.Listener: (Security) [com.apple.securityd:mds] Recording an MDS plugin: /System/Library/Security/ldapdl.bundle {87191ca6-0fc9-11d4-849a-000502b52122}
2023-08-04 19:09:53.599703+0000 0x318fc8   Default     0x0                  69064  0    Runner.Listener: (Security) [com.apple.securityd:mds] Recording an MDS plugin: /System/Library/Frameworks/Security.framework {87191ca0-0fc9-11d4-849a-000502b52122}
2023-08-04 19:09:53.620820+0000 0x318f1d   Default     0xb4e442             160    0    trustd: [com.apple.securityd:OTATrust] User has disabled system data installation.
2023-08-04 19:09:53.621029+0000 0x318f1d   Default     0xb4e442             160    0    trustd: [com.apple.securityd:OTATrust] User has disabled system data installation.
2023-08-04 19:09:53.623326+0000 0x318fc8   Default     0x0                  69064  0    Runner.Listener: (Security) [com.apple.securityd:security_exception] MacOS error: -25294
2023-08-04 19:09:53.623504+0000 0x318fc8   Default     0x0                  69064  0    Runner.Listener: (Security) [com.apple.securityd:security_exception] MacOS error: -25294
2023-08-04 19:09:53.623575+0000 0x318fc8   Default     0x0                  69064  0    Runner.Listener: (Security) [com.apple.securityd:security_exception] MacOS error: -25294
2023-08-04 19:09:53.623612+0000 0x318fc8   Default     0x0                  69064  0    Runner.Listener: (Security) [com.apple.securityd:security_exception] MacOS error: -25294
2023-08-04 19:09:53.650957+0000 0x318f1d   Default     0xb4e443             160    0    trustd: [com.apple.securityd:OTATrust] User has disabled system data installation.
2023-08-04 19:09:53.651116+0000 0x318f1d   Default     0xb4e443             160    0    trustd: [com.apple.securityd:OTATrust] User has disabled system data installation.
2023-08-04 19:09:53.652042+0000 0x318fc8   Default     0x0                  69064  0    Runner.Listener: (Security) [com.apple.securityd:security_exception] MacOS error: -25294
2023-08-04 19:09:53.652136+0000 0x318fc8   Default     0x0                  69064  0    Runner.Listener: (Security) [com.apple.securityd:security_exception] MacOS error: -25294
2023-08-04 19:09:53.652188+0000 0x318fc8   Default     0x0                  69064  0    Runner.Listener: (Security) [com.apple.securityd:security_exception] MacOS error: -25294
2023-08-04 19:09:53.655347+0000 0x318f1d   Default     0xb4e444             160    0    trustd: [com.apple.securityd:policy] cert[0]: ServerAuthEKU =(path)[]> 0
2023-08-04 19:09:53.655430+0000 0x318f1d   Default     0xb4e444             160    0    trustd: [com.apple.securityd:policy] cert[1]: TemporalValidity =(path)[]> 0
2023-08-04 19:09:53.655540+0000 0x318f1d   Default     0xb4dd81             160    0    trustd: (Security) [com.apple.securityd:SecCritical] Failed to talk to secd after 4 attempts.
2023-08-04 19:09:53.655589+0000 0x318f1d   Default     0xb4e444             160    0    trustd: [com.apple.securityd:policy] cert[1]: TemporalValidity =(path)[]> 0
2023-08-04 19:09:53.655864+0000 0x318f1d   Default     0xb4dd82             160    0    trustd: (Security) [com.apple.securityd:SecCritical] Failed to talk to secd after 4 attempts.
2023-08-04 19:09:53.655965+0000 0x318f1d   Default     0xb4dd83             160    0    trustd: (Security) [com.apple.securityd:SecCritical] Failed to talk to secd after 4 attempts.
2023-08-04 19:09:53.656076+0000 0x318f1d   Default     0xb4e444             160    0    trustd: [com.apple.securityd:policy] cert[0]: ServerAuthEKU =(path)[]> 0
2023-08-04 19:09:53.656148+0000 0x318f1d   Default     0xb4e444             160    0    trustd: [com.apple.securityd:OTATrust] User has disabled system data installation.
2023-08-04 19:09:53.656200+0000 0x318f1d   Default     0xb4e444             160    0    trustd: [com.apple.securityd:OTATrust] User has disabled system data installation.
2023-08-04 19:09:53.656236+0000 0x318f1d   Default     0xb4e444             160    0    trustd: [com.apple.securityd:OTATrust] User has disabled system data installation.
2023-08-04 19:09:53.656362+0000 0x318fc8   Default     0x0                  69064  0    Runner.Listener: (Security) [com.apple.securityd:SecError] Trust evaluate failure: [leaf ServerAuthEKU]
2023-08-04 19:09:53.656767+0000 0x318f1d   Default     0xb4e445             160    0    trustd: [com.apple.securityd:policy] cert[0]: ServerAuthEKU =(path)[]> 0
2023-08-04 19:09:53.656816+0000 0x318f1d   Default     0xb4e445             160    0    trustd: [com.apple.securityd:policy] cert[1]: TemporalValidity =(path)[]> 0
2023-08-04 19:09:53.656899+0000 0x318f1d   Default     0xb4dd84             160    0    trustd: (Security) [com.apple.securityd:SecCritical] Failed to talk to secd after 4 attempts.
2023-08-04 19:09:53.656960+0000 0x318f1d   Default     0xb4e445             160    0    trustd: [com.apple.securityd:policy] cert[1]: TemporalValidity =(path)[]> 0
2023-08-04 19:09:53.657235+0000 0x318f1d   Default     0xb4dd85             160    0    trustd: (Security) [com.apple.securityd:SecCritical] Failed to talk to secd after 4 attempts.
2023-08-04 19:09:53.657450+0000 0x318f1d   Default     0xb4e445             160    0    trustd: [com.apple.securityd:policy] cert[1]: TemporalValidity =(path)[]> 0
2023-08-04 19:09:53.657523+0000 0x318f1d   Default     0xb4e445             160    0    trustd: [com.apple.securityd:policy] cert[1]: TemporalValidity =(path)[]> 0
2023-08-04 19:09:53.657604+0000 0x318f1d   Default     0xb4e445             160    0    trustd: [com.apple.securityd:policy] cert[1]: TemporalValidity =(path)[]> 0
2023-08-04 19:09:53.657658+0000 0x318f1d   Default     0xb4e445             160    0    trustd: [com.apple.securityd:OTATrust] User has disabled system data installation.
2023-08-04 19:09:53.657704+0000 0x318f1d   Default     0xb4e445             160    0    trustd: [com.apple.securityd:OTATrust] User has disabled system data installation.
2023-08-04 19:09:53.657739+0000 0x318f1d   Default     0xb4e445             160    0    trustd: [com.apple.securityd:OTATrust] User has disabled system data installation.
2023-08-04 19:09:53.657870+0000 0x318fc8   Default     0x0                  69064  0    Runner.Listener: (Security) [com.apple.securityd:SecError] Trust evaluate failure: [ca1 TemporalValidity]

Runner.Listener is my application, it's a dotnet 6.0 self-contained console app.

Trust evaluate failure: [leaf ServerAuthEKU] might related to the self-sign cert doesn't have 1.3.6.1.5.5.7.3.1 server auth extension
I am not sure how to understand Trust evaluate failure: [ca1 TemporalValidity]

Can you help me check if i missed anything? also any improvement we can make to get the error code/name flow into the event source trace in C#? 🙇

[wfurt]

https://support.apple.com/en-us/HT210176

it may be the requirement about CA validity. Can yo get hands on the actual certificate?
It should be possible to call something like openssl s_client -connect github.com:443.
When saved, they should be able to run
security verify-cert -c certificate.crt to see what OS would think about the trust.

As far as reporting the code from #1513 should show first error from SecTrustEvaluate. If the OS function does not provide details we would fail to include that in traces - but I'm not sure there is anything we can do about it.