Linux: TCP error 0x2714 after Apache reload

[Snowknight26]

PHP Driver version or file name

5.9.0

SQL Server version

Microsoft SQL Server 2019 (RTM-CU8-GDR) (KB4583459) - 15.0.4083.2 (X64)

Client operating system

RHEL 7.8
Kernel: Linux 3.10.0-1127.18.2.el7.x86_64 x86_64

PHP version

7.4.16 NTS (7.4.16-1.el7.remi)

Microsoft ODBC Driver version

Microsoft ODBC Driver for SQL Server 17.7.1.1 (msodbcsql17.x86_64 17.7.1.1-1)
unixODBC 2.3.7 (unixODBC.x86_64 2.3.7-1.rh)

Table schema

N/A

Problem description

Reloading Apache during a long-running query causes the next query to be executed after child processes come back to generate the following error:
SQLSTATE[08S01]: [Microsoft][ODBC Driver 17 for SQL Server]TCP Provider: Error code 0x2714

Occasionally this error occurs instead:
SQLSTATE[08S01]: [Microsoft][ODBC Driver 17 for SQL Server]Communication link failure

Expected behavior and actual behavior

The next query should succeed.

Repro code or steps to reproduce

Create a script with the following:

$pdo = new PDO( 'sqlsrv:Server=server; LoginTimeout=15; MultipleActiveResultSets=false', '', '', [ PDO::ATTR_ERRMODE => PDO::ERRMODE_EXCEPTION ] );

$pdo->query( "WAITFOR DELAY '00:00:05'" );

var_dump( $pdo->query( 'SELECT 1 AS Row1' )->fetchAll( PDO::FETCH_ASSOC ) );

Save the script in a location that can be served up by Apache (httpd24-httpd.x86_64 2.4.34-18.el7 in my case) and executed by PHP.
For example: http://localhost/test.php

Continually refresh the page after after it has been served (will take a minimum of 5 seconds due to the WAITFOR).

Reload the Apache service. My RHEL installation required /bin/systemctl reload httpd24-httpd.service.

Once child processes are back, reloading the page (executing the script) will generate the error stated above.

The issue only seems to happen when using PDO_SQLSRV and not any other PDO driver.
For example, I've tried the following and was unable to reproduce:

• new PDO( 'odbc:server', '', '' ) - using PDO_ODBC instead
• new PDO( 'dblib:server', '', '' ) - using FreeTDS

Tried the following but the issue still occurred:

• Disabling pooling
• Restarting Apache service instead of reloading (/bin/systemctl restart httpd24-httpd.service)
• ConnectRetryCount > 1 in the DSN (I believe this is Windows only though so no surprise there)

odbcinst -j output:

unixODBC 2.3.7
DRIVERS............: /etc/odbcinst.ini
SYSTEM DATA SOURCES: /etc/odbc.ini
FILE DATA SOURCES..: /etc/ODBCDataSources
USER DATA SOURCES..: /home/user/.odbc.ini
SQLULEN Size.......: 8
SQLLEN Size........: 8
SQLSETPOSIROW Size.: 8

Relevant section of odbcinst.ini:

[ODBC Driver 17 for SQL Server]
Description=Microsoft ODBC Driver 17 for SQL Server
Driver=/opt/microsoft/msodbcsql17/lib64/libmsodbcsql-17.7.so.1.1
UsageCount=1
CPTimeout=120

Let me know if anything else is needed.

[yitam]

Thank you @Snowknight26 for bringing this to our attention. We will investigate and get back to you on this.

[yitam]

Hi @Snowknight26 I can't seem to be able to reproduce this issue. I've tried modifying the pdo script slightly and ran different tests. With connection pooling, I refreshed the browser while or after reloading Apache service. I did not see the aforementioned connection error but sometimes the SELECT query failed after the delay had elapsed.

Could you please provide an ODBC trace and Apache error logs? Make sure you add TraceOn=1; to the connection string and also modify /etc/odbcinst.ini like this, as an example:

[ODBC]
Trace = yes
Trace File = /tmp/sql.log

[Snowknight26]

@yitam
My mistake, through my trials and errors I mistyped the test script. The PDO error mode should be set to exception. I've updated my initial comment.

The failed SELECT query that you saw I believe is the exact issue, but without the error mode set to exceptions it wasn't possible to see the underlying reason (just "Call to a member function fetchAll() on boolean" or something like that).

I'm still working on providing logs but I believe setting the PDO::ATTR_ERRMODE attribute to PDO::ERRMODE_EXCEPTION should let you reproduce it.

[Snowknight26]

