Connection is lost randomly

237 views
Skip to first unread message

Mathias Bøgsted

unread,
Apr 14, 2015, 1:33:39 PM4/14/15
to h2-da...@googlegroups.com
I'm running in cluster mode and I randomly (often) loose connection with either of the servers (sometimes both).
This leaves the cluster in an inconsistent state where data is inserted into one database but not the other.

The following example connects 10.000 times to the cluster.
Below the example is the output where connection is lost.

When both servers are gone, output will show the following along with exceptions:
  FAIL: properties null

When one server is gone, output will show the following:
  FAIL: 1
  127.0.0.1:9101 / 127.0.0.1:9102
  null

Br Mathias

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

package h2debug;

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.SQLWarning;
import java.sql.Statement;
import java.util.Properties;

public class H2debugClusterMode{
	String javaPath = "C:\\Program Files\\Java\\jre1.8.0_40\\bin\\java.exe";
	String classPath = "C:\\h2test\\h2-1.4.187.jar";
	
	public static int SLEEP_BETWEEN_STEPS = 1000;
	
	public static boolean REUSE_CONNECTION = false;
	public static boolean REUSE_STATEMENT = false;
	
	Connection conn;
	Statement statement;
	
	public static void main(String[] args) {
		new H2debugClusterMode();
	}
	public H2debugClusterMode(){
		testDatabaseConsistency();
	}
	public void testDatabaseConsistency(){
		try{
			startDatabaseServer(1);
			startDatabaseServer(2);
			Thread.sleep(SLEEP_BETWEEN_STEPS);
			for(int i = 0;i < 10000;i++){
				if(i % 100 == 0){
					System.out.println(i);
				}
				Statement statement = null;
				try{
					statement = getStatement(false);
				}catch(Exception e){
					e.printStackTrace();
				}
				
				Properties properties = null;
				try{
					properties = statement.getConnection().getClientInfo();
				}catch(Exception e){}
				if(properties == null){
					System.out.println("FAIL: properties null");
				}else if(!"2".equals(properties.get("numServers"))){
					System.out.println("FAIL: " + properties.get("numServers"));
					for(int t = 0;t < 2;t++){
						try{
							System.out.println(properties.get("server" + t));
						}catch(Exception e){}
					}
				}
				try{
					statement.close();
				}catch(Exception e){
					e.printStackTrace();
				}
			}
		}catch(Throwable t){
			t.printStackTrace();
		}
		stop();
	}
	
	public Statement getStatement(boolean forceRenew){
		if(!forceRenew && REUSE_STATEMENT && statement != null){
			return statement;
		}
		try{
			if(forceRenew || !REUSE_CONNECTION || conn == null){
				Class.forName("org.h2.Driver");
				conn = DriverManager.getConnection("jdbc:h2:tcp://localhost:9101,localhost:9102/test;TRACE_LEVEL_FILE=1");
			}
			statement = conn.createStatement();
			return statement;
		}catch(Throwable t){
			t.printStackTrace();
		}
		return null;
	}
	
	Process[] servers = new Process[2];
	public void startDatabaseServer(int database){
		System.out.println("Starting database " + database);
		try{
			stopDatabaseServer(database);
			String command = javaPath + " -cp " + classPath + " org.h2.tools.Server -tcp -tcpPort 910" + database + " -web -webPort 800" + database + " -browser -baseDir c:/h2test/db" + database;
			ProcessBuilder pb = new ProcessBuilder(command.split(" "));
			Process process = pb.start();
			servers[database - 1] = process;
		}catch(Throwable t){
			t.printStackTrace();
		}
	}
	public void stopDatabaseServer(int database){
		if(servers[database - 1] != null){
			System.out.println("Stopping database " + database);
			servers[database - 1].destroy();
			servers[database - 1] = null;
		}
	}
	public void outputWarnings(SQLWarning warning){
		if(warning != null){
			warning.printStackTrace();
		}
	}
	public void stop(){
		try{
			Thread.sleep(SLEEP_BETWEEN_STEPS);
			stopDatabaseServer(1);
			stopDatabaseServer(2);
			Thread.sleep(SLEEP_BETWEEN_STEPS);
		}catch(Throwable t){
			t.printStackTrace();
		}
	}
}


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


