msphpsql: Apache httpd times out, will not start, when SQLSRV enabled

When extension=sqlsrv.so and extension=pdo_sqlsrv.so are enabled, Apache httpd will timeout and not start. This is occurring on one server, but I cannot replicate on two other servers. All servers are managed through the same Ansible scripts and should be very consistently built. I’m having trouble determining what is causing this issue.

If I run sudo systemctl restart httpd, then after 3 minutes (exactly), this error occurs:

Job for httpd.service failed because a fatal signal was delivered to the control process. See “systemctl status httpd.service” and “journalctl -xe” for details.

Removing file /etc/php.d/20-sqlsrv.ini results in the same problem. Reinstating /etc/php.d/20-sqlsrv.ini and instead removing /etc/php.d/30-pdo_sqlsrv.ini results in the same problem. Removing both allows Apache httpd to start normally.

Below I make reference to the “Failing system” which is showing this error and the “Comparison system” which is not seeing the error. I’ve also run the same setup on a VirtualBox CentOS setup and haven’t seen the problem. I’m at a loss for how to determine why this one system will not work.

PHP Driver version or file name

php --re sqlsrv | head -1 gives:

Failing system: Extension [ <persistent> extension #43 sqlsrv version 5.2.0 ] { Comparison system: Extension [ <persistent> extension #43 sqlsrv version 5.2.0 ] {

php -re pdo_sqlsrv | head -1 gives:

Failing system: Extension [ <persistent> extension #56 pdo_sqlsrv version 5.2.0 ] { Comparison system: Extension [ <persistent> extension #56 pdo_sqlsrv version 5.2.0 ] {

SQL Server version

N/A. Can’t even get Apache to start. This exact setup has worked on Microsoft SQL Server 2016 without issue.

Client operating system

Failing system: Red Hat Enterprise Linux Server release 7.5 (Maipo) Comparison system: CentOS Linux release 7.5.1804 (Core)

PHP version

Failing system: PHP 7.0.30 (cli) (built: Apr 26 2018 13:30:55) ( NTS ) Comparison system: PHP 7.0.30 (cli) (built: Apr 26 2018 13:30:35) ( NTS )

Microsoft ODBC Driver version

Doing yum info msodbcsql17 yields the following:

Failing system:

Installed Packages
Name        : msodbcsql17
Arch        : x86_64
Version     : 17.1.0.1
Release     : 1
Size        : 17 M
Repo        : installed
From repo   : packages-microsoft-com-prod
Summary     : ODBC Driver for Microsoft(R) SQL Server(R)
License     : https://aka.ms/odbc170eula
Description : This package provides an ODBC driver that can connect to Microsoft(R) SQL Server(R).

Comparison system:

Installed Packages
Name        : msodbcsql17
Arch        : x86_64
Version     : 17.1.0.1
Release     : 1
Size        : 17 M
Repo        : installed
From repo   : packages-microsoft-com-prod
Summary     : ODBC Driver for Microsoft(R) SQL Server(R)
License     : https://aka.ms/odbc170eula
Description : This package provides an ODBC driver that can connect to Microsoft(R) SQL Server(R).

Table schema

N/A

Problem description

See above.

Expected behavior and actual behavior

Expected: Apache starts Actual: Apache times out and fails

Repro code or steps to reproduce

Installation is managed by a set of Ansible scripts. Specifically:

Relevant logs

After running echo $(date) && sudo systemctl restart httpd below are the relevant log files after the echoed time stamp Mon Jun 25 11:46:25 CDT 2018. Estimated failure time at 11:49:25 since it’s been timing out 3 minutes after running restart httpd.

journalctl -xe output

Jun 25 11:46:25 server-that-fails sudo[11948]: someusername : TTY=pts/0 ; PWD=/opt/data-meza/logs ; USER=root ; COMMAND=/bin/systemctl restart httpd
Jun 25 11:46:25 server-that-fails polkitd[843]: Registered Authentication Agent for unix-process:11949:21590202 (system bus name :1.983 [/usr/bin/pkttyagent --notify-fd 5 --fallback], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
Jun 25 11:46:25 server-that-fails systemd[1]: Starting The Apache HTTP Server...
-- Subject: Unit httpd.service has begun start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit httpd.service has begun starting up.
Jun 25 11:47:56 server-that-fails systemd[1]: httpd.service start operation timed out. Terminating.
Jun 25 11:49:26 server-that-fails systemd[1]: httpd.service stop-final-sigterm timed out. Killing.
Jun 25 11:49:26 server-that-fails systemd[1]: httpd.service: main process exited, code=killed, status=9/KILL
Jun 25 11:49:26 server-that-fails systemd[1]: Failed to start The Apache HTTP Server.
-- Subject: Unit httpd.service has failed
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit httpd.service has failed.
--
-- The result is failed.
Jun 25 11:49:26 server-that-fails systemd[1]: Unit httpd.service entered failed state.
Jun 25 11:49:26 server-that-fails systemd[1]: httpd.service failed.
Jun 25 11:49:26 server-that-fails polkitd[843]: Unregistered Authentication Agent for unix-process:11949:21590202 (system bus name :1.983, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) (disconnected from bus)

/var/log/secure

Jun 25 11:46:25 server-that-fails sudo: someusername : TTY=pts/0 ; PWD=/opt/data-meza/logs ; USER=root ; COMMAND=/bin/systemctl restart httpd
Jun 25 11:46:25 server-that-fails polkitd[843]: Registered Authentication Agent for unix-process:11949:21590202 (system bus name :1.983 [/usr/bin/pkttyagent --notify-fd 5 --fallback], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
Jun 25 11:49:26 server-that-fails polkitd[843]: Unregistered Authentication Agent for unix-process:11949:21590202 (system bus name :1.983, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) (disconnected from bus)

php error log

No entries from this time period

/var/log/httpd/error_log

Note: Apache LogLevel set to debug.

[Mon Jun 25 11:46:25.959154 2018] [core:notice] [pid 11956] SELinux policy enabled; httpd running as context system_u:system_r:httpd_t:s0
[Mon Jun 25 11:46:25.960487 2018] [suexec:notice] [pid 11956] AH01232: suEXEC mechanism enabled (wrapper: /usr/sbin/suexec)
[Mon Jun 25 11:46:25.960626 2018] [ssl:debug] [pid 11956] ssl_engine_pphrase.c(181): AH02199: SSL not enabled on vhost server-that-fails.example.com:80, skipping SSL setup
[Mon Jun 25 11:46:25.960638 2018] [ssl:debug] [pid 11956] ssl_engine_pphrase.c(181): AH02199: SSL not enabled on vhost server-that-fails.example.com:8090, skipping SSL setup
[Mon Jun 25 11:46:25.960646 2018] [ssl:debug] [pid 11956] ssl_engine_pphrase.c(181): AH02199: SSL not enabled on vhost MezaMainEntrypoint:80, skipping SSL setup
[Mon Jun 25 11:46:25.960657 2018] [ssl:info] [pid 11956] AH01887: Init: Initializing (virtual) servers for SSL
[Mon Jun 25 11:46:25.960689 2018] [ssl:info] [pid 11956] AH01876: mod_ssl/2.4.6 compiled against Server: Apache/2.4.6, Library: OpenSSL/1.0.2k
[Mon Jun 25 11:46:25.991267 2018] [auth_digest:notice] [pid 11956] AH01757: generating secret for digest authentication ...
[Mon Jun 25 11:46:25.991300 2018] [auth_digest:debug] [pid 11956] mod_auth_digest.c(250): AH01759: done
[Mon Jun 25 11:46:25.992240 2018] [slotmem_shm:debug] [pid 11956] mod_slotmem_shm.c(448): AH02301: attach looking for /run/httpd/slotmem-shm-mod_heartmonitor.shm
[Mon Jun 25 11:46:25.992260 2018] [lbmethod_heartbeat:notice] [pid 11956] AH02282: No slotmem from mod_heartmonitor
[Mon Jun 25 11:46:25.992363 2018] [ssl:debug] [pid 11956] ssl_engine_pphrase.c(181): AH02199: SSL not enabled on vhost server-that-fails.example.com:80, skipping SSL setup
[Mon Jun 25 11:46:25.992374 2018] [ssl:debug] [pid 11956] ssl_engine_pphrase.c(181): AH02199: SSL not enabled on vhost server-that-fails.example.com:8090, skipping SSL setup
[Mon Jun 25 11:46:25.992381 2018] [ssl:debug] [pid 11956] ssl_engine_pphrase.c(181): AH02199: SSL not enabled on vhost MezaMainEntrypoint:80, skipping SSL setup
[Mon Jun 25 11:46:25.992401 2018] [ssl:warn] [pid 11956] AH01873: Init: Session Cache is not configured [hint: SSLSessionCache]
[Mon Jun 25 11:46:25.992408 2018] [ssl:info] [pid 11956] AH01887: Init: Initializing (virtual) servers for SSL
[Mon Jun 25 11:46:25.992425 2018] [ssl:info] [pid 11956] AH01876: mod_ssl/2.4.6 compiled against Server: Apache/2.4.6, Library: OpenSSL/1.0.2k
[Mon Jun 25 11:48:31.921182 2018] [core:warn] [pid 11956] AH00098: pid file /run/httpd/httpd.pid overwritten -- Unclean shutdown of previous Apache run?
[Mon Jun 25 11:48:31.927498 2018] [mpm_prefork:notice] [pid 11956] AH00163: Apache/2.4.6 (Red Hat Enterprise Linux) OpenSSL/1.0.2k-fips PHP/7.0.30 configured -- resuming normal operations
[Mon Jun 25 11:48:31.927531 2018] [mpm_prefork:info] [pid 11956] AH00164: Server built: Jan  8 2018 06:49:04
[Mon Jun 25 11:48:31.927559 2018] [core:notice] [pid 11956] AH00094: Command line: '/usr/sbin/httpd -D FOREGROUND'
[Mon Jun 25 11:48:31.927577 2018] [mpm_prefork:debug] [pid 11956] prefork.c(1005): AH00165: Accept mutex: sysvsem (default: sysvsem)
[Mon Jun 25 11:48:31.929526 2018] [proxy:debug] [pid 12376] proxy_util.c(1843): AH00925: initializing worker proxy:reverse shared
[Mon Jun 25 11:48:31.929573 2018] [proxy:debug] [pid 12376] proxy_util.c(1885): AH00927: initializing worker proxy:reverse local
[Mon Jun 25 11:48:31.929616 2018] [proxy:debug] [pid 12376] proxy_util.c(1936): AH00931: initialized single connection worker in child 12376 for (*)
[Mon Jun 25 11:48:31.929832 2018] [proxy:debug] [pid 12377] proxy_util.c(1843): AH00925: initializing worker proxy:reverse shared
[Mon Jun 25 11:48:31.929879 2018] [proxy:debug] [pid 12377] proxy_util.c(1885): AH00927: initializing worker proxy:reverse local
[Mon Jun 25 11:48:31.929919 2018] [proxy:debug] [pid 12377] proxy_util.c(1936): AH00931: initialized single connection worker in child 12377 for (*)
[Mon Jun 25 11:48:31.930093 2018] [proxy:debug] [pid 12374] proxy_util.c(1843): AH00925: initializing worker proxy:reverse shared
[Mon Jun 25 11:48:31.930128 2018] [proxy:debug] [pid 12374] proxy_util.c(1885): AH00927: initializing worker proxy:reverse local
[Mon Jun 25 11:48:31.930166 2018] [proxy:debug] [pid 12374] proxy_util.c(1936): AH00931: initialized single connection worker in child 12374 for (*)
[Mon Jun 25 11:48:31.930791 2018] [proxy:debug] [pid 12378] proxy_util.c(1843): AH00925: initializing worker proxy:reverse shared
[Mon Jun 25 11:48:31.930825 2018] [proxy:debug] [pid 12378] proxy_util.c(1885): AH00927: initializing worker proxy:reverse local
[Mon Jun 25 11:48:31.930862 2018] [proxy:debug] [pid 12378] proxy_util.c(1936): AH00931: initialized single connection worker in child 12378 for (*)
[Mon Jun 25 11:48:31.931137 2018] [proxy:debug] [pid 12379] proxy_util.c(1843): AH00925: initializing worker proxy:reverse shared
[Mon Jun 25 11:48:31.931169 2018] [proxy:debug] [pid 12379] proxy_util.c(1885): AH00927: initializing worker proxy:reverse local
[Mon Jun 25 11:48:31.931205 2018] [proxy:debug] [pid 12379] proxy_util.c(1936): AH00931: initialized single connection worker in child 12379 for (*)

More info

  • SELinux is in “permissive” mode
  • Apache from yum install httpd-devel, PHP 7.0 from IUS repository

About this issue

  • Original URL
  • State: closed
  • Created 6 years ago
  • Comments: 43 (18 by maintainers)

Commits related to this issue

Most upvoted comments

All seems to be working. Concur with closing. Thanks for the help!

+1
jamesmontalvo3 on Jul 24, 2018

@yitam the significant settings difference is that the failing system has /home as an autofs file system. This is outside my expertise so I may not get the details right, but I believe each users’ home directory is mounted and shared, and if a directory is not available in /home it will attempt to mount it. If it is unable to mount it, it times out in ~2 minutes.

My guess is that all Apache-based systems on RedHat/CentOS and loading with systemd are looking here, but most systems quickly see that the file doesn’t exist and move on. This one just lags A LOT looking for the file.

+1
jamesmontalvo3 on Jul 6, 2018

When checking user Apache’s $HOME I get:

$ sudo su apache -s /bin/sh -c 'echo $HOME'
/usr/share/httpd

I’ve been unsuccessful trying to get systemd to output what it thinks Apache’s $HOME is, but it seems like it thinks it’s just /home. I’m sure there’s some easy way to confirm this, but I haven’t figured it out.

So I changed the end of /etc/sysconfig/httpd to remove all the ODBC* environment variables and instead just specified HOME. With this httpd loads immediately AND I’m querying an MSSQL Server database without errors.

LANG=C
#ODBCINI=/etc/odbc.ini
#ODBCINSTINI=/etc/odbcinst.ini
#ODBCSYSINI=/etc
HOME=/usr/share/httpd

I’d like to spend a little time making sure there are no other issues associated with this, but otherwise I think this probably closes the issue. There’s definitely some weirdness going on with the ODBC* environment variables which should be passed along to the developers of that system. I read on a few other sites that there are issues with these variables.

Thank you so much for your help!

+1
jamesmontalvo3 on Jul 6, 2018

@yitam good idea to try it on another RedHat box. I booted a RedHat install and tried it: no issues.

I’ve posted this issue on the Apache mailing list, and will report back here any relevant info. If you can think of anything else I’d really appreciate it. Thank you so much for the support thus far!

+1
jamesmontalvo3 on Jun 29, 2018
Read more comments on GitHub
← msphpsql: After upgrading from pdo_sqlsrv release candidate and msodbcsql17.1: Can't open lib '/opt/microsoft/msodbcsql17/lib64/libmsodbcsql-17.1.so.0.1' : file not found
msphpsql: ATTR_ERRMODE exception is not supported →