none
IIS7 で 特定のコードで極稀に応答が返ってこない RRS feed

  • 質問

  • ◆サーバ情報

    OS: Windows Server 2008 Std SP2 (R2ではない)

    IIS:IIS7.0

    ◆現象の概要

    C#でコードを組んでいるWebアプリケーションで、応答が返ってこないケースがあります。

    コードはざっくり↓の感じです。

    -----------------------------------------------------------------------

    using System;

    using System.Reflection;

    ~(中略)

    using AAA;

    ~(中略)

    #AAAの中のBBBのインスタンスを名前:CCCで作成

    this.CCC = new BBB

    #CCC内のDDD処理を実行

    ## DDD実行前デバッグログ書き込み

    Writelog(DDD実行前)

    ## DDD実行

    if ( !this.CCC.DDD )

    {

       Writelog (DDDエラー)

    }

    ## DDD実行後デバッグログ書き込み

    Writelog(DDD実行後)

    -----------------------------------------------------------------------

    これで、DDDの処理実行直前(if文前)のログが書かれたあとの処理がログに残りません。

    正月以外はほぼ毎日100回以上はこのコードを通るのですが、この現象が発生したのは約3年ぶりとなります。

    ◆解析にあたって質問したいこと

    当時(3年前)、再発時にはプロセスダンプを取って解析しようということで落ち着き、今回発生したためダンプを取りました。

    →ダンプの取得手順・・・タスクマネージャから w3wpのダンプ作成を実施、

    →解析手順・・・、windbg でk コマンドでコールスタックを見ましたが、作成したdllの名前は出力結果に見当たりませんでした。

    ダンプ取得手順が悪いのか、解析手順が悪いのか、或いはダンプを取るタイミング(事象が確認されてから1時間後)が悪いのか。

    何が考えられますでしょうか。

    思い当たることがあれば教えて頂きたく、よろしくお願いいたします。

    2016年5月10日 10:17

