Unable to connect to SQL server after update

2

I updated my server today with all pending update and after reboot I was unable to connect to SQL server. Prior to reboot I've also enabled the firewall but now it's disabled again and server is after another reboot. When I try to connect locally using "sqlcmd -S localhost" I get error:

Sqlcmd: Error: Microsoft ODBC Driver 17 for SQL Server : Login timeout expired.
Sqlcmd: Error: Microsoft ODBC Driver 17 for SQL Server : TCP Provider: Error code 0x2749.
Sqlcmd: Error: 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..

Server itself is up and running:

hyperqbe@slaro:/etc$ sudo systemctl status mssql-server
[sudo] hasło użytkownika hyperqbe:
● mssql-server.service - Microsoft SQL Server Database Engine
   Loaded: loaded (/lib/systemd/system/mssql-server.service; enabled; vendor preset: enabled)
   Active: active (running) since Thu 2019-08-08 15:06:28 CEST; 19min ago
     Docs: https://docs.microsoft.com/en-us/sql/linux
 Main PID: 7259 (sqlservr)
    Tasks: 158
   CGroup: /system.slice/mssql-server.service
           ├─7259 /opt/mssql/bin/sqlservr
           └─7288 /opt/mssql/bin/sqlservr

sie 08 15:06:38 slaro sqlservr[7259]: [95B blob data]
sie 08 15:06:38 slaro sqlservr[7259]: [91B blob data]
sie 08 15:06:38 slaro sqlservr[7259]: [145B blob data]
sie 08 15:06:38 slaro sqlservr[7259]: [61B blob data]
sie 08 15:06:39 slaro sqlservr[7259]: [96B blob data]
sie 08 15:06:39 slaro sqlservr[7259]: [66B blob data]
sie 08 15:06:40 slaro sqlservr[7259]: [96B blob data]
sie 08 15:06:40 slaro sqlservr[7259]: [100B blob data]
sie 08 15:06:40 slaro sqlservr[7259]: [71B blob data]
sie 08 15:06:40 slaro sqlservr[7259]: [124B blob data]

I'm unable to connect remotely from other machine as well:

TITLE: Connect to Server
------------------------------
Cannot connect to 192.168.1.141.
------------------------------
ADDITIONAL INFORMATION:
A connection was successfully established with the server, but then an error occurred during the login process. (provider: SSL Provider, error: 0 - Istniejące połączenie zostało gwałtownie zamknięte przez zdalnego hosta.) (Microsoft SQL Server, Error: 10054)
For help, click: http://go.microsoft.com/fwlink?ProdName=Microsoft%20SQL%20Server&EvtSrc=MSSQLServer&EvtID=10054&LinkId=20476
As far as I know there were no errors during update process.

Here are the last entries from errorlog:

2019-08-08 15:06:34.89 Server      Microsoft SQL Server 2019 (CTP3.2) - 15.0.1800.32 (X64)
        Jul 17 2019 21:29:33
        Copyright (C) 2019 Microsoft Corporation
        Express Edition (64-bit) on Linux (Ubuntu 18.04.3 LTS) <X64>
2019-08-08 15:06:34.89 Server      UTC adjustment: 2:00
2019-08-08 15:06:34.89 Server      (c) Microsoft Corporation.
2019-08-08 15:06:34.89 Server      All rights reserved.
2019-08-08 15:06:34.89 Server      Server process ID is 32.
2019-08-08 15:06:34.89 Server      Logging SQL Server messages in file '/var/opt/mssql/log/errorlog'.
2019-08-08 15:06:34.89 Server      Registry startup parameters:
         -d /var/opt/mssql/data/master.mdf
         -l /var/opt/mssql/data/mastlog.ldf
         -e /var/opt/mssql/log/errorlog
