问题

场景：每隔一分钟执行一次的定时任务
现象：第一次调度成功后，第二次调度必会失败。但是等待第三次调度后，第二次的执行结果却是第三次调度的时间。

奇怪的是，只有每隔一分钟执行一次的任务才会这样，其他间隔一秒或者一小时的又不会有这个问题。
某次调度错误信息：

调度中心调度原理

线上xxl-job版本：2.2.0-SNAPSHOT

在排查原因之前，我看了一下这个版本的源码，对任务的调度以及执行有了一些了解。


执行器内部会开启一个http服务器，用于接受调度中心的调度请求。每次的调度请求都会复用Http连接，避免多次连接消耗资源。
调度步骤：

1. 调度中心从连接池中获取连接
2. 调度中心发送调度请求（带有RequestId，JobLogId），并阻塞线程等待执行器响应
3. 执行器返回调度响应，并异步执行定时任务
4. 调度中心收到调度响应，根据回传的RequestId，回写数据库调取状态。
5. 执行器执行任务后，回调调度中心更新任务执行状态接口，根据JobLogId回写任务执行情况。

根据异常堆载定位问题

根据异常堆栈XxlRpcFutureResponse.java:117，我们可以在代码中找到对应抛出异常的位置。位于调度请求发送后，从Future获取异步结果的get方法。futureResponse的get方法的逻辑是休眠调度线程（默认休眠1秒），等待执行器响应调度请求。线程被唤醒后去检查本次调度是否完成，要是没有完成，就抛出调度失败的错误。
从上面逻辑可以推断出调度中心是成功发送调用请求出去了，因为执行器没有响应导致的调度失败错误。
那么，为什么执行器没有响应调度请求呢？我们就得去看看执行器那边的情况了。

由于xxl-job中处理调度请求的Netty处理器并没有打印具体的日志，所以我们要使用Arthas来观察Netty调度请求处理的执行情况了。

使用Arthas观察调用请求执行情况

使用arthas的watch命令观察执行器接收调用请求情况。

watch com.xxl.rpc.remoting.net.impl.netty_http.server.NettyHttpServerHandler channelRead0 '{params}' -x 2

分析日志

整理一下日志，在问题产生的这段时间内，执行器这边的Netty的调度请求处理器只收到了三个请求

调用日志中，有两个点比较奇怪

1.18:02:30收到了一次请求

在这个时间点为什么会收到一次请求的呢？而且这个请求的请求大小与正常的调用请求的大小还一样，仅有159字节。这么小的请求体，让我想到了一个东西：心跳包。
在RPC框架中，为了监测通信通道的正常以及节点的健康，会定时向节点发送一个请求包，用于判断通道是否正常连接。
虽然调度中心与执行器用的是Http请求，但是xxl-job为了减少资源浪费，使用了连接池，于是也引入了心跳监测。当通道在30秒内没有读写操作时，就发送一个心跳请求。
在执行器也能看到心跳请求的日志。但是这个心跳请求有点奇怪，为什么只在18:02:30分收到呢？18:03:30没有收到呢？
这个问题就跟下面的问题有所关联了。

2.channel远程地址的IP不太对劲，居然是本地地址并非是调度中心的地址

经我了解后，公司的K8S环境中引入了Istio进行服务治理，其中进出Pod的流量都会被Envoy代理，所以127.0.0.6正是Envoy的IP地址。

Envoy是一个由Lyft开发的高性能、可扩展的代理（Proxy）服务器，用于处理微服务架构中的网络通信。它被设计成可用于多种不同的部署场景，并提供了丰富的功能集，如负载均衡、流量路由、故障恢复、安全认证等。

定时任务执行情况

收集日志的时间段正好处于问题发生的一个区间内，这个时间段内定时任务执行情况：

