如何快速过滤出一次请求的所有日志？

TIPS：下文于2019/03/29 11:36分享在公司内部wiki上。觉得不错，在博客园晒出来。

 

 

• 由 张国战创建, 最后修改于三月 29, 2019

 

本文在说什么？？？

先看下面的日志：

2019-03-29 11:41:00,766 INFO  [pool-9-thread-26] ? (:) - 执行请求......

2019-03-29 12:02:30,759 INFO  [pool-9-thread-26] ? (:) - 消息类型:epcc.401.001.01-网联格式......

我们知道，应用程序的线程池里的线程是会被重复利用的，就是说，一个线程处理完一个任务（比如一次http请求）后只是暂时处于空闲状态，然后会继续执行不断涌向线程池的任务。每个线程都有自己的Id（Thread#tid，只读属性）和名字（Thread#name），线程id是不可改变的，线程名通常是默认的XXXPool-M-Thread-N，例如Pool-1-Thread-0、DubboServerHandler-192.168.40.84:20880-thread-110

。我们在应用程序的log文件里也经常可以看到不同时间的两笔（或多笔）请求的线程名是一样的。

那么，问题来了，当现网系统请求比较大的时候，一次请求的所有日志并不是逐行在一起的，而是穿插在其他请求的日志行里。再加上线程名会重复。就像下面这样子的，我们要过滤出请求1的所有日志来排查问题，并不是一件容易的事情！本文要说的就是如何快速过滤出一次请求的所有日志。

2019-03-29 11:41:00,361 INFO [线程名1] 请求1的log，......
2019-03-29 11:41:00,362 INFO [线程名2] 请求2的log，......
2019-03-29 11:41:00,766 INFO [线程名2] 请求2的log，......
2019-03-29 11:41:00,812 INFO [线程名2] 请求2的log，......
2019-03-29 11:41:00,812 INFO [线程名1] 请求1的log，......
2019-03-29 11:41:00,833 INFO [线程名3] 请求3的log，......
2019-03-29 11:41:00,834 INFO [线程名4] 请求4的log，......
2019-03-29 11:41:00,891 INFO [线程名2] 请求2的log，......
2019-03-29 11:41:00,900 INFO [线程名1] 请求1的log，......
2019-03-29 11:41:01,000 INFO [线程名1] 请求5的log，......
2019-03-29 11:41:01,111 INFO [线程名1] 请求5的log，......
2019-03-29 11:41:01,111 INFO [线程名1] 请求5的log，......

曾经，，，

我曾在对接某银行银企直联通道时，看到了他们前置机系统log文件里所打印的日志，每个请求都有唯一的一个标志，查看日志感觉很清爽。于是我在那时的项目里也尝试并使用这种方式，在后续的系统运维排障中爽歪歪。https://www.cnblogs.com/buguge/p/7417737.html

樊哥也说，很多公司都是用这种方法，来定位业务日志的。比如华为的这哥们儿，也在用其他工具来实现类似这种的方式，来提高工作排障效率，https://wudashan.cn/2018/02/15/Log-Request-In-MutiThread/。

 

现在，，，

payment_api转账这块，我把默认线程名改成有意义的字符串了，每次请求都有唯一的一个标志，方便排障。

 

 

但是payment_server和gateway_server的不好使。会重复。
现象：服务重启后，一旦某个线程被占用，更改了它的线程名之后，以后即使再被用到，线程名就改不了了。
通过分析thrift源码，目前进展是，线程池控制在TThreadedSelectorServer.startThreads()方法里。再往下分析比较吃力。