Definitely a deadlock in logging, reassigning to Jarda as author logging infrastructure.

As a workaround don't enable log from
private static Logger LOG = Logger.getLogger(LookupSensitiveAction.class.getName());

Actually, running with 
-J-Dorg.level=2147483647
which should (and in fact does) disable all logging for pretty much everything does not fix this deadlock - just switch between editor and projects tab a few times.  I'm really looking forward to demoing this deadlock for 4000 people day after tomorrow :-)

IMO, any logging API should be non-blocking, if there is *any* risk of having this sort of problem.  Timestamp records and queue them to be written on a background thread that can do it safely.

Created attachment 92189 [details]
Another thread dump

Another deadlock stack trace, same culprit.

Common pattern is that syntax highlighting stops working first - "Parsing and indexing thread" is already deadlocked with another thread.  Then the AWT thread joins the party...

Created attachment 92190 [details]
Deadlocks still happen in background threads with UI logging code deleted

Deleted the UI logging code in org.netbeans.modules.project.ui.actions.LookupSensitiveAction - so far AWT thread does not deadlock, but still getting deadlocks between other threads.

Uy!  I found the culprit.  Anki, assigning to you.  The deadlocks are caused by the Ant task calling offcardinstaller.Main in the Java Card RI, which calls either LogManager.getLogManager().reset() or LogManager.getLogManager().readConfiguration().

I can fix this for the demo with a patched TopSecurityManager that does some horrible unwind-the-stack stuff:
        if (LoggingPermission.class.isInstance(perm)) {
            Throwable t = new Exception().fillInStackTrace();
            for (StackTraceElement e : t.getStackTrace()) {
                if ("java.util.logging.LogManager".equals(e.getClassName()) && "reset".equals(e.getMethodName())) {
                    throw new SecurityException("Illegal attempt to reset system logger");
            ...

but LogManager uses the same Permission object to decide if you're allowed to create a new logger as it uses to completely rewire the JDK's logging system.  

Performance-wise, I expect my check in TopSecurityManager that blocks evil with the system logger can be allowed in production code, for performance reasons - doing this every time a logger is constructed will be expensive.

Jesse, Jarda, any other ideas how to block this Ant task from replacing NetBeans logger with one which will deadlock the IDE?  I.e. without the Java Card team having to change code a few days from release?

java.lang.Exception: Stack trace
        at java.lang.Thread.dumpStack(Thread.java:1206)
        at org.netbeans.TopSecurityManager.checkLogger(TopSecurityManager.java:414)
        at org.netbeans.TopSecurityManager.checkPermission(TopSecurityManager.java:369)
        at java.util.logging.LogManager.checkAccess(LogManager.java:960)
        at java.util.logging.LogManager.readConfiguration(LogManager.java:749)
        at com.sun.javacard.tools.util.JCToolsLogger.<init>(Unknown Source)
        at com.sun.javacard.tools.util.JCToolsLogger.getLogger(Unknown Source)
        at com.sun.javacard.cli.Tool.<init>(Unknown Source)
        at com.sun.javacard.offcardinstaller.Main.<init>(Unknown Source)
        at com.sun.javacard.offcardinstaller.Main.execute(Unknown Source)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at com.sun.javacard.nbtasks.CreateTask.execute(Unknown Source)
        at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:288)
        at sun.reflect.GeneratedMethodAccessor54.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:106)
        at org.apache.tools.ant.Task.perform(Task.java:348)
        at org.apache.tools.ant.Target.execute(Target.java:357)
        at org.apache.tools.ant.Target.performTasks(Target.java:385)
        at org.apache.tools.ant.Project.executeSortedTargets(Project.java:1337)
        at org.apache.tools.ant.Project.executeTarget(Project.java:1306)
        at org.apache.tools.ant.helper.DefaultExecutor.executeTargets(DefaultExecutor.java:41)
        at org.apache.tools.ant.Project.executeTargets(Project.java:1189)
        at org.apache.tools.ant.module.bridge.impl.BridgeImpl.run(BridgeImpl.java:278)
        at org.apache.tools.ant.module.run.TargetExecutor.run(TargetExecutor.java:498)
        at org.netbeans.core.execution.RunClassThread.run(RunClassThread.java:151)

Oops, forgot to actually assign this to you.  Anki, please read.

Created attachment 92192 [details]
Diff for TopSecurityManager to detect evil logger configuration twiddling

Attached is a patch to TopSecurityManager to detect attempts to reset the JDK's logger configuration.

It works well enough to make Java Card support demoable without deadlocking instantly, but because it has to construct an Exception and unwind its StackTraceElements, it is probably unsuitable for production code for performance reasons - this code will run every time Logger.getLogger() is called too.

Maybe there is a way to block this some other way, before launching an Ant process, without also blocking the ability of Ant tasks to use Loggers completely (which would probably just break everything)?  Say, at the ThreadGroup level where we run Ant tasks?

I would recommend the problem be fixed at the source in JavaCard. Either com.sun.javacard.offcardinstaller.Main.execute should not mess around with logger configs, or it should offer a variant which does not and the Ant task should call that, or the Ant task should call Main by forking a JVM process. It is almost certainly too late to do anything in core NB code for 6.8.


Regarding the patch as a possible way to better diagnose these kinds of problems in the future:


[JG01] To minimize cost, run these checks only when assertions are on (generally means only in dev builds), so that module developers will catch these problems but there is no performance penalty for regular users. (This is assuming that the cost is small enough to be bearable in dev builds; if too big, cannot be enabled by default anywhere.) Easiest is to return true from checkLogger and invoke as: assert checkLogger(perm);


[JG02] I think there is a more efficient way to do stack trace inspection from a SecurityManager. getClassContext or classDepth may be helpful. Not sure.


[JG03] Do not call 'se.printStackTrace()'; leave it up to higher code to decide whether and how to handle the SE.

Fixing in JavaCard tools by adding some check for netbeans.home system property.
Fix committed to javacard workspace. New build of RI will be available tomorrow.

Once Tim verifies this, we can close.

Okay, will commit the TopSecurityManager patch soon  with the suggested changes and we'll see if it causes too much of a performance penalty - easy enough to turn it off if necessary.

Possibly the check could be done with getClassContext(), by checking if LogManager.class.equals(getClassContext()[0]) && LogManager.class.equals(getClassContext()[1]) && !LogManager.class.equals(getClassContext()[1}) - but we'd have to be sure there is no legitimate call sequence that can match this pattern, that that will never change, and that that set of calling classes remains the correct pattern across future JDK versions - pretty fragile.

What is really needed is for LogManager to use a different Permission for creating Logger instances vs. reconfiguring the entire system - a JDK enhancement request would be worthwhile (probably a compatibility issue unless additional checks with more refined Permission objects are used for both cases).

Re printing the stack trace, ordinarily I would not do this, but this sort of exception is often swallowed completely by callers (part of why it took my four hours to track down the problem) - and it's definitely not the moment to call out to logger :-/  But easy enough not to do it.

Thanks, Anki, for dealing with the issue at the root, at the last minute :-)