1. 18:02分的任务正常调度并执行成功了。
2. 18:03分的任务调度失败，但是由于执行时间的回填是由执行器针对JobLogId来进行匹配的，所以能得出一个结论03分发送的调度请求，执行器在04分收到了并触发了定时任务。
3. 18:04分的任务调度失败，并且没有执行情况。

总结

截至目前能得到的信息总结一下

1. 调度中心会在通道30秒内没有读写情况下，向各个执行器发送一个心跳请求。
2. 调度中心发送心跳请求后，后续的调度请求都无法进入执行器中。
3. 因为执行器服务部署在K8S中，而且K8S中引入了Istio，导致进入Pod的流量都会被Envoy代理。
4. 该问题的第二次调度虽然失败了，但是会在第三次调度时被执行器成功接收并处理。

好像没有什么突破点，并没有找到真正调度失败的问题。不过我们可以着重去看看Envoy，因为目前进入到Pod的流量都会被它给代理，去观察一下调度失败发生时Envoy的日志。

Envoy日志

[2024-02-21T18:02:00.026Z] "POST / HTTP/1.1" 200 - via_upstream - "-" 626 176 1 0 "-" "-" "d9313e61-6530-4c08-aae2-fd864930ea31" "ebc-portal.ebc-bpm.svc.cluster.local" "10.64.195.45:7666" inbound|7666|| 127.0.0.6:48733 10.64.195.45:7666 10.64.217.207:45584 - default
[2024-02-21T18:02:30.055Z] "POST / HTTP/1.1" 503 UC upstream_reset_before_response_started{connection_termination} - "-" 159 95 90031 - "-" "-" "3de88bd6-41cf-4078-a381-3542b460dd90" "ebc-portal.ebc-bpm.svc.cluster.local" "10.64.195.45:7666" inbound|7666|| 127.0.0.6:48733 10.64.195.45:7666 10.64.217.207:45584 - default
[2024-02-21T18:04:00.087Z] "POST / HTTP/1.1" 200 - via_upstream - "-" 626 176 1 0 "-" "-" "25dac8f9-8364-42bd-8fdd-d08285ed1632" "ebc-portal.ebc-bpm.svc.cluster.local" "10.64.195.45:7666" inbound|7666|| 127.0.0.6:39739 10.64.195.45:7666 10.64.217.207:45584 - default
[2024-02-21T18:04:00.088Z] "POST / HTTP/1.1" 0 DC downstream_remote_disconnect - "-" 159 0 1 - "-" "-" "bfa7dcee-123f-4582-9368-84edcb8476c7" "ebc-portal.ebc-bpm.svc.cluster.local" "10.64.195.45:7666" inbound|7666|| 127.0.0.6:39739 10.64.195.45:7666 10.64.217.207:45584 - default

上面比较异常的日志信息有两段分别是18:02:30以及第二个18:04:00的请求，响应码都不是正常的200，我们来分析一下异常的原因。

异常日志一

[2024-02-21T18:02:30.055Z] "POST / HTTP/1.1" 503 UC upstream_reset_before_response_started{connection_termination} - "-" 159 95 90031 - "-" "-" "3de88bd6-41cf-4078-a381-3542b460dd90" "ebc-portal.ebc-bpm.svc.cluster.local" "10.64.195.45:7666" inbound|7666|| 127.0.0.6:48733 10.64.195.45:7666 10.64.217.207:45584 - default

提取一下比较关键的日志翻译一下。

• "2024-02-21T18:02:30"：请求到达Envoy时间
• "503" 本次请求最终的响应码
• "UC upstream_reset_before_response_started{connection_termination}"：UC代表Upstream Connection，上游服务出现问题，具体的问题信息为上游服务在响应之前重置了，因为连接被终止了。
• "159 95 90031 -"：159是请求体大小，说明是心跳请求；95是响应体大小；90031是请求从 Envoy 到目标服务的持续时间

这个请求比较异常的点有三个：

1.返回了503响应码