2019-08-08 15:06:34.90 Server      SQL Server detected 1 sockets with 4 cores per socket and 4 logical processors per socket, 4 total logical processors; using 4 logical processors based on SQL Server licensing. This is an informational message; no user action is required.
2019-08-08 15:06:34.90 Server      SQL Server is starting at normal priority base (=7). This is an informational message only. No user action is required.
2019-08-08 15:06:34.90 Server      Detected 12800 MB of RAM. This is an informational message; no user action is required.
2019-08-08 15:06:34.90 Server      Using conventional memory in the memory manager.
2019-08-08 15:06:34.90 Server      Page exclusion bitmap is enabled.
2019-08-08 15:06:35.01 Server      Buffer pool extension is not supported on Linux platform.
2019-08-08 15:06:35.02 Server      Buffer Pool: Allocating 2097152 bytes for 1963331 hashPages.
2019-08-08 15:06:35.16 Server      Default collation: SQL_Latin1_General_CP1_CI_AS (us_english 1033)
2019-08-08 15:06:35.69 Server      Buffer pool extension is already disabled. No action is necessary.
2019-08-08 15:06:35.99 Server      Successfully initialized the TLS configuration. Allowed TLS protocol versions are ['1.0 1.1 1.2']. Allowed TLS ciphers are ['ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES128-SHA256:ECDHE-ECDSA-AES256-SHA384:ECDHE-ECDSA-AES256-SHA:ECDHE-ECDSA-AES128-SHA:AES256-GCM-SHA384:AES128-GCM-SHA256:AES256-SHA256:AES128-SHA256:AES256-SHA:AES128-SHA:!DHE-RSA-AES256-GCM-SHA384:!DHE-RSA-AES128-GCM-SHA256:!DHE-RSA-AES256-SHA:!DHE-RSA-AES128-SHA'].
2019-08-08 15:06:36.01 Server      Query Store settings initialized with enabled = 1,
2019-08-08 15:06:36.07 Server      The maximum number of dedicated administrator connections for this instance is '1'
2019-08-08 15:06:36.07 Server      Node configuration: node 0: CPU mask: 0x000000000000000f:0 Active CPU mask: 0x000000000000000f:0. This message provides a description of the NUMA configuration for this computer. This is an informational message only. No user action is required.
2019-08-08 15:06:36.11 Server      Using dynamic lock allocation.  Initial allocation of 2500 Lock blocks and 5000 Lock Owner blocks per node.  This is an informational message only.  No user action is required.
2019-08-08 15:06:36.17 Server      In-Memory OLTP initialized on lowend machine.
2019-08-08 15:06:36.37 Server      CLR version v4.0.30319 loaded.
2019-08-08 15:06:36.57 Server      [INFO] Created Extended Events session 'hkenginexesession'

2019-08-08 15:06:36.58 Server      Database Instant File Initialization: enabled. For security and performance considerations see the topic 'Database Instant File Initialization' in SQL Server Books Online. This is an informational message only. No user action is required.
2019-08-08 15:06:36.59 Server      Total Log Writer threads: 2. This is an informational message; no user action is required.
2019-08-08 15:06:36.72 Server      clflushopt is selected for pmem flush operation.
2019-08-08 15:06:36.72 Server      Software Usage Metrics is disabled.
2019-08-08 15:06:36.97 spid11s     [1]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1.
2019-08-08 15:06:36.98 spid11s     Starting up database 'master'.
2019-08-08 15:06:37.58 Server      Common language runtime (CLR) functionality initialized.
2019-08-08 15:06:37.77 spid11s     SQL Server Audit is starting the audits. This is an informational message. No user action is required.
2019-08-08 15:06:37.78 spid11s     SQL Server Audit has started the audits. This is an informational message. No user action is required.
2019-08-08 15:06:38.05 Server      Failed to verify the Authenticode signature of 'C:\binn\secforwarder.dll'. Signature verification of SQL Server DLLs will be skipped. Genuine copies of SQL Server are signed. Failure to verify the Authenticode signature might indicate that this is not an authentic release of SQL Server. Install a genuine copy of SQL Server or contact customer support.
2019-08-08 15:06:38.11 spid11s     SQL Trace ID 1 was started by login "sa".
2019-08-08 15:06:38.27 spid11s     Server name is 'slaro'. This is an informational message only. No user action is required.
2019-08-08 15:06:38.29 spid29s     Always On: The availability replica manager is starting. This is an informational message only. No user action is required.
2019-08-08 15:06:38.29 spid29s     Always On: The availability replica manager is waiting for the instance of SQL Server to allow client connections. This is an informational message only. No user action is required.
2019-08-08 15:06:38.30 spid11s     [4]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1.
2019-08-08 15:06:38.30 spid11s     Starting up database 'msdb'.
2019-08-08 15:06:38.32 spid12s     [32767]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1.
2019-08-08 15:06:38.32 spid12s     Starting up database 'mssqlsystemresource'.
2019-08-08 15:06:38.33 spid12s     The resource database build version is 15.00.1800. This is an informational message only. No user action is required.
2019-08-08 15:06:38.36 spid12s     [3]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1.
2019-08-08 15:06:38.36 spid12s     Starting up database 'model'.
2019-08-08 15:06:38.40 Server      Failed to verify the Authenticode signature of 'C:\binn\msoledbsql.dll'. Signature verification of SQL Server DLLs will be skipped. Genuine copies of SQL Server are signed. Failure to verify the Authenticode signature might indicate that this is not an authentic release of SQL Server. Install a genuine copy of SQL Server or contact customer support.
2019-08-08 15:06:38.48 spid28s     A self-generated certificate was successfully loaded for encryption.
2019-08-08 15:06:38.51 Server      Error: 37308, Severity: 16, State: 1.
2019-08-08 15:06:38.51 Server      Loaded None enclave for always encrypted.
2019-08-08 15:06:38.51 spid28s     Server is listening on [ 192.168.1.141 <ipv4> 1433].
2019-08-08 15:06:38.54 spid28s     Dedicated administrator connection support was not started because it is disabled on this edition of SQL Server. If you want to use a dedicated administrator connection, restart SQL Server using the trace flag 7806. This is an informational message only. No user action is required.
2019-08-08 15:06:38.54 spid28s     Error: 39002, Severity: 16, State: 1.
2019-08-08 15:06:38.54 spid28s     SQL failed to boot extensibility for error code 0x80070005.
2019-08-08 15:06:38.55 spid28s     InitializeXdbPkgLauncher failed. ErrorCode: 0x80004005.
2019-08-08 15:06:38.55 spid28s     SQL Server is now ready for client connections. This is an informational message; no user action is required.
2019-08-08 15:06:38.85 spid12s     Clearing tempdb database.
2019-08-08 15:06:39.88 spid12s     [2]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1.
2019-08-08 15:06:39.89 spid12s     Starting up database 'tempdb'.
2019-08-08 15:06:40.26 spid29s     The Service Broker endpoint is in disabled or stopped state.
2019-08-08 15:06:40.26 spid29s     The Database Mirroring endpoint is in disabled or stopped state.
2019-08-08 15:06:40.27 spid29s     Service Broker manager has started.
2019-08-08 15:06:40.27 spid11s     Recovery is complete. This is an informational message only. No user action is required.
2019-08-08 15:27:16.30 spid55      [5]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1.
2019-08-08 15:27:16.30 spid55      Starting up database 'ProgramMagazynowy'.
2019-08-08 15:27:16.53 spid55      Parallel redo is started for database 'ProgramMagazynowy' with worker pool size [2].
2019-08-08 15:27:16.73 spid55      Parallel redo is shutdown for database 'ProgramMagazynowy' with worker pool size [2].