Starting database 1
Starting database 2
0
100
200
300
400
FAIL: properties null
org.h2.jdbc.JdbcSQLException: Connection is broken: "session closed" [90067-181]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
	at org.h2.message.DbException.get(DbException.java:179)
	at org.h2.message.DbException.get(DbException.java:155)
	at org.h2.engine.SessionRemote.checkClosed(SessionRemote.java:555)
	at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:455)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:327)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:108)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:92)
	at org.h2.Driver.connect(Driver.java:72)
	at java.sql.DriverManager.getConnection(DriverManager.java:582)
	at java.sql.DriverManager.getConnection(DriverManager.java:207)
	at h2debug.H2debugClusterMode.getStatement(H2debugClusterMode.java:76)
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:38)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
java.lang.NullPointerException
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:58)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
FAIL: 1
127.0.0.1:9101
null
FAIL: 1
127.0.0.1:9101
null
FAIL: 1
127.0.0.1:9101
null
org.h2.jdbc.JdbcSQLException: Connection is broken: "session closed" [90067-181]
FAIL: properties null
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
	at org.h2.message.DbException.get(DbException.java:179)
	at org.h2.message.DbException.get(DbException.java:155)
	at org.h2.engine.SessionRemote.checkClosed(SessionRemote.java:555)
	at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:455)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:327)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:108)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:92)
	at org.h2.Driver.connect(Driver.java:72)
	at java.sql.DriverManager.getConnection(DriverManager.java:582)
	at java.sql.DriverManager.getConnection(DriverManager.java:207)
	at h2debug.H2debugClusterMode.getStatement(H2debugClusterMode.java:76)
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:38)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
java.lang.NullPointerException
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:58)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
org.h2.jdbc.JdbcSQLException: Connection is broken: "session closed" [90067-181]
FAIL: properties null
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
	at org.h2.message.DbException.get(DbException.java:179)
	at org.h2.message.DbException.get(DbException.java:155)
	at org.h2.engine.SessionRemote.checkClosed(SessionRemote.java:555)
	at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:455)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:327)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:108)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:92)
	at org.h2.Driver.connect(Driver.java:72)
	at java.sql.DriverManager.getConnection(DriverManager.java:582)
	at java.sql.DriverManager.getConnection(DriverManager.java:207)
	at h2debug.H2debugClusterMode.getStatement(H2debugClusterMode.java:76)
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:38)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
java.lang.NullPointerException
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:58)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
org.h2.jdbc.JdbcSQLException: Connection is broken: "session closed" [90067-181]
FAIL: properties null
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
	at org.h2.message.DbException.get(DbException.java:179)
	at org.h2.message.DbException.get(DbException.java:155)
	at org.h2.engine.SessionRemote.checkClosed(SessionRemote.java:555)
	at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:455)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:327)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:108)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:92)
	at org.h2.Driver.connect(Driver.java:72)
	at java.sql.DriverManager.getConnection(DriverManager.java:582)
	at java.sql.DriverManager.getConnection(DriverManager.java:207)
	at h2debug.H2debugClusterMode.getStatement(H2debugClusterMode.java:76)
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:38)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
java.lang.NullPointerException
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:58)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
org.h2.jdbc.JdbcSQLException: Connection is broken: "session closed" [90067-181]
FAIL: properties null
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
	at org.h2.message.DbException.get(DbException.java:179)
	at org.h2.message.DbException.get(DbException.java:155)
	at org.h2.engine.SessionRemote.checkClosed(SessionRemote.java:555)
	at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:455)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:327)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:108)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:92)
	at org.h2.Driver.connect(Driver.java:72)
	at java.sql.DriverManager.getConnection(DriverManager.java:582)
	at java.sql.DriverManager.getConnection(DriverManager.java:207)
	at h2debug.H2debugClusterMode.getStatement(H2debugClusterMode.java:76)
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:38)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
java.lang.NullPointerException
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:58)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
org.h2.jdbc.JdbcSQLException: Connection is broken: "session closed" [90067-181]
FAIL: properties null
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
	at org.h2.message.DbException.get(DbException.java:179)
	at org.h2.message.DbException.get(DbException.java:155)
	at org.h2.engine.SessionRemote.checkClosed(SessionRemote.java:555)
	at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:455)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:327)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:108)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:92)
	at org.h2.Driver.connect(Driver.java:72)
	at java.sql.DriverManager.getConnection(DriverManager.java:582)
	at java.sql.DriverManager.getConnection(DriverManager.java:207)
	at h2debug.H2debugClusterMode.getStatement(H2debugClusterMode.java:76)
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:38)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
java.lang.NullPointerException
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:58)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
FAIL: 1
127.0.0.1:9101
null
500
600
700
800
900
1000
1100
1200
1300
1400
1500
1600
1700
1800
1900
2000
2100
2200
2300
2400
2500
2600
2700
2800
2900
3000
3100
3200
3300
3400
3500
3600
3700
3800
3900
4000
org.h2.jdbc.JdbcSQLException: Connection is broken: "session closed" [90067-181]
FAIL: properties null
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
	at org.h2.message.DbException.get(DbException.java:179)
	at org.h2.message.DbException.get(DbException.java:155)
	at org.h2.engine.SessionRemote.checkClosed(SessionRemote.java:555)
	at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:455)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:327)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:108)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:92)
	at org.h2.Driver.connect(Driver.java:72)
	at java.sql.DriverManager.getConnection(DriverManager.java:582)
	at java.sql.DriverManager.getConnection(DriverManager.java:207)
	at h2debug.H2debugClusterMode.getStatement(H2debugClusterMode.java:76)
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:38)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
java.lang.NullPointerException
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:58)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
4100
4200
4300
4400
4500
4600
4700
4800
4900
5000
5100
FAIL: 1
127.0.0.1:9101
null
FAIL: 1
127.0.0.1:9102
null
FAIL: 1
127.0.0.1:9101
null
org.h2.jdbc.JdbcSQLException: Connection is broken: "session closed" [90067-181]
FAIL: properties null
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
	at org.h2.message.DbException.get(DbException.java:179)
	at org.h2.message.DbException.get(DbException.java:155)
	at org.h2.engine.SessionRemote.checkClosed(SessionRemote.java:555)
	at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:455)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:327)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:108)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:92)
	at org.h2.Driver.connect(Driver.java:72)
	at java.sql.DriverManager.getConnection(DriverManager.java:582)
	at java.sql.DriverManager.getConnection(DriverManager.java:207)
	at h2debug.H2debugClusterMode.getStatement(H2debugClusterMode.java:76)
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:38)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
java.lang.NullPointerException
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:58)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
org.h2.jdbc.JdbcSQLException: Connection is broken: "session closed" [90067-181]
FAIL: properties null
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
	at org.h2.message.DbException.get(DbException.java:179)
	at org.h2.message.DbException.get(DbException.java:155)
	at org.h2.engine.SessionRemote.checkClosed(SessionRemote.java:555)
	at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:455)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:327)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:108)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:92)
	at org.h2.Driver.connect(Driver.java:72)
	at java.sql.DriverManager.getConnection(DriverManager.java:582)
	at java.sql.DriverManager.getConnection(DriverManager.java:207)
	at h2debug.H2debugClusterMode.getStatement(H2debugClusterMode.java:76)
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:38)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
java.lang.NullPointerException
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:58)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
org.h2.jdbc.JdbcSQLException: Connection is broken: "session closed" [90067-181]
FAIL: properties null
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
	at org.h2.message.DbException.get(DbException.java:179)
	at org.h2.message.DbException.get(DbException.java:155)
	at org.h2.engine.SessionRemote.checkClosed(SessionRemote.java:555)
	at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:455)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:327)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:108)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:92)
	at org.h2.Driver.connect(Driver.java:72)
	at java.sql.DriverManager.getConnection(DriverManager.java:582)
	at java.sql.DriverManager.getConnection(DriverManager.java:207)
	at h2debug.H2debugClusterMode.getStatement(H2debugClusterMode.java:76)
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:38)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
java.lang.NullPointerException
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:58)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
org.h2.jdbc.JdbcSQLException: Connection is broken: "session closed" [90067-181]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
	at org.h2.message.DbException.get(DbException.java:179)
