Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Using MapStoreConfig in a cluster raises Transition not allowed from state NOT_LOADED to LOADED exception #8196

Closed
TheBellman opened this issue May 17, 2016 · 38 comments

Comments

Projects
None yet
4 participants
@TheBellman
Copy link

commented May 17, 2016

(Cross posting from Stack Overflow)

Note this relates to version 3.6.2

I am attempting to use persistence for a distributed HazelCast Map. When I query the map on one node in a cluster, the other nodes report (many) instances of the following exception:

May 16, 2016 5:43:45 PM com.hazelcast.map.impl.operation.LoadStatusOperation
SEVERE: [172.17.0.2]:5701 [dev_docker] [3.6.2] Transition not allowed from state NOT_LOADED to LOADED
java.lang.IllegalStateException: Transition not allowed from state NOT_LOADED to LOADED
    at com.hazelcast.util.Preconditions.checkState(Preconditions.java:313)
    at com.hazelcast.util.StateMachine.next(StateMachine.java:60)
    at com.hazelcast.util.StateMachine.nextOrStay(StateMachine.java:70)
    at com.hazelcast.map.impl.MapKeyLoader.trackLoading(MapKeyLoader.java:228)
    at com.hazelcast.map.impl.recordstore.DefaultRecordStore.updateLoadStatus(DefaultRecordStore.java:115)
    at com.hazelcast.map.impl.operation.LoadStatusOperation.run(LoadStatusOperation.java:48)
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:172)
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:393)
    at com.hazelcast.spi.impl.operationexecutor.classic.OperationThread.processPacket(OperationThread.java:184)
    at com.hazelcast.spi.impl.operationexecutor.classic.OperationThread.process(OperationThread.java:137)
    at com.hazelcast.spi.impl.operationexecutor.classic.OperationThread.doRun(OperationThread.java:124)
    at com.hazelcast.spi.impl.operationexecutor.classic.OperationThread.run(OperationThread.java:99)

The Map is being created in each node, on request, as follows:

    MapConfig config = hazelcastInstance.getConfig().getMapConfig("someName");
    MapStoreConfig msConfig = config.getMapStoreConfig();
    msConfig.setEnabled(true)
        .setInitialLoadMode(MapStoreConfig.InitialLoadMode.LAZY)
        .setWriteDelaySeconds(WRITE_DELAY_SECONDS)
        .setWriteBatchSize(WRITE_BATCH_SIZE)
        .setImplementation(new RegistrationCacheStore(queueRepository));
    IMap<String, RegistrationWrapper> regMap = hazelcastInstance.getMap("someName");
    regMap.addEntryListener(new RegistrationCacheListener(queueManager, hazelcastInstance), true);

where RegistrationCacheStore is just a bridge across to the actual persistence layer.

When I invoke values() against the map in one node, it appears to silently work as desired (at least no exceptions are thrown in that node), but the other nodes go nuts with the exception above. Note that the underlying datastore for the map is empty at the time this is invoked, however the same behaviour pertains if there is data in the underlying table.

All the code in question works fine if there is only a single node in the cluster, which suggests I am getting something wrong with the way I'm trying to use persistence. In my case I want a distributed Map which persists through the failure/shutdown of one or all nodes in the cluster.

I have placed debugging traces into my persistence layer, and can see that the MapStore.loadAllKeys() is invoked and successfully returns on the node that I am invoking values() against, while the other nodes do not attempt to invoke the MapStore at all

@vbekiaris

This comment has been minimized.

Copy link
Contributor

commented May 17, 2016

Thanks for reporting the issue @TheBellman. Can you please start your Hazelcast members with the JVM option -Dhazelcast.slow.operation.detector.stacktrace.logging.enabled=true and share relevant stack traces, should they occur?
Also, if your custom MapStore implements MapLoaderLifecycleSupport, can you share what your init method does?

@TheBellman

This comment has been minimized.

Copy link
Author

commented May 17, 2016

Cheers for the response, I'll make those changes in a few hours after my current meeting, and report back on what I find.

@TheBellman

This comment has been minimized.

Copy link
Author

commented May 17, 2016

Ok, was able to sneak some time during the meeting - adding the logging flag did not provide any additional stack traces.

Currently the my RegistrationCacheStore only implements MapStore - should it also implement MapLoaderLifecycleSupport if I am using it in a cluster?

@vbekiaris

This comment has been minimized.

Copy link
Contributor

commented May 17, 2016

Thanks, I will attempt to reproduce using the code you posted. You don't need to implement MapLoaderLifecycleSupport, just wondering because not getting invocations in your MapStore methods seemed familiar.

@TheBellman

This comment has been minimized.

Copy link
Author

commented May 17, 2016

Do you need more info on how I'm setting up the Hazelcast Instance? might be of relevance anyway. The following is used by Spring and some of our own framework to blow in various configuration items at startup:

    MulticastConfig multicastConfig = new MulticastConfig()
        .setEnabled(true)
        .setMulticastGroup(multicastGroup)
        .setMulticastPort(multicastPort)
        .addTrustedInterface(trustedInterface);

    JoinConfig joinConfig = new JoinConfig()
        .setMulticastConfig(multicastConfig);

    NetworkConfig networkConfig = new NetworkConfig()
        .setPort(port)
        .setPortAutoIncrement(true)
        .addOutboundPort(0)
        .setJoin(joinConfig);

    Config config = new Config();
    config.setNetworkConfig(networkConfig);
    config.getGroupConfig()
        .setName(makeName(clusterName))
        .setPassword(clusterPassword == null ? GroupConfig.DEFAULT_GROUP_PASSWORD : clusterPassword);
    config.setProperty("hazelcast.phone.home.enabled", "false");
    config.getQueueConfigs().put("*", new QueueConfig().setEmptyQueueTtl(registrationTtl + FIVE_MINUTES));
    config.getSetConfigs().put("*", new SetConfig().setBackupCount(1));

    logger.info("Constructed HazelcastInstance configuration: {}", config);

    instance = Hazelcast.newHazelcastInstance(config);
