0

I have embedded jetty spring boot app. while making a rest call using apache httpclient lib, the target service to which am making a rest call goes down after establishing connection and then in few milliseconds I can see there is a idle time out exception on console.

I need to catch this exception in code, but am not able to do that. please help!!!

below are the logs

2020-11-11 07:26:53.208 SocketChannelEndPoint@4107f6f5{/10.192.73.136:37100<->/10.195.165.64:8080,OPEN,fill=FI,flush=-,to=29955/30000}{io=1/1,kio=1,kro=1}->HttpConnection@2419e554[p=HttpParser{s=START,0 of -1},g=HttpGenerator@5a570f7c{s=START}]=>HttpChannelOverHttp@33c85589{s=HttpChannelState@55afe3fc{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: 29955 ms, remaining: 45 ms
2020-11-11 07:26:53.253 SocketChannelEndPoint@4107f6f5{/10.192.73.136:37100<->/10.195.165.64:8080,OPEN,fill=FI,flush=-,to=30001/30000}{io=1/1,kio=1,kro=1}->HttpConnection@2419e554[p=HttpParser{s=START,0 of -1},g=HttpGenerator@5a570f7c{s=START}]=>HttpChannelOverHttp@33c85589{s=HttpChannelState@55afe3fc{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: 30001 ms, remaining: -1 ms
2020-11-11 07:26:53.253 SocketChannelEndPoint@4107f6f5{/10.192.73.136:37100<->/10.195.165.64:8080,OPEN,fill=FI,flush=-,to=30001/30000}{io=1/1,kio=1,kro=1}->HttpConnection@2419e554[p=HttpParser{s=START,0 of -1},g=HttpGenerator@5a570f7c{s=START}]=>HttpChannelOverHttp@33c85589{s=HttpChannelState@55afe3fc{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
2020-11-11 07:26:53.254 onFail FillInterest@2bc26da2{AC.ReadCB@2419e554{HttpConnection@2419e554::SocketChannelEndPoint@4107f6f5{/10.192.73.136:37100<->/10.195.165.64:8080,OPEN,fill=FI,flush=-,to=30001/30000}{io=1/1,kio=1,kro=1}->HttpConnection@2419e554[p=HttpParser{s=START,0 of -1},g=HttpGenerator@5a570f7c{s=START}]=>HttpChannelOverHttp@33c85589{s=HttpChannelState@55afe3fc{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: 30001/30000 ms
        at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:171) ~[jetty-io-9.4.26.v20200117.jar!/:9.4.26.v20200117]
        at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113) ~[jetty-io-9.4.26.v20200117.jar!/:9.4.26.v20200117]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
2020-11-11 07:26:53.254 close HttpParser{s=START,0 of -1}
2020-11-11 07:26:53.254 START --> CLOSE
2020-11-11 07:26:53.254 HttpConnection@2419e554::SocketChannelEndPoint@4107f6f5{/10.192.73.136:37100<->/10.195.165.64:8080,OPEN,fill=-,flush=-,to=30002/30000}{io=1/1,kio=1,kro=1}->HttpConnection@2419e554[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@5a570f7c{s=START}]=>HttpChannelOverHttp@33c85589{s=HttpChannelState@55afe3fc{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 {}
2020-11-11 07:26:53.254 shutdownOutput SocketChannelEndPoint@4107f6f5{/10.192.73.136:37100<->/10.195.165.64:8080,OPEN,fill=-,flush=-,to=30002/30000}{io=1/1,kio=1,kro=1}->HttpConnection@2419e554[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@5a570f7c{s=START}]=>HttpChannelOverHttp@33c85589{s=HttpChannelState@55afe3fc{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}
2020-11-11 07:26:53.256 fillInterested HttpConnection@2419e554::SocketChannelEndPoint@4107f6f5{/10.192.73.136:37100<->/10.195.165.64:8080,OSHUT,fill=-,flush=-,to=30004/30000}{io=1/1,kio=1,kro=1}->HttpConnection@2419e554[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@5a570f7c{s=START}]=>HttpChannelOverHttp@33c85589{s=HttpChannelState@55afe3fc{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}
2020-11-11 07:26:53.256 interested FillInterest@2bc26da2{AC.ReadCB@2419e554{HttpConnection@2419e554::SocketChannelEndPoint@4107f6f5{/10.192.73.136:37100<->/10.195.165.64:8080,OSHUT,fill=FI,flush=-,to=0/30000}{io=1/1,kio=1,kro=1}->HttpConnection@2419e554[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@5a570f7c{s=START}]=>HttpChannelOverHttp@33c85589{s=HttpChannelState@55afe3fc{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}}}
2020-11-11 07:26:53.256 changeInterests p=false 1->1 for SocketChannelEndPoint@4107f6f5{/10.192.73.136:37100<->/10.195.165.64:8080,OSHUT,fill=FI,flush=-,to=0/30000}{io=1/1,kio=1,kro=1}->HttpConnection@2419e554[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@5a570f7c{s=START}]=>HttpChannelOverHttp@33c85589{s=HttpChannelState@55afe3fc{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}
2020-11-11 07:26:53.256 Queued change org.eclipse.jetty.io.ChannelEndPoint$1@158db25 on ManagedSelector@2935fd2c{STARTED} id=0 keys=2 selected=0 updates=0
2020-11-11 07:26:53.256 Wakeup on submit ManagedSelector@2935fd2c{STARTED} id=0 keys=2 selected=0 updates=1
2020-11-11 07:26:53.257 Selector sun.nio.ch.EPollSelectorImpl@50d0532a woken with none selected
2020-11-11 07:26:53.257 Selector sun.nio.ch.EPollSelectorImpl@50d0532a woken up from select, 0/0/2 selected
2020-11-11 07:26:53.257 Selector sun.nio.ch.EPollSelectorImpl@50d0532a processing 0 keys, 1 updates
2020-11-11 07:26:53.257 updateable 1
2020-11-11 07:26:53.257 ignored: WriteFlusher@5f339f8b{IDLE}->null
java.util.concurrent.TimeoutException: Idle timeout expired: 30001/30000 ms
        at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:171) ~[jetty-io-9.4.26.v20200117.jar!/:9.4.26.v20200117]
        at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113) ~[jetty-io-9.4.26.v20200117.jar!/:9.4.26.v20200117]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]

try{
ConnectionKeepAliveStrategy myStrategy = new ConnectionKeepAliveStrategy() {

                public long getKeepAliveDuration(HttpResponse response, HttpContext context) {
                    // Honor 'keep-alive' header
                    HeaderElementIterator it = new BasicHeaderElementIterator(
                            response.headerIterator(HTTP.CONN_KEEP_ALIVE));
                    while (it.hasNext()) {
                        HeaderElement he = it.nextElement();
                        String param = he.getName();
                        String value = he.getValue();
                        if (value != null && param.equalsIgnoreCase("timeout")) {
                            try {
                                return Long.parseLong(value) * 1000;
                            } catch(NumberFormatException ignore) {
                            }
                        }
                    }
                    // keep alive for 30 seconds only
                    return 30 * 1000;
                }

            };
httpClient =  HttpClients.custom().setKeepAliveStrategy(myStrategy).build();
postRequest = new HttpPost(url);
response = httpClient.execute(postRequest);
} catch(TimeoutException e) {
            throw e;
        } catch(IOException e) {
            throw e;
        } catch (Exception e) {
            throw e;
        }
crazy_code
  • 344
  • 3
  • 16
  • 1
    What do you mean "catch the idletimeout"? That stacktrace looks like a server side cleanup thread that is expiring threads that have had no activity in 30,000 ms (aka 30 seconds). – Joakim Erdfelt Nov 11 '20 at 11:39
  • Thanks for the comment @JoakimErdfelt Lets say I made a rest call to service A and service A takes 1min to respond, after 20 secs elapsed, someone killed service A, Only in this case am getting idle timeout exception and I somehow want to catch this to mark my request as failed. Otherwise the status of my rest call will be on-going forever. – crazy_code Nov 11 '20 at 11:43
  • 1
    Where are you wanting to catch this exception? Your question is all about HTTP client, but the stacktrace is all about server. – Joakim Erdfelt Nov 11 '20 at 15:11
  • Please have a look at the logs again, I have updated them. What I feel is, once the target service'A goes down after establishing connection, the connection object doesn't have any activity, and the jetty container marking it idle. could you please tell me, what can I do to track connection failure or idle connections and link it to the rest call which was using it ? – crazy_code Nov 12 '20 at 06:42
  • Those are incomplete logs, they do not show the logger name and thread name (critical for understanding what is happening). Based solely on these incomplete logs that you have copy/pasted, they appear to be logs from the server side. (not the client side). So again, why are you asking about client behaviors? This is a confusing question as it currently stands. – Joakim Erdfelt Nov 12 '20 at 13:31

1 Answers1

1

As this is an idle timeout on the server side, there's nothing you can do on the client side to catch it.

Per the HTTP specs, the server is free to close the connection for any reason.

The client has to make a decision on what do next.

See https://stackoverflow.com/a/45019073/775715

It sounds like you have a classic situation where your HTTP response takes longer then your server defined idle timeout.

You might be tempted to just make the server idle timeout longer, which will work for a small number of HTTP clients.

Wait? Why did I say clients? Well, the idle timeout on the client side is often something that you cannot control, such as on a web browser, or a HTTP intermediary (like a corporate proxy, or a mobile network proxy, or load balancer). So if you increase the idle timeout on the server, you might start seeing idle timeout failures from different locations now.

This means you have to fix things in a dramatic way.

The simplest option is to fix the task on the server side to not take that long to respond.

The next option is to have the server side task feed information back to the client as soon as it has information, even if it's incomplete, keeping the connection alive. Don't wait till you have ALL of the information to write to the client.

An example would be a long lookup of information, if you have some of the information, write it to the client (in the appropriate content-type/format. partial json, partial xml, etc). Then keep doing that until you have the full information and can complete your response.

Another common approach is to break up the long running task into multiple requests/response exchanges.

  1. Your client request the long running task, you get a unique identifier for your results.
  2. Your client uses this unique identifier over time to make issue more requests for the status of the results. Returning status code 204 when there's no content (yet), and 200 when there is content, and 404 if there is no response, and 410 if the unique identifier is no longer valid.

Another common approach is to limit the scope of the task to not allow it to take that long.

  1. Your client requests a task that will return LOTS of data.
  2. The server responds with a single "page" of (limited) data, along with an identifier to use to request the next "page".
Joakim Erdfelt
  • 46,896
  • 7
  • 86
  • 136