It may have something to do with ODBC driver. I was able to enable logging and found this:

[ODBC][29210][1565333226.007247][SQLDriverConnectW.c][290]
                Entry:
                        Connection = 0x8c90e0
                        Window Hdl = (nil)
                        Str In = [DRIVER={ODBC Driver 17 for SQL Server};SERVER={192.168.1.141};Trusted_Connection={YES};WSID={slaro};APP={SQLCMD};][length = 113 (SQL_NTS)]
                        Str Out = (nil)
                        Str Out Max = 0
                        Str Out Ptr = (nil)
                        Completion = 0
                UNICODE Using encoding ASCII 'ANSI_X3.4-1968' and UNICODE 'UTF-16LE'

According to Documentation

If the ASCII character encoding is not UTF-8, there is more than one Driver Manager installed and your application is using the wrong one, or the Driver Manager was not built correctly.

In my case it's 'ANSI_X3.4-1968' so there has to be something wrong. I will further review the articles suggested in documentation but right now I don't know how to confirm that I indeed have two drivers installed and how to remove one.

odbcinst lists only one driver:

hyperqbe@slaro:/etc$ odbcinst -q -d
[ODBC Driver 17 for SQL Server]

This part seems to be fine. I'm not sure if I have my odbc.ini and odbcinst.ini defined correctly.

hyperqbe@slaro:/etc$ cat odbc.ini
[slaro]
Driver='ODBC Driver 17 for SQL Server'
Servername=192.168.1.141

hyperqbe@slaro:/etc$ cat odbcinst.ini
[ODBC Driver 17 for SQL Server]
Description=Microsoft ODBC Driver 17 for SQL Server
Driver=/opt/microsoft/msodbcsql17/lib64/libmsodbcsql-17.4.so.1.1
UsageCount=1
Trace=Yes
TraceFile=/home/hyperqbe/odbc.log
ubuntu
sql-server
odbc
asked on Super User Aug 9, 2019 by HyperQBE

0 Answers

Nobody has answered this question yet.


User contributions licensed under CC BY-SA 3.0