もりはやメモφ(・ω・ )

インフラなエンジニアからSREへ

digdagのslaディレクティブを使い、ジョブの意図せぬ長時間実行に対策する

digdagを利用していて時おり困ることの一つに、何らかのジョブ*1がハングなどで長時間実行されてしてしまい、ジョブのキューが溜まり後続のジョブが実行されない問題があります。その対策として sla ディレクティブを利用した、という内容です。

digdagのsla ディレクティブとは

slaディレクティブを使用することで、digdagのジョブが特定の時間を超えた、または経過した場合に特定の処理を実行したり、エラーを発生させることができます。*2

ドキュメントのslaについての記載 には Setting an alert if a workflow doesn’t finish within expected time とあります。

slaディレクティブのオプション

sla ディレクティブで利用可能なオプションは、2019/10/12現在で以下の通りです。*3

  • sla: parameter supports duration: HH:MM:SS syntax in addition to time: HH:MM:SS syntax.
  • sla: parameter supports fail: BOOLEAN and alert: BOOLEAN options. Setting fail: true makes the workflow failed. Setting alert: true sends an notification using above notification mechanism.

経過時間を指定する場合は duration 、終了時間を指定する場合は time を使い、終了時にfailさせるのか、現状隠しパラメタ的なアラート処理を実行するのかを指定できます。噛み砕くと以下のようになります。

  • duration か time のどちらかを選択する
    • 経過時間を指定したい場合は duration
    • 終了時間を指定したい場合は time
  • 超過した場合、終了時にfailさせて、 _error: の処理も実行したい場合は fail: true
  • 超過した場合、終了時にnotificateion.typeによる通知を実行する場合は alert: true *4

余談ですが time:duration を両方指定した場合は以下のエラーとなります、親切ですね。

error: SLA must be specified using either the 'time' or 'duration' option (config)

slaディレクティブのサンプル

slaディレクティブのサンプルを記載します。

durationによる経過時間の超過を検知するサンプル

以下の条件を満たすサンプルコードです。

  • 6秒を超過した場合 (duration: 00:00:06)
  • エラー終了とし(fail: true)
  • "#### Long Running !!!###" と表示する (+alert:から続くジョブ)
timezone: Asia/Tokyo

schedule:
  daily>: 22:00:00

sla:
  duration: 00:00:06
  fail: true
  +alert:
    sh>: echo "#### Long Running !!!###"

_export:
  workflow_name: "test-sla"

+start:
  +sub1:
    sh>: echo "job1" ;sleep 5
  +sub2:
    sh>: echo "job2" ;sleep 5

+job_end:
  echo>: Success

_error:
  echo>: Error!!!!!

以下のようなメッセージが出力されます

019-10-15 00:51:45 +0900 [INFO] (main): Starting a new session project id=1 workflow name=test-sla session_time=2019-10-13T01:00:00+09:00
2019-10-15 00:51:46 +0900 [INFO] (0017@[0:default]+test-sla+start+sub1): sh>: echo "job1" ;sleep 5
job1
2019-10-15 00:51:51 +0900 [INFO] (0017@[0:default]+test-sla+start+sub2): sh>: echo "job2" ;sleep 5
job2
2019-10-15 00:51:52 +0900 [INFO] (0019@[0:default]+test-sla^sla^alert): type: notify
2019-10-15 00:51:52 +0900 [INFO] (0020@[0:default]+test-sla^sla^fail): type: fail
2019-10-15 00:51:52 +0900 [ERROR] (0020@[0:default]+test-sla^sla^fail): Task +test-sla^sla^fail failed.
SLA violation
2019-10-15 00:51:52 +0900 [INFO] (0021@[0:default]+test-sla^sla+alert): sh>: echo "#### Long Running !!!###"
#### Long Running !!!###
2019-10-15 00:51:56 +0900 [INFO] (0017@[0:default]+test-sla+job_end): echo>: Success
Success
2019-10-15 00:51:57 +0900 [INFO] (0021@[0:default]+test-sla^error): echo>: Error!!!!!
Error!!!!!
2019-10-15 00:51:57 +0900 [INFO] (0017@[0:default]+test-sla^failure-alert): type: notify
error:
  * +test-sla^sla^fail:
    SLA violation

