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

[jamesmontalvo3]

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:

• Apache: https://github.com/enterprisemediawiki/meza/blob/31.x/src/roles/apache-php/tasks/main.yml
• PHP: https://github.com/enterprisemediawiki/meza/blob/31.x/src/roles/apache-php/tasks/php.yml
• PHP driver for MSSQL: https://github.com/enterprisemediawiki/meza/blob/master/src/roles/apache-php/tasks/mssql_driver_for_php.yml

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

[david-puglielli]

@jamesmontalvo3 Do you have the same problem when trying to run a script that makes use of the sqlsrv or pdo_sqlsrv API from the command line (try php <sometestscript.php>)? Also, what is the output of php -m on both machines?

[jamesmontalvo3]

Both servers have the same output of php -m:

someuser@server-that-fails ~ $ php -m
[PHP Modules]
bcmath
bz2
calendar
Core
ctype
curl
date
dom
exif
fileinfo
filter
ftp
gd
gettext
hash
iconv
igbinary
intl
json
libxml
mbstring
mcrypt
memcached
mysqli
mysqlnd
odbc
openssl
pcntl
pcre
PDO
pdo_mysql
PDO_ODBC
pdo_sqlite
pdo_sqlsrv
Phar
posix
pspell
readline
Reflection
session
shmop
SimpleXML
snmp
soap
sockets
SPL
sqlite3
sqlsrv
standard
sysvmsg
sysvsem
sysvshm
tokenizer
wddx
xml
xmlreader
xmlrpc
xmlwriter
xsl
Zend OPcache
zip
zlib

[Zend Modules]
Zend OPcache

To test command line PHP I created the following script:

<?php

$conn = 'sqlsrv:server=[redacted] ; Database=[redacted]';
$user = '[redacted]';
$pass = '[redacted]';

$dbh = new PDO( $conn, $user, $pass );

echo "hello\n";

On the functioning server I get:

someuser@server-that-works ~ $ php test.php
hello

On the failing server I get:

someuser@server-that-fails ~ $ php test.php
PHP Fatal error:  Uncaught PDOException: SQLSTATE[HYT00]: [unixODBC][Microsoft][ODBC Driver 17 for SQL Server]Login timeout expired in /home/someuser/test.php:7
Stack trace:
#0 /home/someuser/test.php(7): PDO->__construct('sqlsrv:server=r...', '[redacted username]', '[redacted password]')
#1 {main}
  thrown in /home/someuser/test.php on line 7

[jamesmontalvo3]

I'm not sure if this is significant, but each failed httpd restart appears to be adding 5 semaphores. In the terminal output below each of the [Note: ...] are added by me for clarity.

someuser@server-that-fails ~ $ ipcs -s

------ Semaphore Arrays --------
key        semid      owner      perms      nsems
0x00000000 8421376    apache     600        1
0x00000000 8454145    apache     600        1
0x00000000 8486914    apache     600        1
0x00000000 8519683    apache     600        1
0x00000000 294916     root       600        1
0x00000000 327685     root       600        1
0x00000000 360454     root       600        1
0x00000000 393223     root       600        1
0x00000000 8552456    apache     600        1

[note: 5 apache semaphores]

someuser@server-that-fails ~ $ sudo systemctl restart httpd
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.
someuser@server-that-fails ~ $ ipcs -s

------ Semaphore Arrays --------
key        semid      owner      perms      nsems
0x00000000 8421376    apache     600        1
0x00000000 8454145    apache     600        1
0x00000000 8486914    apache     600        1
0x00000000 8519683    apache     600        1
0x00000000 294916     root       600        1
0x00000000 327685     root       600        1
0x00000000 360454     root       600        1
0x00000000 393223     root       600        1
0x00000000 8552456    apache     600        1
0x00000000 8650761    apache     600        1
0x00000000 8683530    apache     600        1
0x00000000 8716299    apache     600        1
0x00000000 8749068    apache     600        1
0x00000000 8781837    apache     600        1

