PostgreSQL ODBC Connection SSPI Authentication Failure

Question

I've recently made some changes to an existing application that I'm maintaining for our company to try to improve on some of the functionality. However, I've run into an issue, and I'm not able to find anything helpful through all of my Google searches. Here's the platform:

VB6 application running on Windows 7 (64-bit) using ADODB connection via ODBC to a PostgreSQL (v. 9.1.1) server.

The issue is that, for some reason it seems that the SSPI authentication method I'm using fails to retrieve a value from a sequence in the PostgreSQL database. Other (VB.NET) applications connect to the same database server using SSPI authentication with no problem (using Npgsql).

Here's the basic connection string used for the ODBC connection in the VB6 application:

DRIVER={PostgreSQL ANSI};Server=<SERVERNAMEHERE>;Port=<####>;Database=<DATABASENAMEHERE>;Uid=<USERNAMEHERE>

When I check the PostgreSQL server logs after attempting to make a connection to the database, I find the following error:

CDT FATAL:  SSPI authentication failed for user "<USERNAMEHERE>"
CDT LOG:  could not send data to client: No connection could be made because the target machine actively refused it.

I tried connecting to the database as this user from another machine (logged in with their credentials) through PGAdmin III, and I can connect just fine. I actually tried the same application from this second machine (also Windows 7 64-bit), and it doesn't appear to give me any errors in the connection.

