Skip to main content
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
Re: [jetty-users] jetty http/2 push broken? or Chrome?
Hi Greg,

Just gave your test Http2Server a go and I was still able to reproduce the errors, you can find the log files here https://github.com/teyckmans/http2-push/blob/master/logs/2001502091749_Http2Server_test_logging.7z

Steps taken:
browse to https://localhost:8443 -> looks ok (see spdy_session_1.log)

refresh using ctrl+F5 -> page is broken no images are shown (see spdy_session_3.log)

Don't bother looking in spdy_session_2.log and spdy_session_4.log thought I was on to something and then I noticed it was for favicon.ico :P.

The jetty_Http2Server.log contains the standard output, there are IllegalStateExceptions and unexpected thread deaths in there. This is on windows 8.1.

I didn't test with this snapshot build on gcloud but I've encountered them with previous builds on the container-vm image.

Hope there is something in the logs that may help. 

This was on Version 42.0.2298.0 canary (64-bit)

And now I see that it is 'nearly' up to date, so I'll be doing this again on Version 42.0.2299.0 canary (64-bit) next.

On 6 February 2015 at 04:05, Greg Wilkins <gregw@xxxxxxxxxxx> wrote:
Tom,

I had a little play with your project but could not reproduce the thread death issues.   However it was not working as I expect either, so I went back and tested the jetty mechanism again.... I found a few funnies and changed a few things.

Main change is that the PushBuilder now takes absolute URIs rather than context relative ones - just saved me lots of fiddling with the URIs.

I've now got a demo in the master repo at jetty-http2/http2-server/src/test/java/org/eclipse/jetty/http2/server/Http2Server.java
Plus a image tile demo docroot.   I have included a filter that notices if the get request is a push and if so serves the pushed/tileXY.jpg instead of the tiles/tileXY.jpg.   Each tile has it's name and location in the image, so you can visually see if it came from a push or not.

I tried adding a header to the pushed requests to indicate that it is a push, but that does not appear in the browser debug for the pushed resources, even when I see that the image has indeed been pushed.

This has been working OK with FF35.0.1, but I have issues with my chrome even before I get to the push... so I need to investigate that.

Pushing 304's does sometimes appear to result in confusion in the browser.  If you push a 304 when the browser does not have the image, it just displays nothing and does not fetch it again.

Anyway,  if you wanted to play in that push sandpit for a while, that would be easier for me to try reproduce and debug any issues.

cheers



On 5 February 2015 at 03:40, Tom Eyckmans <teyckmans@xxxxxxxxx> wrote:
Hi Greg,

Hope you had a good vacation and well rested :)

I've logged a bug for the IllegalStateExceptions and unexpected thread deaths https://bugs.eclipse.org/bugs/show_bug.cgi?id=459081 
I've logged this as one bug since I assume that the exceptions are causing the thread deaths.

Kind regards,
Tom

On 4 February 2015 at 00:07, Greg Wilkins <gregw@xxxxxxxxxxx> wrote:

Guys,

Also note it might be worthwhile for you to read the thread in the Servlet 4.0 expert group mailing list, to see some of the history and motivation behind the push API:
https://java.net/projects/servlet-spec/lists/jsr369-experts/archive/2014-12/thread/1   Subject HTTP Push, URI and header mutations

Feedback on that is most welcome.

cheers


On 4 February 2015 at 10:00, Greg Wilkins <gregw@xxxxxxxxxxx> wrote:
Shawn, Tom,

just a quick note to say that I'm just back from vacation and working on push from both an API and impl point of view is high on my agenda.   So I'll be digesting this interesting thread over the next day or so and will get back to you soon with comments and requests for feedback etc.


cheers


On 3 February 2015 at 09:26, Shawn Bissell <shawn.bissell@xxxxxxxxx> wrote:
Thanks for looking into that Tom. I was really just trying using Jetty as a test platform so I could see how the browsers handle the push streams. I moved on and was able to experiment using some examples from nghttp2. I assume the Jetty devs monitor this mailing list and are either aware of or will look into the IllegalStateException issue themselves? 