timeによる終了時刻の超過を検知するサンプル

以下の条件を満たすサンプルコードです。

  • 01:42:00を超過した場合 (time: 01:42:00)
  • エラー終了とする(fail: true)
timezone: Asia/Tokyo

schedule:
  daily>: 01:41:37

sla:
  time: 01:42:00
  fail: true

_export:
  workflow_name: "test-sla"

+start:
  +sub1:
    sh>: echo "job1" ;sleep 5
  +sub2:
    sh>: echo "job2" ;sleep 50

+job_end:
  echo>: Success

_error:
  echo>: Error!!!!!

以下のようなメッセージが出力されます

2019-10-13 01:41:37 +0900 [INFO] (main): Starting a new session project id=1 workflow name=test-sla session_time=2019-10-13T01:00:00+09:00
2019-10-13 01:41:38 +0900 [INFO] (0017@[0:default]+test-sla+start+sub1): sh>: echo "job1" ;sleep 5
job1
2019-10-13 01:41:43 +0900 [INFO] (0017@[0:default]+test-sla+start+sub2): sh>: echo "job2" ;sleep 50
job2
2019-10-13 01:42:04 +0900 [INFO] (0019@[0:default]+test-sla^sla^fail): type: fail
2019-10-13 01:42:04 +0900 [ERROR] (0019@[0:default]+test-sla^sla^fail): Task +test-sla^sla^fail failed.
SLA violation
2019-10-13 01:42:33 +0900 [INFO] (0017@[0:default]+test-sla+job_end): echo>: Success
Success
2019-10-13 01:42:34 +0900 [INFO] (0019@[0:default]+test-sla^error): echo>: Error!!!!!
Error!!!!!
2019-10-13 01:42:34 +0900 [INFO] (0017@[0:default]+test-sla^failure-alert): type: notify
error:
  * +test-sla^sla^fail:
    SLA violation

alert: true によるログ記録を行うサンプル

fail: true と違い、現在のドキュメントからは使い方がわからない alert: true のサンプルです。 GitHubのissueに古橋さんが例を記載してくれています。以下は単純なshellを利用していますが、mailやhttpも利用とのことです。 どうにもExperimental感が強いので、ローカルで試したのみで本番利用するつもりは今のところ...

  • config
notification.type = shell
notification.shell.command = echo "workflow error" >> /tmp/hoge
  • code
timezone: Asia/Tokyo

schedule:
  daily>: 22:00:00

sla:
  duration: 00:00:06
  alert: true

_export:
  workflow_name: "test-sla"

+start:
  +sub1:
    sh>: echo "job1" ;sleep 5
  +sub2:
    sh>: echo "job2" ;sleep 5

+job_end:
  echo>: Success

_error:
  echo>: Error!!!!!

以下のようなメッセージが出力されます

2019-10-13 02:07:05 +0900 [INFO] (main): Starting a new session project id=1 workflow name=test-sla session_time=2019-10-13T01:00:00+09:00
2019-10-13 02:07:06 +0900 [INFO] (0017@[0:default]+test-sla+start+sub1): sh>: echo "job1" ;sleep 5
job1
2019-10-13 02:07:11 +0900 [INFO] (0017@[0:default]+test-sla+start+sub2): sh>: echo "job2" ;sleep 5
2019-10-13 02:07:11 +0900 [INFO] (0019@[0:default]+test-sla^sla^alert): type: notify
job2
2019-10-13 02:07:16 +0900 [INFO] (0017@[0:default]+test-sla+job_end): echo>: Success
Success

configで指定した notification.type = shell の処理も動作していました。

# cat /tmp/hoge
workflow error

slaディレクティブを使用し、一定時間以上が経過したジョブを自動キャンセルする

