NullPointerException in InjectorImpl.injectMembers (Guice 1.0)

[Esko Luontola]

I had the following exception today once when running the tests in my
project. I'm suspecting that it is caused by a concurrency bug in
Guice (the line InjectorImpl.java:673 is the for loop statement -
apparenty the list 'injectorsForClass' was null). The test where that
exception happened (EntityRepositorySpec
$WhenAnEntityIsOnlyReadAndNotModified.theEntityIsNotUpdatedAndThusCanBeReadConcurrentlyInManyTasks
()) has two threads running in parallel, and that exception caused the
test to deadlock.

The sources of that project are here, in case you need them:
http://github.com/orfjackal/dimdwarf/tree/2fb2a3d3e1c820c014b8f0d5280d362b227f383a



6.3.2009 19:01:18 net.orfjackal.dimdwarf.tasks.TransactionFilter
filter
INFO: Task failed, rolling back its transaction
java.lang.NullPointerException
at com.google.inject.InjectorImpl.injectMembers(InjectorImpl.java:
673)
at com.google.inject.InjectorImpl$8.call(InjectorImpl.java:682)
at com.google.inject.InjectorImpl$8.call(InjectorImpl.java:681)
at com.google.inject.InjectorImpl.callInContext(InjectorImpl.java:
747)
at com.google.inject.InjectorImpl.injectMembers(InjectorImpl.java:
680)
at
net.orfjackal.dimdwarf.serial.InjectObjectsOnDeserialization.afterResolve
(InjectObjectsOnDeserialization.java:51)
at net.orfjackal.dimdwarf.serial.ObjectSerializerImpl
$MyObjectInputStream.resolveObject(ObjectSerializerImpl.java:135)
at java.io.ObjectInputStream.checkResolve(ObjectInputStream.java:
1377)
at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1329)
at java.io.ObjectInputStream.readObject(ObjectInputStream.java:351)
at
net.orfjackal.dimdwarf.serial.ObjectSerializerImpl.deserializeFromStream
(ObjectSerializerImpl.java:82)
at net.orfjackal.dimdwarf.serial.ObjectSerializerImpl.deserialize
(ObjectSerializerImpl.java:65)
at
net.orfjackal.dimdwarf.gc.entities.GcAwareEntityRepository.readFromDatabase
(GcAwareEntityRepository.java:80)
at net.orfjackal.dimdwarf.gc.entities.GcAwareEntityRepository.read
(GcAwareEntityRepository.java:70)
at
net.orfjackal.dimdwarf.entities.EntityManagerImpl.loadEntityFromDatabase
(EntityManagerImpl.java:108)
at net.orfjackal.dimdwarf.entities.EntityManagerImpl.getEntityById
(EntityManagerImpl.java:97)
at net.orfjackal.dimdwarf.entities.EntityRepositorySpec
$WhenAnEntityIsOnlyReadAndNotModified$1.run(EntityRepositorySpec.java:
164)
at net.orfjackal.dimdwarf.tasks.FilterChain.execute(FilterChain.java:
58)
at net.orfjackal.dimdwarf.tasks.FilterChain.access$000
(FilterChain.java:40)
at net.orfjackal.dimdwarf.tasks.FilterChain$FilterRecursion.run
(FilterChain.java:73)
at net.orfjackal.dimdwarf.entities.EntityFlushingFilter.filter
(EntityFlushingFilter.java:50)
at net.orfjackal.dimdwarf.tasks.FilterChain.execute(FilterChain.java:
56)
at net.orfjackal.dimdwarf.tasks.FilterChain.access$000
(FilterChain.java:40)
at net.orfjackal.dimdwarf.tasks.FilterChain$FilterRecursion.run
(FilterChain.java:73)
at net.orfjackal.dimdwarf.tasks.TransactionFilter.filter
(TransactionFilter.java:54)
at net.orfjackal.dimdwarf.tasks.FilterChain.execute(FilterChain.java:
56)
at net.orfjackal.dimdwarf.tasks.FilterChain.execute(FilterChain.java:
50)
at net.orfjackal.dimdwarf.tasks.TaskExecutor$1.run(TaskExecutor.java:
57)
at net.orfjackal.dimdwarf.context.ThreadContext.runInContext
(ThreadContext.java:51)
at net.orfjackal.dimdwarf.tasks.TaskExecutor.execute
(TaskExecutor.java:55)
at net.orfjackal.dimdwarf.entities.EntityRepositorySpec
$WhenAnEntityIsOnlyReadAndNotModified$3.run(EntityRepositorySpec.java:
177)
at java.lang.Thread.run(Thread.java:619)
Exception in thread "Thread-21" java.lang.NullPointerException
at com.google.inject.InjectorImpl.injectMembers(InjectorImpl.java:
673)
at com.google.inject.InjectorImpl$8.call(InjectorImpl.java:682)
at com.google.inject.InjectorImpl$8.call(InjectorImpl.java:681)
at com.google.inject.InjectorImpl.callInContext(InjectorImpl.java:
747)
at com.google.inject.InjectorImpl.injectMembers(InjectorImpl.java:
680)
at
net.orfjackal.dimdwarf.serial.InjectObjectsOnDeserialization.afterResolve
(InjectObjectsOnDeserialization.java:51)
at net.orfjackal.dimdwarf.serial.ObjectSerializerImpl
$MyObjectInputStream.resolveObject(ObjectSerializerImpl.java:135)
at java.io.ObjectInputStream.checkResolve(ObjectInputStream.java:
1377)
at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1329)
at java.io.ObjectInputStream.readObject(ObjectInputStream.java:351)
at
net.orfjackal.dimdwarf.serial.ObjectSerializerImpl.deserializeFromStream
(ObjectSerializerImpl.java:82)
at net.orfjackal.dimdwarf.serial.ObjectSerializerImpl.deserialize
(ObjectSerializerImpl.java:65)
at
net.orfjackal.dimdwarf.gc.entities.GcAwareEntityRepository.readFromDatabase
(GcAwareEntityRepository.java:80)
at net.orfjackal.dimdwarf.gc.entities.GcAwareEntityRepository.read
(GcAwareEntityRepository.java:70)
at
net.orfjackal.dimdwarf.entities.EntityManagerImpl.loadEntityFromDatabase
(EntityManagerImpl.java:108)
at net.orfjackal.dimdwarf.entities.EntityManagerImpl.getEntityById
(EntityManagerImpl.java:97)
at net.orfjackal.dimdwarf.entities.EntityRepositorySpec
$WhenAnEntityIsOnlyReadAndNotModified$1.run(EntityRepositorySpec.java:
164)
at net.orfjackal.dimdwarf.tasks.FilterChain.execute(FilterChain.java:
58)
at net.orfjackal.dimdwarf.tasks.FilterChain.access$000
(FilterChain.java:40)
at net.orfjackal.dimdwarf.tasks.FilterChain$FilterRecursion.run
(FilterChain.java:73)
at net.orfjackal.dimdwarf.entities.EntityFlushingFilter.filter
(EntityFlushingFilter.java:50)
at net.orfjackal.dimdwarf.tasks.FilterChain.execute(FilterChain.java:
56)
at net.orfjackal.dimdwarf.tasks.FilterChain.access$000
(FilterChain.java:40)
at net.orfjackal.dimdwarf.tasks.FilterChain$FilterRecursion.run
(FilterChain.java:73)
at net.orfjackal.dimdwarf.tasks.TransactionFilter.filter
(TransactionFilter.java:54)
at net.orfjackal.dimdwarf.tasks.FilterChain.execute(FilterChain.java:
56)
at net.orfjackal.dimdwarf.tasks.FilterChain.execute(FilterChain.java:
50)
at net.orfjackal.dimdwarf.tasks.TaskExecutor$1.run(TaskExecutor.java:
57)
at net.orfjackal.dimdwarf.context.ThreadContext.runInContext
(ThreadContext.java:51)
at net.orfjackal.dimdwarf.tasks.TaskExecutor.execute
(TaskExecutor.java:55)
at net.orfjackal.dimdwarf.entities.EntityRepositorySpec
$WhenAnEntityIsOnlyReadAndNotModified$3.run(EntityRepositorySpec.java:
177)
at java.lang.Thread.run(Thread.java:619)