すべての返信

  • 「C#でコードを組んでいるWebアプリケーション」というのは具体的に何ですか? 何をどのように動かしているのですか? if ( !this.CCC.DDD ) がどのようなときに true になるのですか? 少なくとも自分にはさっぱり分からないのですが・・・
    2016年5月10日 10:31
  • すでにワーカープロセスが再起動していたり、処理が中断されていた場合はダンプをとっても何も出てこないことになります。

    1時間だと遅すぎた可能性が高い気がします。

    ※基本的にExecutionTimeoutなどでタイムアウトすると、アンマネージコード中以外では処理が中断されますし(ただこの場合はアプリケーションでエラーログは出せる場合が多いですが)

    イベントログに、ワーカープロセスの再起動などの情報は出ているかもしれません。

    ただいずれにしても再現しない状態では、これから調査というのは難しい感じがします。

    ちなみに件のライブラリ?は、アンマネージ処理などをやっていますか?

    2016年5月10日 11:02
  • SurferOnWww様

    ご返信ありがとうございます。

    私の知識が不十分で、IIS+ASP.NET環境下でアプリケーションが動いている、というざっくりしたことしかわかっておらず、

    とんちんかんな質問になっていたようです。

    >C#でコードを組んでいるWebアプリケーション」というのは具体的に何ですか? 何をどのように動かしているのですか?

    私がわかるのは、IISでwebサイトの下に仮想ディレクトリを作成し、

    仮想ディレクトリ下にservice.asmxファイルとweb.configファイル、binフォルダを配置、
    binフォルダ下にはdll群を置いている。ということくらいです。

    正しい用語でどうお伝えすればよいか今時点ではお答えできません。

    (近くにいた開発者に聞いてみましたが、言葉に悩んでいました)


    >if ( !this.CCC.DDD ) がどのようなときに true になるのですか

    これはベンダー提供のDLLのクラスで、とある通信を行う処理の初期化処理です。

    この初期化処理の後、通信のためのパラメータをセットするコードが続くので、各変数等の宣言を行う処理ではないかと思います。

    処理の詳細は開示されておらず、これもそこまでしかわかっていません。

    2016年5月10日 11:10
  • > IIS+ASP.NET環境下でアプリケーションが動いている、というざっくりしたことしかわかっておらず、

    質問者さんの方でも「ざっくりしたこと」しかわからないということですと、この掲示板に書いてある情報が全ての第三者にとってはもっと分からないので、FAQ 的な(よくある問題・質問的な)ことでない限り答えを得るのは難しいと思います。

    今提供されている情報で自分が分かるのは、「サードパーティ製の .dll を使って ASP.NET で Web サービスを提供するサイトを運用していて、極稀に応答が返ってこないという問題が 3 年ぶりに起こったが、ログを調べても原因がわからない」ということぐらいです。

    Web サーバーに問題があるのか、通信経路に問題があるのか、クライアント側のアプリケーションに問題があるのかの切り分けは済んでいるのでしょうか? その上で Web サーバーに問題があるという結論になって、Web サーバーのログを調べているのですか?

    2016年5月10日 11:32
  • なちゃ様

    ご返信ありがとうございます。

    ワーカープロセスのリサイクルは全てイベントログに記録するよう、アプリケーションプールで設定していますが、リサイクルのイベントはありませんでした。

    Execution timeoutは忘れていましたが、それらを超えている可能性はありますね。

    独自に作っているフレームワークに設定箇所があるかもなので、そのソースを見てみます。

    #確かに1時間後だと遅すぎた感あります。

    >ちなみに件のライブラリ?は、アンマネージ処理などをやっていますか?

    ベンダー提供のDLLのため、わかりません。
    この現象の調査のために3年前にログを詳細に出力するバージョンのdllをもらったのですが、今回何も記録されていませんでした。

    >ただいずれにしても再現しない状態では、これから調査というのは難しい感じがします

    やはりそうですか。。

    何もわかりませんでしただけでは苦しいので、せめて次回発生時はこうやって調査する、というのがあればいいのですが。

    ロードバランサでサーバを負荷分散させているので、この現象が発生したらそのサーバだけを本番運用環境から切り離したうえで、

    デバッガをアタッチして解析してみる、というのは思いつきましたが、他に考えられますでしょうか。

    2016年5月10日 11:35
  • SurferOnWww様

    ご返信ありがとうございます。

    >Web サーバーに問題があるのか、通信経路に問題があるのか、クライアント側のアプリケーションに問題があるのかの切り分けは済んでいるのでしょうか? その上で Web サーバーに問題があるという結論になって、Web サーバーのログを調べているのですか?

    情報をきちんと提示できていないということがなんとなくわかりました。

    まだ整理できていないのですが、少なくともWebサーバーでの問題というところまでは切り分けはできていると思います。

    クローズドな環境(社内)で運用されているシステムで、クライアントもブラウザではなく専用画面があるもので、クライアント側の問題ではありません。

    また、通信経路についてですが、if ( !this.CCC.DDD ) の処理で通信が発生していないことはパケットキャプチャして(wiresharkで)確認しましたのでこれも間違いないかと思います。

    2016年5月10日 12:07
  • まとめると以下のような状況でしょうか? 違っていたら書き直してください。

    (1) とある通信を行うサードパーティ製の .dll を使って ASP.NET で Web サービスを提供するサイトを運用している。

    (2) 「極稀に応答が返ってこない」という問題が 3 年ぶりに再発した。

    (3) 「応答が返ってこない」というが具体的にどういうことか不明。(← HTTP 200 はもちろん、HTTP 500 なども含めて一切何も返ってこないのですか? 確認してください。何らかのエラーコードは返ってきているのではないかと思うのですが)

    (4) Web サーバーに問題があるのか、通信経路に問題があるのか、クライアント側のアプリケーションに問題があるのかの切り分けは済んでいて、Web サーバーに問題があるという結論になっている。

    (5) Web サービスのメソッドの次のステップでログを書き出すようにコーディングしてある:① サードパーティ製 .dll のクラスからインスタンスを生成した直後、② サードパーティ製 .dll が「とある通信」してエラーになった時、③ 全ての処理が終わった時。

    (6) 応答が返ってこないケースの処理で上記 (5) のログを見ると、① は書き出されているが、② と ③ は書き出されていない。

    (7) コールスタックを見たが作成した .dll の名前は出力結果に見当たらない。(←「とある通信」を行う処理 DDD が呼び出されていないと言っていますか?)

    ここまで書いておいて何ですが、「とある通信」を行う処理 DDD が呼び出されてない原因の見当がつかない自分にはお手上げです。

    呼び出されなければ ExecutionTimeout(デフォルトで 110 秒)に引っかかってサーバーエラーになると思うのですが、もし上記 (3) に書いたように HTTP 500 なども含めて一切何も返ってこないとすると、謎は深まるばかりです。

    お役に立てずすみませんが、もし上記 (1) ~ (7) が違っていたら状況を整理して書き直し、他の方の回答をお待ちいただければと思います。

    2016年5月11日 3:17
  • SurferOnWww様

    ご返信ありがとうございます。

    書き直しました。直したのは(3) と(7) の部分と、(8)にあと書いてなかった情報+個人的な推測を追記しました。

    (1) とある通信を行うサードパーティ製の .dll を使って ASP.NET で Web サービスを提供するサイトを運用している。

    (2) 「極稀に応答が返ってこない」という問題が 3 年ぶりに再発した。

    (3) 「応答が返ってこない」というのは具体的には、

      → WebサーバのIISログにエラーは記録されていない(復旧のためサーバ再起動するまでの全てのステータスは200だった。)

      → WebサーバのイベントログにもIISに関連したエラー、警告等は出ていない。

      →クライアント側の画面(exe)では、configファイルでhttpのタイムアウト(WebServiceTimeout)を30分に設定しているが、webサーバからは何の応答もなく30分待ってタイムアウトエラーとなっている。

    (4) Web サーバーに問題があるのか、通信経路に問題があるのか、クライアント側のアプリケーションに問題があるのかの切り分けは済んでいて、Web サーバーに問題があるという結論になっている。

    (5) Web サービスのメソッドの次のステップでログを書き出すようにコーディングしてある:① サードパーティ製 .dll のクラスからインスタンスを生成した直後、② サードパーティ製 .dll が「とある通信」してエラーになった時、③ 全ての処理が終わった時。

    (6) 応答が返ってこないケースの処理で上記 (5) のログを見ると、① は書き出されているが、② と ③ は書き出されていない。

    (7) コールスタックを見たが作成した .dll の名前は出力結果に見当たらない。

        →現象確認して一時間超経過後に取ったw3wpのダンプ(クラッシュダンプ)から見た限り、「とある通信」を行う処理 DDD が呼び出されていないように見える。

    (8) その他の情報と個人的な推測

     ・Webサーバ3台でロードバランサで負荷分散して運用しているが、今回この現象が発生したのは1台だけ。

     ・その1台では、最初に発生~ダンプを取ってサーバ再起動するまでの約1~2時間の間に、同現象が複数(4回)発生している。但し、そのサーバで同じ時間帯にこのロジックの部分が正常終了しているケースも4回以上ある。なお、このロジック以外のところでは問題は発生していない。

     →ワーカープロセスを8つ構成にしているが、プロセスのうちの1つないし数個が、ハングアップ/フリーズはしていないものの何かがおかしくなったのでは、と個人的に推測。

    SurferOnWww様の仰るとおり、サーバーエラーなど何か出ていればほかに調べようもあったと思うのですが、なんでこういう現象が起きるのか本当に謎で仕方ありません。

    今のとこ、次に発生したときはサーバを本番から切り離してデバッガアタッチしてトレースしてみるか、、という感じになってます。

    どなたか、些細なことでもいいので思いついたことなど助言いただければ幸いです。

    (来年にはWin2012にマイグレーションするので、それで出なくなったら追跡しなくて楽なんですけど、、)

    2016年5月11日 9:31
  • > →ダンプの取得手順・・・タスクマネージャから w3wpのダンプ作成を実施、
    > →解析手順・・・、windbg でk コマンドでコールスタックを見ましたが、
    >   作成したdllの名前は出力結果に見当たりませんでした。
    > ダンプ取得手順が悪いのか、解析手順が悪いのか、
    > 或いはダンプを取るタイミング(事象が確認されてから1時間後)が悪いのか。

    採取したプロセス ダンプ内に、自作 DLL が関連するコール スタックが残っていないからといって、自作 DLL は無関係。。。ということにはならないと思います。
    ダンプ ファイルに記録されるのは、採取した「瞬間」の状態になるので、その直前に自作 DLL 内の処理から抜けて (リターンして) しまった場合、コール スタック情報は残りません。
    該当プロセス内に自作 DLL がロードされている以上、自作 DLL の問題である可能性を排除すべきでないと思います。
    (該当プロセス内に自作 DLL がロードされているかは、シンボルをきちんと合わせた WinDBG 上から、"!peb" コマンドを実行すれば確認出来るはずです。)

    とにかく採取したプロセス ダンプをもう一度詳しく見直し、どこで止まっているのかを、きちんと精査する必要があると思います。
    また、止まっている箇所が他のサービス プロセス等への RPC (Remote Procedure Call) である場合は、関連するプロセスのダンプ状態も確認する必要があります。
    この場合、プロセス ダンプだけでの解析はほぼ不可能なので、「完全メモリ ダンプ」を生成させる設定と、キーボード クラッシュ可能な設定を行い、現象発生時の完全メモリ ダンプを採取し、それの解析が必要になります。

    2016年5月16日 7:40