Just to close the loop on the Firefox issue .. I did find and log a bug in which push streams are closed when the promises come before the response to the initial request.



On 2015-Feb-02, at 1:54 PM, Tom Eyckmans <teyckmans@xxxxxxxxx> wrote:

Hi Shawn,

Just tested with the RequestDispatcher.push. 

Using that method the query parameters are apparently also copied on the push URL without a way to toggle it of. 

So I copied the code from the method to stop the copy of the query string.

Then I got the same behaviour as before works with many pushes, doesn't with rows parameter smaller than 10.
I get illegalstateexceptions state=CLOSED and thread death errors.

Looks like I'll have to dive into the jetty code.




On 29 January 2015 at 21:28, Tom Eyckmans <teyckmans@xxxxxxxxx> wrote:
Hi Shawn,

Looks like it's going downhill...

Just rebuilt the docker images and retested based on the latest commit 7d7fba4.

Really odd behavior on chrome, I'm getting SPDY protocol errors in the network trace of the developer toolbar when I'm passing a value smaller than 10 as rows, from 10 up the push works.

I'm getting illegal state exceptions on the server side in this case and no push promises in chrome.

Looks like there is something really wrong, I'll try and give the 'deprecated' way another go.

On 20 January 2015 at 07:19, Shawn Bissell <shawn.bissell@xxxxxxxxx> wrote:
Actually scratch that theory … the Cache-Control: no-cache was being caused by the Firefox dev tools since I had the “Disable Cache (when toolbox is open)” option selected for my testing. Once I turned that off the no-cache on the PUSH_PROMISE went away, but they were still RST_STREAM. So basically it looks like the Jetty PushBuilder doesn’t work with Firefox at all :( where as at least in Chrome we can see the PUSH streams are “adopted”. This is on Firefox Nightly 38.0a1 (2015-01-19) using h2-15 where as Chrome Canary 42 was using h2-14.

Also I should note that in the Jetty Debug log there were no IllegalStateExceptions just a bunch of org.eclipse.jetty.io.EofExceptions which seem to correspond to the RST_STREAMs


On 2015-Jan-19, at 9:59 PM, Shawn Bissell <shawn.bissell@xxxxxxxxx> wrote:

Tom, so I tired using Firefox just for comparison. I finally got a Wireshark trace decoded properly ... Wow that was complicated! I needed to tell Wireshark about the the private RSA key AND use the NSS SSLKEYLOGFILE as the Master-Secrect log file. As you can see from the trace in the screenshot below (I hope that comes through the mailing list) every PUSH_PROMISE is immediately reset by Firefox with a RST_STREAM. I’m thinking either FF doesn’t support PUSH yet (which doesn’t make sense since they could just turn it off in the SETTINGS frame) OR maybe the PUSH is malformed somehow … maybe the Cache-Control: no-cache is the problem? Chrome seemed to be fine with it though<Screen Shot 2015-01-19 at 9.48.47 PM.png>


On 2015-Jan-18, at 10:33 PM, Tom Eyckmans <teyckmans@xxxxxxxxx> wrote:

Shawn,

The bugs kept me up, so I was pondering why I didn't notice them myself. 

While writing the blog the RequestDispatcher.push method got deprecated and I switched to using the PushBuilder. As it turns out this caused of both issues. 

When using RequestDispatcher.push you need to added the context root yourself and because you're creating the complete request path I didn't add the query parameters and everything worked just fine :)

Apparently the PushBuilder takes care of adding the context root which is nice but I certainly didn't expect this. 

I don't really understand why the PushBuilder passes on the query parameters by default. I expect most resources that will be pushed to be static in nature and the query parameters are not needed for these resources. Nice that it is possible but would have expected this to be an opt-in type of feature rather than a default.

Great that you get the same results, always good to have a repeatable case.
I'll try to confirm your findings with the latest snapshot.


