Embedded Jetty stops responding and then hangs while stopping #6059

bhawani1978 · 2021-03-12T07:40:08Z

Jetty version 9.4.33.v20201020

Java version JRE-8u271

OS type/version Windows Server

We are running embedded jetty in our java application, and perform a health check by calling a simple webservice, which just returns a success status. This health check done in main thread about every 1 minute and if we don't get response in time out interval (20 seconds), then we try to restart embedded jetty server by calling stop and later start method. We have noticed sometimes, we don’t see any trace for health check call in jetty log but we see other request are being served. Than after 20 sec we receive time out socketException, main thread thinks, service is not in good status and try to restart jetty, and then it hangs in stop.

From time to time we see this TimeoutException though:
java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:171)
at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113)
at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
at java.util.concurrent.FutureTask.run(Unknown Source)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(Unknown Source)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)

attaching rest of the jetty longs.
jetty-hang-log.zip

sbordet · 2021-03-12T09:42:16Z

Sorry, it's not clear what you're doing, nor where the problem is.

From your logs I see server-side logs when from your description you have a problem in the client, so it's not clear if you have a client problem contacting an external webservice, or you also run the webservice with Jetty?
Is the problem in the client or in the server?

It's not clear what you mean by "restart Jetty" because you're speaking about the client, while "Jetty" typically indicates the server.

Also from your logs, the server is just idle and perfectly working (it just served a request few seconds before the end of the logs).

Also from your logs, you seem to use custom extensions of Jetty classes (WorkaroundManagedSelector) which may be buggy.

I doubt it's Jetty the problem here. I would double check your application.

joakime · 2021-03-12T12:28:06Z

Idle timeout rarely point at anything useful for troubleshooting this.
It only means you have a client connection that hasn't been closed by either the client or server side.

When you experience a "hung jetty", do the following, before your restart.

Collect the Server State Dump - https://www.eclipse.org/jetty/documentation/jetty-9/index.html#jetty-server-dump
- Make sure you have QueuedThreadPool.setDetailDump(true) set at server startup before you experience these issues
Make requests to the server that you know will fail with a response from Jetty, not your Application.
- Request something that will result in a 400 bad request
- Request something against a context that you don't have registered (should result in a 404)
- If you have multiple connectors, request something against the other connectors

Some example requests ...

