8051959: Add thread and timestamp options to java.security.debug system property #18084

coffeys · 2024-03-01T15:13:49Z

Proposal to improve the java.security.debug output so that options exist to add thread ID, thread name, source of log record and a timestamp information to the output.

examples:
format without patch :

properties: Initial security property: package.definition=sun.misc.,sun.reflect.
properties: Initial security property: krb5.kdc.bad.policy=tryLast 
keystore: Creating a new keystore in PKCS12 format

format with thread info included:

properties[10|main|Security.java:122]: Initial security property: package.definition=sun.misc.,sun.reflect.
properties[10|main|Security.java:122]: Initial security property: krb5.kdc.bad.policy=tryLast 
keystore[10|main|KeyStoreDelegator.java:216]: Creating a new keystore in PKCS12 format

format with thread info and timestamp:

properties[10|main|Security.java:122|2024-03-01 14:59:42.859 UTC]: Initial security property: package.definition=sun.misc.,sun.reflect.
properties[10|main|Security.java:122|2024-03-01 14:59:42.859 UTC]: Initial security property: krb5.kdc.bad.policy=tryLast

It's a similar format to what can be seen when the TLS (javax.net.debug) debug logging option is in use

current proposal is to keep the thread and timestamp information off (make it opt in)

The extra decorator info is controlled by appending option to each component specified in the "java.security.debug" option list.

e.g

-Djava.security.debug=properties+timestamp+thread turns on logging for the properties component and also decorates the records with timestamp and thread info

-Djava.security.debug=properties+thread+timestamp,keystore would decorate the properties component but no decorating performed for the keystore component.

Progress

Change must be properly reviewed (1 review required, with at least 1 Reviewer)
Change requires CSR request JDK-8327569 to be approved
Change must not contain extraneous whitespace
Commit message must refer to an issue

Issues

JDK-8051959: Add thread and timestamp options to java.security.debug system property (Enhancement - P4)
JDK-8327569: Add thread and timestamp options to java.security.debug system property (CSR)

Reviewers

Sean Mullan (@seanjmullan - Reviewer) ⚠️ Review applies to d89308b5
Weijun Wang (@wangweij - Reviewer)

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.org/jdk.git pull/18084/head:pull/18084
$ git checkout pull/18084

Update a local copy of the PR:
$ git checkout pull/18084
$ git pull https://git.openjdk.org/jdk.git pull/18084/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 18084

View PR using the GUI difftool:
$ git pr show -t 18084

Using diff file

Download this PR as a diff file:
https://git.openjdk.org/jdk/pull/18084.diff

Webrev

Link to Webrev Comment

bridgekeeper · 2024-03-01T15:14:41Z

👋 Welcome back coffeys! A progress list of the required criteria for merging this PR into master will be added to the body of your pull request. There are additional pull request commands available for use with this pull request.

openjdk · 2024-03-01T15:16:11Z

@coffeys The following label will be automatically applied to this pull request:

security

When this pull request is ready to be reviewed, an "RFR" email will be sent to the corresponding mailing list. If you would like to change these labels, use the /label pull request command.

mlbridge · 2024-03-01T15:19:05Z

Webrevs

AlanBateman · 2024-03-01T15:25:57Z

src/java.base/share/classes/sun/security/util/Debug.java

+        String retString = "";
+        if (printThreadDetails) {
+            retString = toHexString(Thread.currentThread().threadId()) + "|" +
+                    Thread.currentThread().getName() + "|" + formatCaller();


The thread ID is in decimal in the default string representation of thread, also other diagnostic features such as the new thread dump. So I think you want to change this to "#" + Thread.currentThread().threadId().

Thanks Alan. Today, the TLS javax.net.debug logging prints the thread ID in hex format. I was repeating behaviour seen from that impl. Having java.security.debug output in decimal and the other in hex would prove confusing. We could consider flipping both to decimal format in a follow on patch.

Change it here, or in a later PR is okay. Main thing is that the logs are confusing then the Thread string is "#" but the TLS debug logs are different.

ecki · 2024-03-06T16:45:20Z

src/java.base/share/classes/sun/security/util/Debug.java

+
+    }
+
+    // copied from sun/security/ssl/Utilities.java for now


Why own helper, string.format(%x) can build the whole string or call Long.toHexString() or toString(,16)?

I was emulating what's done for the TLS logging code. Yes - I'll look at using a JDK library method instead.

ecki · 2024-03-06T16:52:42Z

