tcp broken after shutdown/restart Connection refused: localhost" [90067-169]

[Dave Atkins]

I recently shutdown this H2 database and after restarting the service, I can no longer connect via TCP. I've been troubleshooting from command line; the web interface just times out. Here's what I see:

java -cp  /home/rules/h2/bin/h2-1.3.169.jar org.h2.tools.Shell -url jdbc:h2:tcp://localhost//home/rules/care -user sa

Exception in thread "main" org.h2.jdbc.JdbcSQLException: Connection is broken: "java.net.ConnectException: Connection refused: localhost" [90067-169]

        at org.h2.message.DbException.getJdbcSQLException(DbException.java:329)

        at org.h2.message.DbException.get(DbException.java:158)

        at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:399)

        at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:287)

        at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:109)

        at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:93)

        at org.h2.Driver.connect(Driver.java:72)

        at java.sql.DriverManager.getConnection(DriverManager.java:571)

        at java.sql.DriverManager.getConnection(DriverManager.java:215)

        at org.h2.tools.Shell.runTool(Shell.java:144)

        at org.h2.tools.Shell.main(Shell.java:80)

Caused by: java.net.ConnectException: Connection refused

        at java.net.PlainSocketImpl.socketConnect(Native Method)

        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)

        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)

        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)

        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)

        at java.net.Socket.connect(Socket.java:579)

        at org.h2.util.NetUtils.createSocket(NetUtils.java:119)

        at org.h2.util.NetUtils.createSocket(NetUtils.java:100)

        at org.h2.engine.SessionRemote.initTransfer(SessionRemote.java:93)

        at org.h2.engine.SessionRemote.connectServer(SessionRemote.java:395)

        ... 8 more

However, it is possible to connect using the file protocol:

java -cp  /home/rules/h2/bin/h2-1.3.169.jar org.h2.tools.Shell -url jdbc:h2:file://home/rules/care -user sa

This is fortunate, because this is a production system and we were able to get the application running again by changing the connection string.

How do I troubleshoot this? I can't find any log files or places where there would be useful startup messages logged.

  for each startup, one line in /var/log: "Web Console server running at...", and

  the trace file is full of "01-10 09:39:03 pageStore: Transaction log could not be truncated; size: 16 MB" 

I am not familiar with H2; I am approaching this from an operations perspective; more familiar with mysql and MSSQL server. My intuition is that somewhere, there is a file that is locking the connection from when the server was last shutdown. We need a clean restart.

More background that might be helpful: the reason for the shutdown/restart etc. was that the database file had grown to 2.5GB in size. A backup and restore to another server resulted in a 40MB file. I suspect the transaction logs (whereever they might be?) grew out of control and needed to be truncated. I had hoped to shutdown compact, but I did not even get that far; a simple shutdown led to the current situation.

I was able to shrink the database eventually by deleting the database file and copying over a test database to replace it. Then, I was able to connect with file method above and restore a backup. The current database file size is only 92MB.

[Noel Grandin]

On Fri, Jan 10, 2014 at 5:21 PM, Dave Atkins <datk...@gmail.com> wrote:
> I recently shutdown this H2 database and after restarting the service, I can
> no longer connect via TCP. I've been troubleshooting from command line; the
> web interface just times out. Here's what I see:

The most likely answer is simply that the service did not restart
properly and so there was nothing to connect to.

[Dave Atkins]

Is there any way to diagnose this? Are there any log files I don't know about? Where would I find an exception or some indication that the service did not start properly?

[Thomas Mueller]

Hi,

How did you start the service? I would expect an exception there if it didn't work.

Regards,

Thomas

--
You received this message because you are subscribed to the Google Groups "H2 Database" group.
To unsubscribe from this group and stop receiving emails from it, send an email to h2-database...@googlegroups.com.
To post to this group, send email to h2-da...@googlegroups.com.
Visit this group at http://groups.google.com/group/h2-database.
For more options, visit https://groups.google.com/groups/opt_out.

[Dave Atkins]

The service starts, but the tcp server is not running. It is possible to connect by the file method.

The service is started with default options, from a script in init.d...e.g.

service careH2 start

=>

/usr/java/latest/bin/java -Dname=CareH2d -cp /home/rules/h2/bin/h2-1.3.169.jar org.h2.tools.Server

--
You received this message because you are subscribed to a topic in the Google Groups "H2 Database" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/h2-database/3lJV5BZn2OE/unsubscribe.
To unsubscribe from this group and all its topics, send an email to h2-database...@googlegroups.com.

[Thomas Mueller]

Hi,

The service starts, but the tcp server is not running.