[note: 10 apache semaphores]

someuser@server-that-fails ~ $ sudo systemctl restart httpd
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.
someuser@server-that-fails ~ $ ipcs -s

------ Semaphore Arrays --------
key        semid      owner      perms      nsems
0x00000000 8421376    apache     600        1
0x00000000 8454145    apache     600        1
0x00000000 8486914    apache     600        1
0x00000000 8519683    apache     600        1
0x00000000 294916     root       600        1
0x00000000 327685     root       600        1
0x00000000 360454     root       600        1
0x00000000 393223     root       600        1
0x00000000 8552456    apache     600        1
0x00000000 8650761    apache     600        1
0x00000000 8683530    apache     600        1
0x00000000 8716299    apache     600        1
0x00000000 8749068    apache     600        1
0x00000000 8781837    apache     600        1
0x00000000 8880142    apache     600        1
0x00000000 8912911    apache     600        1
0x00000000 8945680    apache     600        1
0x00000000 8978449    apache     600        1
0x00000000 9011218    apache     600        1

[note: 15 apache semaphores]

someuser@server-that-fails ~ $ cd /etc/php.d/
someuser@server-that-fails /etc/php.d $ ls *sqlsrv*
20-sqlsrv.ini  30-pdo_sqlsrv.ini
someuser@server-that-fails /etc/php.d $ sudo rm 20-sqlsrv.ini
someuser@server-that-fails /etc/php.d $ sudo rm 30-pdo_sqlsrv.ini
someuser@server-that-fails /etc/php.d $ ipcs -s

------ Semaphore Arrays --------
key        semid      owner      perms      nsems
0x00000000 8421376    apache     600        1
0x00000000 8454145    apache     600        1
0x00000000 8486914    apache     600        1
0x00000000 8519683    apache     600        1
0x00000000 294916     root       600        1
0x00000000 327685     root       600        1
0x00000000 360454     root       600        1
0x00000000 393223     root       600        1
0x00000000 8552456    apache     600        1
0x00000000 8650761    apache     600        1
0x00000000 8683530    apache     600        1
0x00000000 8716299    apache     600        1
0x00000000 8749068    apache     600        1
0x00000000 8781837    apache     600        1
0x00000000 8880142    apache     600        1
0x00000000 8912911    apache     600        1
0x00000000 8945680    apache     600        1
0x00000000 8978449    apache     600        1
0x00000000 9011218    apache     600        1

[note: 15 apache semaphores]

someuser@server-that-fails /etc/php.d $ sudo systemctl restart httpd
someuser@server-that-fails /etc/php.d $ ipcs -s

------ Semaphore Arrays --------
key        semid      owner      perms      nsems
0x00000000 8421376    apache     600        1
0x00000000 8454145    apache     600        1
0x00000000 8486914    apache     600        1
0x00000000 8519683    apache     600        1
0x00000000 294916     root       600        1
0x00000000 327685     root       600        1
0x00000000 360454     root       600        1
0x00000000 393223     root       600        1
0x00000000 8552456    apache     600        1
0x00000000 8650761    apache     600        1
0x00000000 8683530    apache     600        1
0x00000000 8716299    apache     600        1
0x00000000 8749068    apache     600        1
0x00000000 8781837    apache     600        1
0x00000000 8880142    apache     600        1
0x00000000 8912911    apache     600        1
0x00000000 8945680    apache     600        1
0x00000000 8978449    apache     600        1
0x00000000 9011218    apache     600        1
0x00000000 9109523    apache     600        1
0x00000000 9142292    apache     600        1
0x00000000 9175061    apache     600        1
0x00000000 9207830    apache     600        1
0x00000000 9240599    apache     600        1

[note: 20 apache semaphores]

someuser@server-that-fails /etc/php.d $ sudo systemctl restart httpd
someuser@server-that-fails /etc/php.d $ ipcs -s

