Goのライブラリのバグを見つけてから直すまで layerx.go#0

layerx.go #0

概要
LayerXでは、バクラク事業部で開発・運用しているバクラクをはじめ、ほか事業部が開発しているほとんどのサービスでGo言語を利用しています。また、2023年の夏頃からは「Go 読書会」を社内の有志にて開催しており、組織横断的にGoの知見を交換しています。

本イベント「layerx.go」では、LayerXのGo言語の"実践的な"活用事例を共有するだけでなく、社外の方からの知見も積極的に取り入れる場として位置付けています。LayerXの行動指針"Bet Technology"と"徳"の観点から、本イベントを継続的に開催することでGo言語の裾野を広げていきたいと考えています。

初回のテーマは「Goの情報収集や知見の共有活動 / Goのプロダクトコードのキャッチアップ」です！

https://layerx.connpass.com/event/317228/

Transcript

1. © LayerX Inc. Goのライブラリのバグを見つけてから直すまで 2024/05/24 layerx.go #0 Tomoaki Kitaoka Go MachineryでGraceful shutdownできてないバグを直した話
2. 2 © LayerX Inc. 自己紹介 北岡 知晃（Tomoaki Kitaoka）@tapioca_pudd 2019年〜 株式会社LayerX バクラク事業部 機械学習チーム Software Engineer • インターン→新卒入社 • バクラクのリリース初期から AI-OCR機能の開発 • Go歴3年くらい • 趣味は体を鍛えること（クロスフィット）と服を作ること
3. 目次 Agenda • 背景 • 起きていた事象 • 調査する • デバッグする • 修正する • さいごに
4. 背景
5. © LayerX Inc. 5 • 請求書に記入されている項目（支払期日や支払金 額、取引先名など）を目視で確認して、ミスなく入 力・管理することはとても負荷の高い仕事 ◦ 枚数が増えるにつれてミスが起こりやすい ◦ 帳票のフォーマットが多種に渡り単純に大変 ◦ ミスは許されないためダブルチェック等確認 作業にもコストがかかってしまう バクラクのAI-OCR 背景
6. © LayerX Inc. 6 バクラク請求書 AI-OCR（請求書読み取り）機能のデモ 背景
7. © LayerX Inc. 7 バクラクのAI-OCRを支える非同期処理アーキテクチャ 背景 ファイルを扱う処理は重く、また突発的に大量のリクエストが来ることもあるため非同期処理のアーキテクチャを採用。 Lambda ECS 2. 重い処理は分離 （同期呼び出し） ECS SQS 3. 次の処理へ SQS 4.受信 S3 1. リクエスト SageMaker Lambda S3 SageMaker AI-OCRのAPIサーバーでは主にGo言語を採用しており、非同期で実行したい処理はメッセージキューとしてAmazon SQS、 メッセージの送受信やジョブワーカーの管理にはMachinery(v1)を使用しています。
8. © LayerX Inc. 8 MachineryはGo製の非同期タスク管理フレームワーク 背景 SQS ECS メッセージ 受信 非同期処理 SQS メッセージ送 信 ↑ ここで動くのが machinery • メッセージブローカーとして、 SQSはもちろん、RedisやAMQPなども利用可能 • メッセージに応じて異なるタスクを実行するだけでなく、遅延実行したり、エラーのリトライ時に はタイミングや回数の制御もでき、多段タスクや並列タスクの実行も可能 • タスクの定期的な実行も可能 参考：https://github.com/RichardKnop/machinery
9. 起きていた事象
10. © LayerX Inc. 10 デプロイ時になぜか毎回リクエストが数件タイムアウト 起きていた事象 ECS ECS 新ジョブワーカー 旧ジョブワーカー AI-OCRの非同期処理を担うジョブワーカーのデプロイ時、新しいジョブワーカーが起動して旧ジョブワーカー が停止する切り替えのタイミングで、毎度数件のリクエストがタイムアウトしていた。 c注：非同期で処理するようにはしているものの、client側に一定時間内にレスポンスを返したいのでタイムアウトを設定している部分がある
11. 調査する
12. © LayerX Inc. 12 調査する ECS 旧ジョブワーカー 旧workerのログを見る terminateのシグナルを受信してから0.2秒ほどでGracefull shutdownしている ※Graceful Shutdown:現在処理中のリクエストを適切に完了させ、新しいリクエストを受け付けずにプロセスを終了させる こと
13. © LayerX Inc. 13 調査する タイムアウトしているリクエストを追う 旧ジョブワーカーで実行 新ジョブワーカーで再実行 SQSの可視性タイムアウトと 同じ時間経過後再実行 タイムアウトしているリクエストを追ってみると、Amazon SQSの可視性タイムアウトと同じ時間 経過後ジョブが再実行されている形跡を発見 ※可視性タイムアウト： メッセージが受信された直後は、メッセージはキューに保留されたままです。他のコンシューマーが同じメッセー ジを再び処理しないように、 Amazon SQSは可視性タイムアウト、つまり Amazon SQS が他のカスタマーがそのメッセージの受信や 処理できなくなる期間を設定します。デフォルトの可視性タイムアウトは 30秒です。 https://docs.aws.amazon.com/ja_jp/AWSSimpleQueueService/latest/SQSDeveloperGuide/sqs-visibility-timeout.html
14. © LayerX Inc. 14 調査する タイムアウトしているリクエストを追う 旧workerで実行 新workerで再実行 SQSの可視性タイムアウトと 同じ時間経過後再実行 タイムアウトしているリクエストを追ってみると、SQSの可視性タイムアウトと同じ時間経過後ジョ ブが再実行されている形跡を発見 🤔 SQSのメッセージが可視性タイムアウトになっ ている場合、メッセージの受信自体はされてい る。 となると旧ジョブワーカーがGraceful Shutdownできてないのでは？
15. © LayerX Inc. 15 調査する Machineryのコードを読む 具体的にシャットダウン処理が走っているところ
16. © LayerX Inc. 16 調査する Machineryのコードを読む(worker.Quit()の中身) ① consumeの停止 ② receiveの停止
17. © LayerX Inc. 17 調査する 仮説を立てる メッセージの受信中の間に terminateを受けると、先にメッセージを処理する goroutine（Consume）を終了させ てしまうため、受信中だったメッセージが受信完了しても処理できていないのではないか ?
18. © LayerX Inc. 18 調査する 仮説を立てる メッセージの受信中の間に terminateを受けると、先にメッセージを処理する goroutine（Consume）を終了させ てしまうため、受信中だったメッセージが受信完了しても処理できていないのではないか ? 厨房締め作業 完了 締め作業を終えた厨房に オーダーが入る 飲食店で例えると、厨房の締め作 業も終わったのに追加でオーダー が入ってきたイメージ
19. デバッグする
20. © LayerX Inc. 20 Machineryをcloneしローカルで動かす デバッグする go mod edit -replace で元々のライブラリへの参照を別のライブラリへ一発で切り替えできて便利
21. © LayerX Inc. 21 デバッグ用のログを仕込んでみる デバッグする 旧ジョブワーカー 新ジョブワーカー ①メッセージの受信を開始 ②受信したメッセージが処理されることなく gracefully shutdown ③新しいジョブワーカーでメッセージを受信 注：メッセージ受信中にterminateのsingalを受け取ることが重要なの で、receiveの処理にsleep処理を入れ、事象を再現しやすくした
22. © LayerX Inc. 22 時系列に並べてみる デバッグする 旧ジョブワーカー (worker1) 新ジョブワーカー (worker2)
23. © LayerX Inc. 23 時系列に並べてみる デバッグする 旧ジョブワーカー (worker1) 新ジョブワーカー (worker2) 😃 仮説は合っていそうだ！！！
24. 修正する
25. © LayerX Inc. 25 修正する StopConsuming()でConsumeを止めた後に、Receiveを止めているのが問題なので、Receiveを先に止め、 Receive中の処理が完全に消化されたらConsumeも止めてあげるようにします receiveを完全に終了させてからconsumeも止める
26. © LayerX Inc. 26 修正する StopConsuming()でConsumeを止めた後に、Receiveを止めているのが問題なので、Receiveを先に止め、 Receive中の処理が完全に消化されたらConsumeも止めてあげるようにします receiveを完全に終了させてからconsumeも止める ラストオーダー 全部聞き終える 厨房締め作業 完了
27. © LayerX Inc. 27 修正する 修正する https://github.com/tomo25/machinery/pull/1/files
28. さいごに
29. © LayerX Inc. 29 さいごに 結果と感想 • 修正後、デプロイに伴うジョブワーカーのタイムアウトエラーは0件に。🎉🎉🎉 • プロダクトローンチ直後はジョブワーカーの切り替えタイミングにピンポイントでリクエストがくることがなく気がつか なったが、プロダクトの規模が徐々に大きくなるにつれ発覚。リリースのタイミングは常に不審なログがないか注視すべ し。 • ローカル環境ではlocalstackを利用することでSQS+Machineryの構成を再現できて便利だった。 • go mod edit -replace 初めて使ったけどコマンド一発で参照するライブラリの変更が完結して便利だった。
30. © LayerX Inc. 30 さいごに バクラクではMLOpsエンジニアを大大大募集しています！ バクラクのMLOpsについて書いたブログ カジュアル面談 サマーインターンも大募集中！ ソフトウェアエンジニア 機械学習エンジニア