Idle H2 threads don't terminate on "graceful" Apache restart (mpm_event)

[famzah]

Vanilla Apache with "mpm_event" functions in the following way after a "graceful" restart:

1. Old child processes which serve no requests are terminated immediately.
2. Old child processes which have threads busy with existing requests are left alive. The busy threads continue to work until the requests are completed. The idle threads are terminated immediately.

This is an efficient way to handle "graceful" restarts because we can increase the ServerLimit a lot, in order to accommodate lots of old child processes (finishing a few old connections), and have a couple of up-to-date active child processes (with lots of threads waiting to serve new clients).

The old child processes allocate very few memory resources because most of their threads are terminated.

Unfortunately, mod_http2 doesn't honor the "graceful" restart. None of the following settings made any difference during my tests:

1. H2MinWorkers 1 (additionally, I figured out that this isn't honored at all because a lot of H2 threads are always created, even for an idle Apache server which just started)
2. H2MaxWorkerIdleSeconds 5 (the idle H2 thread live forever regardless of this setting combined with H2MinWorkers 1)

The old Apache child processes keep all their H2 threads active forever, regardless of the fact that most of those H2 threads are idle. I will appreciate it if you can look into this.

[famzah]

I'm attaching my test installation, configuration and results. But basically it's very easy to reproduce this:

1. Create a large file (1 GBytes).
2. Start to download it using curl --limit-rate 32k (both --http1.1 and --http2 reproduce the problem).
3. Restart Apache "gracefully".
4. Watch how the old Apache child process terminates most of its threads by ps -o thcount,pid,command axf|grep httpd|grep -v grep. H2 threads do not terminate, though. The curl request is continued to be served until you terminate curl.

configs.txt
install.txt
tests_with_h2.txt
tests_without_h2.txt

[icing]

The implementation in mod_http2 lets ongoing requests continue and closes the connections when they are finished normally. If you enable LogLevel http2:debug, you should see that the module logs sth like:

... AH03068: h2_session(2,BUSY,1): sent FRAME[GOAWAY[error=0, reason='', ...

when you initiate the graceful restart. Once the request is done, it closes the connection on its own, sends a

sent FRAME[GOAWAY[error=0, reason='', last_stream=1]]
...
AH03078: h2_session(2,DONE,0): transit [BUSY] -- local goaway --> [DONE]

the local goaway means that the server initiated the connection close. So, if you can confirm these logs in your setup, the module works as designed.

The question then is, is this the correct design? To my knowledge, this is the same has HTTP/1.1 works. A graceful restart will let ongoing HTTP/1.1 requests continue till the end.

Maybe I am wrong and misunderstood your issue?

[covener]

I think the Q is maybe more about whether the idle H2 threads exit right away during the graceful, or if they linger while the active ones finish? If they linger, it means the outgoing process uses marginally more resources than necessary.

[icing]

Good point, @covener. Seems like the right thing to do. Need to look how to achieve this...

[famzah]

What @covener said :) The correct behavior would be that "idle" H2 threads exit immediately.

If "busy" H2 threads do not correspond 1:1 with the "busy" Apache worker threads, it's a good compromise that you leave exactly that many H2 threads as we have Apache threads. For example, if during "goaway" Apache leaves only five threads in the terminating child, you can leave five H2 threads, too. I suppose that five H2 threads are enough to serve five Apache threads. When one Apache thread exits, you terminate one "idle" H2 thread, too. And so on, until no threads are active and the old child process terminates, too.

If H2MinWorkers and H2MaxWorkerIdleSeconds work properly, then during "goaway" you can just set H2MinWorkers 1, and also set H2MaxWorkerIdleSeconds 1. This way most "idle" H2 threads will terminate very quickly and if Apache needs more of them for some reason during the handling of the old existing connections, more "active" H2 threads will be born and later will terminate when they get "idle" again.

The problem is that my tests show that H2MinWorkers and H2MaxWorkerIdleSeconds have no effect, regardless if the Apache child is in "normal" or in a "goaway" state.

[famzah]

@icing, did you have a chance to look into this? Is there some configuration option which we can tune, in order to achieve a similar effect?

[icing]

@famzah I have in master now a version that should trigger that. It would be nice if you could verify it.

[famzah]

I tried two versions of mod_h2: (1) from master, and (2) the latest release v1.15.20 with 2e536e3 applied as patch. Built for Apache 2.4.48.

Both versions show the same behavior on graceful restart:

• OK: idle H2 threads are correctly terminated if there is an ongoing HTTP/2 request (curl -v ... --limit-rate 32k --http2)
• NOT OK: no H2 threads are terminated if there is an ongoing HTTP/1.1 request (curl -v ... --limit-rate 32k --http1.1) and no HTTP/2 requests are active

This is regardless of whether H2MinWorkers is set to 1 or 1000.

Next step is to understand why no H2 threads are terminated when all of them are idle.

P.S. Additionally, I wanted to discuss if it isn't better that you leave the same count of H2 threads as the count of currently active Apache worker threads. I'm not sure if there is a case when all H2 threads are currently idle because all existing Apache threads don't need them right now but those existing Apache threads may need some H2 threads at a later time when they service the existing requests. Excuse me, if I'm talking nonsense...

[icing]

Both versions show the same behavior on graceful restart:

• OK: idle H2 threads are correctly terminated if there is an ongoing HTTP/2 request (curl -v ... --limit-rate 32k --http2)
• NOT OK: no H2 threads are terminated if there is an ongoing HTTP/1.1 request (curl -v ... --limit-rate 32k --http1.1) and no HTTP/2 requests are active

Thanks for verifying that the change is effective at least in the case it is being called. I am investigating on the httpd dev list what the best, generic mechanism would be to achieve this.

This is regardless of whether H2MinWorkers is set to 1 or 1000.

Next step is to understand why no H2 threads are terminated when all of them are idle.

See above. Someone needs to notify the workers.

P.S. Additionally, I wanted to discuss if it isn't better that you leave the same count of H2 threads as the count of currently active Apache worker threads. I'm not sure if there is a case when all H2 threads are currently idle because all existing Apache threads don't need them right now but those existing Apache threads may need some H2 threads at a later time when they service the existing requests. Excuse me, if I'm talking nonsense...

You raise a valid point. I rechecked the code: on a graceful shutdown of the server, h2 will stop accepting new streams (e.g. requests), but continue processing all it has. This indeed could result in no workers being available to do this if all idle are shut down.

So, the question is: what should actually happen on a graceful shutdown regarding h2. There could be hundreds of requests queued in the server and shutting down h2 workers would prolong processing them. Otoh, if there is only one ongoing request remaining, one would like to reclaim the resources of idle workers early.

But I am not sure how to achieve this balance.

[famzah]

Thank you for looking into this!

The best approach would be if H2MinWorkers and H2MaxWorkerIdleSeconds work as described. My tests show that they don't.

If these config settings start working as advertised, then the best and most simple solution on graceful shutdown in regards to H2 would be:

1. Administratively set H2MinWorkers 1 (or 0, if possible).
2. Administratively set H2MaxWorkerIdleSeconds 5 (or 1, if viable).
3. Change nothing else and continue servicing requests as before when the Apache child was in normal state. Let the H2 workers exit because they're idle for 5 seconds, and keep only one idle H2 thread. If the standard Apache threads need H2, it will create additional threads, do its work and after 5 seconds of idle time terminate those H2 threads again.

Fixing the scale up/down will benefit H2 when working in the "normal" Apache child state, too.

---

The second best approach would be to keep the same count of threads for both Apache and H2. This way we're sure that Apache threads will never starve for H2 attention. When an Apache thread exits, one H2 thread exists, too, if the count of H2 threads is bigger than the count of Apache threads.

Note that we're sure that Apache threads never get more, once the Apache child gets into graceful shutdown. The Apache threads only get fewer with time, as they finish their existing requests.

If it's hard to get notified when an Apache threads exits, it's also acceptable that you never kill any H2 threads. Once you get the "graceful shutdown" event, you kill most H2 threads leaving the same count as currently active Apache threads. Then you never decrease the H2 threads when Apache threads exit. This is a "better than nothing" compromise.

[icing]

I am working on a change that makes h2 workers...work against as advertised in regards to dynamic and idle timeouts.

What you observe is that h2 only detects a shutdown when it is active. There are no callbacks at the moment that let a module get informed about a shutdown. I am proposing to add such a facility in the main server, but that will take some time to go into a release.

The number of active connections is not so easily determined from a module due to the internal architecture and varying mpm modules. I would favour, once a graceful shutdown is detected, to go down to H2MinWorkers immediately.

WDYT?

[famzah]

I am working on a change that makes h2 workers...work again as advertised in regards to dynamic and idle timeouts.

Sounds like a good plan!

When you're ready with this, let me know and I will test it. Thank you.

[icing]

I am ready with this: the current master makes workers dynamic again. I added some load test cases to stress it a bit. But it would be good if you could also hammer it.

[icing]

@famzah ping! do you know when you can throws this into your meatgrinder?

[famzah]

Sorry for the late reply. I was off for a week.

I compiled mod_h2 release 1.15.21 with Apache 2.4.48. Simple tests show that everything works as expected.

Unfortunately, on a busy production server I encountered a problem. The "old gen" Apache processes never terminate. I see this almost for all "old gen" processes. The threads in each of those "old gen" processes decrease until it's just one thread according to ps -o thcount,pid,command axf.

"Old gen" processes stay with one thread forever. An "strace" shows the following:

strace: Process 47785 attached
futex(0x7334efbf9128, FUTEX_WAIT_PRIVATE, 0, NULL ... # forever

I can't reproduce this on a tester machine. Please review the latest source code changes and if nothing rings a bell, you could fork mod_h2 release 1.15.21, add a lot of debug log() suitable for a busy production server, and then I can try to collect debug info.

P.S. Our previous Apache build with mod_h2 release 1.15.19 works flawlessly. The "old gen" processes work (sometimes for very long time) until they finish all requests, and finally they terminate.

[icing]

Can you disclose the H2*Workers* settings you configure in production? Maybe there is something connected to that.

[icing]

Ah, you mean that the configure fails now. I see. Working on that.

[icing]

Can you verify that master now works for you?

[famzah]

In production I use the following:

H2MinWorkers 1
H2MaxWorkers 1000
H2MaxWorkerIdleSeconds 5

It's not a problem with configure. I can compile everything, it runs correctly on a tester machine but fails on a busy production machine.

When the old Apache child processes enter "graceful shutdown", they finish all their connections but the Linux processes never terminate.

The process tree looks like this:

# ps -o thcount,pid,command axf | grep httpd | grep -v grep
    1 47082 /apache/bin/httpd -k start
    1 56700  \_ /apache/bin/httpd -k start # this old process with 1 OS thread never terminates
    1 10785  \_ /apache/bin/httpd -k start # this old process with 1 OS thread never terminates
 1003 10786  \_ /apache/bin/httpd -k start # an active Apache process which serves new connections
 1003 12051  \_ /apache/bin/httpd -k start # an active Apache process which serves new connections

Do you have any idea why?

[icing]

When I tried to reproduce this, I came across a scenario in my test suite where children did not exit cleanly and the main process needed to kill it after a timeout. I am investigating this with the others on the httpd dev list.

This may be the same bug that you are seeing. This one is unrelated to h2 workers and looks as if a mpm_event does not see changes in a volatile int as it expects. I'll update here if we can find the cause and a fix for it.

But since you say the child never terminates, it looks like something different. Nevertheless, I want this other mystery solved before I can try to analyse what you see. 2 Heisenbugs at the same time is messy.

[famzah]

My issue looks pretty similar. Except that the main process never kills the stale child processes.

Two notes:

• our previous Apache build with mod_h2 release 1.15.19 works flawlessly; so I suspect the latest changes in mod_h2 are causing this
• you say "the main process needed to kill it after a timeout"; is there an Apache setting I can configure, in order to try this?

[icing]

My issue looks pretty similar. Except that the main process never kills the stale child processes.

Two notes:

• our previous Apache build with mod_h2 release 1.15.19 works flawlessly; so I suspect the latest changes in mod_h2 are causing this

It seems likely.

• you say "the main process needed to kill it after a timeout"; is there an Apache setting I can configure, in order to try this?

No, and the bug becomes visible when you tell the server to stop. Then something like this would be in your logs:

[core:warn] [pid 72813:tid 4493635072] AH00045: child process 72886 still did not exit, sending a SIGTERM
[core:warn] [pid 72813:tid 4493635072] AH00045: child process 72886 still did not exit, sending a SIGTERM
[core:warn] [pid 72813:tid 4493635072] AH00045: child process 72886 still did not exit, sending a SIGTERM
[core:error] [pid 72813:tid 4493635072] AH00046: child process 72886 still did not exit, sending a SIGKILL

[covener]

No, and the bug becomes visible when you tell the server to stop. Then something like this would be in your logs:

I think OP may see similar result, with less logging, from MaxRequestsPerChild/MaxConnectionsPerChild nonzero or MaxSpareThreads < MaxClients too.

[icing]

@famzah I made a stopgap solution in master that makes sure that child processes exit latest after 5 seconds, even if not all h2 workers have terminated cleanly. A warning will be logged in such a case to make it visible what happened.

I'd appreciate if you could try that and let me know how it behaves on your system.

[icing]

@famzah just added a fix of the fix after more testing. sorry, if you already checked out.

[famzah]

This definitely fixed the problem! I see very often the following in the Apache error log:

[warn] [pid 10210] h2_workers.c(353): AH: h2_workers: cleanup, 11 idle workers did not exit after 5 seconds.

The count of "idle workers" is a random number from 1 to 14, but I guess this depends on how busy the server is.

(+) One small thing to fix. I got the following in the error log:

[warn] [pid 42553] h2_workers.c(353): AH: h2_workers: cleanup, 0 idle workers did not exit after 5 seconds.

If it is the expected behavior that we have "0 idle workers", then this warning should not be printed in this case.

(+) One more thought. The problem is now fixed but using a cleanup "hack" so to say. Should we dig to understand why the idle H2 workers don't exit in the first place?

What I can say for sure is that there are no real Linux threads active. When the stopgap cleanup is triggered, I'm positive that all Linux threads have terminated already. Maybe the threads are not pthread_join()'ed in time and that's why they are still accounted as active?

[icing]

This definitely fixed the problem! I see very often the following in the Apache error log:

[warn] [pid 10210] h2_workers.c(353): AH: h2_workers: cleanup, 11 idle workers did not exit after 5 seconds.

The count of "idle workers" is a random number from 1 to 14, but I guess this depends on how busy the server is.

This is excellent news, since we now know where the problem happened.

(+) One small thing to fix. I got the following in the error log:

[warn] [pid 42553] h2_workers.c(353): AH: h2_workers: cleanup, 0 idle workers did not exit after 5 seconds.

If it is the expected behavior that we have "0 idle workers", then this warning should not be printed in this case.

Yes.

(+) One more thought. The problem is now fixed but using a cleanup "hack" so to say. Should we dig to understand why the idle H2 workers don't exit in the first place?

What I can say for sure is that there are no real Linux threads active. When the stopgap cleanup is triggered, I'm positive that all Linux threads have terminated already. Maybe the threads are not pthread_join()'ed in time and that's why they are still accounted as active?

I believe the change in the dynamic workers is causing the counting to go off. Since you report the threads to have terminated, I should hopefully be able to find out where that happens. Will let you know when I have a possible solution as I am so far not able to reproduce this locally.

[famzah]

@icing, we are compiling mod_h2 as an external module by getting the source code from the releases here. Our build of Apache 2.4.51 runs mod_h2 version "1.15.24" which is the same version that is shipped with Apache sources but I found some differences like the following:

--- mod_http2-1.15.24/mod_http2/h2_version.h    2021-09-10 12:38:38.000000000 +0300
+++ httpd-2.4.51/modules/http2/h2_version.h     2021-09-26 17:30:51.000000000 +0300
@@ -27,7 +27,7 @@
  * @macro
  * Version number of the http2 module as c string
  */
-#define MOD_HTTP2_VERSION "1.15.24-git"
+#define MOD_HTTP2_VERSION "1.15.24"

--- mod_http2-1.15.24/mod_http2/h2_workers.c    2021-09-10 10:50:35.000000000 +0300
+++ httpd-2.4.51/modules/http2/h2_workers.c     2021-09-26 17:30:51.000000000 +0300
@@ -319,9 +319,9 @@
 static apr_status_t workers_pool_cleanup(void *data)
 {
     h2_workers *workers = data;
-    apr_time_t timout = apr_time_from_sec(1);
+    apr_time_t end, timeout = apr_time_from_sec(1);
     apr_status_t rv;
-    int i, n = 5;
+    int n, wait_sec = 5;
 
     ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, workers->s,
                  "h2_workers: cleanup %d workers idling",
@@ -333,24 +333,23 @@
      * have either been handled (graceful) or we are forced exiting
      * (ungrateful). Either way, we show limited patience. */
     apr_thread_mutex_lock(workers->lock);
-    for (i = 0; i < n; ++i) {
-        if (!apr_atomic_read32(&workers->worker_count)) {
-            break;
-        }
-        rv = apr_thread_cond_timedwait(workers->all_done, workers->lock, timout);
+    end = apr_time_now() + apr_time_from_sec(wait_sec);
+    while ((n = apr_atomic_read32(&workers->worker_count)) > 0
+           && apr_time_now() < end) {
+        rv = apr_thread_cond_timedwait(workers->all_done, workers->lock, timeout);
         if (APR_TIMEUP == rv) {
             ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, workers->s,
-                         APLOGNO() "h2_workers: waiting for idle workers to close, "
+                         APLOGNO(10290) "h2_workers: waiting for idle workers to close, "
                          "still seeing %d workers living",
                          apr_atomic_read32(&workers->worker_count));
             continue;
         }
     }
-    if (i >= n) {
+    if (n) {
         ap_log_error(APLOG_MARK, APLOG_WARNING, 0, workers->s,
-                     APLOGNO() "h2_workers: cleanup, %d idle workers "
+                     APLOGNO(10291) "h2_workers: cleanup, %d idle workers "
                      "did not exit after %d seconds.",
-                     apr_atomic_read32(&workers->worker_count), i);
+                     n, wait_sec);
     }
     apr_thread_mutex_unlock(workers->lock);
     ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, workers->s,

I don't know if this could bring a significant difference in the behavior. But it could explain why everything works on our servers but @nabheet and @hansborr are reporting issues, assuming that they use the mod_h2 sources which were shipped with the source code of Apache 2.4.51.

[hansborr]

I was using the one bundled with 2.4.51 -- but I've just now tried compiling mod_http2 from the source in this git repo (mod_h2-1.15.24), and I still see the same behavior.

Note: I've waited with "hung" processes on graceful restart for ~20minutes so far on the new build, which seems like it's long enough to confirm that they won't close out on their own.

[icing]

Could you try the following patch on top of 1.15.24?

index dc883b5..a97c0cb 100644
--- a/mod_http2/h2_session.c
+++ b/mod_http2/h2_session.c
@@ -275,7 +275,7 @@ static int on_begin_headers_cb(nghttp2_session *ngh2,
                                const nghttp2_frame *frame, void *userp)
 {
     h2_session *session = (h2_session *)userp;
-    h2_stream *s;
+    h2_stream *s = NULL;

     /* We may see HEADERs at the start of a stream or after all DATA
      * streams to carry trailers. */
@@ -284,7 +284,7 @@ static int on_begin_headers_cb(nghttp2_session *ngh2,
     if (s) {
         /* nop */
     }
-    else {
+    else if (session->local.accepting) {
         s = h2_session_open_stream(userp, frame->hd.stream_id, 0);
     }
     return s? 0 : NGHTTP2_ERR_START_STREAM_NOT_ALLOWED;

[hansborr]

It still seems to happen even with that patch.

Would it be helpful to you to have access to a server in the affected state? I could spin up a temporary box on digital ocean and get it in the state with hung threads.

[icing]

It would be nice to have a backtrace of where the threads are at with symbols - if one can dream.

I will analyze my code some more and see where h2 connections on a graceful shutting down child process get stuck. My current read of the situation is:

• a h2 client is busy sending many, many requests on a connection
• a server is reloaded gracefully or reaches its connection limit and starts a new child, shutting down the current one.
• shut down child process never terminates
• h2 client hangs

The process of gracefully stopping a child is:

1. no longer accept new connections
2. let existing connections run to their end
3. terminate all worker threads and exit

We seem to get stuck in 2. The h2 connection never finishes, but also does no longer process requests from the client.

[icing]

Based on the analysis above, the patch below should mitigate the problem.

Gist: the new graceful_shutdown was too aggressive. It prevented handling of h2 requests that a connection had already taken in, but not started processing yet. These requests then became stuck.

diff --git a/mod_http2/h2_session.c b/mod_http2/h2_session.c
index dc883b5..a97c0cb 100644
--- a/mod_http2/h2_session.c
+++ b/mod_http2/h2_session.c
@@ -275,7 +275,7 @@ static int on_begin_headers_cb(nghttp2_session *ngh2,
                                const nghttp2_frame *frame, void *userp)
 {
     h2_session *session = (h2_session *)userp;
-    h2_stream *s;
+    h2_stream *s = NULL;

     /* We may see HEADERs at the start of a stream or after all DATA
      * streams to carry trailers. */
@@ -284,7 +284,7 @@ static int on_begin_headers_cb(nghttp2_session *ngh2,
     if (s) {
         /* nop */
     }
-    else {
+    else if (session->local.accepting) {
         s = h2_session_open_stream(userp, frame->hd.stream_id, 0);
     }
     return s? 0 : NGHTTP2_ERR_START_STREAM_NOT_ALLOWED;
diff --git a/mod_http2/h2_workers.c b/mod_http2/h2_workers.c
index 28bb428..ae250b0 100644
--- a/mod_http2/h2_workers.c
+++ b/mod_http2/h2_workers.c
@@ -479,8 +479,6 @@ apr_status_t h2_workers_unregister(h2_workers *workers, struct h2_mplx *m)
 void h2_workers_graceful_shutdown(h2_workers *workers)
 {
     workers->shutdown = 1;
-    workers->min_workers = 1;
     workers->max_idle_duration = apr_time_from_sec(1);
-    h2_fifo_term(workers->mplxs);
     wake_non_essential_workers(workers);
 }

[famzah]

I don't know if this helps but I've seen the aforementioned error long before the latest Apache changes, when I worked on this in July:

[Fri Jul 09 17:13:17 2021] [notice] [pid 59559] event.c(3181): AH00493: SIGUSR1 received.  Doing graceful restart
[Fri Jul 09 17:13:17 2021] [error] [pid 16383] h2_mplx.c(660): (70014)End of file found: [client 127.0.0.1:59658] AH10021: h2_mplx(4532): register at workers

At the point when this happened, I also got "curl" errors like the following:

curl: (16) Error in the HTTP2 framing layer

I'm not 100% positive that the Apache error message and the "curl" errors are always related. But I definitely was getting the "curl" errors during Apache graceful restarts. At this time I was doing a lot of short "curl" HTTP2 requests.

I had this laying in my work notes with the tag "todo" :)

[icing]

Thanks @famzah, that would confirm my suspicions that the shutdown was done too aggressively. The line

    h2_fifo_term(workers->mplxs);

prevented any further scheduling of h2 requests and that led to the End of file found errors in the log.

[hansborr]

The latest patch seems to fix it -- I haven't been able to get h2 worker threads to appear to "hang" with h2load and a graceful restart any more. The h2load client doesn't freeze up anymore either.

Note: My testing overall is pretty minimal though, I've only been checking for the one specific problem Nabheet and I were seeing. Not sure how to exhaustively test that no other problems have occured.

[icing]

@hansborr many thanks for testing this! I understand that your testing was focussed on this case and rightly so.

I will make a release here with that patch.

[icing]

Released as v1.15.25. Thank you all!