Jetty 服务器为 REST 调用抛出空闲超时

【问题标题】：Jetty server throws idle timeout for REST callsJetty 服务器为 REST 调用抛出空闲超时
【发布时间】：2021-08-18 23:41:26
【问题描述】：

我有一个非常简单的代码 sn-p 来测试 Jetty server 9.4.41。在调试级别日志中，我看到了超时异常。我知道它与空闲超时有关，并且在连接上没有读/写活动时发生。但我只是想知道，我是否应该在日志中获取异常？在我看来，有些事情是不对的。如果有人能帮助理解我为什么会得到这个，我将不胜感激。

这是我的 Jetty 服务器代码：

public class JettyServer {
    private Server server;

    public void start() throws Exception {
        server = new Server();
        ServerConnector connector = new ServerConnector(server);
        connector.setPort(8090);
        connector.setIdleTimeout(30000);
        server.setConnectors(new Connector[]{connector});

        ServletContextHandler handler = new ServletContextHandler(server, "/example");
        handler.addServlet(ExampleServlet.class, "/");

        server.start();
    }
}

我的 Main 方法只是启动了这个服务器，而 ExampleServlet.class 只是为请求返回一个简单的成功响应：{ "status": "ok"}。响应只需 50 毫秒（使用任何 REST 客户端，或使用浏览器调用 API）。

这是生成响应的 servlet 代码：

public class ExampleServlet extends HttpServlet {

    protected void doGet(
            HttpServletRequest request,
            HttpServletResponse response)
            throws ServletException, IOException {
        response.setContentType("application/json");
        response.setStatus(HttpServletResponse.SC_OK);

        response.getWriter().println("{ \"status\": \"ok\"}");
    }
}

这是我在调试级别日志中看到的异常：

