PRINT messages from triggers not being returned when SET NOCOUNT is ON

[hb2638]

Please first make sure you have looked at:

• Documentation: https://github.com/mkleehammer/pyodbc/wiki
• Other issues

Environment

To diagnose, we usually need to know the following, including version numbers. On Windows, be sure to specify 32-bit Python or 64-bit:

• Python: 3.11
• pyodbc: 4.0.39
• OS: Windows
• DB: SQL Server 2019
• driver: ODBC Driver 18 for SQL Server 2018.181.02.01

Issue

The cursor.messages is always empty in the below code because of the SET NOCOUNT ON statemen but I see the PRINT statement when I run it in Microsoft SQL Studio Manager. I believe it's because you're not calling SQLGetDiagRec when you get SQL_NO_DATA_FOUND.

According to Return Codes ODBC. The application should call SQLGetDiagRec or SQLGetDiagField to retrieve additional information when it gets the following return codes.

• SQL_SUCCESS
• SQL_SUCCESS_WITH_INFO
• SQL_ERROR
• SQL_NO_DATA
• SQL_NEED_DATA
• SQL_STILL_EXECUTING

So please make sure you're calling those functions in those scenarios.

Code to replicate

import logging
import unittest

import pyodbc

log = logging.getLogger(__name__)

class MyTestCase(unittest.TestCase):

    def test_something(self):
        conn_str = "Driver=ODBC Driver 18 for SQL Server;Server=localhost;TrustServerCertificate=yes;Trusted_Connection=yes;APP=tests.utils.TestCase:1022::46840;MARS_Connection=yes;ConnectRetryCount=30"
        conn = pyodbc.connect(conn_str, autocommit=True)
        cursor = conn.execute("DROP TABLE IF EXISTS FOO; CREATE TABLE FOO(ID INT IDENTITY PRIMARY KEY, NAME NVARCHAR(255) NULL);")
        while cursor.nextset():
            cursor.nextset()
        cursor = conn.execute("""
CREATE  TRIGGER [dbo].[trg_FOO] ON FOO
AFTER INSERT
AS
BEGIN
    SET NOCOUNT ON
    --UNCOMMENTING THE BELOW LINE CAUSES PYODBC TO GET THE PRINT STATEMENT
    --SET NOCOUNT OFF
    PRINT 'WOW!!!!'
END
        """)
        cursor.nextset()
        cursor = cursor.execute("INSERT INTO FOO(Name) SELECT NEWID() WHERE 1=0")
        log.info(f"{cursor.messages=}")
        while cursor.nextset():
            log.info(f"{cursor.messages=}")
        log.info(f"{cursor.messages=}")

if __name__ == '__main__':
    unittest.main()

Trace Files

SQL.NO_COUNT_OFF.LOG SQL.NO_COUNT_ON.LOG

[v-chojas]

https://learn.microsoft.com/en-us/sql/odbc/reference/syntax/sqlexecdirect-function?view=sql-server-ver16

"When SQLExecDirect returns either SQL_ERROR or SQL_SUCCESS_WITH_INFO, an associated SQLSTATE value can be obtained by calling SQLGetDiagRec with a HandleType of SQL_HANDLE_STMT and a Handle of StatementHandle. "

It looks like you're getting SQL_NO_DATA_FOUND in the NOCOUNT OFF case, and thus there shouldn't be any diagnostic records to retrieve.

[hb2638]

https://learn.microsoft.com/en-us/sql/odbc/reference/syntax/sqlexecdirect-function?view=sql-server-ver16

"When SQLExecDirect returns either SQL_ERROR or SQL_SUCCESS_WITH_INFO, an associated SQLSTATE value can be obtained by calling SQLGetDiagRec with a HandleType of SQL_HANDLE_STMT and a Handle of StatementHandle. "

It looks like you're getting SQL_NO_DATA_FOUND in the NOCOUNT OFF case, and thus there shouldn't be any diagnostic records to retrieve.

Hi @v-chojas . And that's the bug. You need to call SQLGetDiagRec or SQLGetDiagField when you get SQL_NO_DATA_FOUND .