Of course, when I run the code through the VB6 IDE on my WinXP VM (under my own credentials), everything seems to work exactly as expected. I verified the user's Active Directory account is active and unlocked, and the PostgreSQL database has the correct user created with the correct group role membership, etc. So, obviously my thought is that there must be something wrong with the ODBC driver installed for PostgreSQL. I installed the 64-bit PostgreSQL ODBC driver, and (of course) it didn't help. I uninstalled and reinstalled the 32-bit driver (since it's running through a 32-bit application), but no change.

Here's the VB6 code I'm using to try to connect to the database:

Private Function GetPGCertNumber() As Long
    On Error GoTo PGSQLError

    Dim PGDB As ADODB.Connection
    Dim RS As ADODB.Recordset
    Dim CertNum As Long
    Dim SQLStr As String

    Set PGDB = New ADODB.Connection
    PGDB.ConnectionString = PGSQL_CONNECTION_STR
    PGDB.CursorLocation = adUseServer
    PGDB.Open

    SQLStr = "SELECT nextval('certificatenumber_seq')"
    Set RS = New ADODB.Recordset
    RS.CursorLocation = adUseServer
    RS.Open SQLStr, PGDB

    If Not RS.EOF And Not RS.BOF Then
        CertNum = RS!nextval
    Else
        CertNum = -1
    End If

    GetPGCertNumber = CertNum
    RS.Close
    Set RS = Nothing
    PGDB.Close
    Set PGDB = Nothing
    Exit Function
PGSQLError:
    Dim ErrorMsg As String

    GetPGCertNumber = -1
    ErrorMsg = "An error occurred retrieving the next certificate number to use." & vbCrLf & _
               "Connection String: " & PGSQL_CONNECTION_STR & vbCrLf & _
               "Command String: " & SQLStr & vbCrLf & _
               "Database State: " & PGDB.State & vbCrLf & vbCrLf
    MsgBox ErrorMsg, vbCritical + vbOKOnly, "POSTGRESQL DATABASE ERROR"

    On Error Resume Next

    If Not PGDB Is Nothing Then
        If PGDB.State <> 0 Then
            PGDB.Close
        End If

        Set PGDB = Nothing
    End If
End Function

I've checked the sequence in the PostgreSQL database, and the sequence is not getting incremented. The error message that appears indicates that the SQLStr variable hasn't even been populated yet, which tells me that it's occurring when the Open method is being called.

I've come up with a "Band-Aid" workaround for the time being: I've created a new, limited access user on the PostgreSQL server that uses an MD5 login (specified in the pg_hba.conf) instead of SSPI, and hard-coded this in my connection string (PGSQL_CONNECTION_STR). From what I can tell so far, this appears to be working correctly, which leads me further to believe that the issue is specifically related to using SSPI with the ODBC connector for PostgreSQL in this environment.

I'm basically wondering at this point if someone might know of a specific issue with using the PostgreSQL ODBC driver to authenticate a connection to a PostgreSQL database via SSPI. I would much prefer to not have to hard-code credentials into the application, even if the credentials are for a limited-access user. I've tried everything I know to look at, although I've probably failed to mention it above, so please let me know if you need any clarification. Thanks in advance for your help.

EDIT: The only thing I have not tried yet is installing the 64-bit ODBC driver and changing my connection string to use that instead. The reason I haven't tried this is that we still have some users that haven't yet been upgraded to a 64-bit OS. If, perhaps, I can find a way to determine whether the user is on a 32-bit or 64-bit OS through VB6, this might be a viable alternative (assuming the 64-bit ODBC driver actually works correctly).

EDIT - debugging log details (redacted):

[mylog_3380.log]

[3336-0.000]calling getDSNdefaults
[3336-0.015]CC_connect: entering...
[3336-0.015]sslmode=disable
[3336-0.015]original_CC_connect: entering...
[3336-0.015]Driver Version='09.03.0300,201405140001' linking 1600 dynamic Multithread library
[3336-0.031]original_CC_connect: DSN = '', server = '<SERVERNAMEHERE>', port = '####', database = '<DATABASENAMEHERE>', username = '<USERNAMEHERE>', password=''
[3336-0.031]connecting to the server socket...
[3336-0.047](0)(null) ERRNO=0
[3336-0.047]connection to the server socket succeeded.
[3336-0.047]!!! usrname=<USERNAMEHERE> server=<SERVERNAMEHERE>
[3336-0.047]sizeof startup packet = 80
[3336-0.047]sent the authentication block successfully.
[3336-0.047]gonna do authentication
[3336-0.047]read -1, global_socket_buffersize=4096
[3336-0.047]Lasterror=10035
[3336-0.062]read 9, global_socket_buffersize=4096
[3336-0.062]auth got 'R'
[3336-0.062]areq = 9 salt=0000000000
[3336-0.062]in AUTH_REQ_SSPI
[3336-47.767][[SQLAllocHandle]][3336-47.767]PGAPI_AllocConnect: entering...
[3336-47.767]**** PGAPI_AllocConnect: henv = 02B413B8, conn = 02B481C0
[3336-47.767]EN_add_connection: self = 02B413B8, conn = 02B481C0
[3336-47.767]       added at i=1, conn->henv = 02B413B8, conns[i]->henv = 02B413B8
[3336-47.767][SQLGetInfo(30)][3336-47.767]PGAPI_GetInfo: entering...fInfoType=77
[3336-47.767]PGAPI_GetInfo: p='03.50', len=0, value=0, cbMax=12
[3336-47.767][[SQLSetConnectAttr]] 103
[3336-47.767]PGAPI_SetConnectAttr for 02B481C0: 103 0000000F
[3336-47.767]PGAPI_SetConnectOption: entering fOption = 103 vParam = 15
[3336-47.767][SQLDriverConnect][3336-47.767]PGAPI_DriverConnect: entering...
[3336-47.767]**** PGAPI_DriverConnect: fDriverCompletion=0, connStrIn='DRIVER={PostgreSQL ANSI};UID=<USERNAMEHERE>;Server=<SERVERNAMEHERE>;Port=####;Database=<DATABASENAMEHERE>;debug=1;commlog=1;'
[3336-47.767]CC_conninfo_init opt=2
[3336-47.767]copy_globals driver=PostgreSQL ANSI socket_buffersize=4096
[3336-47.767]our_connect_string = 'DRIVER={PostgreSQL ANSI};UID=<USERNAMEHERE>;Server=<SERVERNAMEHERE>;Port=####;Database=<DATABASENAMEHERE>;debug=1;commlog=1;'
[3336-47.767]attribute = 'DRIVER', value = '{PostgreSQL ANSI}'
[3336-47.783]copyAttributes: DSN='',server='',dbase='',user='',passwd='',port='',onlyread='',protocol='',conn_settings='(null)',disallow_premature=-1)
[3336-47.783]attribute = 'UID', value = '<USERNAMEHERE>'
[3336-47.783]copyAttributes: DSN='',server='',dbase='',user='<USERNAMEHERE>',passwd='',port='',onlyread='',protocol='',conn_settings='(null)',disallow_premature=-1)
[3336-47.783]attribute = 'Server', value = '<SERVERNAMEHERE>'
[3336-47.783]copyAttributes: DSN='',server='<SERVERNAMEHERE>',dbase='',user='<USERNAMEHERE>',passwd='',port='',onlyread='',protocol='',conn_settings='(null)',disallow_premature=-1)
[3336-47.783]attribute = 'Port', value = '####'
[3336-47.783]copyAttributes: DSN='',server='<SERVERNAMEHERE>',dbase='',user='<USERNAMEHERE>',passwd='',port='####',onlyread='',protocol='',conn_settings='(null)',disallow_premature=-1)
[3336-47.783]attribute = 'Database', value = '<DATABASENAMEHERE>'
[3336-47.783]copyAttributes: DSN='',server='<SERVERNAMEHERE>',dbase='<DATABASENAMEHERE>',user='<USERNAMEHERE>',passwd='',port='####',onlyread='',protocol='',conn_settings='(null)',disallow_premature=-1)
[3336-47.783]attribute = 'debug', value = '1'
[3336-47.783]copyAttributes: DSN='',server='<SERVERNAMEHERE>',dbase='<DATABASENAMEHERE>',user='<USERNAMEHERE>',passwd='',port='####',onlyread='',protocol='',conn_settings='(null)',disallow_premature=-1)
[3336-47.783]attribute = 'commlog', value = '1'
[3336-47.783]copyAttributes: DSN='',server='<SERVERNAMEHERE>',dbase='<DATABASENAMEHERE>',user='<USERNAMEHERE>',passwd='',port='####',onlyread='',protocol='',conn_settings='(null)',disallow_premature=-1)
[3336-47.783]getDSNinfo: DSN= overwrite=0
[3336-47.799]our_connect_string = 'DRIVER={PostgreSQL ANSI};UID=<USERNAMEHERE>;Server=<SERVERNAMEHERE>;Port=####;Database=<DATABASENAMEHERE>;debug=1;commlog=1;'
[3336-47.799]attribute = 'DRIVER', value = '{PostgreSQL ANSI}'
[3336-47.799]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=0;B3=0;B4=0;B5=1;B6=0;B7=1;B8=0;B9=1;C0=0;C1=0;C2=dd_;[3336-47.799]attribute = 'UID', value = '<USERNAMEHERE>'
[3336-47.799]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=0;B3=0;B4=0;B5=1;B6=0;B7=1;B8=0;B9=1;C0=0;C1=0;C2=dd_;[3336-47.799]attribute = 'Server', value = '<SERVERNAMEHERE>'
[3336-47.799]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=0;B3=0;B4=0;B5=1;B6=0;B7=1;B8=0;B9=1;C0=0;C1=0;C2=dd_;[3336-47.799]attribute = 'Port', value = '####'
[3336-47.799]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=0;B3=0;B4=0;B5=1;B6=0;B7=1;B8=0;B9=1;C0=0;C1=0;C2=dd_;[3336-47.799]attribute = 'Database', value = '<DATABASENAMEHERE>'
[3336-47.799]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=0;B3=0;B4=0;B5=1;B6=0;B7=1;B8=0;B9=1;C0=0;C1=0;C2=dd_;[3336-47.799]attribute = 'debug', value = '1'
[3336-47.799]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=1;B3=0;B4=0;B5=1;B6=0;B7=1;B8=0;B9=1;C0=0;C1=0;C2=dd_;[3336-47.799]attribute = 'commlog', value = '1'
[3336-47.799]copyCommonAttributes: A7=100;A8=4096;A9=0;B0=255;B1=8190;B2=1;B3=1;B4=0;B5=1;B6=0;B7=1;B8=0;B9=1;C0=0;C1=0;C2=dd_;[3336-47.799]calling getDSNdefaults
[3336-47.799]CC_connect: entering...
[3336-47.799]sslmode=disable
[3336-47.799]original_CC_connect: entering...
[3336-47.799]Driver Version='09.03.0300,201405140001' linking 1600 dynamic Multithread library
[3336-47.799]original_CC_connect: DSN = '', server = '<SERVERNAMEHERE>', port = '####', database = '<DATABASENAMEHERE>', username = '<USERNAMEHERE>', password=''
[3336-47.799]connecting to the server socket...
[3336-47.814](0)(null) ERRNO=0
[3336-47.814]connection to the server socket succeeded.
[3336-47.814]!!! usrname=<USERNAMEHERE> server=<SERVERNAMEHERE>
[3336-47.814]sizeof startup packet = 80
[3336-47.814]sent the authentication block successfully.
[3336-47.814]gonna do authentication
[3336-47.814]read -1, global_socket_buffersize=4096
[3336-47.814]Lasterror=10035
[3336-47.830]read 9, global_socket_buffersize=4096
[3336-47.830]auth got 'R'
[3336-47.830]areq = 9 salt=0000000000
[3336-47.830]in AUTH_REQ_SSPI

