【AWS】Systems Manager AutomationのrunCommandで、RedshiftのUNLOADコマンドが正常終了したにもかかわらずERRORが出る謎を解く

問題となったAWSサービス

Systems Manager AutomationのrunCommand

Systems Manager Automationは、Systems Managerで提供されている機能の一つで、EC2やRDS、Redshift、S3などのAWSサービス共通の保守、デプロイ、改善のタスクを簡素化して運用できる。
AWS Systems Manager Automation
このAutomationにおいてrunCommandという、マネージドインスタンス（EC2）でコマンドを実行するアクションを実装できる。
例えば、管理下のEC2サーバ上でシェルスクリプトを実行させるようなタスクである。
これを、エンジニアがSSHして踏み台サーバ経由でいちいち黒い画面を開いてコマンドを叩くことなく完遂できる。

# 公式ドキュメントのサンプルコード
- name: checkMembership
  action: 'aws:runCommand'
  inputs:
    DocumentName: AWS-RunPowerShellScript
    InstanceIds:
      - '{{InstanceIds}}'
    Parameters:
      commands:
        - (Get-WmiObject -Class Win32_ComputerSystem).PartOfDomain

aws:runCommand

このコマンド実行の結果（ResponseCodeとOutput、それぞれ終了ステータスと出力結果）は、AWSのマネジメントコンソールのAutomation実行履歴のページや、Systems ManagerのAPIを叩くことで確認できる。

イメージの出典

RedshiftのUNLOADコマンド

Redshiftのテーブルに対して実行するクエリの結果を、簡潔な記述でS3にエクスポートしてくれるコマンド。

-- 公式ドキュメントのサンプルコード
unload ('select * from venue where venueid in 
(select venueid from venue order by venueid desc limit 10)') 
to 's3://mybucket/venue_pipe_' iam_role 'arn:aws:iam::0123456789012:role/MyRedshiftRole';

UNLOAD

現象

業務で実際に書いているコードは公開できないが、下記のようなシェルスクリプト（本現象の該当部分を抜粋）をAutomationで実行した。
Redshiftのテーブルから、1件のidについてレコードにある日付（yyyymm）のリストを抽出するというシンプルなクエリ。

sample.sh

#!/bin/bash

QFILE="/your/folder/query.sql"
QUERY="unload ('select id, yyyymm from your_table where id in (select id from your_table limit 1)') to 's3://your-bucket/your-key' CREDENTIALS 'aws_iam_role=arn:aws:iam::XXXXXXXXXXXX:role/yourRole' delimiter '\t' PARALLEL OFF gzip allowoverwrite;"
echo ${QUERY} > ${QFILE}

psql -h ${ENDPOINT} -p ${PORT} -d ${DBNAME} -U ${USERNAME} -t -A -F"  " < ${QFILE}

Automationのマネジメントコンソールからログを確認すると、Outputは以下のようになった。

Output

UNLOAD

----------ERROR-------
INFO:  UNLOAD completed, XXX record(s) unloaded successfully.

ん？

unloadに成功したのに、エラー？？？
Automationの実行ステータスも「成功」となっている。
S3にもunloadされたファイルが正常に置かれている。

試したこと

AutomationのrunCommandの実行ステータスは、シェルスクリプトの場合は最後に実行されたコマンドの終了コードが0であれば「成功」、0以外であれば「失敗」となる。
今回は上のようにOutputにしっかりERRORの文字があったが、実行ステータスは「成功」だった。

（上記の抜粋ではなく）実際に実行したシェルスクリプトには、unloadを実行した後に数行のコマンドがあり、これらが成功したためにAutomationとしては正常終了したという仮説が立った。

上のスクリプトの最後に1行追加して、psqlコマンドの終了コードが0でない可能性を確かめた。

#!/bin/bash

QFILE="/your/folder/query.sql"
QUERY="unload ('select id, yyyymm from your_table where id in (select id from your_table limit 1)') to 's3://your-bucket/your-key' CREDENTIALS 'aws_iam_role=arn:aws:iam::XXXXXXXXXXXX:role/yourRole' delimiter '\t' PARALLEL OFF gzip allowoverwrite;"
echo ${QUERY} > ${QFILE}

psql -h ${ENDPOINT} -p ${PORT} -d ${DBNAME} -U ${USERNAME} -t -A -F"  " < ${QFILE}
# ここでpsqlの終了コードを標準出力
echo $?

が、当然ながら終了コードも「0」だった。

ここで「終了コードが0でないため、エラー」という可能性が消え、しばし思考停止。

開発チームのメンバーに相談しながら再度ログ出力をよく見ると、「UNLOAD」という単語だけの行も出力されていることに気づく（この出力はERRORではなさそうだ）。
ということは、標準出力まわりに原因がありそう？

今度はAutomationを使わずに、EC2サーバにSSH接続で入り、以下のコマンドを叩いてみた。
標準出力と標準エラー出力をそれぞれstdout.txt、stderr.txtにリダイレクト。

sh sample.sh 1> stdout.txt 2> stderr.txt

すると、ERROR表示の原因が見えてきた。

stdout.txt

UNLOAD

stderr.txt

INFO:  UNLOAD completed, XXX record(s) unloaded successfully.

解決

Redshiftのunloadコマンド実行時に出力されるメッセージのうち、「INFO: ~」は標準出力ではなく標準エラー出力だった。
Systems Manager AutomationのOutputの仕様については調べてもあまり情報が見当たらず、真偽は不明だが、おそらくOutputの「----------ERROR-------」はそれ以下の出力が標準エラー出力であるのを示すと思われる。

コマンドの終了コードでAutomationの成功・失敗を判定させたい場合には、今回のように正常終了しているのにOutputにERRORの表示が出るのは誤解を招くだろう。
Automationで実行するコマンドを以下のようにすることで、本現象のERROR表示を無くせる。
2>&1をコマンドの末尾に付け、標準エラー出力を標準出力として出力させる。

su ec2-user -c 'sh sample.sh' 2>&1

ちなみに、Automationはデフォルトではrootユーザでコマンドを実行してしまうので、suコマンドでec2-userに実行ユーザをスイッチしている。

Output

INFO:  UNLOAD completed, XXX record(s) unloaded successfully.
UNLOAD

おわりに

ERRORの文字を見て、コマンドが失敗した結果だろうという誤った理解で詰まり、解決まで時間を溶かした、、、
限られた仮説に縛られずに、柔軟に考えてできるだけ速く問題解決できるようになりたい。

unloadが成功しても、「INFO」メッセージが標準エラー出力なのでAutomationのログではERRORが出るという、少しもやもやする現象だが検証はとりあえずできた。