[Esko Luontola]

I browsed Guice's sources some and I might some idea of where that bug
is. The line InjectorImpl.java:672 calls
com.google.inject.InjectorImpl.injectors.get(Object) whose
implementation is com.google.inject.util.AbstractReferenceCache#get.
The only possibility of AbstractReferenceCache#get to return null is
if AbstractReferenceCache#internalCreate returns null. The only
possibility for that to return null is if the line "return previous.get
();" returns null, in other words if
com.google.inject.util.AbstractReferenceCache.FutureValue#get returns
null.

Having a closer look at FutureValue showed a synchronization issue. In
FutureValue.get(), the access to fields 'set', 't' and 'value' is not
synchronized. This looks similar to the kind of concurrency bug in a
typical wrongly implemented double-checked-locking:
http://jeremymanson.blogspot.com/2008/05/double-checked-locking.html
http://www.cs.umd.edu/~pugh/java/memoryModel/DoubleCheckedLocking.html

Now that I look at FutureValue even closer, it's not even enough to
mark the fields 'set', 't' and 'value' volatile, like in the case of
double-checked-locking, because the following is possible:
1. Thread 1 calls setValue(someValue), which executes "set();"
completely, which sets "set = true".
2. Thread 2 calls get(), notices that "set == true", and returns
"value" which is null.
3. Thread 1 sets "value = someValue".

