The execution order of requests is not defined by the protocol and up to the server implementation. As you noticed, one major factor is the mpm active in httpd, influencing how, and if, requests are handled in parallel.
Even setting dependencies and priorities on streams will not make this fully deterministic, as I tried to explain. The case of a prefork mpm without further configuration is an extreme case. Prefork, intended to allow a single thread processing model, has by default 1(!) http/2 worker. That means that requests are worked on one at a time. A blocking request may therefore block all later requests. This is not how HTTP/2 is supposed to work, but it is how prefork is. You can configure more H2Workers and have multiple threads even in prefork. But you need to be sure that the application you run can live with multi-threading. Without knowing your client that well, it seems to assume that requests are processed one after the other. And rely on that. This assumption no longer holds in HTTP/2. If you send 2 requests, responses may arrive in any order or interleaved, not matter what you specify for priority. Relying on the exposed behaviour of a certain implementation under certain configuration is probably the least that you'd want. //Stefan > Am 25.11.2015 um 03:10 schrieb Bert Huijben <[email protected]>: > >> -----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
