Product Advertising APIを使って新製品があったらSlackに投稿するみたいなことをやっていましたが、数日前からエラーが発生していました。
エラーの概要は400 Bad Request。
/opt/rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/amazon-ecs-2.4.0/lib/amazon/ecs.rb:141:in `send_request': HTTP Response: 400 Bad Request (Amazon::RequestError)
from /opt/rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/amazon-ecs-2.4.0/lib/amazon/ecs.rb:102:in `item_search'
from amazon_db_insert.rb:106:in `block in getAll'
from /opt/rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/activesupport-4.2.5/lib/active_support/core_ext/range/each.rb:7:in `each'
from /opt/rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/activesupport-4.2.5/lib/active_support/core_ext/range/each.rb:7:in `each_with_time_with_zone'
from amazon_db_insert.rb:105:in `getAll'
from amazon_db_insert.rb:168:in `<main>'
なんでやねん。何も変えていないのにいきなり400 Bad Requestって。いみわからん。意味ワカだよ。
ってことで、重い腰を上げて調べはじめました。
ちなみに環境的には
- Ruby2.2.2
- amazon-ecs(gem)
です。
[調査1] コマンドラインから叩いてみる
このコマンド自体はRubyで作っていて、Jenkinsさんに定期的に叩いてもらっています。なので、とりあえずサーバに直接入って、直接コマンドを叩いてみました。
結果は以下のとおりってことで、特に進展なし。
/opt/rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/amazon-ecs-2.4.0/lib/amazon/ecs.rb:141:in `send_request': HTTP Response: 400 Bad Request (Amazon::RequestError)
from /opt/rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/amazon-ecs-2.4.0/lib/amazon/ecs.rb:102:in `item_search'
from amazon_db_insert.rb:106:in `block in getAll'
from /opt/rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/activesupport-4.2.5/lib/active_support/core_ext/range/each.rb:7:in `each'
from /opt/rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/activesupport-4.2.5/lib/active_support/core_ext/range/each.rb:7:in `each_with_time_with_zone'
from amazon_db_insert.rb:105:in `getAll'
from amazon_db_insert.rb:168:in `<main>'
で、エラーコードの400 Bad Requestが発生する条件が何なのか？がわからなかったので次はこれを調査。
[調査2] AmazonECSで400 Bad Requestはどうやったら発生するのか？
最初、access_keyとかsecret_keyの有効期限が切れたのかな？とも思ったんだけど、そういう認証関連であれば401とか403が返ってくるのが多いので、そこのチェックは後回し。
となると、400はどういう時に返ってくるのか？
400 Bad Requestに関しては、WSDLの形式（と言うかRequestの形式）がおかしい時に返ってくることが多いそうです。
おそらくリクエスト中にあるxmlの形式がおかしくて発生しているのか？ってことで次の調査はこちら。
[調査3] リクエストパラメータを削ったり、gemを更新したり
Amazon側のほうでIFを変えたとかそういう情報は一切見つからなくて、Amazon-ecsのGemのほうでも更新をしたとかそういう情報は見当たらない。
だけど、とりあえずGemが古かったのでgemを更新。
その後実行してみてもやっぱり400 Bad Requestのまま。
う〜ん。わからん。
ってことで調査を中断しようとしたその時・・・・・
パケットキャプチャとかとって、リクエストの形式とか細かく調べようと思ったけどやめました。
状況を整理すると
という状況なので、世の中一般的に何かがあったというよりか、自分のサーバなり内部的な問題により動かなくなっているのではないかという結論に。
で、もう一個別のスクリプトがあるんですが、そっちの調査を先に手を付けるかと思って調べていた時にたどり着いた情報がこれ。
http://www.infoscoop.org/blogjp/2015/03/10/google_invalid_grant/
ふーん。アクセスキーとかってちゃんと時間を見ているんだね〜。それで弾いたりとかするケースがあるのか。と思って、自分のサーバの時間を確認してみると！！
ずれてる！！orz
30分ずれていました。
もしかしてこれか？！これが原因なのか？！と思って時刻を直して再度コマンドを実行してみると・・・・
動いたーーーー！！
なんてことでしょう。これは全然知らなかったわ。時間がおかしくてもBad Requestとして扱われるんだね。すっげー勉強になった。
結論
AmazonECSから400 Bad Requestが返ってきた場合、リクエストの形式がおかしくないのであれば、時間を確認してみる。
400 Bad Requestはリクエスト時刻がおかしいときに返される場合がある。
これは勉強になった。400とか500って本当原因がわからないから困る。
今回のケースで言えば、認証キーも有効だから401を返すことも出来ず、規制をかけているわけではないから403を返すことも出来ず、結果400になっているのかな〜。
サーバの時間、NTPサーバで合わせておいたらこんなことにならなかったのに・・・・。設定しておこう。
