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.

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

Add tracing to the Linux X509Chain implementation #65860

Merged
merged 5 commits into from
Mar 16, 2022

Conversation

bartonjs
Copy link
Member

The tracing is heavily focused on transient behaviors, like AIA/CRL/OCSP downloads and cache interactions.

Things like applying ApplicationPolicy aren't really traced because that can be "easily" evaluated by looking at the certificates in isolation.

Example tracing, from the microsoft.com certificate:

Validating Certificate: microsoft.com

2022-02-24T19:12:09.079Z: ChainStart - Starting X.509 chain build.
2022-02-24T19:12:09.265Z: FindFirstChainFinished - First build finished with status 20.
2022-02-24T19:12:09.305Z: AssetDownloadStart - Starting download of certificate asset uri 'http://www.microsoft.com/pkiops/certs/Microsoft%20Azure%20TLS%20Issuing%20CA%2006%20-%20xsign.crt' with a 15000ms timeout.
2022-02-24T19:12:09.611Z: AssetDownloadStop - Asset download finished with a 1527-byte response. - Duration 305.885ms
2022-02-24T19:12:09.629Z: FindChainViaAiaFinished - AIA-based build retrieved 1 certificate(s) and finished with status 0.
2022-02-24T19:12:09.630Z: CachingIntermediate - Caching the intermediate certificate ('CN=Microsoft Azure TLS Issuing CA 06, O=Microsoft Corporation, C=US') to the CurrentUser\CA store.
2022-02-24T19:12:09.695Z: FlushStores - Manual store flush triggered.
2022-02-24T19:12:09.703Z: RevocationCheckStart - Starting 'ExcludeRoot' revocation check in mode 'Online' with a 3-element chain.
2022-02-24T19:12:09.711Z: CrlIdentifiersDetermined - Certificate 'CN=microsoft.com, O=Microsoft Corporation, L=Redmond, S=WA, C=US' has a CRL Distribution Point of 'http://www.microsoft.com/pkiops/crl/Microsoft%20Azure%20TLS%20Issuing%20CA%2006.crl', will use '12fa6c3e.efbe5079.crl' as the cache file.
2022-02-24T19:12:09.711Z: CrlCacheCheckStart - Checking for a cached CRL.
2022-02-24T19:12:09.712Z: CrlCacheOpenError - Could not open the CRL cache file, it likely does not exist.
2022-02-24T19:12:09.712Z: CrlCacheCheckStop - Duration 0.640ms
2022-02-24T19:12:09.713Z: AssetDownloadStart - Starting download of certificate asset uri 'http://www.microsoft.com/pkiops/crl/Microsoft%20Azure%20TLS%20Issuing%20CA%2006.crl' with a 15000ms timeout.
2022-02-24T19:12:09.744Z: AssetDownloadStop - Asset download finished with a 1405-byte response. - Duration 31.416ms
2022-02-24T19:12:09.746Z: CrlCacheWriteSucceeded - The downloaded CRL was successfully written to the cache.
2022-02-24T19:12:09.747Z: CrlIdentifiersDetermined - Certificate 'CN=Microsoft Azure TLS Issuing CA 06, O=Microsoft Corporation, C=US' has a CRL Distribution Point of 'http://crl3.digicert.com/DigiCertGlobalRootG2.crl', will use '607986c7.8ab5229e.crl' as the cache file.
2022-02-24T19:12:09.747Z: CrlCacheCheckStart - Checking for a cached CRL.
2022-02-24T19:12:09.747Z: CrlCacheOpenError - Could not open the CRL cache file, it likely does not exist.
2022-02-24T19:12:09.747Z: CrlCacheCheckStop - Duration 0.097ms
2022-02-24T19:12:09.750Z: AssetDownloadStart - Starting download of certificate asset uri 'http://crl3.digicert.com/DigiCertGlobalRootG2.crl' with a 15000ms timeout.
2022-02-24T19:12:09.781Z: AssetDownloadStop - Asset download finished with a 877-byte response. - Duration 31.149ms
2022-02-24T19:12:09.781Z: CrlCacheWriteSucceeded - The downloaded CRL was successfully written to the cache.
2022-02-24T19:12:09.785Z: CrlChainFinished - With CRLs applied, the chain build finished with status 0.
2022-02-24T19:12:09.785Z: RevocationCheckStop - Duration 81.682ms
2022-02-24T19:12:09.789Z: ChainStop - Duration 709.927ms

Fixes #40445.

@ghost
Copy link

ghost commented Feb 24, 2022

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

Issue Details

The tracing is heavily focused on transient behaviors, like AIA/CRL/OCSP downloads and cache interactions.

Things like applying ApplicationPolicy aren't really traced because that can be "easily" evaluated by looking at the certificates in isolation.

Example tracing, from the microsoft.com certificate:

Validating Certificate: microsoft.com

