まだプログラマーですが何か?

プログラマーネタとアスリートネタ中心。たまに作成したウェブサービス関連の話も http://twitter.com/dotnsf

タグ:push

IBM Bluemix を使ってアプリ開発を行い、「期待していた通りに動かない・・・ (--;」ということは普通にあると思っています。 そんな時のトラブルシューティングについて、大きく3つの原因パターンに分けて紹介します。


ケースその1 Bluemix 側に問題が発生している
 
何よりもまず最初に調べる必要なのがこれです。Bluemix 側に原因があってうまくいかないのか、自分のコードやアクションに問題があるのか、という切り分けです。

Bluemix のランタイムやサービスが正しく稼働していない場合(あるいはメンテナンス中の場合)、その機能を使ったアプリは当然うまく動かなくなります。そのため、まずは Bluemix の稼働ステータスを確認してください:
https://status.ng.bluemix.net/
2015120104


↑このサイトでデータセンターリージョン毎/ランタイム・サービス毎の稼働状態を確認することができます(近い将来のメンテナンス情報もわかります):
2015120105


おおまかにはこのサイトの情報で充分だと思いますが、認証機能などの内部的な機能レベルでの稼動状態を調べるにはこちらを参照ください:
http://estado.ng.bluemix.net/
2015120107


IBM DevOps Services などの外部サービスを併用して使っている場合は、それらの併用サービスについても確認が必要になります。例えば IBM DevOps Services の稼動状態はこちらで確認できます:
http://status.hub.jazz.net/
2015120106


これら上記4つの URL はブックマークしておくことをおすすめします。


ケースその2 プッシュ(デプロイ)できない

Bluemix 側に特に異常がないにもかかわらず、自分の作ったアプリケーションコードのプッシュ(デプロイ)に失敗する場合は、コードや設定ファイルの内容そのものに間違いが含まれている可能性を疑う必要があります。

例えば cf ツールを使って push したらこんな感じでエラーが発生することがあります:
> cf push appname1
Updating app appname1 in org dotnsf@jp.ibm.com / space dev as dotnsf@jp.ibm.com...
OK

Uploading appname1...
Uploading app files from: C:\tmp\appname1
Uploading 15.9K, 13 files
Done uploading
OK

Stopping app appname1 in org dotnsf@jp.ibm.com / space dev as dotnsf@jp.ibm.com...
OK

Starting app appname1 in org dotnsf@jp.ibm.com / space dev as dotnsf@jp.ibm.com...
-----> Downloaded app package (12K)
-----> Downloaded app buildpack cache (3.9M)


-------> Buildpack version 4.1.5


Traceback (most recent call last):
     :
     :
(中略)
: : ValueError: Expecting object: line 1 column 1 (char 0) Staging failed: Buildpack compilation step failed FAILED BuildpackCompileFailed TIP: use 'cf logs appname1 --recent' for more information

エラーが出てプッシュが FAILED になってしまいました。さてどうしましょう?

このようなケースではプッシュ時のログを参照するのがいいです。その方法は上記の最後に書かれているように、cf logs コマンドに "--recent" オプションを付けて実行することで(直近のログを)確認できます:
> cf logs appname1 --recent
      :
      :
      :
2015-12-01T09:53:08.75+0900 [STG/0]      OUT Downloaded [file:///var/vcap/data/d
ea_next/admin_buildpacks/ee88f28c-4afb-47c3-bc0f-db9ddc1ebb1d_6cbec4f53c789b674b
c4f011895cfb0f72c4d3e0/dependencies/https___pivotal-buildpacks.s3.amazonaws.com_
php_binaries_trusty_composer_1.0.0-alpha10_composer.phar] to [/tmp]
2015-12-01T09:53:08.76+0900 [STG/0]      OUT PROTIP: Include a `composer.lock` file with your application! This will make sure the exact same version of dependencies are used when you deploy to CloudFoundry.
2015-12-01T09:53:08.90+0900 [STG/0]      ERR Loading composer repositories with package information
2015-12-01T09:53:09.51+0900 [STG/0]      ERR Installing dependencies
2015-12-01T09:53:15.05+0900 [STG/0]      ERR Nothing to install or update
2015-12-01T09:53:15.05+0900 [STG/0]      ERR Generating autoload files
      :
      :
      :

この例だと composer の処理の中でエラーが発生しているようなメッセージが出力されていました。とすると、composer.json に間違いがあったのかな・・・と思って実際の composer.json ファイルを確認したらこんな内容でした:
{

閉じなければいけない大カッコが閉じられていませんでした。ケアレスミス! これが原因ですね。最後に "}" を追加してプッシュし直した所、エラーはなくなりました。これはあくまで一例ですが、プッシュ時のエラーに対してはプッシュ時のログを確認する、という対応が解決への近道になります。


ケースその3 プッシュしたアプリが正しく動かない

アプリケーションのプッシュ(デプロイ)には成功して、つまり Bluemix 上でアプリケーションが動いている状態になっていて、その上でアプリケーションが期待していたように動かない、ということがあります。コーディング内容と状態にもよりますが、画面にエラーが表示されたり、されなかったりします。

こんな時は(Bluemix 環境だけのトラブルシューティングではありませんが)稼働中のアプリケーションのログを見るのが第一です。Bluemix の場合はダッシュボードの「ログ」を選択すると、アプリケーションの全ログを参照することができます:
2015120101


ログが大量に出力されている場合はその TYPE や CHANNEL(標準出力/標準エラー)ごとに選別して絞り込むこともできます:
2015120102


この例であれば、明らかな PHP エラーが出力されていることがわかるような行がありました。これをヒントに該当のソースコードを見なおして、何が原因だったのか?を推測して修正する、ということが可能になります:
2015120103


この例の場合であれば up.php の 5 ~ 8 行目でまとめてエラーが出ていた、ということがわかります。ソースコードのこの辺りに原因が・・・という推測ができるわけです。後はソースコードを見て判断、ということになりますね。


以上をまとめると、Bluemix アプリケーション開発時のトラブルシューティングとしては以下のようになります:
1. Bluemix 側の異常ではないかを切り分け
2. プッシュ時のエラーはプッシュログを確認
3. プッシュ成功後のアプリケーション稼働時の問題はアプリケーションログを確認




 

IBM Bluemix 環境に cf ツールでアプリケーションを push した後にログが表示されますが・・・
2015021601



このログを詳しく調べて、「コマンド実行後に何をやっているのか?」の説明をします。

なお、今回の説明内容の前提として、2015/02/16 時点の、Liberty Java アプリケーション(war ファイル)1インスタンスをデプロイしています。このアプリケーションでは MySQL をデータストアとしてバインドしています。その条件下でのログを紹介します:

まずログ全文はこんな感じです:
$ cf push dotnsf-20150212 -p GeoImgWeb.war
Updating app dotnsf-20150212 in org (ユーザー名) / space dev as (ユーザー名)...
OK

Uploading dotnsf-20150212...
Uploading app files from: GeoImgWeb.war
Uploading 2.4M, 258 files
Done uploading
OK

Stopping app dotnsf-20150212 in org (ユーザー名) / space dev as (ユーザー名)...
OK

Starting app dotnsf-20150212 in org (ユーザー名) / space dev as (ユーザー名)...
-----> Downloaded app buildpack cache (224K)
-----> Retrieving IBM 1.7.1_sr2fp1ifx-20141220 JRE (ibm-java-jre-7.1-2.1-pxa6470
_27sr2fp1ifx-20141220_02-sfj.tgz) ... (0.0s)
         Expanding JRE to .java ... (0.8s)
-----> Retrieving App Management Agent 2015.02.04_102631 (com.ibm.ws.cloudoe.app
-mgmt-proxy-agent.zip) ... (0.0s)
         Expanding App Management to .app-management (0.0s)
-----> Downloading and installing client jar(s) from https://download.run.pivota
l.io/mariadb-jdbc/mariadb-jdbc-1.1.8.jar (0.0s)
-----> Auto-configuration is creating config for service instance 'mysql-x3' of
type 'mysql'
-----> Liberty buildpack is done creating the droplet



-----> Uploading droplet (116M)

0 of 1 instances running, 1 starting
1 of 1 instances running

App started


OK

App dotnsf-20150212 was started using this command `.liberty/initial_startup.rb`


Showing health and status for app dotnsf-20150212 in org (ユーザー名) / spa
ce dev as (ユーザー名)...
OK

requested state: started
instances: 1/1
usage: 512M x 1 instances
urls: dotnsf-20150212.eu-gb.mybluemix.net
package uploaded: Mon Feb 16 01:15:44 +0000 2015

     state     since                    cpu    memory           disk
#0   running   2015-02-16 10:16:46 AM   2.8%   149.4M of 512M   182M of 1G

$ 

まず、push コマンド:
$ cf push dotnsf-20150212 -p GeoImgWeb.war

で「dotnsf-20150212 という Bluemix アプリケーションに、GeoImgWeb.war という Java アプリケーションをデプロイする」という命令をしています。この GeoImgWeb.war はカレントディレクトリに存在しているものとします。

その直後のログは以下のようになっています:
Updating app dotnsf-20150212 in org (ユーザー名) / space dev as (ユーザー名)...
OK

Uploading dotnsf-20150212...
Uploading app files from: GeoImgWeb.war
Uploading 2.4M, 258 files
Done uploading
OK

Stopping app dotnsf-20150212 in org (ユーザー名) / space dev as (ユーザー名)...
OK

デプロイ先のアプリケーションを更新するため、GeoImgWeb.war をアップロードして、そして dotnsf-20150212 を一旦停止しています。ここまではまあ一般的というか、Bluemix / Cloud Foundry 環境に特化した内容ではないのでわかりやすいと思います。

この後から少し特殊な処理になります:
Starting app dotnsf-20150212 in org (ユーザー名) / space dev as (ユーザー名)...
-----> Downloaded app buildpack cache (224K)
-----> Retrieving IBM 1.7.1_sr2fp1ifx-20141220 JRE (ibm-java-jre-7.1-2.1-pxa6470
_27sr2fp1ifx-20141220_02-sfj.tgz) ... (0.0s)
         Expanding JRE to .java ... (0.8s)
-----> Retrieving App Management Agent 2015.02.04_102631 (com.ibm.ws.cloudoe.app
-mgmt-proxy-agent.zip) ... (0.0s)
         Expanding App Management to .app-management (0.0s)
-----> Downloading and installing client jar(s) from https://download.run.pivota
l.io/mariadb-jdbc/mariadb-jdbc-1.1.8.jar (0.0s)
-----> Auto-configuration is creating config for service instance 'mysql-x3' of
type 'mysql'
-----> Liberty buildpack is done creating the droplet

dotnsf-20150212 を起動する処理の中身です。Java アプリケーションとしての基板となる Liberty Buildpack をダウンロードし、IBM Java 1.7.1 & App Management Agent & MariaDB JDBC 1.1.8 を続けてビルド(実際にはダウンロード)しています。これらはビルドパック内で定義されている処理です。これで droplet と呼ばれる実行可能なアプリケーションが作成されます。

その後、作成した droplet をアップロードしてアプリケーションインスタンスを起動します。ここでちょっと時間がかかります:
-----> Uploading droplet (116M)

0 of 1 instances running, 1 starting
1 of 1 instances running

App started

OK

実はここまでの段階でアプリケーションとしては利用可能になっています。最後にアプリケーションやサーバーリソースの状態を確認するためのコマンドが実行され、その結果が表示されています:
App dotnsf-20150212 was started using this command `.liberty/initial_startup.rb`


Showing health and status for app dotnsf-20150212 in org (ユーザー名) / spa
ce dev as (ユーザー名)...
OK

requested state: started
instances: 1/1
usage: 512M x 1 instances
urls: dotnsf-20150212.eu-gb.mybluemix.net
package uploaded: Mon Feb 16 01:15:44 +0000 2015

     state     since                    cpu    memory           disk
#0   running   2015-02-16 10:16:46 AM   2.8%   149.4M of 512M   182M of 1G

CPU やメモリ、ディスクリソースの状態と合わせてアプリケーションの状態が最後に表示されています。この例ではサーバーは1インスタンスなので1行だけで表示されていますが、複数インスタンスで起動している場合は複数行の結果になります。



 

このページのトップヘ