Bug 1434916

Summary: httpd.service: Failed with result timeout
Product: [Fedora] Fedora Reporter: Morten Stevens <mstevens>
Component: httpdAssignee: Luboš Uhliarik <luhliari>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: high Docs Contact:
Priority: unspecified    
Version: 26CC: atu, jkaluza, jorton, luhliari, mstevens, pahan
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: httpd-2.4.25-5.fc26 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-04-01 17:33:18 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Morten Stevens 2017-03-22 15:12:55 UTC
Description of problem:

httpd.service: Failed with result timeout
httpd.service: Unit entered failed state.

Version-Release number of selected component (if applicable):

httpd-2.4.25-4.fc26.x86_64

How reproducible:

Steps to Reproduce:
1. Install fedora rawhide (clean install)
2. dnf install httpd
3. systemctl start httpd
4. systemctl stop httpd

Actual results:

Mar 22 16:07:53 fc26 systemd: Stopping The Apache HTTP Server...
Mar 22 16:09:23 fc26 systemd: httpd.service: State 'stop-sigterm' timed out. Killing.
Mar 22 16:09:23 fc26 systemd: httpd.service: Killing process 2818 (httpd) with signal SIGKILL.
Mar 22 16:09:23 fc26 systemd: httpd.service: Killing process 2819 (httpd) with signal SIGKILL.
Mar 22 16:09:23 fc26 systemd: httpd.service: Killing process 2820 (httpd) with signal SIGKILL.
Mar 22 16:09:23 fc26 systemd: httpd.service: Killing process 2821 (httpd) with signal SIGKILL.
Mar 22 16:09:23 fc26 systemd: httpd.service: Killing process 2822 (httpd) with signal SIGKILL.
Mar 22 16:09:23 fc26 systemd: httpd.service: Killing process 2823 (httpd) with signal SIGKILL.
Mar 22 16:09:23 fc26 systemd: httpd.service: Main process exited, code=killed, status=9/KILL
Mar 22 16:09:23 fc26 systemd: httpd.service: Killing process 2822 (httpd) with signal SIGKILL.
Mar 22 16:09:23 fc26 systemd: Stopped The Apache HTTP Server.
Mar 22 16:09:23 fc26 systemd: httpd.service: Unit entered failed state.

Comment 1 Anton Guda 2017-03-26 13:02:31 UTC
It seems to me a deadlock in apr part, and especially for inner "OPTIONS" request. 3-4 previous httpd rpm build suffer from it.

(gdb) bt
#0  0x00007f03be3c7471 in pthread_cond_destroy@@GLIBC_2.3.2 () from target:/lib64/libpthread.so.0
#1  0x00007f03be5f4f6e in run_cleanups (cref=<optimized out>) at memory/unix/apr_pools.c:2352
#2  apr_pool_destroy (pool=0x55a87e09d838) at memory/unix/apr_pools.c:814
#3  0x00007f03be5f4f4d in apr_pool_destroy (pool=0x55a87e099798) at memory/unix/apr_pools.c:811
#4  0x00007f03b3008fbc in clean_child_exit (code=code@entry=0) at prefork.c:230
#5  0x00007f03b30094a2 in child_main (child_num_arg=child_num_arg@entry=6, child_bucket=child_bucket@entry=0) at prefork.c:
#6  0x00007f03b3009883 in make_child (s=0x55a87db08400, slot=6, bucket=0) at prefork.c:834
#7  0x00007f03b300a50d in perform_idle_server_maintenance (p=<optimized out>) at prefork.c:942
#8  prefork_run (_pconf=<optimized out>, plog=<optimized out>, s=<optimized out>) at prefork.c:1138
#9  0x000055a87bc0861e in ap_run_mpm (pconf=0x55a87dae1168, plog=0x55a87db0e388, s=0x55a87db08400) at mpm_common.c:94
#10 0x000055a87bc00dbd in main (argc=<optimized out>, argv=<optimized out>) at main.c:783

