[Bug or not?]Confusion logback traceid print

[xiangtianyu]

I create a demo to explain the problem that i met.

I tried to print logs in thread pool. And i add "trace=%X{trace_id},span=%X{span_id}" to my logback.xml

@RestController
@Slf4j
public class ThreadController {
    private final ThreadPoolExecutor threadPoolExecutor = new ThreadPoolExecutor(10, 10, 5, TimeUnit.MINUTES,
            new LinkedBlockingDeque<>(1024), new BasicThreadFactory.Builder().namingPattern("queue-worker-%d").build(), new ThreadPoolExecutor.CallerRunsPolicy());

    @Resource
    private ThreadPoolTaskExecutor threadPoolTaskExecutor;

    @GetMapping("/testLog")
    public String testLog() {

        for (int i = 0; i < 20; i++) {
            threadPoolTaskExecutor.execute(() -> {
                log.info("--->" + Thread.currentThread().getName());
            });
        }

        for (int j = 0; j < 20; j++) {
            threadPoolExecutor.execute(() -> {
                log.info("===>" + Thread.currentThread().getName());
            });
        }

        return "OK";
    }

}

And the app log like this, some logs having trace id and span id but some have nothing.

2023-08-10 15:47:26,736 [task-executor-15] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:31] trace=,span= - --->task-executor-15
2023-08-10 15:47:26,734 [task-executor-10] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:31] trace=,span= - --->task-executor-10
2023-08-10 15:47:26,736 [task-executor-14] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:31] trace=dda15781c8cdca3e958f2dd914fb134c,span=49ba2f8fc5086c32 - --->task-executor-14
2023-08-10 15:47:26,731 [task-executor-3] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:31] trace=dda15781c8cdca3e958f2dd914fb134c,span=49ba2f8fc5086c32 - --->task-executor-3
2023-08-10 15:47:26,735 [task-executor-11] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:31] trace=dda15781c8cdca3e958f2dd914fb134c,span=49ba2f8fc5086c32 - --->task-executor-11
2023-08-10 15:47:26,731 [task-executor-1] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:31] trace=dda15781c8cdca3e958f2dd914fb134c,span=49ba2f8fc5086c32 - --->task-executor-1
2023-08-10 15:47:26,736 [task-executor-13] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:31] trace=,span= - --->task-executor-13
2023-08-10 15:47:26,736 [task-executor-16] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:31] trace=dda15781c8cdca3e958f2dd914fb134c,span=49ba2f8fc5086c32 - --->task-executor-16
2023-08-10 15:47:26,731 [task-executor-2] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:31] trace=,span= - --->task-executor-2
2023-08-10 15:47:26,734 [task-executor-9] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:31] trace=dda15781c8cdca3e958f2dd914fb134c,span=49ba2f8fc5086c32 - --->task-executor-9
2023-08-10 15:47:26,735 [task-executor-8] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:31] trace=dda15781c8cdca3e958f2dd914fb134c,span=49ba2f8fc5086c32 - --->task-executor-8
2023-08-10 15:47:26,733 [task-executor-6] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:31] trace=dda15781c8cdca3e958f2dd914fb134c,span=49ba2f8fc5086c32 - --->task-executor-6
2023-08-10 15:47:26,735 [task-executor-12] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:31] trace=dda15781c8cdca3e958f2dd914fb134c,span=49ba2f8fc5086c32 - --->task-executor-12
2023-08-10 15:47:26,733 [task-executor-7] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:31] trace=,span= - --->task-executor-7
2023-08-10 15:47:26,732 [task-executor-5] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:31] trace=dda15781c8cdca3e958f2dd914fb134c,span=49ba2f8fc5086c32 - --->task-executor-5
2023-08-10 15:47:26,731 [task-executor-4] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:31] trace=,span= - --->task-executor-4
2023-08-10 15:47:26,738 [task-executor-15] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:31] trace=,span= - --->task-executor-15
2023-08-10 15:47:26,738 [task-executor-7] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:31] trace=dda15781c8cdca3e958f2dd914fb134c,span=49ba2f8fc5086c32 - --->task-executor-7
2023-08-10 15:47:26,739 [task-executor-7] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:31] trace=,span= - --->task-executor-7
2023-08-10 15:47:26,739 [task-executor-15] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:31] trace=dda15781c8cdca3e958f2dd914fb134c,span=49ba2f8fc5086c32 - --->task-executor-15
2023-08-10 15:47:26,743 [queue-worker-1] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:35] trace=dda15781c8cdca3e958f2dd914fb134c,span=49ba2f8fc5086c32 - ===>queue-worker-1
2023-08-10 15:47:26,743 [queue-worker-2] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:35] trace=,span= - ===>queue-worker-2
2023-08-10 15:47:26,744 [queue-worker-3] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:35] trace=dda15781c8cdca3e958f2dd914fb134c,span=49ba2f8fc5086c32 - ===>queue-worker-3
2023-08-10 15:47:26,744 [queue-worker-4] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:35] trace=,span= - ===>queue-worker-4
2023-08-10 15:47:26,744 [queue-worker-5] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:35] trace=dda15781c8cdca3e958f2dd914fb134c,span=49ba2f8fc5086c32 - ===>queue-worker-5
2023-08-10 15:47:26,744 [queue-worker-7] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:35] trace=dda15781c8cdca3e958f2dd914fb134c,span=49ba2f8fc5086c32 - ===>queue-worker-7
2023-08-10 15:47:26,745 [queue-worker-8] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:35] trace=dda15781c8cdca3e958f2dd914fb134c,span=49ba2f8fc5086c32 - ===>queue-worker-8
2023-08-10 15:47:26,745 [queue-worker-9] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:35] trace=,span= - ===>queue-worker-9
2023-08-10 15:47:26,745 [queue-worker-10] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:35] trace=dda15781c8cdca3e958f2dd914fb134c,span=49ba2f8fc5086c32 - ===>queue-worker-10
2023-08-10 15:47:26,744 [queue-worker-6] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:35] trace=,span= - ===>queue-worker-6
2023-08-10 15:47:26,746 [queue-worker-1] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:35] trace=,span= - ===>queue-worker-1
2023-08-10 15:47:26,746 [queue-worker-1] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:35] trace=,span= - ===>queue-worker-1
2023-08-10 15:47:26,746 [queue-worker-10] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:35] trace=,span= - ===>queue-worker-10
2023-08-10 15:47:26,746 [queue-worker-2] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:35] trace=dda15781c8cdca3e958f2dd914fb134c,span=49ba2f8fc5086c32 - ===>queue-worker-2
2023-08-10 15:47:26,746 [queue-worker-7] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:35] trace=,span= - ===>queue-worker-7
2023-08-10 15:47:26,746 [queue-worker-5] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:35] trace=,span= - ===>queue-worker-5
2023-08-10 15:47:26,746 [queue-worker-3] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:35] trace=,span= - ===>queue-worker-3
2023-08-10 15:47:26,746 [queue-worker-9] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:35] trace=,span= - ===>queue-worker-9
2023-08-10 15:47:26,746 [queue-worker-8] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:35] trace=,span= - ===>queue-worker-8
2023-08-10 15:47:26,746 [queue-worker-4] INFO  [com.example.springreceiver.controller.ThreadController] [ThreadController.java:35] trace=,span= - ===>queue-worker-4