@TheBellman

This comment has been minimized.

Copy link
Author

commented May 20, 2016

Any news on this issue? At the moment this is a show-stopper for us

@vbekiaris

This comment has been minimized.

Copy link
Contributor

commented May 20, 2016

Sorry to hear that; I have not done any real progress for now, I was quite busy as we are approaching code freeze for 3.7. It would help a lot if you could provide a simple reproducer (e.g. in the form of a test).

@TheBellman

This comment has been minimized.

Copy link
Author

commented May 20, 2016

Will do - I will get this to you within the next few days.

@TheBellman

This comment has been minimized.

Copy link
Author

commented May 24, 2016

I have spent much of the day building a dummy version of the server that was manifesting the problem, and have put it in my personal GitHub for your consumption : https://github.com/TheBellman/MapStoreConfigTest

The bad news is that when I ran this, using two Docker images in the same VM, the problem did not manifest. I will endeavour to refine the test and hopefully get it to break again. If not, then this has the horrible smell of something colliding between Hazelcast and the Datastax Cassandra drivers, or Hazelcast and Tomcat, or some combination.

Addendum
I have returned to the actual service to verify that the problem still exists, which it does. Here's how I'm reproducing with the actual service, which fails out every time:

  1. run a 4-node Cassandra 3.x cluster in Docker;
  2. run 2 instances of the service in Docker, in the same VM (note that the application is a WAR run inside a Tomcat 8)
  3. use curl from my host OS to invoke the health-check API on each instance of the service, to verify it has successfully connected to the Cassandra cluster;
  4. use curl to invoke the get-registrations API on one instance of the service, which just asks the IMap instance for it's values as shown below:
 registrationCache
        .values()
        .stream()
        .filter(Objects::nonNull)
        .map(it -> new Registration(it.getRegistration()))
        .collect(Collectors.toList());
  1. observe in the logs of one of the instances that the MapStore.loadAllKeys is invoked and exits cleanly, while the other instance goes nuts with the exception.

In the most recent iteration of testing around this, I modified the MapStore implementation so that it did not invoke the Cassandra data store layer at all, and the problem persisted.

@TheBellman

This comment has been minimized.

Copy link
Author

commented May 24, 2016

Looking at the stack trace and the code, is it that the node that is erroring is being told "get ready, you're going to load stuff", putting it in the NOT_LOADED state, but does not get any keys to load and so the next instruction it gets is "you're finished", which tries to put it in the LOADED state? Sorry, trying to wrap my head around the state machine, and I can't see how the second node gets into LOADING

@vbekiaris

This comment has been minimized.

Copy link
Contributor

commented May 30, 2016

Thanks for attempting to reproduce the issue @TheBellman . Indeed, it looks like what you described, the map loader is asked to enter LOADED state with the LoadStatusOperation while being in NOT_LOADED state, a transition that is not allowed.
Are you able to set the loggers for com.hazelcast.map.impl.MapKeyLoader and com.hazelcast.map.impl.recordstore.DefaultRecordStore to finest level and obtain output?

@TheBellman

This comment has been minimized.

Copy link
Author

commented May 31, 2016

Sigh. Trying to. Have been beating my head against this all morning, and not seeing any log messages at DEBUG or lower for those classes. Logback configuration is:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <contextName>ctp-eventlog-service</contextName>
    <contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator">
        <resetJUL>true</resetJUL>
    </contextListener>
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>${logback.log.level.console:-ALL}</level>
        </filter>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <Pattern>%d{HH:mm:ss} %-5p %c [%t] - %msg%n</Pattern>
        </encoder>
    </appender>
    <logger name="com.hazelcast" level="INFO"/>
    <logger name="com.hazelcast.map.impl.MapKeyLoader" level="DEBUG"/>
    <logger name="com.hazelcast.map.impl.recordstore.DefaultRecordStore" level="DEBUG"/>
    <logger name="ctp" level="${logback.log.level.com.ctp:-INFO}"/>
    <logger name="com.datastax" level="INFO" />
    <logger name="org.apache" level="WARN"/>
    <logger name="org.apache.cxf" level="${logback.log.level.org.apache.cxf:-ERROR}"/>
    <logger name="org.springframework" level="WARN"/>
    <root level="ALL">
        <appender-ref ref="CONSOLE"/>
    </root>
</configuration>

and I can see that the appropriate logging property is set

/apps/ctp/java/jdk8/bin/java
  -Djava.util.logging.config.file=/apps/ctp/tomcat/eventlogsvc/conf/logging.properties 
  -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
  -Djava.security.egd=file:/dev/urandom
  -Dhazelcast.slow.operation.detector.stacktrace.logging.enabled=true
  -Dhazelcast.logging.type=slf4j
  -Dorg.apache.catalina.connector.RECYCLE_FACADES=false
  -Dorg.apache.catalina.connector.CoyoteAdapter.ALLOW_BACKSLASH=false
  -Dorg.apache.tomcat.util.buf.UDecoder.ALLOW_ENCODED_SLASH=false
  -Dorg.apache.coyote.USE_CUSTOM_STATUS_MSG_IN_HEADER=false
  -Xmx800m -Xms800m -XX:MaxPermSize=512m
  -Djava.endorsed.dirs=/apps/ctp/tomcat/tomcat8/endorsed
  -classpath /apps/ctp/tomcat/tomcat8/bin/bootstrap.jar:/apps/ctp/tomcat/tomcat8/bin/tomcat-juli.jar
  -Dcatalina.base=/apps/ctp/tomcat/eventlogsvc
  -Dcatalina.home=/apps/ctp/tomcat/tomcat8
  -Djava.io.tmpdir=/apps/ctp/tomcat/eventlogsvc/temp
