看麻了呀，线程池日志错乱问题

一、背景

由于推送业务的历史问题，推送业务代码比较散乱，推送日志也不方便查看，推送模型也不够统一，因此专门设计一个核心模块来逐步替换掉之前的推送业务代码，进行统一管理

二、问题描述

通过线程池抓取数据后进行组装然后推送给业务方，在推送过程中出现整个日志上下文打印错乱的问题，如A线程持有的上下文参数对象，在B线程的日志中被打印出来了。在测试case中，有三类数据要被推送，不同类型的数据被分到同一个线程池的不同线程处理，如下(正常情况)：A类数据—>T1线程处理–>T1线程日志展示A类数据的上下文信息(如类型信息，list大小,查询条件内容等等) B类数据—>T2线程处理–>T2线程日志展示B类数据的上下文信息(如类型信息，list大小,查询条件内容等等) C类数据—>T3线程处理–>T3线程日志展示C类数据的上下文信息(如类型信息，list大小,查询条件内容等等) 但是在日志显示上是错乱的，如下：A类数据—>T1线程处理–>T1线程日志展示A类数据的上下文信息(如类型信息，list大小,查询条件内容等等)+部分B类数据的上下文信息(如list大小,查询条件内容) B类数据—>T2线程处理–>T2线程日志展示B类数据的上下文信息(如类型信息，list大小,查询条件内容等等)+部分A类数据的上下文信息(如list大小,查询条件内容) C类数据—>T3线程处理–>T3线程日志展示C类数据的上下文信息(如类型信息，list大小,查询条件内容等等)

上面的是打印日志方面的问题，但是实际上在测试过程中整个数据推送流程没有问题，因此当时第一阶段上线前并没有太在意，上线之后也没有问题，但是至于为啥会错乱，肯定需要排查的。

三、排查思路

3.1 并发问题

第一印象是觉得可能出现了并发问题，因此在关键方法上加了锁，重新发了一版之后生效了，但是后面又出现了，所以这个方向不对。

3.2 trace问题

由于是xxljob触发调度，在调度过程中没有统一的trace信息，因此加上了，最初也是怀疑是因为aop+MDC trace导致的，另外之前也看过trace多线程日志错乱问题，但是明显跟我这个场景不一样,在业务代码中注释了引入的trace代码之后还是存在问题，所以这个方向也排除了。

3.3 其他问题

配置问题
嵌套调用
…..

另外也通过上面的方向排查了，没啥思路。

3.4 问题场景回归

每个线程只处理一类数据，上下文是隔离的，但是当前日志的内容却打印了别的类型的数据，明显出现错乱，所以可能是组装数据的上下文不是纯隔离的。如下代码：

   /**
     * 推送
     * @param pushDataContext
     */
    private void exePush(PushDataContext pushDataContext){
        Map<Long, List<PushTaskMain>> pushTaskGroupMap = pushDataContext.getPushTaskList().stream().collect(Collectors.groupingBy(PushTaskMain::getPushConfigId));
        try {
            for (Map.Entry<Long,List<PushTaskMain>> pushTaskGroup : pushTaskGroupMap.entrySet()){
                PushConfig pushConfig = pushConfigService.getCacheById(pushTaskGroup.getKey());
                if(pushConfig == null){
                    log.debug("orgId={},找不到pushConfig id= {},不再推送数据任务",pushDataContext.getOrgId(), pushTaskGroup.getKey());
                    continue;
                }
                pushThreadExecutor.execute(()->{
                    try {
                        pushProcess(pushConfig, pushTaskGroup.getValue(), pushDataContext);
                    }catch (Exception e) {
                        log.error("推送任务执行异常",e);
                      
                    }
                });
            }
        }catch (Exception e) {
            log.error("推送任务执行异常",e);
        }
    }
    /**
     * 执行入口
     * @param pushConfig
     * @param pushTaskList
     * @param pushDataContext
     */
    public void pushProcess(PushConfig pushConfig, List<PushTaskMain> pushTaskList, PushDataContext pushDataContext){
        //这里进行线程隔离，每个线程池持有一个新的PushDataContext对象
        PushDataContext newPushDataContext = new PushDataContext();
        newPushDataContext.setPushConfig(pushConfig);
        newPushDataContext.setRound(pushDataContext.getRound());
        newPushDataContext.setOrgId(pushConfig.getOrgId());
        Map<String,PushTaskMain> pushTaskMainMap = pushTaskList.stream().collect(Collectors.toMap(PushTaskMain::getDataId,o->o,(o1,o2)->o1));
        newPushDataContext.setPushTaskList(pushTaskList);
        newPushDataContext.setPushTaskMap(pushTaskMainMap);
        newPushDataContext.setQueryParams(pushDataContext.getQueryParams());
     //调用数据抓取和组装的processorBean,然后后面继续调用推送的processorBean
        PushDataProcessor pushDataProcessor = (PushDataProcessor)ApplicationContextUtils.getBean(pushConfig.getDataProcessorBeanName());
        pushDataProcessor.processData(newPushDataContext);
    }

初步怀疑是对象引用问题，导致 PushDataContext newPushDataContext虽然是新对象，但是其值却不是，由于排查过程中并不太方便打印sql，所以仅仅针对pushTaskList做了一次深拷贝，然后测试，结果也不对，另外也在多个地方打印了newPushDataContext对象的地址，印证了每个线程只会持有自己的对象，另外也排除掉了嵌套调用的情况。后面因为整个推送流程涉及到多个服务类的调用，所以在多个关键节点上加了对推送类型，查询参数，查询sql和数据返回方面的日志，在多次反复测试过程中发现了线索，日志如下：T1线程处理A类数据，打印T1持有的A类数据的相关内容，打印A类数据的上下文的queryParams的内容 T2线程处理B类数据，打印T2持有的B类数据的相关内容，打印B类数据的上下文的queryParams的内容(但是此时这个map里的kv却包含了A类上下文才持有的查询参数kv) T3线程处理C类数据，打印T3持有的C类数据的相关内容，打印C类数据的上下文的queryParams的内容(但是此时这个map里的kv却包含了A类上下文才持有的查询参数kv) 由此可见确定了是因为newPushDataContext.setQueryParams的数据是被多线程共享了，导致后面往里塞查询条件kv的时候被其他线程看到了，然后打印了其他线程的数据。