为什么会返回503响应码呢？我看了一下执行器的Netty调度请求处理器中，并没有返回503状态码的代码。那么这个503响应码就可能是Envoy代理服务器返回的。
我修改了一下Envoy日志等级，找到本次心跳请求Debug等级的日志

2024-02-21T18:02:30.846361Z debug envoy router [C32432][S12678816626782510759] cluster 'inbound|7666||' match for URL '/'
2024-02-21T18:02:30.846396Z debug envoy router [C32432][S12678816626782510759] router decoding headers:
':authority', 'ebc-portal.ebc-bpm.svc.cluster.local'
':path', '/'
':method', 'POST'
':scheme', 'http'
'content-length', '159'
'x-forwarded-proto', 'http'
'x-request-id', 'ab261a30-679c-403d-be2b-12b161810f28'
2024-02-21T18:02:30.846434Z debug envoy router [C32432][S12678816626782510759] pool ready
2024-02-21T18:02:30.846469Z debug envoy http [C32432][S12678816626782510759] request end stream
2024-02-21T18:04:00.877035Z debug envoy router [C32432][S12678816626782510759] upstream reset: reset reason: connection termination, transport failure reason:
2024-02-21T18:04:00.877095Z debug envoy http [C32432][S12678816626782510759] Sending local reply with details upstream_reset_before_response_started{connection_termination}
2024-02-21T18:04:00.877148Z debug envoy http [C32432][S12678816626782510759] encoding headers via codec (end_stream=false):
':status', '503'
'content-length', '95'
'content-type', 'text/plain'
'date', 'Mon, 21 Feb 2024 18:04:00 GMT'
'server', 'istio-envoy'

从这行日志中可以看到

Sending local reply with details upstream_reset_before_response_started{connection_termination}

本次心跳请求从18:02:30请求进来，18:04:00Envoy发现上游服务器连接终止，于是自己构造了一个503响应码的响应体返回给调度中心。

2.请求时间90031毫秒

本次心跳请求时间太长了，找了一下执行器中Netty调度请求处理器对于心跳请求的处理，发现xxl-job在这个版本中，是不会对心跳做任何处理的。

导致一直不会返回Http响应，而且在Envoy中要是没有一个请求没有收到响应的话，会认为该请求仍在处理中的。直到达到Envoy的请求超时才会取消这次请求。

3.上游服务终止了连接

在这个时间点2024-02-21T18:04:00执行器中打印了一行日志，提示执行器关闭了空闲连接。
找了一下该行日志在源码中的位置，发现这个关闭连接的前提是90秒内通道没有进行读写，然后执行器觉得该连接通道已经异常了，这也是为什么Envoy会提示上游服务终止了连接的原因。

异常日志二

[2024-02-21T18:04:00.088Z] "POST / HTTP/1.1" 0 DC downstream_remote_disconnect - "-" 159 0 1 - "-" "-" "bfa7dcee-123f-4582-9368-84edcb8476c7" "ebc-portal.ebc-bpm.svc.cluster.local" "10.64.195.45:7666" inbound|7666|| 127.0.0.6:39739 10.64.195.45:7666 10.64.217.207:45584 - default

• "2024-02-21T18:04:00"：请求到达Envoy时间
• "0"：本次请求最终的响应码，实际上本次调度中心的请求并没有完成
• "DC downstream_remote_disconnect"：DC代表Downstream Connection，下游服务出现问题，具体的问题信息为下游远程服务终止了连接。
• "159 0 1 - "：159是请求体大小，说明是心跳请求；0是响应体大小；1是请求从 Envoy 到目标服务的持续时间。

在这行日志中，下游服务指的正是调度中心，此刻查看一下调度中心打印的日志，发现抛出了一个XxlRpcException的异常，从这个异常信息我们可以看出，是因为收到了一个无效响应码导致的。照葫芦画瓢，我也找到这个异常位于源码的位置：
这个异常的抛出是由于执行器返回了非200状态码的响应，结合异常日志一中Envoy生成的503响应。我们可以推断出，正是由于这个503响应，导致调度中心关闭了与执行器的连接通道，实际上该连接通道是与Pod中Envoy的连接通道。