[psqlodbc_3380.log]

[0.015]Driver Version='09.03.0300,201405140001' linking 1600 dynamic Multithread library
[0.015]Global Options: fetch=100, socket=4096, unknown_sizes=0, max_varchar_size=255, max_longvarchar_size=8190
[0.015]                disable_optimizer=0, ksqo=1, unique_index=1, use_declarefetch=0
[0.015]                text_as_longvarchar=1, unknowns_as_longvarchar=0, bools_as_char=1 NAMEDATALEN=64
[0.031]                extra_systable_prefixes='dd_;', conn_settings='(null)' conn_encoding=''
[47.767]conn=02B481C0, PGAPI_DriverConnect( in)='DRIVER={PostgreSQL ANSI};UID=<USERNAMEHERE>;Server=<SERVERNAMEHERE>;Port=####;Database=<DATABASENAMEHERE>;debug=1;commlog=1;', fDriverCompletion=0
[47.799]Driver Version='09.03.0300,201405140001' linking 1600 dynamic Multithread library
[47.799]Global Options: fetch=100, socket=4096, unknown_sizes=0, max_varchar_size=255, max_longvarchar_size=8190
[47.799]                disable_optimizer=0, ksqo=1, unique_index=1, use_declarefetch=0
[47.799]                text_as_longvarchar=1, unknowns_as_longvarchar=0, bools_as_char=1 NAMEDATALEN=64
[47.799]                extra_systable_prefixes='dd_;', conn_settings='(null)' conn_encoding=''

