digdag で発生した "Text file busy" の調査

概要

要約すると sh> を通じてシェルスクリプトを実行すると、稀に "Text file busy" が発生するというもの。

2024-04-04 23:50:00.958 +0000 [INFO] (0417@[0:batch:58677:58677]+batch.import+import) io.digdag.core.agent.OperatorManager: sh>: cmd/batch_app.sh import
.digdag/tmp/digdag-sh-122635-8641042193224341649/runner.sh: 1: .digdag/tmp/digdag-sh-122635-8641042193224341649/runner.sh: cmd/batch_app.sh: Text file busy
2024-04-04 23:50:01.067 +0000 [ERROR] (0417@[0:batch:58677:58677]+batch.import+import) io.digdag.core.agent.OperatorManager: Task failed with unexpected error: Command failed with code 2
java.lang.RuntimeException: Command failed with code 2
	at io.digdag.standards.operator.ShOperatorFactory$ShOperator.runCode(ShOperatorFactory.java:121)
	at io.digdag.standards.operator.ShOperatorFactory$ShOperator.runTask(ShOperatorFactory.java:88)
	at io.digdag.util.BaseOperator.run(BaseOperator.java:35)
	at io.digdag.core.agent.OperatorManager.callExecutor(OperatorManager.java:399)
	at io.digdag.server.metrics.DigdagTimedMethodInterceptor.invokeMain(DigdagTimedMethodInterceptor.java:58)
	at io.digdag.server.metrics.DigdagTimedMethodInterceptor.invoke(DigdagTimedMethodInterceptor.java:31)
	at io.digdag.core.agent.OperatorManager.runWithWorkspace(OperatorManager.java:308)
	at io.digdag.server.metrics.DigdagTimedMethodInterceptor.invokeMain(DigdagTimedMethodInterceptor.java:58)
	at io.digdag.server.metrics.DigdagTimedMethodInterceptor.invoke(DigdagTimedMethodInterceptor.java:31)
	at io.digdag.core.agent.OperatorManager.lambda$runWithHeartbeat$2(OperatorManager.java:152)
	at io.digdag.core.agent.ExtractArchiveWorkspaceManager.withExtractedArchive(ExtractArchiveWorkspaceManager.java:75)
	at io.digdag.core.agent.OperatorManager.runWithHeartbeat(OperatorManager.java:150)
	at io.digdag.server.metrics.DigdagTimedMethodInterceptor.invokeMain(DigdagTimedMethodInterceptor.java:58)
	at io.digdag.server.metrics.DigdagTimedMethodInterceptor.invoke(DigdagTimedMethodInterceptor.java:31)
	at io.digdag.core.agent.OperatorManager.run(OperatorManager.java:133)
	at io.digdag.server.metrics.DigdagTimedMethodInterceptor.invokeMain(DigdagTimedMethodInterceptor.java:58)
	at io.digdag.server.metrics.DigdagTimedMethodInterceptor.invoke(DigdagTimedMethodInterceptor.java:31)
	at io.digdag.core.agent.MultiThreadAgent.lambda$null$0(MultiThreadAgent.java:132)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

仮説１． 異なる Session / 異なる Task から同じシェルを実行している

結論、その可能性はない。

Task ごとに作業ディレクトリとして一時ディレクトリを作成し、その下に必要なファイル群をコピーしてきて実行しているため。
これは、Task からシェルを介して作業ディテクトリをウォークすると分かる。

#!/bin/sh -x

pwd
ls -la
ls -la .digdag
ls -la .digdag/tmp
ls -la .digdag/tmp/digdag-sh-*
echo "$(cat .digdag/tmp/digdag-sh-*/runner.sh)"

2024-04-16 02:26:35.113 +0000 [INFO] (76901@[0:test:75340:75395]+test.test-script+test_batch) io.digdag.core.agent.OperatorManager: sh>: cmd/batch_test.sh
+ pwd
/tmp/digdag-tempdir4756914849299489096/workspace/8_test.test-script_75395_159276_2999550162698923174
+ ls -la
total 24
drwx------ 4 root root 4096 Apr 16 02:26 .
drwxr-xr-x 3 root root 4096 Apr 16 02:26 ..
drwxr-xr-x 3 root root 4096 Apr 16 02:26 .digdag
-rwxrwxrwx 1 root root  400 Apr 16 02:26 Makefile
drwxr-xr-x 2 root root 4096 Apr 16 02:26 cmd
-rwxrwxrwx 1 root root  117 Apr 16 02:26 test.test-script.dig
+ ls -la .digdag
total 12
drwxr-xr-x 3 root root 4096 Apr 16 02:26 .
drwx------ 4 root root 4096 Apr 16 02:26 ..
drwxr-xr-x 3 root root 4096 Apr 16 02:26 tmp
+ ls -la .digdag/tmp
total 12
drwxr-xr-x 3 root root 4096 Apr 16 02:26 .
drwxr-xr-x 3 root root 4096 Apr 16 02:26 ..
drwx------ 2 root root 4096 Apr 16 02:26 digdag-sh-159276-8382444378983671278
+ ls -la .digdag/tmp/digdag-sh-159276-8382444378983671278
total 12
drwx------ 2 root root 4096 Apr 16 02:26 .
drwxr-xr-x 3 root root 4096 Apr 16 02:26 ..
-rw-r--r-- 1 root root   17 Apr 16 02:26 runner.sh
+ cat .digdag/tmp/digdag-sh-159276-8382444378983671278/runner.sh
+ echo cmd/batch_test.sh
cmd/batch_test.sh

仮説２． 一時ディレクトリ名がバッティングして異なる Task がファイルを握り合った

結論、その可能性は低い。

java.nio.file.Files を利用し一時ティレクトリを作成しているため。下記が実際に作成された一時ディレクトリと指定箇所。

/tmp/digdag-tempdir[java.nio.file.Filesによる自動採番]/workspace/[ProjectID]_[Workflow名]_[Attempt ID]_[Task ID]_[java.nio.file.Filesによる自動採番]

仮説３． 一時ディレクトリにコピーし切る前に実行された

結論、その可能性はない。

一時ディレクトリにコピー→実行 が順次実行されているため。

結論

原因の解明には至らず。ジョブが異常終了することから無視できないが、頻度も低いため静観することとする。