P488
@P488

Are you sure you want to delete the question?

Leaving a resolved question undeleted may help others!

Java Tomcat PostgreSQL 「バックエンドへの送信中に、入出力エラーが起こりました。」について

解決したいこと

JavaTomcatのWebシステムでPostgreSQLへ対してSQLを実行しているのですが、検索開始から5分程度経過すると、「バックエンドへの送信中に、入出力エラーが起こりました。」となり、エラーが発生してしまっています。

上記で実行しているSQLをpsqlコマンドやpgAdmin4で実行したところ、問題無く実行出来たため、JavaorTomcatが原因では無いかと考えています。

解決方法を教えて下さい。

2020/12/22 11:20追記

  1. 実行環境を変えて実行

    試しに、Windows → DB(Docker)で試してみたところ、こちらはエラーが発生しなかった。
    このことから上記エラーは、APP(Docker) → DB(Docker)で実行した場合に発生する。

  2. SQLを変えて実行

    メモリ関連のエラーと分離するため、以下のSQLを試したところ、開始から約5分で上記と同じエラーが発生した。

    select pg_sleep(600);
    

発生している問題・エラー

  • App側のログ
2020-12-21 14:19:06:928,重大,org.postgresql.util.PSQLException: バックエンドへの送信中に、入出力エラーが起こりました。
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:350)
    at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:473)
    at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:393)
    at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:164)
    at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:114)
    ...
Caused by: java.io.EOFException
    at org.postgresql.core.PGStream.receiveChar(PGStream.java:443)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2057)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:323)
    ... 12 more

(以下は別機能で発生していたエラーでした。参考程度に記載しています。)

2020-12-21 14:19:06:975,普通,コネクションを検証しています 
org.postgresql.util.PSQLException: このコネクションは既にクローズされています。
    at org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:885)
    at org.postgresql.jdbc.PgConnection.setNetworkTimeout(PgConnection.java:1610)
    at org.postgresql.jdbc.PgConnection.isValid(PgConnection.java:1436)
    at org.apache.commons.dbcp2.DelegatingConnection.isValid(DelegatingConnection.java:897)
    at org.apache.commons.dbcp2.PoolableConnection.validate(PoolableConnection.java:270)
    at org.apache.commons.dbcp2.PoolableConnectionFactory.validateConnection(PoolableConnectionFactory.java:630)
    at org.apache.commons.dbcp2.PoolableConnectionFactory.validateObject(PoolableConnectionFactory.java:648)
    at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:492)
    at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:363)
    at org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134)
    at org.apache.commons.dbcp2.BasicDataSource.getConnection(BasicDataSource.java:753)
    ...
  • DB側のログ
LOG: could not send data to client: Broken pipe
STATEMENT: {実行SQL}
FATAL: connection to client lost
STATEMENT: {実行SQL}
LOG: database system was interrupted; last known up at 2020-12-21 13:10:24 UTC
LOG: database system was not properly shut down; automatic recovery in progress
LOG: record with zero length at 60/66A6D1D0
LOG: redo is not required
LOG: MultiXact member wraparound protections are now enabled
LOG: database system is ready to accept connections
LOG: autovacuum launcher started
LOG: incomplete startup packet
LOG: incomplete startup packet
LOG: incomplete startup packet
LOG: incomplete startup packet
LOG: incomplete startup packet
LOG: incomplete startup packet
LOG: incomplete startup packet
LOG: incomplete startup packet

該当するソースコード

  • java
private Connection getConnection() throws SQLException {
    Connection connection = DriverManager.getConnection(url);
    return connection;
}

private Object query() {
    try (Connection connection = getConnection();
            PreparedStatement preparedST = connection.prepareStatement(sql);) {
        /*パラメータの設定*/
        preparedST.setLong(1, param);
        ...
        /* クエリーの実行 */
        try (ResultSet rs = preparedST.executeQuery()) {
            /* Result Set から値を取得する */
            ...
        }
    }
}

2020/12/22 11:20追記

切り分けのため、以下のソースで実行したが、こちらもNG

package main;

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.PreparedStatement;
import java.sql.ResultSet;
import java.util.Date;

public class Sample {

    static {
        try {
            Class.forName("org.postgresql.Driver");
        } catch (Exception e) {
            e.printStackTrace();
        }
    }

    public static void main(String[] args) throws Exception {
        System.out.print("START,");
        System.out.println(new Date());
        String url = "jdbc:postgresql://192.168.3.2:5432/sample?currentSchema=user1";
        String user = "user";
        String password = "password";
        String sql = "select pg_sleep(600);";
        try (Connection conn = DriverManager.getConnection(url, user, password);
                PreparedStatement pstmt = conn.prepareStatement(sql);) {
            try (ResultSet rs = pstmt.executeQuery();) {
                System.out.print("OK,");
                System.out.println(new Date());
            }
        } catch (Exception e) {
            System.out.print("ERROR,");
            System.out.println(new Date());
            e.printStackTrace();
        }
        System.out.print("END,");
        System.out.println(new Date());
    }
}

  • SQL
