org.hornetq.core.logging.impl.JULLogDelegate.error() blocking

[hughbragg]

I'm running HornetQ 2.1.2 standalone as a service on Windows Server 2008 by a domain user account.

Aparently M$ have made some changes related to this in recent years, one of which is not to allow interactive services due to some security exploits.

My guess is that this is the cause of my problems because initially I was logging to the console just for debugging convenience and didn't bother stopping it on production. Once I found that this was blocking, I turned console logging off and the problem went away. Recently however I had 2 services running the same client consuming messages remotely from different HornetQ standalone. The sequence of events seem to be:

1. Some network or service related problem occured causing the hornet JMS consumer to throw a JMSException on a receive(200) call.

2. A rollback was attempted causing an IllegalStateException.

3. A new connection attempt was initiated and the createConnection() call blocks for 8 hours.

4. The client service is restarted and everything continues as usual.

My server configuration the default standalone non-clustered with JNDI disabled.

The client uses all default settings.

The stack trace I obtained from jconsole on the JMS thread is:

Name: Thread-2
State: RUNNABLE
Total blocked: 125,069  Total waited: 898,727

Stack trace:
java.io.FileOutputStream.writeBytes(Native Method)
java.io.FileOutputStream.write(Unknown Source)
java.io.BufferedOutputStream.write(Unknown Source)
   - locked java.io.BufferedOutputStream@1b4920f8
java.io.PrintStream.write(Unknown Source)
   - locked java.io.PrintStream@5e1387c6
sun.nio.cs.StreamEncoder.writeBytes(Unknown Source)
sun.nio.cs.StreamEncoder.implFlushBuffer(Unknown Source)
sun.nio.cs.StreamEncoder.implFlush(Unknown Source)
sun.nio.cs.StreamEncoder.flush(Unknown Source)
   - locked java.io.OutputStreamWriter@5437086a
java.io.OutputStreamWriter.flush(Unknown Source)
java.util.logging.StreamHandler.flush(Unknown Source)
   - locked java.util.logging.ConsoleHandler@69099257
java.util.logging.ConsoleHandler.publish(Unknown Source)
java.util.logging.Logger.log(Unknown Source)
java.util.logging.Logger.doLog(Unknown Source)
java.util.logging.Logger.log(Unknown Source)
org.hornetq.core.logging.impl.JULLogDelegate.error(JULLogDelegate.java:68)
org.hornetq.core.logging.Logger.error(Logger.java:169)
org.hornetq.core.remoting.impl.netty.NettyConnector.createConnection(NettyConnector.java:483)
org.hornetq.core.client.impl.FailoverManagerImpl.getConnection(FailoverManagerImpl.java:953)
org.hornetq.core.client.impl.FailoverManagerImpl.getConnectionWithRetry(FailoverManagerImpl.java:834)
org.hornetq.core.client.impl.FailoverManagerImpl.createSession(FailoverManagerImpl.java:342)
   - locked java.lang.Object@5fb57890
   - locked java.lang.Object@c1dfe1a
org.hornetq.core.client.impl.ClientSessionFactoryImpl.createSessionInternal(ClientSessionFactoryImpl.java:1123)
   - locked org.hornetq.core.client.impl.ClientSessionFactoryImpl@3f2221f6
org.hornetq.core.client.impl.ClientSessionFactoryImpl.createSession(ClientSessionFactoryImpl.java:849)
org.hornetq.jms.client.HornetQConnection.authorize(HornetQConnection.java:565)
org.hornetq.jms.client.HornetQConnectionFactory.createConnectionInternal(HornetQConnectionFactory.java:624)
   - locked org.hornetq.jms.client.HornetQConnectionFactory@76c5a2f7
org.hornetq.jms.client.HornetQConnectionFactory.createConnection(HornetQConnectionFactory.java:116)
org.hornetq.jms.client.HornetQConnectionFactory.createConnection(HornetQConnectionFactory.java:111)

Can anyone tell me how to stop hornet client calling JUL?

After all, I'm only interested in the exception so I can make another connection attempt.

Can anyone shed any light on this that might help me fix it?

I know I'd much rather not use Windows, but there is no choice and I can't see why logging is required here.