Well, if the TCP server is not running, then the service did not start properly, right? I don't know how, but I guess there is a way to look at the output of the server, so see what the problem is?

>  It is possible to connect by the file method.

That only means the database is not open. The TCP server only opens the database when a connection is open (not when the TCP server is started).

Regards,

Thomas

[Dave Atkins]

When the server starts, the only logging I have found is a file in /var/log/databasename.log which contains entries like:

TCP server running at tcp://xxx.xx.xx.xxx:9092 (only local connections)

PG server running at pg://xxx.xx.xx.xxx:5435 (only local connections)

Web Console server running at http://xxx.xx.xx.xxx:8082 (only local connections)

TCP server running at tcp://xxx.xx.xx.xxx:9092 (only local connections)

PG server running at pg://xxx.xx.xx.xxx:5435 (only local connections)

Web Console server running at http://xxx.xx.xx.xxx:8082 (only local connections)

Web Console server running at http://xxx.xx.xx.xxx:8082 (only local connections)

Web Console server running at http://xxx.xx.xx.xxx:8082 (only local connections)

There are no timestamps so I don't know when each entry was made, but I think what I should be seeing is 3 lines for each startup: PG, Web Console, and TCP server running... So what I see instead, for the last 3 startups is just the Web Console server running.

I can attempt more restarts to see what happens, but this is a production system and I want to avoid more trouble. As I recall, I did attempt 3 restarts but then we found the file connection method and were able to switch over our application to use that protocol. The server has been running for a week in this mode.

When I start the server...there is never any kind of message; it just says the service was started. Then you can do a ps -ef | grep java and see it running:

rules    10880     1 55 Jan09 ?        3-03:33:48 /usr/java/latest/bin/java -Dname=CareH2d -cp /home/rules/h2/bin/h2-1.3.169.jar org.h2.tools.Server

Then, you can attempt to connect via tcp:

java -cp  /home/rules/h2/bin/h2-1.3.169.jar org.h2.tools.Shell -url jdbc:h2:tcp://localhost//home/rules/care -user sa

This throws the exception:

Exception in thread "main" org.h2.jdbc.JdbcSQLException: Connection is broken: "java.net.ConnectException: Connection refused: localhost" [90067-169]

So then, we change the connection string:

java -cp  /home/rules/h2/bin/h2-1.3.169.jar org.h2.tools.Shell -url jdbc:h2:file://home/rules/care -user sa

and I am able to connect to the database, execute queries, etc.

It seems obvious to me that the tcp server is just not running. But apart from restarting over and over until it starts up properly, what can I do? I have 4 other servers that are for development and testing...sometimes (like 1/10 restarts) I have this problem, but I cannot reliably reproduce it. We have upgraded the jar to .174 and at our next code release, will deploy that and go through the restart process again with the file connection method as our fallback.

[Dave Atkins]

Here is some more information. I can now reproduce the problem and suspect it may be due to our version of java. These probelms began with our upgrade from Java 6.

[root@SHCBRMSTST202] [/home/rules] > java -version

java version "1.7.0_45"

Java(TM) SE Runtime Environment (build 1.7.0_45-b18)

Java HotSpot(TM) 64-Bit Server VM (build 24.45-b08, mixed mode)

Here is an example of starting the server repeatedly from the command line to observe the startup messages. Notice how there is a sequence when the TCP and PG servers fail to start. Then, after a few fails, it starts OK.

[root@SHCBRMSTST202] [/home/rules] >  /usr/java/latest/bin/java -Dname=CareH2d -cp /home/rules/h2/bin/h2.jar org.h2.tools.Server

Web Console server running at http://localhost:8082 (only local connections)

TCP server running at tcp://localhost:9092 (only local connections)

PG server running at pg://localhost:5435 (only local connections)

^C

[root@SHCBRMSTST202] [/home/rules] >  /usr/java/latest/bin/java -Dname=CareH2d -cp /home/rules/h2/bin/h2.jar org.h2.tools.Server

Web Console server running at http://localhost:8082 (only local connections)

TCP server running at tcp://localhost:9092 (only local connections)

PG server running at pg://localhost:5435 (only local connections)

^C

[root@SHCBRMSTST202] [/home/rules] >  /usr/java/latest/bin/java -Dname=CareH2d -cp /home/rules/h2/bin/h2.jar org.h2.tools.Server

Web Console server running at http://localhost:8082 (only local connections)

TCP server running at tcp://localhost:9092 (only local connections)

PG server running at pg://localhost:5435 (only local connections)

^C

[root@SHCBRMSTST202] [/home/rules] >  /usr/java/latest/bin/java -Dname=CareH2d -cp /home/rules/h2/bin/h2.jar org.h2.tools.Server