WITH q1 AS (
    SELECT
        *
    FROM
        public.table1 AS t1
    WHERE
        ...
),
q2 AS (
    SELECT
        *
    FROM
        public.table2 AS t2
    WHERE
        (id) IN (
            SELECT DISTINCT
                id
            FROM
                q1
        )
),
q3 AS (
    SELECT
        *
    FROM
        public.table3 AS t3
    WHERE
        ...
)
SELECT DISTINCT
    COUNT(*)
FROM
    q1 AS t1,
    q2 AS t2,
    q3 AS t3
WHERE
    t1.id = t2.id
    AND t2.code = t3.code
    ...

構成

アプリケーション構成

Application Version
Java Eclipse OpenJ9 VM AdoptOpenJDK 11.0.8
Tomcat 9.0.31
PostgreSQL 9.4

システム構成(2020/12/22 11:20追記)

OS Name
host os windows 10
docker host wsl (Ubuntu)
java os Centos7(Docker)
db os Alpine(Docker)

自分で試したこと

  • psqlコマンド → OK
  • pgAdmin4 → OK
  • windows → OK
  • Linux(Docker) → NG
0

1Answer

java.io.EOFExceptionバックエンドへの送信中に、入出力エラーが起こりました。というメッセージから判断するに、SQL実行中に何らかの事情でJDBC Connectionが切断されたのだと思います。そして、その切断されたConnectionを使いまわそうとして、このコネクションは既にクローズされています。が発生しているように見えます。

なので、Connectionが切断された理由を探るのが問題解決の近道だと思うのですが、ここで気になるのは「検索開始から5分程度経過する」と述べられていることで、これは「実行するSQLがスロークエリで、完了までに5分以上かかるが、5分経過するとエラーになってしまう」ということでしょうか? であれば、TomcatやPostgreSQLなどの設定として、statement timeoutのような設定が入っていないかどうか確認できますでしょうか?

また、Javaのスタックトレースを提示していただいており、これはTomcat側のログであるという認識です。つまり、問題が発生した近辺のPostgreSQL側のログを見て、何か手がかりになりそうなものはありますでしょうか?

(すでに解決済みならご放念ください)

0Like

Comments

  1. @P488

    Questioner

    コメントいただき、ありがとうございます。

    エラーの詳細としては、実行するSQLがスロークエリで、完了までに5分以上かかるが、5分経過するとエラーになってしまう」で認識に相違ありません。
    追記した部分で以下のSQLを試したところ、同様にエラーが発生しました。
    select pg_sleep(600);

    また、PostgreSQLのログを追記しましたので、ご確認いただけますと幸いです。
    当方にて確認した感じでは、手掛かりになりそうなログは見られませんでした。
  2. DBログに"could not send data to client: Broken pipe"があること、Tomcatの環境を変えると問題が発生しなくなったことから、DB Connectionを破棄したのはDBMS側ではなく、Tomcat側の設定による可能性が高そうです。

    問題が発生したTomcatと問題が発生しなかったTomcatで、server.xmlやcontext.xmlのような設定ファイルに差はあるでしょうか?

  3. @P488

    Questioner

    ご返信いただき、ありがとうございます。

    Tomcatですが、設定ファイルやバージョンに差はありません。
    また、以下のプログラムをコマンドラインから実行した場合も、上記と同様のエラーが発生しました。
    https://qiita.com/P488/questions/08d13115ec308d8fc8f1#20201222-1120%E8%BF%BD%E8%A8%98-1

    考えられる原因としては、OSの差であると考えています。
    おそらくですが、Linuxの機能で5分以上の通信が切断されている気がしています。
    何か設定等はないでしょうか?
  4. Docker環境のLinuxで発生するということでしたら、syslogのようなOS側のログやDockerのシステムログから何か手がかりになりそうなものは発見できますでしょうか?

    またOSやFirewallの機能が一定時間無通信の接続をクローズする場合があります。Linux側の設定変更が可能なら、TCP Keepalive関連の設定を変更した後、JDBCの接続プロパティにtcpKeepAlive=trueを追加して、問題が再現するか確認できますでしょうか?

    https://jdbc.postgresql.org/documentation/head/connect.html
  5. @P488

    Questioner

    ご返信いただき、ありがとうございます。

    ありがとうございます。上記エラーが解消しました。
    TCP Keepaliveの設定がデフォルトの(time: 7200, intvl: 75, probes: 9)だったので、(time: 300, intvl: 60, probes: 5)にして、tcpKeepAlive=trueにしたところ、上記エラーが解消されました。
    本当にありがとうございました。助かりました。

Your answer might help someone💌