FAIL: properties null
	at org.h2.message.DbException.get(DbException.java:155)
	at org.h2.engine.SessionRemote.checkClosed(SessionRemote.java:555)
	at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:455)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:327)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:108)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:92)
	at org.h2.Driver.connect(Driver.java:72)
	at java.sql.DriverManager.getConnection(DriverManager.java:582)
	at java.sql.DriverManager.getConnection(DriverManager.java:207)
	at h2debug.H2debugClusterMode.getStatement(H2debugClusterMode.java:76)
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:38)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
java.lang.NullPointerException
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:58)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
org.h2.jdbc.JdbcSQLException: Connection is broken: "session closed" [90067-181]
FAIL: properties null
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
	at org.h2.message.DbException.get(DbException.java:179)
	at org.h2.message.DbException.get(DbException.java:155)
	at org.h2.engine.SessionRemote.checkClosed(SessionRemote.java:555)
	at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:455)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:327)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:108)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:92)
	at org.h2.Driver.connect(Driver.java:72)
	at java.sql.DriverManager.getConnection(DriverManager.java:582)
	at java.sql.DriverManager.getConnection(DriverManager.java:207)
	at h2debug.H2debugClusterMode.getStatement(H2debugClusterMode.java:76)
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:38)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
java.lang.NullPointerException
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:58)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
FAIL: 1
127.0.0.1:9102
null
5200
5300
5400
5500
5600
org.h2.jdbc.JdbcSQLException: Connection is broken: "session closed" [90067-181]
FAIL: properties null
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
	at org.h2.message.DbException.get(DbException.java:179)
	at org.h2.message.DbException.get(DbException.java:155)
	at org.h2.engine.SessionRemote.checkClosed(SessionRemote.java:555)
	at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:455)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:327)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:108)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:92)
	at org.h2.Driver.connect(Driver.java:72)
	at java.sql.DriverManager.getConnection(DriverManager.java:582)
	at java.sql.DriverManager.getConnection(DriverManager.java:207)
	at h2debug.H2debugClusterMode.getStatement(H2debugClusterMode.java:76)
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:38)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
java.lang.NullPointerException
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:58)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
FAIL: 1
127.0.0.1:9101
null
FAIL: 1
127.0.0.1:9101
null
org.h2.jdbc.JdbcSQLException: Connection is broken: "session closed" [90067-181]
FAIL: properties null
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
	at org.h2.message.DbException.get(DbException.java:179)
	at org.h2.message.DbException.get(DbException.java:155)
	at org.h2.engine.SessionRemote.checkClosed(SessionRemote.java:555)
	at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:455)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:327)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:108)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:92)
	at org.h2.Driver.connect(Driver.java:72)
	at java.sql.DriverManager.getConnection(DriverManager.java:582)
	at java.sql.DriverManager.getConnection(DriverManager.java:207)
	at h2debug.H2debugClusterMode.getStatement(H2debugClusterMode.java:76)
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:38)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
java.lang.NullPointerException
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:58)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
org.h2.jdbc.JdbcSQLException: Connection is broken: "session closed" [90067-181]
FAIL: properties null
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
	at org.h2.message.DbException.get(DbException.java:179)
	at org.h2.message.DbException.get(DbException.java:155)
	at org.h2.engine.SessionRemote.checkClosed(SessionRemote.java:555)
	at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:455)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:327)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:108)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:92)
	at org.h2.Driver.connect(Driver.java:72)
	at java.sql.DriverManager.getConnection(DriverManager.java:582)
	at java.sql.DriverManager.getConnection(DriverManager.java:207)
	at h2debug.H2debugClusterMode.getStatement(H2debugClusterMode.java:76)
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:38)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
java.lang.NullPointerException
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:58)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
FAIL: 1
127.0.0.1:9101
null
org.h2.jdbc.JdbcSQLException: Connection is broken: "session closed" [90067-181]
FAIL: properties null
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
	at org.h2.message.DbException.get(DbException.java:179)
	at org.h2.message.DbException.get(DbException.java:155)
	at org.h2.engine.SessionRemote.checkClosed(SessionRemote.java:555)
	at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:455)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:327)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:108)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:92)
	at org.h2.Driver.connect(Driver.java:72)
	at java.sql.DriverManager.getConnection(DriverManager.java:582)
	at java.sql.DriverManager.getConnection(DriverManager.java:207)
	at h2debug.H2debugClusterMode.getStatement(H2debugClusterMode.java:76)
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:38)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
java.lang.NullPointerException
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:58)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
org.h2.jdbc.JdbcSQLException: Connection is broken: "session closed" [90067-181]
FAIL: properties null
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
	at org.h2.message.DbException.get(DbException.java:179)
	at org.h2.message.DbException.get(DbException.java:155)
	at org.h2.engine.SessionRemote.checkClosed(SessionRemote.java:555)
	at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:455)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:327)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:108)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:92)
	at org.h2.Driver.connect(Driver.java:72)
	at java.sql.DriverManager.getConnection(DriverManager.java:582)
	at java.sql.DriverManager.getConnection(DriverManager.java:207)
	at h2debug.H2debugClusterMode.getStatement(H2debugClusterMode.java:76)
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:38)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
java.lang.NullPointerException
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:58)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
org.h2.jdbc.JdbcSQLException: Connection is broken: "session closed" [90067-181]
FAIL: properties null
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
	at org.h2.message.DbException.get(DbException.java:179)
	at org.h2.message.DbException.get(DbException.java:155)
	at org.h2.engine.SessionRemote.checkClosed(SessionRemote.java:555)
	at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:455)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:327)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:108)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:92)
	at org.h2.Driver.connect(Driver.java:72)
	at java.sql.DriverManager.getConnection(DriverManager.java:582)
	at java.sql.DriverManager.getConnection(DriverManager.java:207)
	at h2debug.H2debugClusterMode.getStatement(H2debugClusterMode.java:76)
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:38)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
java.lang.NullPointerException
	at h2debug.H2debugClusterMode.testDatabaseConsistency(H2debugClusterMode.java:58)
	at h2debug.H2debugClusterMode.<init>(H2debugClusterMode.java:25)
	at h2debug.H2debugClusterMode.main(H2debugClusterMode.java:22)