そして個人的にはこれが一番やりたかったことですが、slaディレクティブを使うことで、長時間実行されてしまうジョブをキャンセルすることが可能です。 以下のコードではjob2の実行中に digdag kill によるキャンセルが発生し、job3は実行されません。

**digdagはserverモードでの利用を前提としています

timezone: Asia/Tokyo

schedule:
  daily>: 22:00:00

sla:
  duration: 00:00:06
  +kill:
    +alert:
      sh>: bin/nothice.sh
    +kill:
     sh>: digdag kill ${attempt_id}

_export:
  workflow_name: "test-sla"

+start:
  +sub1:
    sh>: echo "job1" ;sleep 5
  +sub2:
    sh>: echo "job2" ;sleep 5
  +sub3:
    sh>: echo "job3" ;sleep 5

+job_end:
  echo>: Success

_error:
  echo>: Error!!!!!

ポイントはslaディレクティブのジョブで digdag kill ${attempt_id} を行なっている点です。attempt_idは0.9.32から利用できるようになりましたが、slaディレクティブと組み合わせることで「slaを守れない自分をキャンセル(digdag kill)する」ことができます。なおキャンセルをするため faile: true を指定する意味はありません。

加えて、digdag killする前に +alert で行なっているようにSlackやメールなどの通知を行なっておくことをお勧めします。理由としてキャンセルを行う場合 _error 処理は実行されず、_error 処理による検知に頼っている場合キャンセル発生を見逃してしまう可能性があるためです。

digdag kill で止まるケース

以下のようなケースはdigdag killが有効で、job2までは実行されますが、job3、job4は実行されません。

timezone: Asia/Tokyo

schedule:
  daily>: 22:00:00

sla:
  duration: 00:00:06
  +kill:
    +alert:
      sh>: bin/nothice.sh
    +kill:
     sh>: digdag kill ${attempt_id}

_export:
  workflow_name: "test-sla"

+start:
  +sub1:
    sh>: echo "job1" ;sleep 5
  +sub2:
    sh>: echo "job2" ;sleep 5
  +sub3:
    sh>: echo "job3" ;sleep 5
  +sub4:
    sh>: echo "job4" ;sleep 5

+job_end:
  echo>: Success

_error:
  echo>: Error!!!!!

digdag kill で止まらないケース

以下のようなケースはdigdag killは行われますが、job2が途中で中断されることはなく、digdagはjob2の終了を待ってしまいます。私の期待としては6秒を超えた時点でsh>実行中のプロセスに対してもkillシグナルを発行してもらいたいのですが、現状は待ち続けるようでした。このように特定の長時間化した処理をどうしても止めたい場合はdigdagの外部(OS上など)から強制停止を行う必要がありそうです。

timezone: Asia/Tokyo

schedule:
  daily>: 22:00:00

sla:
  duration: 00:00:06
  +kill:
    +alert:
      sh>: bin/nothice.sh
    +kill:
      sh>: digdag kill ${attempt_id} ; date

_export:
  workflow_name: "test-sla"

+start:
  +sub1:
    sh>: echo "job1" ;sleep 5
  +sub2:
    sh>: echo "job2" ;sleep 100

+job_end:
  echo>: Success

_error:
  echo>: Error!!!!!

まとめ

以上、slaディレクティブを使った想定外に長時間実行してしまうジョブへの対策、でした。 「キューが溜まってdigdag serverで管理するジョブがある時点から全停止してる?!」なんて悲劇が起きる前に仕込んでおきたいですね。

参考になったサイト

*1:digdagではWorkflowと呼ぶけどここでは一般用語として"ジョブ"とします

*2:SLA(Service Level Agreement)を定義する意味からのオプション名でしょうが、Timeoutとかの方が個人的には分かりやすいです

*3:このオプションの説明がRelease Noteにしかなくて分かりづらいので、ドキュメント修正のPRを出したりしました

*4:そもそもこのnotification.typeが現状ドキュメントにないのはなぜなんだろ