org.apache.catalina.startup.Bootstrap start

I can continue by attempting to widen the scope of logging at debug level, but I'm not sure that I'm configuring this logging correctly - certainly if I extend logging to DEBUG on "com.hazelcast" I see the heartbeats logging, but I still did not see any additional messages out of the map or map store classes.

@vbekiaris

This comment has been minimized.

Copy link
Contributor

commented May 31, 2016

Hi Robert, I think in your logback config you need to set level to TRACE in order to see what hazelcast logs at FINEST level.

    <logger name="com.hazelcast.map.impl.MapKeyLoader" level="TRACE"/>
    <logger name="com.hazelcast.map.impl.recordstore.DefaultRecordStore" level="TRACE"/>
@TheBellman

This comment has been minimized.

Copy link
Author

commented May 31, 2016

That did the trick, although there' still a puzzle:

    <!-- <logger name="com.hazelcast" level="ALL"/> -->
    <logger name="com.hazelcast.map.impl.MapKeyLoader" level="TRACE"/>
    <logger name="com.hazelcast.map.impl.recordstore.DefaultRecordStore" level="TRACE"/>
    <logger name="ctp" level="${logback.log.level.com.ctp:-INFO}"/>
    <logger name="com.datastax" level="INFO" />
    <logger name="org.apache" level="WARN"/>
    <logger name="org.apache.cxf" level="${logback.log.level.org.apache.cxf:-ERROR}"/>
    <logger name="org.springframework" level="WARN"/>
    <root level="ALL">
        <appender-ref ref="CONSOLE"/>
    </root>

I would have thought this would suppress all logging from Hazelcast apart from those two classes, but I'm now getting TRACE level messages from all Hazelcast clusters!

I'm not seeing anything coming out of MapKeyLoader but on the node which is not throwing the exception I see a bunch of these from DefaultRecordStore

2016-05-31 10:41:02,395 TRACE com.hazelcast.map.impl.recordstore.DefaultRecordStore [hz._hzInstance_1_dev_docker.partition-operation.thread-0] - [172.17.0.7]:5701 [dev_docker] [3.6.2] Completed loading map ElsRegistrationCache on partitionId=0
2016-05-31 10:41:02,571 TRACE com.hazelcast.map.impl.recordstore.DefaultRecordStore [hz._hzInstance_1_dev_docker.partition-operation.thread-1] - [172.17.0.7]:5701 [dev_docker] [3.6.2] Completed loading map ElsRegistrationCache on partitionId=111

etc

I have attached the logs from the two instances
Logs.zip

@TheBellman

This comment has been minimized.

Copy link
Author

commented May 31, 2016

This gave a happier result. Not thinking this morning...

    <logger name="com.hazelcast" level="INFO"/>
    <logger name="com.hazelcast.map.impl.MapKeyLoader" level="TRACE"/>
    <logger name="com.hazelcast.map.impl.recordstore.DefaultRecordStore" level="TRACE"/>

Slightly cleaner files attached
Logs.zip

@sgerr

This comment has been minimized.

Copy link

commented Jun 7, 2016

Hi, I'm facing the same problem with hazelcast-3.6.3 using MapStore

Jun 07, 2016 1:53:13 PM com.hazelcast.map.impl.operation.LoadStatusOperation
SEVERE: [10.78.15.146]:5701 [dev] [3.6.3] Transition not allowed from state NOT_LOADED to LOADED
java.lang.IllegalStateException: Transition not allowed from state NOT_LOADED to LOADED
        at com.hazelcast.util.Preconditions.checkState(Preconditions.java:313)
        at com.hazelcast.util.StateMachine.next(StateMachine.java:60)
        at com.hazelcast.util.StateMachine.nextOrStay(StateMachine.java:70)
        at com.hazelcast.map.impl.MapKeyLoader.trackLoading(MapKeyLoader.java:228)
        at com.hazelcast.map.impl.recordstore.DefaultRecordStore.updateLoadStatus(DefaultRecordStore.java:115)
        at com.hazelcast.map.impl.operation.LoadStatusOperation.run(LoadStatusOperation.java:48)
        at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:172)
        at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:393)
        at com.hazelcast.spi.impl.operationexecutor.classic.OperationThread.processPacket(OperationThread.java:184)
        at com.hazelcast.spi.impl.operationexecutor.classic.OperationThread.process(OperationThread.java:137)
        at com.hazelcast.spi.impl.operationexecutor.classic.OperationThread.doRun(OperationThread.java:124)
        at com.hazelcast.spi.impl.operationexecutor.classic.OperationThread.run(OperationThread.java:99)

Important note: the problem occures when trying configure MapStore programmatically by specifying factoryClassName. When MapStore is configured using hazelcast.xml (<map-store enabled="true" initial-mode="LAZY">) it works fine.

@TheBellman

This comment has been minimized.

Copy link
Author

commented Jun 8, 2016

Interesting. Unfortunately it is probably not possible for me to use XML configuration, as I need to create some of the hazel cast objects dynamically. I'm setting the persistence implementation directly via setImplementation() which is different to what you are doing, but this might suggest there is a different initialisation path taken for the MapStoreConfig or MapStore object(s) depending on whether the persistence implementation is injected more directly or indirectly through the XML configuration.