FAIL: 1
127.0.0.1:9102
null
FAIL: 1
127.0.0.1:9101
null
5700
5800
5900
6000
6100
6200
6300
6400
6500
6600
6700
6800
6900
7000
7100
7200
7300
7400
7500
7600
7700
7800
7900
8000
8100
8200
8300
8400
8500
8600
8700
8800
8900
9000
9100
FAIL: 1
127.0.0.1:9101
null
FAIL: 1
127.0.0.1:9102
null
9200
9300
9400
9500
9600
9700
9800
9900
Stopping database 1
Stopping database 2

Mathias Bøgsted

unread,
Apr 20, 2015, 9:47:02 AM4/20/15
to h2-da...@googlegroups.com
The experienced problem is a show stopper and could eliminate H2 as a candidate for our project.
Have my bug been acknowledged yet or did it get lost in your inbox.

We will soon have to assess if we will continue with H2 - would it be possible to get an estimated fix date?
And would it be possible to hire you to fix this issue?

Br Mathias.

Noel Grandin

unread,
Apr 20, 2015, 10:17:33 AM4/20/15
to h2-da...@googlegroups.com
Are you willing to build H2 yourself to debug this issue?

Because it's hiding behind another problem, which I have a patch for, but I can't reproduce your exact problem.

Mathias Bøgsted

