> -----Original Message-----
> From: Stefan Eissing [mailto:[email protected]]
> Sent: vrijdag 20 november 2015 10:26
> To: [email protected]
> Subject: Re: H2 stream dependencies
>
> Bert,
>
> interesting and nice to see the progress. You probably could use priorities
> for
> ordering, especially when using the stream dependencies. I am not certain,
> however, if this will give you totally deterministic behavior. If stream B
> depends on A, usually A will be sent out before B. However, should stream A
> become suspended - e.g. unable to progress, either because there is no data
> available which some other thread needs to produce, or because the flow
> control window has not been updated in time - the server will start sending
> data for B.
>
> The state of the implementation is:
> 2.4.17: fully implemented priority handling on sending stream data, as
> implemented by the nghttp2 library
I'm seeing different behavior when running against my FreeBSD httpd 2.4.17
(prefork mpm) and Windows (winnt mpm) builds.
Everything appears to work ok when sending a dependency within the headers
frame to my FreeBSD box, while on my Windows build I get responses out of order.
Is it possible that different requests over the same connection are handled by
different threads in this case?
Is there any logging that may help me diagnose this further?
(See log below)
The propfind is handled by mod_dav, while the report is handled by mod_dav_svn.
Bert
--
[:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_stream.c(58): [client
::1:15125] h2_stream(12-11): created
[:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_session.c(71): [client
::1:15125] h2_session: stream(12-11): opened
[:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_workers.c(303):
h2_workers: register mplx(12)
[:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_stream.c(167): [client
::1:15125] h2_mplx(12-11): start stream, task PROPFIND
/svn-test-work/local_tmp/repos/!svn/rev/1 (localhost:7829)
[:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_stream.c(180): [client
::1:15125] h2_stream(12-11): closing input
[:09.091881 2015] [http2:debug] [pid 1956:tid 572] h2_workers.c(166):
h2_worker(14): start task(12-11)
[:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_session.c(420): [client
::1:15125] h2_stream(12-11): input closed
[:09.091881 2015] [http2:debug] [pid 1956:tid 572] h2_task_input.c(84): [client
::1:15125] h2_task_input(12-11): request is:
[:09.091881 2015] [http2:debug] [pid 1956:tid 572] h2_h2.c(215): [client
::1:15125] adding h1_to_h2_resp output filter
[:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_stream.c(58): [client
::1:15125] h2_stream(12-13): created
[:09.091881 2015] [ssl:debug] [pid 1956:tid 572] ssl_engine_kernel.c(238):
[client ::1:15125] AH02034: Subsequent (No.2) HTTPS request received for child
119652660 (server localhost:443)
[:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_session.c(71): [client
::1:15125] h2_session: stream(12-13): opened
[:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_workers.c(303):
h2_workers: register mplx(12)
[:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_stream.c(167): [client
::1:15125] h2_mplx(12-13): start stream, task REPORT
/svn-test-work/local_tmp/repos/!svn/rev/1 (localhost:7829)
[:09.091881 2015] [http2:debug] [pid 1956:tid 340] h2_workers.c(166):
h2_worker(4): start task(12-13)
[:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_stream.c(180): [client
::1:15125] h2_stream(12-13): closing input
[:09.091881 2015] [http2:debug] [pid 1956:tid 340] h2_task_input.c(84): [client
::1:15125] h2_task_input(12-13): request is:
[:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_session.c(420): [client
::1:15125] h2_stream(12-13): input closed
[:09.091881 2015] [http2:debug] [pid 1956:tid 340] h2_h2.c(215): [client
::1:15125] adding h1_to_h2_resp output filter
[:09.091881 2015] [ssl:debug] [pid 1956:tid 340] ssl_engine_kernel.c(238):
[client ::1:15125] AH02034: Subsequent (No.2) HTTPS request received for child
56701100 (server localhost:443)
[:09.091881 2015] [http2:debug] [pid 1956:tid 340] h2_task_input.c(107):
[client ::1:15125] h2_task_input(12-13): read, block=0, mode=1, readbytes=0
[:09.091881 2015] [http2:debug] [pid 1956:tid 340] h2_task_input.c(107):
[client ::1:15125] h2_task_input(12-13): read, block=0, mode=0, readbytes=153
[:09.091881 2015] [http2:debug] [pid 1956:tid 340] h2_task_input.c(107):
[client ::1:15125] h2_task_input(12-13): read, block=0, mode=1, readbytes=0
[:09.091881 2015] [http2:debug] [pid 1956:tid 340] h2_task_input.c(107):
[client ::1:15125] h2_task_input(12-13): read, block=0, mode=1, readbytes=0
[:09.091881 2015] [http2:debug] [pid 1956:tid 340] h2_task_input.c(107):
[client ::1:15125] h2_task_input(12-13): read, block=0, mode=1, readbytes=0
[:09.092880 2015] [http2:debug] [pid 1956:tid 572] h2_task_input.c(107):
[client ::1:15125] h2_task_input(12-11): read, block=0, mode=1, readbytes=0
[:09.092880 2015] [http2:debug] [pid 1956:tid 572] h2_task_input.c(107):
[client ::1:15125] h2_task_input(12-11): read, block=0, mode=0, readbytes=95
[:09.092880 2015] [http2:debug] [pid 1956:tid 572] h2_task_input.c(107):
[client ::1:15125] h2_task_input(12-11): read, block=0, mode=1, readbytes=0
[:09.092880 2015] [http2:debug] [pid 1956:tid 572] h2_task_input.c(107):
[client ::1:15125] h2_task_input(12-11): read, block=0, mode=1, readbytes=0
[:09.092880 2015] [http2:debug] [pid 1956:tid 572] h2_task_input.c(107):
[client ::1:15125] h2_task_input(12-11): read, block=0, mode=1, readbytes=0
[:09.097882 2015] [http2:debug] [pid 1956:tid 340] h2_mplx.c(564): [client
::1:15125] h2_mplx(12-13): open response: 200
::1 - jrandom [25/Nov/2015:02:55:09 +0100] "REPORT
/svn-test-work/local_tmp/repos/!svn/rev/1 HTTP/1.1" 200 2718
[:09.097882 2015] [http2:debug] [pid 1956:tid 908] h2_session.c(1126): [client
::1:15125] h2_stream(12-13): submitted response 200, rv=0
[:09.097882 2015] [http2:debug] [pid 1956:tid 908] h2_session.c(234): [client
::1:15125] h2_stream(12-13): handled, closing
[:09.097882 2015] [http2:debug] [pid 1956:tid 340] h2_task_input.c(107):
[client ::1:15125] h2_task_input(12-13): read, block=1, mode=3, readbytes=1
[:09.097882 2015] [http2:debug] [pid 1956:tid 340] h2_stream.c(75): [client
::1:15125] h2_stream(12-13): destroy
[:09.105878 2015] [http2:debug] [pid 1956:tid 572] h2_mplx.c(564): [client
::1:15125] h2_mplx(12-11): open response: 207
::1 - jrandom [25/Nov/2015:02:55:09 +0100] "PROPFIND
/svn-test-work/local_tmp/repos/!svn/rev/1 HTTP/1.1" 207 1267
[:09.105878 2015] [http2:debug] [pid 1956:tid 572] h2_task_input.c(107):
[client ::1:15125] h2_task_input(12-11): read, block=1, mode=3, readbytes=1
[:09.105878 2015] [http2:debug] [pid 1956:tid 908] h2_session.c(1126): [client
::1:15125] h2_stream(12-11): submitted response 207, rv=0
[:09.105878 2015] [http2:debug] [pid 1956:tid 908] h2_session.c(234): [client
::1:15125] h2_stream(12-11): handled, closing
[:09.105878 2015] [http2:debug] [pid 1956:tid 908] h2_stream.c(75): [client
::1:15125] h2_stream(12-11): destroy
[:11.307516 2015] [ssl:info] [pid 1956:tid 908] (OS 10054)An existing
connection was forcibly closed by the remote host. : [client ::1:15125]
AH01991: SSL input filter read failed.
[:11.307516 2015] [http2:debug] [pid 1956:tid 908] h2_conn_io.c(170): (OS
10054)An existing connection was forcibly closed by the remote host. : [client
::1:15125] h2_conn_io: error reading
[:11.307516 2015] [ssl:info] [pid 1956:tid 904] (OS 10054)An existing
connection was forcibly closed by the remote host. : [client ::1:15126]
AH01991: SSL input filter read failed.
[:11.307516 2015] [http2:info] [pid 1956:tid 908] (OS 10054)An existing
connection was forcibly closed by the remote host. : [client ::1:15125]
AH02950: h2_session(12): error reading, terminating
[:11.307516 2015] [http2:debug] [pid 1956:tid 904] h2_conn_io.c(170): (OS
10054)An existing connection was forcibly closed by the remote host. : [client
::1:15126] h2_conn_io: error reading
[:11.307516 2015] [http2:debug] [pid 1956:tid 908] h2_session.c(693): [client
::1:15125] session(12): aborting session, reason=-505 Protocol error
[:11.307516 2015] [http2:info] [pid 1956:tid 904] (OS 10054)An existing
connection was forcibly closed by the remote host. : [client ::1:15126]
AH02950: h2_session(14): error reading, terminating
[:11.308516 2015] [http2:debug] [pid 1956:tid 904] h2_session.c(693): [client
::1:15126] session(14): aborting session, reason=-505 Protocol error
[:11.307516 2015] [http2:debug] [pid 1956:tid 908] h2_conn.c(328): (OS 10054)An
existing connection was forcibly closed by the remote host. : [client
::1:15125] h2_session(12): done
[:11.308516 2015] [http2:debug] [pid 1956:tid 904] h2_conn.c(328): (OS 10054)An
existing connection was forcibly closed by the remote host. : [client
::1:15126] h2_session(14): done
[:11.308516 2015] [ssl:debug] [pid 1956:tid 904] ssl_engine_io.c(1003): [client
::1:15126] AH02001: Connection closed to child 14 with standard shutdown
(server localhost:443)
[:11.308516 2015] [ssl:debug] [pid 1956:tid 908] ssl_engine_io.c(1003): [client
::1:15125] AH02001: Connection closed to child 12 with standard shutdown
(server localhost:443)
[:11.359567 2015] [mpm_winnt:crit] [pid 1956:tid 364] AH02538: Child: Parent
process exited abruptly. Child process is ending
[:11.359567 2015] [mpm_winnt:warn] [pid 1956:tid 936] (OS 995)The I/O operation
has been aborted because of either a thread exit or an application request. :
AH00341: winnt_accept: Asynchronous AcceptEx failed.
[:11.359567 2015] [mpm_winnt:warn] [pid 1956:tid 920] (OS 995)The I/O operation
has been aborted because of either a thread exit or an application request. :
AH00341: winnt_accept: Asynchronous AcceptEx failed.
[:11.359567 2015] [mpm_winnt:debug] [pid 1956:tid 936] child.c(735): AH00348:
Child: Accept thread exiting.
[:11.359567 2015] [mpm_winnt:debug] [pid 1956:tid 920] child.c(735): AH00348:
Child: Accept thread exiting.
[:12.360520 2015] [mpm_winnt:debug] [pid 1956:tid 364] child.c(1215): AH00359:
Child: Released the start mutex
[:12.360520 2015] [mpm_winnt:debug] [pid 1956:tid 364] child.c(1227): AH00361:
Child: 16 threads blocked on the completion port