------ Semaphore Arrays --------
key        semid      owner      perms      nsems
0x00000000 8421376    apache     600        1
0x00000000 8454145    apache     600        1
0x00000000 8486914    apache     600        1
0x00000000 8519683    apache     600        1
0x00000000 294916     root       600        1
0x00000000 327685     root       600        1
0x00000000 360454     root       600        1
0x00000000 393223     root       600        1
0x00000000 8552456    apache     600        1
0x00000000 8650761    apache     600        1
0x00000000 8683530    apache     600        1
0x00000000 8716299    apache     600        1
0x00000000 8749068    apache     600        1
0x00000000 8781837    apache     600        1
0x00000000 8880142    apache     600        1
0x00000000 8912911    apache     600        1
0x00000000 8945680    apache     600        1
0x00000000 8978449    apache     600        1
0x00000000 9011218    apache     600        1
0x00000000 9338899    apache     600        1
0x00000000 9371668    apache     600        1
0x00000000 9404437    apache     600        1
0x00000000 9437206    apache     600        1
0x00000000 9469975    apache     600        1

[note: 20 apache semaphores]

[david-puglielli]

Since the problem affects command line PHP, I doubt it has anything to do with Apache (though the semaphore leak is strange. Have you seen this link?).

To verify that apache is not responsible, could you uninstall Apache from the system and verify that the script produces the same error? Thanks!

[jamesmontalvo3]

I'll uninstall Apache to make sure, but I agree the command line test likely exonerates Apache. Assuming removing it has no effect, what else can I try? Is there some additional logging I can enable?

[david-puglielli]

You can try generating an ODBC trace - in the connection string, set TraceOn to true and set TraceFile to the file to write the trace to, and then add the following to /etc/odbcinst.ini:

Trace=Yes
TraceFile=/path/to/log/file

Note that tracing must be set in both the connection string and odbcinst.ini to work. For more information, see this link.

[jamesmontalvo3]

cat /home/someuser/test.php gives:

<?php

$conn = 'sqlsrv:server=[redacted] ; Database=[redacted]; Trace=true; TraceFile=/opt/data-meza/logs/odbc.log ';
$user = '[redacted]';
$pass = '[redacted]';

$dbh = new PDO( $conn, $user, $pass );

echo "hello\n";

cat /etc/odbcinst.ini gives:

[PostgreSQL]
Description=ODBC for PostgreSQL
Driver=/usr/lib/psqlodbcw.so
Setup=/usr/lib/libodbcpsqlS.so
Driver64=/usr/lib64/psqlodbcw.so
Setup64=/usr/lib64/libodbcpsqlS.so
FileUsage=1

[MySQL]
Description=ODBC for MySQL
Driver=/usr/lib/libmyodbc5.so
Setup=/usr/lib/libodbcmyS.so
Driver64=/usr/lib64/libmyodbc5.so
Setup64=/usr/lib64/libodbcmyS.so
FileUsage=1

[ODBC Driver 17 for SQL Server]
Description=Microsoft ODBC Driver 17 for SQL Server
Driver=/opt/microsoft/msodbcsql17/lib64/libmsodbcsql-17.1.so.0.1
UsageCount=1
Trace=Yes
TraceFile=/opt/data-meza/logs/odbc.log

Doing php /home/someuser/test.php still gives the same error. The file /opt/data-meza/logs/odbc.log does not exist. I don't think the ODBC trace worked.

Then I did sudo yum remove httpd-devel to remove Apache and retried php /home/someuser/test.php: no change, still failed.

[david-puglielli]

The keyword for the connection string is not Trace, it is TraceOn. It should work if you fix that in your script. (Your odbcinst.ini is correct - for the ini file, it is Trace and not TraceOn.)

[jamesmontalvo3]

Okay to simplify things I moved everything into /opt...

cat /opt/test.php:

<?php

$conn = 'sqlsrv:server=[redacted] ; Database=[redacted]; TraceOn=true; TraceFile=/opt/odbc.log ';
$user = '[redacted]';
$pass = '[redacted]';