unread,
Apr 21, 2015, 3:31:30 AM4/21/15
to h2-da...@googlegroups.com
Hi Noel,

Yes - I will build H2 myself.
Do you prefer a revision to patch. I can see the repository from http://h2database.googlecode.com/svn/trunk/
What patch should I apply?

Thank you for your help.

Br Mathias.

Noel Grandin

unread,
Apr 21, 2015, 3:53:23 AM4/21/15
to h2-da...@googlegroups.com
Hi

edit the removeServer method in the SessionRemote class so that it looks like:

public void removeServer(IOException e, int i, int count) {
trace.error(e, "removing server because of exception");
transferList.remove(i);
if (transferList.size() == 0 && autoReconnect(count)) {
return;
}
checkClosed();
switchOffCluster();
}

Then run your tests again and look in the trace logs to see what the error was.

The bug was that we were logging the problem with "debug" level
priority, so it would not show up when running H2 normally.

Regards, Noel

Mathias Bøgsted

unread,
Apr 21, 2015, 4:03:28 PM4/21/15
to h2-da...@googlegroups.com
So this is quite interesting.
I've been playing with the debugging, you proposed, but didn't get any logged errors.
But I did manage to inject some usefull debugging. It turns out my testcase uses all available socket buffering memory and fails due to this.

