Preciso de outro par de olhos para ajudar a depurar um problema. Esta será uma mensagem longa. Fornecerei muito contexto porque não tenho certeza de quais detalhes podem ser importantes.
Temos dois servidores: dev e produção. Os servidores existentes estão executando o RHEL7 e estão prestes a atingir o fim de sua vida útil. Estou no processo de construção de duas novas VMs RHEL9 para substituí-las.
Os servidores hospedam uma variedade de aplicativos. Eles são independentes um do outro e cada um reside em seu próprio subdiretório fora da raiz do documento. A raiz do documento está localizada em /var/www/html.
O que está me causando problemas é uma instalação nova e brilhante do Drupal 10.2. Instalei-o em/var/www/drupal usando o compositor e, em seguida, criei um link simbólico em/var/www/html/databases que aponta para/var/www/drupal/web. Tive que ajustar um pouco as permissões para garantir que o usuário do Apache pudesse fazer tudo o que precisava, mas logo tive uma instalação funcional do Drupal tanto no desenvolvimento quanto na produção.
Então o do dev parou de funcionar, logo depois de clonar uma cópia do nosso tema personalizado para a pasta de temas. Quando visito, recebo esta mensagem de erro:
The website encountered an unexpected error. Try again later.
O ssl_access_log mostra este erro:
10.133.0.30 - - [21/Feb/2024:13:55:07 -0600] "GET /databases/ HTTP/1.1" 500 61
Nossa, uma mensagem de erro 500. A mensagem de erro que pode significar literalmente qualquer coisa e, portanto, não significa absolutamente nada. Maravilhoso.
Configurei meu LogLevel para depuração, reproduzi o problema e verifiquei o ssl_error_log, onde ele relata o seguinte:
[Wed Feb 21 13:55:07.118063 2024] [ssl:info] [pid 7769:tid 7944] [client 10.133.0.30:64845] AH01964: Connection to child 81 established (server undcflwebdev0.und.edu:443)
[Wed Feb 21 13:55:07.118300 2024] [ssl:debug] [pid 7769:tid 7944] ssl_engine_kernel.c(2391): [client 10.133.0.30:64845] AH02043: SSL virtual host for servername undcflwebdev0.und.edu found
[Wed Feb 21 13:55:07.118492 2024] [core:debug] [pid 7769:tid 7944] protocol.c(2460): [client 10.133.0.30:64845] AH03155: select protocol from , choices=h2,http/1.1 for server undcflwebdev0.und.edu
[Wed Feb 21 13:55:07.120744 2024] [ssl:debug] [pid 7769:tid 7944] ssl_engine_kernel.c(2251): [client 10.133.0.30:64845] AH02041: Protocol: TLSv1.3, Cipher: TLS_AES_256_GCM_SHA384 (256/256 bits)
[Wed Feb 21 13:55:07.120862 2024] [socache_shmcb:debug] [pid 7769:tid 7944] mod_socache_shmcb.c(508): AH00831: socache_shmcb_store (0x16 -> subcache 22)
[Wed Feb 21 13:55:07.120889 2024] [socache_shmcb:debug] [pid 7769:tid 7944] mod_socache_shmcb.c(745): AH00842: expiring 11 and reclaiming 0 removed socache entries
[Wed Feb 21 13:55:07.120901 2024] [socache_shmcb:debug] [pid 7769:tid 7944] mod_socache_shmcb.c(765): AH00843: we now have 0 socache entries
[Wed Feb 21 13:55:07.120911 2024] [socache_shmcb:debug] [pid 7769:tid 7944] mod_socache_shmcb.c(862): AH00847: insert happened at idx=0, data=(0:32)
[Wed Feb 21 13:55:07.120917 2024] [socache_shmcb:debug] [pid 7769:tid 7944] mod_socache_shmcb.c(865): AH00848: finished insert, subcache: idx_pos/idx_used=0/1, data_pos/data_used=0/230
[Wed Feb 21 13:55:07.120923 2024] [socache_shmcb:debug] [pid 7769:tid 7944] mod_socache_shmcb.c(530): AH00834: leaving socache_shmcb_store successfully
[Wed Feb 21 13:55:07.121011 2024] [ssl:debug] [pid 7769:tid 7944] ssl_engine_kernel.c(415): [client 10.133.0.30:64845] AH02034: Initial (No.1) HTTPS request received for child 81 (server undcflwebdev0.und.edu:443)
[Wed Feb 21 13:55:07.121357 2024] [authz_core:debug] [pid 7769:tid 7944] mod_authz_core.c(815): [client 10.133.0.30:64845] AH01626: authorization result of Require all granted: granted
[Wed Feb 21 13:55:07.121390 2024] [authz_core:debug] [pid 7769:tid 7944] mod_authz_core.c(815): [client 10.133.0.30:64845] AH01626: authorization result of <RequireAny>: granted
[Wed Feb 21 13:55:07.121491 2024] [authz_core:debug] [pid 7769:tid 7944] mod_authz_core.c(815): [client 10.133.0.30:64845] AH01626: authorization result of Require all granted: granted
[Wed Feb 21 13:55:07.121514 2024] [authz_core:debug] [pid 7769:tid 7944] mod_authz_core.c(815): [client 10.133.0.30:64845] AH01626: authorization result of <RequireAny>: granted
[Wed Feb 21 13:55:07.121680 2024] [proxy:debug] [pid 7769:tid 7944] mod_proxy.c(1520): [client 10.133.0.30:64845] AH01143: Running scheme unix handler (attempt 0)
[Wed Feb 21 13:55:07.121703 2024] [proxy_ajp:debug] [pid 7769:tid 7944] mod_proxy_ajp.c(795): [client 10.133.0.30:64845] AH00894: declining URL fcgi://localhost/var/www/html/databases/index.php
[Wed Feb 21 13:55:07.121719 2024] [proxy_fcgi:debug] [pid 7769:tid 7944] mod_proxy_fcgi.c(1069): [client 10.133.0.30:64845] AH01076: url: fcgi://localhost/var/www/html/databases/index.php proxyname: (null) proxyport: 0
[Wed Feb 21 13:55:07.121736 2024] [proxy_fcgi:debug] [pid 7769:tid 7944] mod_proxy_fcgi.c(1078): [client 10.133.0.30:64845] AH01078: serving URL fcgi://localhost/var/www/html/databases/index.php
[Wed Feb 21 13:55:07.121758 2024] [proxy:debug] [pid 7769:tid 7944] proxy_util.c(2568): AH00942: FCGI: has acquired connection for (*:80)
[Wed Feb 21 13:55:07.121776 2024] [proxy:debug] [pid 7769:tid 7944] proxy_util.c(2626): [client 10.133.0.30:64845] AH00944: connecting fcgi://localhost/var/www/html/databases/index.php to localhost:8000
[Wed Feb 21 13:55:07.121792 2024] [proxy:debug] [pid 7769:tid 7944] proxy_util.c(2662): [client 10.133.0.30:64845] AH02545: fcgi: has determined UDS as /run/php-fpm/www.sock
[Wed Feb 21 13:55:07.122008 2024] [proxy:debug] [pid 7769:tid 7944] proxy_util.c(2852): [client 10.133.0.30:64845] AH00947: connected /var/www/html/databases/index.php to httpd-UDS:0
[Wed Feb 21 13:55:07.122082 2024] [proxy:debug] [pid 7769:tid 7944] proxy_util.c(3222): AH02823: FCGI: connection established with Unix domain socket /run/php-fpm/www.sock (*:80)
[Wed Feb 21 13:55:07.150902 2024] [proxy:debug] [pid 7769:tid 7944] proxy_util.c(2584): AH00943: FCGI: has released connection for (*:80)
[Wed Feb 21 13:55:07.151140 2024] [ssl:debug] [pid 7769:tid 7944] ssl_engine_io.c(1151): [client 10.133.0.30:64845] AH02001: Connection closed to child 81 with standard shutdown (server undcflwebdev0.und.edu:443)
Não existem armas definitivas óbvias, mas acho que o problema pode ser esta linha:
[Wed Feb 21 13:55:07.121703 2024] [proxy_ajp:debug] [pid 7769:tid 7944] mod_proxy_ajp.c(795): [client 10.133.0.30:64845] AH00894: declining URL fcgi://localhost/var/www/html/databases/index.php
Se bem entendi, FCGI é a interface entre Apache e PHP. Se a FCGI estiver recusando a conexão, o script PHP não será interpretado e tudo será interrompido.
Temos o SELinux instalado e ele costuma causar problemas, então desliguei-o temporariamente. Mas isso não ajudou - o problema ocorre mesmo quando o SELinux é colocado no modo permissivo. Então não acho que seja um problema do SELinux.
Todo o resto no servidor está funcionando bem. Tenho vários aplicativos PHP em suas próprias pastas que funcionam sem problemas. Então pensei que talvez fosse algo relacionado ao link simbólico. Excluí o link e o substituí por uma pasta comum chamada "bancos de dados" contendo um arquivo index.html que diz "Olá, mundo". Funcionou muito bem. Renomeei index.html para index.php e ele falhou imediatamente com as mesmas mensagens de erro acima. Por capricho, copiei o arquivo index.php para "test.php" e o acessei. E funcionou bem!
Enquanto isso, todos os outros aplicativos PHP na máquina continuam funcionando perfeitamente. Além disso, a instalação do Drupal no servidor de produção está funcionando perfeitamente, apesar de estar em um link simbólico. Pelo que sei, o problema ocorre apenas para o caminho exato /var/www/html/databases/index.php, independentemente de os bancos de dados serem uma pasta real ou um link simbólico. Literalmente, todos os outros arquivos PHP no servidor funcionam bem.
Eu pesquisei no Google. Não encontrei ninguém que tenha tido o mesmo problema. Encontrei algumas pessoas relatando o código de erro AH00894 em servidores com proxies reversos instalados. Isso me fez pensar, porque realmente tenho um proxy reverso configurado. Um dos outros aplicativos no servidor é antigo, desajeitado e irritantemente insubstituível. Ele não será executado em nada mais recente que o PHP 5.6. Então, eu tenho um contêiner docker em execução, fornecendo um ambiente PHP 5.6. O Apache está configurado para se comunicar com a instância do docker por meio de um proxy reverso, assim:
# Listen to all traffic on port 80.
<VirtualHost *:80>
# Keep the original host name.
ProxyPreserveHost On
# Redirect all traffic for the /archon folder to :8080 instead.
ProxyPass /archon http://localhost:8080/
ProxyPassReverse /archon http://localhost:8080/
</VirtualHost>
E novamente em ssl.conf eu tenho os seguintes bits:
SSLProxyEngine On
ProxyPreserveHost On
# Prevent SSL offloading
RequestHeader set X-Forwarded-Proto "https"
RequestHeader set X-Forwarded-Port "443"
# Redirect all traffic for the /archon folder to :8080 instead.
ProxyPass /archon http://localhost:8080/
ProxyPassReverse /archon http://localhost:8080/
O aplicativo proxy funciona bem. Posso acessar https://dev.example.com/archon/ e ele carrega. Mas me perguntei se talvez o proxy esteja de alguma forma interferindo na instância drupal.
Então desativei todas as coisas do proxy. Comentei o virtualhost e todas as linhas de configuração do Proxy em ssl.conf e reiniciei o Apache. Verifiquei que o archon parou de funcionar conforme o esperado e tentei meu Drupal. Ele gerou exatamente o mesmo erro. Então ativei todo o proxy novamente.
Neste ponto, estou batendo a cabeça contra esse problema há dois dias. Se li os logs corretamente, o problema é que o FCGI está recusando a conexão. Mas não sei POR QUE está recusando. Por que todos os outros aplicativos PHP no servidor funcionam bem? O servidor de produção é configurado de forma idêntica ao servidor de desenvolvimento, mas a produção funciona e o desenvolvimento não. Por que? Todos os outros arquivos PHP no servidor funcionam perfeitamente. Por que? O que há nesse URL que morre consistentemente quando todo o resto funciona?
Eu poderia talvez renomear o arquivo index.php para outra coisa e então usar um arquivo .htaccess para identificar esse nome de arquivo como o índice da pasta. Isso pode ser uma solução alternativa. Mas é muito estranho e temo que renomear o arquivo principal do Drupal possa causar problemas inesperados. Não sei se algum código do Drupal tem esse nome de arquivo codificado em algum lugar.
Estou preso. Não sei mais o que tentar para descobrir o que diabos há de errado com essa maldita coisa. Os novos servidores devem entrar no ar na segunda-feira, dia 26. Meu tempo está acabando rapidamente e este é meu último bloqueador. Qualquer sugestão seria apreciada.
O Apache só aparece
500nos logs porque você está usandophp-fpme o Apache não conhece os detalhes do problema. Apenas encaminha o código de erro.php-fpmtem seu próprio arquivo de log que deve mostrar uma mensagem de erro detalhada.