原因

经过了上面对于该问题的细致分析排查，终于找到了这个问题产生的原因了。
由于该版本xxl-job在Http协议下的RPC调用中，缺少心跳请求的响应导致的，并且两个服务之间的流程被Envoy给代理了，所以产生了该问题。
服务迁移至K8S后，引进了Istio服务治理，给每个Pod都导入了一个新容器Envoy，用于代理进出Pod的流量。
Envoy在转发一个请求到后端服务后，会等待后端服务返回一个响应。如果一个连接上有多个请求，那么这些请求会被阻塞，直到前一个请求的响应返回。并且由于调度中心使用连接池，而不是每次都新建一个请求，就会导致请求在Envoy阻塞了。
当调度中心发送一个心跳请求时，该请求被Envoy转发给执行器后，Envoy会等待执行器返回响应结果。由于执行器收到心跳请求时，不会进行任何操作，导致Envoy中心会一直等待心跳响应，阻塞后续的调度请求。
由于Envoy阻塞了后续正常的调度请求，导致执行器与调度中心的连接在90S内没有进行读写操作，于是执行器就会将该连接通道关闭。
调度失败路径：

1. 调度中心与执行器正常连接。
2. 第一次调度，成功调度并执行定时任务。
3. 经过30S后，调度中心发送一个心跳请求到执行器。
4. Envoy代理心跳请求并转发到执行器。
5. 执行器忽略心跳请求，不会返回Http响应。导致Envoy阻塞本条Http连接，以至于后续的调度请求无法进入执行器。
6. 执行器90秒后发现和调度中心的Http连接没有任何读写操作，于是关闭该条Http连接。
7. Envoy等待心跳响应的时候，发现转发的请求被异常关闭，于是自己构造了一个503的响应发送给调度中心。构造完503响应后，按顺序处理该通道后续请求，此时第二次调度被转发到执行器中，第二次调度被执行器正常处理。
8. 调度中心收到503的响应后，内部Netty的处理器会抛出一个XxlRpcException的异常，导致在调度中心也会关闭与执行器的http连接，导致第三次调度失败。

解决办法

该问题的根因是由于在该版本xxl-job在Http协议下的RPC调用中，缺少心跳请求的响应导致的，并且两个服务之间的流程被Envoy给代理了，所以产生了该问题。
这个问题有两个解决方法：

1. 在执行器端增加心跳请求响应
2. 调度中心和执行器之间的流量不再经过Envoy代理

由于xxl-job在该版本下的xxl-rpc已经两年没有更新了，所以只能看看怎么将两个服务之间的流量不走Envoy代理。
此时Istio服务治理中另外一个角色Sidecar出现了。

Sidecar

Sidecar的作用：
可以拦截Pod中的所有入口和出口流量，然后根据Istio的路由规则将流量路由到正确的服务。

在k8s中的Istio创建一个Sidecar，设置调用执行器xxl-job的http端口的流量不经过任何Istio功能。
例子：

apiVersion: networking.istio.io/v1beta1
kind: Sidecar
metadata:
  name: direct-xxl-job-my-app
  namespace: ebc-bpm
spec:
  # 入口流量设置
  ingress:
  # 直接转发到Pod容器的7679接口
  - defaultEndpoint: 127.0.0.1:7679
    port:
      name: direct-access-port
      number: 7679
      protocol: TCP
  # 对应的工作负载
  workloadSelector:
    labels:
      app: my-app

上面的这个Sidecar配置的作用就是将带有标签app=my-app应用的7679端口TCP入口流量重定向到Pod中的7679端口，不再经过Envoy的代理。
所以我们可以在K8S环境中，配置Sidecar来控制流量是否被Enovy代理，就能有效的解决这个问题了。