@tombujok

This comment has been minimized.

Copy link
Contributor

commented Jun 16, 2016

@TheBellman @sgerr Could you test with 3.7 EA? It shouldn't appear anymore.

@TheBellman

This comment has been minimized.

Copy link
Author

commented Jun 17, 2016

I have retested just now with 3.7 EA that I pulled yesterday - same problem exists.

2016-06-17 11:12:26,023 ERROR com.hazelcast.map.impl.operation.LoadStatusOperation [hz._hzInstance_1_dev_docker.partition-operation.thread-0] - [172.17.0.6]:5701 [dev_docker] [3.7-EA]  Transition not allowed from state NOT_LOADED to LOADED
java.lang.IllegalStateException: Transition not allowed from state NOT_LOADED to LOADED
    at com.hazelcast.util.Preconditions.checkState(Preconditions.java:313) ~[hazelcast-3.7-EA.jar:3.7-EA]
@tombujok

This comment has been minimized.

Copy link
Contributor

commented Jun 17, 2016

OK, Thanks for testing! This problem does not lead to data-loss or corruption, so it may be ignored, but the transition is broken for these nodes. I'll keep that in the backlog for 3.8.

@tombujok tombujok added this to the 3.8 milestone Jun 17, 2016

@tombujok tombujok assigned tombujok and unassigned vbekiaris Jun 17, 2016

@TheBellman

This comment has been minimized.

Copy link
Author

commented Jun 17, 2016

Hmm. I will continue testing, when I was using this previously this error was actually preventing items that were in the backing database being loaded to the in-memory map. I should be able to confirm within a few hours whether this is still actually breaking for us.

@TheBellman

This comment has been minimized.

Copy link
Author

commented Jun 17, 2016

No, this is still badly broken for us. With data in the backing store, I ran two instances of my app that is using a distributed map. Once I saw that both instances had enrolled in the hazel cast cluster, I invoked the operation that attempted to read from the map - nothing was retrieved from the map. I reran this test with only a single instance, and retrieval from the map succeeded. Somehow when this is exception is being thrown, the map is winding up in a corrupted state, or perhaps more correctly no data is loaded from the backing store. This is a show stopper for us - if we are going to persist with HazelCast as a solution the persisted state of distributed in-memory objects needs to be able to be reinstated if the whole cluster is restarted. Our intention is to be deploying our application as Docker images, so it is highly likely that the whole application cluster will be restarted. In this scenario it is demonstrable that we get data loss.

@tombujok

This comment has been minimized.

Copy link
Contributor

commented Jun 17, 2016

@TheBellman Hmm, that's really weird. Let me recap:

  • you have two nodes in a cluster: node A and B
  • you have some data in an underlying DB
  • you configured Lazy Loading with a MapLoader that loads from the DB
  • when the cluster is operational and both nodes joined you invoked map.values() on node A
  • operation finishes without any exception, but there result is empty
  • node A does not throw any exceptions, but node B has the Transition not allowed from state NOT_LOADED to LOADED exception in the logs.

My questions:

  • Could you attach log files from both nodes?
  • How many records are there in the DB?
  • Are you calling map.values() from the client or from within the JVM of one node? (which one?)
@TheBellman

This comment has been minimized.

Copy link
Author

commented Jun 17, 2016

Good questions and recap :-)

  1. will attach logs...
    nodeB.log.zip
    nodeA.log.zip
  2. there are two records in the database (initial testing had only 1 record);
  3. map.values() is invoked from the JVM of node A...

Note in the logs that the select() was initiated around 13:46:59,308.

At the time this test was done, the map will have been empty, the first operation against it was the values() call, and no other processing against either HazelCast or the database had occurred at this time.

@tombujok

This comment has been minimized.

Copy link
Contributor

commented Jun 24, 2016

Thx for the info. I'll try to reproduce it today.

@tombujok

This comment has been minimized.

Copy link
Contributor

commented Jul 5, 2016

@TheBellman I tried to reproduce it using the following test:
https://gist.github.com/tombujok/e439d087ab196c767890763959374971

I added it to MapLoaderTest.java
https://github.com/tombujok/hazelcast/blob/63c8c38c0cf804506318d414d22145b32b91142f/hazelcast/src/test/java/com/hazelcast/map/impl/mapstore/MapLoaderTest.java#L56-L56

It works fine. Am I missing something from your config?
Could you try making it fail?

@tombujok tombujok modified the milestones: 3.7, 3.8 Jul 5, 2016

@TheBellman

This comment has been minimized.

Copy link
Author

commented Jul 7, 2016

Thanks @tombujok I should be able to look at this properly tomorrow, however at a glance that test looks ok. This is starting to smell badly like something that is only showing up with some combination of Tomcat and/or Cassandra, which is profoundly weird.

@TheBellman

This comment has been minimized.

Copy link
Author

commented Jul 12, 2016

Taking me longer to get this tested and examined than I wanted - I got sidetracked working the application into the form we are actually going to run it in, which is within a Docker Swarm cluster, using TCP/IP rather than Multicast. Fortunately that all appears to work as desired, and the only thing still causing problems is the original problem.

@vbekiaris vbekiaris modified the milestones: 3.8, 3.7 Jul 12, 2016

@TheBellman

This comment has been minimized.

Copy link
Author

commented Jul 12, 2016

