After upgrade for F35 Squirrelmail webmail ISE 500; ModSecurity: AH00894: declining URL fcgi://localhost/usr/share/squirrelmail/src/login.php

After upgrading to Fedora 35, our webmail via SquirrelMail and Dovecot will not load and gets a Internal Server Error 500. There aren’t any space issues. Here are some debug logs. Anything stick out? Is this specific error meaningful?: AH00894: declining URL fcgi://localhost/usr/share/squirrelmail/src/login.php

--6f927f2d-A--
[04/Jan/2022:13:11:33.212839 --0500] YdSN1ckjF3ewhHSOAl3k-QAAANE 7377 443
--6f927f2d-B--
GET /webmail/src/login.php HTTP/1.1
Host: 
Connection: keep-alive
Pragma: no-cache
Cache-Control: no-cache
sec-ch-ua: " Not A;Brand";v="99", "Chromium";v="96", "Google Chrome";v="96"
sec-ch-ua-mobile: ?0
sec-ch-ua-platform: "Windows"
DNT: 1
Upgrade-Insecure-Requests: 1
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.110 Safari/537.36
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9
Sec-Fetch-Site: cross-site
Sec-Fetch-Mode: navigate
Sec-Fetch-User: ?1
Sec-Fetch-Dest: document
Accept-Encoding: gzip, deflate, br
Accept-Language: en-US,en;q=0.9
GEOIP_ADDR: 
GEOIP_CONTINENT_CODE: NA
GEOIP_COUNTRY_CODE: US
GEOIP_COUNTRY_NAME: United States

--6f927f2d-F--
HTTP/1.1 500 Internal Server Error
X-Powered-By: PHP/8.0.14
Content-Length: 0
Connection: close
Content-Type: text/html; charset=UTF-8

--6f927f2d-E--

