Irregular - Sqlcmd: Error: Microsoft ODBC Driver 13 for SQL Server : Login timeout expired. Only from linux

[stefankaifer]

Hi

I've a big problem with PHPSQLSRV, and SQLMCD on linux, too. We have irregular (mostly every 30-40 or X minutes) no connection to our SQL 2016 windows-server. This is the error message of sqlcmd:

Sqlcmd: Error: Microsoft ODBC Driver 13 for SQL Server : TCP Provider: Timeout error [258]. .
Sqlcmd: Error: Microsoft ODBC Driver 13 for SQL Server : Unable to complete login process due to delay in prelogin response.
[2017-07-07 14:00:26] Error : [1] when executing command: 'chronic /opt/mssql-tools/bin/sqlcmd -S 10.64.150.15 -d easy_prod -U myUser -P myPassword -l 2 -t 2 -Q 'SELECT @@Version''

I've created a BASH-script, that runs every 5 seconds SQLCMD:

#!/bin/bash
safeRunCommand() {
dt=$(date '+%Y-%m-%d %H:%M:%S');
typeset cmnd="$*"
typeset ret_code

eval $cmnd
ret_code=$?
if [ $ret_code != 0 ]; then
printf "[%s] Error : [%d] when executing command: '$cmnd'" "$dt" $ret_code
fi
}

LOG_FILE=/var/log/test-sqlconnection.errors.log
command="chronic /opt/mssql-tools/bin/sqlcmd -S 10.64.150.15 -d easy_dev -U myUser -P myPassword -l 2 -t 2 -Q 'SELECT @@Version'"

exec 3>&1 1>>${LOG_FILE} 2>&1
while [ "1" = "1" ]; do
safeRunCommand "$command"
sleep 3
done

I've created a POWERSHELL-Script, that runs on a Windows2012-server and on the SQL-Server:

FUNCTION Test-SQLConnection {
[CmdletBinding()]
Param (
[Parameter(Mandatory=$true)]
[string[]]
$Servers
,
[Parameter(Mandatory=$false)]
[Alias('LogPath')]
[string]$Path='',
[ValidateSet("String","Object")]
[string]
$OutputTo

)

BEGIN {}

PROCESS {
TRY {
Invoke-Sqlcmd -ServerInstance 127.0.0.1 -Database easy_prod -Username myUsername -Password myPassword -ConnectionTimeout 3 -QueryTimeout 3 -Query 'SELECT @@Version'
}
CATCH {
Write-Log -Message "No connection to SQL-server" -LogPath $LogPath
Write-Output "No connection to SQL-server"
}
}
}

}

function Write-Log
{
[CmdletBinding()]
Param
(
[Parameter(Mandatory=$true,
ValueFromPipelineByPropertyName=$true)]
[ValidateNotNullOrEmpty()]
[Alias("LogContent")]
[string]$Message,
[Parameter(Mandatory=$false)]
[Alias('LogPath')]
[string]$Path='',

    [Parameter(Mandatory=$false)] 
    [ValidateSet("Error","Warn","Info")] 
    [string]$Level="Info", 
     
    [Parameter(Mandatory=$false)] 
    [switch]$NoClobber 
) 
Begin 
{ 
    $VerbosePreference = 'Continue' 
} 
Process 
{ 
    if ((Test-Path $Path) -AND $NoClobber) { 
        Write-Error "Log file $Path already exists, and you specified NoClobber. Either delete the file or specify a different name." 
        Return 
        } 
    elseif (!(Test-Path $Path)) { 
        Write-Verbose "Creating $Path." 
        $NewLogFile = New-Item $Path -Force -ItemType File 
        } 
    else { 
        } 
    $FormattedDate = Get-Date -Format "yyyy-MM-dd HH:mm:ss" 
    switch ($Level) { 
        'Error' { 
            Write-Error $Message 
            $LevelText = 'ERROR:' 
            } 
        'Warn' { 
            Write-Warning $Message 
            $LevelText = 'WARNING:' 
            } 
        'Info' { 
            Write-Verbose $Message 
            $LevelText = 'INFO:' 
            } 
        } 
     
    "$FormattedDate $LevelText $Message" | Out-File -FilePath $Path -Append 
} 
End 
{ 
} 

}

$LogPath = $PSScriptRoot + "" + $MyInvocation.MyCommand.Name -replace "ps1", "log"

while (1 -eq 1){
Test-SQLConnection -Servers 10.64.150.15 -LogPath $LogPath

start-sleep -seconds 5

}

This script runs every 5 seconds, too.

The irregular connection problems are only on the two linux-servers (same time are the problems!), not on the Windows2012-servers!

