TORIPIYO DIARY

recent events, IoT, programming, security topics

JMXを利用してtomcatのJDBCコネクションプールのトラブルシューティング

セキュリティの勉強のために脆弱性のあるJavaアプリケーションを作ったのですが、スキャナをかけてしばらくするとアプリから応答が返ってこなくなります。この現象は数時間経っても変わらず、コンテナを再起動しないと直りません。
アプリケーションはローカルのdocker環境で動かしていて、

クライアントリクエスト -> apacheコンテナ -> tomcatコンテナ -> mysqlコンテナ

というフローで処理をしています。ちょっと調べてみると、tomcatコンテナまでの処理をするリクエストなら正常に返ってくるのですが、mysqlコンテナと通信する必要がある処理は応答が返ってこないことがわかりました。
ですので、原因はtomcatコンテナかmysqlコンテナにあります。さらに、mysqlコンテナ上でtcpdumpを使ってパケットはtomcatコンテナから届いているのか確認すると、何もパケットが来ていません。ということは、tomcatコンテナが正常にmysqlコンテナに接続リクエストを投げていないことが推測できます。

いろいろと調べると、tomcatコンテナにはデータベース接続プールがあり、この接続プールにあるコネクションが枯渇すると新規のリクエストがデータベースに接続出来なくなるようです。(ちょっと、細かい説明間違っているかもしれません。)ということで、tomcatのデータベースコネクションプールのコネクション数はどれぐらいあるのか確認する方法を調べました。

またまた、いろいろと調べるとJMXを利用するとtomcatのデータベースコネクションプールの様子がわかりそうです。JMXを有効にするために、docker-composeのtomcatコンテナの設定に以下を追加しました。
JMX用のポートをtomcatコンテナの9999ポートにアサインして、ローカルマシンからtomcatコンテナの9999ポートに接続できるようにしています。(ちなみに、-Djava.rmi.server.hostname=127.0.0.1を-Djava.rmi.server.hostname=0.0.0.0とするとうまくJMXに接続出来ず、一時間ぐらい悩みました。)

    image: tomcat:9.0-jre9
    ports:
      - 9999:9999
    environment:
      CATALINA_OPTS: "-Dcom.sun.management.jmxremote
        -Dcom.sun.management.jmxremote.port=9999
        -Dcom.sun.management.jmxremote.rmi.port=9999
        -Dcom.sun.management.jmxremote.ssl=false
        -Dcom.sun.management.jmxremote.authenticate=false
        -Dcom.sun.management.jmxremote.local.only=false
        -Djava.rmi.server.hostname=127.0.0.1"

docker-compose up でコンテナを立ち上げたあとは、ローカルマシンのターミナル上で
jconsole service:jmx:rmi:///jndi/rmi://localhost:9999/jmxrmi
を入力すればjsonsoleが立ち上がります。

使用中のデータベースコネクションの数(numActive)と、待機中のデータベースコネクションの数(numIdle)は、MBeansタブから、
Catalina => DataSource => localhost => /app => javax.sql.DataSource => jdbc_(データベース名) => connections => Attributes
と辿って行くと見つけることが出来ます。

f:id:ha107chan:20180629003839p:plain

スキャナを実行する前は、numActiveは0だったのですが、スキャナを実行してしばらくするとnumActiveは8となって、maxTotalの数8と同じになります。この状態になるとDBに接続処理のリクエストの場合は応答が返ってこなくなりました。データベース接続プールの枯渇が原因の可能性大です。

では、なぜデータベースのコネクションは解放されないのか?ソースコードを見ると、あまりJavaに詳しくないのですがなんとなく原因を特定出来ました。

問題のあるコード

    InitialContext context;
    DataSource ds;
    try {
      context = new InitialContext();
      ds = (DataSource) context.lookup("java:comp/env/xxxx");
      Connection con = ds.getConnection();

      Statement stmt = con.createStatement();
      context.close();

      String query = "select * from items where title like '%" + word + "%';";
      ResultSet result = stmt.executeQuery(query);

      // *** skip *** //

      context.close();
      con.close();

      // *** skip *** //

    } catch (NamingException e) {
      e.printStackTrace();
    } catch (SQLException e) {
      e.printStackTrace();
    }

このアプリはセキュリティの勉強をするために作ったので、わざとSQLインジェクションが起こるように作っています。スキャナは細工したパラメータ値をリクエストで送るので、queryは正しいSQL文にならない可能性もあります。
そうすると、ResultSet result = stmt.executeQuery(query); の時点で例外を吐いて、con.close();の処理が実行されないためにコネクションが解放されていないようでした。そこで、以下のようにSQLの実行時に例外を吐いてもコネクションがcloseされるように修正しました。

修正したコード

    InitialContext context;
    Connection con = null;
    DataSource ds;
    try {
      context = new InitialContext();
      ds = (DataSource) context.lookup("java:comp/env/xxxx");
      con = ds.getConnection();

      Statement stmt = con.createStatement();
      context.close();

      String query = "select * from items where title like '%" + word + "%';";
      ResultSet result = stmt.executeQuery(query);

      // *** skip *** //

    } catch (NamingException e) {
      e.printStackTrace();
    } catch (SQLException e) {
      e.printStackTrace();
    } finally {
      if (con != null){
        try {
          con.close();
        } catch (SQLException e) {
          e.printStackTrace();
        }
        con = null;
      }
    }

たぶん、まだまだ改善できるコードなんだろうなとは思いますが、この修正後、スキャナを実行してしばらくたつと応答が返ってこなくなる現象は無くなり、なんとか問題を解決することが出来ました。