https://learn.microsoft.com/en-us/sql/odbc/reference/develop-app/return-codes-odbc?view=sql-server-ver16

SQL_NO_DATA | No more data was available. The application calls SQLGetDiagRec or SQLGetDiagField to retrieve additional information. One or more driver-defined status records in class 02xxx may be returned. Note: In ODBC 2.x, this return code was named SQL_NO_DATA_FOUND. -- | --

[v-chojas]

Compare your ODBC traces. There is no message returned in the NOCOUNT ON case.

[hb2638]

Compare your ODBC traces. There is no message returned in the NOCOUNT ON case.

SET NOCOUNT ON returns (SQL_NO_DATA_FOUND) SET NOCOUNT OFF returns (SQL_SUCCESS_WITH_INFO)

It's right there on line 481....

jb_unittest_ru 94d4-5c4c EXIT SQLExecDirectW with return code 100 (SQL_NO_DATA_FOUND) HSTMT 0x00000233B1675550 WCHAR * 0x00000233912BDC50 [ 46] "INSERT INTO FOO(Name) SELECT NEWID() WHERE 1=0" SDWORD 46

VS

_jb_unittest_ru af7c-9efc EXIT SQLExecDirectW with return code 1 (SQL_SUCCESS_WITH_INFO) HSTMT 0x0000029951625550 WCHAR * 0x000002993126DC50 [ 46] "INSERT INTO FOO(Name) SELECT NEWID() WHERE 1=0" SDWORD 46

[gordthompson]

This behaviour appears to be specific to msodbcsql. When I perform the same test with FreeTDS ODBC version 1.3.6, the driver returns SQL_SUCCESS_WITH_INFO instead of SQL_NO_DATA_FOUND when SET NOCOUNT ON is in effect:

[ODBC][5853][1689102033.883672][SQLExecDirectW.c][177]
        Entry:
            Statement = 0x555aa6e48eb0
            SQL = [INSERT INTO FOO(Name) SELECT NEWID() WHERE 1=0][length = 46]
[ODBC][5853][1689102033.898879][SQLExecDirectW.c][456]
        Exit:[SQL_SUCCESS_WITH_INFO]

odbctrace.log

[gordthompson]

Confirmed. On the same (Linux) test machine as above, msodbcsql18 does the following:

SET NOCOUNT ON

[ODBC][3597][1689112136.325880][SQLExecDirectW.c][177]
        Entry:
            Statement = 0x563536a98440
            SQL = [INSERT INTO FOO(Name) SELECT NEWID() WHERE 1=0][length = 46]
[ODBC][3597][1689112136.341876][SQLExecDirectW.c][456]
        Exit:[SQL_NO_DATA]

SET NOCOUNT OFF

[ODBC][3576][1689111788.933062][SQLExecDirectW.c][177]
        Entry:
            Statement = 0x5560348a4440
            SQL = [INSERT INTO FOO(Name) SELECT NEWID() WHERE 1=0][length = 46]
[ODBC][3576][1689111788.945593][SQLExecDirectW.c][456]
        Exit:[SQL_SUCCESS_WITH_INFO]

[hb2638]

This is a pyodbc issue, not a driver issue. Microsoft’s documentation says you need to call SQLGetDiagRec or SQLGetDiagField on almost all response codes, including the no data one. may pyodbc be updated to do that.

[v-chojas]

The driver would return _WITH_INFO if there were diag recs available.

Note that other drivers may even crash if you try to retrieve nonexistent diag recs, and I believe there were some long-standing unixODBC bugs related to that too.

[hb2638]

There are a few ways of solving that

Allow the caller to pass in a flag on whether or not to check the diagnostics based on Microsoft’s documentation

or

Expose the function calls and data structures we need to make so we can make the calls ourselves. I like this because it makes it easier for us to do lower level stuff like changing the cursor timeouts which is another issue I raised.

or

pyodbc can evaluate the engine/driver to determine Microsoft’s documentation should be followed on when to check the diagnostic records