src/java.base/share/classes/sun/security/util/Debug.java


    public void println()
    {
-        System.err.println(prefix + ":");


While we are her we could switch to Platfom logger, that also removes the need for timestamps (and thread info)

I'm thinking along the same lines. the javax.net.debug property (TLS) already allows the use of System Logger. I'd be interested to hear from anyone who uses that Logger, by passing no args to javax.net.debug. No reason why this (java.security.debug) code couldn't be updated also. I'd like to do this in a follow on (hoping to backport this patch to LTS update releases)

I think the Logger experience could do with tweaking also - something I spoke briefly about at the recent OpenJDK Committers' Workshop in Brussels. One option might be a mechanism where the Logger Level can be dialed up and down remotely (e.g. jconsole). I've been looking at this with the PlatformLoggingMXBean.setLoggerLevel operation.

seanjmullan

Some initial comments.

seanjmullan · 2024-03-13T19:27:17Z

src/java.base/share/classes/sun/security/util/Debug.java

+        System.err.println("+timestamp can be appended to any of above options to print");
+        System.err.println("              a timestamp for that debug option");
+        System.err.println("+thread can be appended to any of above options to print");
+        System.err.println("              thread information for that debug option");
+        System.err.println();


Would it be more reasonable to place these lines after line 113 ("x509") which are the main options?

yes - can do.

seanjmullan · 2024-03-13T19:30:40Z

src/java.base/share/classes/sun/security/util/Debug.java

            args = marshal(args);
            if (args.equals("help")) {
                Help();
+            } else if (args.contains("all")) {


Suggest adding a comment explaining why you need to treat all specially here.

good point - will update in next commit

seanjmullan · 2024-03-13T19:35:28Z

src/java.base/share/classes/sun/security/util/Debug.java

+            d.printThreadDetails = getConfigInfo(option, "+thread");
+            d.printDateTime = getConfigInfo(option, "+timestamp");
+            if (d.printDateTime && !dateTimeFormatInitialized) {
+                // trigger loading of Locale service impl now to avoid


You may want to try the test case added in JDK-8280890 with debugging enabled to make sure you don't get a similar recursion issue.

interesting - I did add -Djava,security.debug=all to the internals of that test and see issues.

However - they're issues that exist even without my patch. I need to take a closer look. sun.util.locale.provider.LocaleServiceProviderPool doesn't like to be invoked too early. That's a concern - maybe it should be able to handle such scenarios and return a simple/default Locale provider.

Caused by: java.lang.IllegalStateException: getSystemClassLoader cannot be called during the system class loader instantiation at java.lang.ClassLoader.getSystemClassLoader([java.base@23-ea](mailto:java.base@23-ea)/ClassLoader.java:1952) at java.lang.ClassLoader.getSystemResources([java.base@23-ea](mailto:java.base@23-ea)/ClassLoader.java:1723) at java.util.ServiceLoader$LazyClassPathLookupIterator.nextProviderClass([java.base@23-ea](mailto:java.base@23-ea)/ServiceLoader.java:1189) at java.util.ServiceLoader$LazyClassPathLookupIterator.hasNextService([java.base@23-ea](mailto:java.base@23-ea)/ServiceLoader.java:1224) at java.util.ServiceLoader$LazyClassPathLookupIterator.hasNext([java.base@23-ea](mailto:java.base@23-ea)/ServiceLoader.java:1269) at java.util.ServiceLoader$2.hasNext([java.base@23-ea](mailto:java.base@23-ea)/ServiceLoader.java:1305) at java.util.ServiceLoader$3.hasNext([java.base@23-ea](mailto:java.base@23-ea)/ServiceLoader.java:1387) at sun.util.cldr.CLDRLocaleProviderAdapter.lambda$new$0([java.base@23-ea](mailto:java.base@23-ea)/CLDRLocaleProviderAdapter.java:84) at java.security.AccessController.doPrivileged([java.base@23-ea](mailto:java.base@23-ea)/AccessController.java:571) at sun.util.cldr.CLDRLocaleProviderAdapter.<init>([java.base@23-ea](mailto:java.base@23-ea)/CLDRLocaleProviderAdapter.java:83) at jdk.internal.reflect.DirectConstructorHandleAccessor.newInstance([java.base@23-ea](mailto:java.base@23-ea)/DirectConstructorHandleAccessor.java:62) at java.lang.reflect.Constructor.newInstanceWithCaller([java.base@23-ea](mailto:java.base@23-ea)/Constructor.java:502) at java.lang.reflect.Constructor.newInstance([java.base@23-ea](mailto:java.base@23-ea)/Constructor.java:486) at sun.util.locale.provider.LocaleProviderAdapter.forType([java.base@23-ea](mailto:java.base@23-ea)/LocaleProviderAdapter.java:182) at sun.util.locale.provider.LocaleServiceProviderPool.findProviders([java.base@23-ea](mailto:java.base@23-ea)/LocaleServiceProviderPool.java:311) at sun.util.locale.provider.LocaleServiceProviderPool.getLocalizedObjectImpl([java.base@23-ea](mailto:java.base@23-ea)/LocaleServiceProviderPool.java:283) at sun.util.locale.provider.LocaleServiceProviderPool.getLocalizedObject([java.base@23-ea](mailto:java.base@23-ea)/LocaleServiceProviderPool.java:245) at sun.util.locale.provider.TimeZoneNameUtility.retrieveDisplayNamesImpl([java.base@23-ea](mailto:java.base@23-ea)/TimeZoneNameUtility.java:197) at sun.util.locale.provider.TimeZoneNameUtility.retrieveDisplayName([java.base@23-ea](mailto:java.base@23-ea)/TimeZoneNameUtility.java:150) at java.util.TimeZone.getDisplayName([java.base@23-ea](mailto:java.base@23-ea)/TimeZone.java:430) at java.util.Date.toString([java.base@23-ea](mailto:java.base@23-ea)/Date.java:1045) at java.lang.String.valueOf([java.base@23-ea](mailto:java.base@23-ea)/String.java:4509) at java.lang.StringBuilder.append([java.base@23-ea](mailto:java.base@23-ea)/StringBuilder.java:173) at sun.security.x509.CertificateValidity.toString([java.base@23-ea](mailto:java.base@23-ea)/CertificateValidity.java:118) at java.lang.String.valueOf([java.base@23-ea](mailto:java.base@23-ea)/String.java:4509) at java.lang.StringBuilder.append([java.base@23-ea](mailto:java.base@23-ea)/StringBuilder.java:173) at sun.security.x509.X509CertInfo.toString([java.base@23-ea](mailto:java.base@23-ea)/X509CertInfo.java:221) at java.lang.String.valueOf([java.base@23-ea](mailto:java.base@23-ea)/String.java:4509) at java.lang.StringBuilder.append([java.base@23-ea](mailto:java.base@23-ea)/StringBuilder.java:173) at sun.security.x509.X509CertImpl.toString([java.base@23-ea](mailto:java.base@23-ea)/X509CertImpl.java:560) at java.lang.String.valueOf([java.base@23-ea](mailto:java.base@23-ea)/String.java:4509) at java.lang.StringBuilder.append([java.base@23-ea](mailto:java.base@23-ea)/StringBuilder.java:173) at sun.security.util.SignatureFileVerifier.getSigners([java.base@23-ea](mailto:java.base@23-ea)/SignatureFileVerifier.java:742) at sun.security.util.SignatureFileVerifier.processImpl([java.base@23-ea](mailto:java.base@23-ea)/SignatureFileVerifier.java:312) at sun.security.util.SignatureFileVerifier.process([java.base@23-ea](mailto:java.base@23-ea)/SignatureFileVerifier.java:281) at java.util.jar.JarVerifier.processEntry([java.base@23-ea](mailto:java.base@23-ea)/JarVerifier.java:320) at java.util.jar.JarVerifier.update([java.base@23-ea](mailto:java.base@23-ea)/JarVerifier.java:232) at java.util.jar.JarFile.initializeVerifier([java.base@23-ea](mailto:java.base@23-ea)/JarFile.java:760) at java.util.jar.JarFile.getInputStream([java.base@23-ea](mailto:java.base@23-ea)/JarFile.java:858) at jdk.internal.loader.URLClassPath$JarLoader$2.getInputStream([java.base@23-ea](mailto:java.base@23-ea)/URLClassPath.java:837) at jdk.internal.loader.Resource.cachedInputStream([java.base@23-ea](mailto:java.base@23-ea)/Resource.java:77) at jdk.internal.loader.Resource.getByteBuffer([java.base@23-ea](mailto:java.base@23-ea)/Resource.java:163) at jdk.internal.loader.BuiltinClassLoader.defineClass([java.base@23-ea](mailto:java.base@23-ea)/BuiltinClassLoader.java:853) at jdk.internal.loader.BuiltinClassLoader.findClassOnClassPathOrNull([java.base@23-ea](mailto:java.base@23-ea)/BuiltinClassLoader.java:760) at jdk.internal.loader.BuiltinClassLoader.loadClassOrNull([java.base@23-ea](mailto:java.base@23-ea)/BuiltinClassLoader.java:681) at jdk.internal.loader.BuiltinClassLoader.loadClass([java.base@23-ea](mailto:java.base@23-ea)/BuiltinClassLoader.java:639) at jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass([java.base@23-ea](mailto:java.base@23-ea)/ClassLoaders.java:188) at java.lang.ClassLoader.loadClass([java.base@23-ea](mailto:java.base@23-ea)/ClassLoader.java:528) at java.lang.Class.forName0([java.base@23-ea](mailto:java.base@23-ea)/Native Method) at java.lang.Class.forName([java.base@23-ea](mailto:java.base@23-ea)/Class.java:578) at java.lang.Class.forName([java.base@23-ea](mailto:java.base@23-ea)/Class.java:557) at java.lang.ClassLoader.initSystemClassLoader([java.base@23-ea](mailto:java.base@23-ea)/ClassLoader.java:1997) at java.lang.System.initPhase3([java.base@23-ea](mailto:java.base@23-ea)/System.java:2338)

Interesting. It seems any attempt to calls like Date.toString() early on that triggers a TimeZone lookup is going to potentially cause this. A possible workaround is to change CertificateValidity.toString() to emit dates as Date.toInstant().toString() which is similar to what I did in the fix for JDK-8280890. But this is a separate issue.

openjdk · 2024-03-13T20:12:00Z

@coffeys This change now passes all automated pre-integration checks.

ℹ️ This project also has non-automated pre-integration requirements. Please see the file CONTRIBUTING.md for details.

After integration, the commit message for the final commit will be:

8051959: Add thread and timestamp options to java.security.debug system property

Reviewed-by: mullan, weijun

You can use pull request commands such as /summary, /contributor and /issue to adjust it as needed.

At the time when this comment was updated there had been 141 new commits pushed to the master branch:

20cb6e7: 8329337: Problem list BufferStrategyExceptionTest.java on Windows
d1b51e3: 8321550: Update several runtime/cds tests to use vm flags or mark as flagless
8a0ef81: 8326627: Document Double/Float.valueOf(String) behavior for numeric strings with non-ASCII digits
5b05f8e: 8329112: Clean up CDS checking of unsupported module options
59c2aff: 8323624: ProviderList.ServiceList does not need to be a list
418deaf: 8328361: Use memset() in method CardTable::dirty_MemRegion()
245514d: 8328953: JEditorPane.read throws ChangedCharSetException
df01cc5: 8323576: [Windows] Fallthrough to ::abort instead of os::infinite_sleep for noreturn methods
bf93e77: 8329118: Run MessageFormat additional subformat pattern tests under en_US locale
991e04e: 8327383: Clean up _Stalled and _Spinner fields
... and 131 more: https://git.openjdk.org/jdk/compare/d3f3011d56267360d65841da3550eca79cf1575b...master

As there are no conflicts, your changes will automatically be rebased on top of these commits when integrating. If you prefer to avoid this automatic rebasing, please check the documentation for the /integrate command for further details.

➡️ To integrate this PR with the above commit message to the master branch, type /integrate in a new comment.

ecki · 2024-03-15T11:52:41Z

src/java.base/share/classes/sun/security/util/Debug.java

-            retString = toHexString(Thread.currentThread().threadId()) + "|" +
-                    Thread.currentThread().getName() + "|" + formatCaller();
+            retString = "0x" + Long.toHexString(
+                    Thread.currentThread().threadId()).toUpperCase(Locale.ROOT) +


mmhh.. i can understand the desire to unify casing, but maybe changing the other logs to use javas default casing for hex (instead of changing it here) makes the code faster and better to read?
(Not sure if StringBuilder optimization (including starting with [) would be worth the complication)

seanjmullan · 2024-03-15T17:27:06Z

Suggest changing the title of the issue to "Add thread and timestamp options to java.security.debug system property"

seanjmullan · 2024-03-18T17:36:20Z

src/java.base/share/classes/sun/security/util/Debug.java

+        System.err.println("+timestamp can be appended to any of above options to print");
+        System.err.println("              a timestamp for that debug option");
+        System.err.println("+thread can be appended to any of above options to print");
+        System.err.println("              thread information for that debug option");


How about mentioning caller too? "thread and caller information ..."

seanjmullan · 2024-03-18T17:39:13Z

src/java.base/share/classes/sun/security/util/Debug.java

+                threadInfoAll = args.substring(beginIndex, commaIndex).contains("+thread");;
+                timeStampInfoAll = args.substring(beginIndex, commaIndex).contains("+timestamp");;


extra semi-colon at end of line.

…e krb5 test

coffeys · 2024-03-21T19:41:39Z

@wangweij
Updated the PR to incorporate extra changes as a result JDK-8327818
Would appreciate if you can take a look

wangweij · 2024-03-21T20:38:22Z

src/java.base/share/classes/sun/security/util/Debug.java

+        printDateTime = getConfigInfo(option, "+timestamp", ofInstance);
+        if (printDateTime && !dateTimeFormatInitialized) {
+            // trigger loading of Locale service impl now to avoid
+            // possible bootstrap recursive class load issue


Does this need to be manually loaded? I thought the FormatHolder field will be automatically loaded when it's first accessed and only once.

It's still necessary I'm afraid. During an early classloader operation, the Security class can be triggered which causes security properties to be read. If debugging is enabled, this triggers loading of CLDR service. Quite a long stack trace but I'll paste it here for history.

I agree on your other comments - I'll try a clean up and will come back to you then.

stderr: [Error: A JNI error has occurred, please check your installation and try again Exception in thread "main" java.util.ServiceConfigurationError: Locale provider adapter "CLDR"cannot be instantiated. at java.base/sun.util.locale.provider.LocaleProviderAdapter.forType(LocaleProviderAdapter.java:193) at java.base/sun.util.locale.provider.LocaleServiceProviderPool.findProviders(LocaleServiceProviderPool.java:311) at java.base/sun.util.locale.provider.LocaleServiceProviderPool.getLocalizedObjectImpl(LocaleServiceProviderPool.java:283) at java.base/sun.util.locale.provider.LocaleServiceProviderPool.getLocalizedObject(LocaleServiceProviderPool.java:245) at java.base/sun.util.locale.provider.TimeZoneNameUtility.retrieveDisplayNamesImpl(TimeZoneNameUtility.java:197) at java.base/sun.util.locale.provider.TimeZoneNameUtility.retrieveDisplayNames(TimeZoneNameUtility.java:120) at java.base/java.time.format.DateTimeFormatterBuilder$ZoneTextPrinterParser.getDisplayName(DateTimeFormatterBuilder.java:4484) at java.base/java.time.format.DateTimeFormatterBuilder$ZoneTextPrinterParser.format(DateTimeFormatterBuilder.java:4535) at java.base/java.time.format.DateTimeFormatterBuilder$CompositePrinterParser.format(DateTimeFormatterBuilder.java:2537) at java.base/java.time.format.DateTimeFormatter.formatTo(DateTimeFormatter.java:1905) at java.base/java.time.format.DateTimeFormatter.format(DateTimeFormatter.java:1879) at java.base/sun.security.util.Debug.extraInfo(Debug.java:345) at java.base/sun.security.util.Debug.println(Debug.java:299) at java.base/java.security.Security.loadProps(Security.java:161) at java.base/java.security.Security.initialize(Security.java:103) at java.base/java.security.Security.lambda$static$0(Security.java:84) at java.base/java.security.AccessController.doPrivileged(AccessController.java:319) at java.base/java.security.Security.<clinit>(Security.java:83) at java.base/sun.security.util.SecurityProperties.getOverridableProperty(SecurityProperties.java:57) at java.base/sun.security.util.SecurityProperties.privilegedGetOverridable(SecurityProperties.java:48) at java.base/sun.security.util.SecurityProperties.includedInExceptions(SecurityProperties.java:72) at java.base/sun.security.util.SecurityProperties.<clinit>(SecurityProperties.java:36) at java.base/sun.security.util.FilePermCompat.<clinit>(FilePermCompat.java:43) at java.base/java.io.FilePermission.init(FilePermission.java:319) at java.base/java.io.FilePermission.<init>(FilePermission.java:490) at java.base/sun.net.www.protocol.file.FileURLConnection.getPermission(FileURLConnection.java:223) at java.base/sun.security.util.LazyCodeSourcePermissionCollection.ensureAdded(LazyCodeSourcePermissionCollection.java:69) at java.base/sun.security.util.LazyCodeSourcePermissionCollection.toString(LazyCodeSourcePermissionCollection.java:115) at java.base/java.lang.String.valueOf(String.java:4509) at java.base/java.lang.StringBuilder.append(StringBuilder.java:173) at java.base/java.security.ProtectionDomain.toString(ProtectionDomain.java:434) at java.base/java.lang.String.valueOf(String.java:4509) at java.base/java.lang.StringBuilder.append(StringBuilder.java:173) at java.base/java.security.SecureClassLoader$1.apply(SecureClassLoader.java:231) at java.base/java.security.SecureClassLoader$1.apply(SecureClassLoader.java:222) at java.base/java.util.concurrent.ConcurrentHashMap.computeIfAbsent(ConcurrentHashMap.java:1713) at java.base/java.security.SecureClassLoader.getProtectionDomain(SecureClassLoader.java:222) at java.base/java.security.SecureClassLoader.defineClass(SecureClassLoader.java:150) at java.base/jdk.internal.loader.BuiltinClassLoader.defineClass(BuiltinClassLoader.java:862) at java.base/jdk.internal.loader.BuiltinClassLoader.findClassOnClassPathOrNull(BuiltinClassLoader.java:760) at java.base/jdk.internal.loader.BuiltinClassLoader.loadClassOrNull(BuiltinClassLoader.java:681) at java.base/jdk.internal.loader.BuiltinClassLoader.loadClass(BuiltinClassLoader.java:639) at java.base/jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(ClassLoaders.java:188) at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:528) at java.base/java.lang.Class.forName0(Native Method) at java.base/java.lang.Class.forName(Class.java:578) at java.base/java.lang.Class.forName(Class.java:557) at java.base/sun.launcher.LauncherHelper.loadMainClass(LauncherHelper.java:847) at java.base/sun.launcher.LauncherHelper.checkAndLoadMain(LauncherHelper.java:732) Caused by: java.lang.reflect.InvocationTargetException at java.base/jdk.internal.reflect.DirectConstructorHandleAccessor.newInstance(DirectConstructorHandleAccessor.java:74) at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:502) at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:486) at java.base/sun.util.locale.provider.LocaleProviderAdapter.forType(LocaleProviderAdapter.java:182) ... 48 more Caused by: java.util.ServiceConfigurationError: Locale provider adapter "CLDR"cannot be instantiated. at java.base/sun.util.locale.provider.LocaleProviderAdapter.forType(LocaleProviderAdapter.java:193) at java.base/sun.util.locale.provider.LocaleServiceProviderPool.findProviders(LocaleServiceProviderPool.java:311) at java.base/sun.util.locale.provider.LocaleServiceProviderPool.getLocalizedObjectImpl(LocaleServiceProviderPool.java:283) at java.base/sun.util.locale.provider.LocaleServiceProviderPool.getLocalizedObject(LocaleServiceProviderPool.java:245) at java.base/sun.util.locale.provider.TimeZoneNameUtility.retrieveDisplayNamesImpl(TimeZoneNameUtility.java:197) at java.base/sun.util.locale.provider.TimeZoneNameUtility.retrieveDisplayNames(TimeZoneNameUtility.java:120) at java.base/java.time.format.DateTimeFormatterBuilder$ZoneTextPrinterParser.getDisplayName(DateTimeFormatterBuilder.java:4484) at java.base/java.time.format.DateTimeFormatterBuilder$ZoneTextPrinterParser.format(DateTimeFormatterBuilder.java:4535) at java.base/java.time.format.DateTimeFormatterBuilder$CompositePrinterParser.format(DateTimeFormatterBuilder.java:2537) at java.base/java.time.format.DateTimeFormatter.formatTo(DateTimeFormatter.java:1905) at java.base/java.time.format.DateTimeFormatter.format(DateTimeFormatter.java:1879) at java.base/sun.security.util.Debug.extraInfo(Debug.java:345) at java.base/sun.security.util.Debug.println(Debug.java:299) at java.base/java.security.SecureClassLoader$1.apply(SecureClassLoader.java:231) at java.base/java.security.SecureClassLoader$1.apply(SecureClassLoader.java:222) at java.base/java.util.concurrent.ConcurrentHashMap.computeIfAbsent(ConcurrentHashMap.java:1713) at java.base/java.security.SecureClassLoader.getProtectionDomain(SecureClassLoader.java:222) at java.base/java.security.SecureClassLoader.defineClass(SecureClassLoader.java:182) at java.base/jdk.internal.loader.BuiltinClassLoader.defineClass(BuiltinClassLoader.java:821) at java.base/jdk.internal.loader.BuiltinClassLoader.findClassInModuleOrNull(BuiltinClassLoader.java:741) at java.base/jdk.internal.loader.BuiltinClassLoader.findClass(BuiltinClassLoader.java:621) at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:640) at java.base/java.lang.Class.forName(Class.java:669) at java.base/java.lang.Class.forName(Class.java:644) at java.base/java.util.ServiceLoader.loadProvider(ServiceLoader.java:855) at java.base/java.util.ServiceLoader$ModuleServicesLookupIterator.hasNext(ServiceLoader.java:1080) at java.base/java.util.ServiceLoader$2.hasNext(ServiceLoader.java:1309) at java.base/java.util.ServiceLoader$3.hasNext(ServiceLoader.java:1391) at java.base/sun.util.cldr.CLDRLocaleProviderAdapter.lambda$new$0(CLDRLocaleProviderAdapter.java:84) at java.base/java.security.AccessController.doPrivileged(AccessController.java:571) at java.base/sun.util.cldr.CLDRLocaleProviderAdapter.<init>(CLDRLocaleProviderAdapter.java:83) at java.base/jdk.internal.reflect.DirectConstructorHandleAccessor.newInstance(DirectConstructorHandleAccessor.java:62) ... 51 more Caused by: java.lang.reflect.InvocationTargetException at java.base/jdk.internal.reflect.DirectConstructorHandleAccessor.newInstance(DirectConstructorHandleAccessor.java:74) at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:502) at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:486) at java.base/sun.util.locale.provider.LocaleProviderAdapter.forType(LocaleProviderAdapter.java:182) ... 82 more Caused by: java.lang.IllegalStateException: Recursive update at java.base/java.util.concurrent.ConcurrentHashMap.computeIfAbsent(ConcurrentHashMap.java:1768) at java.base/java.security.SecureClassLoader.getProtectionDomain(SecureClassLoader.java:222) at java.base/java.security.SecureClassLoader.defineClass(SecureClassLoader.java:182) at java.base/jdk.internal.loader.BuiltinClassLoader.defineClass(BuiltinClassLoader.java:821) at java.base/jdk.internal.loader.BuiltinClassLoader.findClassInModuleOrNull(BuiltinClassLoader.java:741) at java.base/jdk.internal.loader.BuiltinClassLoader.findClass(BuiltinClassLoader.java:621) at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:640) at java.base/java.lang.Class.forName(Class.java:669) at java.base/java.lang.Class.forName(Class.java:644) at java.base/java.util.ServiceLoader.loadProvider(ServiceLoader.java:855) at java.base/java.util.ServiceLoader$ModuleServicesLookupIterator.hasNext(ServiceLoader.java:1080) at java.base/java.util.ServiceLoader$2.hasNext(ServiceLoader.java:1309) at java.base/java.util.ServiceLoader$3.hasNext(ServiceLoader.java:1391) at java.base/sun.util.cldr.CLDRLocaleProviderAdapter.lambda$new$0(CLDRLocaleProviderAdapter.java:84) at java.base/java.security.AccessController.doPrivileged(AccessController.java:571) at java.base/sun.util.cldr.CLDRLocaleProviderAdapter.<init>(CLDRLocaleProviderAdapter.java:83) at java.base/jdk.internal.reflect.DirectConstructorHandleAccessor.newInstance(DirectConstructorHandleAccessor.java:62) ... 85 more ]

