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

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

タグ:error

まだ同期/非同期処理の違いに戸惑いながら Node.js を使っています。で、先日こんな実行時エラーに遭遇しました:
  :
  :
events.js:141 throw er; // Unhandled 'error' event ^ Error: EMFILE: too many open files, open '/home/kkimura/XXX/images/*****.jpg` at Error (native)

その時のコード(抜粋)がこちらです:
var fs = require( 'fs' );
fs.readdir( './images', function( err, files ){  // ./images/ フォルダを開く
  if( err ) throw err;
  
  files.forEach( function( jpgfile ){  // ./images/ フォルダの全ファイルを1つずつ取り出して、、、
          :
    (各ファイルに対する処理)
          :
  });
});

現在のディレクトリから、fs モジュールを使って images/ サブフォルダの中にある画像ファイル全てを取り出して、各ファイルに対して何らかの処理をする・・・という、よくあるとまで言えるかどうかはわかりませんが、ごく普通の内容だと思います。この処理中に上記のエラーが発生しました。エラーそのものもネイティブコードの中で発生しているので、どの画像ファイルを読み込んでいる時のエラーかはわかるのですが、何が原因のエラーなのかのヒントはほとんどありませんでした(結論としては画像ファイル側の問題ではないので、どの画像ファイルであったかは解決の上ではあまり重要な情報ではありませんでした)。

が、エラーメッセージそのものから原因はなんとなく推測できました。

まず、この処理は特定のフォルダ(./images)の中にある全てのファイルを取り出し、forEach() ループで各ファイル毎になんらかの処理をする、というものです。そしてエラーメッセージは "Too many open files(ファイルを開きすぎている)"。 実際、このフォルダ内には非常に多くのファイルが存在していたのですが、それらを同時に開きすぎて、処理の限界を超えてしまった、というエラーが発生していたようです。

というわけで原因はなんとなくわかりました。しかし本当の問題はここから。


Node.js(JavaScript) は非同期に処理を実行します。つまり上記のようなケースでは「ファイルを1つずつ開いて処理をして、終わったら閉じて次へ」ではなく、「同時に(非同期に)全ファイルを開いて、同時に(非同期に)全ファイルに処理を施して・・・」という形で実行されます。そしてその際に多くのファイルを開きすぎて "Too many open files" というエラーが発生していたのでした。このエラーは多くのファイルが保管されているディレクトリへの処理を非同期に実行する以上は解決しにくい問題のように思えますが、さてどうする・・・


これ、自分以外でも悩んでいる人が多かったらしく、StackOverflow などでも議論(後述)されていました。結果的には fs ライブラリそのものを改良したものを使う、という方法が紹介されていました。その改良モジュール(graceful-fs)はこちら:
https://github.com/isaacs/node-graceful-fs

この graceful-fs は fs の代わりに使うことができ、かつ "Too many open files" エラー時に発生する EMFILE イベントを検知したら、少し待ってからやり直し処理を行う(という方法でエラーを回避しながら全ファイルを処理する)、という処理が実装されたもののようです。

graceful-fs モジュールを使うには、まず npm 等でインストールを行います:
$ npm install graceful-fs

そしてコードを書き換えます。といっても require( 'fs' ) を require( 'graceful-fs' ) にするだけで、他は変更なしでそのままエラーもなく動きました:
var fs = require( 'graceful-fs' );
fs.readdir( './images', function( err, files ){
  if( err ) throw err;
  
  files.forEach( function( jpgfile ){
          :
    (jpgfile に対する処理)
          :
  });
});


それにしても同期/非同期処理の頭を素早く切り替え出来るのって、それだけで才能ではないかと思う。。。


(参考)
http://stackoverflow.com/questions/8965606/node-and-error-emfile-too-many-open-files

とある REST API を使っていて気付いたこと/考えさせられたことをまとめてみました。明快な結論や提案があるわけではなく、グダグダに感じられる内容かもしれないので、あらかじめご了承ください。


