Entry processor gets invoked twice even with backups=0 and atomicityMode=ATOMIC

[Philosobyte]

On Ignite 2.16.0 with Java 21, entry processors invoked on empty caches seem to execute twice.
I have created a simple example repo titled "ignite-duplicate-processing-test": https://github.com/Philosobyte/ignite-duplicate-processing-test/blob/main/src/test/java/com/philosobyte/igniteduplicateprocessingtest/DuplicateProcessingTest.java

In this example...

• the number of backups is set to 0 to avoid any scenario where an entry processor executes on both a primary partition and backup partitions
• atomicityMode is set to ATOMIC because, even if there were backups, ATOMIC is supposed to make an entry processor execute only on the primary partition

        @Bean
        public IgniteCache<LightsaberWielder, LightsaberColor> lightsaberColorsCache(Ignite ignite) {
            CacheConfiguration<LightsaberWielder, LightsaberColor> cacheConfig = new CacheConfiguration<>();
            cacheConfig.setName("lightsaber-colors");
            cacheConfig.setCacheMode(CacheMode.PARTITIONED);

            // make sure there are no backup partitions for an entry processor to execute on
            cacheConfig.setBackups(0);
            // even if there were backups, in ATOMIC mode, an entry processor should only execute on the primary partition
            cacheConfig.setAtomicityMode(CacheAtomicityMode.ATOMIC);

            return ignite.getOrCreateCache(cacheConfig);
        }

• the cache key is a POJO containing just one String field
• the cache value is an enum

    // cache key
    @Data
    @NoArgsConstructor
    @AllArgsConstructor
    public static class LightsaberWielder {
        String name;
    }

    // cache value
    public enum LightsaberColor {
        BLUE, RED
    }

• the entry processor randomly selects an enum value out of all possible values and saves it into the cache with entry.setValue

        @Override
        public LightsaberColor process(MutableEntry<LightsaberWielder, LightsaberColor> entry, Object... arguments) throws EntryProcessorException {
            LightsaberWielder lightsaberUser = entry.getKey();
            LightsaberColor existingColor = entry.getValue();
            log.info(
                "Processing on node {} for key {} and existing value {} and random int: {}",
                ignite.cluster().localNode().id(), lightsaberUser, existingColor, random.nextInt()
            );

            LightsaberColor replacementColor = getRandomColor();
            log.info("Setting color to {}", replacementColor);
            entry.setValue(replacementColor);

            return replacementColor;
        }

• the test calls .invoke just once

    @Test
    void test() {
        LightsaberWielder anakin = new LightsaberWielder("anakin");
        LightsaberColor replacementColor = lightsaberRecordsCache.invoke(anakin, lightsaberRecordsEntryProcessor);
        log.info("replacementColor: {}", replacementColor);

        // No assertions here to keep this example simple, but...
        // Log statements show that lightsaberRecordsEntryProcessor.process executes twice, even though
        // the entry processor is invoked only once during the test.

        // The return value, titled replacementColor, always comes from the second execution.
    }

This is the output:

2024-06-29T17:14:26.842-04:00  INFO 36880 --- [ignite-duplicate-processing-test] [    Test worker] c.p.i.DuplicateProcessingTest            : Processing on node b01f1c8d-b3dc-4f96-9ed1-7dcef02761e9 for key DuplicateProcessingTest.LightsaberWielder(name=anakin) and existing value null and random int: 1574068936
2024-06-29T17:14:26.842-04:00  INFO 36880 --- [ignite-duplicate-processing-test] [    Test worker] c.p.i.DuplicateProcessingTest            : Setting color to RED
2024-06-29T17:14:26.844-04:00  INFO 36880 --- [ignite-duplicate-processing-test] [    Test worker] c.p.i.DuplicateProcessingTest            : Processing on node b01f1c8d-b3dc-4f96-9ed1-7dcef02761e9 for key DuplicateProcessingTest.LightsaberWielder(name=anakin) and existing value null and random int: -666424287
2024-06-29T17:14:26.844-04:00  INFO 36880 --- [ignite-duplicate-processing-test] [    Test worker] c.p.i.DuplicateProcessingTest            : Setting color to BLUE
2024-06-29T17:14:26.850-04:00  INFO 36880 --- [ignite-duplicate-processing-test] [    Test worker] c.p.i.DuplicateProcessingTest            : replacementColor: BLUE

Note how there are two sets of log statements from the entry processor where I would normally expect just one. Interestingly, the result returned to the caller is always the result from the second execution instead of the first.

The reason this is a problem for us is we would have liked our entry processor not to be idempotent. This lets us optimize by not doing work when nothing has changed. If the entry processor executes twice, then the first execution will think "something has changed", then the second execution will think "nothing has changed", and then the return value will always tell the client "nothing has changed".

I would be happy to provide further information, and I appreciate any input.

P.S. this is the simplest example... in our business code, we ran into a bizarre case where passing different arguments to the entry processor affected whether the entry processor executed once or twice, even if the entry processor does not actually use the argument except to log the argument to console. For example, if we passed in an EmptyValue POJO containing no fields, the entry processor would execute once. If we passed in a much larger POJO containing maybe 1kB's worth of fields, the entry processor would execute twice. If there is interest, I can attempt to reproduce that more complicated case in a sample project, but I figured posting the simple example would suffice for now.

[ptupitsyn]

Discussed on the user list: https://lists.apache.org/thread/xbcnk17jrhvt278ps9mqo44n6z5jl24w

Please avoid asking the same question in multiple channels.