(gdb) frame 2
#2  apr_pool_destroy (pool=0x55a87e09d838) at memory/unix/apr_pools.c:814
814         run_cleanups(&pool->cleanups);
(gdb) p pool
$1 = (apr_pool_t *) 0x55a87e09d838
(gdb) p pool->cleanups
$2 = (cleanup_t *) 0x55a87e09d9d8

Comment 2 Morten Stevens 2017-03-27 00:23:33 UTC
Fedora 26 is also affected. Changed it to F26.

Comment 3 Joe Orton 2017-03-27 08:45:21 UTC
What modules do you have installed?   rpm -qf /etc/httpd/conf*.d/*

Comment 4 Morten Stevens 2017-03-27 11:56:06 UTC
(In reply to Joe Orton from comment #3)
> What modules do you have installed?   rpm -qf /etc/httpd/conf*.d/*

httpd-2.4.25-5.fc27.x86_64
cacti-1.1.0-1.fc27.noarch
php-7.1.3-3.fc27.x86_64
phpMyAdmin-4.6.6-2.fc26.noarch
httpd-filesystem-2.4.25-5.fc27.noarch
mod_ssl-2.4.25-5.fc27.x86_64
httpd-2.4.25-5.fc27.x86_64
httpd-2.4.25-5.fc27.x86_64
httpd-2.4.25-5.fc27.x86_64
httpd-2.4.25-5.fc27.x86_64
httpd-2.4.25-5.fc27.x86_64
httpd-2.4.25-5.fc27.x86_64
httpd-2.4.25-5.fc27.x86_64
httpd-2.4.25-5.fc27.x86_64
mod_ssl-2.4.25-5.fc27.x86_64
httpd-2.4.25-5.fc27.x86_64
httpd-2.4.25-5.fc27.x86_64
php-7.1.3-3.fc27.x86_64
httpd-2.4.25-5.fc27.x86_64

Comment 6 Joe Orton 2017-03-27 16:05:49 UTC
I think it's mod_http2.

To workaround disable mod_http2, e.g.:

sed -i '/http2/s,\(.*\),#\1,' /etc/httpd/conf.modules.d/00-base.conf

Comment 8 Joe Orton 2017-03-27 16:37:54 UTC
Lubos I wonder if it's one of the mod_http2 changes in 2.4.x upstream since 2.4.25

  *) mod_http2: moving session cleanup to pre_close hook to avoid races with
     modules already shut down and slave connections still operating.
     [Stefan Eissing]

or

  *) mod_http2: regression fix on PR 59348, on graceful restart, ongoing 
     streams are finished normally before the final GOAWAY is sent. 
     [Stefan Eissing, <slavko gmail.com>]

^ ... this is like a graceful restart, we use "graceful stop."

Comment 9 Morten Stevens 2017-03-27 19:11:50 UTC
(In reply to Joe Orton from comment #6)
> I think it's mod_http2.
> 
> To workaround disable mod_http2, e.g.:
> 
> sed -i '/http2/s,\(.*\),#\1,' /etc/httpd/conf.modules.d/00-base.conf

Yeah, this is it. After disabling mod_http2 it works fine to stop and restart httpd.

Comment 11 Luboš Uhliarik 2017-03-28 11:12:12 UTC
I can confirm, patch [1] fixes the issue. I will commit it to rawhide and F26 ASAP + add it to Bodhi.

[1] https://svn.apache.org/viewvc?view=revision&revision=1787141

Comment 12 Fedora Update System 2017-03-28 13:06:30 UTC
httpd-2.4.25-5.fc26 has been submitted as an update to Fedora 26. https://bodhi.fedoraproject.org/updates/FEDORA-2017-9e69f156ea

Comment 13 Fedora Update System 2017-03-28 17:54:43 UTC
httpd-2.4.25-5.fc26 has been pushed to the Fedora 26 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2017-9e69f156ea

Comment 14 Fedora Update System 2017-04-01 17:33:18 UTC
httpd-2.4.25-5.fc26 has been pushed to the Fedora 26 stable repository. If problems still persist, please make note of it in this bug report.