Non-deterministic trouble with PrivateModules and Multibindings

[Esko Luontola]

I'm facing non-deterministic trouble with PrivateModules and
Multibindings.

My architecture is that I have Controller-Service pairs which
communicate using a MessageQueue. Each Service is running in its own
thread and only the Controller which is paired with it can send
messages to it. All Controllers are placed into a ControllerHub (which
is also itself a Service running in its own thread), which broadcasts
messages to all Controllers.

To prevent anyone else from getting direct access to the Controllers
and Services, I've implemented them as PrivateModules like this:

Infrastructure:
http://github.com/orfjackal/dimdwarf/blob/ctrl-bug/dimdwarf-core/src/main/java/net/orfjackal/dimdwarf/modules/ServiceInstallerModule.java
http://github.com/orfjackal/dimdwarf/blob/ctrl-bug/dimdwarf-core/src/main/java/net/orfjackal/dimdwarf/services/ServiceModule.java

Modules:
http://github.com/orfjackal/dimdwarf/blob/ctrl-bug/dimdwarf-core/src/main/java/net/orfjackal/dimdwarf/modules/CommonModules.java
http://github.com/orfjackal/dimdwarf/blob/ctrl-bug/dimdwarf-core/src/main/java/net/orfjackal/dimdwarf/modules/ControllerModule.java
http://github.com/orfjackal/dimdwarf/blob/ctrl-bug/dimdwarf-core/src/main/java/net/orfjackal/dimdwarf/modules/AuthenticatorModule.java
http://github.com/orfjackal/dimdwarf/blob/ctrl-bug/dimdwarf-core/src/main/java/net/orfjackal/dimdwarf/modules/NetworkModule.java

The class which gets all the ServiceRegistrations and starts them in
their own threads:
http://github.com/orfjackal/dimdwarf/blob/ctrl-bug/dimdwarf-core/src/main/java/net/orfjackal/dimdwarf/services/ServiceStarter.java
http://github.com/orfjackal/dimdwarf/blob/ctrl-bug/dimdwarf-core/src/main/java/net/orfjackal/dimdwarf/services/ServiceRunner.java

