NullPointerException in other shutdown hooks

[remkop]

We are working to make Log4j 2 garbage-free and we are using the Allocation Instrumenter in our unit tests to verify that we don't allocate objects during steady state logging.

We see our tests randomly fail with this exception:

Exception in thread "Thread-0" java.lang.NullPointerException
 at com.google.monitoring.runtime.instrumentation.AllocationRecorder.getObjectSize(AllocationRecorder.java:200)
 at com.google.monitoring.runtime.instrumentation.AllocationRecorder.recordAllocation(AllocationRecorder.java:244)
 at java.util.Hashtable.getEnumeration(Hashtable.java:665)
 at java.util.Hashtable.keys(Hashtable.java:329)
 at java.util.logging.LogManager$LoggerContext.getLoggerNames(LogManager.java:688)
 at java.util.logging.LogManager.reset(LogManager.java:1135)
 at java.util.logging.LogManager$Cleaner.run(LogManager.java:248)

I believe this is a bug in AllocationRecorder:

The NullPointerException above occurs when the (java.util.logging) LogManager$Cleaner shutdown hook allocates a new object and the instrumented bytecode invokes the recordAllocation method.

The AllocationRecorder also has a shutdown hook which sets its instrumentation field to null.
These shutdown hook threads can run at the same time, so if the instrumentation field is set to null after the null check (line 236) but before it is used in getObjectSize (line 200), we get the above exception.

One solution would be to introduce a local Instrumentation variable, assign the value of the static instrumentation field to the local variable, and do the null check on that local variable. If non-null, call the getObjectSize method with the local Instrumentation variable as one of the parameters. The getObjectSize method would use the passed Instrumentation parameter and should not access the static field.

[fischman]

The documented reason for setting instrumentation to null is working around a bug in JVM shutdown in some 1.5 & 1.6 JVMs. I suspect that if the proposed change is made then the same bug would get triggered.
ISTM a better approach would be to replace instrumentation with a fake that unconditionally returned zero for getObjectSize(). Then the null-check can be dropped and the race becomes immaterial.

Caveat: I haven't thought about any of this code for years, so I might be missing something fundamental/important.

[remkop]

Thanks for your reply! I realize my explanation was unclear. Setting the instrumentation field to null is fine and I don't propose to change this. My proposal is to ensure this field is read only once. By copying the value into a local variable further references to the volatile field can be avoided. I'll create a pull request to show what I mean in code.

[remkop]

After re-reading your comment and the documented reason for setting instrumentation to null I agree that your approach is better.

If we create a pull request that implements this to your satisfaction, would you be open to creating a new release that includes the fix?

[jhmanson]

I'm generally not a big fan of introducing a largish new class to workaround a bug like this.

I'm probably being stupid, but why would the original proposed fix cause the bug to reappear with any meaningful probability? You hold a reference to a dead instrumentation object for slightly longer than it does now, but it would likely be just for a few instructions.

If you really didn't want that, you could add null checks in getObjectSize().

[fischman]

@jhmanson yeah when I made my suggestion I forgot that Instrumentation was an interface not a concrete do-nothing class, so in my mind it would have been a tiny inline derived class, not a largish standalone one.

I can't reason about the probabilities involved because I neither remember the frequency with which the original bug was observed nor what guarantees (I thought) we have about the relative timings of shutdownhooks vs. the bug manifesting. I don't have a problem with rolling the dice with null some more. Your call.

(maybe the workaround can be dropped entirely for an assert that this code is running on JVM>=7? Or maybe the JVM bug still manifests even in newer JVMs? IDK)

[garydgregory]

How about dropping support for Java < 7?

Gary

On Wed, May 4, 2016 at 10:16 AM, Ami Fischman notifications@github.com
wrote:

@jhmanson https://github.com/jhmanson yeah when I made my suggestion I
forgot that Instrumentation was an interface not a concrete do-nothing
class, so in my mind it would have been a tiny inline derived class, not a
largish standalone one.

I can't reason about the probabilities involved because I neither remember
the frequency with which the original bug was observed nor what guarantees
(I thought) we have about the relative timings of shutdownhooks vs. the bug
manifesting. I don't have a problem with rolling the dice with null some
more. Your call.

