RFR: 8148188: Enhance the security libraries to record events of interest
Erik Gahlin
erik.gahlin at oracle.com
Mon Jul 9 16:21:22 UTC 2018
Thanks Sean.
Some feedback on the code in the security libraries.
- We should use camel case naming convention for variables (not underscore).
- Looking at sun/security/ssl/Finished.java,
I wonder if it wouldn't be less code and more easy to read, if we would
commit the event in a local private function and then use the
EventHelper class for common functionality. Instead of:
private static void recordEvent(SSLSessionImpl session) {
TLSHandshakeEvent hs_event = new TLSHandshakeEvent();
if (hs_event.isEnabled() || EventHelper.loggingSecurity()) {
String certIDs = "";
try {
certIDs = Stream.of(session.getPeerCertificates())
.filter(c -> c instanceof X509Certificate)
.map(c -> (X509Certificate) c)
.map(c -> c.getSerialNumber().toString(16))
.collect(Collectors.joining(", "));
} catch (SSLPeerUnverifiedException e) {
certIDs = e.getMessage(); // not verified msg
}
EventHelper.commitTLSHandshakeEvent(hs_event, null,
session.getPeerHost(), session.getPeerPort(),
session.getCipherSuite(), session.getProtocol(),
certIDs);
}
}
...
public static void commitTLSHandshakeEvent(TLSHandshakeEvent event,
Instant start,
String remoteHost,
int remotePort,
String cipherSuite,
String protocolVersion,
String certChain) {
if (event != null && event.shouldCommit()) {
event.remoteHost = remoteHost;
event.remotePort = remotePort;
event.cipherSuite = cipherSuite;
event.protocolVersion = protocolVersion;
event.certificateChain = certChain;
event.commit();
}
if (loggingSecurity()) {
String prepend = getDurationString(start);
SECURITY_LOGGER.log(LOG_LEVEL, prepend +
" TLSHandshake: {0}:{1,number,#}, {2}, {3}, {4}",
remoteHost, remotePort, protocolVersion, cipherSuite,
certChain);
}
}
We would do:
private static void logHandshake(SSLSessionImpl s) {
TLSHandshakeEvent event = new TLSHandshakeEvent();
if (event.shouldCommit()) {
event.remoteHost = s.getPeerHost();
event.remotePort = s.getPeerPort();
event.cipherSuite = s.getCipherSuite();
event.protocolVersion = s.getProtocol();
event.certificateChain =
EventHelper.certificateChain(s.getPeerCerticates());
event.commit();
}
if (EventHelper.isLoggingSecurity()) {
EventHelper.SECURITY_LOGGER.log(LOG_LEVEL, " TLSHandshake:
{0}:{1,number,#}, {2}, {3}, {4}",
s.getPeerHost(), s.getPeerPort(), s.getProtocol(),
s.getCipherSuite(),
EventHelper.certificateChain(s.getPeerCerticates()));
}
}
...
public static String certificateChain(Certificate[] certificates) {
try {
return Stream.of(certificates)
.filter(c -> c instanceof X509Certificate)
.map(c -> (X509Certificate) c)
.map(c -> c.getSerialNumber().toString(16))
.collect(Collectors.joining(", "));
} catch (SSLPeerUnverifiedException e) {
return e.getMessage(); // not verified msg
}
}
It will also meanless overhead, since only one check is needed for the
log and the JIT will be able to remove the allocation.
Maybe a similar pattern could be used for the other events as well?
Thanks
Erik
> As per request from Erik, I separated the tests out into individual
> ones to test the JFR and Logger functionality. I introduced a new
> separate test for the CertificateChainEvent event also. Originally
> this was wrapped into the TLSHandshakeEvent test.
>
> Thanks to Erik for extra refactoring and modifications carried out to
> clean up the code up further.
>
> http://cr.openjdk.java.net/~coffeys/webrev.8148188.v5/webrev/
>
> This enhancement has a dependency on JDK-8203629
>
> Regards,
> Sean.
>
> On 02/07/18 09:49, Erik Gahlin wrote:
>>
>>> On 29 Jun 2018, at 17:34, Seán Coffey <sean.coffey at oracle.com> wrote:
>>>
>>> I've introduced a new test helper class in the jdk/test/lib/jfr
>>> directory to help with the dual test nature of the new tests. It's
>>> helped alot with test code duplication.
>>>
>> My thinking was to put things like the certificates in a separate
>> file, i.e TestCertificates, and then have a logging test and a JFR
>> test reuse it.
>>
>> One rationale for adding logging was to use it if JFR is not present.
>> By putting the tests together, it becomes impossible to compile and
>> test logging without having JFR.
>>
>>> Looked at use of @DataAmount(DataAmount.BITS) also. Not sure if it's
>>> fits. The output is displayed in units like "KiB" - not the normal
>>> when examining key lengths used in X509Certificates. i.e a 2048 bit
>>> key gets displayed as "2 KiB" - I'd prefer to keep the 2048 display
>>> version.
>> We should not let the JMC GUI decide how units are specified. There
>> will be other GUIs and this is the first event that uses bits, so I
>> don’t think it is formatted that way because it was considered superior.
>>
>> Erik
>>
>>> new webrev at:
>>> http://cr.openjdk.java.net/~coffeys/webrev.8148188.v4/webrev/
>>>
>>> Regards,
>>> Sean.
>>>
>>> On 28/06/18 17:59, Seán Coffey wrote:
>>>> Comments inline.
>>>>
>>>>
>>>> On 28/06/2018 17:20, Erik Gahlin wrote:
>>>>> It's sufficient if an event object escapes to another method
>>>>> (regardless if JFR is enabled or not).
>>>>>
>>>>> Some more feedback:
>>>>>
>>>>> Rename event jdk.CertChain to jdk.CertificateChain
>>>>> Rename event jdk.X509Cert to jdk.X509Certificate
>>>>> Rename field certChain to certificateChain.
>>>>> Rename field serialNum to serialNumber
>>>> all above done.
>>>>> Rename field algId to AlgorithmicId or AlgorithmicID
>>>> maybe "algorithm" works here also ?
>>>>> Rename @Label("Ciphersuite") to @Label("Cipher Suite")
>>>>> Rename @Label("Cert Chain") to @Label("Certificate Chain")
>>>>> Rename @Label("Property Name") to "Name" or "Key" if that makes
>>>>> sense in the context?
>>>>> Rename @Label("Property Value") to "Value".
>>>>> Put events in a subcategory, i.e @Category({"Java Development
>>>>> Kit", "Security"})
>>>> done.
>>>>> Make classes final.
>>>> done. I had thought that the JFR mechanism required non-final classes.
>>>>> What is the unit of the key in X509Certificate event? Bits? If
>>>>> that is the case, use @DataAmount(DataAmount.BITS)
>>>> Yes - it's essentially the bit length of the keys used. Let me look
>>>> into that annotation usage.
>>>>> @Label("Serial numbers forming chain of trust") should not be a
>>>>> sentence. How about "Serial Numbers"?
>>>>>
>>>>> I think the tests are hard to read when two things are tested at
>>>>> the same time. It is also likely that if a test fail due to
>>>>> logging issues, it will be assigned to JFR because of the test
>>>>> name, even thought the issues is not JFR related.
>>>> I think we're always going to have some ownership issues when tests
>>>> serve a dual purpose. I still think it makes sense to keep the test
>>>> logic in one place. Any failures in these tests will most likely be
>>>> owned by security team. (moving the tests to security directory is
>>>> also an option)
>>>>> If you want to reuse code between tests, I would put it in
>>>>> testlibrary.
>>>> Let me check if there's any common patterns that could be added to
>>>> the testlibary.
>>>>
>>>> Thanks,
>>>> Sean.
>>>>> Erik
>>>>>
>>>>>> Thanks for the update Erik. By default I'm proposing that the new
>>>>>> JFR Events and Logger be disabled. As a result the event class
>>>>>> shouldn't escape. If performance metrics highlight an issue, we
>>>>>> should revisit.
>>>>>>
>>>>>> regards,
>>>>>> Sean.
>>>>>>
>>>>>>
>>>>>> On 27/06/2018 20:57, Erik Gahlin wrote:
>>>>>>> On 2018-06-27 21:14, Seán Coffey wrote:
>>>>>>>>
>>>>>>>> On 27/06/2018 19:57, Xuelei Fan wrote:
>>>>>>>>> Hi Sean,
>>>>>>>>>
>>>>>>>>> I may reply in several replies.
>>>>>>>>>
>>>>>>>>> PKIXMasterCertPathValidator.java
>>>>>>>>> --------------------------------
>>>>>>>>> + CertChainEvent cce = new CertChainEvent();
>>>>>>>>> + if(cce.isEnabled() || EventHelper.loggingSecurity()) {
>>>>>>>>> + String c = reversedCertList.stream()
>>>>>>>>> + .map(x -> x.getSerialNumber().toString(16))
>>>>>>>>> + .collect(Collectors.joining(", "));
>>>>>>>>> + EventHelper.commitCertChainEvent(cce, c);
>>>>>>>>> + }
>>>>>>>>>
>>>>>>>>> No matter the event or the JFR mechanism is enabled or not,
>>>>>>>>> the above code will create a new instance. Is the return
>>>>>>>>> value of cce.isEnabled() dynamically changed or static?
>>>>>>>> This is a requirement from the JFR framework. All their
>>>>>>>> event.isEnabled calls are instance methods and follow a similar
>>>>>>>> pattern. The JFR team assure me that the JIT can optimize away
>>>>>>>> such calls.
>>>>>>> The JIT will most likely not be able to optimize if the event
>>>>>>> class escapes.
>>>>>>>
>>>>>>> From a JFR perspective, this would be the preferred layout:
>>>>>>>
>>>>>>> EventA eventA= new EventA();
>>>>>>> eventA.value = this.value;
>>>>>>> eventA.commit();
>>>>>>>
>>>>>>> and then do logging separately:
>>>>>>>
>>>>>>> System.Logger.log(DEBUG, this.value)
>>>>>>>
>>>>>>> With this layout, the JIT will remove the allocation and dead
>>>>>>> store.
>>>>>>>
>>>>>>> If it is expensive to gather the data for the event, like the
>>>>>>> CertChainEvent above, the following pattern should be used.
>>>>>>>
>>>>>>> EventB eventB= new EventB ();
>>>>>>> if (eventB.shouldCommit()) {
>>>>>>> eventB.value = calculateValue();
>>>>>>> eventB .commit();
>>>>>>> }
>>>>>>>
>>>>>>> If JFR is not enabled, shouldCommit returns false and the JIT
>>>>>>> should be able to remove the allocation. This will be best from
>>>>>>> a performance point of view, and also in my opinion from a
>>>>>>> maintenance and readability perspective. Others may disagree.
>>>>>>>
>>>>>>> Erik
>>>>>>>
>>>>>>>>> Is there a need to support both logging and JFR? I'm new to
>>>>>>>>> record events. I did not get the point to use both.
>>>>>>>> I was initially hoping to concentrate on just JFR events but I
>>>>>>>> got strong feedback to also consider use of Logger (esp. in
>>>>>>>> cases where the jdk.jfr module is not available)
>>>>>>>>
>>>>>>>> regards,
>>>>>>>> Sean.
>>>>>>>>
>>>>>>>>> Thanks,
>>>>>>>>> Xuelei
>>>>>>>>>
>>>>>>>>> On 6/26/2018 3:18 PM, Seán Coffey wrote:
>>>>>>>>>> Erik,
>>>>>>>>>>
>>>>>>>>>> I rebased the patch with TLS v1.3 integration today. I hadn't
>>>>>>>>>> realized how much the handshaker code had changed. Hopefully,
>>>>>>>>>> I'll get a review from security dev team on that front.
>>>>>>>>>>
>>>>>>>>>> Regards the JFR semantics, I believe the edits should match
>>>>>>>>>> majority of requests . I still have a preference for the test
>>>>>>>>>> infra design for these new logger/JFR tests used in version 1
>>>>>>>>>> of webrev. I think it makes sense to keep the test
>>>>>>>>>> functionality together - no sense in separating them out into
>>>>>>>>>> different components IMO. Also, some of the edits to the JFR
>>>>>>>>>> testing were made to test for the new dual log/record
>>>>>>>>>> functionality. I might catch up with you tomorrow to see what
>>>>>>>>>> the best arrangement would be.
>>>>>>>>>>
>>>>>>>>>> http://cr.openjdk.java.net/~coffeys/webrev.8148188.v2/webrev/
>>>>>>>>>>
>>>>>>>>>> regards,
>>>>>>>>>> Sean.
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> On 25/06/2018 21:22, Seán Coffey wrote:
>>>>>>>>>>> Many thanks for the review comments Erik. Replies inline.
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> On 24/06/2018 14:21, Erik Gahlin wrote:
>>>>>>>>>>>> Hi Sean,
>>>>>>>>>>>>
>>>>>>>>>>>> Some of the changes in the webrev belongs to JDK-8203629
>>>>>>>>>>>> and should be removed for clarity.
>>>>>>>>>>>>
>>>>>>>>>>>> Some initial comments:
>>>>>>>>>>>>
>>>>>>>>>>>> default.jfc, profile.jfr:
>>>>>>>>>>>> The events should not have control="enable-exceptions". The
>>>>>>>>>>>> purpose of the control attribute is so to provide
>>>>>>>>>>>> parameterized configuration of events for JMC. As it is
>>>>>>>>>>>> now, the security events will be enabled when a user turns
>>>>>>>>>>>> on the exception events.
>>>>>>>>>>> Makes sense. I'll remove that parameter.
>>>>>>>>>>>> X509CertEvent:
>>>>>>>>>>>> You should use milliseconds since epoch to represent a date
>>>>>>>>>>>> instead of a string value, i.e.
>>>>>>>>>>>>
>>>>>>>>>>>> @Label("Valid From")
>>>>>>>>>>>> @Timestamp(Timestamp.MILLISECONDS_SINCE_EPOCH)
>>>>>>>>>>>> public long validFrom;
>>>>>>>>>>>>
>>>>>>>>>>>> @Label("Valid Until")
>>>>>>>>>>>> @Timestamp(Timestamp.MILLISECONDS_SINCE_EPOCH)
>>>>>>>>>>>> public long validUntil;
>>>>>>>>>>>>
>>>>>>>>>>> The CertificateValidity class operates on Date Object
>>>>>>>>>>> values. I'll work with the Date.getTime() method then (and
>>>>>>>>>>> update the Logger formatting)
>>>>>>>>>>>> This following annotation adds little value
>>>>>>>>>>>>
>>>>>>>>>>>> @Description("Details of Security Property")
>>>>>>>>>>>>
>>>>>>>>>>>> I would either remove the annotation, or provide
>>>>>>>>>>>> information that helps a user understand the event. For
>>>>>>>>>>>> instance, what is X509, and what kind of certificates are
>>>>>>>>>>>> we talking about?
>>>>>>>>>>> Yes - that looks like the wrong Description. I'll review all
>>>>>>>>>>> of these fields.
>>>>>>>>>>>> @Category("Java Application")
>>>>>>>>>>>>
>>>>>>>>>>>> I'm a bit worried that we will pollute the "Java
>>>>>>>>>>>> Application" namespace if we add lots of JDK events in that
>>>>>>>>>>>> category. We may want to add a new top level category "Java
>>>>>>>>>>>> Development Kit", analogous to the "Java Virtual Machine"
>>>>>>>>>>>> category, and put all security related events in
>>>>>>>>>>>> subcategory, perhaps called "Security".
>>>>>>>>>>> Yes - Open to suggestions. "Security" sounds like a good
>>>>>>>>>>> suggestion.
>>>>>>>>>>>> @Label("X509Cert")
>>>>>>>>>>>>
>>>>>>>>>>>> The label should be human readable name, with spaces, title
>>>>>>>>>>>> cased etc. I would recommend "X.509 Certificate". In
>>>>>>>>>>>> general, avoid abbreviations like "certs" and instead use
>>>>>>>>>>>> labels such as "Certificate Chain". The label should be
>>>>>>>>>>>> short and not a full sentence.
>>>>>>>>>>>>
>>>>>>>>>>>> For details see,
>>>>>>>>>>>> https://docs.oracle.com/javase/10/docs/api/jdk/jfr/Label.html
>>>>>>>>>>>>
>>>>>>>>>>>> I think it would be good to separate testing of JFR and
>>>>>>>>>>>> logging into different files / tests. I would prefer that
>>>>>>>>>>>> the test name is the same as the event prefixed with
>>>>>>>>>>>> "Test", i.e TestX509CertificateEvent, as this is the
>>>>>>>>>>>> pattern used by other JFR tests.
>>>>>>>>>>>>
>>>>>>>>>>> I'll take a look at that pattern again. I've separated out
>>>>>>>>>>> the current tests into an (a) outer test to analyze the
>>>>>>>>>>> logger output and (b) the inner test which checks for JFR
>>>>>>>>>>> correctness. I did include extra logic to make sure that the
>>>>>>>>>>> EventHelper configuration was working correctly.
>>>>>>>>>>> "Events.assertField" looks very helpful. Thanks for the
>>>>>>>>>>> pointer.
>>>>>>>>>>>
>>>>>>>>>>> Let me take on board the suggestions below and get a new
>>>>>>>>>>> webrev out on Tuesday.
>>>>>>>>>>>
>>>>>>>>>>> regards,
>>>>>>>>>>> Sean.
>>>>>>>>>>>
>>>>>>>>>>>> I reworked one of the tests to how I like to see it:
>>>>>>>>>>>>
>>>>>>>>>>>> /*
>>>>>>>>>>>> * @test
>>>>>>>>>>>> * @key jfr
>>>>>>>>>>>> * @library /test/lib
>>>>>>>>>>>> * @run main/othervm
>>>>>>>>>>>> jdk.jfr.event.security.TestX509CertificateEvent
>>>>>>>>>>>> */
>>>>>>>>>>>> public class TestX509CertificateEvent {
>>>>>>>>>>>>
>>>>>>>>>>>> private static final String CERTIFICATE_1 = "...";
>>>>>>>>>>>> private static final String CERTIFICATE_2 = "...";
>>>>>>>>>>>>
>>>>>>>>>>>> public static void main(String... args) throws
>>>>>>>>>>>> CertificateException {
>>>>>>>>>>>>
>>>>>>>>>>>> Recording r = new Recording();
>>>>>>>>>>>> r.enable(EventNames.X509Certificate).withoutStackTrace();
>>>>>>>>>>>> r.start();
>>>>>>>>>>>>
>>>>>>>>>>>> CertificateFactory cf =
>>>>>>>>>>>> CertificateFactory.getInstance("X.509");
>>>>>>>>>>>> cf.generateCertificate(new
>>>>>>>>>>>> ByteArrayInputStream(CERTIFICATE_1.getBytes()));
>>>>>>>>>>>> cf.generateCertificate(new
>>>>>>>>>>>> ByteArrayInputStream(CERTIFICATE_2.getBytes()));
>>>>>>>>>>>>
>>>>>>>>>>>> // Make sure only one event per certificate
>>>>>>>>>>>> cf.generateCertificate(new
>>>>>>>>>>>> ByteArrayInputStream(CERTIFICATE_1.getBytes()));
>>>>>>>>>>>> cf.generateCertificate(new
>>>>>>>>>>>> ByteArrayInputStream(CERTIFICATE_2.getBytes()));
>>>>>>>>>>>>
>>>>>>>>>>>> r.stop();
>>>>>>>>>>>>
>>>>>>>>>>>> List<RecordedEvent> events = Events.fromRecording(r);
>>>>>>>>>>>> Asserts.assertEquals(events.size(), 2, "Expected
>>>>>>>>>>>> two X.509 Certificate events");
>>>>>>>>>>>>
>>>>>>>>>>>> assertEvent(events, "1000", "SHA256withRSA",
>>>>>>>>>>>> "CN=SSLCertificate, O=SomeCompany",
>>>>>>>>>>>> "CN=Intermediate CA Cert, O=SomeCompany",
>>>>>>>>>>>> "RSA", 2048);
>>>>>>>>>>>> assertEvent(events, "1000", "SHA256withRSA",
>>>>>>>>>>>> "CN=SSLCertificate, O=SomeCompany",
>>>>>>>>>>>> "CN=Intermediate CA Cert, O=SomeCompany",
>>>>>>>>>>>> "RSA", 2048);
>>>>>>>>>>>> }
>>>>>>>>>>>>
>>>>>>>>>>>> private static void assertEvent(List<RecordedEvent>
>>>>>>>>>>>> events, String certID, String algId, String subject,
>>>>>>>>>>>> String issuer, String keyType, int length)
>>>>>>>>>>>> throws Exception {
>>>>>>>>>>>>
>>>>>>>>>>>> for (RecordedEvent e : events) {
>>>>>>>>>>>> if (e.getString("serialNumber").equals(certID)) {
>>>>>>>>>>>> Events.assertField(e, "algId").equal(algId);
>>>>>>>>>>>> ...
>>>>>>>>>>>> return;
>>>>>>>>>>>> }
>>>>>>>>>>>> }
>>>>>>>>>>>> System.out.println(events);
>>>>>>>>>>>> throw new Exception("Could not find event with Cert
>>>>>>>>>>>> ID: " + certID);
>>>>>>>>>>>> }
>>>>>>>>>>>> }
>>>>>>>>>>>>
>>>>>>>>>>>> The reworked example uses the Events.assertField method,
>>>>>>>>>>>> which will give context if the assertion fails. Keeping the
>>>>>>>>>>>> test simple, means it can be analyzed quickly if it fails
>>>>>>>>>>>> in testing. There is no new test framework to learn, or
>>>>>>>>>>>> methods to search for, and it is usually not hard to
>>>>>>>>>>>> determine if the failure is product, test or infrastructure
>>>>>>>>>>>> related, and what component (team) should be assigned the
>>>>>>>>>>>> issue. The use of EventNames.X509Certificate means all
>>>>>>>>>>>> occurrences of the event can be tracked done in an IDE
>>>>>>>>>>>> using find by reference.
>>>>>>>>>>>>
>>>>>>>>>>>> Thanks
>>>>>>>>>>>> Erik
>>>>>>>>>>>>
>>>>>>>>>>>>> Following on from the recent JDK-8203629 code review, I'd
>>>>>>>>>>>>> like to propose enhancements on how we can record events
>>>>>>>>>>>>> in security libs. The introduction of the JFR libraries
>>>>>>>>>>>>> can give us much better ways of examining JDK actions. For
>>>>>>>>>>>>> the initial phase, I'm looking to enhance some key
>>>>>>>>>>>>> security library events in JDK 11 so that they can be
>>>>>>>>>>>>> either recorded to JFR, logged to a traditional logger, or
>>>>>>>>>>>>> both.
>>>>>>>>>>>>>
>>>>>>>>>>>>> Examples of how useful JFR recordings could be can be seen
>>>>>>>>>>>>> here :
>>>>>>>>>>>>>
>>>>>>>>>>>>> http://cr.openjdk.java.net/~coffeys/event_snaps/X509Event_1.png
>>>>>>>>>>>>>
>>>>>>>>>>>>> http://cr.openjdk.java.net/~coffeys/event_snaps/securityProp_1.png
>>>>>>>>>>>>>
>>>>>>>>>>>>> http://cr.openjdk.java.net/~coffeys/event_snaps/securityProp_2.png
>>>>>>>>>>>>>
>>>>>>>>>>>>> http://cr.openjdk.java.net/~coffeys/event_snaps/TLSEvent_1.png
>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>> securityProp_2.png gives an example of how the JFR
>>>>>>>>>>>>> recording can be queried to quickly locate events of
>>>>>>>>>>>>> interest (in this case, code setting the jdk.tls.*
>>>>>>>>>>>>> Security properties). I still need to clean up the
>>>>>>>>>>>>> TLSEvents testcase to improve test coverage and hope to do
>>>>>>>>>>>>> that in coming days.
>>>>>>>>>>>>>
>>>>>>>>>>>>> JBS record :
>>>>>>>>>>>>> * https://bugs.openjdk.java.net/browse/JDK-8148188
>>>>>>>>>>>>>
>>>>>>>>>>>>> webrev :
>>>>>>>>>>>>> http://cr.openjdk.java.net/~coffeys/webrev.8148188.v1/webrev/
>>>>>>>>>>>>>
>
More information about the security-dev
mailing list