Xxl-Job定时任务调度失败的排查与解决

已于 2024-03-04 23:23:25 修改
阅读量3.1k 收藏 24
点赞数 24
文章标签： java
于 2024-02-26 14:58:17 首次发布
版权声明：本文为博主原创文章，遵循 CC 4.0 BY-SA 版权协议，转载请附上原文出处链接和本声明。
本文链接：https://blog.csdn.net/Azir_/article/details/136299628
版权
文章描述了一个问题，xxl-job的定时任务在特定间隔下调度失败，经排查发现是由于调度中心与执行器间的心跳请求被Envoy代理阻塞，导致执行器未响应调度。通过分析Envoy日志，确认问题与心跳包的处理和IstioSidecar的配置有关。解决办法是调整Sidecar配置，使流量绕过Envoy代理直接到达执行器。
摘要由CSDN通过智能技术生成

问题

场景：每隔一分钟执行一次的定时任务
现象：第一次调度成功后，第二次调度必会失败。但是等待第三次调度后，第二次的执行结果却是第三次调度的时间。
image.png
奇怪的是，只有每隔一分钟执行一次的任务才会这样，其他间隔一秒或者一小时的又不会有这个问题。
某次调度错误信息：
image.png

调度中心调度原理

线上xxl-job版本：2.2.0-SNAPSHOT

在排查原因之前，我看了一下这个版本的源码，对任务的调度以及执行有了一些了解。
image.png
执行器内部会开启一个http服务器，用于接受调度中心的调度请求。每次的调度请求都会复用Http连接，避免多次连接消耗资源。
调度步骤：

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

根据异常堆载定位问题

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

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

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

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

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

分析日志

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

时间点channel远程地址信息请求信息
18:02:00R:/127.0.0.6:41163POST / HTTP/1.1;content-length: 626
18:02:30R:/127.0.0.6:41163POST / HTTP/1.1;content-length: 159
18:04:00R:/127.0.0.6:52551POST / HTTP/1.1;content-length: 626

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

  1. 18:02:30收到了一次请求

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

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

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

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

定时任务执行情况

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

  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响应码的响应体返回给调度中心。

  1. 请求时间90031毫秒

本次心跳请求时间太长了，找了一下执行器中Netty调度请求处理器对于心跳请求的处理，发现xxl-job在这个版本中，是不会对心跳做任何处理的。
image.png
导致一直不会返回Http响应，而且在Envoy中要是没有一个请求没有收到响应的话，会认为该请求仍在处理中的。直到达到Envoy的请求超时才会取消这次请求。

  1. 上游服务终止了连接

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

异常日志二