EDIT - server logs: Here are the log entries from right around the time of my testing. It's pretty much the same thing I posted before, but I went forward a few minutes to allow for connection timeouts and such. It's from a different function in my VB6 application that's calling a stored procedure, but it's resulting in the same error/issue with the SSPI authentication.

2014-06-30 16:57:17 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.   
2014-06-30 16:57:17 CDT LOG:  unexpected EOF on client connection
2014-06-30 16:57:30 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.   
2014-06-30 16:57:30 CDT LOG:  unexpected EOF on client connection
2014-06-30 16:57:31 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.   
2014-06-30 16:57:31 CDT LOG:  unexpected EOF on client connection
2014-06-30 16:58:38 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.   
2014-06-30 16:58:38 CDT LOG:  unexpected EOF on client connection
2014-06-30 16:59:02 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.   
2014-06-30 16:59:02 CDT LOG:  unexpected EOF on client connection
2014-06-30 16:59:22 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.   
2014-06-30 16:59:22 CDT LOG:  unexpected EOF on client connection
2014-06-30 17:00:23 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.   
2014-06-30 17:00:23 CDT LOG:  unexpected EOF on client connection
2014-06-30 17:00:44 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.   
2014-06-30 17:00:44 CDT LOG:  unexpected EOF on client connection
2014-06-30 17:00:46 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.   
2014-06-30 17:00:46 CDT LOG:  unexpected EOF on client connection
2014-06-30 17:00:52 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.   
2014-06-30 17:00:52 CDT LOG:  unexpected EOF on client connection
2014-06-30 17:01:17 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.   
2014-06-30 17:01:17 CDT LOG:  unexpected EOF on client connection
2014-06-30 17:01:43 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.   
2014-06-30 17:01:43 CDT FATAL:  SSPI authentication failed for user "<USERNAMEHERE>"
2014-06-30 17:01:43 CDT LOG:  could not send data to client: No connection could be made because the target machine actively refused it.    
2014-06-30 17:01:43 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.   
2014-06-30 17:01:43 CDT FATAL:  SSPI authentication failed for user "<USERNAMEHERE>"
2014-06-30 17:01:43 CDT LOG:  could not send data to client: No connection could be made because the target machine actively refused it.    
2014-06-30 17:03:56 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.   
2014-06-30 17:03:56 CDT LOG:  unexpected EOF on client connection
2014-06-30 17:04:02 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.   
2014-06-30 17:04:02 CDT LOG:  unexpected EOF on client connection
2014-06-30 17:04:10 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.
2014-06-30 17:04:10 CDT LOG:  unexpected EOF on client connection
2014-06-30 17:05:30 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.   
2014-06-30 17:05:30 CDT LOG:  unexpected EOF on client connection
2014-06-30 17:05:39 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.   
2014-06-30 17:05:39 CDT LOG:  unexpected EOF on client connection
2014-06-30 17:06:33 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.   
2014-06-30 17:06:33 CDT LOG:  unexpected EOF on client connection
2014-06-30 17:11:05 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.   
2014-06-30 17:11:05 CDT LOG:  unexpected EOF on client connection
2014-06-30 17:11:50 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.   
2014-06-30 17:11:50 CDT LOG:  unexpected EOF on client connection

