Reduce logging of errors during shutdown - #10589

@martin-kanis - I took an attempt and now the logs are down from 110 MB to 13 MB.

The change contains to commits while it is in draft mode:

1. the first commit makes sure not to enqueue threads to already closed executors
2. the second commit restructures ClientListenerExecutorDecorator.java so that it will work without error logs and problems even if the number of queued tasks exceeds the executors queue size of the default 1024. It actually implements an unlimited in-memory queue for changes.

The second change is a change to the default behavior, at the same time I wonder when one would discard events here in the first place; I would assume people want to get and process all these event instead of filling the log.

I'd love to hear a first comment. Depending on your comment we could ask more people for feedback here.

// cc: @mhajas, @hmlnarik

@martin-kanis - after yesterdays's call I looked a bit deeper also into DefaultExecutorsProviderFactory and the change you pointed me at.

This is the code in the main branch:

        if (min == max) {
            return Executors.newFixedThreadPool(min, threadFactory);
        } else {
            // Same like Executors.newCachedThreadPool. Besides that "min" and "max" are configurable
            return new ThreadPoolExecutor(min, max,
                    60L, TimeUnit.SECONDS,
                    new ArrayBlockingQueue<>(1024),
                    threadFactory);
        }

Previously this was a SynchronousQueue, then your change in 30b3cae changed it to a ArrayBlockingQueue. Looking at the comment it should be "Same like Executors.newCachedThreadPool", and looking at that code of Executors.newFixedThreadPool() the JDK uses is a LinkedBlockingQueue.

The behaviors of the different classes:

• SynchronousQueue: queue size of 0, accept tasks only if there is an idle thread
• ArrayBlockingQueue with 1024 as the parameter: queue size of 1024, accept tasks only if there is an idle thread or if the queue size is less than 1024
• LinkedBlockingQueue: accept all tasks independent of the queue size

This indicates that when it is configured as min == max, it will accept all tasks as it will use the LinkedBlockingQueue.

I now changed the code to match the comment, it now uses a LinkedBlockingQueue that will never reject a task. This will ensure that all events are published for example to the remote caches, and no task is lost. I prefer this solution over the my initial work as it doesn't touch that much code.

Now the behavior to never reject a task is the same if one would configure min/max to the same size. The downside is that it could queue up a lot of tasks, and I will reach out to Marek in another comment to hear his thoughts.

For now, I'd like you to have a look/review and give me your thoughts on this. Thanks!

// cc: @mhajas, @hmlnarik

Hi @mposolda - we've seen lots of exception as such as the following during the model tests when we create lots of offline sessions to test. They are rejected due to the setup of the executors in DefaultExecutorsProviderFactory.

ERROR [org.keycloak.models.sessions.infinispan.remotestore.ClientListenerExecutorDecorator] (Thread-0) Rejected execution of task for the event 'ClientEvent [ type=CLIENT_CACHE_ENTRY_REMOVED, key=e64b14ae-c978-414d-8656-3084d3580643, version=-1 ]' . Try to increase the pool size. Pool is 'java.util.concurrent.ThreadPoolExecutor@e9bc730[Running, pool size = 64, active threads = 64, queued tasks = 1024, completed tasks = 345]'
13:40:52,179 ERROR [org.infinispan.HOTROD] (Thread-0) ISPN004038: Unexpected error consuming event RemovedEventImpl(key=e64b14ae-c978-414d-8656-3084d3580643)
org.infinispan.commons.CacheListenerException: ISPN004035: Caught exception [java.lang.reflect.InvocationTargetException] while invoking method [public void org.keycloak.models.sessions.infinispan.remotestore.RemoteCacheSessionListener.removed(org.infinispan.client.hotrod.event.ClientCacheEntryRemovedEvent)] on listener instance: org.keycloak.models.sessions.infinispan.remotestore.RemoteCacheSessionListener@7337e84

I wonder if you could remember a reason when an executor should actually reject the task that Keycloak wants to execute, for example when it is about to send something to a remote cache. I would think that I'd rather queue the task than discard it.

Looking at the code I found that when min=max size of the pool, it constructs a thread pool that has a LinkedBlockingQueue of an unlimited size; I'd rather use that setup to never discard an event.

Please let me know what you think about this change in DefaultExecutorsProviderFactory https://github.com/keycloak/keycloak/pull/10589/files#diff-afccac3c0d30862d947ddc23b9670f7e26dbbf26a4687e7b266fc7f8b538df90

Thanks!

@martin-kanis, updated testPersistenceMultipleNodesClientSessionsAtRandomNode a bit so that it can cope with error messages when a cache is shutting down. Do you have more information on the Cross-DC tests failing?

@martin-kanis, updated testPersistenceMultipleNodesClientSessionsAtRandomNode a bit so that it can cope with error messages when a cache is shutting down. Do you have more information on the Cross-DC tests failing?

I don't know yet why Cross-DC tests are failing. Tests use auth-server-wildfly so there should the Wildfly managed thread pool used instead of embedded one, but I'm not sure that is relevant.

@ahus1 Failures in Cross-DC tests are maybe related to this https://developer.jboss.org/thread/239373

Hi @hmlnarik - this PR is ready to be merged.

The biggest change is in DefaultExecutorsProviderFactory.java that changes a bounded queue to an unbounded queue; changing a previous commit here 30b3cae#diff-afccac3c0d30862d947ddc23b9670f7e26dbbf26a4687e7b266fc7f8b538df90.

Thanks!

@hmlnarik - all review comments are now implemented. The current build failed for model tests and quickstarts as the version number changed to "999-SNAPSHOT", therefore this is not relevant here. Thanks.