Linux-Webserver1 - 10.64.150.21, Ubuntu 16.04, msodbcsql 13.1.9.0-1, unixodbc 2.3.1-4.1, PHP7.1
Linux-Webserver2 - 10.64.150.22, Ubuntu 16.04, msodbcsql 13.1.9.0-1, unixodbc 2.3.1-4.1, PHP7.1
Windows-Webserver - 10.64.150.23, Windows 2012 R2, Powershell 5.0
SQLserver - 10.64.150.15, Windows 2012 R2, SQL 2016 Standard, Powershell 5.0

There are no activated firewalls on all of the servers. I'm connectiong over IP, not over DNS-name. All server are virtualized. We don't have any other connection problems or network problems. All the servers are in the same subnet. We have no problem by the connection from Windows-Webserver to the SQLserver, only between
Linux-Webserver1 -> SQLserver
and
Linux-Webserver2 -> SQLserver.

Please help me to solve problem.
Best regards

Stefan

[david-puglielli]

Hi @stefankaifer, this sounds like a network issue - the function that returns that particular error message reads TDS packets. Have you tried using wireshark or netcat to identify the problem?

[stefankaifer]

Hi @david-puglielli, sorry, but I can't explain that (network issue). Why?

1. Same server, same subnet, only different OS:
   Windows to SQL-Server: no problems in the last 5 days.
   Linux (IP: 10.64.150.21) to SQL-Server (IP: 10.64.150.15): random timeouts in the last 5 days.

2. I've installed Wireshark on the SQL-machine; if I understand the wireshark log, it can't be a network issue. Why? Please see this log:

Please see the Line No. 29314-29325. in the first lines are everything OK, but in the last not. Same ports. Why can I see the errors (No. 29322-29325) in Wireshark, if I've a network problem? I think, that the problem is on SQL-side, or not?
But in the SQL-errorlogs I can't find an issue. Can you advice me, please?

Regards,

Stefan

[david-puglielli]

You're getting RST responses, so the linux client is refusing packets from the server. My guess is a configuration issue on the client side. I would try running wireshark on the client. Also, does the problem happen if you try connecting with isql (from unixODBC) instead of sqlcmd?

[david-puglielli]

@stefankaifer Please run the bash script you wrote above using strace -tt. strace -tt sh <scriptname>

When a failure occurs, inspect the timestamps and look for any backward jumps. We suspect there is a bug in the way the ODBC driver calculates clock time - it may jump backwards occasionally, possibly right when sqlcmd disconnects. Please let us know if you observe this behaviour.

[stefankaifer]

@david-puglielli thanks! I'm capturing on the linux-client with tshark and I wrote a isql-script, too. Since yesterday there was no connection issue with isql, but with sqlcmd again!

My isql-command:
chronic /usr/bin/isql -v SECTION_FROM_ODBC.INI USERNAME PASSWORD -b < isql.sql

Here is a screenshot of the tshark-capture on the linux-client:

Strace-command for the sqlcmd-script is running now:

strace -tt -o /var/log/strace.log /bin/bash /data/test-sqlconnection-prod.sh

I'm waiting for the next connection error...

[v-chojas]

That will strace the /bin/bash, which won't log anything about sqlcmd. Instead, you should run strace on sqlcmd inside the script, and have the script exit the loop when sqlcmd fails. That way you will obtain the log of a failure only, and not spend huge amounts of disk space logging successful runs.

[stefankaifer]