@yitam
I've attached some log files reproducing the issue. The Apache service was restarted a few times before so you might see some output from prior reproduction attempts, but the issue happened at Tue Mar 30 13:26:52.885195 2021 CST (Unix timestamp of 1617128812) per the Apache logs. Should be able to match up the Unix timestamp in the ODBC trace..

odbc.log - ODBC trace
php_output.log - browser output
httpd_error.log - Apache error log

[yitam]

Thanks @Snowknight26 I can reproduce it now, and I'll also examine the logs you provided. Will get back to you on this after some investigation.

[yitam]

Hi @Snowknight26 I did try pdo_odbc and could also reproduce the same problem:

[Snowknight26]

@yitam

When I was testing PDO_ODBC I believe FreeTDS was being used to provide the ODBC functionality. I was able to configure my environment to work with PDO_ODBC using Microsoft ODBC Driver 17 for SQL Server.

To elaborate further, I changed the test script to this:

<?php
$pdo = new PDO( 'sqlsrv:Server=server; LoginTimeout=15; MultipleActiveResultSets=false', '', '', [ PDO::ATTR_ERRMODE => PDO::ERRMODE_EXCEPTION ] );

try {
  var_dump( $pdo->query( 'SELECT 1 AS Row1' )->fetchAll( PDO::FETCH_ASSOC )[0]['Row1'] );
} catch( Throwable $e ) {
  var_dump( $e );
}

try {
  $pdo->query( "WAITFOR DELAY '00:00:05'" );
} catch( Throwable $e ) {
  var_dump( $e );
}

try {
  var_dump( $pdo->query( 'SELECT 2 AS Row1' )->fetchAll( PDO::FETCH_ASSOC )[0]['Row1'] );
} catch( Throwable $e ) {
  var_dump( $e );
}

Then I ran the same test with 5 different DSNs.

Expand each section to see the output.

sqlsrv:Server=server; LoginTimeout=15; MultipleActiveResultSets=false

string(1) "1"
object(PDOException)#3 (8) {
  ["message":protected]=>
  string(90) "SQLSTATE[08S01]: [Microsoft][ODBC Driver 17 for SQL Server]TCP Provider: Error code 0x2714"
  ["string":"Exception":private]=>
  string(0) ""
  ["code":protected]=>
  string(5) "08S01"
  ["file":protected]=>
  string(47) "/usr/local/apache/verify/htdocs2/common/test.php"
  ["line":protected]=>
  int(11)
  ["trace":"Exception":private]=>
  array(1) {
    [0]=>
    array(6) {
      ["file"]=>
      string(47) "/usr/local/apache/verify/htdocs2/common/test.php"
      ["line"]=>
      int(11)
      ["function"]=>
      string(5) "query"
      ["class"]=>
      string(3) "PDO"
      ["type"]=>
      string(2) "->"
      ["args"]=>
      array(1) {
        [0]=>
        string(24) "WAITFOR DELAY '00:00:05'"
      }
    }
  }
  ["previous":"Exception":private]=>
  NULL
  ["errorInfo"]=>
  array(6) {
    [0]=>
    string(5) "08S01"
    [1]=>
    int(10004)
    [2]=>
    string(73) "[Microsoft][ODBC Driver 17 for SQL Server]TCP Provider: Error code 0x2714"
    [3]=>
    string(5) "08S01"
    [4]=>
    int(10004)
    [5]=>
    string(68) "[Microsoft][ODBC Driver 17 for SQL Server]Communication link failure"
  }
}
object(PDOException)#4 (8) {
  ["message":protected]=>
  string(85) "SQLSTATE[08S01]: [Microsoft][ODBC Driver 17 for SQL Server]Communication link failure"
  ["string":"Exception":private]=>
  string(0) ""
  ["code":protected]=>
  string(5) "08S01"
  ["file":protected]=>
  string(47) "/usr/local/apache/verify/htdocs2/common/test.php"
  ["line":protected]=>
  int(17)
  ["trace":"Exception":private]=>
  array(1) {
    [0]=>
    array(6) {
      ["file"]=>
      string(47) "/usr/local/apache/verify/htdocs2/common/test.php"
      ["line"]=>
      int(17)
      ["function"]=>
      string(5) "query"
      ["class"]=>
      string(3) "PDO"
      ["type"]=>
      string(2) "->"
      ["args"]=>
      array(1) {
        [0]=>
        string(16) "SELECT 2 AS Row1"
      }
    }
  }
  ["previous":"Exception":private]=>
  NULL
  ["errorInfo"]=>
  array(3) {
    [0]=>
    string(5) "08S01"
    [1]=>
    int(0)
    [2]=>
    string(68) "[Microsoft][ODBC Driver 17 for SQL Server]Communication link failure"
  }
}

