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

Event Journal throws StaleSequenceException when TTL > 0 #13746

Closed
cangencer opened this issue Sep 12, 2018 · 0 comments
Closed

Event Journal throws StaleSequenceException when TTL > 0 #13746

cangencer opened this issue Sep 12, 2018 · 0 comments

Comments

@cangencer
Copy link
Contributor

@cangencer cangencer commented Sep 12, 2018

Event Journal when configured with TTL > 0 can sometimes throw StaleSequenceException

com.hazelcast.ringbuffer.StaleSequenceException: sequence:21393 is too small and data store is disabled. The current headSequence is:21394 tailSequence is:22124
	at com.hazelcast.ringbuffer.impl.RingbufferContainer.checkBlockableReadSequence(RingbufferContainer.java:435)
	at com.hazelcast.ringbuffer.impl.RingbufferContainer.shouldWait(RingbufferContainer.java:241)
	at com.hazelcast.map.impl.journal.RingbufferMapEventJournalImpl.isNextAvailableSequence(RingbufferMapEventJournalImpl.java:122)
	at com.hazelcast.internal.journal.EventJournalReadOperation.shouldWait(EventJournalReadOperation.java:140)
	at com.hazelcast.spi.Operation.call(Operation.java:143)
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:202)
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:191)
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:120)
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.run(OperationThread.java:100)

A reproducer (might take a few runs / some time to reproduce):

package test;

import com.hazelcast.config.Config;
import com.hazelcast.config.EventJournalConfig;
import com.hazelcast.core.ExecutionCallback;
import com.hazelcast.core.HazelcastInstance;
import com.hazelcast.core.IMap;
import com.hazelcast.internal.journal.EventJournalReader;
import com.hazelcast.map.journal.EventJournalMapEvent;
import com.hazelcast.projection.Projections;
import com.hazelcast.ringbuffer.ReadResultSet;
import com.hazelcast.test.HazelcastParallelClassRunner;
import com.hazelcast.test.HazelcastTestSupport;
import com.hazelcast.util.function.Consumer;
import org.junit.Before;
import org.junit.Test;
import org.junit.runner.RunWith;

import java.util.concurrent.TimeUnit;
import java.util.concurrent.locks.LockSupport;

@RunWith(HazelcastParallelClassRunner.class)
public class EventJournalTest extends HazelcastTestSupport {
    private static final int JOURNAL_CAPACITY = 1000;
    private IMap<String, Integer> map;
    private String MAP_NAME = "test";
    private EventJournalReader<EventJournalMapEvent<String, Integer>> reader;
    private HazelcastInstance hz;

    @Before
    public void setUp() {
        Config config = new Config();

        EventJournalConfig journalConfig = new EventJournalConfig()
                .setMapName("*")
                .setCapacity(JOURNAL_CAPACITY)
                .setTimeToLiveSeconds(1)
                .setEnabled(true);
        config.addEventJournalConfig(journalConfig);
        config.setProperty("hazelcast.partition.count", "1");
        hz = this.createHazelcastInstance(config);

        map = hz.getMap(MAP_NAME);
        reader = (EventJournalReader<EventJournalMapEvent<String, Integer>>) map;
    }

    @Test
    public void test() {
        readFromJournal(0, e -> {
            System.out.println(e.getNewValue());
        });

        for (int i = 0; i < 100_000; i++) {
            map.put("a", i);
            LockSupport.parkNanos(TimeUnit.MILLISECONDS.toNanos(1));
        }

    }

    private void readFromJournal(long seq,
                                 Consumer<EventJournalMapEvent<String, Integer>> consumer
    ) {
        reader.readFromEventJournal(
                seq, 1, 128, 0, e -> true, Projections.identity()
        ).andThen(new ExecutionCallback<ReadResultSet<EventJournalMapEvent<String, Integer>>>() {
            @Override
            public void onResponse(ReadResultSet<EventJournalMapEvent<String, Integer>> response) {
                readFromJournal(response.getNextSequenceToReadFrom(), consumer);
                for (EventJournalMapEvent<String, Integer> event : response) {
                    consumer.accept(event);
                }
                LockSupport.parkNanos(TimeUnit.SECONDS.toNanos(2));
            }

            @Override
            public void onFailure(Throwable t) {
                t.printStackTrace();
            }
        });
    }
}
@cangencer cangencer added this to the 3.11 milestone Sep 12, 2018
mmedenjak added a commit to mmedenjak/hazelcast that referenced this issue Sep 12, 2018
The event journal read operation would clean up expired events in two
places - before executing the operation and each time events would be
added to the result set. As the read operation is loss-tolerant, the
requested sequence was corrected only after the first cleanup. Since
there is a time window between these two cleanups, the sequence needs to
be readjusted after the second cleanup as well.
This might also mean that the result set may contain "gaps" if there
were big pauses and the items expired after they have been added to the
journal and before they were added to the result set.

Fixes: hazelcast#13746
@mmedenjak mmedenjak self-assigned this Sep 12, 2018
mmedenjak added a commit to mmedenjak/hazelcast that referenced this issue Sep 26, 2018
The event journal read operation would clean up expired events in two
places - before executing the operation and each time events would be
added to the result set. As the read operation is loss-tolerant, the
requested sequence was corrected only after the first cleanup. Since
there is a time window between these two cleanups, the sequence needs to
be readjusted after the second cleanup as well.
This might also mean that the result set may contain "gaps" if there
were big pauses and the items expired after they have been added to the
journal and before they were added to the result set.

Fixes: hazelcast#13746
mmedenjak added a commit that referenced this issue Sep 26, 2018
Skip expired events in journal when reading

The event journal read operation would clean up expired events in two
places - before executing the operation and each time events would be
added to the result set. As the read operation is loss-tolerant, the
requested sequence was corrected only after the first cleanup. Since
there is a time window between these two cleanups, the sequence needs to
be readjusted after the second cleanup as well.
This might also mean that the result set may contain "gaps" if there
were big pauses and the items expired after they have been added to the
journal and before they were added to the result set.

Fixes: #13746
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

2 participants
You can’t perform that action at this time.