I've verified that the configuration of the test case - apart from the implementation of the loader - is what I have in my live code. I've also verified that the results from my loader implementation correspond to the test, i.e. load() returns null when no result, and loadAll() and loadAllKeys() return a non-null collection when no result. I've even put some 100ms sleeps in my implementation to match the test case. And yet, it still fails. Very much at the end of my tether with this, as the differences between my live case and the test case can be summarised as

  • running 3 instances in docker containers in separate virtual machines
  • running the application inside a tomcat
  • using Cassandra (with the Datastax drivers) as the backing store.

I do notice though that all of the tests are running multiple nodes in the same JVM, rather than separate JVMs. Combined with the suggestion that configuring via XML might have solved the problem, is it feasible that somewhere the finite state machine is not being initialised correctly? Otherwise this is an absolutely berserk problem arising from either Docker, Tomcat or Cassandra!

ADDENDUM:
I've checked out the latest master, and have verified I can build it locally. On that basis, I will litter MapKeyLoader with debug logging, and see if I can trace the invocations on the nodes.

@TheBellman

This comment has been minimized.

Copy link
Author

commented Jul 13, 2016

Hmm. Tracing is interesting. I notice that MapKeyLoader.promoteToLoadedOnMigration() appears to be intended to massage the state machine to get around this problem, jumping the state machine correctly to LOADING then to LOADED.

That is only called from DefaultRecordStore.startLoading()

public void startLoading() {
    if (logger.isFinestEnabled()) {
        logger.finest("StartLoading invoked " + getStateMessage());
    }
    if (mapStoreContext.isMapLoader() && !loadedOnCreate) {
        if (!loadedOnPreMigration) {
            if (logger.isFinestEnabled()) {
                logger.finest("Triggering load " + getStateMessage());
            }
            loadedOnCreate = true;
            loadingFutures.add(keyLoader.startInitialLoad(mapStoreContext, partitionId));
        } else {
            if (logger.isFinestEnabled()) {
                logger.finest("Promoting to loaded on migration " + getStateMessage());
            }
            keyLoader.promoteToLoadedOnMigration();
        }
    }
}

and on the nodes that are throwing the exception, it is never being called - i observe that loadedOnCreate and loadedOnPreMigration stay false in every report.

startLoading invoked on partitionId=1 on [eventlog-2]:5701 loadedOnCreate=false loadedOnPreMigration=false isLoaded=true

Given that I can see the bad nodes entering DefaultRecordStore.startLoading() but never firing either the "triggering load" or "promoting to loaded" messages, I can only guess that mapStoreContext.isMapLoader() is always false.

Addendum

The plot thickens. On the node that I invoke the call, I have a full fledged MapContext in the method above:

BasicMapStoreContext{mapName='ElsRegistrationCache', 
    mapStoreManager=com.hazelcast.map.impl.mapstore.writebehind.WriteBehindManager@29f563cb,
    storeWrapper=MapStoreWrapper{mapName='ElsRegistrationCache',
    mapStore=ctp.eventlog.core.cache.RegistrationCacheStore@6b148f21,
    mapLoader=ctp.eventlog.core.cache.RegistrationCacheStore@6b148f21},
    mapServiceContext=com.hazelcast.map.impl.MapServiceContextImpl@28046c27,
    mapStoreConfig=MapStoreConfig{enabled=true, className='null', factoryClassName='null',
    writeDelaySeconds=2,
    writeBatchSize=50, 
    implementation=ctp.eventlog.core.cache.RegistrationCacheStore@6b148f21,
    factoryImplementation=null, properties={}, readOnly=null, initialLoadMode=LAZY, 
    writeCoalescing=true}}  

However on the other two nodes, which are erring out, I have

EmptyMapStoreContext{}

which is not what I was expecting - this suggests that the secondary nodes do not know they should have a map store associated with the map?

@TheBellman

This comment has been minimized.

Copy link
Author

commented Jul 14, 2016

Ok, I've spent quite some time tracing this, and think I might know what is going on. The MapStoreContext comes out of MapStoreContextFactory.createMapStoreContext(), which returns the EmptyMapStoreContext if the MapStoreConfig has isEnabled() == false

Examining the state of the overall configuration at NodeEngineImpl.getConfig() (which is the source of the Config and thus ultimately the MapStoreConfig) I can see there's a big difference in the MapStoreConfig between the "good" and "bad" nodes.

The "good" node, which is the one receiving the map request, has the following mapConfigs:

mapConfigs={
    default=MapConfig{
        name='default'', inMemoryFormat=BINARY', backupCount=1, asyncBackupCount=0,
        timeToLiveSeconds=0, maxIdleSeconds=0, evictionPolicy='NONE', mapEvictionPolicy='null',
        evictionPercentage=25, minEvictionCheckMillis=100,
        maxSizeConfig=MaxSizeConfig{maxSizePolicy='PER_NODE', size=2147483647},
        readBackupData=false, hotRestart=HotRestartConfig{enabled=false, fsync=false},
        nearCacheConfig=null,
        mapStoreConfig=MapStoreConfig{
            enabled=false, className='null', factoryClassName='null', writeDelaySeconds=0,
            writeBatchSize=1, implementation=null, factoryImplementation=null, properties={},
            readOnly=null, initialLoadMode=LAZY, writeCoalescing=true},
        mergePolicyConfig='com.hazelcast.map.merge.PutIfAbsentMapMergePolicy',
        wanReplicationRef=null, entryListenerConfigs=[], mapIndexConfigs=[],
        mapAttributeConfigs=[], quorumName=null, queryCacheConfigs=[],
        cacheDeserializedValues=INDEX_ONLY},
    ElsRegistrationCache=MapConfig{
        name='ElsRegistrationCache'', inMemoryFormat=BINARY', backupCount=1, asyncBackupCount=0,
        timeToLiveSeconds=0, maxIdleSeconds=0, evictionPolicy='NONE', mapEvictionPolicy='null',
        evictionPercentage=25, minEvictionCheckMillis=100,
        maxSizeConfig=MaxSizeConfig{maxSizePolicy='PER_NODE', size=2147483647},
        readBackupData=false, hotRestart=HotRestartConfig{enabled=false, fsync=false},
        nearCacheConfig=null, mapStoreConfig=MapStoreConfig{
            enabled=true, className='ctp.eventlog.core.cache.RegistrationCacheStore',
            factoryClassName='null', writeDelaySeconds=2, writeBatchSize=50,
            implementation=ctp.eventlog.core.cache.RegistrationCacheStore@2937dd11,
            factoryImplementation=null, properties={}, readOnly=null,
            initialLoadMode=LAZY, writeCoalescing=true},
        mergePolicyConfig='com.hazelcast.map.merge.PutIfAbsentMapMergePolicy',
        wanReplicationRef=null, entryListenerConfigs=[], mapIndexConfigs=[],
        mapAttributeConfigs=[], quorumName=null, queryCacheConfigs=[],
        cacheDeserializedValues=INDEX_ONLY}},

