--- theme: condensed-night-purple --- # 问题 **场景**：每隔一分钟执行一次的定时任务
**现象**：第一次调度成功后，第二次调度**必会失败**。但是等待第三次调度后，第二次的执行结果**却是第三次调度**的时间。
![image.png](https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/e169b2a67d3445609eb5e2919deb9b8c~tplv-k3u1fbpfcp-jj-mark:0:0:0:0:q75.image#?w=1890\&h=473\&s=171180\&e=png\&b=fbfbfb)
奇怪的是，只有每隔一分钟执行一次的任务才会这样，其他间隔一秒或者一小时的又不会有这个问题。
某次调度错误信息：
![image.png](https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/6afebf8aa288492280dda5a184a799bb~tplv-k3u1fbpfcp-jj-mark:0:0:0:0:q75.image#?w=585\&h=722\&s=133903\&e=png\&b=585858) # 调度中心调度原理 > 线上xxl-job版本：2.2.0-SNAPSHOT 在排查原因之前，我看了一下这个版本的源码，对任务的调度以及执行有了一些了解。
![image.png](https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/8374a74ce7304434b0617b642b788323~tplv-k3u1fbpfcp-jj-mark:0:0:0:0:q75.image#?w=483\&h=517\&s=33386\&e=png\&b=fafafc)
执行器内部会开启一个http服务器，用于接受调度中心的调度请求。每次的调度请求都会复用Http连接，避免多次连接消耗资源。
调度步骤： 1. 调度中心从连接池中获取连接 2. 调度中心发送调度请求（带有**RequestId**，**JobLogId**），并阻塞线程等待执行器响应 3. 执行器返回调度响应，并异步执行定时任务 4. 调度中心收到调度响应，根据回传的**RequestId**，回写数据库调取状态。 5. 执行器执行任务后，回调调度中心更新任务执行状态接口，根据**JobLogId**回写任务执行情况。 # 根据异常堆载定位问题根据异常堆栈`XxlRpcFutureResponse.java:117`，我们可以在代码中找到对应抛出异常的位置。位于调度请求发送后，从Future获取异步结果的get方法。
![image.png](https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/2d63b9e208344fc2aeee700a97df7efb~tplv-k3u1fbpfcp-jj-mark:0:0:0:0:q75.image#?w=1156\&h=207\&s=34223\&e=png\&b=1e1f22)
futureResponse的get方法的逻辑是**休眠调度线程**（默认休眠1秒），等待执行器响应调度请求。线程被唤醒后去检查本次调度是否完成，要是没有完成，就抛出调度失败的错误。
![image.png](https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/c2d50de456464d328cb3e5cb1729cc89~tplv-k3u1fbpfcp-jj-mark:0:0:0:0:q75.image#?w=1321\&h=650\&s=81666\&e=png\&b=1f2023)
从上面逻辑可以推断出调度中心是**成功发送调用请求**出去了，因为执行器**没有响应**导致的调度失败错误。
那么，为什么执行器没有响应调度请求呢？我们就得去看看执行器那边的情况了。 *** 由于xxl-job中处理调度请求的Netty处理器并没有打印具体的日志，所以我们要使用**Arthas**来观察Netty调度请求处理的执行情况了。
![image.png](https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/6703efa7636b4636866db4f1072206bb~tplv-k3u1fbpfcp-jj-mark:0:0:0:0:q75.image#?w=1039\&h=316\&s=51592\&e=png\&b=1e1f22) # 使用Arthas观察调用请求执行情况使用arthas的watch命令观察执行器接收调用请求情况。 watch com.xxl.rpc.remoting.net.impl.netty_http.server.NettyHttpServerHandler channelRead0 '{params}' -x 2 ## 分析日志 ![image.png](https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/5211404f450049ef9b544247723c5489~tplv-k3u1fbpfcp-jj-mark:0:0:0:0:q75.image#?w=1563\&h=452\&s=145589\&e=png\&b=ffffff)
整理一下日志，在问题产生的这段时间内，执行器这边的Netty的调度请求处理器只收到了三个请求 | 时间点 | channel远程地址信息 | 请求信息 | | -------- | ------------------ | ----------------------------------- | | 18:02:00 | R:/127.0.0.6:41163 | POST / HTTP/1.1;content-length: 626 | | 18:02:30 | R:/127.0.0.6:41163 | POST / HTTP/1.1;content-length: 159 | | 18:04:00 | R:/127.0.0.6:52551 | POST / HTTP/1.1;content-length: 626 | 调用日志中，有两个点比较奇怪 1. **18:02:30收到了一次请求** 在这个时间点为什么会收到一次请求的呢？而且这个请求的请求大小与正常的调用请求的大小还一样，仅有159字节。这么小的请求体，让我想到了一个东西：**心跳包**。
在RPC框架中，为了监测通信通道的正常以及节点的健康，会定时向节点发送一个请求包，用于判断通道是否正常连接。
虽然调度中心与执行器用的是Http请求，但是`xxl-job`为了减少资源浪费，使用了连接池，于是也引入了心跳监测。当通道在30秒内没有读写操作时，就发送一个心跳请求。
![image.png](https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/7908ce7755c843e3b65c24382e2efcd7~tplv-k3u1fbpfcp-jj-mark:0:0:0:0:q75.image#?w=996\&h=363\&s=54807\&e=png\&b=1e1f22)
在执行器也能看到心跳请求的日志。
![image.png](https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/5ce33ee8b80e48d0947ae87345741e7d~tplv-k3u1fbpfcp-jj-mark:0:0:0:0:q75.image#?w=1141\&h=41\&s=7628\&e=png\&b=ffffff)
但是这个心跳请求有点奇怪，为什么只在18:02:30分收到呢？18:03:30没有收到呢？
这个问题就跟下面的问题有所关联了。 2. **channel远程地址的IP不太对劲，居然是本地地址并非是调度中心的地址** 经我了解后，公司的K8S环境中引入了`Istio`进行服务治理，其中进出Pod的流量都会被Envoy代理，所以`127.0.0.6`正是**Envoy**的IP地址。
![image.png](https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/f56fab294ab8483ebf56cff440351afe~tplv-k3u1fbpfcp-jj-mark:0:0:0:0:q75.image#?w=492\&h=209\&s=23001\&e=png\&b=f9f9fb) > Envoy是一个由Lyft开发的高性能、可扩展的代理（Proxy）服务器，用于处理微服务架构中的网络通信。它被设计成可用于多种不同的部署场景，并提供了丰富的功能集，如负载均衡、流量路由、故障恢复、安全认证等。 ## 定时任务执行情况收集日志的时间段正好处于问题发生的一个区间内，这个时间段内定时任务执行情况：
![image.png](https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/8c366dbf32d64be8abdd5f6410c2a2ee~tplv-k3u1fbpfcp-jj-mark:0:0:0:0:q75.image#?w=1858\&h=113\&s=42835\&e=png\&b=fcfcfc) 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:00`Envoy发现上游服务器连接终止，于是自己构造了一个`503`响应码的响应体返回给调度中心。 2. **请求时间90031毫秒** 本次心跳请求时间太长了，找了一下执行器中Netty调度请求处理器对于心跳请求的处理，发现`xxl-job`在这个版本中，是**不会对心跳做任何处理**的。
![image.png](https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/e89697fdb3744718bcac39c898235b7f~tplv-k3u1fbpfcp-jj-mark:0:0:0:0:q75.image#?w=1064\&h=462\&s=64306\&e=png\&b=1e1f22)
导致一直不会返回Http响应，而且在Envoy中要是没有一个请求没有收到响应的话，会认为该请求仍在处理中的。直到达到Envoy的请求超时才会取消这次请求。 3. **上游服务终止了连接** 在这个时间点`2024-02-21T18:04:00`执行器中打印了一行日志，提示执行器关闭了空闲连接。
![image.png](https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/baa4b3960a6441ffae30a7023c649520~tplv-k3u1fbpfcp-jj-mark:0:0:0:0:q75.image#?w=984\&h=13\&s=3271\&e=png\&b=ffffff)
找了一下该行日志在源码中的位置，发现这个关闭连接的前提是90秒内通道**没有进行读写**，然后执行器觉得该连接通道已经异常了，这也是为什么Envoy会提示上游服务终止了连接的原因。
![image.png](https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/809335c40e504be2a2295f7c17c4c8d0~tplv-k3u1fbpfcp-jj-mark:0:0:0:0:q75.image#?w=980\&h=276\&s=39666\&e=png\&b=1f2023) ## 异常日志二 > \[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`的异常，从这个异常信息我们可以看出，是因为收到了一个**无效响应码**导致的。
![image.png](https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/85d541ee6aa94e2887a0cfc056887f09~tplv-k3u1fbpfcp-jj-mark:0:0:0:0:q75.image#?w=914\&h=347\&s=50339\&e=png\&b=ffffff)
照葫芦画瓢，我也找到这个异常位于源码的位置：
![output.png](https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/01610860cb974e318a8c04203fdaaa90~tplv-k3u1fbpfcp-jj-mark:0:0:0:0:q75.image#?w=1153\&h=674\&s=64336\&e=png\&b=1e1f22)
这个异常的抛出是由于执行器返回了非`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`功能。
例子： ```yaml 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代理，就能有效的解决这个问题了。