$dbh = new PDO( $conn, $user, $pass );

echo "hello\n";

cat /etc/odbcinst.ini:

[PostgreSQL]
Description=ODBC for PostgreSQL
Driver=/usr/lib/psqlodbcw.so
Setup=/usr/lib/libodbcpsqlS.so
Driver64=/usr/lib64/psqlodbcw.so
Setup64=/usr/lib64/libodbcpsqlS.so
FileUsage=1

[MySQL]
Description=ODBC for MySQL
Driver=/usr/lib/libmyodbc5.so
Setup=/usr/lib/libodbcmyS.so
Driver64=/usr/lib64/libmyodbc5.so
Setup64=/usr/lib64/libodbcmyS.so
FileUsage=1

[ODBC Driver 17 for SQL Server]
Description=Microsoft ODBC Driver 17 for SQL Server
Driver=/opt/microsoft/msodbcsql17/lib64/libmsodbcsql-17.1.so.0.1
UsageCount=1
Trace=Yes
TraceFile=/opt/odbc.log

As someuser, php /opt/test.php gives the error:

EDIT: this comment initially had a "could not find driver error" here because I had disabled the MS SQLSRV extensions while troubleshooting. The incorrect error has been removed, and the actual error is below:

[26-Jun-2018 22:51:03 UTC] PHP Fatal error:  Uncaught PDOException: SQLSTATE[HYT00]: [unixODBC][Microsoft][ODBC Driver 17 for SQL Server]Login timeout expired in /opt/test.php:7
Stack trace:
#0 /opt/test.php(7): PDO->__construct('sqlsrv:server=r...', '[redacted]', '[redacted]')
#1 {main}
  thrown in /opt/test.php on line 7

As root, php /opt/test.php gives no output. No error. No "hello" echoed. (EDIT: see comments below. Reason for difference between root and someuser was because someuser did not have permissions to write to PHP error log)

There is nothing in /opt/odbc.log, so I did touch /opt/odbc.log and chmod 777 /opt/odbc.log to make sure it was present and writable. Running both as someuser and root gave the same results above and did not write to /opt/odbc.log.

[jamesmontalvo3]

I should have also given this:

$ ls -al /opt/test.php
-rwxrwxrwx. 1 root root 229 Jun 26 08:37 /opt/test.php

[jamesmontalvo3]

The reason for the difference between root and someuser is that my php error log was not writable by my user. I fixed this and now both give the error message. However, the error message I gave two comments above was wrong. I had disabled the SQLSRV extensions prior to running that, hence giving the "could not find driver" message. The original error I gave (about 9 comments above) was legitimate, though, and is what I'm getting now:

[26-Jun-2018 22:51:03 UTC] PHP Fatal error:  Uncaught PDOException: SQLSTATE[HYT00]: [unixODBC][Microsoft][ODBC Driver 17 for SQL Server]Login timeout expired in /opt/test.php:7
Stack trace:
#0 /opt/test.php(7): PDO->__construct('sqlsrv:server=r...', '[redacted]', '[redacted]')
#1 {main}
  thrown in /opt/test.php on line 7

Still nothing in /opt/odbc.log though.

[yitam]

Hi @jamesmontalvo3 , @david-puglielli is not in the office today. Anyway, with an error message like login timeout expired, I'd suggest you try something as simple as using sqlcmd or isql to connect first. Do you also get the same login timeout error?

[jamesmontalvo3]

@yitam I'm not sure what you're suggesting. Can you provide an edited version of test.php from above?

Keep in mind that simply trying to load extension=sqlsrv.so and extension=pdo_sqlsrv.so prevents Apache from starting...it's not actually trying to use these extensions at that point.

[david-puglielli]

@jamesmontalvo3, @yitam is referring to the sqlcmd command available from the mssql-tools package, or the isql command installed alonside unixODBC. It may be worth trying them so we can rule out a network issue.

[jamesmontalvo3]

