Reproducible failure under load, SSL only

[stuarthalloway]

I have encountered a problem where repeated creation, use, and destruction of a session leads to an internal SSL failure followed by inability to reconnect. The same example runs without issue when SSL is turned off.

Sample project, instructions to reproduce, error messages, and logs are all available at https://github.com/Datomic/datomic-java-examples/wiki/Hornet-SSL-Oddity.

Any suggestions?

Thanks,

Stu

[clebert.suconic]

I'm getting a build error here:

INFO] ------------------------------------------------------------------------

[INFO] BUILD FAILURE

[INFO] ------------------------------------------------------------------------

[INFO] Total time: 6.582s

[INFO] Finished at: Tue Dec 04 10:53:40 CST 2012

[INFO] Final Memory: 9M/119M

[INFO] ------------------------------------------------------------------------

[ERROR] Failed to execute goal on project datomic-java-examples: Could not resolve dependencies for project com.datomic:datomic-java-examples:jar:0.0: Could not find artifact com.datomic:datomic-free:jar:0.8.3627 in jboss-developer-repository-group (https://repository.jboss.org/nexus/content/groups/developer/) -> [Help 1]

[ERROR]

It's probably a simple thing.. can  you tell me what to mvn install here?

[stuarthalloway]

The build should be finding the Datomic dependency from the clojars repository. I deleted it from my maven cache, and then saw the following:

>mvn dependency:tree

Downloading: http://files.datomic.com/maven/com/datomic/datomic-free/0.8.3627/datomic-free-0.8.3627.pom

Downloading: http://oss.sonatype.org/content/repositories/releases/com/datomic/datomic-free/0.8.3627/datomic-free-0.8.3627.pom

Downloading: https://repository.jboss.org/nexus/content/groups/public/com/datomic/datomic-free/0.8.3627/datomic-free-0.8.3627.pom

Downloading: http://clojars.org/repo/com/datomic/datomic-free/0.8.3627/datomic-free-0.8.3627.pom

Downloaded: http://clojars.org/repo/com/datomic/datomic-free/0.8.3627/datomic-free-0.8.3627.pom (10 KB at 21.4 KB/sec)

Downloading: http://files.datomic.com/maven/com/datomic/datomic-free/0.8.3627/datomic-free-0.8.3627.jar

Downloading: http://oss.sonatype.org/content/repositories/releases/com/datomic/datomic-free/0.8.3627/datomic-free-0.8.3627.jar

Downloading: https://repository.jboss.org/nexus/content/groups/public/com/datomic/datomic-free/0.8.3627/datomic-free-0.8.3627.jar

Downloading: http://clojars.org/repo/com/datomic/datomic-free/0.8.3627/datomic-free-0.8.3627.jar

Downloaded: http://clojars.org/repo/com/datomic/datomic-free/0.8.3627/datomic-free-0.8.3627.jar (2726 KB at 1429.3 KB/sec)

Is there something blocking you from connectiong to clojars.org?

Stu

[clebert.suconic]

You are using hornetq 2.2.2 there... and I'm not sure where you declare it (It seems declared at some of your datatomic dependencies). (and I'm not sure how to change it.. I'm not very good at maven.. I just use it )

Can you try with a newer version, and tell me how to upgrade it here?

2.2.2 is very old... 2.2.23 would be a good one to be used. (from AS7 branch)

[clebert.suconic]

I could fix the depency BTW: I had some settings.xml on my .m2 that we used for JBoss projects.. I just commented out temporarily.

[stuarthalloway]

If the repo is being squirrelly you can also download Datomic directly. Unzip distro, then

>bin/maven-install

[clebert.suconic]

I could make it work.. I just want to know now how to replace hornetq by a newer version.

If you could actually maybe do that test with a newer version before I work on it? (especially the newer netty version)

[clebert.suconic]

Did you try playing with connection TTL override?

The Server's side TTL will be set by the first ping. When under load maybe this will take longer to arrive there, and since you're using SSL maybe that's causing issues?

[jbertram]

I updated your test to use HornetQ 2.3.0.Beta2 and I haven't seen a failure.  I got up to 34,000 pings before I stopped it.  Here are the changes I made:

diff --git a/pom.xml b/pom.xml
index 45bd2e0..8adf9f6 100644
--- a/pom.xml
+++ b/pom.xml
@@ -8,6 +8,10 @@
       <version>0.8.3627</version>
       <exclusions>
         <exclusion>
+          <groupId>org.hornetq</groupId>
+          <artifactId>hornetq-core</artifactId>
+        </exclusion>
+        <exclusion>
           <groupId>org.slf4j</groupId>
           <artifactId>slf4j-log4j12</artifactId>
         </exclusion>
@@ -22,6 +26,11 @@
       <artifactId>logback-classic</artifactId>
       <version>1.0.1</version>
     </dependency>
+<dependency>
+  <groupId>org.hornetq</groupId>
+  <artifactId>hornetq-server</artifactId>
+  <version>2.3.0.BETA2</version>
+</dependency>
  </dependencies>
  <version>0.0</version>
  <groupId>com.datomic</groupId>
@@ -38,6 +47,17 @@
     <directory>src/resources</directory>
    </resource>
   </resources>
+<plugins>
+      <plugin>
+        <groupId>org.apache.maven.plugins</groupId>
+        <artifactId>maven-compiler-plugin</artifactId>
+        <version>2.0.2</version>
+        <configuration>
+          <source>1.5</source>
+          <target>1.5</target>
+        </configuration>
+      </plugin>
+    </plugins>
  </build>
  <repositories>
    <repository>

FYI - I was getting a compilation failure without the <plugins> configuration update.

[stuarthalloway]

Hi Justin,

Thanks for your help. My superpower seems to be obtaining anomalous results. I was immediately able to reproduce the same failure on 2.3.0.Beta2. Here is a text file with my dependency tree, and the log file at the time of failure.

Were you able to reproduce the problem before upgrading HornetQ?

Stu

[stuarthalloway]

Here is the relevant output from the Producer, with -Djavax.net.debug=ssl-handshake enabled:

***

Old I/O client worker ([id: 0x53b258fa, /127.0.0.1:54710 => localhost/127.0.0.1:5000]), WRITE: TLSv1 Handshake, length = 32

Old I/O client worker ([id: 0x53b258fa, /127.0.0.1:54710 => localhost/127.0.0.1:5000]), READ: TLSv1 Alert, length = 2

Old I/O client worker ([id: 0x53b258fa, /127.0.0.1:54710 => localhost/127.0.0.1:5000]), RECV TLSv1 ALERT:  fatal, internal_error

Old I/O client worker ([id: 0x53b258fa, /127.0.0.1:54710 => localhost/127.0.0.1:5000]), fatal: engine already closed.  Rethrowing javax.net.ssl.SSLException: Received fatal alert: internal_error

Old I/O client worker ([id: 0x53b258fa, /127.0.0.1:54710 => localhost/127.0.0.1:5000]), fatal: engine already closed.  Rethrowing javax.net.ssl.SSLException: Received fatal alert: internal_error

Old I/O client worker ([id: 0x53b258fa, /127.0.0.1:54710 => localhost/127.0.0.1:5000]), called closeOutbound()

Old I/O client worker ([id: 0x53b258fa, /127.0.0.1:54710 => localhost/127.0.0.1:5000]), closeOutboundInternal()

Old I/O client worker ([id: 0x53b258fa, /127.0.0.1:54710 => localhost/127.0.0.1:5000]), SEND TLSv1 ALERT:  warning, description = close_notify

Old I/O client worker ([id: 0x53b258fa, /127.0.0.1:54710 => localhost/127.0.0.1:5000]), WRITE: TLSv1 Alert, length = 18

Old I/O client worker ([id: 0x53b258fa, /127.0.0.1:54710 => localhost/127.0.0.1:5000]), called closeInbound()

Old I/O client worker ([id: 0x53b258fa, /127.0.0.1:54710 => localhost/127.0.0.1:5000]), fatal: engine already closed.  Rethrowing javax.net.ssl.SSLException: Inbound closed before receiving peer's close_notify: possible truncation attack?

hornet.samples.PingProducer.main(), called closeOutbound()

hornet.samples.PingProducer.main(), closeOutboundInternal()

Old I/O client worker ([id: 0x53b258fa, /127.0.0.1:54710 => localhost/127.0.0.1:5000]), called closeOutbound()

Old I/O client worker ([id: 0x53b258fa, /127.0.0.1:54710 => localhost/127.0.0.1:5000]), closeOutboundInternal()

Dec 6, 2012 3:16:25 PM org.hornetq.core.logging.impl.JULLogDelegate warn

WARNING: Tried 1 times to connect. Now giving up.

HornetQException[errorCode=2 message=Cannot connect to server(s). Tried with all available servers.]

          at org.hornetq.core.client.impl.ServerLocatorImpl.createSessionFactory(ServerLocatorImpl.java:619)

          at hornet.samples.PingProducer.main(PingProducer.java:48)

          at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

          at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

          at java.lang.reflect.Method.invoke(Method.java:597)

          at org.codehaus.mojo.exec.ExecJavaMojo$1.run(ExecJavaMojo.java:291)

          at java.lang.Thread.run(Thread.java:680)

I can reproduce this on a wide variety of netty and HornetQ versions.

[jbertram]

Here is a text file with my dependency tree, and the log file at the time of failure.

The output from 'mvn dependency:tree' on my box is exactly the same as yours.

Were you able to reproduce the problem before upgrading HornetQ?

Negative.  I tried with 2.2.2 (the version from your original pom.xml) and I wasn't able to reproduce it there either.  After that I tried 2.3.0.Beta1 and 2.3.0.Beta2.  Never had any failures on the producer like you're seeing.

What version of Java are you using?  It looks like 1.6.0_29.  Is that correct?  I'm using 1.7.0_09.  Could you try that version?

[stuarthalloway]

Hi Justin,

I was able to reproduce the problem on Java 7 as well. There is something very strange here -- people who hit the problem hit it quickly and often, and other people don't hit it at all.

[clebert.suconic]

I have tried it myself and was never able to hit it in three different envionments I had... it is definitely environmental.

anyway, your tests seems like an attack (opening / closing quickly).. you should maybe avoid that behaviour and you would be good on any situation.

[clebert.suconic]

(Also, try the latest update on Java7)...

It's worth talking to Norman on hornetq/IRC, as he's been facing a lot of other usages on Netty / SSL.