そのとある REST API を使ったウェブアプリケーションを作って運用している中で、おかしな挙動に気付くことがありました。以前は問題なく動いていたのに、あるタイミングで実行すると期待通りに動かない、という「まあまあよくある」ケースです。自分のケースでは動かないというよりも、タイムアウトを起こすような挙動になっていました。ただ REST API そのものが止まっている様子はない、というケースでした。

自分のソースコードでは一応エラーハンドリングはしていたつもりでしたが、REST API がエラーを起こしている様子もなく、原因究明に時間を要するものでした。結論としては自分のアプリケーションコードを見ていてもよく分からず、REST API のユニットテストのようなツールを動かした結果気付くことがありました。

それがこちら:
20170207


・・・わかるでしょうか? REST API を実行したレスポンス本文が Response Body に、ステータスコードが Response Code に記述されています。これによるとレスポンス本文は
{
  "status": "ERROR",
  "statusInfo": "daily-transaction-limit-exceeded"
}

となっていて、"daily-transaction-limit-exceeded" が原因のエラーが発生している、という内容でした。この API には Daily Transaction Limit(1日で使える回数の上限)が決められていて、その上限に達したのでもう実行できない、という内容です。これに関してはそういう条件で使っている API なので、なるほど、エラーの原因はわかりました。

問題はこの REST API を実行したステータスコードが 200 になっている点です。HTTP ステータスコードの分類とその意味についてはウィキペディアなどを参照していただきたいのですが、簡単にいうとこんな感じで分類されています:
コード意味考えられる原因など
2xx(200番台)成功 -
4xx(400番台)クライアントエラー認証が必要、アクセス権がない、URLが間違っている、タイムアウト、、、
5xx(500番台)サーバーエラーアプリケーションエラー、不正なゲートウェイが利用されている、、、


200 番台は成功。400 番台と 500 番台がエラーで、それぞれクライアント側のエラーなのか、サーバー側のエラーなのかを分類しています。

で、今回のケースですが、実行結果はエラーなのに 200 番のステータスコードが返されているのでした。自分のプログラムコードの中では「200 が返ってきたら成功」と決めつけて実装していたため、このようなケースに対処できていなかったのでした。


ここまでが実際に目の当たりにしたエラーとその原因でした。以下はこの件に関して自分が考えたことです。


自分を弁護する意味で「えー、でもそれっておかしくない? エラーなんだからスタータスコードは 400 番台なり 500 番台で返ってくるべきでは?」という考えもないわけではありません。ただ今回のケースではこれも難しいような、つまり 200 番のステータスコードがあながち間違ってはいないような気もしています。

その理由として、まず「これはクライアントエラーなのか?それともサーバーエラーなのか?どちらかに分類できるのか?」という問題です。これに関してはどちらとも言えるし、どちらとも言えないと思っています。

実は 402 番のステータスコードは "Payment Required" 、つまり(お金を払わないといけないんだけど)払ってないエラー、と定義されています。が、実際には定義だけで実装されていない、つまり将来のための定義とされているのでした。また厳密には支払い契約を結んで使っているわけではなく、「この条件で1日○○回使える」というルールの下で利用しているだけなので、402 番に(クライアントエラーに)該当するエラーであるとは考えにくいのです。

※本来の意味とは違いますが、「権限がない」に該当するのではないかと言われると、まあ・・・ という考え方もあるとは思います。ただそれをクライアントエラーとして返してもクライアント側はどうにもできないので、やはり 400 番台エラーには該当しないと思います。

ではサーバーエラーなのか?というと、これも該当しないと思います。プログラミングにミスがあったわけではなく、「実行したら、『実行できない』という結果が返ってきた」のは、正しく実行された(結果が期待通りではなかった)とも言えます。そう考えると、そもそも今回の件は REST API レベルではエラーですらないとも言えます。


そう考えると、今のように API を組み合わせてアプリケーションを作ることが珍しくない環境においては、200 番のステータスコードが返ってきてもエラーの可能性を疑ってコーディングする必要があるのかも、と思うようになりました。このケースであれば実装側が工夫すれば(というか、そもそもちゃんと色んなケースを想定してエラーハンドリングしていれば)防げるものです。

