小さな修正こそ不具合の証明に責任を持つべきだと OpenJD で実感した話 #OSSコントリビュート
はじめに
業務で構築した AWS Deadline Cloud のレンダリング環境で、3ds Max のジョブがエラーを出さずに途中で止まり続ける現象に遭遇しました。調べたところ、原因は OpenJD のアダプタランタイムの不具合でした。Issue と 1 行の修正 PR を送り、マージされました。
小さな修正でも、不具合の原因を突き止め、テストで証明するところまでは自分で責任を持って渡すべきだと感じています。 送った PR は、レビューでの改善を経て 0.9.6 として配布されました。同じ現象に出会った場合は、アダプタランタイムを 0.9.6 以降へ更新すれば解消します。
本記事では、レンダリングを運用している方に向けて不具合の見分け方を書きます。また、OSS への報告を迷っている方に向けて、修正を送ってみて感じたことを書きます。
調査の手法については、次の 2 本の記事にまとめています。
OpenJD とは
Open Job Description (OpenJD) は、レンダリングなどのジョブを記述するためのオープンな仕様です。AWS Deadline Cloud はこの仕様にもとづいてジョブを実行します。3ds Max などの DCC を動かすアダプタは、共通の処理を openjd-adaptor-runtime-for-python というライブラリに任せています。今回の修正先は、このライブラリのリポジトリです。
参考
不具合と原因
今回修正 PR を送るきっかけになったのは、3ds Max の特定の重いシーンのレンダリングが失敗にならずに毎回同じ進行度で進まなくなる問題に遭遇したことでした。ログの詳細度を下げてみたところ、進行度はもう少し先まで進んだもののやはりそこで進まなくなります。ログの詳細度を最も低い設定にしたところ進行度は一応 100% になりました。しかし、100% になったタイミングでアダプタがレンダリング完了を検知できず、やはりそこで進まなくなってしまいました。つまるところ、ログの詳細度変更は回避策にならなかった形です。
決め手は、アダプタの Python プロセスのスレッドを py-spy で調べたことです。3ds Max の標準出力を読むスレッドが死んでいて、アダプタの出力ログに次の例外が残っていました。
Exception in thread AdaptorRuntimeStdoutLogger:
Traceback (most recent call last):
File "<frozen codecs>", line 322, in decode
UnicodeDecodeError: 'utf-8' codec can't decode byte 0xc7 in position 2: invalid continuation byte
アダプタランタイムは、サブプロセスの出力を厳格な UTF-8 で読んでいました。3ds Max が UTF-8 でないバイト (0xc7) を出すと、例外で読み取りスレッドが終了します。読み手がいなくなったパイプは満杯になり、3ds Max は出力の書き込みで止まります。止まる位置がログの量で変わっていた原因は、このパイプの溢れだったのです。 ログが多いほどパイプは早く溢れるため、そのぶん早い位置で止まっていました。
3ds Max は、描画する本体と、その出力を中継する 3dsmaxbatch の 2 つのプロセスで動いています。書き込みはエラーにならず、パイプに空きが出るのを待ち続けるため、ジョブは失敗にならずに止まり続けます。止まるまでの流れをざっくり図で説明すると、次のような感じです。正常時は、読み手が出力を読み続けるのでパイプは詰まりません。
読み取りスレッドが終了すると、パイプが溢れ、上流が番号の順に止まっていきます。
送った修正
手元では修正入りのイメージを作り直して対応していましたが、パッチを持ち続ける保守の手間が残ります。AWS サポートからも公式リポジトリへの報告を案内されたため、Issue #274 を起票し、次の PR を送りました。
修正したのは、サブプロセスを起動する subprocess.Popen に渡す引数です。文字コード (encoding) だけを指定し、デコードできないバイトの扱い (errors) を指定していなかったため、既定の厳格な扱いで例外が出ていました。ここに errors="replace" を加え、デコードできないバイトを置換文字に置き換えるようにしました。
# Create the subprocess
popen_params: Dict[str, Any] = dict(
args=args,
stdin=subprocess.PIPE,
stderr=subprocess.PIPE,
stdout=subprocess.PIPE,
encoding=encoding,
+ errors="replace",
cwd=startup_directory,
)
※実際の差分には理由を説明するコメントも含まれますが、ここでは省いています。
送る際に気をつけたのは 2 点です。
まず、範囲を欠陥 1 つに絞りました。読み取りスレッドはほかの例外でも終了しうる作りでしたが、既存のテストがその挙動を仕様として守っていたため、Issue で触れるだけにしました。
次に、回帰テストを添えました。UTF-8 でないバイトを出すサブプロセスを起動し、その後の行がログされることを確かめるテストで、修正前のコードで失敗することを確認してから送りました。なお、最初はコミットに DCO の sign-off を付け忘れ、チェックが失敗したため付け直しました。
約 4 日後に 2 名のメンテナが承認し、マージされました。レビューでは、errors="replace" より backslashreplace のほうが元のバイト値がログに残り、DCC が出す文字コードを調べやすいと提案されました。この変更はメンテナ自身が #277 で入れ、0.9.6 として配布されました。
学び
送る前は、1 行の修正を上流へ出す価値を小さく感じていました。しかし、1 行の差分だけでは、その変更が必要である理由をメンテナは判断しにくいと思います。原因を突き止め、範囲を自分で証明できる欠陥 1 つに絞り、修正前に失敗するテストで不具合を示したことで、小さな修正でも受け入れてもらえたと考えています。レビューでの改善案は、自分の修正に足りなかった観点を知る機会になりました。小さな修正こそ、必要である理由の証明まで自分で責任を持つべきというのを実感する体験でした。
さいごに
3ds Max などの DCC のジョブが無言で止まる場合は、アダプタランタイムを 0.9.6 以降へ更新し、出力を読むスレッドの例外の有無を確かめてみてください。業務で OSS の不具合を直した方は、原因の説明と不具合を再現するテストを添えて、手元のパッチを上流へ返してみてください。迅速にレビューしてくださったメンテナの皆さんに感謝します。本記事が、同じ現象に出会った方や、OSS への報告を迷っている方の参考になれば幸いです。
