3 Replies Latest reply on Feb 9, 2018 12:17 PM by jfisherdev

    Remoting Deadlock in WildFly 9.0.2.Final?

    jfisherdev

      We recently upgraded our enterprise suite from running on JBoss AS 4.2.2 to WildFly 9.0.2.Final and since putting it in production we have been encountering a deadlock in some cases. I suspect the issue could be somewhere in an application, as it seems to happen primarily when a particular is deployed to the server, but unfortunately there has been nothing to point back to that from what information has been captured. Most of the time when this has been reported, it's when a remote standalone EJB client application is trying to connect to the server via EJB client invocation and is receiving no response. I am unfortunately only aware of this issue after the fact, as it's reported by customer support staff and to this point has been resolved by restarting the WildFly server. We have been able to capture thread dumps prior to restarting and have observed a pattern of deadlocking that looks like this:

       

      The thread, which is usually an "EJB default - ..." thread, calling org.jboss.remoting3.remote.RemoteConnection$RemoteWriteListener.send() is waiting for a lock owned by another thread, which is usually a "default I/O - ..." thread, calling

      org.jboss.remoting3.remote.OutboundMessage.cancel(). Thread dump information is provided at the end of the post.

       

      Looking through the JBoss Remoting project issue tracker it looks like this issue was reported and addressed in 4.0.7 [REM3-204] Deadlock when connection is closing while we are writing - JBoss Issue Tracker  but was reported in version 4.0.8 and later marked as cannot reproduce [REM3-226] Deadlock when connection is closing while we are writing - JBoss Issue Tracker. It sounds like it should be fixed in version 4.0.9, which is bundled with WildFly, but that doesn't seem to be the case.

       

      This is a frustrating issue on many fronts as we have not been able to reproduce it internally or in testing and it only first appeared in production, we have not found anything that points to an issue on the application side, and, worst of all, it has unfortunately created a negative end user experience and consequently some resistance to upgrading to WildFly 9.

       

      We need to do something about this, but we don't know what that is.

       

      The main questions we have are:

      - First and foremost, is this a library issue or something else?

          - If it is a library issue, do we need to upgrade something, whether that's the Remoting library or WildFly itself?

      - If this is something application related, what should we look for on the application side that might be causing the deadlock?

      - Is there anything on the configuration side that could cause this?

       

      Any information that could help would be very much appreciated.

       

      Note that the thread dumps are captured via Jolokia, hence the JSON formatting, and that this is on a standalone server.

       

       

      {

                  "thread-id" => 1381L,

                  "thread-name" => "EJB default - 220",

                  "thread-state" => "BLOCKED",

                  "blocked-time" => -1L,

                  "blocked-count" => 2L,

                  "waited-time" => -1L,

                  "waited-count" => 504L,

                  "lock-info" => {

                      "class-name" => "java.util.ArrayDeque",

                      "identity-hash-code" => 355091095

                  },

                  "lock-name" => "java.util.ArrayDeque@152a4297",

                  "lock-owner-id" => 159L,

                  "lock-owner-name" => "default I/O-14",

                  "stack-trace" => [

                      {

                          "file-name" => "RemoteConnection.java",

                          "line-number" => 300,

                          "class-name" => "org.jboss.remoting3.remote.RemoteConnection$RemoteWriteListener",

                          "method-name" => "send",

                          "native-method" => false

                      },

                      {

                          "file-name" => "RemoteConnection.java",

                          "line-number" => 123,

                          "class-name" => "org.jboss.remoting3.remote.RemoteConnection",

                          "method-name" => "send",

                          "native-method" => false

                      },

                      {

                          "file-name" => "OutboundMessage.java",

                          "line-number" => 154,

                          "class-name" => "org.jboss.remoting3.remote.OutboundMessage$1",

                          "method-name" => "accept",

                          "native-method" => false

                      },

                      {

                          "file-name" => "BufferPipeOutputStream.java",

                          "line-number" => 122,

                          "class-name" => "org.xnio.streams.BufferPipeOutputStream",

                          "method-name" => "send",

                          "native-method" => false

                      },

                      {

                          "file-name" => "BufferPipeOutputStream.java",

                          "line-number" => 110,

                          "class-name" => "org.xnio.streams.BufferPipeOutputStream",

                          "method-name" => "send",

                          "native-method" => false

                      },

                      {

                          "file-name" => "BufferPipeOutputStream.java",

                          "line-number" => 139,

                          "class-name" => "org.xnio.streams.BufferPipeOutputStream",

                          "method-name" => "flush",

                          "native-method" => false

                      },

                      {

                          "file-name" => "BufferPipeOutputStream.java",

                          "line-number" => 131,

                          "class-name" => "org.xnio.streams.BufferPipeOutputStream",

                          "method-name" => "flush",

                          "native-method" => false

                      },

                      {

                          "file-name" => "OutboundMessage.java",

                          "line-number" => 277,

                          "class-name" => "org.jboss.remoting3.remote.OutboundMessage",

                          "method-name" => "flush",

                          "native-method" => false

                      },

                      {

                          "file-name" => "DataOutputStream.java",

                          "line-number" => 123,

                          "class-name" => "java.io.DataOutputStream",

                          "method-name" => "flush",

                          "native-method" => false

                      },

                      {

                          "file-name" => "FilterOutputStream.java",

                          "line-number" => 158,

                          "class-name" => "java.io.FilterOutputStream",

                          "method-name" => "close",

                          "native-method" => false

                      },

                      {

                          "file-name" => "IoUtils.java",

                          "line-number" => 134,

                          "class-name" => "org.xnio.IoUtils",

                          "method-name" => "safeClose",

                          "native-method" => false

                      },

                      {

                          "file-name" => "MethodInvocationMessageHandler.java",

                          "line-number" => 380,

                          "class-name" => "org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler",

                          "method-name" => "writeMethodInvocationResponse",

                          "native-method" => false

                      },

                      {

                          "file-name" => "MethodInvocationMessageHandler.java",

                          "line-number" => 69,

                          "class-name" => "org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler",

                          "method-name" => "access$600",

                          "native-method" => false

                      },

                      {

                          "file-name" => "MethodInvocationMessageHandler.java",

                          "line-number" => 245,

                          "class-name" => "org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1",

                          "method-name" => "run",

                          "native-method" => false

                      },

                      {

                          "file-name" => "Executors.java",

                          "line-number" => 511,

                          "class-name" => "java.util.concurrent.Executors$RunnableAdapter",

                          "method-name" => "call",

                          "native-method" => false

                      },

                      {

                          "file-name" => "FutureTask.java",

                          "line-number" => 266,

                          "class-name" => "java.util.concurrent.FutureTask",

                          "method-name" => "run",

                          "native-method" => false

                      },

                      {

                          "file-name" => "ThreadPoolExecutor.java",

                          "line-number" => 1142,

                          "class-name" => "java.util.concurrent.ThreadPoolExecutor",

                          "method-name" => "runWorker",

                          "native-method" => false

                      },

                      {

                          "file-name" => "ThreadPoolExecutor.java",

                          "line-number" => 617,

                          "class-name" => "java.util.concurrent.ThreadPoolExecutor$Worker",

                          "method-name" => "run",

                          "native-method" => false

                      },

                      {

                          "file-name" => "Thread.java",

                          "line-number" => 745,

                          "class-name" => "java.lang.Thread",

                          "method-name" => "run",

                          "native-method" => false

                      },

                      {

                          "file-name" => "JBossThread.java",

                          "line-number" => 320,

                          "class-name" => "org.jboss.threads.JBossThread",

                          "method-name" => "run",

                          "native-method" => false

                      }

                  ],

                  "suspended" => false,

                  "in-native" => false,

                  "locked-monitors" => [],

                  "locked-synchronizers" => []

              }

       

      {

                  "thread-id" => 159L,

                  "thread-name" => "default I/O-14",

                  "thread-state" => "BLOCKED",

                  "blocked-time" => -1L,

                  "blocked-count" => 13L,

                  "waited-time" => -1L,

                  "waited-count" => 3L,

                  "lock-info" => {

                      "class-name" => "org.xnio.streams.BufferPipeOutputStream",

                      "identity-hash-code" => 1575379229

                  },

                  "lock-name" => "org.xnio.streams.BufferPipeOutputStream@5de6611d",

                  "lock-owner-id" => 1381L,

                  "lock-owner-name" => "EJB default - 220",

                  "stack-trace" => [

                      {

                          "file-name" => "OutboundMessage.java",

                          "line-number" => 289,

                          "class-name" => "org.jboss.remoting3.remote.OutboundMessage",

                          "method-name" => "cancel",

                          "native-method" => false

                      },

                      {

                          "file-name" => "RemoteConnectionChannel.java",

                          "line-number" => 560,

                          "class-name" => "org.jboss.remoting3.remote.RemoteConnectionChannel",

                          "method-name" => "closeMessages",

                          "native-method" => false

                      },

                      {

                          "file-name" => "RemoteConnectionChannel.java",

                          "line-number" => 542,

                          "class-name" => "org.jboss.remoting3.remote.RemoteConnectionChannel",

                          "method-name" => "closeAction",

                          "native-method" => false

                      },

                      {

                          "file-name" => "AbstractHandleableCloseable.java",

                          "line-number" => 372,

                          "class-name" => "org.jboss.remoting3.spi.AbstractHandleableCloseable",

                          "method-name" => "closeAsync",

                          "native-method" => false

                      },

                      {

                          "file-name" => "RemoteConnectionHandler.java",

                          "line-number" => 429,

                          "class-name" => "org.jboss.remoting3.remote.RemoteConnectionHandler",

                          "method-name" => "closeAllChannels",

                          "native-method" => false

                      },

                      {

                          "file-name" => "RemoteConnectionHandler.java",

                          "line-number" => 233,

                          "class-name" => "org.jboss.remoting3.remote.RemoteConnectionHandler",

                          "method-name" => "sendCloseRequest",

                          "native-method" => false

                      },

                      {

                          "file-name" => "RemoteConnectionHandler.java",

                          "line-number" => 113,

                          "class-name" => "org.jboss.remoting3.remote.RemoteConnectionHandler",

                          "method-name" => "handleConnectionClose",

                          "native-method" => false

                      },

                      {

                          "file-name" => "RemoteReadListener.java",

                          "line-number" => 82,

                          "class-name" => "org.jboss.remoting3.remote.RemoteReadListener",

                          "method-name" => "handleEvent",

                          "native-method" => false

                      },

                      {

                          "file-name" => "RemoteReadListener.java",

                          "line-number" => 45,

                          "class-name" => "org.jboss.remoting3.remote.RemoteReadListener",

                          "method-name" => "handleEvent",

                          "native-method" => false

                      },

                      {

                          "file-name" => "ChannelListeners.java",

                          "line-number" => 92,

                          "class-name" => "org.xnio.ChannelListeners",

                          "method-name" => "invokeChannelListener",

                          "native-method" => false

                      },

                      {

                          "file-name" => "TranslatingSuspendableChannel.java",

                          "line-number" => 199,

                          "class-name" => "org.xnio.channels.TranslatingSuspendableChannel",

                          "method-name" => "handleReadable",

                          "native-method" => false

                      },

                      {

                          "file-name" => "TranslatingSuspendableChannel.java",

                          "line-number" => 113,

                          "class-name" => "org.xnio.channels.TranslatingSuspendableChannel$1",

                          "method-name" => "handleEvent",

                          "native-method" => false

                      },

                      {

                          "file-name" => "ChannelListeners.java",

                          "line-number" => 92,

                          "class-name" => "org.xnio.ChannelListeners",

                          "method-name" => "invokeChannelListener",

                          "native-method" => false

                      },

                      {

                          "file-name" => "ChannelListeners.java",

                          "line-number" => 1092,

                          "class-name" => "org.xnio.ChannelListeners$DelegatingChannelListener",

                          "method-name" => "handleEvent",

                          "native-method" => false

                      },

                      {

                          "file-name" => "ChannelListeners.java",

                          "line-number" => 92,

                          "class-name" => "org.xnio.ChannelListeners",

                          "method-name" => "invokeChannelListener",

                          "native-method" => false

                      },

                      {

                          "file-name" => "ReadReadyHandler.java",

                          "line-number" => 66,

                          "class-name" => "org.xnio.conduits.ReadReadyHandler$ChannelListenerHandler",

                          "method-name" => "readReady",

                          "native-method" => false

                      },

                      {

                          "file-name" => "NioSocketConduit.java",

                          "line-number" => 88,

                          "class-name" => "org.xnio.nio.NioSocketConduit",

                          "method-name" => "handleReady",

                          "native-method" => false

                      },

                      {

                          "file-name" => "WorkerThread.java",

                          "line-number" => 539,

                          "class-name" => "org.xnio.nio.WorkerThread",

                          "method-name" => "run",

                          "native-method" => false

                      }

                  ],

                  "suspended" => false,

                  "in-native" => false,

                  "locked-monitors" => [],

                  "locked-synchronizers" => []

              }

        • 1. Re: Remoting Deadlock in WildFly 9.0.2.Final?
          jaikiran

          Josh Fisher wrote:

           

          We need to do something about this, but we don't know what that is.

           

          The main questions we have are:

          - First and foremost, is this a library issue or something else?

          - If it is a library issue, do we need to upgrade something, whether that's the Remoting library or WildFly itself?

          This is pretty much an issue in the (internal) libraries of WildFly and not your application code. Upgrading just remoting library may not be the solution (there might be some XNIO upgrade needed too, based on some of the issues in this area that were fixed). I would highly recommend upgrading WildFly itself.

          • 2. Re: Remoting Deadlock in WildFly 9.0.2.Final?
            jfisherdev

            Jaikiran,

             

            As always, thank you for responding.

             

            Long term we are looking at upgrading to a newer release of WildFly, but short term we are looking at patching the remoting subsystem. A couple of my colleagues have been testing out remoting 4.14 and it seems to be working so far. I still think something in a particular application is inducing this state, given that we have pretty much only seen this when a particular application is deployed.  I'm not sure that it actually fixes the issue, but it's worth a try.

             

            I'm not sure if it means anything, but I should mention that around the time this is reported, we see this in the logs:

             

            ERROR [org.jboss.as.ejb3] WFLYEJB0150: Could not write method invocation failure for method $method$ on bean named $bean-name$ for appname $app-name$ modulename $module-name$ distinctname  due to: java.io.IOException: WFLYEJB0422: Could not open message outputstream for writing to Channel

            at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.writeMethodInvocationResponse(MethodInvocationMessageHandler.java:364)

            at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.access$600(MethodInvocationMessageHandler.java:69)

            at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler$1.run(MethodInvocationMessageHandler.java:245)

            at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)

            at java.util.concurrent.FutureTask.run(FutureTask.java:266)

            at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)

            at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)

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

            at org.jboss.threads.JBossThread.run(JBossThread.java:320)

            Caused by: org.jboss.remoting3.NotOpenException: Writes closed

            at org.jboss.remoting3.remote.RemoteConnectionChannel.openOutboundMessage(RemoteConnectionChannel.java:117)

            at org.jboss.remoting3.remote.RemoteConnectionChannel.writeMessage(RemoteConnectionChannel.java:306)

            at org.jboss.as.ejb3.remote.protocol.versionone.ChannelAssociation.acquireChannelMessageOutputStream(ChannelAssociation.java:68)

            at org.jboss.as.ejb3.remote.protocol.versionone.MethodInvocationMessageHandler.writeMethodInvocationResponse(MethodInvocationMessageHandler.java:362)

            ... 8 more

             

            I will be sure to add a follow-up post with our findings.

            • 3. Re: Remoting Deadlock in WildFly 9.0.2.Final?
              jfisherdev

              I meant to follow up on this much sooner, but patching WildFly 9.0.2.final with jboss-remoting 4.0.14 seems to have resolved the deadlock issues we were encountering. While it makes sense that the changes in 4.0.14 to RemoteReadListener [specifically this commit Avoid a possible deadlock when writing a message at the same time tha… · jboss-remoting/jboss-remoting@ef6a84d · GitHub ], I suspect that a specific application is doing something unusual [since it only seemed to happen when that application was deployed] that I could see [REM3-226] Deadlock when connection is closing while we are writing - JBoss Issue Tracker being marked as cannot reproduce.

               

              As Jaikiran noted, it would be best to upgrade to a newer version of WildFly, which we hope to do in the near future.

               

              Thank you.