そういう意味でもいい反省の機会でした。 でも今後は同様のケースを想定した「成功でもエラーでもないステータス」が出て来る可能性もありますよね。。


Node.js を使っていると、たまにこんなエラーメッセージが出てサーバーが止まることがあります:
# node .
  :
  :

FATAL ERROR: JS Allocation failed - process out of memory
Aborted (core dumped)

"out of memory" と書かれているのでメモリ不足な状態になっているように見えます。が、これは物理メモリが足りないというメッセージではなく、Node.js の(1オブジェクトあたりの)ヒープサイズが足りなくなっている、というメッセージです。ちなみにデフォルトでは 512MB です。なので物理メモリを大量に搭載しているサーバーでも、サイズの巨大なファイルを扱ったり、大容量のアウトプットデータを取り扱おうとするとこのエラーは起こりうる、ということになります。

このヒープサイズを増やして利用するには node の実行時にパラメータを指定することで可能です。以下の例では 2048MB(=2GB) を指定しています:
# node --max-old-space-size=2048 .
  :
  :

あくまで「Node.js のヒープサイズ」の指定なので、他に使うサーバーアプリとの兼ね合いやスワップも含めた物理メモリサイズも含めて指定サイズを見積もる必要があります。


(参考)
http://stackoverflow.com/questions/29442965/fatal-error-js-allocation-failed-process-out-of-memory-aborted-core-dumped 


先日、マンホールマップのログイン機能に障害が発生しました:

通常、マンホールマップ(PC版)のトップページにアクセスすると、画面右上には "Login with Twitter" マークが表示されます(未ログインの場合):
2015122801


で、ここをクリックして、Twitter の OAuth 認可によってマンホールマップにログインして・・・という流れでログインするのですが、ここに問題が発生していると「現在、何らかの障害によってログインできません。」というメッセージが表示されます:
2015122802


一般的には Twitter API の障害が発生していることを示すメッセージなのですが、先日マンホールマップで発生していたものは Twitter API には障害が発生していないにも関わらず、上記のようなメッセージが表示されていたのでした。 ちなみに Twitter API の稼動状態はこちらで確認できます:
API Status | Twitter Developers


さて、上記の原因はなんだったのでしょうか? ちなみにマンホールマップは Java で開発された Web アプリケーションで、この Twitter の OAuth 認可の部分は Twitter4J を使って実装しています(最新版の 4.0.4 でも、スナップショット版の 4.0.5 でも再現)。で、問題部分のコードは以下のようになっていました:
String authorizationURL = null;
try{
  Twitter twitter = new TwitterFactory().getInstance();
  twitter.setOAuthConsumer( TWITTER_CONSUMER_KEY, TWITTER_CONSUMER_SECRET );
  RequestToken requestToken = twitter.getOAuthRequestToken();  ←ここで Exception 発生

  String token = requestToken.getToken();
  String tokenSecret = requestToken.getTokenSecret();
    :
    :
}catch( Exception e ){
  e.printStackTrace();
}

リクエストトークンを取得するための Twitter.getOAuthRequestToken() メソッド実行時に Exception が発生していました。それまでに設定しているのは Twitter API の Consumer Key と Consumer Secret だけで、これは正しい値が設定できていました(というか、正しく動いていた時から何も変えてません)。 で、その下の catch 内で以下のようなスタックトレースが出力されていました:
Invalid signature on ECDH server key exchange message
Relevant discussions can be found on the Internet at:
        http://www.google.co.jp/search?q=3cc69290 or
        http://www.google.co.jp/search?q=45a986b4
