Digdagにてスケジュール通りにワークフローが実行されず、next_run_timeが3時間以上遅延する。

Question

実現したいこと

Digdagのバージョンを0.10.4→0.10.5にアップデートを実施しました。
アップデートを実施したのちデータ転送基盤の正常性を確認したところ、Digdagでスケジュール通りにワークフローが実行されない事象(3時間以上の遅延)を確認しています。
本遅延の原因の解明、および事象解消したく検討しています。

前提

AWS Fargate上でDigdag serverコンテナ+Digdag workerコンテナ+Embulkコンテナでデータ転送基盤を構築しています。
環境: Digdag: 0.10.4→0.10.5
Amazon Linux:
public.ecr.aws/amazonlinux/amazonlinux:2.0.20230119.1
→public.ecr.aws/amazonlinux/amazonlinux:2.0.20230628.0
Farggate Spot
Postgre SQL:13.10
設定ファイル:
sla.dig

sla:
  #duration: 時:分:秒（経過時間）
  duration: 01:00:00
  fail: false
  +notice:
    echo>: "[WARN] Execution Time 60 minutes Exceeded." 

schedule.dig

schedule:
  hourly>: 00:00
  skip_on_overtime: false

ログ:
原因となるログが確認できていません。
scheduler等をDigdagのOS標準出力のログを確認していますが、上記SLA違反(3時間以上の遅延によるdurationを超えたログ)は確認しています。

[CRITICAL] Execution Time 60 minutes Exceeded.

発生している問題・エラーメッセージ

スケジュール通りにワークフローが実行されない（遅延している）以外はワークフローの実行等にError等は出ていません。

該当のソースコード

2023-10-02 10:15:00+09 実行時 digdag_dbにて以下コマンドを実行。

digdag_db=> SELECT
digdag_db-> s.id, p.name AS project_name, w.name AS workflow_name,
digdag_db-> to_timestamp(s.next_run_time) AS next_run_time,
digdag_db-> to_timestamp(s.next_schedule_time) next_schedule_time,
digdag_db-> to_timestamp(s.last_session_time) AS last_session_time,
digdag_db-> s.created_at,s.updated_at,s.disabled_at
digdag_db-> FROM schedules s, projects p, workflow_definitions w
digdag_db-> WHERE project_id = p.id
digdag_db-> AND workflow_definition_id = w.id
digdag_db-> ORDER BY 2,3;
id | project_name | workflow_name | next_run_time | next_schedule_time | last_session_time | created_at | updated_at | disabled_at
------+----------------+------------------------------------------------------+------------------------+------------------------+------------------------+-------------------------------+-------------------------------+-------------
2242 | aaaa | aaaa_endpoint_aaaaa | 2023-10-02 08:20:00+09 | 2023-10-02 08:20:00+09 | 2023-10-02 07:50:00+09 | 2023-01-11 14:24:56.892609+09 | 2023-10-02 09:51:02.757178+09 |
2241 | aaaa | aaaa_aaaaaa-endpoint_event_aaaaaaa-aaaa-pc01 | 2023-10-02 07:20:00+09 | 2023-10-02 07:20:00+09 | 2023-10-02 07:10:00+09 | 2023-01-11 14:24:56.892609+09 | 2023-10-02 09:23:38.228986+09 |
2244 | aaaa | aaaa_aaaaaa-endpoint_event_aaaaaaa-aaaa-pc02 | 2023-10-02 07:10:00+09 | 2023-10-02 07:10:00+09 | 2023-10-02 04:50:00+09 | 2023-01-11 14:24:56.892609+09 | 2023-10-02 09:19:33.995814+09 |
2243 | aaaa | aaaa_aaaaaa-endpoint_event_aaaaaaa-aaaa-pc03 | 2023-10-02 08:10:00+09 | 2023-10-02 08:10:00+09 | 2023-10-02 08:00:00+09 | 2023-01-11 14:24:56.892609+09 | 2023-10-02 09:51:36.496488+09 |

試したこと

上記SQL文を定期的に実行して遅延時間に変化がない（遅延し続けている）ことを確認しています。

補足情報（FW/ツールのバージョンなど）

Digdagサーバのスケジュール実行がさぼっているように見受けられます。
遅延発生から3日経過しますが、改善の状況が見られません。

以下2点、ご教示ください。
・next_schedule_time(3 hours ago) をスケジュール通りの実行時刻に戻す方法
・原因究明のためのdigdagログの検索方法

確認観点が不足していればご指摘お願いします。
以上、よろしくお願いします。

Answer 1

この小さい再現コードでは、2個のタスクが同時に動くようです。(2個がrunningになる)

• Java 8
• Digdag 0.10.5
• macOS: 13.5.2

timezone: Asia/Tokyo

schedule:
  minutes_interval>: 1

sla:
  duration: 00:01:30
  fail: false
  +notice:
    echo>: "*** sla ***"

+task1:
  sh>: "date ; sleep 125; date"