odbc:driver={ODBC Driver 17 for SQL Server}; server=server; Trusted_Connection=yes

string(1) "1"
object(PDOException)#3 (8) {
  ["message":protected]=>
  string(209) "SQLSTATE[08S01]: Communication link failure: 10004 [Microsoft][ODBC Driver 17 for SQL Server]TCP Provider: Error code 0x2714 (SQLExecute[10004] at /builddir/build/BUILD/php-7.4.16/ext/pdo_odbc/odbc_stmt.c:259)"
  ["string":"Exception":private]=>
  string(0) ""
  ["code":protected]=>
  string(5) "08S01"
  ["file":protected]=>
  string(67) "/usr/local/apache/verify/htdocs2/common/test.php"
  ["line":protected]=>
  int(11)
  ["trace":"Exception":private]=>
  array(1) {
    [0]=>
    array(6) {
      ["file"]=>
      string(67) "/usr/local/apache/verify/htdocs2/common/test.php"
      ["line"]=>
      int(11)
      ["function"]=>
      string(5) "query"
      ["class"]=>
      string(3) "PDO"
      ["type"]=>
      string(2) "->"
      ["args"]=>
      array(1) {
        [0]=>
        string(24) "WAITFOR DELAY '00:00:05'"
      }
    }
  }
  ["previous":"Exception":private]=>
  NULL
  ["errorInfo"]=>
  array(4) {
    [0]=>
    string(5) "08S01"
    [1]=>
    int(10004)
    [2]=>
    string(158) "[Microsoft][ODBC Driver 17 for SQL Server]TCP Provider: Error code 0x2714 (SQLExecute[10004] at /builddir/build/BUILD/php-7.4.16/ext/pdo_odbc/odbc_stmt.c:259)"
    [3]=>
    string(5) "08S01"
  }
}
object(PDOException)#4 (8) {
  ["message":protected]=>
  string(196) "SQLSTATE[08S01]: Communication link failure: 0 [Microsoft][ODBC Driver 17 for SQL Server]Communication link failure (SQLExecute[0] at /builddir/build/BUILD/php-7.4.16/ext/pdo_odbc/odbc_stmt.c:259)"
  ["string":"Exception":private]=>
  string(0) ""
  ["code":protected]=>
  string(5) "08S01"
  ["file":protected]=>
  string(67) "/usr/local/apache/verify/htdocs2/common/test.php"
  ["line":protected]=>
  int(17)
  ["trace":"Exception":private]=>
  array(1) {
    [0]=>
    array(6) {
      ["file"]=>
      string(67) "/usr/local/apache/verify/htdocs2/common/test.php"
      ["line"]=>
      int(17)
      ["function"]=>
      string(5) "query"
      ["class"]=>
      string(3) "PDO"
      ["type"]=>
      string(2) "->"
      ["args"]=>
      array(1) {
        [0]=>
        string(16) "SELECT 2 AS Row1"
      }
    }
  }
  ["previous":"Exception":private]=>
  NULL
  ["errorInfo"]=>
  array(4) {
    [0]=>
    string(5) "08S01"
    [1]=>
    int(0)
    [2]=>
    string(149) "[Microsoft][ODBC Driver 17 for SQL Server]Communication link failure (SQLExecute[0] at /builddir/build/BUILD/php-7.4.16/ext/pdo_odbc/odbc_stmt.c:259)"
    [3]=>
    string(5) "08S01"
  }
}

odbc:driver=FreeTDSODBC;servername=server

string(1) "1"
string(1) "2"

odbc:server

string(1) "1"
string(1) "2"

dblib:host=server

int(1)
int(2)

From the results, we can see the following:

• PDO_SQLSRV fails after the first query.
• PDO_ODBC using ODBC Driver 17 fails after the first query.
• In my environment at least, specifying odbc:server or odbc:driver=FreeTDSODBC;servername=server seem to be equivalent (based on what I can tell from /etc/odbc.ini, /etc/odbcinst.ini and /etc/freetds.conf). I was not able to replicate the issue using PDO_ODBC with FreeTDS.
• I was not able to replicate the issue using PDO_DBLIB with FreeTDS.

It's puzzling that in the case of the first two DSNs, only the first query succeeds, as reloading Apache is a graceful operation and in theory should wait for the script to finish executing.

My takeaway is that there's an issue with the Microsoft ODBC Driver 17 for SQL Server. Would that be a fair assessment to make?

Do you know if the queries that failed due to TCP errors are fully executed on SQL Server's end, or is it impossible to tell? I'm not sure when the TCP connection is broken.

