Re: [jetty-users] Unexpected delay after each HTTP response

[cowwoc <cowwoc@xxxxxxxxxxxxxxxx>]

Michael Gorovoy wrote:
> 
> I've recently used embedded Jetty 7.5.0-SNAPSHOT with slf4j v1.6.1 and
> logback v0.9.27 and it was working for me. I would suggest that you first
> get the standalone Jetty configuration working so that you can make sure
> you
> have correct configuration, and then attempt to do it with maven plugin.
> If
> you run standalone Jetty using command 'java -jar start.jar DEBUG=true' it
> will output a lot of additional information that should help you diagnose
> the problem.
> 
> The same can be achieved by setting
> 'MAVEN_OPTS=-Dorg.eclipse.jetty.util.log.DEBUG=true' when running with
> maven
> plugin. The most likely cause of the issues you are experiencing is that
> slf4j and/or logback is not being added to the classpath, that could be
> caused by choosing an incorrect dependency scope. You could also ran Maven
> with option -X that will output extended information about artifacts and
> plugin execution that may be helpful in determining the cause of the
> issue.

For some reason rebuilding my project fixed the problem. <shrug>

Here is more information about the original 500ms delay I reported.

The server logs:

2011-08-25 13:38:28.552,DEBUG,qtp7356647-12 - /devices REQUEST /devices on
org.eclipse.jetty.server.nio.SelectChannelConnector$SelectChannelHttpConnection@38d4e2@10.0.1.32:80<->10.0.1.32:53882
2011-08-25 13:38:28.553,DEBUG,qtp7356647-12 - /devices scope null||/devices
@
o.e.j.w.WebAppContext{/,file:/C:/Users/g.tzabari/Documents/vitex/database.server/src/main/webapp/},src/main/webapp
2011-08-25 13:38:28.553,DEBUG,qtp7356647-12 - /devices context=||/devices @
o.e.j.w.WebAppContext{/,file:/C:/Users/g.tzabari/Documents/vitex/database.server/src/main/webapp/},src/main/webapp
2011-08-25 13:38:28.553,DEBUG,qtp7356647-12 - /devices
sessionManager=org.eclipse.jetty.server.session.HashSessionManager@14fb35d
2011-08-25 13:38:28.553,DEBUG,qtp7356647-12 - /devices session=null
2011-08-25 13:38:28.554,DEBUG,qtp7356647-12 - /devices servlet
|/devices|null -> default
2011-08-25 13:38:28.554,DEBUG,qtp7356647-12 - /devices chain=
2011-08-25 13:38:28.554,DEBUG,qtp7356647-12 - /devices call filter Guice
Filter
2011-08-25
13:38:28.555,TRACE,com.muxlab.vitex.database.server.ConnectionFilter.doFilter,qtp7356647-12
- /devices start HTTP/1.1 GET http://10.0.1.32/devices
2011-08-25
13:38:28.558,TRACE,com.muxlab.vitex.database.server.ConnectionFilter.doFilter,qtp7356647-12
- /devices end HTTP/1.1 GET http://10.0.1.32/devices
2011-08-25 13:38:28.559,DEBUG,qtp7356647-12 - /devices RESPONSE /devices 
307
2011-08-25 13:38:29.072,DEBUG,qtp7356647-18 Selector0
SelectChannelConnector@0.0.0.0:80 STARTED closed
org.eclipse.jetty.server.nio.SelectChannelConnector$SelectChannelHttpConnection@38d4e2@10.0.1.32:80<->10.0.1.32:53882
2011-08-25 13:38:29.074,DEBUG,qtp7356647-16 - /devices/ REQUEST /devices/ on
org.eclipse.jetty.server.nio.SelectChannelConnector$SelectChannelHttpConnection@6abc19@10.0.1.32:80<->10.0.1.32:53883

The client logs:

Thu Aug 25 13:38:28.546 EDT 2011 sun.net.www.protocol.http.HttpURLConnection
plainConnect
FINEST: ProxySelector Request for http://10.0.1.32/devices
Thu Aug 25 13:38:28.548 EDT 2011 sun.net.www.protocol.http.HttpURLConnection
plainConnect
FINEST: Proxy used: DIRECT
Thu Aug 25 13:38:28 EDT.549 2011 sun.net.www.protocol.http.HttpURLConnection
writeRequests
FINE: sun.net.www.MessageHeader@10ef5a55 pairs: {GET /devices HTTP/1.1:
null}{Accept: application/vnd.com.muxlab.vitex.devices+json;
version=1.0}{User-Agent: Java/1.7.0}{Host: 10.0.1.32}{Connection:
keep-alive}
Thu Aug 25 13:38:29 EDT.063 2011 sun.net.www.protocol.http.HttpURLConnection
getInputStream
FINE: sun.net.www.MessageHeader@46c7b04 pairs: {null: HTTP/1.1 307 Temporary
Redirect}{Location: http://10.0.1.32/devices/}{Content-Length: 0}{Server:
Jetty(7.4.4.v20110707)}
Thu Aug 25 13:38:29 EDT.064 2011 sun.net.www.protocol.http.HttpURLConnection
followRedirect
FINE: Redirected from http://10.0.1.32/devices to http://10.0.1.32/devices/

Looking at the server log, notice the 500 ms delay at time 13:38:28.559,
between "RESPONSE /devices" and "STARTED closed". I believe this is the
problem I am seeing. I suspect Jetty is not flushing the response until
"STARTED closed". Any ideas?

Gili

--
View this message in context: http://jetty.1047016.n5.nabble.com/Unexpected-delay-after-each-HTTP-response-tp4728842p4735381.html
Sent from the jetty-users mailing list archive at Nabble.com.