And if i do something in the thread, such as make an rpc, all the logs will have trace id

@RestController
@Slf4j
public class ThreadController {
    @Resource
    private FeignService feignService;

    private final ThreadPoolExecutor threadPoolExecutor = new ThreadPoolExecutor(10, 10, 5, TimeUnit.MINUTES,
            new LinkedBlockingDeque<>(1024), new BasicThreadFactory.Builder().namingPattern("queue-worker-%d").build(), new ThreadPoolExecutor.CallerRunsPolicy());

    @Resource
    private ThreadPoolTaskExecutor threadPoolTaskExecutor;

    @GetMapping("/testLog")
    public String testLog() {

        for (int i = 0; i < 20; i++) {
            threadPoolTaskExecutor.execute(() -> {
                log.info("--->" + Thread.currentThread().getName());
                feignService.receiver();
            });
        }

        for (int j = 0; j < 20; j++) {
            threadPoolExecutor.execute(() -> {
                log.info("===>" + Thread.currentThread().getName());
                feignService.receiver();
            });
        }

        return "OK";
    }

}

Is this a bug? Or just a print mistake?

What version are you using?
1.15.0

Environment
Compiler: corretto jdk 11
OS: (e.g., "Ubuntu 20.04") macos m1
Runtime (if different from JDK above): corretto jdk 11
OS (if different from OS compiled on): macos m1

[mateuszrzeszutek]

This is a bug, and it's an interesting one. I think I have an idea what causes this, I'll try to fix that.