TwitterException{exceptionCode=[3cc69290-45a986b4 3cc69290-45a9868a], statusCode=-1, message=null, code=-1, retryAfter=-1, rateLimitStatus=null, version=4.0.5-SNAPSHOT(build: 9b7efa6faa540a9defb3e6ba9122a356155986b1)}
        at twitter4j.HttpClientImpl.handleRequest(HttpClientImpl.java:179)
        at twitter4j.HttpClientBase.request(HttpClientBase.java:57)
        at twitter4j.HttpClientBase.post(HttpClientBase.java:86)
        at twitter4j.auth.OAuthAuthorization.getOAuthRequestToken(OAuthAuthorization.java:115)
        at twitter4j.auth.OAuthAuthorization.getOAuthRequestToken(OAuthAuthorization.java:92)
        at twitter4j.TwitterBaseImpl.getOAuthRequestToken(TwitterBaseImpl.java:292)
        at twitter4j.TwitterBaseImpl.getOAuthRequestToken(TwitterBaseImpl.java:287)
        at me.juge.geoimgweb.AppInfo.GetAuthorizationURLTwitter(AppInfo.java:361)
        at me.juge.geoimgweb.AppInfo.GetAuthorizationURL(AppInfo.java:350)
        at org.apache.jsp.stats_jsp._jspService(stats_jsp.java:928)
        at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
        at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:377)
        at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:313)
        at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:260)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at filters.SetCharacterEncodingFilter.doFilter(SetCharacterEncodingFilter.java:122)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:857)
        at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:588)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
        at java.lang.Thread.run(Thread.java:745)
Caused by: javax.net.ssl.SSLKeyException: Invalid signature on ECDH server key exchange message
        at sun.security.ssl.HandshakeMessage$ECDH_ServerKeyExchange.(HandshakeMessage.java:1098)
        at sun.security.ssl.ClientHandshaker.processMessage(ClientHandshaker.java:278)
        at sun.security.ssl.Handshaker.processLoop(Handshaker.java:913)
        at sun.security.ssl.Handshaker.process_record(Handshaker.java:849)
        at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:1035)
        at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1344)
        at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1371)
        at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1355)
        at sun.net.www.protocol.https.HttpsClient.afterConnect(HttpsClient.java:559)
        at sun.net.www.protocol.https.AbstractDelegateHttpsURLConnection.connect(AbstractDelegateHttpsURLConnection.java:185)
        at sun.net.www.protocol.http.HttpURLConnection.getOutputStream(HttpURLConnection.java:1093)
        at sun.net.www.protocol.https.HttpsURLConnectionImpl.getOutputStream(HttpsURLConnectionImpl.java:250)
        at twitter4j.HttpClientImpl.handleRequest(HttpClientImpl.java:137)
        ... 30 more


問題の getRequestOAuthToken() を実行した時に "Invalid signature on ECDH server key exchange message" というエラーメッセージが出力されています。何コレ?"Invalid signature" って言われても、この時点ではこちらは Key と Secret 以外何も指定してないので間違えているとは思えないけど・・・??

しつこいようですが、今までは何の問題もなく動いていたコードが、ある時を境に急にこのような挙動になってしまいました。となると、Java ソースコードに直接の原因があるとは考えにくい・・・


しかもこの問題、何が厄介かというと、デバッグしようとしてローカルの Eclipse 内で動かすと、このエラーも Exception も発生しないのです。ちゃんと動いてしまいます。更に言うと、別のサーバー内に同様の Java + Tomcat 環境を作って、同じ war をデプロイして実行しても発生しない。要はこの本番サーバーだけで発生するエラーだったのです。。 となると環境依存か、原因特定は更に厄介だぞ・・・

とりあえず緊急でサーバーを1つ作り、そちらに Java と Tomcat を導入し、アプリの war をデプロイ、したら動きました。なので、応急処置としてはこれでなんとかなります。この応急処置サーバーで運用を続けながら原因追求と解決を続けます。 ああ、クラウドってこういう時に便利なのね。。。


さて、このエラーメッセージをググってみると分かるのですが、SSL 関連の Exception のようなのです。はて、マンホールマップに SSL 関連モジュールなんか使ってたっけ?? 何よりも仮に使っていたとしても、実行コードは Twitter4J の中だし、指定しているのは Key と Secret だけで変えようがないし、他のサーバー環境だと動いちゃうし・・・ 念のため API Key と Secret を新たに取得し直して見ましたが、状況は変わりませんでした。