--6f927f2d-H--
Apache-Error: [file "ssl_engine_kernel.c"] [line 415] [level 7] AH02034: Initial (No.1) HTTPS request received for child 209 (server OURDOMAIN:443)
Apache-Error: [file "mod_authz_core.c"] [line 815] [level 7] AH01626: authorization result of Require all granted: granted
Apache-Error: [file "mod_authz_core.c"] [line 815] [level 7] AH01626: authorization result of <RequireAny>: granted
Apache-Error: [file "mod_proxy.c"] [line 1503] [level 7] AH01143: Running scheme unix handler (attempt 0)
Apache-Error: [file "mod_proxy_ajp.c"] [line 755] [level 7] AH00894: declining URL fcgi://localhost/usr/share/squirrelmail/src/login.php
Apache-Error: [file "mod_proxy_fcgi.c"] [line 1054] [level 7] AH01076: url: fcgi://localhost/usr/share/squirrelmail/src/login.php proxyname: (null) proxyport: 0
Apache-Error: [file "mod_proxy_fcgi.c"] [line 1063] [level 7] AH01078: serving URL fcgi://localhost/usr/share/squirrelmail/src/login.php
Apache-Error: [file "proxy_util.c"] [line 2587] [level 7] AH00944: connecting fcgi://localhost/usr/share/squirrelmail/src/login.php to localhost:8000
Apache-Error: [file "proxy_util.c"] [line 2623] [level 7] AH02545: fcgi: has determined UDS as /run/php-fpm/www.sock
Apache-Error: [file "proxy_util.c"] [line 2810] [level 7] AH00947: connected /usr/share/squirrelmail/src/login.php to httpd-UDS:0
Apache-Handler: proxy:unix:/run/php-fpm/www.sock|fcgi://localhost
Stopwatch: 1641319893209301 3764 (- - -)
Stopwatch2: 1641319893209301 3764; combined=34, p1=21, p2=10, p3=1, p4=0, p5=2, sr=0, sw=0, l=0, gc=0
Response-Body-Transformed: Dechunked
Producer: ModSecurity for Apache/2.9.4 (http://www.modsecurity.org/).
Server: Apache
Engine-Mode: "ENABLED"

--6f927f2d-Z--


ssl error log:

[Tue Jan 04 13:13:20.496232 2022] [ssl:info] [pid 69264:tid 69436] [client 108.54.237.13:7415] AH01964: Connection to child 151 established (server OURDOMAIN:443)
[Tue Jan 04 13:13:20.496522 2022] [ssl:debug] [pid 69264:tid 69436] ssl_engine_kernel.c(2395): [client 108.54.237.13:7415] AH02043: SSL virtual host for servername OURDOMAIN found
[Tue Jan 04 13:13:20.496695 2022] [core:debug] [pid 69264:tid 69436] protocol.c(2449): [client 108.54.237.13:7415] AH03155: select protocol from , choices=h2,http/1.1 for server OURDOMAIN
[Tue Jan 04 13:13:20.504736 2022] [ssl:debug] [pid 69264:tid 69436] ssl_engine_kernel.c(2254): [client 108.54.237.13:7415] AH02041: Protocol: TLSv1.3, Cipher: TLS_AES_256_GCM_SHA384 (256/256 bits)
[Tue Jan 04 13:13:20.504902 2022] [socache_shmcb:debug] [pid 69264:tid 69436] mod_socache_shmcb.c(508): AH00831: socache_shmcb_store (0x48 -> subcache 8)
[Tue Jan 04 13:13:20.504920 2022] [socache_shmcb:debug] [pid 69264:tid 69436] mod_socache_shmcb.c(862): AH00847: insert happened at idx=0, data=(0:32)
[Tue Jan 04 13:13:20.504930 2022] [socache_shmcb:debug] [pid 69264:tid 69436] mod_socache_shmcb.c(865): AH00848: finished insert, subcache: idx_pos/idx_used=0/1, data_pos/data_used=0/226
[Tue Jan 04 13:13:20.504939 2022] [socache_shmcb:debug] [pid 69264:tid 69436] mod_socache_shmcb.c(530): AH00834: leaving socache_shmcb_store successfully
[Tue Jan 04 13:13:20.505217 2022] [ssl:debug] [pid 69264:tid 69436] ssl_engine_kernel.c(415): [client 108.54.237.13:7415] AH02034: Initial (No.1) HTTPS request received for child 151 (server OURDOMAIN:443)
[Tue Jan 04 13:13:20.505416 2022] [authz_core:debug] [pid 69264:tid 69436] mod_authz_core.c(815): [client 108.54.237.13:7415] AH01626: authorization result of Require all granted: granted
[Tue Jan 04 13:13:20.505433 2022] [authz_core:debug] [pid 69264:tid 69436] mod_authz_core.c(815): [client 108.54.237.13:7415] AH01626: authorization result of <RequireAny>: granted
[Tue Jan 04 13:13:20.505646 2022] [proxy:debug] [pid 69264:tid 69436] mod_proxy.c(1503): [client 108.54.237.13:7415] AH01143: Running scheme unix handler (attempt 0)
[Tue Jan 04 13:13:20.505665 2022] [proxy_ajp:debug] [pid 69264:tid 69436] mod_proxy_ajp.c(755): [client 108.54.237.13:7415] AH00894: declining URL fcgi://localhost/usr/share/squirrelmail/src/login.php
[Tue Jan 04 13:13:20.505676 2022] [proxy_fcgi:debug] [pid 69264:tid 69436] mod_proxy_fcgi.c(1054): [client 108.54.237.13:7415] AH01076: url: fcgi://localhost/usr/share/squirrelmail/src/login.php proxyname: (null) proxyport: 0
[Tue Jan 04 13:13:20.505688 2022] [proxy_fcgi:debug] [pid 69264:tid 69436] mod_proxy_fcgi.c(1063): [client 108.54.237.13:7415] AH01078: serving URL fcgi://localhost/usr/share/squirrelmail/src/login.php
[Tue Jan 04 13:13:20.505702 2022] [proxy:debug] [pid 69264:tid 69436] proxy_util.c(2531): AH00942: FCGI: has acquired connection for (*)
[Tue Jan 04 13:13:20.505716 2022] [proxy:debug] [pid 69264:tid 69436] proxy_util.c(2587): [client 108.54.237.13:7415] AH00944: connecting fcgi://localhost/usr/share/squirrelmail/src/login.php to localhost:8000
[Tue Jan 04 13:13:20.505727 2022] [proxy:debug] [pid 69264:tid 69436] proxy_util.c(2623): [client 108.54.237.13:7415] AH02545: fcgi: has determined UDS as /run/php-fpm/www.sock
[Tue Jan 04 13:13:20.505819 2022] [proxy:debug] [pid 69264:tid 69436] proxy_util.c(2810): [client 108.54.237.13:7415] AH00947: connected /usr/share/squirrelmail/src/login.php to httpd-UDS:0
[Tue Jan 04 13:13:20.505881 2022] [proxy:debug] [pid 69264:tid 69436] proxy_util.c(3177): AH02823: FCGI: connection established with Unix domain socket /run/php-fpm/www.sock (*)
[Tue Jan 04 13:13:20.508437 2022] [proxy:debug] [pid 69264:tid 69436] proxy_util.c(2546): AH00943: FCGI: has released connection for (*)
[Tue Jan 04 13:13:20.508999 2022] [ssl:debug] [pid 69264:tid 69436] ssl_engine_io.c(1147): [client 108.54.237.13:7415] AH02001: Connection closed to child 151 with standard shutdown (server OURDOMAIN:443)

Edit: after disabling mod_security I see these errors:

[Tue Jan 04 16:13:33.661487 2022] [ssl:info] [pid 77902:tid 77948] [client 108.54.237.13:1092] AH01964: Connection to child 210 established (server OURDOMAIN:443)
[Tue Jan 04 16:13:33.661714 2022] [ssl:debug] [pid 77902:tid 77948] ssl_engine_kernel.c(2425): [client 108.54.237.13:1092] AH02645: Server name not provided via TLS extension (using default/first virtual host)
[Tue Jan 04 16:13:33.661869 2022] [core:debug] [pid 77902:tid 77948] protocol.c(2449): [client 108.54.237.13:1092] AH03155: select protocol from , choices=h2,http/1.1 for server OURDOMAIN
[Tue Jan 04 16:13:33.672615 2022] [socache_shmcb:debug] [pid 77902:tid 77948] mod_socache_shmcb.c(570): AH00837: socache_shmcb_remove (0x3c -> subcache 28)
[Tue Jan 04 16:13:33.672649 2022] [socache_shmcb:debug] [pid 77902:tid 77948] mod_socache_shmcb.c(954): AH00852: possible match at idx=2, data=438
[Tue Jan 04 16:13:33.672659 2022] [socache_shmcb:debug] [pid 77902:tid 77948] mod_socache_shmcb.c(959): AH00853: shmcb_subcache_remove removing matching entry
[Tue Jan 04 16:13:33.672669 2022] [socache_shmcb:debug] [pid 77902:tid 77948] mod_socache_shmcb.c(585): AH00839: leaving socache_shmcb_remove successfully
[Tue Jan 04 16:13:33.672683 2022] [ssl:info] [pid 77902:tid 77948] [client 108.54.237.13:1092] AH02008: SSL library error 1 in handshake (server OURDOMAIN:443)
[Tue Jan 04 16:13:33.672715 2022] [ssl:info] [pid 77902:tid 77948] SSL Library Error: error:14094416:SSL routines:ssl3_read_bytes:sslv3 alert certificate unknown (SSL alert number 46)
[Tue Jan 04 16:13:33.672731 2022] [ssl:info] [pid 77902:tid 77948] [client 108.54.237.13:1092] AH01998: Connection closed to child 210 with abortive shutdown (server OURDOMAIN:443)
[Tue Jan 04 16:13:33.683683 2022] [ssl:info] [pid 77902:tid 77937] [client 108.54.237.13:1095] AH01964: Connection to child 199 established (server OURDOMAIN:443)
[Tue Jan 04 16:13:33.683823 2022] [ssl:debug] [pid 77902:tid 77937] ssl_engine_kernel.c(2425): [client 108.54.237.13:1095] AH02645: Server name not provided via TLS extension (using default/first virtual host)
[Tue Jan 04 16:13:33.683876 2022] [core:debug] [pid 77902:tid 77937] protocol.c(2449): [client 108.54.237.13:1095] AH03155: select protocol from , choices=h2,http/1.1 for server OURDOMAIN
[Tue Jan 04 16:13:33.701176 2022] [ssl:debug] [pid 77902:tid 77937] ssl_engine_kernel.c(2254): [client 108.54.237.13:1095] AH02041: Protocol: TLSv1.3, Cipher: TLS_AES_256_GCM_SHA384 (256/256 bits)
[Tue Jan 04 16:13:33.701312 2022] [socache_shmcb:debug] [pid 77902:tid 77937] mod_socache_shmcb.c(508): AH00831: socache_shmcb_store (0xe3 -> subcache 3)
[Tue Jan 04 16:13:33.701329 2022] [socache_shmcb:debug] [pid 77902:tid 77937] mod_socache_shmcb.c(745): AH00842: expiring 1 and reclaiming 0 removed socache entries
[Tue Jan 04 16:13:33.701338 2022] [socache_shmcb:debug] [pid 77902:tid 77937] mod_socache_shmcb.c(765): AH00843: we now have 0 socache entries
[Tue Jan 04 16:13:33.701350 2022] [socache_shmcb:debug] [pid 77902:tid 77937] mod_socache_shmcb.c(862): AH00847: insert happened at idx=3, data=(677:709)
[Tue Jan 04 16:13:33.701360 2022] [socache_shmcb:debug] [pid 77902:tid 77937] mod_socache_shmcb.c(865): AH00848: finished insert, subcache: idx_pos/idx_used=3/1, data_pos/data_used=677/201
[Tue Jan 04 16:13:33.701370 2022] [socache_shmcb:debug] [pid 77902:tid 77937] mod_socache_shmcb.c(530): AH00834: leaving socache_shmcb_store successfully
[Tue Jan 04 16:13:33.701494 2022] [socache_shmcb:debug] [pid 77902:tid 77937] mod_socache_shmcb.c(508): AH00831: socache_shmcb_store (0x43 -> subcache 3)
[Tue Jan 04 16:13:33.701511 2022] [socache_shmcb:debug] [pid 77902:tid 77937] mod_socache_shmcb.c(862): AH00847: insert happened at idx=4, data=(878:910)
[Tue Jan 04 16:13:33.701519 2022] [socache_shmcb:debug] [pid 77902:tid 77937] mod_socache_shmcb.c(865): AH00848: finished insert, subcache: idx_pos/idx_used=3/2, data_pos/data_used=677/402
[Tue Jan 04 16:13:33.701528 2022] [socache_shmcb:debug] [pid 77902:tid 77937] mod_socache_shmcb.c(530): AH00834: leaving socache_shmcb_store successfully
[Tue Jan 04 16:13:33.701713 2022] [ssl:debug] [pid 77902:tid 77937] ssl_engine_kernel.c(415): [client 108.54.237.13:1095] AH02034: Initial (No.1) HTTPS request received for child 199 (server OURDOMAIN:443)
[Tue Jan 04 16:13:33.701903 2022] [authz_core:debug] [pid 77902:tid 77937] mod_authz_core.c(815): [client 108.54.237.13:1095] AH01626: authorization result of Require all granted: granted
[Tue Jan 04 16:13:33.701921 2022] [authz_core:debug] [pid 77902:tid 77937] mod_authz_core.c(815): [client 108.54.237.13:1095] AH01626: authorization result of <RequireAny>: granted
[Tue Jan 04 16:13:33.702127 2022] [proxy:debug] [pid 77902:tid 77937] mod_proxy.c(1503): [client 108.54.237.13:1095] AH01143: Running scheme unix handler (attempt 0)
[Tue Jan 04 16:13:33.702153 2022] [proxy_ajp:debug] [pid 77902:tid 77937] mod_proxy_ajp.c(755): [client 108.54.237.13:1095] AH00894: declining URL fcgi://localhost/usr/share/squirrelmail/src/login.php
[Tue Jan 04 16:13:33.702167 2022] [proxy_fcgi:debug] [pid 77902:tid 77937] mod_proxy_fcgi.c(1054): [client 108.54.237.13:1095] AH01076: url: fcgi://localhost/usr/share/squirrelmail/src/login.php proxyname: (null) proxyport: 0
[Tue Jan 04 16:13:33.702179 2022] [proxy_fcgi:debug] [pid 77902:tid 77937] mod_proxy_fcgi.c(1063): [client 108.54.237.13:1095] AH01078: serving URL fcgi://localhost/usr/share/squirrelmail/src/login.php
[Tue Jan 04 16:13:33.702191 2022] [proxy:debug] [pid 77902:tid 77937] proxy_util.c(2531): AH00942: FCGI: has acquired connection for (*)
[Tue Jan 04 16:13:33.702205 2022] [proxy:debug] [pid 77902:tid 77937] proxy_util.c(2587): [client 108.54.237.13:1095] AH00944: connecting fcgi://localhost/usr/share/squirrelmail/src/login.php to localhost:8000
[Tue Jan 04 16:13:33.702217 2022] [proxy:debug] [pid 77902:tid 77937] proxy_util.c(2623): [client 108.54.237.13:1095] AH02545: fcgi: has determined UDS as /run/php-fpm/www.sock
[Tue Jan 04 16:13:33.702317 2022] [proxy:debug] [pid 77902:tid 77937] proxy_util.c(2810): [client 108.54.237.13:1095] AH00947: connected /usr/share/squirrelmail/src/login.php to httpd-UDS:0
[Tue Jan 04 16:13:33.702378 2022] [proxy:debug] [pid 77902:tid 77937] proxy_util.c(3177): AH02823: FCGI: connection established with Unix domain socket /run/php-fpm/www.sock (*)
[Tue Jan 04 16:13:33.704872 2022] [proxy:debug] [pid 77902:tid 77937] proxy_util.c(2546): AH00943: FCGI: has released connection for (*)
[Tue Jan 04 16:13:33.705352 2022] [ssl:debug] [pid 77902:tid 77937] ssl_engine_io.c(1147): [client 108.54.237.13:1095] AH02001: Connection closed to child 199 with standard shutdown (server OURDOMAIN:443)
[Tue Jan 04 16:13:33.751263 2022] [ssl:info] [pid 77902:tid 77943] [client 31.205.216.198:58085] AH01964: Connection to child 205 established (server OURDOMAIN:443)
[Tue Jan 04 16:13:33.751443 2022] [ssl:debug] [pid 77902:tid 77943] ssl_engine_kernel.c(2395): [client 31.205.216.198:58085] AH02043: SSL virtual host for servername OURDOMAIN found
[Tue Jan 04 16:13:33.751493 2022] [ssl:info] [pid 77902:tid 77945] [client 31.205.216.198:58086] AH01964: Connection to child 207 established (server OURDOMAIN:443)
[Tue Jan 04 16:13:33.751592 2022] [core:debug] [pid 77902:tid 77943] protocol.c(2449): [client 31.205.216.198:58085] AH03155: select protocol from , choices=h2,http/1.1 for server OURDOMAIN
[Tue Jan 04 16:13:33.751653 2022] [ssl:debug] [pid 77902:tid 77945] ssl_engine_kernel.c(2395): [client 31.205.216.198:58086] AH02043: SSL virtual host for servername OURDOMAIN found
[Tue Jan 04 16:13:33.751795 2022] [core:debug] [pid 77902:tid 77945] protocol.c(2449): [client 31.205.216.198:58086] AH03155: select protocol from , choices=h2,http/1.1 for server OURDOMAIN
[Tue Jan 04 16:13:33.913997 2022] [ssl:debug] [pid 77902:tid 77943] ssl_engine_kernel.c(2254): [client 31.205.216.198:58085] AH02041: Protocol: TLSv1.3, Cipher: TLS_AES_256_GCM_SHA384 (256/256 bits)
[Tue Jan 04 16:13:33.914150 2022] [socache_shmcb:debug] [pid 77902:tid 77943] mod_socache_shmcb.c(508): AH00831: socache_shmcb_store (0x74 -> subcache 20)
[Tue Jan 04 16:13:33.914174 2022] [socache_shmcb:debug] [pid 77902:tid 77943] mod_socache_shmcb.c(862): AH00847: insert happened at idx=7, data=(1554:1586)
[Tue Jan 04 16:13:33.914184 2022] [socache_shmcb:debug] [pid 77902:tid 77943] mod_socache_shmcb.c(865): AH00848: finished insert, subcache: idx_pos/idx_used=5/3, data_pos/data_used=1116/664
[Tue Jan 04 16:13:33.914195 2022] [socache_shmcb:debug] [pid 77902:tid 77943] mod_socache_shmcb.c(530): AH00834: leaving socache_shmcb_store successfully
[Tue Jan 04 16:13:33.915172 2022] [ssl:debug] [pid 77902:tid 77945] ssl_engine_kernel.c(2254): [client 31.205.216.198:58086] AH02041: Protocol: TLSv1.3, Cipher: TLS_AES_256_GCM_SHA384 (256/256 bits)
[Tue Jan 04 16:13:33.915309 2022] [socache_shmcb:debug] [pid 77902:tid 77945] mod_socache_shmcb.c(508): AH00831: socache_shmcb_store (0x4f -> subcache 15)
[Tue Jan 04 16:13:33.915327 2022] [socache_shmcb:debug] [pid 77902:tid 77945] mod_socache_shmcb.c(862): AH00847: insert happened at idx=3, data=(653:685)
[Tue Jan 04 16:13:33.915337 2022] [socache_shmcb:debug] [pid 77902:tid 77945] mod_socache_shmcb.c(865): AH00848: finished insert, subcache: idx_pos/idx_used=2/2, data_pos/data_used=439/439
[Tue Jan 04 16:13:33.915348 2022] [socache_shmcb:debug] [pid 77902:tid 77945] mod_socache_shmcb.c(530): AH00834: leaving socache_shmcb_store successfully

The errors that stick out for me are:

AH02008: SSL library error 1 in handshake (server OURDOMAIN:443)
SSL Library Error: error:14094416:SSL routines:ssl3_read_bytes:sslv3 alert certificate unknown (SSL alert number 46)

Any setting that needs changing?

You might take this in consideration:

Thanks this turns out to be a known issue and these errors are perhaps a bit of a red herring in that Squirrelmail has not been updated for Fedora 35 and compatibility with PHP 8. Once I enabled debugging in php.ini I saw this error:

Fatal error Array and string offset access syntax with curly braces is no longer supported in /usr/share/squirrelmail/functions/strings.php on line 634

1 Like