My problem is that even though I bind the message queue interfaces
inside the private modules (http://github.com/orfjackal/dimdwarf/blob/
ctrl-bug/dimdwarf-core/src/main/java/net/orfjackal/dimdwarf/services/
ServiceModule.java#L72-76), sometimes non-deterministically the
controllers from two different modules both receive the same message
queue instance.

Here are the controllers. I've made them print in their constructors
the MessageSender instance that is injected. It will print either
"MessageQueue(Network)" or "MessageQueue(Authenticator)" depending on
which module owns that message queue.

http://github.com/orfjackal/dimdwarf/blob/ctrl-bug/dimdwarf-core/src/main/scala/net/orfjackal/dimdwarf/auth/AuthenticatorController.scala
http://github.com/orfjackal/dimdwarf/blob/ctrl-bug/dimdwarf-core/src/main/scala/net/orfjackal/dimdwarf/net/NetworkController.scala




Here is the output from a passing test run. Notice that now
AuthenticatorController and NetworkController both got their own
MessageQueue instances injected. They print "AuthenticatorController:
MessageQueue(Authenticator)" and "NetworkController:
MessageQueue(Network)" respectively.

00:57:42.592 [main] INFO net.orfjackal.dimdwarf.server.Main -
Dimdwarf 0.1.0-SNAPSHOT starting up
00:57:43.103 [main] INFO net.orfjackal.dimdwarf.server.Main - Modules
loaded
00:57:43.113 [main] INFO net.orfjackal.dimdwarf.server.Main -
Bootstrapper created
AuthenticatorModule.service: MessageQueue(Authenticator)
00:57:43.117 [Authenticator] DEBUG n.o.d.services.ServiceMessageLoop -
START: class net.orfjackal.dimdwarf.auth.AuthenticatorService
NetworkModule.service: MessageQueue(Network)
00:57:43.120 [Network] DEBUG n.o.d.services.ServiceMessageLoop -
START: class net.orfjackal.dimdwarf.net.NetworkService
AuthenticatorController: MessageQueue(Authenticator)
00:57:43.238 [Controller] INFO n.o.d.modules.ControllerModule -
Registering controller "Authenticator" of type
net.orfjackal.dimdwarf.auth.AuthenticatorController
NetworkController: MessageQueue(Network)
00:57:43.239 [Controller] INFO n.o.d.modules.ControllerModule -
Registering controller "Network" of type
net.orfjackal.dimdwarf.net.NetworkController
00:57:43.239 [Controller] DEBUG n.o.d.services.ServiceMessageLoop -
START: class net.orfjackal.dimdwarf.controller.ControllerHub
00:57:43.241 [Network] INFO n.o.dimdwarf.net.NetworkService - Begin
listening on port 56536
00:57:43.247 [main] INFO net.orfjackal.dimdwarf.server.Main - Server
started
00:57:43.339 [NioProcessor-1] INFO o.a.m.filter.logging.LoggingFilter
- CREATED
00:57:43.339 [NioProcessor-1] INFO o.a.m.filter.logging.LoggingFilter
- OPENED
00:57:43.386 [NioProcessor-1] INFO o.a.m.filter.logging.LoggingFilter
- RECEIVED: HeapBuffer[pos=0 lim=26 cap=2048: 00 18 10 05 00 04 75 73
65 72 00 0E 77 72 6F 6E...]
00:57:43.386 [NioProcessor-1] DEBUG o.a.m.f.codec.ProtocolCodecFilter
- Processing a MESSAGE_RECEIVED for session 1
00:57:43.395 [NioProcessor-1] DEBUG
n.o.d.net.SimpleSgsProtocolIoHandler - RECEIVED: LoginRequest()
00:57:43.395 [Controller] DEBUG n.o.d.services.ServiceMessageLoop -
PROCESS: LoginRequest()
MessageQueue(Authenticator)
00:57:43.398 [Authenticator] DEBUG n.o.d.services.ServiceMessageLoop -
PROCESS: IsUserAuthenticated()
00:57:43.399 [Controller] DEBUG n.o.d.services.ServiceMessageLoop -
PROCESS: NoUserIsNotAuthenticated()
00:57:43.400 [Network] DEBUG n.o.d.services.ServiceMessageLoop -
PROCESS: LoginFailure()
00:57:43.404 [NioProcessor-1] INFO o.a.m.filter.logging.LoggingFilter
- SENT: HeapBuffer[pos=0 lim=5 cap=5: 00 03 12 00 00]
00:57:43.404 [NioProcessor-1] INFO o.a.m.filter.logging.LoggingFilter
- SENT: HeapBuffer[pos=0 lim=0 cap=0: empty]
00:57:43.406 [NioProcessor-1] INFO o.a.m.filter.logging.LoggingFilter
- CLOSED


Here is the output from a failing test run, without any source code
modifications. Notice that now both AuthenticatorController and
NetworkController print that they got the same MessageQueue instance
"MessageQueue(Network)" injected!

00:53:44.347 [main] INFO net.orfjackal.dimdwarf.server.Main -
Dimdwarf 0.1.0-SNAPSHOT starting up
00:53:44.893 [main] INFO net.orfjackal.dimdwarf.server.Main - Modules
loaded
00:53:44.903 [main] INFO net.orfjackal.dimdwarf.server.Main -
Bootstrapper created
AuthenticatorModule.service: MessageQueue(Authenticator)
NetworkModule.service: MessageQueue(Network)
00:53:44.927 [Authenticator] DEBUG n.o.d.services.ServiceMessageLoop -
START: class net.orfjackal.dimdwarf.auth.AuthenticatorService
00:53:44.928 [Network] DEBUG n.o.d.services.ServiceMessageLoop -
START: class net.orfjackal.dimdwarf.net.NetworkService
AuthenticatorController: MessageQueue(Network)
NetworkController: MessageQueue(Network)
00:53:45.037 [Controller] INFO n.o.d.modules.ControllerModule -
Registering controller "Network" of type
net.orfjackal.dimdwarf.net.NetworkController
00:53:45.037 [Controller] INFO n.o.d.modules.ControllerModule -
Registering controller "Authenticator" of type
net.orfjackal.dimdwarf.auth.AuthenticatorController
00:53:45.038 [Controller] DEBUG n.o.d.services.ServiceMessageLoop -
START: class net.orfjackal.dimdwarf.controller.ControllerHub
00:53:45.051 [Network] INFO n.o.dimdwarf.net.NetworkService - Begin
listening on port 56379
00:53:45.058 [main] INFO net.orfjackal.dimdwarf.server.Main - Server
started
00:53:45.151 [NioProcessor-1] INFO o.a.m.filter.logging.LoggingFilter
- CREATED
00:53:45.151 [NioProcessor-1] INFO o.a.m.filter.logging.LoggingFilter
- OPENED
00:53:45.201 [NioProcessor-1] INFO o.a.m.filter.logging.LoggingFilter
- RECEIVED: HeapBuffer[pos=0 lim=26 cap=2048: 00 18 10 05 00 04 75 73
65 72 00 0E 77 72 6F 6E...]
00:53:45.201 [NioProcessor-1] DEBUG o.a.m.f.codec.ProtocolCodecFilter
- Processing a MESSAGE_RECEIVED for session 1
00:53:45.211 [NioProcessor-1] DEBUG
n.o.d.net.SimpleSgsProtocolIoHandler - RECEIVED: LoginRequest()
00:53:45.212 [Controller] DEBUG n.o.d.services.ServiceMessageLoop -
PROCESS: LoginRequest()
MessageQueue(Network)
00:53:45.216 [Network] DEBUG n.o.d.services.ServiceMessageLoop -
PROCESS: IsUserAuthenticated()
00:53:45.222 [NioProcessor-1] INFO o.a.m.filter.logging.LoggingFilter
- SENT: HeapBuffer[pos=0 lim=0 cap=0: empty]


Do you have any ideas where the problem could be? Have I understood
incorrectly that how PrivateModules work and is my plugin system
flawed? Could it be related that the controllers from all
PrivateModules run in the same thread-local scope ControllerScoped?
Can it affect this, that the services are controllers are all injected
concurrently in different threads? Can it be related that the
ControllerModule, which is itself a ServiceModule (which extends
PrivateModule), uses the Set<ControllerRegistration> multibinding from
all other ServiceModules?


P.S. In case the logs in this message are hard to read due to line
wrapping by the mailing list, here is a copy of the same message:
http://www.orfjackal.net/temp/guice_message_2010-08-27.txt

[limpb...@gmail.com]

Are you creating threads during @Inject-annotated methods or
constructors? When those injections happen at injector-creation time,
the spawned threads can witness the injector in a partially-
constructed state. Guice tries to keep this consistent, but it's racy
and could be a source of nondeterminism.

Otherwise I can't recall any sources of nondeterminism in private
modules or multibindings.

[Willi Schönborn]

Take a look at
http://code.google.com/p/google-guice/wiki/Multibindings#Limitations:
"You cannot create collections whose elements span private modules."

That might be your problem.

W

[Esko Luontola]

I was able to find out what the problem was. One of the private
modules had a constructor-injected dependency to a concrete class
which was logically part of another private module. But since implicit
bindings are created for concrete classes, the other class from the
other private module became accidentally part of the this private
module.

Here a test to reproduce (also in http://pastebin.com/wt3YrkEx). The
problem was that Foo had a direct dependency to Bar. The solution that
I'll try is to create an interface for Bar, so that bindings are not
created implicitly for it, and then expose Bar's interface from the
other private module.


import com.google.inject.*;
import com.google.inject.name.Names;
import org.junit.Test;

import static org.junit.Assert.assertEquals;

public class PrivateModuleBugTest {

@Test
public void
private_modules_should_not_see_each_others_private_bindings() {
Injector injector = Guice.createInjector(new FooModule(), new
BarModule());
PrivateValue foo =
injector.getInstance(Key.get(PrivateValue.class, Names.named("Foo")));
Bar bar = ((Foo) foo).bar;

assertEquals("Foo", foo.getClass().getSimpleName());
assertEquals("Foo-private", foo.getPrivateValue());
assertEquals("Bar", bar.getClass().getSimpleName());
assertEquals("Bar-private", bar.getPrivateValue()); //
actually returns "Foo-private"
}
}

class FooModule extends PrivateModule {
protected void configure() {
bind(String.class).toInstance("Foo-private");
bind(PrivateValue.class).to(Foo.class);


bind(PrivateValue.class).annotatedWith(Names.named("Foo")).to(Foo.class);
expose(PrivateValue.class).annotatedWith(Names.named("Foo"));
}
}

class BarModule extends PrivateModule {
protected void configure() {
bind(String.class).toInstance("Bar-private");
bind(PrivateValue.class).to(Bar.class);


bind(PrivateValue.class).annotatedWith(Names.named("Bar")).to(Bar.class);
expose(PrivateValue.class).annotatedWith(Names.named("Bar"));
}
}

class Foo implements PrivateValue {
private final String privateValue;
public final Bar bar;

@Inject
public Foo(String privateValue, Bar bar) { // there is no warning
about this dependency to Bar
this.privateValue = privateValue;
this.bar = bar;
}

public String getPrivateValue() {
return privateValue;
}
}

class Bar implements PrivateValue {
private final String privateValue;

@Inject
public Bar(String privateValue) {
this.privateValue = privateValue;
}

public String getPrivateValue() {
return privateValue;
}
}

interface PrivateValue {
String getPrivateValue();
}

[Esko Luontola]

On Aug 27, 12:07 pm, Esko Luontola <esko.luont...@gmail.com> wrote:
> Here a test to reproduce (also inhttp://pastebin.com/wt3YrkEx). The

> problem was that Foo had a direct dependency to Bar. The solution that
> I'll try is to create an interface for Bar, so that bindings are not
> created implicitly for it, and then expose Bar's interface from the
> other private module.

Another, maybe even better solution (it's more reliable), is to expose
Bar.class in the BarModule. That way the dependency from Foo to Bar
can be declared, but at the same time Bar will get its own instance of
the String.

class BarModule extends PrivateModule {
protected void configure() {
bind(String.class).toInstance("Bar-private");
bind(PrivateValue.class).to(Bar.class);

bind(Bar.class);
expose(Bar.class);