while the node that is throwing the exceptions has the following:

mapConfigs={
    default=MapConfig{
        name='default'', inMemoryFormat=BINARY', backupCount=1, asyncBackupCount=0,
        timeToLiveSeconds=0, maxIdleSeconds=0, evictionPolicy='NONE', mapEvictionPolicy='null',
        evictionPercentage=25, minEvictionCheckMillis=100,
        maxSizeConfig=MaxSizeConfig{maxSizePolicy='PER_NODE', size=2147483647},
        readBackupData=false, hotRestart=HotRestartConfig{enabled=false, fsync=false},
        nearCacheConfig=null,
        mapStoreConfig=MapStoreConfig{
            enabled=false, className='null', factoryClassName='null', writeDelaySeconds=0,
            writeBatchSize=1, implementation=null, factoryImplementation=null, properties={},
            readOnly=null, initialLoadMode=LAZY, writeCoalescing=true},
        mergePolicyConfig='com.hazelcast.map.merge.PutIfAbsentMapMergePolicy',
        wanReplicationRef=null, entryListenerConfigs=[], mapIndexConfigs=[],
        mapAttributeConfigs=[], quorumName=null, queryCacheConfigs=[],
        cacheDeserializedValues=INDEX_ONLY}},

In other words, only the first node has the configuration for the specific map. This is bewildering me, although it does suggest why configuration via XML rather than programmatically is working, as the XML configuration is read and instantiated at the time the Hazelcast instance is started, rather than later when the instance is already up and running. I will explore whether something weird in my code is happening such that the setup on the good node is firing, but not firing on the other nodes, but I am sceptical.

@TheBellman

This comment has been minimized.

Copy link
Author

commented Jul 14, 2016

This looks like some sort of timing issue. On the first node, picking out some key points in time, with the value request against this node firing at about 02:52:49,153

2016-07-13 02:51:17,872 INFO  com.hazelcast.cluster.impl.TcpIpJoiner [localhost-startStop-1] - [eventlog-1]:5701 [vagrant] [3.7-SNAPSHOT]
Members [1] {
        Member [eventlog-1]:5701 - fe0ea86b-ad51-4ba1-9fe8-0a92604180c8 this
}
2016-07-13 02:51:18,220 INFO  com.hazelcast.core.LifecycleService [localhost-startStop-1] - [eventlog-1]:5701 [vagrant] [3.7-SNAPSHOT] [eventlog-1]:5701 is STARTED
2016-07-13 02:51:19,267 INFO  ctp.eventlog.core.cache.RegistrationCacheProvider [localhost-startStop-1] - RAH DEBUG RegistrationCacheProvider.afterPropertiesSet has fired
2016-07-13 02:51:56,411 INFO  com.hazelcast.internal.cluster.ClusterService [hz._hzInstance_1_vagrant.generic-operation.thread-0] - [eventlog-1]:5701 [vagrant] [3.7-SNAPSHOT]
Members [3] {
        Member [eventlog-1]:5701 - fe0ea86b-ad51-4ba1-9fe8-0a92604180c8 this
        Member [eventlog-3]:5701 - b27f5c49-5cf7-4664-b0f1-6082d692f4ff
        Member [eventlog-2]:5701 - 2bc9c13c-1351-4cf0-9c2d-f1e95863fed2
}
[request fires]
2016-07-13 02:52:49,153 INFO  com.hazelcast.internal.partition.impl.PartitionStateManager [http-nio-8310-exec-1] - [eventlog-1]:5701 [vagrant] [3.7-SNAPSHOT] Initializing cluster partition table arrangement...

While on the second (bad) node I see