[keitherskine]

Looking at this now...

[gordthompson]

When @v-chojas says

The driver would return _WITH_INFO if there were diag recs available.

it sounds to me like msodbcsql should not be returning SQL_NO_DATA in this case, and FreeTDS OCBC doesn't. That would make it a driver (msodbcsql) issue.

[hb2638]

And perhaps FreeTDS ODBC implemented the ODBC spec incorrectly...

See the Comments section of SQLExecDirect Function

If SQLExecDirect executes a searched update, insert, or delete statement that does not affect any rows at the data source, the call to SQLExecDirect returns SQL_NO_DATA

The code I posted did not affect any rows.

[gordthompson]

perhaps FreeTDS ODBC implemented the ODBC spec incorrectly

Could be, but FWIW the SAP ASE ODBC driver (libsybdrvodb-sqllen8.so on Linux) also returns SQL_SUCCESS_WITH_INFO, like FreeTDS:

[ODBC][11019][1690206010.816353][SQLExecDirectW.c][177]
        Entry:
            Statement = 0x1fdf6d0
            SQL = [INSERT INTO FOO(Name) SELECT NEWID() WHERE 1=0][length = 46]
[ODBC][11019][1690206010.959352][SQLExecDirectW.c][436]
        Exit:[SQL_SUCCESS_WITH_INFO]
        DIAG [ZZZZZ] [SAP][ASE ODBC Driver][Adaptive Server Enterprise]WOW!!!!

[hb2638]

perhaps FreeTDS ODBC implemented the ODBC spec incorrectly

Could be, but FWIW the SAP ASE ODBC driver (libsybdrvodb-sqllen8.so on Linux) also returns SQL_SUCCESS_WITH_INFO, like FreeTDS:

[ODBC][11019][1690206010.816353][SQLExecDirectW.c][177]
        Entry:
            Statement = 0x1fdf6d0
            SQL = [INSERT INTO FOO(Name) SELECT NEWID() WHERE 1=0][length = 46]
[ODBC][11019][1690206010.959352][SQLExecDirectW.c][436]
        Exit:[SQL_SUCCESS_WITH_INFO]
        DIAG [ZZZZZ] [SAP][ASE ODBC Driver][Adaptive Server Enterprise]WOW!!!!

I firmly stand by the ODBC documentation/specs... This is starting to look like javascript/browser wars where everyone did their own thing.

[gordthompson]

If SQLExecDirect executes a searched update, insert, or delete statement that does not affect any rows at the data source, the call to SQLExecDirect returns SQL_NO_DATA

Then shouldn't msodbcsql return SQL_NO_DATA regardless of whether SET ROWCOUNT is ON or OFF? Row counts aren't returned by diag records anyway.

[hb2638]

If SQLExecDirect executes a searched update, insert, or delete statement that does not affect any rows at the data source, the call to SQLExecDirect returns SQL_NO_DATA

Then shouldn't msodbcsql return SQL_NO_DATA regardless of whether SET ROWCOUNT is ON or OFF? Row counts aren't returned by diag records anyway.

touché :^)

I'll fallback to my original point about what the documentation states should be done on various errors codes @ https://learn.microsoft.com/en-us/sql/odbc/reference/develop-app/return-codes-odbc?view=sql-server-ver16 . It states the The application should call SQLGetDiagRec or SQLGetDiagField to retrieve additional information when it gets SQL_NO_DATA.

[keitherskine]

Yes. pyodbc can and should handle this. PR is on it's way.

[gordthompson]

Hi, @keitherskine . Thanks for working on the PR. Alas, I see this as a solution looking for a problem.

The thing is, IMO the SET NOCOUNT statement does not belong in a trigger anyway. Like the SET NOCOUNT docs say (emphasis mine):

[SET NOCOUNT] Controls whether a message that shows the number of rows affected by a Transact-SQL statement or stored procedure is returned after the result set.

In other words, a trigger is not intended to produce row counts or result sets itself, so putting SET NOCOUNT ON in one is sort of meaningless.

