Connection limit problem for "onAccepting" connections

[ecejnj42]

This problem was found on jetty version 9.4.43.v20210629.

There is a problem for the Connection Limit functionality relative to "onAccepting" connections.
The problem appears when the system/jetty is heavily overload. In such situations, the counter for "onAccepting" connections in ConnectionLimit is not properly updated.
In particular, the counter is increased when there is an "accept" connection, but due to overload problem, the connection could be closed. In those cases the counter for the connection limit is not decreased and the "accepting" connection part of the counter holds and incorrect value for ever.

This could be seen in the logs for ConnectionLimit class:

_2022-02-01T09:34:51.769Z onAccepting (12+2) < 20 java.nio.channels.SocketChannel[connected  local=/0:0:0:0:0:0:0:1:8080remote=/0:0:0:0:0:0:0:1:47054]
2022-02-01T09:36:47.789Z onAccepting (13+1) < 20 java.nio.channels.SocketChannel[connected local=/0:0:0:0:0:0:0:1:8080 remote=/0:0:0:0:0:0:0:1:47760]_ 

It can be checked with "ss" linux command that there are no accepting/incoming connections:

>ss -apnt | grep 8080


LISTEN        0          50                                         *:8080                                  *:*      users:(("java",pid=5605,fd=34))            
ESTAB         0          0                                      [::1]:59128                             [::1]:8080   users:(("overload-monito",pid=6615,fd=15)) 
ESTAB         0          0                                      [::1]:8080                              [::1]:59128  users:(("java",pid=5605,fd=39))        

The logs "onAccepting (13+1)" shows there are 13 "accepting" connections and 1 connection established, but "ss" command shows no accepting connections and only the one established.
The problem is that this "accepting" could grow a lot in such overloaded situations, causing the limit to fail without real reason.
In our case we have these limit set to 20, and "accepting" connections sometimes had a value of 18, so opening a few connections just forced the connection to fail with usual log:

org.eclipse.jetty.server.ConnectionLimit Connection Limit(20) reached for [ServerConnector@4613311f{HTTP/1.1, (http/1.1, h2c)} 0.0.0.0:8080}]

Looking throw jetty-io code, we found that the problem is in the following class/file: ManagedSelector.java

The issue is in the following part:

private void execute(Runnable task)
  {
      try
      {
          _selectorManager.execute(task);
      }
      catch (RejectedExecutionException x)
      {
          if (task instanceof Closeable)
              IO.close((Closeable)task);
      }
  }

The task is closed in case of the described exception, that could be raised in some overloaded conditions according to Oracle docs:

"New tasks submitted in method execute(Runnable) will be rejected when the Executor has been shut down, and also when the Executor uses finite bounds for both maximum threads and work queue capacity, and is saturated."

As stated previously, in such cases the task is closed, but in this particular case the task is a "ManagedSelector.Accept" class, which on the close method does not decrease any counter.
I checked that the log for this "close" appears when the counter is not properly decreased and manually added some code to force decreasing the counter:

         @Override
         public void close()
         {
             if (LOG.isDebugEnabled())
                 LOG.debug("closed accept of {}", channel);
+
+            _selectorManager.onAcceptFailed(channel, new RejectedExecutionException("closing"));
             IO.close(channel);
         }
 

This seems to fix that problem of incorrect counting the "accepting" connections, but probably it could have other collateral issues which I cannot identify.
Could you check the fix and provide a general solution to the problem?

BR,
Jorge.

[ecejnj42]

Hi

I have created a test that shows the error in detail.
Jetty_Test.zip
The test is included in attached project. To see the error just issue:

mvn test -Dtest=JettySimpleConnectionLimitTest

All the details are in the readme of the project.
The test uses a custom pool that could be instructed to reject jobs with exception RejectedExecutionException. As stated in my previous comment, this causes the "onAccepting" counter for ConnectionLimit to not be decreased.
The logs show how the "onAccepting" part of the counters get increased but not decreased, causing later connections to hang due to "ConnectionLimit reached" problem.

07:04:36.168 [pool-1-thread-2-acceptor-0@36cda2c2-ServerConnector@295cf707{HTTP/1.1, (http/1.1)}{0.0.0.0:8090}] DEBUG o.e.jetty.server.ConnectionLimit - onAccepting (1+2) < 6 java.nio.channels.SocketChannel[connected local=/127.0.0.1:8090 remote=/127.0.0.1:60412]
07:04:36.184 [pool-1-thread-2-acceptor-0@36cda2c2-ServerConnector@295cf707{HTTP/1.1, (http/1.1)}{0.0.0.0:8090}] DEBUG o.e.jetty.server.ConnectionLimit - onAccepting (2+2) < 6 java.nio.channels.SocketChannel[connected local=/127.0.0.1:8090 remote=/127.0.0.1:60414]
07:04:36.200 [pool-1-thread-2-acceptor-0@36cda2c2-ServerConnector@295cf707{HTTP/1.1, (http/1.1)}{0.0.0.0:8090}] DEBUG o.e.jetty.server.ConnectionLimit - onAccepting (3+2) < 6 java.nio.channels.SocketChannel[connected local=/127.0.0.1:8090
07:04:36.211 07:04:36.211 [pool-1-thread-2-acceptor-0@36cda2c2-ServerConnector@295cf707{HTTP/1.1, (http/1.1)}{0.0.0.0:8090}] DEBUG o.e.jetty.server.ConnectionLimit - onAccepting (4+2) < 6 java.nio.channels.SocketChannel[connected local=/127.0.0.1:8090 remote=/127.0.0.1:60418]
...
07:04:36.211 [pool-1-thread-2-acceptor-0@36cda2c2-ServerConnector@295cf707{HTTP/1.1, (http/1.1)}{0.0.0.0:8090}] INFO o.e.jetty.server.ConnectionLimit - Connection Limit(6) reached for [ServerConnector@295cf707{HTTP/1.1, (http/1.1)}{0.0.0.0:8090}]

Note this test should pass when error is fixed on "ManagedSelector.Accept"

BR,
Jorge.

[github-actions]

This issue has been automatically marked as stale because it has been a
full year without activity. It will be closed if no further activity occurs.
Thank you for your contributions.

[github-actions]

This issue has been automatically marked as stale because it has been a
full year without activity. It will be closed if no further activity occurs.
Thank you for your contributions.

[sbordet]

FTR, this problem only happens when the thread pool queue is bounded, which should not be, see https://jetty.org/docs/jetty/12/programming-guide/arch/threads.html#thread-pool.

Having said that, we have a fix for this corner case in #12320.