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

Jetty server throws idle timeout for REST calls

我有一个非常简单的代码片段来测试 Jetty 服务器 9.4.41。在调试级别日志中,我看到超时异常。我知道它与空闲超时有关,并且在连接上没有 read/write activity 时发生。但我只是想知道,我是否应该在日志中获取异常?在我看来有些不对劲。如果有人能帮助理解我为什么会这样,我将不胜感激。

这是我的 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 只是 return 对请求的简单成功响应:{ "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/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/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

I guess it should be something related related to keep-alive flag in the request header, correct me if I am wrong

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

当请求行包含 HTTP/1.1 时,Jetty 会忽略该值 (keep-alive),结果 header 基本上是一个没有有意义值的 header (也就是 HTTP/1.1)

的默认行为

您发出的请求是针对持久连接(HTTP/1.1 中的默认行为),服务器的响应也保持该持久连接。

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

请注意,您看到的特定空闲超时是 DEBUG 级别事件,而不是 warning/failure 或其他任何事件。这些将记录在警告级别(或更高级别)。

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

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