search

muoncore / newton

Extend Muon into the world of Spring. Implement Muon apis, especially around events to provide DDD patterns natively in Spring Boot
http://muoncore.io
GNU Lesser General Public License v3.0
12 stars 5 forks source link

Locking Process failed with exception #62

Closed bobjana closed 7 years ago

bobjana commented 7 years ago

Photon: 0.0.14

[36mservices-security-service-1 |[0m 2017-08-03T07:40:22.626054259Z 2017-08-03 07:40:22.625  INFO 8 --- [meUniqueService] i.m.newton.cluster.LocalOnlyLockService  : Global lock 'UserUsernameUniqueService' released! Will try again in 500ms
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.063814171Z 2017-08-03 07:40:23.063  INFO 8 --- [e-test/Customer] i.m.newton.cluster.LocalOnlyLockService  : Waiting on the lock AdministratorViewStore-test/Customer
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.063848539Z 2017-08-03 07:40:23.063  INFO 8 --- [e-test/Customer] i.m.newton.cluster.LocalOnlyLockService  : Obtained global lock 'AdministratorViewStore-test/Customer', executing local task on this node
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064357479Z 2017-08-03 07:40:23.064  WARN 8 --- [e-test/Customer] i.m.newton.cluster.LocalOnlyLockService  : Locked process has failed with an exception, and AdministratorViewStore-test/Customer has been unlocked
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064791732Z 2017-08-03 07:40:23.064  WARN 8 --- [e-test/Customer] i.m.newton.cluster.LocalOnlyLockService  : Locking Process failed with exception
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064806271Z
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064809743Z java.lang.IllegalStateException: state should be: open
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064822713Z   at com.mongodb.assertions.Assertions.isTrue(Assertions.java:70)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064826406Z   at com.mongodb.connection.BaseCluster.selectServer(BaseCluster.java:82)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064829396Z   at com.mongodb.binding.ClusterBinding$ClusterBindingConnectionSource.<init>(ClusterBinding.java:75)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064832818Z   at com.mongodb.binding.ClusterBinding$ClusterBindingConnectionSource.<init>(ClusterBinding.java:71)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064836114Z   at com.mongodb.binding.ClusterBinding.getReadConnectionSource(ClusterBinding.java:63)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064839252Z   at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:402)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064842194Z   at com.mongodb.operation.FindOperation.execute(FindOperation.java:510)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064845222Z   at com.mongodb.operation.FindOperation.execute(FindOperation.java:81)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064860115Z   at com.mongodb.Mongo.execute(Mongo.java:836)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064863399Z   at com.mongodb.Mongo$2.execute(Mongo.java:823)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064866462Z   at com.mongodb.DBCursor.initializeCursor(DBCursor.java:870)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064869679Z   at com.mongodb.DBCursor.hasNext(DBCursor.java:142)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064872715Z   at com.mongodb.DBCursor.one(DBCursor.java:679)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064875840Z   at com.mongodb.DBCollection.findOne(DBCollection.java:833)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064879026Z   at com.mongodb.DBCollection.findOne(DBCollection.java:796)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064882282Z   at com.mongodb.DBCollection.findOne(DBCollection.java:743)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064885384Z   at org.springframework.data.mongodb.core.MongoTemplate$FindOneCallback.doInCollection(MongoTemplate.java:2185)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064888764Z   at org.springframework.data.mongodb.core.MongoTemplate$FindOneCallback.doInCollection(MongoTemplate.java:2169)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064891987Z   at org.springframework.data.mongodb.core.MongoTemplate.executeFindOneInternal(MongoTemplate.java:1921)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064895222Z   at org.springframework.data.mongodb.core.MongoTemplate.doFindOne(MongoTemplate.java:1732)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064898298Z   at org.springframework.data.mongodb.core.MongoTemplate.findById(MongoTemplate.java:652)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064901512Z   at org.springframework.data.mongodb.core.MongoTemplate.findById(MongoTemplate.java:645)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064904696Z   at io.muoncore.newton.query.mongo.MongoEventStreamIndexStore.findOneById(MongoEventStreamIndexStore.java:21)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064908670Z   at io.muoncore.newton.cluster.MuonClusterAwareTrackingSubscriptionManager.getEventStreamIndex(MuonClusterAwareTrackingSubscriptionManager.java:122)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064912066Z   at io.muoncore.newton.cluster.MuonClusterAwareTrackingSubscriptionManager.localTrackingSubscription(MuonClusterAwareTrackingSubscriptionManager.java:87)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064921990Z   at io.muoncore.newton.cluster.MuonClusterAwareTrackingSubscriptionManager.lambda$globallyUniqueSubscription$4(MuonClusterAwareTrackingSubscriptionManager.java:67)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064925822Z   at io.muoncore.newton.cluster.LocalOnlyLockService.lambda$executeAndRepeatWithLock$1(LocalOnlyLockService.java:32)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064929105Z   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064932837Z   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[36mservices-security-service-1 |[0m 2017-08-03T07:40:23.064936240Z   at java.lang.Thread.run(Thread.java:745)
daviddawson commented 7 years ago

Is there any context you could add about this?

The stack says that mongo client isn't in a suitable state yet, normally because its starting or stopping for some reason.

bobjana commented 7 years ago

I don't think mongo client is starting/stopping (99% sure) We've had previous stacktraces in past with same mongo stack even though it was a newton &/or underlying client app issue. I've asked Mark to gather a bit more info as to when this is happening

markmcnaughton commented 7 years ago

Hi David, this is the same error as the one mentioned on Tuesday eve. I was hoping 0.0.14 would resolve it but it happened again. It seems to occur fairly randomly but afterwards I need to restart the service which appears to resolve it at least for a while. I'll add more info as soon as I have more.

daviddawson commented 7 years ago

hmm, ok. So this is probably something client side rather than server side. Ie, in the Newton piece/ core-service rather than in the Photon server.

I'll do some experimentation. Do you have a log covering the period the error occurs from the client side (ie, core-service/ whatever)? I'm looking at things around the service. You can slack me that if you want to.

daviddawson commented 7 years ago

In the latest master/ 0.11 snapshots MuonClusterAwareTrackingSubscriptionManager has changed quite a bit to address these kind of problems. Notably https://github.com/muoncore/newton/issues/51

That's marked as fixed in the latest snapshot, so it would be worth upgrading the services to the 0.0.11-SNAPSHOT and verify with that.

Note that this is in newton only, so would require the services to be updated, not the Photon server.