I also verified that under 4.0.39 when SET NOCOUNT ON is in effect for an INSERT on a table with a trigger that

• does not mess with SET NOCOUNT, and
• contains a PRINT statement (which also seems a bit dodgy to me),

the message does get returned. That is, with

CREATE  TRIGGER [dbo].[trg_FOO] ON FOO
AFTER INSERT
AS
BEGIN
    PRINT 'WOW!!!!'
END

and

cursor = cursor.execute("SET NOCOUNT ON; INSERT INTO FOO(Name) SELECT NEWID() WHERE 1=0;")

the logging output includes.

INFO:issue_1238:cursor.messages=[('[01000] (0)', '[Microsoft][ODBC Driver 18 for SQL Server][SQL Server]WOW!!!!')]

That, coupled with the comments from @v-chojas …

Note that other drivers may even crash if you try to retrieve nonexistent diag recs, and I believe there were some long-standing unixODBC bugs related to that too.

… I'd be inclined to leave things as they are.

[hb2638]

I'll just quote MSDN from Trigger Limitations on why you would use SET NOCOUNT inside a trigger.

When a trigger fires, results are returned to the calling application, just like with stored procedures. To prevent results being returned to an application because of a trigger firing, don't include either SELECT statements that return results or statements that carry out variable assignment in a trigger. A trigger that includes either SELECT statements that return results to the user or statements that do variable assignment, requires special handling. You'd have to write the returned results into every application in which modifications to the trigger table are allowed. If variable assignment must occur in a trigger, use a SET NOCOUNT statement at the start of the trigger to prevent the return of any result sets.

We can play these games all night Mr Hunter :^)

[keitherskine]

I agree the use of a PRINT statement in a trigger is kinda unusual, but that wasn't the reason for my PR. After pyodbc executes a SQL query, it should retrieve diagnostic messages for more than just the SQL_SUCCESS_WITH_INFO return value, which is what it is doing right now. The SQLExecDirect ODBC function returns multiple return values. My PR simply makes pyodbc retrieve diagnostic messages for more of those return values.

https://learn.microsoft.com/en-us/sql/odbc/reference/syntax/sqlexecdirect-function?view=sql-server-ver16#returns https://learn.microsoft.com/en-us/sql/odbc/reference/develop-app/return-codes-odbc?view=sql-server-ver16

[gordthompson]

Hi @keitherskine . I'm still concerned about @v-chojas 's comment, particularly

Note that other drivers may even crash if you try to retrieve nonexistent diag recs

Sure, maybe that's technically a bug in those other drivers, but I suspect that a lot of those drivers would never be fixed. So we could be causing headaches for those users just for the sake of stricter adherence to the ODBC spec.

We could add a switch to Cursor similar to fast_executemany (i.e., False by default) so the few people with chatty SQL Server triggers could use it if they need it. Something like

crsr.always_get_messages = True

I just have the feeling that SQL_SUCCESS_WITH_INFO and SQL_ERROR are the only results where diag messages are guaranteed to exist. The same doc you cited above even hints at that when it says

When SQLExecDirect returns either SQL_ERROR or SQL_SUCCESS_WITH_INFO, an associated SQLSTATE value can be obtained by calling SQLGetDiagRec

[hb2638]

Hi @keitherskine . I'm still concerned about @v-chojas 's comment, particularly

Note that other drivers may even crash if you try to retrieve nonexistent diag recs

Sure, maybe that's technically a bug in those other drivers, but I suspect that a lot of those drivers would never be fixed. So we could be causing headaches for those users just for the sake of stricter adherence to the ODBC spec.

We could add a switch to Cursor similar to fast_executemany (i.e., False by default) so the few people with chatty SQL Server triggers could use it if they need it. Something like

crsr.always_get_messages = True

I just have the feeling that SQL_SUCCESS_WITH_INFO and SQL_ERROR are the only results where diag messages are guaranteed to exist. The same doc you cited above even hints at that when it says

