aws-sqsdのSignature(署名リクエスト)エラーについて
aws-sqsdで発生したエラー
Elastic BeanstalkのWorkerインスタンスがSQSのメッセージを捌かなくなり、5XXを頻発するという障害の調査を依頼され、aws-sqsdを確認したところ、ログに以下の様なエラーが出力されていた(タイムスタンプは架空)。
2022-07-24T00:01:02Z healthcheck-err: failed to pull messages from SQS queue with error: Signature not yet current: 20220724T000101Z is still later than 20220723T230411Z (20220723T224911Z + 15 min.) 2022-07-24T00:01:02Z pollers: daemon exception during polling message from sqs: Signature not yet current: 20220724T000102Z is still later than 20220723T230411Z (20220723T224911Z + 15 min.) 2022-07-24T00:01:02Z metrics: Aws::CloudWatch::Errors::SignatureDoesNotMatch: Signature not yet current: 20220724T000102Z is still later than 20220723T225411Z (20220723T224911Z + 5 min.) 2022-07-24T00:01:02Z pollers: daemon exception during polling message from sqs: Signature not yet current: 20220724T000102Z is still later than 20220723T230412Z (20220723T224912Z + 15 min.)
メッセージを読むと時刻のズレに原因があるものと推察出来る。
実際にその通りで、これはAWSのAPIを実行したマシンの時刻が現在時からズレていると生じる、AWS APIの署名リクエストのエラーの一種。
AWS APIはCLIやSDK等でのリクエスト時に、APIの実行時刻をx-amz-dateリクエストヘッダー、乃至はクエリパラメーターとして付与するのだが、その時刻がAPIサーバー側とズレているとこのエラーが返ってくる。
詳細な仕様は下記リンク先の公式ドキュメントを参照。
署名リクエストのエラーは要素に応じて何種類かあるのだが、CLIやSDKを使ってAWSのリソースを操作する場合、ユーザーが意識せずとも暗黙的に正規のリクエストが送られる為、署名リクエストのエラーの中でも、ユーザー側の環境起因で発生する事になるこのエラーに遭遇する確率は高い気がする。
なお、この様なエラーは当然だがaws-sqsdに限らず、他のAWSサービスにおいても発生するもので、S3とかだと以下の様なエラーメッセージをちょくちょく目にする事がある。
The difference between the request time and the current time is too large.
職場でAWSの技術サポート的な事をやっていると、S3の操作が出来ないといった相談を受け、エラーメッセージを送ってもらったらこれで、作業マシンの時刻がズレていました、というのは割とあるあるだったりする。
エラーの原因
上述したaws-sqsdのエラーの原因自体は既に書いた通りなのだが、今回、このエントリを書く切っ掛けとなった障害は、Amazon Linux 2で稼働しているElastic BeanstalkのWorkerインスタンスで発生していた。
Amazon Linux 2の場合、タイムサーバーはchronyが稼働しており、標準で169.254.169.123のリンクローカルIPアドレスでアクセス出来るAmazon Time Sync Serviceを利用して時刻の同期が行われている。
にも関わらず、件のWorkerインスタンスで時刻を確認したところ、数時間単位で未来時刻にズレていたのである。
どういう事だろうかと、まず、journalctlでchronydを見てみたら、以下の様なメッセージが表示された(タイムスタンプは架空)。
Jul 24 07:45:53 ip-xxx-xxx-xxx-xxx.ap-northeast-1.compute.internal chronyd[1683]: Forward time jump detected! Jul 24 07:46:27 ip-xxx-xxx-xxx-xxx.ap-northeast-1.compute.internal chronyd[1683]: Can't synchronise: no selectable sources Jul 24 07:49:16 ip-xxx-xxx-xxx-xxx.ap-northeast-1.compute.internal chronyd[1683]: Selected source 169.254.169.123 Jul 24 09:59:52 ip-xxx-xxx-xxx-xxx.ap-northeast-1.compute.internal systemd[1]: chronyd.service: main process exited, code=exited, status=1/FAILURE Jul 24 09:59:52 ip-xxx-xxx-xxx-xxx.ap-northeast-1.compute.internal systemd[1]: Unit chronyd.service entered failed state. Jul 24 09:59:52 ip-xxx-xxx-xxx-xxx.ap-northeast-1.compute.internal systemd[1]: chronyd.service failed.
唐突に時間が進んでしまい、AWS Time Sync Serviceとの同期が切れた後、プロセスが異常終了してしまった模様で、そのまま再起動する事も無く、chronydがお亡くなりになっていた。
この前に何があったのか、全体のログを確認してみたところ、直前にOOM Killerが発生しており、aws-sqsdのプロセスが殺されて、chronyd以外のサービスにも色々と異常をきたしていた事が判明。
sysstatでリソースの状況を確認していくと、インスタンスが起動した段階からメモリの使用率は90%程度になっており、aws-sqsdがメッセージを処理し始めてから1時間程度でメモリがパンク寸前に。
また、journalctl -u chronydでユニット指定で絞り込んだ時には表示されなかったが、systemdがchronydサービスを異常終了した後に、以下のエラーメッセージが出力されていた事も分かった。
Jul 24 09:59:52 ip-xxx-xxx-xxx-xxx chronyd[1683]: Fatal error : Possible infinite loop in scheduling
このエラーメッセージを検索してみたところ、chronyユーザーのメーリングリストのアーカイブが引っ掛かり、同じ様にメモリの高負荷状況下でchronydがクラッシュして再起動に失敗するという事例が報告されていた。
スレッドを追っていくと、chronyのメンテナーによる返信として、メモリの枯渇でページロードを待機し続けてこのエラーが生じていると推測されており、その後、メモリの高負荷時にこのエラーが出る旨が書かれている。
という訳で、根本原因としてメモリの容量不足が考えられる事は間違い無さそうである。
時刻の同期が狂った状況について、chronyの各種ログを見ればより詳細が分かるのかもしれないが、chronyのログは標準だとsyslogに吐かれるもの以外は出力されない設定になっている。
chronyの設定ファイルである/etc/chrony.confのlogコマンドは以下の通りコメントアウトされており、/var/log/chronyディレクトリには何も吐かれない。
# Specify directory for log files. logdir /var/log/chrony # Select which information is logged. #log measurements statistics tracking
Amazon Linux 2でもこの様な設定なので、残念ながらこれ以上の事は分からなかった。
対応と課題
そもそも、chronyの問題は置いておいたとしても、少なくともメモリの容量が不足しているという問題点は明白だったので、まずは、Workerインスタンスのスケールアップで当座を凌いでもらい、Workerアプリケーションのプロセスやメモリ使用量の監視を後日の課題として、一先ずの調査を終えた。
