RFR: 8148188: Enhance the security libraries to record events of interest

Seán Coffey sean.coffey at oracle.com
Fri Jun 29 15:34:25 UTC 2018


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.

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.

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 core-libs-dev mailing list