But the error I see in production is not caused by this buffer starvation. The mere fact that I build the database myself seems to solve the problem.
- I'm building with the same java version as in my production environment which is 6u16.
- H2 from h2database.com is build using 6u41.
The class binaries are different between the two builds.

So far I've tested my system by booting it for 90 seconds.
- With official H2 release it failed 8 out of 20 times.
- With the local build it failed 0 out of 20 times.

Thank you for your help so far.
I will post a conclusion when I'm confident the cause has been found (and perhaps even test the official build with version 6u41 to verify it's not an error in javac but just a broken backward compatability).

Br Mathias.

Noel Grandin

unread,
Apr 22, 2015, 1:13:04 AM4/22/15
to h2-da...@googlegroups.com
Interesting. Nice work.

perhaps you could use something like
http://www.cjmweb.net/vbindiff/
to see where the differences lie?

Mathias Bøgsted

unread,
Apr 22, 2015, 6:06:36 PM4/22/15
to h2-da...@googlegroups.com
Hi Noel,

I believe I've found another cause. My own build also eventually failed and now seems no more stable than the version online (though it seems statistically impossible given the 8:20 vs 0:20 ratio).

I added some extra logging directly to a file to rule out missing logging caused by lost connection between client and server in SessionRemote line 453 in current revision:
if (len == 1) {
    throw DbException.get(ErrorCode.CONNECTION_BROKEN_1, e, e + ": " + s);
}else{
    logMessage(s);
    logMessage(e);
}

This logged the following Exception to the output file:
connect timed out
java.net.SocketTimeoutException: connect timed out
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:333)
at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:195)
at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:182)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
at java.net.Socket.connect(Socket.java:525)
at org.h2.util.NetUtils.createSocket(NetUtils.java:122)
at org.h2.util.NetUtils.createSocket(NetUtils.java:102)
at org.h2.engine.SessionRemote.initTransfer(SessionRemote.java:116)
at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:450)
at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:331)
at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:108)
at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:92)
at org.h2.Driver.connect(Driver.java:72)
at java.sql.DriverManager.getConnection(DriverManager.java:582)
at java.sql.DriverManager.getConnection(DriverManager.java:185)

I then altered the SOCKET_CONNECT_TIMEOUT from 2 to 10 seconds and added some additional logging of timing in NetUtils.createSocket()
public static Socket createSocket(InetAddress address, int port, boolean ssl)
        throws IOException {
    long start = System.currentTimeMillis();
    for (int i = 0;; i++) {
        try {
            if (ssl) {
                return CipherFactory.createSocket(address, port);
            }
            long start2 = System.currentTimeMillis();
            Socket socket = new Socket();
            socket.connect(new InetSocketAddress(address, port),
                    SysProperties.SOCKET_CONNECT_TIMEOUT);
            long result2 = System.currentTimeMillis() - start2;
            if(result2 > 2100){
                SessionRemote.logMessage("Timeout: Would have failed: " + result2);
            }
            return socket;
        } catch (IOException e) {
            if (System.currentTimeMillis() - start >=
                    SysProperties.SOCKET_CONNECT_TIMEOUT) {
                SessionRemote.logMessage("Timeout: Failed: " + (System.currentTimeMillis() - start));
                // either it was a connect timeout,
                // or list of different exceptions
                throw e;
            }
            if (i >= SysProperties.SOCKET_CONNECT_RETRY) {
                throw e;
            }
            // wait a bit and retry
            try {
                // sleep at most 256 ms
                long sleep = Math.min(256, i * i);
                Thread.sleep(sleep);
            } catch (InterruptedException e2) {
                // ignore
            }
        }
    }
}