2016-07-13 02:51:59,092 INFO  com.hazelcast.internal.cluster.ClusterService [hz._hzInstance_1_vagrant.generic-operation.thread-0] - [eventlog-2]:5701 [vagrant] [3.7-SNAPSHOT]
Members [3] {
        Member [eventlog-1]:5701 - fe0ea86b-ad51-4ba1-9fe8-0a92604180c8
        Member [eventlog-3]:5701 - b27f5c49-5cf7-4664-b0f1-6082d692f4ff
        Member [eventlog-2]:5701 - 2bc9c13c-1351-4cf0-9c2d-f1e95863fed2 this
}
2016-07-13 02:52:01,042 INFO  com.hazelcast.core.LifecycleService [localhost-startStop-1] - [eventlog-2]:5701 [vagrant] [3.7-SNAPSHOT] [eventlog-2]:5701 is STARTED
2016-07-13 02:52:01,931 INFO  ctp.eventlog.core.cache.RegistrationCacheProvider [localhost-startStop-1] - RAH DEBUG RegistrationCacheProvider.afterPropertiesSet has fired
2016-07-13 02:52:51,964 INFO  com.hazelcast.map.impl.recordstore.DefaultRecordStore [hz._hzInstance_1_vagrant.partition-operation.thread-0] - [eventlog-2]:5701 [vagrant] [3.7-SNAPSHOT] RAH DEBUG DefaultRecordStore constructed - mapStoreContext: EmptyMapStoreContext{}

Prior to the DefaultRecordStore being constructed, there had been a call into NodeEngineImpl.getConfig() at 02:51:59,381 that returned a Config only containing the default map configuration.

HOWEVER at 02:52:51,985 I see a call into NodeEngineImpl.getConfig() which is finding the full configuration, including the map store configuration for the map in question.

