[Bug 60671] New: "Event handle is invalid" when using mod_cache_disk

[b***@apache.org]

https://bz.apache.org/bugzilla/show_bug.cgi?id=60671

Bug ID: 60671
Summary: "Event handle is invalid" when using mod_cache_disk
Product: Apache httpd-2
Version: 2.4.25
Hardware: PC
Status: NEW
Severity: normal
Priority: P2
Component: mod_cache_disk / mod_disk_cache
Assignee: ***@httpd.apache.org
Reporter: ***@d-velop.de
Target Milestone: ---

Created attachment 34696
--> https://bz.apache.org/bugzilla/attachment.cgi?id=34696&action=edit
ErrorLog

We are using Apache 2.4.25 (Windows) as a reverse proxy with caching.

I am using the following cache configuration:

CacheRoot cache
CacheDirLevels 5
CacheDirLength 3
CacheEnable disk /

The cache itself is working correctly. But after a period of time (1-x hours),
Apache is crashing/restarting.
The log messages in this case are:

[Thu Jan 26 13:58:34.304331 2017] [mpm_winnt:crit] [pid 8824:tid 324] (OS 6)The
handle is invalid. : AH00356: Child: WAIT_FAILED -- shutting down server
[Thu Jan 26 13:58:34.304331 2017] [mpm_winnt:crit] [pid 8824:tid 324] (OS 6)The
handle is invalid. : AH02644: Child: Event handle #0 (8) is invalid
[Thu Jan 26 13:59:06.336811 2017] [mpm_winnt:notice] [pid 8824:tid 324]
AH00362: Child: Waiting 90 more seconds for 1 worker threads to finish.
[Thu Jan 26 13:59:36.368238 2017] [mpm_winnt:notice] [pid 8824:tid 324]
AH00362: Child: Waiting 60 more seconds for 1 worker threads to finish.
[Thu Jan 26 14:00:06.396427 2017] [mpm_winnt:notice] [pid 8824:tid 324]
AH00362: Child: Waiting 30 more seconds for 1 worker threads to finish.
[Thu Jan 26 14:00:36.420727 2017] [mpm_winnt:notice] [pid 8824:tid 324]
AH00362: Child: Waiting 0 more seconds for 1 worker threads to finish.
[Thu Jan 26 14:00:36.520808 2017] [mpm_winnt:notice] [pid 8824:tid 324]
AH00363: Child: Terminating 1 threads that failed to exit.
[Thu Jan 26 14:00:36.520808 2017] [mpm_winnt:notice] [pid 8824:tid 324]
AH00364: Child: All worker threads have exited.
[Thu Jan 26 14:00:36.542289 2017] [mpm_winnt:notice] [pid 3636:tid 384]
AH00428: Parent: child process 8824 exited with status 0 -- Restarting.
[Thu Jan 26 14:00:36.831791 2017] [mpm_winnt:notice] [pid 3636:tid 384]
AH00455: Apache/2.4.25 (Win64) OpenSSL/1.0.2j configured -- resuming normal
operations
[Thu Jan 26 14:00:36.831791 2017] [mpm_winnt:notice] [pid 3636:tid 384]
AH00456: Apache Lounge VC14 Server built: Dec 17 2016 11:15:57
[Thu Jan 26 14:00:36.831791 2017] [core:notice] [pid 3636:tid 384] AH00094:
Command line: 'E:\\d3\\d.ecs http gateway\\webserver\\bin\\httpd.exe -d
E:/d3/d.ecs http gateway/webserver -d E:\\d3\\d.ecs http gateway\\webserver'
[Thu Jan 26 14:00:36.832768 2017] [mpm_winnt:notice] [pid 3636:tid 384]
AH00418: Parent: Created child process 2012
[Thu Jan 26 14:00:37.525523 2017] [mpm_winnt:notice] [pid 2012:tid 324]
AH00354: Child: Starting 250 worker threads.

(complete logfile attached)

When deactivating the cache, everything runs perfectly for weeks.

We made the following additional tests:

- When changing from disk cache to socache/shmcb ==> no crash.

- Since we use Windows, we tried 3 diffrent compilations from 2 distrubutors
(ApacheHaus, ApacheLounge VC11/VC14) ==> This makes no diffrence (crash)

- We tried the following config without success (config is recommended on
https://www.apachelounge.com/viewtopic.php?p=34683)
AcceptFilter http none
AcceptFilter https none
EnableSendfile off
EnableMMAP off


Let me know, if you need more information or log files. I always can reproduce
this issue in my test environment.

[b***@apache.org]

https://bz.apache.org/bugzilla/show_bug.cgi?id=60671

Szőgyényi Gábor <***@freemail.hu> changed:

What |Removed |Added
----------------------------------------------------------------------------
OS| |All
CC| |***@freemail.hu

[b***@apache.org]

https://bz.apache.org/bugzilla/show_bug.cgi?id=60671

***@destinysolutions.com changed:

What |Removed |Added
----------------------------------------------------------------------------
CC| |***@destinysolutions.
| |com

[b***@apache.org]

https://bz.apache.org/bugzilla/show_bug.cgi?id=60671

--- Comment #1 from ***@destinysolutions.com ---
We are seeing similar behavior on a number of Apache installations we just
upgraded from 2.4.23 to 2.4.27. We enabled the cache feature during the
upgrade.

As these are production systems, we've disabled the cache feature for now, but
look forward to a possible fix.

[b***@apache.org]

https://bz.apache.org/bugzilla/show_bug.cgi?id=60671

--- Comment #2 from Michael Schlenker <***@contact.de> ---
I had a look at some crash dumps (via procdump) of this issue.

In all cases i saw the error seems to be a CloseHandle() on an invalid
apr_thread_mutex_t -> handle inside the apr_file object.

The code can only create a Critical Section Mutex if APR_HAS_UNICODE_FS is
active, but it tries to close a Handle, which is always uninitialized memory
for Critial Section Mutexes.

The Mutex seems to get destroyed twice, the type is always 0xffffffff = -1,
which is the sentinel set by apr_thread_mutex_t when a critical section gets
deleted the first time.


Microsoft (R) Windows Debugger Version 10.0.10586.567 X86
Copyright (c) Microsoft Corporation. All rights reserved.


Loading Dump File [D:\logs\httpd.exe_181120_160002\httpd.exe_181120_161836.dmp]
User Mini Dump File with Full Memory: Only application data is available

Comment:
*** Unhandled exception: C0000008.INVALID_HANDLE'

This dump file has an exception of interest stored in it.
The stored exception information can be accessed via .ecxr.
(d00.fa8): Invalid handle - code c0000008 (first/second chance not available)
eax=00000000 ebx=1736d3c0 ecx=00000000 edx=00000000 esi=64697254 edi=17379108
eip=777ac3ec esp=1599f9f0 ebp=1599fa00 iopl=0 nv up ei pl nz ac pe nc
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000216
ntdll!NtClose+0xc:
777ac3ec c20400 ret 4
0:255> kb
# ChildEBP RetAddr Args to Child
00 1599f9ec 757def8a 64697254 6d018d80 1736c110 ntdll!NtClose+0xc
01 1599fa00 6d018dab 64697254 1599fa20 6d019d99 KERNELBASE!CloseHandle+0x16
02 1599fa0c 6d019d99 17379108 6d016b10 17379108
libapr_1!thread_mutex_cleanup+0x2b
[c:\sdk\src\apr-1.6.3\locks\win32\thread_mutex.c @ 35]
03 1599fa20 6d018f94 1736c0d8 17379108 6d018d80
libapr_1!apr_pool_cleanup_run+0x19
[c:\sdk\src\apr-1.6.3\memory\unix\apr_pools.c @ 2620]
04 1599fa34 6d016b3f 17379108 1736d450 1599fa64
libapr_1!apr_thread_mutex_destroy+0x14
[c:\sdk\src\apr-1.6.3\locks\win32\thread_mutex.c @ 133]
05 1599fa44 6cbd1721 1736b258 1736d430 6cbd1756 libapr_1!apr_file_close+0x2f
[c:\sdk\src\apr-1.6.3\file_io\win32\open.c @ 503]
06 1599fa50 6cbd1756 00000000 1736c118 1736d2d8
mod_cache_disk!close_disk_cache_fd+0x11
[c:\sdk\src\httpd-2.4.33\modules\cache\mod_cache_disk.c @ 605]
07 1599fa64 6cbe37b6 1736d3c0 009e1048 17d7dc50
mod_cache_disk!remove_entity+0x16
[c:\sdk\src\httpd-2.4.33\modules\cache\mod_cache_disk.c @ 618]
08 1599faf4 6d071eba 17379e00 17d7dc50 1736be38
mod_cache!cache_save_filter+0x9b6
[c:\sdk\src\httpd-2.4.33\modules\cache\mod_cache.c @ 1326]
09 1599fb08 6cbf21fc 17379e00 17d7dc50 171be130 libhttpd!ap_pass_brigade+0x5a
[c:\sdk\src\httpd-2.4.33\server\util_filter.c @ 590]
0a 1599fb20 6d071eba 1736be38 17d7dc50 17d7dbc0
mod_headers!ap_headers_output_filter+0x7c
[c:\sdk\src\httpd-2.4.33\modules\metadata\mod_headers.c @ 885]
0b 1599fb34 6cc31f20 1736be38 17d7dc50 1736c118 libhttpd!ap_pass_brigade+0x5a
[c:\sdk\src\httpd-2.4.33\server\util_filter.c @ 590]
0c 1599fb6c 6d071eba 1736be20 17d7dba8 170381a0
mod_deflate!deflate_out_filter+0x760
[c:\sdk\src\httpd-2.4.33\modules\filters\mod_deflate.c @ 913]
0d 1599fb80 6cb53567 1736be20 17d7dba8 18720020 libhttpd!ap_pass_brigade+0x5a
[c:\sdk\src\httpd-2.4.33\server\util_filter.c @ 590]
...

0:255> .frame 02
02 1599fa0c 6d019d99 libapr_1!thread_mutex_cleanup+0x2b
[c:\sdk\src\apr-1.6.3\locks\win32\thread_mutex.c @ 35]
0:255> dt data
Local var @ 0x1599fa14 Type void*
0x17379108
Void
0:255> dt libapr_1!apr_thread_mutex_t 0x17379108
+0x000 pool : 0x1736c0d8 apr_pool_t
+0x004 type : 0xffffffff (No matching name)
+0x008 handle : 0x64697254 Void
+0x00c section : _RTL_CRITICAL_SECTION

[b***@apache.org]

https://bz.apache.org/bugzilla/show_bug.cgi?id=60671

William A. Rowe Jr. <***@apache.org> changed:

What |Removed |Added
----------------------------------------------------------------------------
OS|All |Windows Server 2016
Status|NEW |NEEDINFO

--- Comment #3 from William A. Rowe Jr. <***@apache.org> ---
This sounds very familiar, addressed within the past 18 mos by the APR project.
Would you retest with APR release 1.6.5 and report back? FWIW httpd recently
released 2.4.35 and 2.4.37, either of these should be used over the much older
2.4.27.

This specific bug, IIRC, was specifically a quick in apr and not specific to
httpd. And your report indicates nothing whatsoever to do with Unix that I can
tell.

[b***@apache.org]

https://bz.apache.org/bugzilla/show_bug.cgi?id=60671

Michael Schlenker <***@contact.de> changed:

What |Removed |Added
----------------------------------------------------------------------------
OS| |All

--- Comment #4 from Michael Schlenker <***@contact.de> ---
Thanks, will retry with APR-1.6.5.

Probably you mean https://svn.apache.org/r1808457 ?

That change should fix the mutex issue (by not using a mutex) unless Sendfile
is enabled, which is the case in one place in the mod_cache code.