(maybe the workaround can be dropped entirely for an assert that this code
is running on JVM>=7? Or maybe the JVM bug still manifests even in newer
JVMs? IDK)

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub
#15 (comment)

E-Mail: garydgregory@gmail.com | ggregory@apache.org
Java Persistence with Hibernate, Second Edition
http://www.manning.com/bauer3/
JUnit in Action, Second Edition http://www.manning.com/tahchiev/
Spring Batch in Action http://www.manning.com/templier/
Blog: http://garygregory.wordpress.com
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory

[jhmanson]

It's almost certainly this:

https://bugs.openjdk.java.net/browse/JDK-6572160

Which was fixed in JDK 7.

I don't see any reason to drop the fix - there are certainly still people using JDK 6. That said, no one at Google is using JDK6, and I'm happy to take a version of this patch that reads instrumentation once.

[remkop]

I can create another patch. For what it's worth, there is also this alternative:

public class AllocationRecorder {
  private static final Instrumentation NULL_INSTRUMENTATION = (Instrumentation) Proxy.newProxyInstance(
          AllocationRecorder.class.getClassLoader(), new Class[]{Instrumentation.class}, new InvocationHandler() {
            @Override
            public Object invoke(final Object proxy, final Method method, final Object[] args) throws Throwable {
              if ("getObjectSize".equals(method.getName())) {
                return Long.valueOf(0);
              }
              throw new UnsupportedOperationException(method.getName());
            }
          }
  );
  static {
    // Sun's JVMs in 1.5.0_06 and 1.6.0{,_01} have a bug where calling
    // Instrumentation.getObjectSize() during JVM shutdown triggers a
    // JVM-crashing assert in JPLISAgent.c, so we make sure to not call it after
    // shutdown.  There can still be a race here, depending on the extent of the
    // JVM bug, but this seems to be good enough.
    // instrumentation is volatile to make sure the threads reading it (in
    // recordAllocation()) see the updated value; we could do more
    // synchronization but it's not clear that it'd be worth it, given the
    // ambiguity of the bug we're working around in the first place.
    Runtime.getRuntime().addShutdownHook(new Thread() {
      @Override
      public void run() {
        setInstrumentation(NULL_INSTRUMENTATION);
      }
    });
  }

Now the concrete NullInstrumentation class is no longer necessary.

[garydgregory]

Either way, some Javadoc is needed to explain why this code is needed.

G

On Wed, May 4, 2016 at 10:35 AM, Remko Popma notifications@github.com
wrote:

I can create another patch. For what it's worth, there is also this
alternative:

public class AllocationRecorder {
private static final Instrumentation NULL_INSTRUMENTATION = (Instrumentation) Proxy.newProxyInstance(
AllocationRecorder.class.getClassLoader(), new Class[]{Instrumentation.class}, new InvocationHandler() {
@OverRide
public Object invoke(final Object proxy, final Method method, final Object[] args) throws Throwable {
if ("getObjectSize".equals(method.getName())) {
return Long.valueOf(0);
}
throw new UnsupportedOperationException(method.getName());
}
}
);

Now the concrete NullInstrumentation class is no longer necessary.

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub
#15 (comment)

E-Mail: garydgregory@gmail.com | ggregory@apache.org
Java Persistence with Hibernate, Second Edition
http://www.manning.com/bauer3/
JUnit in Action, Second Edition http://www.manning.com/tahchiev/
Spring Batch in Action http://www.manning.com/templier/
Blog: http://garygregory.wordpress.com
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory

[remkop]

I updated the pull request to read the instrumentation field once.

[remkop]

Jeremy, thank you for merging the fix into master.
Should we use a SNAPSHOT or are you planning to do a release?

Update: it turns out that our release plugin won't let use do a release with a SNAPSHOT dependency so we'll wait for a release.

[remkop]

Guys, are you planning a release for this?

[cgdecker]

I've just done a 3.0.1 release to Maven Central. You should be able to find it there shortly.

[remkop]

Many thanks!

[remkop]

Just a quick follow-up to say that we have not seen the problem on our CI servers since we upgraded to 3.0.1 two weeks ago. Again, many thanks!