Web Console server running at http://localhost:8082 (only local connections)

TCP server running at tcp://localhost:9092 (only local connections)

PG server running at pg://localhost:5435 (only local connections)

^C

[root@SHCBRMSTST202] [/home/rules] >  /usr/java/latest/bin/java -Dname=CareH2d -cp /home/rules/h2/bin/h2.jar org.h2.tools.Server

Web Console server running at http://localhost:8082 (only local connections)

TCP server running at tcp://localhost:9092 (only local connections)

PG server running at pg://localhost:5435 (only local connections)

^C

[root@SHCBRMSTST202] [/home/rules] >  /usr/java/latest/bin/java -Dname=CareH2d -cp /home/rules/h2/bin/h2.jar org.h2.tools.Server

Web Console server running at http://localhost:8082 (only local connections)

^C

[root@SHCBRMSTST202] [/home/rules] >  /usr/java/latest/bin/java -Dname=CareH2d -cp /home/rules/h2/bin/h2.jar org.h2.tools.Server

Web Console server running at http://localhost:8082 (only local connections)

^C

[root@SHCBRMSTST202] [/home/rules] >  /usr/java/latest/bin/java -Dname=CareH2d -cp /home/rules/h2/bin/h2.jar org.h2.tools.Server

Web Console server running at http://localhost:8082 (only local connections)

^C

[root@SHCBRMSTST202] [/home/rules] >  /usr/java/latest/bin/java -Dname=CareH2d -cp /home/rules/h2/bin/h2.jar org.h2.tools.Server

Web Console server running at http://localhost:8082 (only local connections)

^C

[root@SHCBRMSTST202] [/home/rules] >  /usr/java/latest/bin/java -Dname=CareH2d -cp /home/rules/h2/bin/h2.jar org.h2.tools.Server

Web Console server running at http://localhost:8082 (only local connections)

TCP server running at tcp://localhost:9092 (only local connections)

PG server running at pg://localhost:5435 (only local connections)

[cedric]

Hi,

I think you should first confirm on which IP/port H2 is really listening.
You can confirm this by using a command such as 'netstat'.

netstat -npl

There should be a line similar to the following one (look at tcp and 9092 port)
tcp        0      0 0.0.0.0:9092                0.0.0.0:*                   LISTEN      2582/java

If H2 is listening on something else than 0.0.0.0 or 127.0.0.1 there is something wrong in 'localhost' resolution or in your local routing tables.
Such problem may occurs for example on an ipv6 installation.
This can be fixed by your sys admin (or by using plain IP in your connection URLs).

Regards,
Cédric.

Hi,

To unsubscribe from this group and stop receiving emails from it, send an email to h2-database+unsubscribe@googlegroups.com.

To post to this group, send email to h2-da...@googlegroups.com.
Visit this group at http://groups.google.com/group/h2-database.
For more options, visit https://groups.google.com/groups/opt_out.

--
You received this message because you are subscribed to a topic in the Google Groups "H2 Database" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/h2-database/3lJV5BZn2OE/unsubscribe.

To unsubscribe from this group and all its topics, send an email to h2-database+unsubscribe@googlegroups.com.

To post to this group, send email to h2-da...@googlegroups.com.
Visit this group at http://groups.google.com/group/h2-database.
For more options, visit https://groups.google.com/groups/opt_out.

--
You received this message because you are subscribed to the Google Groups "H2 Database" group.

To unsubscribe from this group and stop receiving emails from it, send an email to h2-database+unsubscribe@googlegroups.com.

To post to this group, send email to h2-da...@googlegroups.com.
Visit this group at http://groups.google.com/group/h2-database.
For more options, visit https://groups.google.com/groups/opt_out.

[Thomas Mueller]

Hi,

Hm, I don't know what the problem could be, but my guess is that it is a network problem. For those cases where the TCP server is not started, could you get a full thread dump to find out what it is doing? Maybe it is still in the startup phase (that would be weird, but it's possible). Also, could you start the server with the "-trace" option to get detailed output?

Regards,

Thomas

--

You received this message because you are subscribed to a topic in the Google Groups "H2 Database" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/h2-database/3lJV5BZn2OE/unsubscribe.
To unsubscribe from this group and all its topics, send an email to h2-database...@googlegroups.com.
To post to this group, send email to h2-da...@googlegroups.com.
Visit this group at http://groups.google.com/group/h2-database.
For more options, visit https://groups.google.com/groups/opt_out.

--
You received this message because you are subscribed to the Google Groups "H2 Database" group.