Turns out that it's the java.time.format.DateTimeFormatterBuilder.ZoneTextPrinterParser#format call that triggers the early initialization of the CLDR service (via a getDisplayName call)

We can avoid this call if we print time data without timezone ID - i.e.
using a pattern of "yyyy-MM-dd kk:mm:ss.SSS" rather than "yyyy-MM-dd kk:mm:ss.SSS z"

example of change: (no UTC printed)
(with display name) :
properties[2024-03-22 09:55:48.985 UTC]: Initial security property: keystore.type.compat=true

(without):
properties[2024-03-22 09:55:48.985]: Initial security property: keystore.type.compat=true

I think we can live without the display name detail. Most logs relate to local timezone systems. It shortens the print also.

Yes, using local timezone is OK. Your new test adds a -Duser.timezone=UTC and I doubt anyone is likely to change that.

Back to my comment, I don't understand how this could fix the recursion. This check is also done very early and why doesn't that FormatHolder.DATE_TIME_FORMATTER.format(Instant.now()) trigger a similar error?

In fact, I just tried java -Djava.security.debug=all+timestamp sun.security.util.Debug and there is an error no matter the if block is there or not.

I'm running with an exploded build. Hopefully that makes no difference.

And, both case are fine if the Z is removed from PATTERN.

wangweij · 2024-03-21T20:38:37Z