I can try to turn on the additional debugging, but it might take me a little bit to get any data from it. It's certainly possible (as you suggested earlier) that the issue is related to the version of PostgreSQL, except that these same functions will work correctly in a 32-bit WinXP test environment with the same ODBC connector installed.

EDIT - log_min_messages = debug1:

2014-07-02 10:33:24 CDT DEBUG:  autovacuum: processing database "<DATABASENAMEHERE>"
2014-07-02 10:33:25 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.


2014-07-02 10:33:25 CDT FATAL:  SSPI authentication failed for user "<USERNAMEHERE>"
2014-07-02 10:33:25 CDT LOG:  could not send data to client: No connection could be made because the target machine actively refused it.


2014-07-02 10:33:29 CDT DEBUG:  autovacuum: processing database "<DATABASENAMEHERE>"

log_min_messages = debug5

2014-07-02 10:36:49 CDT DEBUG:  StartTransaction
2014-07-02 10:36:49 CDT DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
2014-07-02 10:36:49 CDT DEBUG:  CommitTransaction
2014-07-02 10:36:49 CDT DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
2014-07-02 10:36:49 CDT DEBUG:  InitPostgres
2014-07-02 10:36:49 CDT DEBUG:  my backend ID is 5
2014-07-02 10:36:49 CDT DEBUG:  StartTransaction
2014-07-02 10:36:49 CDT DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
2014-07-02 10:36:49 CDT DEBUG:  CommitTransaction
2014-07-02 10:36:49 CDT DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
2014-07-02 10:36:49 CDT DEBUG:  autovacuum: processing database "<DATABASENAMEHERE>"
2014-07-02 10:36:49 CDT DEBUG:  StartTransaction
2014-07-02 10:36:49 CDT DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
2014-07-02 10:36:49 CDT DEBUG:  pg_statistic: vac: 80 (threshold 124), anl: 560 (threshold 87)
2014-07-02 10:36:49 CDT DEBUG:  pg_type: vac: 0 (threshold 112), anl: 0 (threshold 81)
2014-07-02 10:36:49 CDT DEBUG:  pg_attribute: vac: 0 (threshold 651), anl: 0 (threshold 351)
2014-07-02 10:36:49 CDT DEBUG:  pg_authid: vac: 19 (threshold 50), anl: 30 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  pg_proc: vac: 0 (threshold 518), anl: 0 (threshold 284)
2014-07-02 10:36:49 CDT DEBUG:  pg_class: vac: 0 (threshold 106), anl: 0 (threshold 78)
2014-07-02 10:36:49 CDT DEBUG:  pg_database: vac: 3 (threshold 50), anl: 7 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  pg_inherits: vac: 0 (threshold 50), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  pg_index: vac: 0 (threshold 72), anl: 0 (threshold 61)
2014-07-02 10:36:49 CDT DEBUG:  pg_operator: vac: 0 (threshold 191), anl: 0 (threshold 121)
2014-07-02 10:36:49 CDT DEBUG:  pg_opfamily: vac: 0 (threshold 64), anl: 0 (threshold 57)
2014-07-02 10:36:49 CDT DEBUG:  pg_opclass: vac: 0 (threshold 73), anl: 0 (threshold 61)
2014-07-02 10:36:49 CDT DEBUG:  pg_amop: vac: 0 (threshold 122), anl: 0 (threshold 86)
2014-07-02 10:36:49 CDT DEBUG:  pg_amproc: vac: 0 (threshold 100), anl: 0 (threshold 75)
2014-07-02 10:36:49 CDT DEBUG:  pg_language: vac: 0 (threshold 51), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  pg_largeobject_metadata: vac: 0 (threshold 50), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  pg_rewrite: vac: 0 (threshold 70), anl: 0 (threshold 60)
2014-07-02 10:36:49 CDT DEBUG:  pg_description: vac: 0 (threshold 705), anl: 0 (threshold 378)
2014-07-02 10:36:49 CDT DEBUG:  pg_cast: vac: 0 (threshold 89), anl: 0 (threshold 70)
2014-07-02 10:36:49 CDT DEBUG:  pg_namespace: vac: 0 (threshold 51), anl: 0 (threshold 51)
2014-07-02 10:36:49 CDT DEBUG:  pg_conversion: vac: 0 (threshold 76), anl: 0 (threshold 63)
2014-07-02 10:36:49 CDT DEBUG:  pg_depend: vac: 0 (threshold 1219), anl: 0 (threshold 635)
2014-07-02 10:36:49 CDT DEBUG:  pg_tablespace: vac: 0 (threshold 50), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  pg_pltemplate: vac: 0 (threshold 52), anl: 0 (threshold 51)
2014-07-02 10:36:49 CDT DEBUG:  pg_auth_members: vac: 9 (threshold 75), anl: 37 (threshold 62)
2014-07-02 10:36:49 CDT DEBUG:  pg_shdepend: vac: 100 (threshold 943), anl: 394 (threshold 496)
2014-07-02 10:36:49 CDT DEBUG:  pg_shdescription: vac: 36 (threshold 50), anl: 42 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  pg_ts_config: vac: 0 (threshold 53), anl: 0 (threshold 52)
2014-07-02 10:36:49 CDT DEBUG:  pg_ts_dict: vac: 0 (threshold 53), anl: 0 (threshold 52)
2014-07-02 10:36:49 CDT DEBUG:  pg_ts_parser: vac: 0 (threshold 50), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  pg_ts_template: vac: 0 (threshold 51), anl: 0 (threshold 51)
2014-07-02 10:36:49 CDT DEBUG:  pg_extension: vac: 0 (threshold 50), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  pg_foreign_data_wrapper: vac: 0 (threshold 50), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  pg_foreign_server: vac: 0 (threshold 50), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  pg_default_acl: vac: 0 (threshold 50), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  pg_seclabel: vac: 0 (threshold 50), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  pg_collation: vac: 0 (threshold 51), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  <TABLENAMEHERE>: vac: 0 (threshold 50), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  pg_attrdef: vac: 0 (threshold 50), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  <TABLENAMEHERE>: vac: 0 (threshold 50), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  pg_db_role_setting: vac: 0 (threshold 50), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  <TABLENAMEHERE>: vac: 0 (threshold 104), anl: 0 (threshold 77)
2014-07-02 10:36:49 CDT DEBUG:  <TABLENAMEHERE>: vac: 0 (threshold 50), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  <TABLENAMEHERE>: vac: 0 (threshold 50), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  <TABLENAMEHERE>: vac: 0 (threshold 96), anl: 0 (threshold 73)
2014-07-02 10:36:49 CDT DEBUG:  <TABLENAMEHERE>: vac: 0 (threshold 50), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  <TABLENAMEHERE>: vac: 0 (threshold 50), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  <TABLENAMEHERE>: vac: 0 (threshold 83), anl: 0 (threshold 67)
2014-07-02 10:36:49 CDT DEBUG:  <TABLENAMEHERE>: vac: 0 (threshold 50), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  <TABLENAMEHERE>: vac: 0 (threshold 104), anl: 0 (threshold 77)
2014-07-02 10:36:49 CDT DEBUG:  <TABLENAMEHERE>: vac: 0 (threshold 134), anl: 0 (threshold 92)
2014-07-02 10:36:49 CDT DEBUG:  <TABLENAMEHERE>: vac: 0 (threshold 50), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  <TABLENAMEHERE>: vac: 0 (threshold 82), anl: 0 (threshold 66)
2014-07-02 10:36:49 CDT DEBUG:  <TABLENAMEHERE>: vac: 0 (threshold 71), anl: 0 (threshold 61)
2014-07-02 10:36:49 CDT DEBUG:  <TABLENAMEHERE>: vac: 0 (threshold 50), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  <TABLENAMEHERE>: vac: 0 (threshold 80), anl: 0 (threshold 65)
2014-07-02 10:36:49 CDT DEBUG:  <TABLENAMEHERE>: vac: 0 (threshold 50), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  <TABLENAMEHERE>: vac: 0 (threshold 50), anl: 0 (threshold 50)
2014-07-02 10:36:49 CDT DEBUG:  <TABLENAMEHERE>: vac: 0 (threshold 826), anl: 0 (threshold 438)
2014-07-02 10:36:49 CDT DEBUG:  CommitTransaction
2014-07-02 10:36:49 CDT DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
2014-07-02 10:36:49 CDT DEBUG:  shmem_exit(0): 8 callbacks to make
2014-07-02 10:36:49 CDT DEBUG:  proc_exit(0): 2 callbacks to make
2014-07-02 10:36:49 CDT DEBUG:  exit(0)
2014-07-02 10:36:49 CDT DEBUG:  shmem_exit(-1): 0 callbacks to make
2014-07-02 10:36:49 CDT DEBUG:  proc_exit(-1): 0 callbacks to make
2014-07-02 10:36:49 CDT DEBUG:  reaping dead processes
2014-07-02 10:36:49 CDT DEBUG:  server process (PID 5692) exited with exit code 0
2014-07-02 10:36:51 CDT LOG:  could not receive data from client: No connection could be made because the target machine actively refused it.