(In reply to comment #11)
> a JDK enhancement request would be worthwhile

Good luck getting a Java API change implemented, but if you do file it, put jdk_bug_NNNNNNN in the status whiteboard here.

> this sort of exception is often swallowed completely by callers

True, but that should be fixed in the caller.

>> a JDK enhancement request would be worthwhile

> Good luck getting a Java API change implemented, but if you do file it, put
> jdk_bug_NNNNNNN in the status whiteboard here.

Yeah, we know the odds of that.

>> this sort of exception is often swallowed completely by callers

> True, but that should be fixed in the caller.

Agreed, but there seems to be some wrongheaded conventional wisdom out there that SecurityExceptions are somehow okay to swallow, for whatever reason (probably from reading ill-advised example code)

Created attachment 93205 [details]
JDK logger patch

Filed JDK bug 1694855 with a trivial application to demonstrate the problem.  

Will attach patch to LogManager which should backward compatibly make it possible to differentiate between Logger configuration calls vs. Logger usage calls here, since there is no way to attach it there until it becomes publicly visible.

Use --unified when asking diff for a patch.

AFAIK Anki removed the logger code from the final release of Java Card 3.0.2.  

I have committed the TopSecurityManager patch in main/ c6988726f41e

Hopefully the stack-dump test will not be too much of a performance penalty; currently it is on only if assertions are enabled;  if necessary, this can be switched to a system property.

Why 'LoggingPermission.class.isInstance(perm)' and not simply 'perm instanceof LoggingPermission' (simpler and faster)?


The check '"java.util.logging.LogManager".equals(e.getClassName())' should be done only once, not twice in sequence.


Conventional way of expecting an exception in a test:

try {
  LogManager.getLogManager().readConfiguration(...);
  fail("...");
} catch (SecurityException e) {/* OK */}

Integrated into 'main-golden', will be available in build *201001150201* on http://bits.netbeans.org/dev/nightly/ (upload may still be in progress)
Changeset: http://hg.netbeans.org/main/rev/c6988726f41e
User: Tim Boudreau <tboudreau@netbeans.org>
Log: #178013 - SecurityManager should prohibit reset/replacement of system logger config.  C.f. JDK bug 1694855.  If this patch causes too much performance degredation, replace assertion test with a system property so logger-related problems can still be detected if necessary.