In other words, at the time the second node received the request to begin loading, it had the EmptyMapStoreContext, and so the loader correctly was not loading, and did not progress the state machine into the expected state. A little later, the second node was aware of the store context, suggesting that a later invocation would work (although it doesn't, once in this state, the map stays thoroughly broken)

Question is there some specific lag between the configuration being pushed into the HZ instance, and it becoming available? You will note that I pushed the map-specific configuration in the second node at 02:52:01,931, but at 02:52:51,964 this configuration was not "visible" at the time the DefaultRecordStore was constructed. Weirdly, I see no trace of a call to fetch the Config prior to the DefaultRecordStore on this second node, whereas I was seeing it on the first node.

Addendum Starting up the set of services, and letting them sit for 10 minutes before attempting access has the same result. As far as I can tell, when the secondary nodes get the request to do the map load, their view of the current configuration has not been updated at all, and they do not "see" the configuration for the specific map until after they have failed. This is all very very bad, and I am not a happy man today.

@TheBellman

This comment has been minimized.

Copy link
Author

commented Jul 15, 2016

Just checking the timings, I can confirm that even though the local node's "set up the map configuration" fired a long time before the invocation of the call, the constructed data store was not aware of the specific configuration:

2016-07-15 10:35:56,325 INFO  ctp.eventlog.core.cache.RegistrationCacheProvider [localhost-startStop-1] - RAH DEBUG
     RegistrationCacheProvider.afterPropertiesSet has fired

2016-07-15 10:45:40,256 INFO  com.hazelcast.map.impl.recordstore.DefaultRecordStore [hz._hzInstance_1_vagrant.partition-operation.thread-0] - 
    [eventlog-3]:5701 [vagrant] [3.7-SNAPSHOT] RAH DEBUG DefaultRecordStore constructed - mapStoreContext: EmptyMapStoreContext{}

2016-07-15 10:45:40,304 INFO  com.hazelcast.map.impl.PartitionContainer [hz._hzInstance_1_vagrant.partition-operation.thread-0] - [eventlog-3]:5701
     [vagrant] [3.7-SNAPSHOT] RAH DEBUG PartitionContainer.createRecordStore, MapStoreConfig.isEnabled = false, MapStoreContext = EmptyMapStoreContext{}

2016-07-15 10:45:40,359 INFO  com.hazelcast.spi.NodeEngine [hz._hzInstance_1_vagrant.partition-operation.thread-0] - [eventlog-3]:5701 [vagrant]
     [3.7-SNAPSHOT] RAH DEBUG NodeEngineImpl.getConfig returning: Config{groupConfig=GroupConfig [name=vagrant, password=****************], 
     properties={hazelcast.phone.home.enabled=false}, networkConfig=NetworkConfig{publicAddress='eventlog-3', port=5701, portCount=100, 
     portAutoIncrement=false, join=JoinConfig{multicastConfig=MulticastConfig [enabled=false, multicastGroup=224.2.2.3, multicastPort=54327, 
     multicastTimeToLive=32, multicastTimeoutSeconds=2, trustedInterfaces=[], loopbackModeEnabled=false], tcpIpConfig=TcpIpConfig [enabled=true, 
     connectionTimeoutSeconds=5, members=[eventlog-1, eventlog-2, eventlog-3, eventlog-3], requiredMember=null], 
     awsConfig=AwsConfig{enabled=false, region='us-east-1', securityGroupName='null', tagKey='null', tagValue='null', 
     hostHeader='ec2.amazonaws.com', iamRole='null', connectionTimeoutSeconds=5}, 
     discoveryProvidersConfig=com.hazelcast.config.DiscoveryConfig@329e49bc}, interfaces=InterfacesConfig{enabled=false, interfaces=[]}, 
     sslConfig=null, socketInterceptorConfig=null, symmetricEncryptionConfig=null}, mapConfigs={default=MapConfig{name='default'', 
     inMemoryFormat=BINARY', backupCount=1, asyncBackupCount=0, timeToLiveSeconds=0, maxIdleSeconds=0, evictionPolicy='NONE', 
     mapEvictionPolicy='null', evictionPercentage=25, minEvictionCheckMillis=100, maxSizeConfig=MaxSizeConfig{maxSizePolicy='PER_NODE', 
     size=2147483647}, readBackupData=false, hotRestart=HotRestartConfig{enabled=false, fsync=false}, nearCacheConfig=null, 
     mapStoreConfig=MapStoreConfig{enabled=false, className='null', factoryClassName='null', writeDelaySeconds=0, writeBatchSize=1, 
     implementation=null, factoryImplementation=null, properties={}, readOnly=null, initialLoadMode=LAZY, writeCoalescing=true}, 
     mergePolicyConfig='com.hazelcast.map.merge.PutIfAbsentMapMergePolicy', wanReplicationRef=null, entryListenerConfigs=[], mapIndexConfigs=[],
     mapAttributeConfigs=[], quorumName=null, queryCacheConfigs=[], cacheDeserializedValues=INDEX_ONLY}, 
     ElsRegistrationCache=MapConfig{name='ElsRegistrationCache'', inMemoryFormat=BINARY', backupCount=1, asyncBackupCount=0, timeToLiveSeconds=0,
     maxIdleSeconds=0, evictionPolicy='NONE', mapEvictionPolicy='null', evictionPercentage=25, minEvictionCheckMillis=100, 
     maxSizeConfig=MaxSizeConfig{maxSizePolicy='PER_NODE', size=2147483647}, readBackupData=false, hotRestart=HotRestartConfig{enabled=false,
     fsync=false}, nearCacheConfig=null, mapStoreConfig=MapStoreConfig{enabled=true, 
     className='ctp.eventlog.core.cache.RegistrationCacheStore', factoryClassName='null', writeDelaySeconds=2, writeBatchSize=50, 
     implementation=ctp.eventlog.core.cache.RegistrationCacheStore@72639d01, factoryImplementation=null, properties={}, readOnly=null, 
     initialLoadMode=LAZY, writeCoalescing=true}, mergePolicyConfig='com.hazelcast.map.merge.PutIfAbsentMapMergePolicy',
     wanReplicationRef=null, entryListenerConfigs=[], mapIndexConfigs=[], mapAttributeConfigs=[], quorumName=null, queryCacheConfigs=[],
     cacheDeserializedValues=INDEX_ONLY}}, topicConfigs={}, reliableTopicConfigs={}, queueConfigs={*=QueueConfig{name='null',
     listenerConfigs=null, backupCount=1, asyncBackupCount=0, maxSize=0, emptyQueueTtl=7500, queueStoreConfig=null, statisticsEnabled=true}}, 
     multiMapConfigs={}, executorConfigs={default=ExecutorConfig{name='default', poolSize=16, queueCapacity=2147483647}},
     semaphoreConfigs={}, ringbufferConfigs={}, wanReplicationConfigs={}, listenerConfigs=[],
     partitionGroupConfig=PartitionGroupConfig{enabled=false, groupType=PER_MEMBER, memberGroupConfigs=[]},
     managementCenterConfig=ManagementCenterConfig{enabled=false, url='null', updateInterval=3}, securityConfig=SecurityConfig{enabled=false,
     memberCredentialsConfig=CredentialsFactoryConfig{className='null', implementation=null, properties={}}, memberLoginModuleConfigs=[],
     clientLoginModuleConfigs=[], clientPolicyConfig=PermissionPolicyConfig{className='null', implementation=null, properties={}},
     clientPermissionConfigs=[]}, liteMember=false}

As you can see, there was no call to get the current node configuration prior to the record store being created.

@tombujok

This comment has been minimized.

Copy link
Contributor

commented Jul 15, 2016

Thank you for your deep analysis @TheBellman ! It enabled diagnosing the problem very quickly.
The bug is caused by the fact that you're modifying the config of a running HazelcastInstance.
The config should be passed to the newHazelcastInstance method - but should not be modified later on. Please check the Javadoc for the Config class:
http://docs.hazelcast.org/docs/latest/javadoc/com/hazelcast/config/Config.html

@TheBellman

This comment has been minimized.

Copy link
Author

commented Jul 15, 2016

Oh dear. This is going to be a problem then - I'll go back to the Hazelcast documentation as well, because my recollection is that the documentation really does not make that clear.

The problem that is going to arise for me is that maps and queues will be created and disposed dynamically and may not have consistent configurations - in particular of course the names of the queues and maps will not be known ahead of time. As you can see from the RegistrationCacheStore I am creating, I pass in the name of the map (and I have a similar strategy with the other backing stores floating around in my application). Does this suggest that I will need to inject a factory into the MapStoreContext?

@tombujok

This comment has been minimized.

Copy link
Contributor

commented Jul 15, 2016

Yeah, sorry, that manual is not clear about that, I agree. I was planning to send a PR to the hazelcast-manual repo to clarify that, but maybe you would like to do it? so that it's fully your contribution? (In this case I would need to ask you to send a signed Contributor Licence Agreement:
https://hazelcast.atlassian.net/wiki/display/COM/Hazelcast+Contributor+Agreement?preview=/6357071/6619138/Hazelcast%2C%20Inc.%20Individual%20Contrbutor%20License%20Agreement%20v100113.pdf

To solve your problem you could use wildcards in the configuration, please have a look at the following manual section:
http://docs.hazelcast.org/docs/3.6/manual/html-single/index.html#using-wildcards

BTW, are you on hazelcast Gitter? Could we connect there to have a short chat?

@TheBellman

This comment has been minimized.

Copy link
Author

commented Jul 15, 2016

Agree, will probably be able to use wildcard configurations, although might need to make my store implementations smarter. Not on Gitter yet, but will sign on soon(ish) and yes, will dig into the manual repo to raise a PR. Will be nice to get this closed off :-)

@tombujok tombujok modified the milestones: 3.7, 3.8 Jul 16, 2016

@tombujok

This comment has been minimized.

Copy link
Contributor

commented Jul 16, 2016

Thanks for the analysis and the PR. Closing this one.

@tombujok tombujok closed this Jul 16, 2016

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.