digdag attempts

  session id: 18
  attempt id: 18
  uuid: 6328746b-7c27-424b-b42e-84ed9561917f
  project: hoge
  workflow: test
  session time: 2023-10-05 14:11:00 +0900
  retry attempt name:
  params: {"last_session_time":"2023-10-05T14:10:00+09:00","next_session_time":"2023-10-05T14:12:00+09:00","last_executed_session_time":"2023-10-05T14:10:00+09:00"}
  created at: 2023-10-05 14:11:00 +0900
  finished at:
  kill requested: false
  status: running

  session id: 19
  attempt id: 19
  uuid: 510b03a2-3e31-4efa-a417-b6e037d610fd
  project: hoge
  workflow: test
  session time: 2023-10-05 14:12:00 +0900
  retry attempt name:
  params: {"last_session_time":"2023-10-05T14:11:00+09:00","next_session_time":"2023-10-05T14:13:00+09:00","last_executed_session_time":"2023-10-05T14:11:00+09:00"}
  created at: 2023-10-05 14:12:00 +0900
  finished at:
  kill requested: false
  status: running

2023-10-05 14:17:00 +0900 [INFO] (scheduler-0): Starting a new session project id=1 workflow name=test session_time=2023-10-05T14:17:00+09:00
2023-10-05 14:17:00 +0900 [INFO] (scheduler-0): Updating next schedule time: sched=StoredSchedule{id=1, projectId=1, createdAt=2023-10-05T04:53:30.825Z, updatedAt=2023-10-05T05:16:29.340Z, lastSessionTime=2023-10-05T05:16:00Z, workflowName=test, workflowDefinitionId=7, nextRunTime=2023-10-05T05:17:00Z, nextScheduleTime=2023-10-05T05:17:00Z}, next=ScheduleTime{runTime=2023-10-05T05:18:00Z, time=2023-10-05T05:18:00Z}, lastSessionTime=2023-10-05T05:17:00Z
2023-10-05 14:17:00 +0900 [INFO] (0109@[0:hoge:24:24]+test+task1): sh>: date ; sleep 125; date
Thu Oct  5 14:17:00 JST 2023
Thu Oct  5 14:17:05 JST 2023
2023-10-05 14:17:31 +0900 [INFO] (0102@[0:hoge:23:23]+test^sla+notice): echo>: *** sla ***
2023-10-05 14:17:31 +0900 [INFO] (0107@[0:hoge:23:23]+test^sla^alert): type: notify
*** sla ***
2023-10-05 14:18:00 +0900 [INFO] (scheduler-0): Starting a new session project id=1 workflow name=test session_time=2023-10-05T14:18:00+09:00
2023-10-05 14:18:00 +0900 [INFO] (scheduler-0): Updating next schedule time: sched=StoredSchedule{id=1, projectId=1, createdAt=2023-10-05T04:53:30.825Z, updatedAt=2023-10-05T05:17:00.585Z, lastSessionTime=2023-10-05T05:17:00Z, workflowName=test, workflowDefinitionId=7, nextRunTime=2023-10-05T05:18:00Z, nextScheduleTime=2023-10-05T05:18:00Z}, next=ScheduleTime{runTime=2023-10-05T05:19:00Z, time=2023-10-05T05:19:00Z}, lastSessionTime=2023-10-05T05:18:00Z
2023-10-05 14:18:00 +0900 [INFO] (0102@[0:hoge:25:25]+test+task1): sh>: date ; sleep 125; date

Comments

[signyah]

検証いただきありがとうございます！

Digdagの本来の動きとしては、やはり、同時に二つ動く認識ですね。
我々の検証環境でも同時に動くことが見えているので、
質問内容の環境のDigdagの本来の仕様から外れた動きをしている形ですね...

[hiroysato]

UIやdigdag attempts等で、状態を確認してみるのはいかがでしょうか？

Answer 2

• Digdagのバージョン
• 環境(OS, Java, Database)
• 設定ファイル
• ログ

という手元で再現できるぐらいの情報がないと回答は難しいような気がします。

スケジューリングならdigdag schedules を確認してみてはいかがでしょうか？

Comments

[signyah]

hiroysato さん

ご指摘ありがとうございます。
質問内容の方に情報を追記しました。

また、digdag schedulesの結果は該当のソースコードの結果(抜粋)と内容変わりありませんでした。

[hiroysato]

slaが動いていますね。スケジュールが hourly> で1時間毎に動作するようになっているので、0:00, 1:00と実行する時に、現在時刻が1:00だとして、0:00のタスクが完了していないのではないでしょうか？

[signyah]

確認いただきありがとうございます。

> slaが動いていますね。

ご認識の通りです。

> 現在時刻が1:00だとして、0:00のタスクが完了していないのではないでしょうか？

正確には、2023-10-02 10:15:00+09時点で2023-10-02 07:10:00+09のタスクが完了していないため、 3時間前のワークフローが動いていない状況になります。

[signyah]

3時間前のタスクは完了していませんが、skip_on_overtime: falseにしているため、3時間前のタスクが実行されなくても並行で2時間前、1時間前のワークフローは動作する認識でしたが、認識相違ありますでしょうか。

[hiroysato]

回答のコメントだとmarkdownが使えないので、別のにコメントしました。