次に行ったのは JDK と Tomcat のアンインストール、および再インストールです。環境は CentOS だったので、 JDK のアンインストールは以下の手順で行いました:
# yum list installed | grep jdk  (インストール済み JDK を確認)
java-1.7.0-openjdk.x86_64
java-1.7.0-openjdk-devel.x86_64
jdk.x86_64              2000:1.7.0_79-fcs (候補は3つ、全部削除してもよいと判断)

# yum remove java-1.7.0* (上2つをアンインストール)
# yum remove jdk* (一番下をアンインストール)

同様にして、Tomcat も以下の手順でアンインストールしました:
# yum list installed | grep tomcat (インストール済み tomcat を確認)
tomcat6.x86_64          6.0.24-90.el6   @base
tomcat6-admin-webapps.x86_64
tomcat6-el-2.1-api.x86_64
tomcat6-jsp-2.1-api.x86_64
tomcat6-lib.x86_64      6.0.24-90.el6   @base
tomcat6-servlet-2.5-api.x86_64 (候補は6つ、全部削除してよいと判断)

# yum remove tomcat6* (まとめてアンインストール)

でもってそれぞれを再インストールします:
# yum install java-1.7.0-openjdk-devel
# yum install tomcat6 tomcat6-admin-webapps

これで Java と Java アプリケーションサーバーはまっさらな状態に戻りました。この状態でマンホールマップの JAR をインストールしてアクセスしたところ・・・ 何も変わらない・・・ orz


全く原因が思いつきません。いよいよヤバい。 改めてこの ECDH なるものを調べてみると暗号化のアルゴリズムっぽいようでした:
ECDH アルゴリズムの概要

暗号化アルゴリズムの、鍵の交換の所で(しかも今まで動いていたものが、ある時から)動かなくなった、ということになります。いよいよ OS レベルの中身がぶっ壊れてしまったか?? と思ったのですが、最後の希望を託してインストールした全ライブラリを更新してみることにしました:
# yum update -y
  :
  :
  :

# /etc/init.d/tomcat6 restart

で、Tomcat をリスタートしてアクセスしてみたら・・・ 直りました! 助かった!!
2015122901
 ↑直ったのはついさっき


後は緊急運用サーバーからこちらに切り替えれば対処完了(予定)。 結局「これ」という直接の原因は分からなかったけど、古いライブラリでは対応しない機能を使っていた、ということなんでしょうかね~。

自分が作って運用しているウェブサービスの多くはクラウド上で動いてますが、このマンホールマップに関しては自宅サーバーで(更に言えば ThinkPad で)運用することにまだこだわっています。今回のエラーはその信念を揺るがすものでしたが、とりあえず解決できました。もうしばらく自宅サーバー運用を続けることができそうです。 v(^o^)



アプリケーションサーバーに PHP を使い、データベースサーバーに MySQL を使っている多くのケースで phpMyAdmin が同時にインストールされているのではないかと思っています。自分もその条件で使うサーバーがあったので phpMyAdmin をインストールして、いざアクセス! しようとしたら「MySQL を 5.5.0 以降にアップグレードしてください」というエラーメッセージに遭遇しました:
2015030501


これは phpMyAdmin のバージョン 4.2 以降では PHP 5.3 以上、MySQL 5.5 以上が動作要件になっていたのでした。CentOS6 の yum でデフォルトインストールされる MySQL は MySQL 5.1 なので、このエラーメッセージが表示されたものだと思います:
2015030502



で、これを回避するには MySQL のバージョンを上げるしかないか・・・ ということはありません。動作要件の MySQL が 5.1 でもよかった頃の phpMyAdmin バージョンを使う、という手もあります。具体的には phpMyAdmin 4.0.X 系は PHP 5.1 以上&MySQL 5 以上が動作要件なので、この最新版をダウンロードし、これをセットアップして使うという方法でも回避できます:
2015030503


phpMyAdmin 4.0.10.8 をダウンロード&セットアップして、PHP と MySQL はそのままで phpMyAdmin にアクセスすると、無事に phpMyAdmin のトップページが表示されました:
2015030504

MySQL ではなく MariaDB の場合も、対応する MySQL のバージョンによっては同じエラーになると思います。お気をつけて。



 

このページのトップヘ