src/java.base/share/classes/sun/security/util/Debug.java

+    }
+
+    // parse an option string to determine if extra details
+    // (like thread and timestamp) should be printed


I find this method (and maybe also configureOptions) a little confusing. The option argument is the option name for getInstance but the property value for of. You can see that in this method there is completely no shared code between ofInstance being true or false.

wangweij · 2024-03-21T20:38:55Z

src/java.base/share/classes/sun/security/util/Debug.java

     * }
-     * @param option the debug option name
+     * @param prefix the debug option name
     * @param property debug setting for this option


Please add some words on the format that propertycan take.

…dates

coffeys · 2024-03-22T16:44:23Z

Updates pushed to incorporate review comments to date. As mentioned, the CLDR JNI issue is triggered via the display name lookup (e.g. "UTC") - we can edit the date string format to not include this data. I've removed the early lookup workaround code as a result.

coffeys · 2024-03-29T15:11:46Z

@wangweij found a scenario where the String parsing in the configureExtras method may not work as expected. Thanks! Shouldn't assume that option String is contained in args String -- "all" value has special treatment.

Method patched and test coverage updated

coffeys · 2024-04-02T08:50:08Z

/integrate

openjdk · 2024-04-02T08:51:15Z

Going to push as commit 3b582df.
Since your change was applied there have been 160 commits pushed to the master branch:

816638e: 8329352: Remove dead code in splashscreen_sys.c
3d22838: 8328997: Remove unnecessary template parameter lists in GrowableArray
5cddc2d: 8325252: C2 SuperWord: refactor the packset
6b1b0e9: 8329103: assert(!thread->in_asgct()) failed during multi-mode profiling
bc546c2: 8328561: test java/awt/Robot/ManualInstructions/ManualInstructions.java isn't used
af7c6af: 8324808: Manual printer tests have no Pass/Fail buttons, instructions close set 3
d3fc8df: 8329135: Store Universe::*exception_instance() in CDS archive
a85c849: 8328273: sun/management/jmxremote/bootstrap/RmiRegistrySslTest.java failed with java.rmi.server.ExportException: Port already in use
70c8ff1: 8328665: serviceability/jvmti/vthread/PopFrameTest failed with a timeout
ecd2b71: 8329354: java/text/Format/MessageFormat/CompactSubFormats.java fails
... and 150 more: https://git.openjdk.org/jdk/compare/d3f3011d56267360d65841da3550eca79cf1575b...master

Your commit was automatically rebased without conflicts.

openjdk · 2024-04-02T08:51:20Z

@coffeys Pushed as commit 3b582df.

💡 You may see a message that your pull request was closed with unmerged commits. This can be safely ignored.