2014-07-02 10:36:51 CDT FATAL:  SSPI authentication failed for user "<USERNAMEHERE>"
2014-07-02 10:36:51 CDT LOG:  could not send data to client: No connection could be made because the target machine actively refused it.


2014-07-02 10:36:51 CDT DEBUG:  shmem_exit(1): 7 callbacks to make
2014-07-02 10:36:51 CDT DEBUG:  proc_exit(1): 3 callbacks to make
2014-07-02 10:36:51 CDT DEBUG:  exit(1)
2014-07-02 10:36:51 CDT DEBUG:  shmem_exit(-1): 0 callbacks to make
2014-07-02 10:36:51 CDT DEBUG:  proc_exit(-1): 0 callbacks to make
2014-07-02 10:36:51 CDT DEBUG:  reaping dead processes
2014-07-02 10:36:51 CDT DEBUG:  server process (PID 4300) exited with exit code 1

I've recently been debugging some SysWow64-related issues with psqlODBC. I wouldn't be entirely surprised if this was another one. As for the 64-bit driver - you *cannot* use the 64-bit ODBC driver with a 32-bit executable, and aFAIK there is no 64-bit VB6 runtime, it only runs on SysWow64 as a 32-bit app under 64-bit windows. In your position I would be (a) updating to a less prehistoric PostgreSQL release, at least the current 9.1 patch release; (b) Enabling psqlODBC driver tracing ("mylog") and looking at the logs; (c) Using wireshark to look at the on-the-wire data exchange. — Craig Ringer, Jun 28 '14 at 04:13
Also - you didn't mention your psqlODBC version. What version are you running? Install the latest 09.03.0300 driver MSI (32- and 64-bit versions) and try again. — Craig Ringer, Jun 28 '14 at 04:14
**@Craig** - Thank you for your feedback, and sorry for the delay in response. At first, we were using an older version of the psqlODBC connector, but I've installed the latest version with no change in the SSPI behavior. As for the 64-bit issues you mentioned, I was afraid that I might run into such an issue, but it was a thought I had while trying to come up with a solution. I will look into the possibility of upgrading the PostgreSQL version we're running. — G_Hosa_Phat, Jun 30 '14 at 13:41
Well - the first thing to do is capture logs of the connection with both system odbc logging and psqlODBC's own logging ("mylog") enabled... — Craig Ringer, Jun 30 '14 at 14:41
Okay, so I changed the connection string to add the debugging flags, recompiled and had a user try again, and I was able to get the mylog file from that computer. I took a quick look through it but I'm not entirely sure what I'm looking for. The last five lines, after it shows that it's "gonna do authentication" read as follows: Line 71 - `Lasterror=10035`, Line 72 - `read 9, global_socket_buffersize=4096`, Line 73 - `auth got 'R'`, Line 74 - `areq = 9 salt=0000000000`, Line 75 - `in AUTH_REQ_SSPI` — G_Hosa_Phat, Jul 01 '14 at 14:03
Sorry 'bout that. I've edited the question and added both logs (mylog and psqlodbc). — G_Hosa_Phat, Jul 01 '14 at 14:47
Weird. It sees an SSPI auth req (message 'R' with type 9 is sspi auth req on the wire protocol per http://www.postgresql.org/docs/9.3/static/protocol-message-formats.html) ... then just *stops*. I'd be using wireshark at this point or building debug versions of the odbc driver and attaching a debugger. — Craig Ringer, Jul 01 '14 at 15:09
Anything in the server error log? What about with `log_min_messages = debug1` ? — Craig Ringer, Jul 01 '14 at 15:09
I've posted the server logs from around the time of my testing last night. As for using Wireshark, I've not ever used this, although I'd be happy to look at anything that would help in getting to an actual resolution. I'll see about turning on the server debugging when I have a minute and try to do some more testing. — G_Hosa_Phat, Jul 01 '14 at 15:46
So, I changed the postgresql.conf to use `log_min_messages = debug1` as you suggested, and tested again. It still didn't show anything different than without the debugging mode turned on. I then bumped it up to `log_min_messages = debug5` and tested. There still doesn't really seem to be that much more information about the actual issue in the log files. I've edited the post again to include the log results. — G_Hosa_Phat, Jul 02 '14 at 15:54
Darn. Sorry - the next step is a network protocol capture to see what's happening on the wire. Since you're on Windows, you don't have a real loopback TCP interface like very other operating system does. So you can either (a) do SSPI to another system over the network, or (b) use `rawcap` (http://www.netresec.com/?page=RawCap ) to create a capture by sniffing local traffic, then open that with wireshark. Wireshark has a PostgreSQL protocol decoder so it should be pretty easy to follow the conversation with reference to the protocol documentation. — Craig Ringer, Jul 02 '14 at 15:56
Oh, I also just noticed this in the very recent git history of the driver, after release 09030300. http://git.postgresql.org/gitweb/?p=psqlodbc.git;a=commit;h=41993dbed1308c019a6e14152adf75162b3386fe . It could be relevant. — Craig Ringer, Jul 03 '14 at 04:35
**@CraigRinger** - Thank you again for all of your help, and I'm sorry for taking so long to respond. Looking at that entry in the git, it refers to "a local Windows user trying to connect to postgres instance on same host". I'm not sure whether that means a local user on the system running the PostgreSQL server, but it does sound an awful lot like what's going on here. I haven't had an opportunity to do any traffic monitoring, but honestly, all of this is telling me at this point that I'm going to have to wait for an updated psqlODBC driver to get an actual resolution. — G_Hosa_Phat, Jul 09 '14 at 19:21
The docs on the psqlODBC website for compiling on Windows are a bit outdated, but I just updated the ones in git. Just install msysgit, `git clone git://git.postgresql.org/git/psqlodbc.git`, and see `docs/` for windows compile info. You only need Visual Studio Express. — Craig Ringer, Jul 10 '14 at 06:06
Sorry for being such a moron, but I'm not a C programmer, and I've never used Git before. I installed msysgit and pulled down a clone. I opened the solution (VS 2008 Pro) and tried to compile, and got errors indicating the file `libpq-fe.h` was missing, so I went and found a copy of that file from my server, copied it into the project folder and added it to the project through the IDE, but the same error came up until I changed all of the include lines for this file to `#include "libpq-fe.h"` (instead of `#include `). continued... — G_Hosa_Phat, Jul 14 '14 at 17:03
Another reference to `postgres_ext.h` changed, and then it's on to the failed references for OpenSSL header files. I haven't installed OpenSSL on my machine yet, but I'm still working on getting all of these references cleared up just so I can test this. I'm beginning to think that it may not be worth the time for me right now, considering I have a "band-aid" workaround solution, and will hopefully be migrating all of these applications to .NET (using Npgsql, which doesn't appear to have any issues with SSPI) soon. — G_Hosa_Phat, Jul 14 '14 at 17:07
I think the visual studio project is outdated. Use the powershell scripts in winbuild\ — Craig Ringer, Jul 14 '14 at 23:46

score 1 · Answer 1 · answered Aug 26 '15 at 16:00

1

Have you checked the case for your login "USERNAMEHERE" ?

The login must be identical on windows and pgsql.

We even have an issue where the windows login is 'usera' and the pgsql login is 'usera' but the login sent through odbc is 'Usera'.

It seems that windows takes what you used to log in as username instead of what's defined in the AD.

We have to manually fix the connectionstring for this one.

Otherwise, you don't need to have a hard-coded login, you could use a mapping in the pg_hba.conf. (see http://www.postgresql.org/docs/9.4/static/auth-username-maps.html)

answered Aug 26 '15 at 16:00

JMG

111
2
3

Thank you for your suggestion. For this issue I finally just decided to go with a hard-coded set of credentials to the database. I had checked the username case, and even built a routine to get the exact login name as it appears in Active Directory to ensure I was passing it in correctly. I didn't really want to go through the process of setting up the mapping since I already have the SSPI working in all of my .NET applications, so I'm just going to drop back and punt on this one. Hopefully I'll be able to rebuild this application in .NET soon, and this whole question will be moot. – G_Hosa_Phat Aug 28 '15 at 15:05

PostgreSQL ODBC Connection SSPI Authentication Failure

1 Answers1