When SQLExecDirect returns either SQL_ERROR or SQL_SUCCESS_WITH_INFO, an associated SQLSTATE value can be obtained by calling SQLGetDiagRec

SQLGetDiagRec Function - Comments

An application typically calls SQLGetDiagRec when a previous call to an ODBC function has returned SQL_ERROR or SQL_SUCCESS_WITH_INFO. However, because any ODBC function can post zero or more diagnostic records each time it is called, an application can call SQLGetDiagRec after any ODBC function call. An application can call SQLGetDiagRec multiple times to return some or all of the records in the diagnostic data structure. ODBC imposes no limit to the number of diagnostic records that can be stored at any one time.

[gordthompson]

This is getting tedious. Unsubscribed.

[v-chojas]

How about only getting the diag recs when the .messages is retrieved? That should satisfy you while not unnecessarily causing breakage for others whose drivers will crash or end up in a weird state if you try to retrieve nonexistent diag recs.

Also, I recommend not blindly trusting the docs - it is well known that not all drivers behave exactly as they should.

[hb2638]

How about only getting the diag recs when the .messages is retrieved? That should satisfy you while not unnecessarily causing breakage for others whose drivers will crash or end up in a weird state if you try to retrieve nonexistent diag recs.

Also, I recommend not blindly trusting the docs - it is well known that not all drivers behave exactly as they should.

I understand your point @v-chojas on not blindly trusting the doc because some specific version of some driver doesn't follow the spec but stopping new functionality because of that holds everyone else back and this is why there were proposals from @gordthompson and myself on how to work around that.... and I recoginize you're also offering a proposal to mitigate the bug.

I really appreciate the speed at which @keitherskine was able to implement this (with automated tests) but I am taken aback by the amount of resistance it has received on this thread to the point I'm strongly considering forking pyodbc so I can apply @keitherskine along with some other code changes I've been toying with and just work off of that going forward.

If there's concern about a change to make pyodbc more compliant breaks some specific vesion of a driver on some specific version of an os/kernel on some specific version of a database engine.... we'll there should be an automated tests for that. The people affected would report the bug and revert to a previous version of pyodbc and ideally, the latest version of whatever driver they're using wont have this bug, and if it does, it should be reported to maintainers of the driver.

And to bring this all back to triggers and SET NOCONT ON and PRINT

We use PRINT for logging. We have a logging stored proc that generates a PRINT wiith a timestamp, the fully qualified module name of @@PROCID, and the log message and this all gets captured in our python code via the cursors.messages property (when it works).

but on top of that, we have triggers that will copy data to an audit table and doing so will affect/change @@ROWCOUNT unbeknownst to the caller. So we need to use SET NOCOUNT ON to supress that.

This is a very standard approach in the world of Microsoft SQL Server and ths is not convered in my example code as the purpose of the example code was to replicate the behavior and not spend days debating why or why not one should use SET NOTCOUNT ON inside the trigger. That created a distraction from the underlying problem (and the elephant in my room) of pyodbc not calling SQLGetDiagRec and SQLGetDiagField after each ODBC call. At this point, the documentation has this stated in at least 5 different places that pyodbc needs to calling SQLGetDiagRec and SQLGetDiagField more often.

Anyways, thanks again @keitherskine for understanding the importance of this bug and quickly getting a MR through. It will be the starting commit of my fork if the MR is rejected by the pyodbc folks.

[v-chojas]

Perhaps you should first realise why things are the way they are, before saying that they're wrong?

If you looked at the traces you will see that even Windows DM doesn't attempt to extract diag recs unless a call returns error or success with info. Did you ask yourself why that is?

There are plenty of ODBC drivers that are broken in various ways, and that won't ever change. pyODBC has to be careful of that.

As for "holds everyone back" - speak for yourself.

You are always welcome to have your own fork, after all this is open source for a reason.

[mkleehammer]

Thanks everyone for the great detail. I'm going to close this for now due to so many people being concerned about it. I am open to doing something about it, especialy the suggestion about a flag to enable it, just in case.

Please reopen if this is still something someone wants to discuss.