To fix that, the FutureValue.get() method should be marked
synchronized.

[Esko Luontola]

It would be good to still write a test case which reproduces that bug,
to make sure that it is really fixed. For example a tests where many
(tens or hundreds?) of threads call the AbstractReferenceCache.get()
method concurrently, and the result should be that all of them return
exactly the same instance which is non-null. And then that test should
be executed hundreds of times - if it fails one time in a million,
then the code is broken.

I've found it useful to follow the tips in Clean Code (http://
www.amazon.com/Clean-Code-Handbook-Software-Craftsmanship/dp/0132350882)
and execute all tests in the project multiple times in parallel, on
more threads than the CPU has cores. For example in IntelliJ IDEA, I
keep the hotkey for running the tests pressed down, until the status
bar shows that 20, 50 or 100 processes are running. Then I wait a
minute or two until CPU and memory usage returns to normal, and check
one-by-one that none of the test runs threw exceptions or deadlocked.
Normally in that project it takes 2 seconds to run all the tests once,
but when executing 50-100 test runs in parallel, it takes even more
than 100 seconds for one test run, so there is lots of thread
switching happening.

There are also frameworks such as http://www.alphaworks.ibm.com/tech/contest
which do bytecode manipulation for forcing thread switches, so that
concurrency bugs would become more apparent. I haven't tried using
such frameworks, but maybe you should try.

[limpb...@gmail.com]

On Mar 6, 9:18 am, Esko Luontola <esko.luont...@gmail.com> wrote:
> I had the following exception today once when running the tests in my
> project. I'm suspecting that it is caused by a concurrency bug in
> Guice (the line InjectorImpl.java:673 is the for loop statement -
> apparenty the list 'injectorsForClass' was null). The test where that
> exception happened (EntityRepositorySpec
> $WhenAnEntityIsOnlyReadAndNotModified.theEntityIsNotUpdatedAndThusCanBeReadConcurrentlyInManyTasks
> ()) has two threads running in parallel, and that exception caused the
> test to deadlock.

Please upgrade to the Guice 2 prerelease snapshot, which fixes this
problem.
http://groups.google.com/group/google-guice/browse_thread/thread/a14e965d95ea862b/92bb280d2d7c9e71?lnk=gst&q=snapshot20090205#92bb280d2d7c9e71

I'm really trying to get Guice 2 final out the door....

[Esko Luontola]

On Mar 7, 1:22 am, "je...@swank.ca" <limpbiz...@gmail.com> wrote:
> Please upgrade to the Guice 2 prerelease snapshot, which fixes this

> problem.http://groups.google.com/group/google-guice/browse_thread/thread/a14e...

>
> I'm really trying to get Guice 2 final out the door....

OK, thanks. I'll switch to Guice 2 then. I was anyways going to switch
to it sooner or later.