Why is slf4j logger sometimes print out parent thread even though the code is suppose to be executed by child thread?

Question

Consider this example

@Test
public void test2() throws InterruptedException {
    int MAX_ENTRIES = 2;
    Map cache = new LinkedHashMap(MAX_ENTRIES+1, .75F, true) {
        public boolean removeEldestEntry(Map.Entry eldest) {
            return size() > MAX_ENTRIES;
        }
    };

    MyBufferService testService = new MyBufferService("test2");

    for (int i = 0; i < 100000; i++) {
        testService.putBufferTask(Integer.toString(i));
    }

    TimeUnit.SECONDS.sleep(1);
}


public class MyBufferService {

    private ThreadPoolExecutor executor;

    private final Logger LOGGER = LoggerFactory.getLogger(MyBufferService.class);
    private final Map cache;
    final int MAX_ENTRIES = 1;

    public MyBufferService(String buffName) {
        executor = new ThreadPoolExecutor(1, // corePoolSize
                1, // maximumPoolSize
                60, TimeUnit.SECONDS, // keepAlive
                new LinkedBlockingQueue<>(10000), // workQueue
                new ThreadFactoryBuilder().setNameFormat(buffName + "-MyBufferService-thread-%d").build(), // factory
                new ThreadPoolExecutor.CallerRunsPolicy() // rejected execution handler
        );

        this.cache = new LinkedHashMap(MAX_ENTRIES+1, .75F, true) {
            public boolean removeEldestEntry(Map.Entry eldest) {
                return size() > MAX_ENTRIES;
            }
        };
    }


    private class BufferTask implements Runnable {

        private final String mystring;
        private final Map cache;

        BufferTask(String mystring, Map cache) throws NullPointerException {
            this.mystring = mystring;
            this.cache = cache;
        }
        @Override
        public void run() {
            try {
                synchronized (this.cache) {
                    this.cache.put(this.mystring, "hi");
                    if (this.cache.size() > 0) {
                        LOGGER.info("this is size {}", this.cache.size() );
                    }
                }
            } catch (Throwable t) {

            }
        }
    }

    public void putBufferTask(
            String mystring) throws RejectedExecutionException, NullPointerException {
        executor.submit(new BufferTask(mystring, this.cache));
    }

}

And consider the following output snippet from the line

LOGGER.info("this is size {}", this.cache.size() );


2018-06-13 18:19:46,760 [INFO] [main] c.t.u.w.$MyBufferService - this is size 1
2018-06-13 18:19:46,761 [INFO] [main] c.t.u.w.$MyBufferService - this is size 1
2018-06-13 18:19:46,761 [INFO] [main] c.t.u.w.$MyBufferService - this is size 1
2018-06-13 18:19:46,761 [INFO] [main] c.t.u.w.$MyBufferService - this is size 1
2018-06-13 18:19:46,761 [INFO] [main] c.t.u.w.$MyBufferService - this is size 1
2018-06-13 18:19:46,761 [INFO] [test2-MyBufferService-thread-0] c.t.u.w.$MyBufferService - this is size 1
2018-06-13 18:19:46,761 [INFO] [test2-MyBufferService-thread-0] c.t.u.w.$MyBufferService - this is size 1
2018-06-13 18:19:46,761 [INFO] [test2-MyBufferService-thread-0] c.t.u.w.$MyBufferService - this is size 1
2018-06-13 18:19:46,761 [INFO] [test2-MyBufferService-thread-0] c.t.u.w.$MyBufferService - this is size 1

We see the code inside BufferTask is being run by 2 threads, the main thread and the child thread MyBufferService-thread-0 inside main thread

I was expecting only the child thread to be executing the task, but it seems like the parent thread is also executing the task.

Why is this happening? Am I doing anything wrong?

Answer 1

You set the rejected excecution policy to have the caller run the task. This means that if the task is rejected in #execute that the calling thread (ie. the main thread in your case) will run the task, which is what you are seeing. Change that policy or handle the exception on the #execute method.