| Re: [jetty-users] Recevied data frames different from Nginx log in HTTP/2 |
I don't know how to open the log for all the class. I set the enablelog to be true in the Http2Session and Http2Flusher manually. Below is the log.
2015-10-21 21:26:54.363:INFO::main: Logging initialized @159ms
2015-10-21 21:26:54.783:DBUG:oejh.HTTP2Session:qtp1360875712-15: Sending PrefaceFrame@245ca300
2015-10-21 21:26:54.784:DBUG:oejh.HTTP2Flusher:qtp1360875712-15: Appended PrefaceFrame@245ca300, frames=1
2015-10-21 21:26:54.784:DBUG:oejh.HTTP2Session:qtp1360875712-15: Sending SettingsFrame@3dae37f6,reply=false:{}
2015-10-21 21:26:54.784:DBUG:oejh.HTTP2Flusher:qtp1360875712-15: Appended SettingsFrame@3dae37f6,reply=false:{}, frames=2
2015-10-21 21:26:54.784:DBUG:oejh.HTTP2Flusher:qtp1360875712-15: Flushing HTTP2ClientSession@11abd39b{queueSize=2,sendWindow=65525,recvWindow=65525,streams=0,NOT_CLOSED}
2015-10-21 21:26:54.785:DBUG:oejh.HTTP2Flusher:qtp1360875712-15: Gathered for write PrefaceFrame@245ca300
2015-10-21 21:26:54.785:DBUG:oejh.HTTP2Flusher:qtp1360875712-15: Gathered for write SettingsFrame@3dae37f6,reply=false:{}
2015-10-21 21:26:54.785:DBUG:oejh.HTTP2Session:qtp1360875712-15: Generated PrefaceFrame@245ca300
2015-10-21 21:26:54.786:DBUG:oejh.HTTP2Session:qtp1360875712-15: Generated SettingsFrame@3dae37f6,reply=false:{}
2015-10-21 21:26:54.786:DBUG:oejh.HTTP2Flusher:qtp1360875712-15: Writing 2 buffers (33 bytes) for 2 frames [PrefaceFrame@245ca300, SettingsFrame@3dae37f6,reply=false:{}]
2015-10-21 21:26:54.788:DBUG:oejh.HTTP2Flusher:qtp1360875712-12: Written 2 frames for [PrefaceFrame@245ca300, SettingsFrame@3dae37f6,reply=false:{}]
2015-10-21 21:26:54.790:DBUG:oejh.HTTP2Flusher:qtp1360875712-15: Flushing HTTP2ClientSession@11abd39b{queueSize=0,sendWindow=65525,recvWindow=65525,streams=0,NOT_CLOSED}
2015-10-21 21:26:54.790:DBUG:oejh.HTTP2Flusher:qtp1360875712-15: Flushed HTTP2ClientSession@11abd39b{queueSize=0,sendWindow=65525,recvWindow=65525,streams=0,NOT_CLOSED}
2015-10-21 21:26:54.791:DBUG:oejh.HTTP2Session:qtp1360875712-15: Received SettingsFrame@73f89337,reply=false:{3=5, 4=2147483647, 5=16777215}
2015-10-21 21:26:54.792:DBUG:oejh.HTTP2Session:qtp1360875712-15: Update max local concurrent streams to 5
2015-10-21 21:26:54.792:DBUG:oejh.HTTP2Session:qtp1360875712-15: Update initial window size to 2147483647
2015-10-21 21:26:54.792:DBUG:oejh.HTTP2Session:qtp1360875712-15: Update max frame size to 16777215
2015-10-21 21:26:54.792:DBUG:oejh.HTTP2Session:qtp1360875712-15: Sending SettingsFrame@327d6aeb,reply=true:{}
2015-10-21 21:26:54.792:DBUG:oejh.HTTP2Flusher:qtp1360875712-15: Appended SettingsFrame@327d6aeb,reply=true:{}, frames=1
2015-10-21 21:26:54.793:DBUG:oejh.HTTP2Flusher:qtp1360875712-15: Flushing HTTP2ClientSession@11abd39b{queueSize=1,sendWindow=65525,recvWindow=65525,streams=0,NOT_CLOSED}
2015-10-21 21:26:54.793:DBUG:oejh.HTTP2Flusher:qtp1360875712-15: Gathered for write SettingsFrame@327d6aeb,reply=true:{}
2015-10-21 21:26:54.793:DBUG:oejh.HTTP2Session:qtp1360875712-15: Generated SettingsFrame@327d6aeb,reply=true:{}
2015-10-21 21:26:54.793:DBUG:oejh.HTTP2Flusher:qtp1360875712-15: Writing 1 buffers (9 bytes) for 1 frames [SettingsFrame@327d6aeb,reply=true:{}]
2015-10-21 21:26:54.794:DBUG:oejh.HTTP2Flusher:qtp1360875712-15: Written 1 frames for [SettingsFrame@327d6aeb,reply=true:{}]
2015-10-21 21:26:54.794:DBUG:oejh.HTTP2Flusher:qtp1360875712-15: Flushing HTTP2ClientSession@11abd39b{queueSize=0,sendWindow=65525,recvWindow=65525,streams=0,NOT_CLOSED}
2015-10-21 21:26:54.794:DBUG:oejh.HTTP2Flusher:qtp1360875712-15: Flushed HTTP2ClientSession@11abd39b{queueSize=0,sendWindow=65525,recvWindow=65525,streams=0,NOT_CLOSED}
2015-10-21 21:26:54.795:DBUG:oejh.HTTP2Session:qtp1360875712-15: Received WindowUpdateFrame@7e20fad5#0,delta=2147418112
2015-10-21 21:26:54.795:DBUG:oejh.HTTP2Flusher:qtp1360875712-15: Flushing HTTP2ClientSession@11abd39b{queueSize=0,sendWindow=65525,recvWindow=65525,streams=0,NOT_CLOSED}
2015-10-21 21:26:54.796:DBUG:oejh.HTTP2Flusher:qtp1360875712-15: Flushed HTTP2ClientSession@11abd39b{queueSize=0,sendWindow=2147483637,recvWindow=65525,streams=0,NOT_CLOSED}
2015-10-21 21:26:54.796:DBUG:oejh.HTTP2Session:qtp1360875712-15: Received SettingsFrame@31d8c981,reply=true:{}
2015-10-21 21:26:54.798:DBUG:oejh.HTTP2Session:main: Created local HTTP2Stream@6108b2d7#1{sendWindow=2147483647,recvWindow=65525,reset=false,NOT_CLOSED}
2015-10-21 21:26:54.799:DBUG:oejh.HTTP2Flusher:main: Appended HeadersFrame@1554909b#1{end=true}, frames=1
2015-10-21 21:26:54.799:DBUG:oejh.HTTP2Flusher:main: Flushing HTTP2ClientSession@11abd39b{queueSize=1,sendWindow=2147483637,recvWindow=65525,streams=1,NOT_CLOSED}
2015-10-21 21:26:54.799:DBUG:oejh.HTTP2Flusher:main: Gathered for write HeadersFrame@1554909b#1{end=true}
2015-10-21 21:26:54.809:DBUG:oejh.HTTP2Session:main: Generated HeadersFrame@1554909b#1{end=true}
2015-10-21 21:26:54.810:DBUG:oejh.HTTP2Flusher:main: Writing 2 buffers (69 bytes) for 1 frames [HeadersFrame@1554909b#1{end=true}]
2015-10-21 21:26:54.810:DBUG:oejh.HTTP2Flusher:main: Written 1 frames for [HeadersFrame@1554909b#1{end=true}]
2015-10-21 21:26:54.810:DBUG:oejh.HTTP2Flusher:main: Flushing HTTP2ClientSession@11abd39b{queueSize=0,sendWindow=2147483637,recvWindow=65525,streams=1,NOT_CLOSED}
2015-10-21 21:26:54.810:DBUG:oejh.HTTP2Flusher:main: Flushed HTTP2ClientSession@11abd39b{queueSize=0,sendWindow=2147483637,recvWindow=65525,streams=1,NOT_CLOSED}
2015-10-21 21:26:54.813:DBUG:oejh.HTTP2Session:qtp1360875712-13: Received DataFrame@3ed90f5#1{length:8038,end=false}
2015-10-21 21:26:54.814:DBUG:oejh.HTTP2Session:qtp1360875712-13: Received DataFrame@3a83903a#1{length:154,end=false}
DataFrame@3a83903a#1{length:154,end=false}index.html
2015-10-21 21:26:54.815:DBUG:oejh.HTTP2Session:qtp1360875712-13: Received DataFrame@7f6d0358#1{length:22,end=true}
2015-10-21 21:26:54.815:DBUG:oejh.HTTP2Session:qtp1360875712-13: Removed HTTP2Stream@6108b2d7#1{sendWindow=2147483647,recvWindow=57311,reset=false,CLOSED}
2015-10-21 21:27:04.818:DBUG:oejh.HTTP2Session:main: Sending GoAwayFrame@22f71333,0/
2015-10-21 21:27:04.819:DBUG:oejh.HTTP2Session:main: Sending GoAwayFrame@22f71333,0/
2015-10-21 21:27:04.819:DBUG:oejh.HTTP2Flusher:main: Appended GoAwayFrame@22f71333,0/, frames=1
2015-10-21 21:27:04.819:DBUG:oejh.HTTP2Flusher:main: Flushing HTTP2ClientSession@11abd39b{queueSize=1,sendWindow=2147483637,recvWindow=57311,streams=0,LOCALLY_CLOSED}
2015-10-21 21:27:04.820:DBUG:oejh.HTTP2Flusher:main: Gathered for write GoAwayFrame@22f71333,0/
2015-10-21 21:27:04.820:DBUG:oejh.HTTP2Session:main: Generated GoAwayFrame@22f71333,0/
2015-10-21 21:27:04.820:DBUG:oejh.HTTP2Flusher:main: Writing 1 buffers (17 bytes) for 1 frames [GoAwayFrame@22f71333,0/]
2015-10-21 21:27:04.821:DBUG:oejh.HTTP2Flusher:main: Written 1 frames for [GoAwayFrame@22f71333,0/]
2015-10-21 21:27:04.823:DBUG:oejh.HTTP2Flusher:main: Flushing HTTP2ClientSession@11abd39b{queueSize=0,sendWindow=2147483637,recvWindow=57311,streams=0,LOCALLY_CLOSED}
2015-10-21 21:27:04.823:DBUG:oejh.HTTP2Flusher:main: Flushed HTTP2ClientSession@11abd39b{queueSize=0,sendWindow=2147483637,recvWindow=57311,streams=0,LOCALLY_CLOSED}
2015-10-21 21:27:04.825:DBUG:oejh.HTTP2Session:qtp1360875712-10: Shutting down HTTP2ClientSession@11abd39b{queueSize=0,sendWindow=2147483637,recvWindow=57311,streams=0,LOCALLY_CLOSED}
DisconnectFrame@59830a39
2015-10-21 21:27:04.826:DBUG:oejh.HTTP2Session:qtp1360875712-10: Sending DisconnectFrame@59830a39
2015-10-21 21:27:04.826:DBUG:oejh.HTTP2Flusher:qtp1360875712-10: Appended DisconnectFrame@59830a39, frames=1
2015-10-21 21:27:04.826:DBUG:oejh.HTTP2Flusher:qtp1360875712-10: Flushing HTTP2ClientSession@11abd39b{queueSize=1,sendWindow=2147483637,recvWindow=57311,streams=0,LOCALLY_CLOSED}
2015-10-21 21:27:04.827:DBUG:oejh.HTTP2Flusher:qtp1360875712-10: Gathered for write DisconnectFrame@59830a39
2015-10-21 21:27:04.827:DBUG:oejh.HTTP2Session:qtp1360875712-10: Generated DisconnectFrame@59830a39
2015-10-21 21:27:04.827:DBUG:oejh.HTTP2Flusher:qtp1360875712-10: Writing 0 buffers (0 bytes) for 1 frames [DisconnectFrame@59830a39]
2015-10-21 21:27:04.827:DBUG:oejh.HTTP2Flusher:qtp1360875712-10: Failed
Hi,
There are several factors at play here, from TLS to implementation details.
On Sun, Oct 18, 2015 at 9:54 AM, Muhui Jiang <jiangmuhui@xxxxxxxxx> wrote:
> Hi
>
> I made a simple request to Nginx 1.9.5, I reviewed the detail log of Nginx,
> and I find
>
> 2015/10/18 15:38:53 [debug] 10707#0: *115 SSL buf copy: 9
> 2015/10/18 15:38:53 [debug] 10707#0: *115 SSL buf copy: 8192
> 2015/10/18 15:38:53 [debug] 10707#0: *115 SSL buf copy: 9
> 2015/10/18 15:38:53 [debug] 10707#0: *115 SSL buf copy: 22
> 2015/10/18 15:38:53 [debug] 10707#0: *115 SSL to write: 8377
> 2015/10/18 15:38:53 [debug] 10707#0: *115 SSL_write: 8377
> 2015/10/18 15:38:53 [debug] 10707#0: *115 http2:1 DATA frame
> 00007F942100AAE0 was sent
> 2015/10/18 15:38:53 [debug] 10707#0: *115 http2 frame sent: 00007F942100AAE0
> sid:1 bl:0 len:8192
> 2015/10/18 15:38:53 [debug] 10707#0: *115 http2:1 DATA frame
> 00007F942100AD48 was sent
> 2015/10/18 15:38:53 [debug] 10707#0: *115 http2 frame sent: 00007F942100AD48
> sid:1 bl:0 len:22
> 2015/10/18 15:38:53 [debug] 10707#0: *115 http write filter 0000000000000000
> 2015/10/18 15:38:53 [debug] 10707#0: *115 http copy filter: 0 "/index.html?"
> 2015/10/18 15:38:53 [debug] 10707#0: *115 http finalize request: 0,
> "/index.html?" a:1, c:1
> 2015/10/18 15:38:53 [debug] 10707#0: *115 http request count:1 blk:0
> 2015/10/18 15:38:53 [debug] 10707#0: *115 http2 close stream 1, queued 0,
> processing 1
>
> The log above shows the server send 2 data frames and the lengths are 8192
> and 22.
>
> But my Jetty client receive data frames are :
>
> 2015-10-18 15:38:52.579:INFO::main: Logging initialized @367ms
>
> HeadersFrame@e4ee4b0#1{end=false}index.html
>
> DataFrame@3cb06f96#1{length:8038,end=false}index.html
>
> DataFrame@5f9460d5#1{length:154,end=false}index.html
>
> DataFrame@61d516bc#1{length:22,end=true}index.html
>
> It seems the first data frame is split. I wanna know how it comes. Many
> Thanks
Do you have the Jetty debug logs for this request ?
--
Simone Bordet
----
http://cometd.org
http://webtide.com
Developer advice, training, services and support
from the Jetty & CometD experts.
_______________________________________________
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