MongoDB problems persisting events

Hi everybody,

I’m trying to do some experiments with Axon and MongoDB event store, and I have the following issue:

I’m able to successfully persist the aggregate creation event, but not the aggregate modification event.
If I issue more creation commands they all complete successfully.

The problem is that the execution doesn’t return after the sendAndWait of the modification command.

While the execution is hanging if I stop the mongodb service I get SocketConnection exception.

Trying to find the origin of the problem I’ve traced the instruction where the execution freezes on, which is
the line “entry.saveAggregate();” in class DefaultUnitOfWork.java

At creation I see the message “Aggregates successfully persisted” which is the next instruction in the code, but
I can’t see it at modification.

Here is the sample code I’m working on :

SimpleCommandBus commandBus = new SimpleCommandBus();
SimpleEventBus eventBus = new SimpleEventBus();

CommandGateway commandGateway = new DefaultCommandGateway(commandBus);

Mongo driver = null;
System.setProperty(“DEBUG.MONGO”, “true”);

System.setProperty(“DB.TRACE”, “true”);

try {
driver = new Mongo(new MongoURI(“mongodb://127.0.0.1:27017”));
} catch (UnknownHostException ex) {

System.exit(-1);

}
MongoTemplate mongo = new DefaultMongoTemplate(driver);
MongoEventStore eventStore = new MongoEventStore(mongo);

eventStore.ensureIndexes();
EventSourcingRepository repository = new EventSourcingRepository<>(Bug.class, eventStore);
repository.setEventBus(eventBus);

AggregateAnnotationCommandHandler.subscribe(Bug.class, repository, commandBus);
AnnotationEventListenerAdapter.subscribe(new EventHandlerBug(), eventBus);

try {
final UUID idBug = UUID.randomUUID();

commandGateway.sendAndWait(new CommandCreateBug(idBug, “bug 1”, new Date()));
commandGateway.sendAndWait(new CommandCloseBug(idBug));

} catch (Throwable t) {
t.printStackTrace();
}

And this is the logger info:

nov 11, 2014 11:09:15 AM com.mongodb.Mongo
Informazioni: Creating Mongo instance (driver version 2.12.4) with authority MongoAuthority{type=Direct, serverAddresses=[127.0.0.1:27017], credentials={credentials={}}} and options MongoOptions{description=‘null’, connectionsPerHost=10, threadsAllowedToBlockForConnectionMultiplier=5, maxWaitTime=120000, connectTimeout=10000, socketTimeout=0, socketKeepAlive=false, autoConnectRetry=false, maxAutoConnectRetryTime=0, slaveOk=false, readPreference=primary, dbDecoderFactory=DefaultDBDecoder.DefaultFactory, dbEncoderFactory=DefaultDBEncoder.DefaultFactory, safe=false, w=0, wtimeout=0, fsync=false, j=false, socketFactory=javax.net.DefaultSocketFactory@148083b, cursorFinalizerEnabled=true, writeConcern=WriteConcern { “getlasterror” : 1} / (Continue on error? false), alwaysUseMBeans=false, requiredReplicaSetName=null}
nov 11, 2014 11:09:15 AM com.mongodb.SingleServerCluster
Informazioni: Cluster created with settings {hosts=[127.0.0.1:27017], mode=Single, requiredClusterType=Unknown}
write concern :1
nov 11, 2014 11:09:15 AM com.mongodb.ServerMonitor$ServerMonitorRunnable logStateChange
Informazioni: Monitor thread successfully connected to server with description ServerDescription{address=127.0.0.1:27017, type=StandAlone, hosts=[], passives=[], arbiters=[], primary=‘null’, maxDocumentSize=16777216, maxMessageSize=48000000, maxWriteBatchSize=1000, tags=TagSet{}, setName=‘null’, averageLatencyNanos=24471308, ok=true, state=Connected, version=ServerVersion{versionList=[2, 6, 5]}, minWireVersion=0, maxWireVersion=2}
[2014-11-11 11:09:15,834 - DEBUG] (SimpleEventBus.java:71) -> [EventListener [EventHandlerBug] subscribed successfully]
[2014-11-11 11:09:15,850 - DEBUG] (IdentifierFactory.java:48) -> [Looking for IdentifierFactory implementation using the context class loader]
[2014-11-11 11:09:15,850 - DEBUG] (IdentifierFactory.java:51) -> [Looking for IdentifierFactory implementation using the IdentifierFactory class loader.]
[2014-11-11 11:09:15,850 - DEBUG] (IdentifierFactory.java:56) -> [Using default UUID-based IdentifierFactory]
[2014-11-11 11:09:15,850 - DEBUG] (SimpleCommandBus.java:120) -> [Dispatching command [oraclevsmongo.dominio.CommandCreateBug]]
[2014-11-11 11:09:15,866 - DEBUG] (NestableUnitOfWork.java:145) -> [Starting Unit Of Work.]
[2014-11-11 11:09:15,866 - DEBUG] (NestableUnitOfWork.java:161) -> [Registering Unit Of Work as CurrentUnitOfWork]
[2014-11-11 11:09:15,897 - DEBUG] (UnitOfWorkListenerCollection.java:161) -> [Registering listener: org.axonframework.repository.LockingRepository$LockCleaningListener]
[2014-11-11 11:09:15,897 - DEBUG] (NestableUnitOfWork.java:51) -> [Committing Unit Of Work]
[2014-11-11 11:09:15,897 - DEBUG] (UnitOfWorkListenerCollection.java:108) -> [Notifying listeners of commit request]
[2014-11-11 11:09:15,897 - DEBUG] (UnitOfWorkListenerCollection.java:111) -> [Notifying listener [org.axonframework.repository.LockingRepository$LockCleaningListener] of upcoming commit]
[2014-11-11 11:09:15,897 - DEBUG] (UnitOfWorkListenerCollection.java:115) -> [Listeners successfully notified]
[2014-11-11 11:09:15,897 - DEBUG] (DefaultUnitOfWork.java:280) -> [Persisting changes to aggregates]
[2014-11-11 11:09:15,897 - DEBUG] (DefaultUnitOfWork.java:283) -> [Persisting changes to [oraclevsmongo.dominio.Bug], identifier: [6c035bb3-bbef-45f0-86f4-4917a8262f21]]
nov 11, 2014 11:09:15 AM com.mongodb.DBCollectionImpl trace
Informazioni: save: axonframework.domainevents { “aggregateIdentifier” : “6c035bb3-bbef-45f0-86f4-4917a8262f21” , “sequenceNumber” : 0 , “serializedPayload” : “<oraclevsmongo.dominio.BugCreatedEvent>6c035bb3-bbef-45f0-86f4-4917a8262f21bug 12014-11-11 10:09:15.850 UTC</oraclevsmongo.dominio.BugCreatedEvent>” , “timeStamp” : “2014-11-11T11:09:15.897+01:00” , “type” : “Bug” , “payloadType” : “oraclevsmongo.dominio.BugCreatedEvent” , “payloadRevision” : null , “serializedMetaData” : “” , “eventIdentifier” : “cb4d161f-4a42-4498-976c-f0bb4c3adc7d”}
[2014-11-11 11:09:15,959 - DEBUG] (MongoEventStore.java:146) -> [1 events appended]
[2014-11-11 11:09:15,959 - DEBUG] (DefaultUnitOfWork.java:289) -> [Aggregates successfully persisted]
[2014-11-11 11:09:15,959 - DEBUG] (NestableUnitOfWork.java:58) -> [This Unit Of Work is not nested. Finalizing commit…]
[2014-11-11 11:09:15,959 - DEBUG] (DefaultUnitOfWork.java:247) -> [Publishing events to the event bus]
[2014-11-11 11:09:15,959 - DEBUG] (DefaultUnitOfWork.java:263) -> [Publishing event [oraclevsmongo.dominio.BugCreatedEvent] to event bus [org.axonframework.eventhandling.SimpleEventBus@1a6a354]]
[2014-11-11 11:09:15,959 - DEBUG] (SimpleEventBus.java:87) -> [Dispatching Event [BugCreatedEvent] to EventListener [EventHandlerBug]]
[2014-11-11 11:09:15,959 - DEBUG] (DefaultUnitOfWork.java:274) -> [All events successfully published.]
[2014-11-11 11:09:15,959 - DEBUG] (UnitOfWorkListenerCollection.java:120) -> [Notifying listeners of transaction commit request]
[2014-11-11 11:09:15,959 - DEBUG] (UnitOfWorkListenerCollection.java:123) -> [Notifying listener [org.axonframework.repository.LockingRepository$LockCleaningListener] of upcoming transaction commit]
[2014-11-11 11:09:15,959 - DEBUG] (UnitOfWorkListenerCollection.java:127) -> [Listeners successfully notified]
[2014-11-11 11:09:15,959 - DEBUG] (UnitOfWorkListenerCollection.java:58) -> [Notifying listeners after commit]
[2014-11-11 11:09:15,959 - DEBUG] (UnitOfWorkListenerCollection.java:63) -> [Notifying listener [org.axonframework.repository.LockingRepository$LockCleaningListener] after commit]
[2014-11-11 11:09:15,959 - DEBUG] (NestableUnitOfWork.java:192) -> [Stopping Unit Of Work]
[2014-11-11 11:09:15,959 - DEBUG] (UnitOfWorkListenerCollection.java:137) -> [Notifying listeners of cleanup]
nov 11, 2014 11:09:15 AM com.mongodb.DBCollectionImpl trace
Informazioni: find: axonframework.snapshotevents { “$query” : { “aggregateIdentifier” : “6c035bb3-bbef-45f0-86f4-4917a8262f21” , “type” : “Bug”} , “$orderby” : { “sequenceNumber” : -1}}
[2014-11-11 11:09:15,959 - DEBUG] (UnitOfWorkListenerCollection.java:143) -> [Notifying listener [org.axonframework.repository.LockingRepository$LockCleaningListener] of cleanup]
[2014-11-11 11:09:15,959 - DEBUG] (UnitOfWorkListenerCollection.java:150) -> [Listeners successfully notified]
[2014-11-11 11:09:15,959 - DEBUG] (NestableUnitOfWork.java:77) -> [Clearing resources of this Unit Of Work.]
[2014-11-11 11:09:15,975 - DEBUG] (SimpleCommandBus.java:120) -> [Dispatching command [oraclevsmongo.dominio.CommandCloseBug]]
[2014-11-11 11:09:15,975 - DEBUG] (NestableUnitOfWork.java:145) -> [Starting Unit Of Work.]
[2014-11-11 11:09:15,975 - DEBUG] (NestableUnitOfWork.java:161) -> [Registering Unit Of Work as CurrentUnitOfWork]
nov 11, 2014 11:09:15 AM com.mongodb.DBCollectionImpl trace
Informazioni: find: axonframework.domainevents { “$query” : { “aggregateIdentifier” : “6c035bb3-bbef-45f0-86f4-4917a8262f21” , “sequenceNumber” : { “$gte” : 0} , “type” : “Bug”} , “$orderby” : { “sequenceNumber” : 1}}
[2014-11-11 11:09:16,006 - DEBUG] (UnitOfWorkListenerCollection.java:161) -> [Registering listener: org.axonframework.eventsourcing.EventSourcingRepository$ConflictResolvingListener]
[2014-11-11 11:09:16,006 - DEBUG] (UnitOfWorkListenerCollection.java:161) -> [Registering listener: org.axonframework.repository.LockingRepository$LockCleaningListener]
[2014-11-11 11:09:16,006 - DEBUG] (NestableUnitOfWork.java:51) -> [Committing Unit Of Work]
[2014-11-11 11:09:16,006 - DEBUG] (UnitOfWorkListenerCollection.java:108) -> [Notifying listeners of commit request]
[2014-11-11 11:09:16,006 - DEBUG] (UnitOfWorkListenerCollection.java:111) -> [Notifying listener [org.axonframework.eventsourcing.EventSourcingRepository$ConflictResolvingListener] of upcoming commit]
[2014-11-11 11:09:16,006 - DEBUG] (UnitOfWorkListenerCollection.java:111) -> [Notifying listener [org.axonframework.repository.LockingRepository$LockCleaningListener] of upcoming commit]
[2014-11-11 11:09:16,006 - DEBUG] (UnitOfWorkListenerCollection.java:115) -> [Listeners successfully notified]
[2014-11-11 11:09:16,006 - DEBUG] (DefaultUnitOfWork.java:280) -> [Persisting changes to aggregates]
[2014-11-11 11:09:16,006 - DEBUG] (DefaultUnitOfWork.java:283) -> [Persisting changes to [oraclevsmongo.dominio.Bug], identifier: [6c035bb3-bbef-45f0-86f4-4917a8262f21]]

Has anybody any clue about this problem ?

Thanx in advance.

We just realized that there probably is a bug involving the class AbstractXStreamSerializer.
The method canSerializeTo infact never returns in our use case specified above (with the modification command, but not with the creation command), so as a workaround we
extended a new XStreamSerializer and overrid the method this way:

@Override
public boolean canSerializeTo(Class expectedRepresentation) {
if (expectedRepresentation.equals(DBObject.class)){
return false;

}
return super.canSerializeTo(expectedRepresentation); //To change body of generated methods, choose Tools | Templates.
}

this solved our use case, but we don’t know yet if it creates other issues later.

Hi Roberto,

this is strange. I’ve been trying to reproduce the problem, but everything seems to work fine in my test cases.
Could you provide me a thread dump of the case where the method seems to hang?

Did you implement any custom ContentTypeConverters?

Cheers,

Allard

Hi Allard,

here’s the thread dump, and we didn’t redefine any ContentTypeConverters.
What is odd is the fact that the same execution path doesn’t freeze on the first command (creation)…

Cheers.

dump.log (5.8 KB)

Hi Roberto,

I was hoping to see a recursion issue in the log, but the operation uses a for loop. I don’t see how the process can hang. Do you see the hanging behavior each time you run the application? If so, could you create a Chronon recording for me? That would allow me to debug the session and see why the for loop never exits. Assuming that’s the issue.

Cheers,

Allard

Hi Allard,

It turns out that the problem we had might be caused by some conflicting libraries in our test project.
After moving to gradle, the same source code performed as expected without any hanging problems, so the workaround I mentioned before isn’t necessary anymore.
I couldn’t find out which library caused the problem yet, but I’ll let you know in case we discover more.

Thanx for the support anyway.