I'm not sure how a network issue could prevent Apache from loading, but will give it a try. I have not used those before, and a quick search didn't show anything. I'll keep looking, but can you provide some docs?

FYI, I changed /opt/test.php to:

<?php

$server = "[redacted]";
$db = "[redacted]";
$table = "[redacted]";
$conn = "sqlsrv:server=$server ; Database=$db; TraceOn=true; TraceFile=/opt/odbc.log ";
$user = '[redacted]';
$pass = '[redacted]';

$conn = sqlsrv_connect( $server, [ "Database" => $db, "UID" => $user, "PWD" => $pass] );

if( $conn === false ) {
     die( print_r( sqlsrv_errors(), true));
}

$stmt = sqlsrv_query( $conn, "SELECT * FROM $table LIMIT 1", [] );

print_r( sqlsrv_fetch_array ( $stmt ) );

echo "hello\n";

Which gave the output:

Array
(
    [0] => Array
        (
            [0] => HYT00
            [SQLSTATE] => HYT00
            [1] => 0
            [code] => 0
            [2] => [unixODBC][Microsoft][ODBC Driver 17 for SQL Server]Login timeout expired
            [message] => [unixODBC][Microsoft][ODBC Driver 17 for SQL Server]Login timeout expired
        )

    [1] => Array
        (
            [0] => 08001
            [SQLSTATE] => 08001
            [1] => 11001
            [code] => 11001
            [2] => [unixODBC][Microsoft][ODBC Driver 17 for SQL Server]TCP Provider: Error code 0x2AF9
            [message] => [unixODBC][Microsoft][ODBC Driver 17 for SQL Server]TCP Provider: Error code 0x2AF9
        )

    [2] => Array
        (
            [0] => 08001
            [SQLSTATE] => 08001
            [1] => 11001
            [code] => 11001
            [2] => [unixODBC][Microsoft][ODBC Driver 17 for SQL Server]A network-related or instance-specific error has occurred while establishing a connection to SQL Server. Server is not found or not accessible. Check if instance name is correct and if SQL Server is configured to allow remote connections. For more information see SQL Server Books Online.
            [message] => [unixODBC][Microsoft][ODBC Driver 17 for SQL Server]A network-related or instance-specific error has occurred while establishing a connection to SQL Server. Server is not found or not accessible. Check if instance name is correct and if SQL Server is configured to allow remote connections. For more information see SQL Server Books Online.
        )

)

To try to isolate the Apache startup problem, I directly ran /usr/sbin/httpd -D FOREGROUND rather than systemctl start httpd. This hang indefinitely, so I ran a stack trace on it. sudo strace -o /tmp/st-httpd -f /usr/sbin/httpd -D FOREGROUND also hang indefinitely, but the repeating portion of the stack trace showed the following (not sure if this is at all helpful):

...
...
...
21620 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>
21626 <... epoll_wait resumed> [], 2, 10000) = 0
21626 epoll_wait(12,  <unfinished ...>
21620 <... select resumed> )            = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>
21626 <... epoll_wait resumed> [], 2, 10000) = 0
21626 epoll_wait(12,  <unfinished ...>
21620 <... select resumed> )            = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>
21626 <... epoll_wait resumed> [], 2, 10000) = 0
21626 epoll_wait(12,  <unfinished ...>
21620 <... select resumed> )            = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
...
...
... this went on apparently indefinitely ...

Each pair of wait4( ... ) and select( ... ) lines (see block [1] below) printed every ~1 second, so the time between each epoll_wait ... select resumed lines (see block [2] below) was about 10 seconds. This appeared to go on indefinitely. I let it run for more than 10 minutes.

[1] These lines repeated every ~1 second:

21620 wait4(-1, 0x7fff2ca882dc, WNOHANG|WSTOPPED, NULL) = 0
21620 select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>

[2] These lines were repeated every ~10 seconds:

21626 <... epoll_wait resumed> [], 2, 10000) = 0
21626 epoll_wait(12,  <unfinished ...>
21620 <... select resumed> )            = 0 (Timeout)