[hughbragg]

And once again this morning, same circumstances:

Name: Thread-2
State: RUNNABLE
Total blocked: 58,099  Total waited: 75,151

Stack trace:
java.io.FileOutputStream.writeBytes(Native Method)
java.io.FileOutputStream.write(Unknown Source)
java.io.BufferedOutputStream.write(Unknown Source)
   - locked java.io.BufferedOutputStream@3caf7a1f
java.io.PrintStream.write(Unknown Source)
   - locked java.io.PrintStream@247aa859
sun.nio.cs.StreamEncoder.writeBytes(Unknown Source)
sun.nio.cs.StreamEncoder.implFlushBuffer(Unknown Source)
sun.nio.cs.StreamEncoder.implFlush(Unknown Source)
sun.nio.cs.StreamEncoder.flush(Unknown Source)
   - locked java.io.OutputStreamWriter@70c27dc4
java.io.OutputStreamWriter.flush(Unknown Source)
java.util.logging.StreamHandler.flush(Unknown Source)
   - locked java.util.logging.ConsoleHandler@70cf08b1
java.util.logging.ConsoleHandler.publish(Unknown Source)
java.util.logging.Logger.log(Unknown Source)
java.util.logging.Logger.doLog(Unknown Source)
java.util.logging.Logger.log(Unknown Source)
org.hornetq.core.logging.impl.JULLogDelegate.error(JULLogDelegate.java:68)
org.hornetq.core.logging.Logger.error(Logger.java:169)
org.hornetq.core.remoting.impl.netty.NettyConnector.createConnection(NettyConnector.java:483)
org.hornetq.core.client.impl.FailoverManagerImpl.getConnection(FailoverManagerImpl.java:953)
org.hornetq.core.client.impl.FailoverManagerImpl.getConnectionWithRetry(FailoverManagerImpl.java:834)
org.hornetq.core.client.impl.FailoverManagerImpl.createSession(FailoverManagerImpl.java:342)
   - locked java.lang.Object@7dabf7cb
   - locked java.lang.Object@29421875
org.hornetq.core.client.impl.ClientSessionFactoryImpl.createSessionInternal(ClientSessionFactoryImpl.java:1123)
   - locked org.hornetq.core.client.impl.ClientSessionFactoryImpl@17fed8b4
org.hornetq.core.client.impl.ClientSessionFactoryImpl.createSession(ClientSessionFactoryImpl.java:849)
org.hornetq.jms.client.HornetQConnection.authorize(HornetQConnection.java:565)
org.hornetq.jms.client.HornetQConnectionFactory.createConnectionInternal(HornetQConnectionFactory.java:624)
   - locked org.hornetq.jms.client.HornetQConnectionFactory@3da2cda9
org.hornetq.jms.client.HornetQConnectionFactory.createConnection(HornetQConnectionFactory.java:116)
org.hornetq.jms.client.HornetQConnectionFactory.createConnection(HornetQConnectionFactory.java:111)

What can be happening?

[hughbragg]

So I can reliably reproduce this problem now.

It happens when I shut down the jms server for an extended period. This connection is over the internet so there is a bigger lag time than with the LAN service which I never see this problem on. It seems that our connection isn't so reliable and sometimes is interrupted for extended periods.

Clebert. I'll post you a self contained package if you like, but the only difference between the receiveNoWait bug example and this is that I use receive(long) instead of receiveNoWait and the setup is slightly different:

{code}
HornetQConnectionFactory hqcf = HornetQJMSClient
            .createConnectionFactory(transportConfiguration);
    hqcf.setReconnectAttempts(1);        // No Transparent reattachment
    hqcf.setCallTimeout(60000);
    hqcf.setClientFailureCheckPeriod(60000);
    hqcf.setConnectionTTL(60000);
    queueConnection = (QueueConnection)hqcf.createConnection();
{code}

I tried it with only setReconnectAttempts() and without the other settings as well, but it failed the same way.

I also tried to detect long periods of inactivity and do a full reset there, but this only makes the problem worse.

[hughbragg]

The only solution was to not call receiveNoWait(). This method is broken.

It is necessary to call Thread.interrupt().

Instead I use receive(long timeout) with a timeout.