网关请求下游系统时长记录

## 1.场景
最近一体机开发人员反馈网关处理时间过长的问题，即一体机系统请求ERP系统(经过网关中转)，响应时长高达12s，但是PO给出的反馈是响应时长在1s之内，那么一体机开发人员得出的结论是网关处理用了11s，由于网关的日志中并没有记录请求下游系统的时长，所以这个锅就由网关背下来了。
## 2.需求
网关的请求日志中打印出请求下游系统的时长。
## 3.解决
### 1.测试网关执行流程
我们请求一个hr系统的接口，传入什么参数，就返回什么参数，来打断点测试下经过了网关的哪些插件。
![](/media/202403/2024-03-06_164830_833825.png)
我们发现y有20个插件参与责任链执行，如下
![](/media/202403/2024-03-06_165250_435331.png)
全部执行完成，我发现执行了如下插件
sign-->request-->divide-->webClient-->loggingConsole-->response。
### 2.分析网关请求下游系统源码
既然要记录网关请求下游系统时长，那么就要搞清楚网关执行divide插件后，具体发起http请求在哪里，具体的响应在哪里，从如上的执行流程中可知应该是webClient这个插件承担了这个角色，走起，看源码。
![](/media/202403/2024-03-06_171018_420511.png)
由如上源码可知，WebClientPlugin继承了AbstractHttpClientPlugin，查看AbstractHttpClientPlugin的源码如下
![](/media/202403/2024-03-06_171248_888972.png)
发现AbstractHttpClientPlugin类下面有两个继承类webclient和netty，我们选择默认的webclient，听说netty承载的并发效果好，这也对应网关官网中请求方式的介绍。
![](/media/202403/2024-03-06_172624_003610.png)
查看源码得知
```
inal Mono<R> response = doRequest(exchange, exchange.getRequest().getMethodValue(), uri, httpHeaders, exchange.getRequest().getBody())
                .timeout(duration, Mono.error(new TimeoutException("Response took longer than timeout: " + duration)))
                .doOnError(e -> LOG.error(e.getMessage(), e));
```
这里是发起请求的具体地方，跟进去就是WebClientPlugin了，具体执行了哪些逻辑，查看代码可知
![](/media/202403/2024-03-06_173206_501375.png)
由如上源码可知，响应的地方也找到了。
### 3.添加代码记录请求开始时间和结束时间
由于最后loggingConsole会打印出本次请求的header信息和响应header信息，因此我将在request header和response header中添加请求时间和结束时间。当然也可以添加在request的前后，但是整体来看日志量比较多，后续查找日志的时候，不太方便，而打印在header中的话，比较醒目些。
![](/media/202403/2024-03-07_111010_071377.png)
如上是请求开始时间。
接着处理结束时间
![](/media/202403/2024-03-07_113318_949416.png)
而这个时间一直伴随着到loggingConsole插件打印出来
![](/media/202403/2024-03-07_113520_104816.png)
我们发现刚好这个时间在response header中，只是Date的格式是格林尼治标准时间，现在只需要将这个时间格式化成"yyyy-MM-dd HH: mm :ss" 就行。
查阅资料才知道将 格林尼治标准时间 转换成 如上这种格式，目前jdk没得通用的类，接着查阅资料才发现格林尼治标准时间遵循RFC822定义，接着找到资料 rome 包可以解析这种格式的时间，如是工程中引入了
```

<dependency>
    <groupId>com.rometools</groupId>
    <artifactId>rome</artifactId>
    <version>2.1.0</version>
</dependency>
```
但是发现2.1.0版本中的代码不齐全，缺少rome-parent包，还是无法解析这种格式的时间，没办法，只有到github上找rome的源码，git地址：https://github.com/rometools/rome
![](/media/202403/2024-03-07_114656_040563.png)
如是将源码拉取下来，发现
![](/media/202403/2024-03-07_115640_998341.png)
于是查阅DateParser.java文件，发现如下
![](/media/202403/2024-03-07_115855_407632.png)
将这个文件加入到我们工程中，解析格林尼治标准时间的代码如下
```
    void addHeader(HttpHeaders headers, String value){
        try {
            Date testDate = DateParser.parseRFC822(value, Locale.US);
            SimpleDateFormat simpleDateFormat = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss");
            String dateString = simpleDateFormat.format(testDate);
            headers.add("responseTime",dateString);
        }catch (Exception e){
            e.printStackTrace();
        }
    }
```
测试结果如下
![](/media/202403/2024-03-07_140128_810184.png)
自此，功能实现！
## 4.反思
如上是解决了网关请求下游系统的时长，如何记录一个请求进入网关后，具体执行了哪些插件，这些插件的执行时间呢？
官方给的样例如下
![](/media/202403/2024-03-07_140344_031968.png)
思路是在exchange中添加属性，属性包括插件名称、进入插件时间、出去插件时间，这其中的时间差就是该插件的执行时长！那么问题来了，如何知道这个插件执行完成的时候呢？