coffeys added 5 commits January 16, 2024 14:47

8051959

2722b38

Merge branch 'master' into 8051959-tracing

4948da1

Holder class idiom

6261cde

Merge branch 'master' into 8051959-tracing

11bf0b9

static dateTimeFormatInitialized

b679e56

openjdk bot changed the title ~~8051959~~ 8051959: Option to print thread information in java.security.debug output Mar 1, 2024

openjdk bot added the rfr Pull request is ready for review label Mar 1, 2024

openjdk bot added the security security-dev@openjdk.org label Mar 1, 2024

AlanBateman reviewed Mar 1, 2024

View reviewed changes

ecki reviewed Mar 6, 2024

View reviewed changes

use default hex output

d89308b

openjdk bot added the csr Pull request needs approved CSR before integration label Mar 7, 2024

unused variable

a06df78

seanjmullan reviewed Mar 13, 2024

View reviewed changes

coffeys changed the title ~~8051959: Option to print thread information in java.security.debug output~~ 8051959: Add decorator options for java.security.debug output Mar 14, 2024

ecki reviewed Mar 15, 2024

View reviewed changes

coffeys added 2 commits March 15, 2024 12:25

more test coverage

5e48ffb

Move help section higher. Add code comment

28558ea

coffeys mentioned this pull request Mar 15, 2024