2021-05-30 02:49:42.979:DBUG:oeji.IdleTimeout:Connector-Scheduler-289d1c02-1: SocketChannelEndPoint@976b06a{l=/0:0:0:0:0:0:0:1:8090,r=/0:0:0:0:0:0:0:1:58250,OPEN,fill=FI,flush=-,to=29990/30000}{io=1/1,kio=1,kro=1}->HttpConnection@45004b9a[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3d68f9d0{s=START}]=>HttpChannelOverHttp@d49259c{s=HttpChannelState@484bba51{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0} idle timeout check, elapsed: 29989 ms, remaining: 11 ms
2021-05-30 02:49:42.995:DBUG:oeji.IdleTimeout:Connector-Scheduler-289d1c02-1: SocketChannelEndPoint@976b06a{l=/0:0:0:0:0:0:0:1:8090,r=/0:0:0:0:0:0:0:1:58250,OPEN,fill=FI,flush=-,to=30005/30000}{io=1/1,kio=1,kro=1}->HttpConnection@45004b9a[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3d68f9d0{s=START}]=>HttpChannelOverHttp@d49259c{s=HttpChannelState@484bba51{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0} idle timeout check, elapsed: 30005 ms, remaining: -5 ms
2021-05-30 02:49:42.996:DBUG:oeji.IdleTimeout:Connector-Scheduler-289d1c02-1: SocketChannelEndPoint@976b06a{l=/0:0:0:0:0:0:0:1:8090,r=/0:0:0:0:0:0:0:1:58250,OPEN,fill=FI,flush=-,to=30006/30000}{io=1/1,kio=1,kro=1}->HttpConnection@45004b9a[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3d68f9d0{s=START}]=>HttpChannelOverHttp@d49259c{s=HttpChannelState@484bba51{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0} idle timeout expired
2021-05-30 02:49:42.997:DBUG:oeji.FillInterest:Connector-Scheduler-289d1c02-1: onFail FillInterest@2864451e{AC.ReadCB@45004b9a{HttpConnection@45004b9a::SocketChannelEndPoint@976b06a{l=/0:0:0:0:0:0:0:1:8090,r=/0:0:0:0:0:0:0:1:58250,OPEN,fill=FI,flush=-,to=30007/30000}{io=1/1,kio=1,kro=1}->HttpConnection@45004b9a[p=HttpParser{s=START,0 of -1},g=HttpGenerator@3d68f9d0{s=START}]=>HttpChannelOverHttp@d49259c{s=HttpChannelState@484bba51{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}}}
java.util.concurrent.TimeoutException: Idle timeout expired: 30005/30000 ms
    at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:171)
    at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:834)
2021-05-30 02:49:42.997:DBUG:oejh.HttpParser:Connector-Scheduler-289d1c02-1: close HttpParser{s=START,0 of -1}
2021-05-30 02:49:42.997:DBUG:oejh.HttpParser:Connector-Scheduler-289d1c02-1: START --> CLOSE
2021-05-30 02:49:42.997:DBUG:oeji.AbstractConnection:Connector-Scheduler-289d1c02-1: HttpConnection@45004b9a::SocketChannelEndPoint@976b06a{l=/0:0:0:0:0:0:0:1:8090,r=/0:0:0:0:0:0:0:1:58250,OPEN,fill=-,flush=-,to=30008/30000}{io=1/1,kio=1,kro=1}->HttpConnection@45004b9a[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@3d68f9d0{s=START}]=>HttpChannelOverHttp@d49259c{s=HttpChannelState@484bba51{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0} onFillInterestedFailed {}
java.util.concurrent.TimeoutException: Idle timeout expired: 30005/30000 ms
    at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:171)
    at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:834)
2021-05-30 02:49:42.998:DBUG:oeji.AbstractEndPoint:Connector-Scheduler-289d1c02-1: shutdownOutput SocketChannelEndPoint@976b06a{l=/0:0:0:0:0:0:0:1:8090,r=/0:0:0:0:0:0:0:1:58250,OPEN,fill=-,flush=-,to=30008/30000}{io=1/1,kio=1,kro=1}->HttpConnection@45004b9a[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@3d68f9d0{s=START}]=>HttpChannelOverHttp@d49259c{s=HttpChannelState@484bba51{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}
2021-05-30 02:49:42.999:DBUG:oeji.AbstractConnection:Connector-Scheduler-289d1c02-1: fillInterested HttpConnection@45004b9a::SocketChannelEndPoint@976b06a{l=/0:0:0:0:0:0:0:1:8090,r=/0:0:0:0:0:0:0:1:58250,OSHUT,fill=-,flush=-,to=30009/30000}{io=1/1,kio=1,kro=1}->HttpConnection@45004b9a[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@3d68f9d0{s=START}]=>HttpChannelOverHttp@d49259c{s=HttpChannelState@484bba51{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}
2021-05-30 02:49:42.999:DBUG:oeji.FillInterest:Connector-Scheduler-289d1c02-1: interested FillInterest@2864451e{AC.ReadCB@45004b9a{HttpConnection@45004b9a::SocketChannelEndPoint@976b06a{l=/0:0:0:0:0:0:0:1:8090,r=/0:0:0:0:0:0:0:1:58250,OSHUT,fill=FI,flush=-,to=0/30000}{io=1/1,kio=1,kro=1}->HttpConnection@45004b9a[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@3d68f9d0{s=START}]=>HttpChannelOverHttp@d49259c{s=HttpChannelState@484bba51{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}}}
2021-05-30 02:49:43.000:DBUG:oeji.ChannelEndPoint:Connector-Scheduler-289d1c02-1: changeInterests p=false 1->1 for SocketChannelEndPoint@976b06a{l=/0:0:0:0:0:0:0:1:8090,r=/0:0:0:0:0:0:0:1:58250,OSHUT,fill=FI,flush=-,to=0/30000}{io=1/1,kio=1,kro=1}->HttpConnection@45004b9a[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@3d68f9d0{s=START}]=>HttpChannelOverHttp@d49259c{s=HttpChannelState@484bba51{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}
2021-05-30 02:49:43.000:DBUG:oeji.ManagedSelector:Connector-Scheduler-289d1c02-1: Queued change lazy=false org.eclipse.jetty.io.ChannelEndPoint$$Lambda$86/0x0000000100123840@6f7f8713 on ManagedSelector@1e730495{STARTED} id=2 keys=1 selected=0 updates=0
2021-05-30 02:49:43.000:DBUG:oeji.ManagedSelector:Connector-Scheduler-289d1c02-1: Wakeup on submit ManagedSelector@1e730495{STARTED} id=2 keys=1 selected=0 updates=1
2021-05-30 02:49:43.001:DBUG:oeji.ManagedSelector:qtp157683534-19: Selector sun.nio.ch.WindowsSelectorImpl@1a6c75fe woken with none selected
2021-05-30 02:49:43.001:DBUG:oeji.WriteFlusher:Connector-Scheduler-289d1c02-1: ignored: WriteFlusher@3f9371c0{IDLE}->null
java.util.concurrent.TimeoutException: Idle timeout expired: 30005/30000 ms
    at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:171)
    at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:834)
2021-05-30 02:49:43.001:DBUG:oeji.ManagedSelector:qtp157683534-19: Selector sun.nio.ch.WindowsSelectorImpl@1a6c75fe woken up from select, 0/0/1 selected
2021-05-30 02:49:43.001:DBUG:oeji.ManagedSelector:qtp157683534-19: Selector sun.nio.ch.WindowsSelectorImpl@1a6c75fe processing 0 keys, 1 updates
2021-05-30 02:49:43.001:DBUG:oeji.ManagedSelector:qtp157683534-19: updateable 1
2021-05-30 02:49:43.002:DBUG:oeji.ManagedSelector:qtp157683534-19: update org.eclipse.jetty.io.ChannelEndPoint$$Lambda$86/0x0000000100123840@6f7f8713

这是请求和响应的详细信息：

请求：

(GET //localhost:8090/example/)
Accept */*
User-Agent PostmanRuntime/7.26.5
Connection keep-alive
Postman-Token 83c2a08e-d881-4f94-993d-aa39d3342dd3
Host localhost:8090
Accept-Encoding gzip, deflate, br
Content-Length 1
Content-Type application/json
Date: Tue, 01 Jun 2021 15:40:46 GMT
Content-Type: application/json

回复：

HTTP/1.1 200 
Date Tue, 01 Jun 2021 15:40:46 GMT
Content-Type application/json

【问题讨论】：

  • 这些是调试级别的事件，没有关于发出的请求或产生的响应的详细信息。这些空闲超时实际上有数百万个原因。如果您需要具体的详细信息，请编辑您的问题以包含生成的原始请求和原始响应，或者来自 DEBUG 日志本身的请求/响应详细信息。
  • 感谢您的回复。我更新了问题以包含生成响应的 servlet 代码（它没有做太多，只是返回 {“status”：“ok”}）。如果需要提供更多信息，请告诉我。
  • 我看不到您在哪里包含原始请求和响应详细信息。 （即：包含标题的“GET ...”和“200 OK ...”）
  • 我刚刚添加了请求和响应详细信息
  • 我想这应该是与请求头中的keep-alive标志相关的东西，如果我错了，请纠正我:)

标签： java rest web-services timeout jetty


【解决方案1】：

我猜应该是和请求头中的keep-alive标志有关的东西，如果我错了，请纠正我

Connection: keep-alive 在 HTTP/1.1 中没有任何意义，因为那只是一个 HTTP/1.0 概念。

当请求行包含 HTTP/1.1 时，Jetty 会忽略该值 (keep-alive)，并且生成的标头基本上是一个没有有意义值的标头（也就是 HTTP/1.1 的默认行为）

您发出的请求是针对持久连接的（HTTP/1.1 中的默认行为），服务器的响应也维护该持久连接。

您获得空闲超时的事实是针对连接本身，而不是针对任何特定请求，并且对于未关闭的持久连接来说是正常行为。

请注意，您看到的特定空闲超时是调试级别事件，而不是警告/故障或其他任何内容。这些将被记录在 WARN 级别（或更高级别）。

您可以轻松地在请求中添加Connection: close，连接将被关闭。

您也可以在服务器端添加Connection: close，然后发送响应然后关闭连接。

【讨论】：

  • 从 Postman 的请求中删除“Connection: keep-alive”标头，或将其更改为“Connection: close”解决了问题，我不再遇到超时。
  • 那么，如果我们确实在 WARN 级别收到了这些 idleTimeout 消息，这意味着什么？ （因为我是）
  • 这里的问题包括一个显示 DEBUG 空闲超时的日志。我建议您使用显示 WARN 的日志打开一个新问题（如果有堆栈跟踪，请务必包含它们）。
猜你喜欢
  • 2017-08-27
  • 2018-01-23
  • 1970-01-01
  • 1970-01-01
  • 1970-01-01
  • 1970-01-01
  • 2021-10-18
  • 2014-07-06
  • 1970-01-01
相关资源
最近更新 更多
热门标签
Java Python linux javascript Mysql C# Docker 算法 前端 SpringBoot Redis Vue spring 设计模式 .net core .net kubernetes c++ 数据库 数据结构 大数据 js 机器学习 微服务 Android Go 程序员 面试 JVM ASP.net core 云原生 人工智能 后端 PHP git CSS golang k8s Nginx Django mybatis 深度学习 多线程 React 架构 devops 爬虫 云计算 Spring Boot LeetCode