0

Can I capture the output from SQL server PRINT statements called from Python with SQLAlchemy? For background, I am building my client application in Python to connect to a MSSQL server, run stored procedures that emit PRINT statements (an existing codebase), then show some information about progress during a long-running operation or at least log the messages.

CREATE PROCEDURE [dbo].[BigCalculation]
AS
    SET NOCOUNT ON
    PRINT 'Inserting costs and benefits ... Message 1'
    BEGIN
    -- query1
    END
    PRINT 'Inserting costs and benefits ... Message 2'
    BEGIN
    -- query2
    END
    PRINT 'Done with big calculation'

According to previous questions and Transact-SQL documentation, in order to capture the output from a PRINT statement, a client can listen for InfoMessage events. The example is in .NET, and I want to use python.

To start, I am connecting to my MSSQL database with sqlalchemy and pyodbc. I prefer SQLAlchemy because it makes code easy to write and understand.

import sqlalchemy
import pyodbc
print(sqlalchemy.__version__)
print(pyodbc.version)
import urllib
params = urllib.parse.quote_plus("DRIVER={ODBC Driver 17 for SQL Server};"
                                 r"SERVER=LAPPY\SQLEXPRESS;"
                                 "DATABASE=MY_OLD_DATABASE;"
                                 "Trusted_Connection=yes")
my_engine = sqlalchemy.create_engine("mssql+pyodbc:///?odbc_connect={}".format(params))
my_engine

Output:

2.0.20
4.0.39
Engine(mssql+pyodbc:///?odbc_connect=DRIVER%3D%7BODBC+Driver+17+for+SQL+Server%7D%3BSERVER%3DLAPPY%5CSQLEXPRESS%3BDATABASE%3DMY_OLD_DATABASE%3BTrusted_Connection%3Dyes)

Attempt 1.

With SQLAlchemy, I can turn on logging, but I can't find a logging message that includes the output of the PRINT statement.

import logging
logging.basicConfig()
logging.getLogger("sqlalchemy.engine").setLevel(logging.INFO)
with my_engine.begin() as conn:
    conn.execute(text("PRINT 'hello'"))

Output:

2023-08-31 09:43:09,004 INFO sqlalchemy.engine.Engine BEGIN (implicit)
INFO:sqlalchemy.engine.Engine:BEGIN (implicit)
2023-08-31 09:43:09,005 INFO sqlalchemy.engine.Engine PRINT 'hello'
INFO:sqlalchemy.engine.Engine:PRINT 'hello'
2023-08-31 09:43:09,005 INFO sqlalchemy.engine.Engine [cached since 7142s ago] ()
INFO:sqlalchemy.engine.Engine:[cached since 7142s ago] ()
2023-08-31 09:43:09,007 INFO sqlalchemy.engine.Engine COMMIT
INFO:sqlalchemy.engine.Engine:COMMIT

Attempt 2.

With SQLAlchemy, I can listen for events, but asking to listen for InfoMessage raises InvalidRequestError.

from sqlalchemy.event import listen

def mylistener(**kwargs):
    print(kwargs)

listen(engine, 'INFOMESSAGE', mylistener)
#listen(engine, 'infomessage', mylistener)
#listen(engine, 'InfoMessage', mylistener)

with engine.begin() as conn:
    conn.execute(text("PRINT 'hello'"))

Output:

InvalidRequestError: No such event 'INFOMESSAGE' for target 'Engine(mssql+pyodbc:///...)'

Attempt 3.

With DBAPI optional extensions, the raw DBAPI connection might offer Connection.messages or Cursor.messages attributes. But with the pyodbc driver (as in this question), it looks like only the raw cursor is working to capture messages, so I can't get PRINT messages from queries executed through the SQLAlchemy connection wrapper.

with engine.begin() as conn:
    # Execute a "normal" sqlalchemy query
    conn.execute(text("PRINT 'hello1'"))

    # Execute a query on a cursor from the raw connection
    connection = conn.connection
    cursor = connection.cursor()
    print(connection)
    print(cursor)
    cursor.execute("PRINT 'hello2'")

    # Look for messages
    for m in cursor.messages:
        print(m)
    for m in connection.messages:
        print(m)

Output:

<sqlalchemy.pool.base._ConnectionFairy object at 0x0000019AC6D2D660>
<pyodbc.Cursor object at 0x0000019AC89CE930>
('[01000] (0)', '[Microsoft][ODBC Driver 17 for SQL Server][SQL Server]hello2')
AttributeError: 'pyodbc.Connection' object has no attribute 'messages'

So, what is the best approach? Are there any other options?

Edit

The behavior is similar for RAISERROR statements, the only difference being the timing. Here is a sample.

import time
def get_result_and_messages(cursor):
    from datetime import datetime
    print(datetime.utcnow())
    for m in cursor.messages:
        print(m)
    try:
        print(cursor.fetchall())
    except pyodbc.ProgrammingError:
        pass

with engine.begin() as conn:
    # Execute a "normal" sqlalchemy query
    conn.execute(text("PRINT 'hello1'"))
    
    # Execute a query on a cursor from the raw connection
    connection = conn.connection
    cursor = connection.cursor()
    cursor.execute("""
        PRINT 'hello2';
        WAITFOR DELAY '00:00:10'
        RAISERROR('hello3',0,1) WITH NOWAIT;
        WAITFOR DELAY '00:00:10'
        SELECT 'hello4';
        WAITFOR DELAY '00:00:10'
        PRINT 'hello5';
        WAITFOR DELAY '00:00:10'
        """)
    print(get_result_and_messages(cursor))
    while cursor.nextset():
        print(get_result_and_messages(cursor))

Output:

2023-08-31 21:59:28.971460
('[01000] (0)', '[Microsoft][ODBC Driver 17 for SQL Server][SQL Server]hello2')
None
2023-08-31 21:59:29.976399
('[01000] (50000)', '[Microsoft][ODBC Driver 17 for SQL Server][SQL Server]hello3')
None
2023-08-31 21:59:58.987831
[('hello4',)]
None
2023-08-31 21:59:58.988891
('[01000] (0)', '[Microsoft][ODBC Driver 17 for SQL Server][SQL Server]hello5')
None
simularis
  • 53
  • 1
  • 5

0 Answers0