On 19 January 2015 at 07:06, Shawn Bissell <shawn.bissell@xxxxxxxxx> wrote:
Tom, I pulled your changes and I reverted back to the Dec 22 snapshot (git e8c88cfd9cf3cab89788cd530838314089ce9b23) for Jetty you are using in your Docker image, and I got the same results as you. Those timeout errors went away, and yes pushing the full page (402 requests) causes java.lang.IllegalStateExceptions you saw. So I believe the latest snapshot probably fixed that error, but introduced an incompatibility with Chrome Canary 42.




On 2015-Jan-18, at 1:32 PM, Tom Eyckmans <teyckmans@xxxxxxxxx> wrote:

Hi Shaw,

Thanks for taking the time to look at this and the great feedback, to bad for me it is not really working the way I thought is was, but thats the only way you really learn right :)

I didn't know about the chrome://net-internals/#events thanks for pointing me to it. Looks like a great resource. 

I changed the push code (also added a default(true) to the push parameter) and now I also see the SPDY_STREAM_ADOPTED_PUSH_STREAM events. Thanks for pointing me to the problems.

Here are some additional test findings (mentioned log files can be found here https://github.com/teyckmans/http2-push/tree/master/logs):

I didn't see the following thread deaths in the Jetty output previously:  

2015-01-18 19:50:50.505:WARN:oejut.QueuedThreadPool:qtp396180261-188: Unexpected thread death: org.eclipse.jetty.util.thread.QueuedThreadPool$3@b6df857 in qtp396180261{STARTED,10<=200<=200,i=129,q=0}
2015-01-18 19:51:50.363:WARN:oejut.QueuedThreadPool:qtp396180261-219: Unexpected thread death: org.eclipse.jetty.util.thread.QueuedThreadPool$3@b6df857 in qtp396180261{STARTED,10<=199<=200,i=195,q=0}

I also had a case when the page kept on loading and there was no active SPDY session listed on the net-internals page in Chrome. See chrome_spdy_session_hangs.log in github project, spdy session just stopped fetching, without timeout I kept waiting for a while but it didn't time out. This was in combination with the thread deaths on the server side. Would have expected Chrome to timeout at some point. 

After some more testing without rows and column restrictions (pushing 400 resources) I got the following IllegalStateExceptions in HttpTransportOverHTTP2.send(HttpTransportOverHTTP2.java:100), in this case server is taking up 100% cpu as it is logging like crazy. 
Looks like the HTTP2 transport code got stuck:

2015-01-18 20:08:07.833:WARN:oejs.HttpChannel:qtp396180261-107: Commit failed
java.lang.IllegalStateException: committed
        at org.eclipse.jetty.http2.server.HttpTransportOverHTTP2.send(HttpTransportOverHTTP2.java:100)
        at org.eclipse.jetty.server.HttpChannel.sendResponse(HttpChannel.java:591)
        at org.eclipse.jetty.server.HttpChannel$CommitCallback.failed(HttpChannel.java:712)
        at org.eclipse.jetty.http2.server.HttpTransportOverHTTP2.send(HttpTransportOverHTTP2.java:100) 

The last 3 lines of the stack are repeated 131 times!

I've pushed out a new version of the teyckmans/blog-http2-push docker image and installed it here: 


Sometimes the page loads fast (1.15 - 1.20 seconds) but sometimes the page takes (+/-4.5 seconds) when using https://146.148.90.85:8443/blog-http2-push/push?rows=5 
Haven't found the cause of this yet.

I haven't tested with a fresh snapshot build from the latest sources, I'll try and get to that somewhere this week.

On 18 January 2015 at 19:24, Shawn Bissell <shawn.bissell@xxxxxxxxx> wrote:
I posted this on Tom Eyckmans’ blog (http://blog.iadvise.eu/2015/01/12/http2-server-push/), but I figure this is a better place for the discussion since there seems to be a problem with the push mechanism itself…

First of all Tom, great work on making this example. I tried creating a similar jetty push example and failed miserably :) I hate to break it to you, but the http2-push site is pushing a different url from the requested one so the pushes are wasted. Hitting the url
https://localhost:8443/blog-http2-push/push?push=true&rows=0&columns=1
(I had to look at the source to determine the ?push=true was required for push)

If you look in the Chrome (Canary build 42) chrome://net-internals/#events screen and find your SPDY_SESSION you can see that the push promise has a url of

/blog-http2-push/blog-http2-push/images/slice_0_0.jpg?push=true&rows=0&columns=1

where as the url requested in the page is just

/blog-http2-push/images/slice_0_0.jpg

So there are 2 problems there … the pushed url path has an extra blog-http2-push in it and the pushed url has the querystring in it.

I tried fixing the servlet code but not calling the absoluteResourcePath method and by setting the query tring to null.
pushBuilder.setQueryString(null);
And then I could see the SPDY_STREAM_ADOPTED_PUSH_STREAM events happening in Chrome, but there was some sort of timeout and the client closes the streams and the pushed resources were not loaded at all. 

Here is what I see in the debug log

2015-01-18 10:11:58.898:DBUG:oejhs.HttpChannelOverHTTP2:         qtp565760380-27: HTTP2 PUSH Request #240/798f5a73:
GET https://localhost:8443/blog-http2-push/images/slice_5_19.jpg HTTP/2
accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
accept-encoding: gzip, deflate, sdch
accept-language: en-US,en;q=0.8
cache-control: public, max-age=777
pragma: no-cache
user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/42.0.2278.0 Safari/537.36
referer: https://localhost:8443/blog-http2-push/push
….
2015-01-18 10:11:58.899:DBUG:oejhs.HttpChannelOverHTTP2:         qtp565760380-27: HTTP2 Commit Response #1/798f5a73:
HTTP/2 200 null
Server: Jetty(9.3.0-SNAPSHOT)
Content-Type: text/html;charset=iso-8859-1
2015-01-18 10:11:58.899:DBUG:oejhs.HttpTransportOverHTTP2:       qtp565760380-27: HTTP2 Response #1:
HTTP/2 200
Server: Jetty(9.3.0-SNAPSHOT)
Content-Type: text/html;charset=iso-8859-1
….
2015-01-18 10:11:58.900:DBUG:oejhs.HttpTransportOverHTTP2:       qtp565760380-27: HTTP2 Response #1 committed
…
15 seconds later
...
2015-01-18 10:12:13.801:DBUG:oeji.IdleTimeout:              Scheduler-1530388690: HTTP2Stream@48dd8f83{id=2,sendWindow=10485760,recvWindow=65535,reset=false,REMOTELY_CLOSED} idle timeout check, elapsed: 15004 ms, remaining: -4 ms
2015-01-18 10:12:13.801:DBUG:oeji.IdleTimeout:              Scheduler-1530388690: HTTP2Stream@48dd8f83{id=2,sendWindow=10485760,recvWindow=65535,reset=false,REMOTELY_CLOSED} idle timeout expired
2015-01-18 10:12:13.801:DBUG:oejh.HTTP2Stream:              Scheduler-1530388690: Idle timeout 15000ms expired on HTTP2Stream@48dd8f83{id=2,sendWindow=10485760,recvWindow=65535,reset=false,REMOTELY_CLOSED}

_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users

_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users

_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users



_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users



--
Greg Wilkins <gregw@xxxxxxxxxxx>  @  Webtide - an Intalio subsidiary
http://eclipse.org/jetty HTTP, SPDY, Websocket server and client that scales
http://www.webtide.com  advice and support for jetty and cometd.



--
Greg Wilkins <gregw@xxxxxxxxxxx>  @  Webtide - an Intalio subsidiary
http://eclipse.org/jetty HTTP, SPDY, Websocket server and client that scales
http://www.webtide.com  advice and support for jetty and cometd.

_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users



--
Greg Wilkins <gregw@xxxxxxxxxxx>  @  Webtide - an Intalio subsidiary
http://eclipse.org/jetty HTTP, SPDY, Websocket server and client that scales
http://www.webtide.com  advice and support for jetty and cometd.

_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users

Back to the top