Thanks, v-chojas. I've modified my script, but since two days I haven't any issues (==> no strace-log). It's very strange!
I've changed only one thing: because of the above "isql"-test, I've created the file /etc/odbc.ini (it wasn't there by default installation). But I don't belive, that it is the solution. I'm investigating further...

[david-puglielli]

Adding an odbc.ini file is not relevant to the problem I think. Please do keep us apprised of any further developments though!

[stefankaifer]

thanks, guys. I had the problem 2 or 3 times in the last days again. I've attached the strace-output.

strace-2017-07-24-21-33-59.txt
strace-2017-07-24-21-34-19.txt
strace-2017-07-25-19-58-19.txt

[david-puglielli]

@stefankaifer I believe you are still using strace on bash, you must run it on sqlcmd inside the script. There doesn't seem to be anything unusual in the logs you have provided.

[Hadis-Fard]

@stefankaifer Have you had a chance to try strace on command as @david-puglielli suggested?

[yitam]

@stefankaifer do you have any update on this?

[stefankaifer]

Hi guys, sorry for the late answer, but I had a lot of todos in the last weeks.
The problem is existing sometimes. My problem is, that I don't know how to run the strace command crrectly. I've read @david-puglielli's answer

@stefankaifer I believe you are still using strace on bash, you must run it on sqlcmd inside the script. There doesn't seem to be anything unusual in the logs you have provided.

but I don't know, ho to do it right. Can someone modify my script, please?

#!/bin/bash
safeRunCommand() {
dt=$(date '+%Y-%m-%d %H:%M:%S');
dtlog=$(date '+%Y-%m-%d-%H-%M-%S');
LOG_FILE_STRACE="/var/log/strace-$dtlog.log"
typeset cmnd="$*"
typeset ret_code

eval $cmnd
ret_code=$?
if [ $ret_code != 0 ]; then
strace -tt -f -o $LOG_FILE_STRACE /opt/mssql-tools/bin/sqlcmd -S 192.168.225.147 -d dbName -U myUser -P myPassword -l 2 -t 2 -Q 'SELECT @@Version'
printf "[%s] Error : [%d] when executing command: '$cmnd'" "$dt" $ret_code
fi
}

LOG_FILE=/var/log/test-sqlconnection.errors.log
command="chronic /opt/mssql-tools/bin/sqlcmd -S 192.168.225.147 -d dbName -U myUser -P myPassword -l 2 -t 2 -Q 'SELECT @@Version'"

exec 3>&1 1>>${LOG_FILE} 2>&1
while [ "1" = "1" ]; do
safeRunCommand "$command"
sleep 3
done

[david-puglielli]

You are running strace correctly - the problem is that the error happens only occasionally, so if you run strace only when an error occurs, the error will probably not occur again if you run the same command again under strace.

What version of the ODBC driver are you using? I would suggest upgrading to version 17, available here. The bug that causes time to jump backwards has been fixed in version 17, so upgrading may solve your issue.

[stefankaifer]

@david-puglielli Thanks. I had version 13, now I've installed version 17 on my development system. I'm observing...

[stefankaifer]

Hi guys,

I think, that with the current odbc-version (17) the problem is gone! I hadn't drops in the past 2 weeks.
Thank you very much for the support!
Regards

Stefan

[david-puglielli]

Glad we could help! You may also be interested to know, we will upload an updated ODBC driver 17 later this month as well.

Closing the issue.

[jeff1985]

@stefankaifer
I'm experiencing a similar issue, which might be connected to this case. Could you clarify: were you using persistent database connections (connection pooling) in your setup?

[stefankaifer]

@jeff1985 I'm using no persistant connections.

[pmartelletti]

@david-puglielli I've tried upgrading to version 17 of the driver, but got:

SQLSTATE[IMSSP]: This extension requires the Microsoft ODBC Driver 13 for SQL Server to communicate with SQL Server

Does that means that v17 is not supported with sqlsrv driver for PHP? or that is not finding the driver at all?

Problem I'm getting is that after 2/3 minutes of the driver running correctly, I get timeout login for all of the connections (even if I try to reconnect again).

Tried enabling pooling and increasing CPTimeout, but nothing helped. 😟

[david-puglielli]

@pmartelletti Please try adding the Driver keyword to your connection string and specifying version 17, like this:

Driver={ODBC Driver 17 for SQL Server};

This will override the default ODBC driver version.

[pmartelletti]

@david-puglielli hmm.. I'm using:

'driver' => 'sqlsrv',

how should I specify the version there? sqlsrv17 won't work.

[pmartelletti]

@david-puglielli sorry, just realised you were referring to the odbcinst.ini file.

Changed it in all the locations that I could find:

/etc/odbcinst.ini
/home/forge/.odbcinst.ini
/opt/microsoft/msodbcsql/etc/odbcinst.ini

to look something like this:

[ODBC]
Pooling=No

[ODBC Driver 17 for SQL Server]
Description=Microsoft ODBC Driver 17 for SQL Server
Driver=/opt/microsoft/msodbcsql/lib64/libmsodbcsql-17.0.so.0.5
UsageCount=1

but still getting from PHP the following:

Can't open lib 'ODBC Driver 13 for SQL Server' : file not found

So seems like it's still trying to use the v13 of the driver.

Any ideas?

[pmartelletti]

@david-puglielli is it possible that the PHP driver only works with the ODCB Driver 13, as per this list? Or that's just listing stable releases?

https://docs.microsoft.com/en-us/sql/connect/php/system-requirements-for-the-php-sql-driver

[david-puglielli]

That page just lists stable releases. The latest preview (5.2.0-RC) supports ODBC 17. To use ODBC 17, instead of 'driver=>'sqlsrv', use

'driver'=>"ODBC Driver 17 for SQL Server"

in your PHP script. To make sure you are using a supported version of the drivers, run

php --ri sqlsrv
php --ri pdo_sqlsrv

from the command line and verify that ExtensionVer is at least 5.2.0.