And again some logging to TcpServer.listen() to verify the server did not directly cause the timeout (note: only if connection takes over 50 ms).
public void listen() {
listenerThread = Thread.currentThread();
String threadName = listenerThread.getName();
try {
long start = 0;
while (!stop) {
if(start > 0 && System.currentTimeMillis() - start > 50){
SessionRemote.logMessage("Accept took " + (System.currentTimeMillis() - start));
}
Socket s = serverSocket.accept();
start = System.currentTimeMillis();
TcpServerThread c = new TcpServerThread(s, this, nextThreadId++);
running.add(c);
Thread thread = new Thread(c, threadName + " thread");
thread.setDaemon(isDaemon);
c.setThread(thread);
thread.start();
}
serverSocket = NetUtils.closeSilently(serverSocket);
} catch (Exception e) {
if (!stop) {
DbException.traceThrowable(e);
}
}
stopManagementDb();
}

The combined client and server log was:
Accept took 62
Accept took 62
Timeout: Would have failed: 3009
Accept took 62
Timeout: Would have failed: 3023
Timeout: Would have failed: 3015
Accept took 63
Timeout: Would have failed: 3012
Accept took 125
Accept took 62
Accept took 78
Timeout: Would have failed: 3024
Accept took 62
Accept took 78
Accept took 70
Accept took 52
Timeout: Would have failed: 3011
Timeout: Would have failed: 3029
Accept took 78
Accept took 63
Accept took 63
Timeout: Would have failed: 3016
Accept took 63
Accept took 63
Accept took 93
Accept took 63
Accept took 140
Accept took 63
Accept took 65
Accept took 63
Timeout: Would have failed: 3017
Accept took 78
Accept took 62
Timeout: Would have failed: 3014
Accept took 63
Accept took 63
Accept took 62
......

So it appears Socket.connect() sometimes takes 3 additional seconds to connect.
I've investigated a little on the Internet and my current theory is that ServerSocket.accept() together with the H2 handling of new connections is single threaded and does not allow concurrent connections.
If clients connect concurrently, only 1 will connect and the other(s) will have to reconnect (I've found no documentation, that the retry interval should be 3 seconds but I'm starting to believe).

I will keep testing to verify if setting SOCKET_CONNECT_TIMEOUT ("h2.socketConnectTimeout") to at least 4 seconds is a sustainable solution.

Br Mathias

Noel Grandin

unread,
Apr 23, 2015, 3:57:25 AM4/23/15
to h2-da...@googlegroups.com
By default, the backlog on the TCP serversocket is set to 50, and
given that the accept is taking less than 50ms, I can't see that the
server side is a problem.

You are not, by any chance, using the h2.bindAddress setting, are you?
Because in that case it looks like we have a bug where we are setting
the backlog to zero.

What operating system are you using? This might be some kind of DNS or
local name resolver issue.

You could try running Wireshark and logging local timestamp and the
port numbers from both ends of the socket, and then looking in
wireshark to see what is happening to the failed connections.

Mathias Bøgsted

unread,
Apr 23, 2015, 4:15:07 AM4/23/15
to h2-da...@googlegroups.com
Hi Noel,

I'm not using any settings or system properties for H2.
I'm running on Windows 7. I believe it to be caused by TCP retransmit timeout: http://www.streppone.it/cosimo/blog/2011/07/how-to-detect-tcp-retransmit-timeouts-in-your-network/

Noel Grandin

unread,
Apr 23, 2015, 4:21:49 AM4/23/15
to h2-da...@googlegroups.com
In that case I think you should try using Microsoft Network Monitor
http://www.microsoft.com/en-za/download/details.aspx?id=4865
It works much better for localhost connections than Wireshark.
And it should show you fairly quickly if you have some kind of
malfunctioning hardware or software.
Reply all
Reply to author
Forward
0 new messages