To unsubscribe from this group and stop receiving emails from it, send an email to h2-database...@googlegroups.com.

[Dave Atkins]

Thank you for the continued followup!

Here is what I see with -trace. First time, all good. Second time, no tcp server. I have upgraded the jar to the .174 version (h2.jar is a symbolic link):

and downgraded java slightly (We can't go back to 1.6; maybe better to upgrade to latest instead and try that):

java version "1.7.0_25"

Java(TM) SE Runtime Environment (build 1.7.0_25-b15)

Java HotSpot(TM) 64-Bit Server VM (build 23.25-b01, mixed mode)

Also attaching thread dumps...but really it just shows what we know: sometimes the TCP (and PG) server fails to start.

Is/could it be a networking problem? I don't see how. We are all on localhost here and once the server is running correctly, we never have problems. The intermittent problem is all about the start up. It appears I can just restart until I get it right, but this is not an answer to the problem.

[root@SHCBRMSTST202] [/home/CCHCS/da14] >  /usr/java/latest/bin/java  -cp /home/rules/h2/bin/h2.jar org.h2.tools.Server -trace

Web Console server running at http://localhost:8082 (only local connections)

TCP server running at tcp://localhost:9092 (only local connections)

PG server running at pg://localhost:5435 (only local connections)

org.h2.server.TcpServerThread@2f74a57e Connect

org.h2.server.TcpServerThread@57e0592c Connect

org.h2.server.TcpServerThread@2f74a57e Disconnect

org.h2.server.TcpServerThread@57e0592c Disconnect

org.h2.server.TcpServerThread@2f74a57e Close

org.h2.server.TcpServerThread@57e0592c Close

Connect

Connect

Disconnect

Close

Disconnect

Close

^C

[root@SHCBRMSTST202] [/home/CCHCS/da14] >  /usr/java/latest/bin/java  -cp /home/rules/h2/bin/h2.jar org.h2.tools.Server -trace

Web Console server running at http://localhost:8082 (only local connections)

[Noel Grandin]

On 2014-01-16 16:25, Dave Atkins wrote:
>
> Also attaching thread dumps...but really it just shows what we know: sometimes the TCP (and PG) server fails to start.
>

Hmmm, it looks like there are two stuck threads there. They say they are RUNNABLE, but that just means that they might
be locked on some native lock, or stuck spinning in some CPU loop.

I suspect that there is an underlying bug in the JDK's javax.sql package which seems to be triggered by us calling
org.h2.Driver.load(), which in turn calls java.sql.DriverManager.DriverManager.registerDriver()
and
java.sql.DriverManager.getLogWriter()
in parallel on two different threads.

Thomas, in org.h2.tools.Server, we start the Web-Console before we start the TCP and PG servers.
Why is this?
Up until version 1351 we started the TCP and PG servers before the web-console, which would have prevented this bug.

Dave, you appear to have something running in the background which is constantly connecting to the Web-Console, and if
it manages to do so during startup, it triggers this bug. Turning that thing off should prevent this bug until we can
fix it properly.

Regards, Noel.

[Thomas Mueller]

Hi,

I guess it makes sense to start the TCP and PG servers first. I don't remember why I changed the order at some point, I guess it wasn't just an accident. I have fixed that now.

Regards,

Thomas

[Dave Atkins]

Thanks...looks like major progress here. Two questions:

1) Thomas, when you say you have fixed it/changed the sequence of startup...will that be a new jar to download? .175?

2) Noel, "something running in background connecting to Web Console" - we are running a perl based webadmin tool...I will check that out and see what happens when I disable it

root      1359     1  0 09:25 ?        00:00:00 /usr/bin/perl /usr/libexec/webmin/miniserv.pl /etc/webmin/miniserv.conf

I also downgraded to java 6 on the test server and I cannot reproduce the problem (with webmin running). So that confirms the bug was not present in java 6. Upgrading back to java 7 u 51 now to test with and without the webmin...

--

You received this message because you are subscribed to a topic in the Google Groups "H2 Database" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/h2-database/3lJV5BZn2OE/unsubscribe.
To unsubscribe from this group and all its topics, send an email to h2-database...@googlegroups.com.

[Thomas Mueller]

Hi,

> 1) Thomas, when you say you have fixed it/changed the sequence of startup...will that be a new jar to download? .175?

Yes. But you could test right now with the latest automated build: http://www.h2database.com/html/build.html#automated - direct link http://www.h2database.com/automated/h2-latest.jar

Regards,

Thomas

To unsubscribe from this group and stop receiving emails from it, send an email to h2-database...@googlegroups.com.

[Dave Atkins]

Awesome! Now it works with this jar, no problems starting.