2022-02-24T19:12:09.079Z: ChainStart - Starting X.509 chain build.
2022-02-24T19:12:09.265Z: FindFirstChainFinished - First build finished with status 20.
2022-02-24T19:12:09.305Z: AssetDownloadStart - Starting download of certificate asset uri 'http://www.microsoft.com/pkiops/certs/Microsoft%20Azure%20TLS%20Issuing%20CA%2006%20-%20xsign.crt' with a 15000ms timeout.
2022-02-24T19:12:09.611Z: AssetDownloadStop - Asset download finished with a 1527-byte response. - Duration 305.885ms
2022-02-24T19:12:09.629Z: FindChainViaAiaFinished - AIA-based build retrieved 1 certificate(s) and finished with status 0.
2022-02-24T19:12:09.630Z: CachingIntermediate - Caching the intermediate certificate ('CN=Microsoft Azure TLS Issuing CA 06, O=Microsoft Corporation, C=US') to the CurrentUser\CA store.
2022-02-24T19:12:09.695Z: FlushStores - Manual store flush triggered.
2022-02-24T19:12:09.703Z: RevocationCheckStart - Starting 'ExcludeRoot' revocation check in mode 'Online' with a 3-element chain.
2022-02-24T19:12:09.711Z: CrlIdentifiersDetermined - Certificate 'CN=microsoft.com, O=Microsoft Corporation, L=Redmond, S=WA, C=US' has a CRL Distribution Point of 'http://www.microsoft.com/pkiops/crl/Microsoft%20Azure%20TLS%20Issuing%20CA%2006.crl', will use '12fa6c3e.efbe5079.crl' as the cache file.
2022-02-24T19:12:09.711Z: CrlCacheCheckStart - Checking for a cached CRL.
2022-02-24T19:12:09.712Z: CrlCacheOpenError - Could not open the CRL cache file, it likely does not exist.
2022-02-24T19:12:09.712Z: CrlCacheCheckStop - Duration 0.640ms
2022-02-24T19:12:09.713Z: AssetDownloadStart - Starting download of certificate asset uri 'http://www.microsoft.com/pkiops/crl/Microsoft%20Azure%20TLS%20Issuing%20CA%2006.crl' with a 15000ms timeout.
2022-02-24T19:12:09.744Z: AssetDownloadStop - Asset download finished with a 1405-byte response. - Duration 31.416ms
2022-02-24T19:12:09.746Z: CrlCacheWriteSucceeded - The downloaded CRL was successfully written to the cache.
2022-02-24T19:12:09.747Z: CrlIdentifiersDetermined - Certificate 'CN=Microsoft Azure TLS Issuing CA 06, O=Microsoft Corporation, C=US' has a CRL Distribution Point of 'http://crl3.digicert.com/DigiCertGlobalRootG2.crl', will use '607986c7.8ab5229e.crl' as the cache file.
2022-02-24T19:12:09.747Z: CrlCacheCheckStart - Checking for a cached CRL.
2022-02-24T19:12:09.747Z: CrlCacheOpenError - Could not open the CRL cache file, it likely does not exist.
2022-02-24T19:12:09.747Z: CrlCacheCheckStop - Duration 0.097ms
2022-02-24T19:12:09.750Z: AssetDownloadStart - Starting download of certificate asset uri 'http://crl3.digicert.com/DigiCertGlobalRootG2.crl' with a 15000ms timeout.
2022-02-24T19:12:09.781Z: AssetDownloadStop - Asset download finished with a 877-byte response. - Duration 31.149ms
2022-02-24T19:12:09.781Z: CrlCacheWriteSucceeded - The downloaded CRL was successfully written to the cache.
2022-02-24T19:12:09.785Z: CrlChainFinished - With CRLs applied, the chain build finished with status 0.
2022-02-24T19:12:09.785Z: RevocationCheckStop - Duration 81.682ms
2022-02-24T19:12:09.789Z: ChainStop - Duration 709.927ms

Fixes #40445.

Author: bartonjs
Assignees: -
Labels:

area-System.Security

Milestone: -

}
else
{
OpenSslX509ChainEventSource.Log.NonHttpCdpEntry(name.Uri);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It might be "http" but failed to parse because of some issue later in the uri. Is that ok?

Copy link
Member Author

@bartonjs bartonjs Mar 14, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

PerfView would just see it as NonHttpCdpEntry / http://test..?q=w.

Something that takes the message into account would see Skipping CDP entry 'http://test..?q=w' because the protocol is not HTTP., which seems less than ideal, but not too far off the mark.

internal bool ShouldLogElementStatuses()
{
return IsEnabled(EventLevel.Verbose, EventKeywords.None);
}
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@marek-safar, will this helper confuse the linker and its ability to remove EventSource-related code based on guards, or is this ok?

}
}

OpenSslX509ChainEventSource.Log.NoMatchingCdpEntry();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

FWIW, we've typically guarded all EventSource calls, even parameterless onces, with IsEnabled() checks. Part of that has been historical, and part of that has been in support of the linker being able to remove everything that's only referenced inside such a guard. @marek-safar should comment on whether this is ok.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

And here I thought that was an artifact of older patterns.

So the correct style, for dotnet/runtime, at least, is an IsEnabled check on both the outside and the inside of the method? (I feel like EventSource's documentation said to have an IsEnabled check for each method, presumably to avoid things like creating the params array when it doesn't matter) Or do we do them outside-only?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yep, linker will have right now difficulties propagating this information. The best is to call directly methods that are substituted when event source is disabled

Copy link
Member

@stephentoub stephentoub left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Other than my comments, LGTM. I didn't analyze all of the reasons for each of the events; I'm assuming since you added them you believe they're all warranted and helpful.

@bartonjs bartonjs merged commit 07eab2b into dotnet:main Mar 16, 2022
@bartonjs bartonjs deleted the linux_chain_tracing branch March 18, 2022 16:13
@ghost ghost locked as resolved and limited conversation to collaborators Apr 17, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Add an EventSource to the certificate stack
4 participants