8327818: Implement Kerberos debug with sun.security.util.Debug #18199

Closed

4 tasks

seanjmullan approved these changes Mar 18, 2024

View reviewed changes

coffeys added 3 commits March 20, 2024 15:39

Merge branch 'master' into 8051959-tracing

a9c8604

krb5 debug merge

4d95eee

merge in krb5 debug changes and implement extra functionality. enhanc…

5628bc2

…e krb5 test

coffeys changed the title ~~8051959: Add decorator options for java.security.debug output~~ 8051959: Add thread and timestamp options to java.security.debug system property Mar 21, 2024

wangweij reviewed Mar 21, 2024

View reviewed changes

Remove display name in format output. Simplify config checks. Test up…

e88e663

…dates

don't assume option string in args

e8f7021

wangweij approved these changes Mar 29, 2024

View reviewed changes

openjdk bot added ready Pull request is ready to be integrated and removed csr Pull request needs approved CSR before integration labels Mar 29, 2024

openjdk bot added the integrated Pull request has been integrated label Apr 2, 2024

openjdk bot closed this Apr 2, 2024

openjdk bot removed ready Pull request is ready to be integrated rfr Pull request is ready for review labels Apr 2, 2024

		threadInfoAll = args.substring(beginIndex, commaIndex).contains("+thread");;
		timeStampInfoAll = args.substring(beginIndex, commaIndex).contains("+timestamp");;

8051959: Add thread and timestamp options to java.security.debug system property #18084

8051959: Add thread and timestamp options to java.security.debug system property #18084

Uh oh!

Conversation

coffeys commented Mar 1, 2024 • edited by openjdk bot Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Progress

Issues

Reviewers

Reviewing

Webrev

Uh oh!

bridgekeeper bot commented Mar 1, 2024

Uh oh!

openjdk bot commented Mar 1, 2024

Uh oh!

mlbridge bot commented Mar 1, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Webrevs

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

seanjmullan left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

openjdk bot commented Mar 13, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

seanjmullan commented Mar 15, 2024

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

coffeys commented Mar 21, 2024

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

wangweij Mar 22, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

coffeys commented Mar 1, 2024 •

edited by openjdk bot

Loading

mlbridge bot commented Mar 1, 2024 •

edited

Loading

openjdk bot commented Mar 13, 2024 •

edited

Loading

wangweij Mar 22, 2024 •

edited

Loading