# 400 request
$ curl -vvv http://localhost:8080/"hello world"
*   Trying 127.0.0.1:8080...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 8080 (#0)
> GET /hello world HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.68.0
> Accept: */*
> 
* Mark bundle as not supporting multiuse
< HTTP/1.1 400 Illegal character SPACE=' '
< Content-Type: text/html;charset=iso-8859-1
< Content-Length: 70
< Connection: close
< Server: Jetty(9.4.38.v20210224)
< 
* Closing connection 0
<h1>Bad Message 400</h1><pre>reason: Illegal character SPACE=' '</pre>

$ curl -vvv -H "Content-Length: abc" http://localhost:8080/
*   Trying 127.0.0.1:8080...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 8080 (#0)
> GET / HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.68.0
> Accept: */*
> Content-Length: abc
> 
* Mark bundle as not supporting multiuse
< HTTP/1.1 400 Invalid Content-Length Value
< Content-Type: text/html;charset=iso-8859-1
< Content-Length: 71
< Connection: close
< Server: Jetty(9.4.38.v20210224)
< 
* Closing connection 0
<h1>Bad Message 400</h1><pre>reason: Invalid Content-Length Value</pre>

# 404 requests
$ curl -vvv http://localhost:8080/%2e;/
*   Trying 127.0.0.1:8080...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 8080 (#0)
> GET /%2e HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.68.0
> Accept: */*
> 
* Mark bundle as not supporting multiuse
< HTTP/1.1 404 Not Found
< Cache-Control: must-revalidate,no-cache,no-store
< Content-Type: text/html;charset=iso-8859-1
< Content-Length: 441
< Server: Jetty(9.4.38.v20210224)
< 
<html>
<head>
<meta http-equiv="Content-Type" content="text/html;charset=utf-8"/>
<title>Error 404 Not Found</title>
</head>
<body><h2>HTTP ERROR 404 Not Found</h2>
<table>
<tr><th>URI:</th><td>/%2e</td></tr>
<tr><th>STATUS:</th><td>404</td></tr>
<tr><th>MESSAGE:</th><td>Not Found</td></tr>
<tr><th>SERVLET:</th><td>-</td></tr>
</table>
<hr><a href="https://eclipse.org/jetty">Powered by Jetty:// 9.4.38.v20210224</a><hr/>

</body>
</html>
$ echo -e "GET ??? HTTP/1.1\r\nHost: localhost\r\nConnection: close\r\n\r\n" | nc localhost 8080
HTTP/1.1 400 Bad URI
Content-Type: text/html;charset=iso-8859-1
Content-Length: 50
Connection: close
Server: Jetty(9.4.38.v20210224)

<h1>Bad Message 400</h1><pre>reason: Bad URI</pre>

What we are trying to do is understand the state of your server. (the server dump helps here)

And we are trying to isolate WHERE in the server you are experiencing the problems.
Is Jetty truly hung? (the only way we've experienced this is due to misconfigured thread pools)
Is the application hung? (the requests for content that doesn't pass through your application tests this)
Is something else impacting you? (eg: database pools)

bhawani1978 · 2021-03-16T06:28:56Z

Sorry, it's not clear what you're doing, nor where the problem is.

From your logs I see server-side logs when from your description you have a problem in the client, so it's not clear if you have a client problem contacting an external webservice, or you also run the webservice with Jetty?
Is the problem in the client or in the server?

It's not clear what you mean by "restart Jetty" because you're speaking about the client, while "Jetty" typically indicates the server.

Also from your logs, the server is just idle and perfectly working (it just served a request few seconds before the end of the logs).

Also from your logs, you seem to use custom extensions of Jetty classes (WorkaroundManagedSelector) which may be buggy.

I doubt it's Jetty the problem here. I would double check your application.

I mean Restart jetty, by calling server.stop() and then server.start().

bhawani1978 · 2021-03-16T06:35:38Z

I see two jetty threads waiting at WindowsSelectorImpl$SubSelector.poll0, rest are at Unsafe.park.

"qtp2056418216-11752" Id=11752 TIMED_WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@110f2e5d
at sun.misc.Unsafe.park(Native Method)
- waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@110f2e5d
at java.util.concurrent.locks.LockSupport.parkNanos(Unknown Source)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(Unknown Source)
at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:382)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.idleJobPoll(QueuedThreadPool.java:842)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:892)
at java.lang.Thread.run(Unknown Source)

"qtp2056418216-11747" Id=11747 TIMED_WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@110f2e5d
at sun.misc.Unsafe.park(Native Method)
- waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@110f2e5d
at java.util.concurrent.locks.LockSupport.parkNanos(Unknown Source)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(Unknown Source)
at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:382)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.idleJobPoll(QueuedThreadPool.java:842)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:892)
at java.lang.Thread.run(Unknown Source)

"qtp2056418216-11729" Id=11729 RUNNABLE (in native)
at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method)
at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(Unknown Source)
at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(Unknown Source)
at sun.nio.ch.WindowsSelectorImpl.doSelect(Unknown Source)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(Unknown Source)
- locked sun.nio.ch.Util$3@536e4a6f
- locked java.util.Collections$UnmodifiableSet@5a73c6fc
- locked sun.nio.ch.WindowsSelectorImpl@794a8e66
at sun.nio.ch.SelectorImpl.select(Unknown Source)
at sun.nio.ch.SelectorImpl.select(Unknown Source)
at org.eclipse.jetty.io.ManagedSelector.nioSelect(ManagedSelector.java:149)
at org.eclipse.jetty.server.WorkaroundManagedSelector.nioSelect(WorkaroundManagedSelector.java:41)
at org.eclipse.jetty.io.ManagedSelector.select(ManagedSelector.java:156)
at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.java:572)
at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:509)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:360)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:184)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:773)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:905)
at java.lang.Thread.run(Unknown Source)

"qtp2056418216-11678" Id=11678 RUNNABLE (in native)
at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method)
at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(Unknown Source)
at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(Unknown Source)
at sun.nio.ch.WindowsSelectorImpl.doSelect(Unknown Source)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(Unknown Source)
- locked sun.nio.ch.Util$3@115f2ad4
- locked java.util.Collections$UnmodifiableSet@304337a2
- locked sun.nio.ch.WindowsSelectorImpl@74c34370
at sun.nio.ch.SelectorImpl.select(Unknown Source)
at sun.nio.ch.SelectorImpl.select(Unknown Source)
at org.eclipse.jetty.io.ManagedSelector.nioSelect(ManagedSelector.java:149)
at org.eclipse.jetty.server.WorkaroundManagedSelector.nioSelect(WorkaroundManagedSelector.java:41)
at org.eclipse.jetty.io.ManagedSelector.select(ManagedSelector.java:156)
at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.java:572)
at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:509)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:360)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:184)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:773)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:905)
at java.lang.Thread.run(Unknown Source)

"qtp2056418216-11657" Id=11657 TIMED_WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@110f2e5d
at sun.misc.Unsafe.park(Native Method)
- waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@110f2e5d
at java.util.concurrent.locks.LockSupport.parkNanos(Unknown Source)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(Unknown Source)
at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:382)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.idleJobPoll(QueuedThreadPool.java:842)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:892)
at java.lang.Thread.run(Unknown Source)

To monitor service performance, we have a WS client within this program, with 20 second timeout, test service, simply returns a String. When this client fails due to time out, program tries to restart by stoping embeded server and starting it, where it seems it gets stuck.
"main" Id=1 WAITING on java.util.concurrent.CountDownLatch$Sync@145dc24a
at sun.misc.Unsafe.park(Native Method)
- waiting on java.util.concurrent.CountDownLatch$Sync@145dc24a
at java.util.concurrent.locks.LockSupport.park(Unknown Source)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(Unknown Source)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(Unknown Source)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(Unknown Source)
at java.util.concurrent.CountDownLatch.await(Unknown Source)
at org.eclipse.jetty.io.ManagedSelector.doStop(ManagedSelector.java:136)
at org.eclipse.jetty.util.component.AbstractLifeCycle.stop(AbstractLifeCycle.java:93)
- locked java.lang.Object@5bef5e7d
at org.eclipse.jetty.util.component.ContainerLifeCycle.stop(ContainerLifeCycle.java:180)
at org.eclipse.jetty.util.component.ContainerLifeCycle.doStop(ContainerLifeCycle.java:201)
at org.eclipse.jetty.io.SelectorManager.doStop(SelectorManager.java:281)
at org.eclipse.jetty.util.component.AbstractLifeCycle.stop(AbstractLifeCycle.java:93)
- locked java.lang.Object@36820335
at org.eclipse.jetty.util.component.ContainerLifeCycle.stop(ContainerLifeCycle.java:180)
at org.eclipse.jetty.util.component.ContainerLifeCycle.doStop(ContainerLifeCycle.java:201)
at org.eclipse.jetty.server.AbstractConnector.doStop(AbstractConnector.java:374)
at org.eclipse.jetty.server.AbstractNetworkConnector.doStop(AbstractNetworkConnector.java:88)
at org.eclipse.jetty.server.ServerConnector.doStop(ServerConnector.java:246)
at org.eclipse.jetty.util.component.AbstractLifeCycle.stop(AbstractLifeCycle.java:93)
- locked java.lang.Object@1bae2c24
at org.eclipse.jetty.server.Server.doStop(Server.java:459)
at org.eclipse.jetty.util.component.AbstractLifeCycle.stop(AbstractLifeCycle.java:93)
- locked java.lang.Object@35e06e3d
at com.fis.IU.FrameWork.ISWebServerJetty.stopWorking(ISWebServerJetty.java:278)

sbordet · 2021-03-16T10:41:39Z

I see two jetty threads waiting at WindowsSelectorImpl$SubSelector.poll0, rest are at Unsafe.park.

That's normal.

To monitor service performance, we have a WS client within this program, with 20 second timeout, test service, simply returns a String. When this client fails due to time out, program tries to restart by stoping embeded server and starting it, where it seems it gets stuck.

You should report what happens when this client fails, and in what status the server is when the server fails.
Please call Server.dump() and report the resulting string in this issue.

So far, what you have reported is a normally, perfectly working server.
We need to know exactly what happens at the moment the client fails.

joakime · 2021-03-16T14:05:53Z

@bhawani1978 what are the results of the information collection outlined in my prior comment?

bhawani1978 · 2021-03-16T16:24:45Z

As of now we are not taking server.dump before stopping. We will make changes to capture before trying to restart.

Also are we having time out of 20 seconds too low before trying to restart, which is causing the problem while stuck in stop.

joakime · 2021-03-16T19:09:16Z

Keep in mind that we are not asking for a memory dump, or a class dump, or any other kind of normal JVM dump.

We are specifically asking for a Jetty Server.dump().
You can access this from JMX as an operation on the server.

bhawani1978 · 2021-04-20T20:05:50Z

We are able to get the server dump when this issue is happening.
jetty_dump.txt

Clients requests are getting time out. Seems old connections are not getting cleaned up, please let us your view.

sbordet · 2021-04-20T20:41:19Z

@bhawani1978 the dump you report shows that the selector threads are gone, and update tasks are accumulating into the selectors, but there is no thread to run them (nor to perform the select operation).

You appear to be running some custom code (WorkaroundManagedSelector), so unless we know exactly what is your code doing, we cannot know what's going on.

Unfortunately Windows's NIO implementation in OpenJDK is not as stable as Linux's so there is not much we can do.
One option for you is to try and use Java 13 or later, can you try that?
In Java 13 the whole socket implementation has been rewritten, so there may be a chance that you don't need any workaround for NIO on Windows (not a guarantee, but worth a try).

What is it that you are working around in WorkaroundManagedSelector?
Are you sure you are doing the right thing? I ask because the selector threads are gone and I suspect that it is your workaround that makes them go, and that is not good.

bhawani1978 · 2021-04-20T20:43:56Z

Hi @sbordet, we used https://github.com/jetty-project/selector-hack as suggested in #2205.

sbordet · 2021-04-20T21:03:00Z

@bhawani1978 have you actually hit the Windows selector spin problem so that you need the workaround?

The code you are using is highly experimental as written in the projects README, so there might be a chance that it does not work in your case.

I don't see how WorkaroundManagedSelector could kill the selector thread, so there must be something else going on that causes another issue that makes the selector thread go away.

You should have logging in your logs that the selector has been rebuilt, and if the selector thread is gone you should have some stack trace of that too in the logs.

bhawani1978 · 2021-04-22T03:38:07Z

On one of the environment, we see that issue starts intermittently and finally over a day or so, it completly stalls it. I was able to get current jetty logs in debug, thread dump and server dump, when its working but on and off.

jetty_logs.log
jetty_server_dump.txt
jetty_thread_dump.txt

sbordet · 2021-04-22T13:05:22Z

@bhawani1978 I can see the selecting threads, but the selectors are in a borked state.

Can you please call QueuedThreadPool.setDetailedDump(true) either in the code or via JMX, and dump the server again with this new setting and the system in borked state?

Also, can you please compare and tell us if your WorkaroundManagedSelector is exactly equal to what we have in the experimental project?
I ask because the minimum code change in this component may render the server invalid.

I hate to say, but I have to, can you move to Linux?
I mean, even if we get this one worked around properly (which is not guaranteed), how long before you hit another Windows NIO issue?

bhawani1978 · 2021-04-22T18:51:58Z

@sbordet thanks for the update.

Our WorkaroundManagedSelector and WorkaroundServerConnector is exactly same, line by line. I will try to enable QueuedThreadPool.setDetailedDump(true) get more details. Also we are thinking about moving to Linux but will take sometime.

Also I noticed that issue starts with intermittent timeout for some requests, where one fails one time passes next time. It takes hours before completely shutting this down for us.

github-actions · 2022-04-23T00:00:21Z

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 · 2022-05-24T00:00:23Z

This issue has been closed due to it having no activity.

joakime added the More Info Required label Mar 16, 2021

swathikumar4precisely mentioned this issue May 4, 2021

Embedded Jetty becomes unresponsive - though the server says it's started successfully, the netstat shows no port tied to the server #6233

Closed

github-actions bot added the Stale For auto-closed stale issues and pull requests label Apr 23, 2022

github-actions bot closed this as completed May 24, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Embedded Jetty stops responding and then hangs while stopping #6059

Embedded Jetty stops responding and then hangs while stopping #6059

bhawani1978 commented Mar 12, 2021

sbordet commented Mar 12, 2021

joakime commented Mar 12, 2021 •

edited

Loading

bhawani1978 commented Mar 16, 2021

bhawani1978 commented Mar 16, 2021

sbordet commented Mar 16, 2021

joakime commented Mar 16, 2021

bhawani1978 commented Mar 16, 2021

joakime commented Mar 16, 2021

bhawani1978 commented Apr 20, 2021

sbordet commented Apr 20, 2021

bhawani1978 commented Apr 20, 2021

sbordet commented Apr 20, 2021

bhawani1978 commented Apr 22, 2021

sbordet commented Apr 22, 2021

bhawani1978 commented Apr 22, 2021

github-actions bot commented Apr 23, 2022

github-actions bot commented May 24, 2022

Embedded Jetty stops responding and then hangs while stopping #6059

Embedded Jetty stops responding and then hangs while stopping #6059

Comments

bhawani1978 commented Mar 12, 2021

sbordet commented Mar 12, 2021

joakime commented Mar 12, 2021 • edited Loading

bhawani1978 commented Mar 16, 2021

bhawani1978 commented Mar 16, 2021

sbordet commented Mar 16, 2021

joakime commented Mar 16, 2021

bhawani1978 commented Mar 16, 2021

joakime commented Mar 16, 2021

bhawani1978 commented Apr 20, 2021

sbordet commented Apr 20, 2021

bhawani1978 commented Apr 20, 2021

sbordet commented Apr 20, 2021

bhawani1978 commented Apr 22, 2021

sbordet commented Apr 22, 2021

bhawani1978 commented Apr 22, 2021

github-actions bot commented Apr 23, 2022

github-actions bot commented May 24, 2022

joakime commented Mar 12, 2021 •

edited

Loading