search

PowerJob / PowerJob

Enterprise job scheduling middleware with distributed computing ability.
http://www.powerjob.tech/
Apache License 2.0
6.83k stars 1.2k forks source link

SYSTEM: unreceived process result #394

Closed iamzzq closed 2 years ago

iamzzq commented 2 years ago

powerjob调度执行器的时候，有时候任务会报 SYSTEM: unreceived process result

Echo009 commented 2 years ago

请提供一下上下文信息，包括但不限于以下内容

  1. 环境信息（操作系统、JDK 版本、部署方式）
  2. 任务的相关配置
  3. worker 中相关的日志 （根据任务实例 id 过滤）
iamzzq commented 2 years ago

1.操作系统win10,jdk1.8,部署方式jar包部署，调度和执行器都在一台服务器 2.配置如下图 9644C7F5-8211-44a4-9625-7041CF1E951A 3.日志如下： 2022-03-29 15:22:00.052 [HashedWheelTimer-Executor-48] INFO c.g.k.p.s.s.DispatchService - [Dispatcher-7|389074099579650112] start to dispatch job: JobInfoDO(id=7, jobName=1分钟清洗, jobDescription=1分钟清洗, appId=1, jobParams=1,1,vkdoihibokinur2v3ee1h4eknt, timeExpressionType=2, timeExpression=0 0/1 ?, executeType=1, processorType=1, processorInfo=induconjob.powerjob.bianpai.DataCleanStasticProcessor, maxInstanceNum=0, concurrency=5, instanceTimeLimit=0, instanceRetryNum=0, taskRetryNum=0, status=1, nextTriggerTime=1648538520000, minCpuCores=0.0, minMemorySpace=0.0, minDiskSpace=0.0, designatedWorkers=, maxWorkerCount=0, notifyUserIds=null, gmtCreate=2021-12-29 08:53:58.278, gmtModified=2022-03-29 15:20:34.405);instancePrams: null. 2022-03-29 15:22:00.052 [HashedWheelTimer-Executor-50] INFO c.g.k.p.s.s.DispatchService - [Dispatcher-12|389074099751616576] start to dispatch job: JobInfoDO(id=12, jobName=环保数据计算, jobDescription=null, appId=1, jobParams=null, timeExpressionType=2, timeExpression=0 0/1 ?, executeType=1, processorType=1, processorInfo=induconjob.powerjob.bianpai.PccDataStatisticStasticProcessor, maxInstanceNum=0, concurrency=5, instanceTimeLimit=0, instanceRetryNum=0, taskRetryNum=1, status=1, nextTriggerTime=1648538520000, minCpuCores=0.0, minMemorySpace=0.0, minDiskSpace=0.0, designatedWorkers=, maxWorkerCount=0, notifyUserIds=null, gmtCreate=2021-12-29 08:59:13.774, gmtModified=2022-03-29 15:20:34.413);instancePrams: null. 2022-03-29 15:22:00.056 [HashedWheelTimer-Executor-50] INFO c.g.k.p.s.s.DispatchService - [Dispatcher-12|389074099751616576] send schedule request to TaskTracker[protocol:AKKA,address:172.20.46.166:27777] successfully: ServerScheduleJobReq(allWorkerAddress=[172.20.46.166:27777], jobId=12, wfInstanceId=null, instanceId=389074099751616576, executeType=STANDALONE, processorType=EMBEDDED_JAVA, processorInfo=induconjob.powerjob.bianpai.PccDataStatisticStasticProcessor, instanceTimeoutMS=0, jobParams=null, instanceParams=null, threadConcurrency=5, taskRetryNum=1, timeExpressionType=CRON, timeExpression=0 0/1 ?, maxInstanceNum=0). 2022-03-29 15:22:00.056 [HashedWheelTimer-Executor-48] INFO c.g.k.p.s.s.DispatchService - [Dispatcher-7|389074099579650112] send schedule request to TaskTracker[protocol:AKKA,address:172.20.46.166:27777] successfully: ServerScheduleJobReq(allWorkerAddress=[172.20.46.166:27777], jobId=7, wfInstanceId=null, instanceId=389074099579650112, executeType=STANDALONE, processorType=EMBEDDED_JAVA, processorInfo=induconjob.powerjob.bianpai.DataCleanStasticProcessor, instanceTimeoutMS=0, jobParams=1,1,vkdoihibokinur2v3ee1h4eknt, instanceParams=null, threadConcurrency=5, taskRetryNum=0, timeExpressionType=CRON, timeExpression=0 0/1 ?, maxInstanceNum=0). 2022-03-29 15:22:03.086 [oms-server-akka.server-actor-dispatcher-137] INFO c.g.k.p.s.s.i.InstanceManager - [Instance-389074099751616576] process finished, final status is SUCCEED. 2022-03-29 15:22:03.988 [omsTimingPool-39] INFO c.g.k.p.s.s.t.s.OmsScheduleService - [JobScheduleService] cron schedule: 1.534 ms, workflow schedule: 400.8 μs, frequent schedule: 395.6 μs. 2022-03-29 15:22:04.110 [omsTimingPool-39] INFO c.g.k.p.s.s.t.InstanceStatusCheckService - [InstanceStatusChecker] status check using 32.17 ms. 2022-03-29 15:22:14.111 [omsTimingPool-39] INFO c.g.k.p.s.s.t.InstanceStatusCheckService - [InstanceStatusChecker] status check using 34.56 ms. 2022-03-29 15:22:16.076 [oms-server-akka.server-actor-dispatcher-137] INFO c.g.k.p.s.s.i.InstanceManager - [Instance-389074099579650112] process finished, final status is SUCCEED. 2022-03-29 15:22:18.094 [omsBackgroundPool-49] INFO c.g.k.p.s.s.InstanceLogService - [InstanceLog-389074099751616576] delete local instanceLog successfully. 2022-03-29 15:22:18.988 [omsTimingPool-39] INFO c.g.k.p.s.s.t.s.OmsScheduleService - [JobScheduleService] cron schedule: 1.553 ms, workflow schedule: 406.8 μs, frequent schedule: 391.4 μs. 2022-03-29 15:22:24.108 [omsTimingPool-39] INFO c.g.k.p.s.s.t.InstanceStatusCheckService - [InstanceStatusChecker] status check using 32.57 ms. 2022-03-29 15:22:31.085 [omsBackgroundPool-50] INFO c.g.k.p.s.s.InstanceLogService - [InstanceLog-389074099579650112] delete local instanceLog successfully. 2022-03-29 15:22:33.986 [omsTimingPool-39] INFO c.g.k.p.s.s.t.s.OmsScheduleService - [CronScheduler] These cron jobs will be scheduled: [JobInfoDO(id=7, jobName=1分钟清洗, jobDescription=1分钟清洗, appId=1, jobParams=1,1,vkdoihibokinur2v3ee1h4eknt, timeExpressionType=2, timeExpression=0 0/1 ?, executeType=1, processorType=1, processorInfo=induconjob.powerjob.bianpai.DataCleanStasticProcessor, maxInstanceNum=0, concurrency=5, instanceTimeLimit=0, instanceRetryNum=0, taskRetryNum=0, status=1, nextTriggerTime=1648538580000, minCpuCores=0.0, minMemorySpace=0.0, minDiskSpace=0.0, designatedWorkers=, maxWorkerCount=0, notifyUserIds=null, gmtCreate=2021-12-29 08:53:58.278, gmtModified=2022-03-29 15:21:34.037), JobInfoDO(id=12, jobName=环保数据计算, jobDescription=null, appId=1, jobParams=null, timeExpressionType=2, timeExpression=0 0/1 ?, executeType=1, processorType=1, processorInfo=induconjob.powerjob.bianpai.PccDataStatisticStasticProcessor, maxInstanceNum=0, concurrency=5, instanceTimeLimit=0, instanceRetryNum=0, taskRetryNum=1, status=1, nextTriggerTime=1648538580000, minCpuCores=0.0, minMemorySpace=0.0, minDiskSpace=0.0, designatedWorkers=, maxWorkerCount=0, notifyUserIds=null, gmtCreate=2021-12-29 08:59:13.774, gmtModified=2022-03-29 15:21:34.045)]. 2022-03-29 15:22:34.028 [omsTimingPool-39] INFO c.g.k.p.s.s.t.s.OmsScheduleService - [JobScheduleService] cron schedule: 42.98 ms, workflow schedule: 454.4 μs, frequent schedule: 402.6 μs. 2022-03-29 15:22:34.110 [omsTimingPool-39] INFO c.g.k.p.s.s.t.InstanceStatusCheckService - [InstanceStatusChecker] status check using 34.18 ms. 2022-03-29 15:22:44.106 [omsTimingPool-39] INFO c.g.k.p.s.s.t.InstanceStatusCheckService - [InstanceStatusChecker] status check using 32.94 ms. 2022-03-29 15:22:48.984 [omsTimingPool-39] INFO c.g.k.p.s.s.t.s.OmsScheduleService - [JobScheduleService] cron schedule: 1.668 ms, workflow schedule: 371.4 μs, frequent schedule: 388.2 μs. 2022-03-29 15:22:54.111 [omsTimingPool-39] INFO c.g.k.p.s.s.t.InstanceStatusCheckService - [InstanceStatusChecker] status check using 35.73 ms. 2022-03-29 15:23:00.026 [HashedWheelTimer-Executor-49] INFO c.g.k.p.s.s.DispatchService - [Dispatcher-7|389074351233695808] start to dispatch job: JobInfoDO(id=7, jobName=1分钟清洗, jobDescription=1分钟清洗, appId=1, jobParams=1,1,vkdoihibokinur2v3ee1h4eknt, timeExpressionType=2, timeExpression=0 0/1 ?, executeType=1, processorType=1, processorInfo=induconjob.powerjob.bianpai.DataCleanStasticProcessor, maxInstanceNum=0, concurrency=5, instanceTimeLimit=0, instanceRetryNum=0, taskRetryNum=0, status=1, nextTriggerTime=1648538580000, minCpuCores=0.0, minMemorySpace=0.0, minDiskSpace=0.0, designatedWorkers=, maxWorkerCount=0, notifyUserIds=null, gmtCreate=2021-12-29 08:53:58.278, gmtModified=2022-03-29 15:21:34.037);instancePrams: null. 2022-03-29 15:23:00.026 [HashedWheelTimer-Executor-51] INFO c.g.k.p.s.s.DispatchService - [Dispatcher-12|389074351292416064] start to dispatch job: JobInfoDO(id=12, jobName=环保数据计算, jobDescription=null, appId=1, jobParams=null, timeExpressionType=2, timeExpression=0 0/1 ?, executeType=1, processorType=1, processorInfo=induconjob.powerjob.bianpai.PccDataStatisticStasticProcessor, maxInstanceNum=0, concurrency=5, instanceTimeLimit=0, instanceRetryNum=0, taskRetryNum=1, status=1, nextTriggerTime=1648538580000, minCpuCores=0.0, minMemorySpace=0.0, minDiskSpace=0.0, designatedWorkers=, maxWorkerCount=0, notifyUserIds=null, gmtCreate=2021-12-29 08:59:13.774, gmtModified=2022-03-29 15:21:34.045);instancePrams: null. 2022-03-29 15:23:00.032 [HashedWheelTimer-Executor-49] INFO c.g.k.p.s.s.DispatchService - [Dispatcher-7|389074351233695808] send schedule request to TaskTracker[protocol:AKKA,address:172.20.46.166:27777] successfully: ServerScheduleJobReq(allWorkerAddress=[172.20.46.166:27777], jobId=7, wfInstanceId=null, instanceId=389074351233695808, executeType=STANDALONE, processorType=EMBEDDED_JAVA, processorInfo=induconjob.powerjob.bianpai.DataCleanStasticProcessor, instanceTimeoutMS=0, jobParams=1,1,vkdoihibokinur2v3ee1h4eknt, instanceParams=null, threadConcurrency=5, taskRetryNum=0, timeExpressionType=CRON, timeExpression=0 0/1 ?, maxInstanceNum=0). 2022-03-29 15:23:00.032 [HashedWheelTimer-Executor-51] INFO c.g.k.p.s.s.DispatchService - [Dispatcher-12|389074351292416064] send schedule request to TaskTracker[protocol:AKKA,address:172.20.46.166:27777] successfully: ServerScheduleJobReq(allWorkerAddress=[172.20.46.166:27777], jobId=12, wfInstanceId=null, instanceId=389074351292416064, executeType=STANDALONE, processorType=EMBEDDED_JAVA, processorInfo=induconjob.powerjob.bianpai.PccDataStatisticStasticProcessor, instanceTimeoutMS=0, jobParams=null, instanceParams=null, threadConcurrency=5, taskRetryNum=1, timeExpressionType=CRON, timeExpression=0 0/1 ?, maxInstanceNum=0). 2022-03-29 15:23:03.106 [oms-server-akka.server-actor-dispatcher-83] INFO c.g.k.p.s.s.i.InstanceManager - [Instance-389074351292416064] process finished, final status is SUCCEED. 2022-03-29 15:23:03.989 [omsTimingPool-39] INFO c.g.k.p.s.s.t.s.OmsScheduleService - [JobScheduleService] cron schedule: 1.571 ms, workflow schedule: 383.5 μs, frequent schedule: 391.9 μs. 2022-03-29 15:23:04.110 [omsTimingPool-39] INFO c.g.k.p.s.s.t.InstanceStatusCheckService - [InstanceStatusChecker] status check using 32.40 ms. 2022-03-29 15:23:14.114 [omsTimingPool-39] INFO c.g.k.p.s.s.t.InstanceStatusCheckService - [InstanceStatusChecker] status check using 35.20 ms. 2022-03-29 15:23:16.053 [oms-server-akka.server-actor-dispatcher-83] INFO c.g.k.p.s.s.i.InstanceManager - [Instance-389074351233695808] process finished, final status is SUCCEED. 2022-03-29 15:23:18.113 [omsBackgroundPool-51] INFO c.g.k.p.s.s.InstanceLogService - [InstanceLog-389074351292416064] delete local instanceLog successfully. 2022-03-29 15:23:18.989 [omsTimingPool-39] INFO c.g.k.p.s.s.t.s.OmsScheduleService - [JobScheduleService] cron schedule: 1.556 ms, workflow schedule: 401.2 μs, frequent schedule: 383.0 μs. 2022-03-29 15:23:24.112 [omsTimingPool-39] INFO c.g.k.p.s.s.t.InstanceStatusCheckService - [InstanceStatusChecker] status check using 34.67 ms. 2022-03-29 15:23:31.059 [omsBackgroundPool-52] INFO c.g.k.p.s.s.InstanceLogService - [InstanceLog-389074351233695808] delete local instanceLog successfully. 2022-03-29 15:23:33.989 [omsTimingPool-39] INFO c.g.k.p.s.s.t.s.OmsScheduleService - [CronScheduler] These cron jobs will be scheduled: [JobInfoDO(id=7, jobName=1分钟清洗, jobDescription=1分钟清洗, appId=1, jobParams=1,1,vkdoihibokinur2v3ee1h4eknt, timeExpressionType=2, timeExpression=0 0/1 ?, executeType=1, processorType=1, processorInfo=induconjob.powerjob.bianpai.DataCleanStasticProcessor, maxInstanceNum=0, concurrency=5, instanceTimeLimit=0, instanceRetryNum=0, taskRetryNum=0, status=1, nextTriggerTime=1648538640000, minCpuCores=0.0, minMemorySpace=0.0, minDiskSpace=0.0, designatedWorkers=, maxWorkerCount=0, notifyUserIds=null, gmtCreate=2021-12-29 08:53:58.278, gmtModified=2022-03-29 15:22:34.01), JobInfoDO(id=12, jobName=环保数据计算, jobDescription=null, appId=1, jobParams=null, timeExpressionType=2, timeExpression=0 0/1 ?, executeType=1, processorType=1, processorInfo=induconjob.powerjob.bianpai.PccDataStatisticStasticProcessor, maxInstanceNum=0, concurrency=5, instanceTimeLimit=0, instanceRetryNum=0, taskRetryNum=1, status=1, nextTriggerTime=1648538640000, minCpuCores=0.0, minMemorySpace=0.0, minDiskSpace=0.0, designatedWorkers=, maxWorkerCount=0, notifyUserIds=null, gmtCreate=2021-12-29 08:59:13.774, gmtModified=2022-03-29 15:22:34.018)]. 2022-03-29 15:23:34.028 [omsTimingPool-39] INFO c.g.k.p.s.s.t.s.OmsScheduleService - [JobScheduleService] cron schedule: 40.68 ms, workflow schedule: 464.2 μs, frequent schedule: 402.6 μs. 2022-03-29 15:23:34.111 [omsTimingPool-39] INFO c.g.k.p.s.s.t.InstanceStatusCheckService - [InstanceStatusChecker] status check using 33.37 ms. 2022-03-29 15:23:44.112 [omsTimingPool-39] INFO c.g.k.p.s.s.t.InstanceStatusCheckService - [InstanceStatusChecker] status check using 35.83 ms. 2022-03-29 15:23:48.987 [omsTimingPool-39] INFO c.g.k.p.s.s.t.s.OmsScheduleService - [JobScheduleService] cron schedule: 1.760 ms, workflow schedule: 460.5 μs, frequent schedule: 394.2 μs. 2022-03-29 15:23:54.109 [omsTimingPool-39] INFO c.g.k.p.s.s.t.InstanceStatusCheckService - [InstanceStatusChecker] status check using 33.07 ms. 4.目前写了个程序10秒打印一次，发现服务器时间有的不是10秒钟打印的 2E913358-0391-4332-BC37-817A126C1E31 感觉是服务器时间影响了，正在让相关人员调试服务器时间，请帮忙看一下服务器这种时间是否影响调度

Echo009 commented 2 years ago

额，你这里提供的都是 server 端的日志，能否提供一下 worker 端的日志，另外能否按照 实例 id 过滤出有效日志

denglianyong commented 2 years ago

AKKA消息乱序，taskTracker先收到 status=6（已完成）后收到status=4（执行中）， 详情见 https://github.com/PowerJob/PowerJob/issues/404 本地修复： 迟滞的消息不更新DB