[yitam]

Thanks @Snowknight26 for your detailed report and analysis. When re-reading your original description, you mentioned:

Once child processes are back, reloading the page (executing the script) will generate the error stated above.

Can you elaborate further what exactly you meant by "once child processes are back"?

In my case, the reload command takes time to complete, but if I wait for it to finish before refreshing the web browser, then I am unable to reproduce this problem.

That is, so far I can only reproduce this if I run the reload command when the long query is being executed. Because of the delay, the query result takes a long time to show after refreshing the web browser.

[Snowknight26]

My Apache instance is set up in is a high-traffic environment that receives millions of requests a day. As such, a cron job reloads Apache daily during off-peak hours to both prevent memory leaks and rotate logs.

This is done using /bin/systemctl reload httpd24-httpd.service. Based on the httpd24-httpd.service file, that command translates to /opt/rh/httpd24/root/usr/sbin/httpd-scl-wrapper $OPTIONS -k graceful.

Per Apache's documentation, passing the graceful option causes Apache to gracefully restart.

The USR1 or graceful signal causes the parent process to advise the children to exit after their current request (or to exit immediately if they're not serving anything). The parent re-reads its configuration files and re-opens its log files. As each child dies off the parent replaces it with a child from the new generation of the configuration, which begins serving new requests immediately.

With that in mind, what I meant by "once child processes are back" was the last sentence in that quote.

Further Apache documentation states that 'graceful' does the following:

Gracefully restarts the Apache httpd daemon. If the daemon is not running, it is started. This differs from a normal restart in that currently open connections are not aborted.

My interpretation is that the httpd daemon keeps running but child processes are stopped after requests have been processed and are started again.

The reason for the WAITFOR in the test script is to more easily trigger the issue, simulating a typical load.

With FreeTDS (either using PDO_ODBC or PDO_DBLIB), regardless of when the reload is issued in relation to which line of the script is currently being executed, the above test script keeps the connection open until the script has finished, all 3 queries are executed successfully, the script finishes, PHP flushes its buffers, Apache sends the data to the open HTTP connection and all is well. Effectively the page runs successfully and a person making the request sees the success-state output.

In contrast, with (I assume) Microsoft ODBC Driver 17 for SQL Server, when the reload is issued, it's possible that PHP's connection to the SQL Server instance is abruptly closed, causing the 2nd (longest) and subsequent queries in the test script to fail. The script finishes executing after having thrown/handled the exceptions/errors, PHP flushes its buffers, and Apache sends the data to the open HTTP connection. Effectively the page errors and a person making the HTTP request sees the error-state output.

In the case of my environment, with millions of hits per day, numerous PDOExceptions are thrown during the process of reloading the child processes/threads/workers (whatever they are called).

[yitam]

Thanks again, @Snowknight26
We suspect this might be related to #885 but we will do more investigation or see if there is any workaround.

[Snowknight26]

@yitam

I saw that bug report as I was submitting this one and considered they might be related - maybe something along the lines of the ODBC driver improperly handling SIGUSR1 or whatever other signal that's being sent.

I did a little more testing to try to figure out what the behavior is on SQL Server's end when the error occurs.

To start, I created a table and a stored procedure:

USE [Contoso]
DROP TABLE IF EXISTS dbo.ConnectionTest
CREATE TABLE dbo.ConnectionTest
(
  [Date]    DATETIME2 NOT NULL,
  Iteration INT NOT NULL,
  Process   VARCHAR(8) NOT NULL
)
GO

GRANT INSERT ON dbo.ConnectionTest TO [public]
GO

CREATE OR ALTER PROCEDURE dbo.ConnectionTestINS
AS
BEGIN
  SET NOCOUNT ON;

  DECLARE @Iteration TINYINT = 0;

  WHILE(@Iteration < 100)
  BEGIN
    SET @Iteration = @Iteration + 1;
    INSERT INTO dbo.ConnectionTest([Date], Iteration, Process) VALUES (GETDATE(), @Iteration, 'Database');
    WAITFOR DELAY '00:00:00.050';
  END

  SELECT @Iteration AS Iteration
END
GO

GRANT EXECUTE ON dbo.ConnectionTestINS TO [public]
GO

Next, I modified the test script to the following:

<?php

$pdo = new PDO( 'sqlsrv:Server=server; LoginTimeout=15; MultipleActiveResultSets=false', '', '', [ PDO::ATTR_ERRMODE => PDO::ERRMODE_EXCEPTION ] );
$i = 0;
$process = 'Apache';

try {
    $stmt = $pdo->prepare( 'INSERT INTO Contoso.dbo.ConnectionTest([Date], Iteration, Process) VALUES (GETDATE(), ?, ?)' );
    $stmt->execute( [ $i++, $process ] );
}
catch( Throwable $e ) {}

try {
    $stmt->execute( [ $i++, $process ] );
    $pdo->query( 'EXEC Contoso.dbo.ConnectionTestINS' );
    $stmt->execute( [ $i++, $process ] );
}
catch( Throwable $e ) {}

try {
    $stmt->execute( [ $i++, $process ] );
}
catch( Throwable $e ) {}

Next, I ran the test before, running reload several times and hitting the page several times simultaneously.

What I found out is that it's possible for the error to occur during the stored procedure execution. Without implicit or explicit transactions, that means that instead of the SP inserting 100 rows, it's possible it inserts anywhere from 0 to 100.

I'm sure you can see why this is alarming.

Doing the same test with FreeTDS's ODBC showed that the SP always finished executing (thus inserting all 100 rows). I was hoping that the behavior would be the same regardless of which driver is used but that appears to not be the case.

All this makes trying to make the permanent switch in my environment from FreeTDS to this driver a bit of a challenge.

[yitam]

Hi @Snowknight26, thanks again for providing more details.

After some investigation with the ODBC team, we conclude that this is actually by design. The process has been interrupted by a signal (from Apache), which breaks the connection and thus exceptions are thrown. On the other hand, FreeTDS does not handle the signal as it should have, which might get the process stuck in a state that might be problematic. In other words, signaling it may not get it unstuck.

[Snowknight26]

@yitam
I'm by no means an expert on signaling nor do I know how the ODBC driver behaves in contexts outside of my use case (PHP running as an Apache module) but I'm a little confused by the design decision.

Based on Apache's graceful signal (emphasis mine)

The USR1 or graceful signal causes the parent process to advise the children to exit after their current request (or to exit immediately if they're not serving anything).

it seems that the connection to the database should not exit immediately, but rather only after the current request, which happens anyway during the PDO object destruction.

I'm just going to naively assume the SIGUSR1 signal is passed as follows:
System -> Apache -> PHP module -> PHP extensions/drivers -> [...]

Under normal conditions, I assume the following happens when SIGUSR1 is sent.

1. The system notifies the Apache daemon
2. Apache daemon notifies child processes
3. Child processes stop accepting new connections
4. Child processes finish processing their current requests (if there are any)
   1. PHP continues executing any running script
   2. PHP finishes executing running scripts
      1. Objects are destroyed
      2. Shutdown handler is called
5. Child processes exit
6. Apache daemon re-reads/parses/validates configuration files
7. Apache daemon starts child processes

If any currently executing PHP scripts are not immediately halted (basically having the equivalent of an 'exit' statement) in 4., why should the database driver immediately close the connection?

I can see how the behavior would make sense in the case of SIGHUP/SIGTERM where the Apache daemon tries to immediately kill off all children, but not in the SIGUSR1 scenario.

Unless I'm mistaken, there seems to be no way to safely wait and close the database connection via a signal? Better yet, is there a way to have the driver ignore SIGUSR1?

On the other hand, FreeTDS does not handle the signal as it should have, which might get the process stuck in a state that might be problematic. In other words, signaling it may not get it unstuck.

That's why timeouts not only in both FreeTDS and the ODBC driver are configurable, but also script execution time in PHP, no? Both of those mechanisms ensure that eventually (after their current request) Apache child processes restart.

[v-chojas]

We see from strace that Apache does not set SA_RESTART when it sets up the SIGUSR1 handler.
This does not match the description to "exit after their current request", rather the intention seems to be the opposite.
In other words this seems a bug on the Apache side, either in their documentation or implementation.

[Snowknight26]

@v-chojas
Would you mind elaborating on this a little more? I only just started looking through the apr/httpd source code (specifically the prefork module) but don't see anything out of the ordinary as far as handling signals go.

https://github.com/apache/httpd/blob/21f16155c38e406e0a0daaa60a539d66128cf044/server/mpm/prefork/prefork.c#L1065
https://github.com/apache/httpd/blob/21f16155c38e406e0a0daaa60a539d66128cf044/server/mpm_unix.c#L327

prefork_run() calls ap_wait_or_timeout() (which I assume waits for child processes to finish), then calls ap_mpm_safe_kill() with AP_SIG_GRACEFUL (SIGUSR1), which passes the signal to kill(), with the PID of the child process.

What do you mean by SA_RESTART?

It seems odd that only Apache behaves this way. I haven't heard of issues with how its signal handling works.
Why is it that the PHP module continues executing but doesn't immediately halt with SIGUSR1, or any other module for that matter?