[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
照葫芦画瓢，我也找到这个异常位于源码的位置：
output.png
这个异常的抛出是由于执行器返回了非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代理，就能有效的解决这个问题了。

Azir_12138
关注
  • 24
    点赞
  • 踩
  • 24
    收藏
    觉得还不错? 一键收藏
  • 1
    评论
分布式调度中xxl-job任务调度失败——java.io.IOException: Too many open files
BUGdeQD的博客
09-24 1万+
先亮出错误 06:15:04.460 logback [xxl-job, admin JobTriggerPoolHelper-fastTriggerPool-567911238] INFO c.x.r.r.i.r.XxlRpcReferenceBean - >>>>>>>>>>> xxl-rpc, invoke error,...
xxl-job适配达梦数据库
02-02
XXL-JOB是一款轻量级分布式任务调度平台，它提供了简单易用的API接口和Web管理界面，使得开发者可以方便地实现任务的分布式调度。在本案例中，我们关注的是如何将XXL-JOB与达梦数据库（DM8）进行适配。达梦数据库...
数据库发生死锁 xxl-job任务不自动执行
lanicc's blog
04-07 904
经过排查，该异常连接属于18:45分挂掉的pod，有一台k8s的worker有问题，节点被k8s驱逐，但实际物理机还在运行，停不掉应用，当前发现物理机节点磁盘有问题，还在排查中。，查到了该连接的客户端地址，并且发现该客户端的连接已经存在了14778秒，约等于4个小时，和事故持续时间一致。业务同学反馈配置的xxl任务在18点45分之后就没有自动执行了，导致业务付款结果更新不及时。请求一次，更新执行器的心跳信息，调度中心启动线程每隔30秒检测一次。根据xxl的原理和业务反馈的问题，很容易想到可能出问题的点。
docker和K8S环境xxl-job定时任务不执行问题总结_dcoker部署xxljob,无法调用其他服务的定时任务(3)
2401_84619342的博客
05-15 723
小编的一位同事在校期间连续三年参加ACM-ICPC竞赛。从参赛开始，原计划每天刷一道算法题，实际上每天有时候不止一题，一年最终完成了 600+：凭借三年刷题经验，他在校招中很快拿到了各大公司的offer。入职前，他把他的刷题经验总结成1121页PDF书籍，作为礼物赠送给他的学弟学妹，希望同学们都能在最短时间内掌握校招常见的算法及解题思路。整本书，我仔细看了一遍，作者非常细心地将常见核心算法题和汇总题拆分为4个章节。开源分享：【大厂前端面试题解析+核心总结学习笔记+真实项目实战+最新讲解视频】
Xxl-Job任务调度失败及解决
热门推荐
qq_43388893的博客
04-09 3万+
一、报状态码500
docker和K8S环境xxl-job定时任务不执行问题总结
日拱一卒无有尽，功不唐捐终入海
10-24 3348
xxl-job 任务不执行，或者执行异常问题整理归纳
spring 框架自带的定时器功能
NetThief3389的博客
08-18 474
1...pom.xml 文件配置 1 <dependencies> 2 <dependency> 3 <groupId>junit</groupId> 4 <artifactId>junit</artifactId> 5 <version&g...
xxJob调用失败
weixin_44754681的博客
11-21 398
xxjob调度失败
xxl-job-2.4.0定时任务框架Oracle版本
10-16
**XXL-JOB定时任务框架Oracle版本详解** XXL-JOB是一个分布式任务调度平台，它提供了简单易用的API和Web界面，使得开发者能够轻松地实现任务的分布式调度。XXL-JOB 2.4.0是该框架的一个重要版本，针对Oracle数据库...
定时调度器 xxl-job
12-21
- **任务定义**：在执行器项目中编写具体的任务逻辑，通常以Spring Bean的形式存在，可以通过@XxlJob注解来定义任务。 - **任务调用**：调度中心通过HTTP或RPC方式调用执行器上的任务，任务执行的结果会反馈回调度...
分布式任务调度平台XXL-JOB应用.rar
03-20
分布式任务调度平台XXL-JOB是一款广泛应用于企业级服务中的高效、易用、稳定的任务调度框架，它能够帮助开发者实现复杂的工作流控制，为大型分布式系统提供强大的定时任务管理能力。XXL-JOB以其轻量级的设计、丰富的...
xxl-job实战源码
03-24
- 任务失败重试机制及异常处理。 3. **监控与调试** - 查看任务执行状态、日志，实时监控任务运行情况。 - 调试执行器中的任务代码，确保任务正确无误。 4. **集群部署** - 如何在多台服务器上部署执行器，...
【原创】xxljob集群模式下调度失败问题排查
最新发布
无所事事的博客
06-05 854
排查旧版本xxljob集群模式下调度任务有时会报错的问题过程
xxl-job调度任务失败
qq_52332492的博客
08-13 4463
触发调度： address：http://169.254.169.105:6666 code：500 msg：xxl-job remoting error(No route to host (Host unreachable)), for url : http://169.254.169.105:6666/run
xxl-job 回调失败 “执行结果失败 任务结果丢失，标记失败”，
屎香香wuqingvika的专栏
04-25 1万+
xxl-job踩过的一些坑 因为部署平台互通防火墙各种端口限制 一开始注册中心不互通 后来没办法将执行器地址设置成容器名称 http://ncim-data-dsrwjobtest:7000/ 后来定时任务调到了回调又不行 出现的情况是 “执行结果失败 任务结果丢失，标记失败”， ----------- xxl-job job callback fail, callbackResult:ReturnT [code=500, msg=xxl-rpc remoting error(No route to h
记一次项目中Xxljob一直调度失败的解决过程
shouwc_Pirate的博客
05-14 5687
记一次项目中Xxljob一直调度失败的解决过程1.遇到的问题2.排查过程 1.遇到的问题 2.排查过程 我按照网上查的资料，启动Xxljob最新的版本代码（2.3.0），并启动项目代码，也能够自动注册，但是，执行一次操作时，就一直失败，后台并无日志打印出来。通过百度，查到了问题是，需要进行手动录入ip，并且加上http：//。 之后可以，请求到了，但是报错：com.xxl.rpc.util.XxlRpcException: com.caucho.hessian.io.HessianProtocolExc
XXl-Job，无法找到调度任务，Linux运维架构师教你如何突破瓶颈
m0_60634964的博客
04-08 587
为了做好运维面试路上的助攻手，特整理了上百道。
xxljob偶然任务调度失败（无调度记录）-原因分析
I12XXXXXLbull的博客
02-18 3403
xxljob调度失败
踩坑Xxljob本地部署后调度一半成功一半失败原因分析及解决方案记录
slipperySoap的博客
12-11 2805
踩坑xxljob本地部署，出现一半调度成功，一半调度失败现象，具体分析原因以及给出解决方案
xxl-job调度python
10-15
xxl-job是一个分布式任务调度平台，可以实现对Python任务进行调度。 首先，xxl-job支持多种任务执行器，可以支持Python任务的执行。我们可以使用Python编写任务代码，并通过任务执行器将任务提交给xxl-job进行调度。任务执行器会接收到任务请求后，执行我们编写的Python任务代码。 其次，xxl-job提供了丰富的调度配置选项，可以灵活地配置Python任务的调度规则。我们可以设置任务的触发方式，如定时触发、间隔触发等；还可以设置任务的执行参数，如超时时间、重试次数等。通过这些配置，我们可以满足不同任务的调度需求。 另外，xxl-job还提供了任务日志和任务监控功能。我们可以查看任务的运行日志，方便调试和排查问题；同时，我们还可以实时监控任务的执行状态，包括任务的执行次数、执行结果等信息，方便进行任务的管理和监控。 最后，xxl-job还支持任务分片，可以将一个大任务拆分为多个子任务并行执行，提高任务的执行效率。对于Python任务，我们可以根据具体场景进行任务分片，将一个大的数据处理任务拆分成多个子任务，通过分布式执行提高任务的处理速度。 综上所述，通过使用xxl-job调度Python任务，我们可以灵活、高效地管理和调度Python任务，提高任务的执行效率，减轻开发者的工作负担。
评论 1
添加红包

请填写红包祝福语或标题

个

红包个数最小为10个

元

红包金额最低5元

当前余额3.43元 前往充值 >
需支付：10.00元
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付元
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明：

1.余额是钱包充值的虚拟货币，按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载，可以购买VIP、付费专栏及课程。

余额充值