'pyodbc.Error' returned a result with an error set

andre-ricardo-moraes commented 2 years ago

Environment

Python: 3,7
pyodbc: 4.0.32
OS: ubuntu 18.04.6 lts
DB: mssql server
driver: ODBC Driver 17 for SQL Server

Issue

I have a issue with pyodbc that doesn't show the especific cause of error when running tasks python on Apache Airflow. Basicaly I have a python in a task that call pyodbc to execute sql commands on mssql, but in some cases this return failed.

Message Error:

[2022-01-24 12:30:41,756] {taskinstance.py:1239} ERROR - Received SIGTERM. Terminating subprocesses.
[2022-01-24 12:30:41,757] {taskinstance.py:1455} ERROR - <class 'pyodbc.Error'> returned a result with an error set
Traceback (most recent call last):
  File "/usr/lib/python3.7/encodings/utf_16_le.py", line 15, in decode
    def decode(input, errors='strict'):
  File "/usr/local/lib/python3.7/dist-packages/airflow/models/taskinstance.py", line 1241, in signal_handler
    raise AirflowException("Task received SIGTERM signal")
airflow.exceptions.AirflowException: Task received SIGTERM signal

The above exception was the direct cause of the following exception:

airflow.exceptions.AirflowException: decoding with 'utf-16le' codec failed (AirflowException: Task received SIGTERM signal)

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/airflow/models/taskinstance.py", line 1112, in _run_raw_task
    self._prepare_and_execute_task_with_callbacks(context, task)
  File "/usr/local/lib/python3.7/dist-packages/airflow/models/taskinstance.py", line 1285, in _prepare_and_execute_task_with_callbacks
    result = self._execute_task(context, task_copy)
  File "/usr/local/lib/python3.7/dist-packages/airflow/models/taskinstance.py", line 1315, in _execute_task
    result = task_copy.execute(context=context)
  File "/airflow/plugins/mssql_utils.py", line 64, in execute
    cur.execute(self.sql)
SystemError: <class 'pyodbc.Error'> returned a result with an error set

Tests:

I'm having do a lot of tests with options on driver and setdecoding/setencoding, but in all cases I don't see the exactly cause of error. some querys in the same database run correctly, but anothers not.

Questions:

There is any command/parameter on pyodbc to show the return data with error ? Is it a possible error on encoding lib utf-16le ?

Code of connection:

conn = pyodbc.connect(
            f"DRIVER={conn.extra_dejson.get('driver')};SERVER={conn.host},{conn.port};DATABASE={database};UID={conn.login};PWD={conn.password};CHARSET=UTF-16le",
            timeout=60,
        )
        conn.setdecoding(pyodbc.SQL_WCHAR, encoding="utf-16le")
        conn.setencoding(encoding="utf-16le")
        conn.setdecoding(pyodbc.SQL_WMETADATA, encoding="utf-16le")

v-chojas commented 2 years ago

"CHARSET" is not a valid connection string option. The full list can be found here: https://docs.microsoft.com/en-us/sql/connect/odbc/dsn-connection-string-attribute
post an ODBC trace for further assistance.

andre-ricardo-moraes commented 2 years ago

"CHARSET" is not a valid connection string option. The full list can be found here: https://docs.microsoft.com/en-us/sql/connect/odbc/dsn-connection-string-attribute

post an ODBC trace for further assistance.

Hi @v-chojas !

Thanks for your response. The CHARSET is one of many tries that I did... but without effect.

I will try to get the trace... but i don't know how to collect it in docker/GCP because my environment doesn't flex (or I don't know how to do it)

I need to learn about it.... I consider your patient to wait my return, as soon as possible

andre-ricardo-moraes commented 2 years ago

Hi @v-chojas !

Thanks for waiting for my return... the real problem isn't with pyodbc, but in the utf_16_le.py

Do you know any way to see the message error, or how to enable the return on function decode that is called by pyodbc?

def decode(input, errors='strict'):

Curiously.... the command sql that I call is a procedure and its run perfectly on manual execution (by Microsoft SQL Server Management Studio). when we call the command by pyodbc, we receive this error.

Farelkin commented 2 years ago

I have same problem.. But if I make request with pycharm - it's ok. Only from python code I have this exception

Traceback (most recent call last):
  File "/usr/local/lib/python3.5/encodings/utf_16_le.py", line 15, in decode
    def decode(input, errors='strict'):
  File "/usr/local/lib/python3.5/site-packages/billiard/common.py", line 125, in _shutdown_cleanup
    sys.exit(-(256 - signum))
  File "/usr/local/lib/python3.5/site-packages/billiard/pool.py", line 280, in exit
    return _exit()
SystemExit

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/orm/session.py", line 1176, in execute
    bind, close_with_result=True).execute(clause, params or {})
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 948, in execute
    return meth(self, multiparams, params)
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/sql/elements.py", line 269, in _execute_on_connection
    return connection._execute_clauseelement(self, multiparams, params)
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1060, in _execute_clauseelement
    compiled_sql, distilled_params
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1200, in _execute_context
    context)
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1416, in _handle_dbapi_exception
    util.reraise(*exc_info)
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/util/compat.py", line 187, in reraise
    raise value
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
    context)
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/engine/default.py", line 507, in do_execute
    cursor.execute(statement, parameters)
SystemError: <class 'pyodbc.Error'> returned a result with an error set

v-chojas commented 2 years ago

As mentioned above, this does not appear to be a pyODBC problem, but perhaps the data you are attempting to retrieve is not in the expected encoding.

mpf82 commented 2 years ago

We also sometimes see this error in Oracle environments (possibly related: https://github.com/mkleehammer/pyodbc/issues/489)

It only ever happens in case of a DB error (e.g. missing column, missing table), never when retrieving data.

But we cannot reproduce it 100%, so we've wrapped it in a special error handling case and ignore it in our unittests.

Since we're specifically testing cases where the DB should return an error, the 'pyodbc.Error' returned a result with an error set is raised at least once per unittest run when testing against oracle DBs (however it varies which test is affected) - and this error never happend once in our Postgres unittests.

Reading this Stack Overflow answer makes me think it's indeed pyodbc related.

lucaspompeun commented 2 years ago

@andre-ricardo-moraes, you should look for 2 possibles causes:

If you're calling your function inside the file, Airflow doesn't deal with it.
If your query string is correct with you default encoding.

v-chojas commented 2 years ago

Until someone posts an ODBC trace of this scenario it's hard to say concretely what is the problem.

lucaspompeun commented 2 years ago

Until someone posts an ODBC trace of this scenario it's hard to say concretely what is the problem.

That's correct, but we can try, at least, speculate some solutions :D

mpf82 commented 2 years ago

Until someone posts an ODBC trace of this scenario it's hard to say concretely what is the problem.

Here you go.

cnxn = pyodbc.connect(ora_conn_str)
print(sys.version) # 3.9.7 (tags/v3.9.7:1016ef3, Aug 30 2021, 20:19:38) [MSC v.1929 64 bit (AMD64)]
print(pyodbc.version) # 4.0.34
print(cnxn.getinfo(pyodbc.SQL_DM_VER)) # 03.81.19041.0000
print(cnxn.getinfo(pyodbc.SQL_ODBC_VER)) # 03.80.0000
print(cnxn.getinfo(pyodbc.SQL_DBMS_VER)) # 12.02.0010
print(cnxn.getinfo(pyodbc.SQL_DRIVER_VER)) # 19.03.0000
print(cnxn.getinfo(pyodbc.SQL_DRIVER_ODBC_VER)) # 03.52

cursor = cnxn.cursor()
sql = "SELECT !"
while 1:
    try:
        with open(odbc_log_file, 'w'):
            pass
        cursor.execute( sql )
    except Exception as e:
        if("error set" in e.args[0]):
            raise e

Since this is actually invalid SQL, this is the "expected exception":

pyodbc.Error: ('HY000', '[HY000] [Oracle][ODBC][Ora]ORA-00936: Ausdruck fehlt\n (936) (SQLExecDirectW)')

However, sometimes a SystemError is raised instead.

Note that sometimes the returned a result with an error set exception can happen with the very first execute, sometimes it takes some hundred iterations, before it happens.

Traceback:

File "c:\Python39\lib\encodings\utf_16_le.py", line 16, in decode return codecs.utf_16_le_decode(input, errors, True) UnicodeDecodeError: 'utf-16-le' codec can't decode bytes in position 124-125: illegal encoding

The above exception was the direct cause of the following exception:

Traceback (most recent call last): File "test_pyodbc10_error_set.py", line 30, in raise e File "test_pyodbc10_error_set.py", line 27, in cursor.execute( sql ) SystemError: <class 'pyodbc.Error'> returned a result with an error set

ODBC Trace:

test_pyodbc10_e 5df0-52e4   ENTER SQLFreeStmt 
        HSTMT               0x00000255BEBBE030
        UWORD                        0 <SQL_CLOSE>

test_pyodbc10_e 5df0-52e4   EXIT  SQLFreeStmt  with return code 0 (SQL_SUCCESS)
        HSTMT               0x00000255BEBBE030
        UWORD                        0 <SQL_CLOSE>

test_pyodbc10_e 5df0-52e4   ENTER SQLExecDirectW 
        HSTMT               0x00000255BEBBE030
        WCHAR *             0x00000255C15665D0 [       8] "SELECT !"
        SDWORD                     8

test_pyodbc10_e 5df0-52e4   EXIT  SQLExecDirectW  with return code -1 (SQL_ERROR)
        HSTMT               0x00000255BEBBE030
        WCHAR *             0x00000255C15665D0 [       8] "SELECT !"
        SDWORD                     8

        DIAG [HY000] [Oracle][ODBC][Ora]ORA-00936: Ausdruck fehlt
 (936) 

test_pyodbc10_e 5df0-52e4   ENTER SQLGetDiagRecW 
        SQLSMALLINT                  3 <SQL_HANDLE_STMT>
        SQLHANDLE           0x00000255BEBBE030
        SQLSMALLINT                  1 
        SQLWCHAR *          0x0000005DEC9EEEE0
        SQLINTEGER *        0x0000005DEC9EEEB8
        SQLWCHAR *          0x00000255D25DC080 
        SQLSMALLINT               1023 
        SQLSMALLINT *       0x0000005DEC9EEEB0

test_pyodbc10_e 5df0-52e4   EXIT  SQLGetDiagRecW  with return code 0 (SQL_SUCCESS)
        SQLSMALLINT                  3 <SQL_HANDLE_STMT>
        SQLHANDLE           0x00000255BEBBE030
        SQLSMALLINT                  1 
        SQLWCHAR *          0x0000005DEC9EEEE0 [       5] "HY000"
        SQLINTEGER *        0x0000005DEC9EEEB8 (936)
        SQLWCHAR *          0x00000255D25DC080 [      90] "[Oracle][ODBC][Ora]ORA-00936: Ausdruck fehlt\ a\ 0\ f\ 0??????\ 0\ 0??\ 0\ 0\16\18\ 0\ 0???\ 0\ 8\ 0\ 0\ 0?\ 0\ 0\ 0?\ 0\ 0\ 0?\ 0\ 0\ 0\ 0\ 0\ 0\ 0??"
        SQLSMALLINT               1023 
        SQLSMALLINT *       0x0000005DEC9EEEB0 (90)

test_pyodbc10_e 5df0-52e4   ENTER SQLGetDiagRecW 
        SQLSMALLINT                  3 <SQL_HANDLE_STMT>
        SQLHANDLE           0x00000255BEBBE030
        SQLSMALLINT                  2 
        SQLWCHAR *          0x0000005DEC9EEEE0
        SQLINTEGER *        0x0000005DEC9EEEB8
        SQLWCHAR *          0x00000255D25DC080 
        SQLSMALLINT               1023 
        SQLSMALLINT *       0x0000005DEC9EEEB0

test_pyodbc10_e 5df0-52e4   EXIT  SQLGetDiagRecW  with return code 100 (SQL_NO_DATA_FOUND)
        SQLSMALLINT                  3 <SQL_HANDLE_STMT>
        SQLHANDLE           0x00000255BEBBE030
        SQLSMALLINT                  2 
        SQLWCHAR *          0x0000005DEC9EEEE0
        SQLINTEGER *        0x0000005DEC9EEEB8
        SQLWCHAR *          0x00000255D25DC080 
        SQLSMALLINT               1023 
        SQLSMALLINT *       0x0000005DEC9EEEB0

test_pyodbc10_e 5df0-52e4   ENTER SQLFreeStmt 
        HSTMT               0x00000255BEBBE030
        UWORD                        0 <SQL_CLOSE>

test_pyodbc10_e 5df0-52e4   EXIT  SQLFreeStmt  with return code 0 (SQL_SUCCESS)
        HSTMT               0x00000255BEBBE030
        UWORD                        0 <SQL_CLOSE>

test_pyodbc10_e 5df0-52e4   ENTER SQLFreeHandle 
        SQLSMALLINT                  3 <SQL_HANDLE_STMT>
        SQLHANDLE           0x00000255BEBBE030

test_pyodbc10_e 5df0-52e4   EXIT  SQLFreeHandle  with return code 0 (SQL_SUCCESS)
        SQLSMALLINT                  3 <SQL_HANDLE_STMT>
        SQLHANDLE           0x00000255BEBBE030

test_pyodbc10_e 5df0-52e4   ENTER SQLEndTran 
        SQLSMALLINT                  2 <SQL_HANDLE_DBC>
        SQLHANDLE           0x00000255BEBBB490
        SQLSMALLINT                  1 

test_pyodbc10_e 5df0-52e4   EXIT  SQLEndTran  with return code 0 (SQL_SUCCESS)
        SQLSMALLINT                  2 <SQL_HANDLE_DBC>
        SQLHANDLE           0x00000255BEBBB490
        SQLSMALLINT                  1 

test_pyodbc10_e 5df0-52e4   ENTER SQLDisconnect 
        HDBC                0x00000255BEBBB490

test_pyodbc10_e 5df0-52e4   EXIT  SQLDisconnect  with return code 0 (SQL_SUCCESS)
        HDBC                0x00000255BEBBB490

test_pyodbc10_e 5df0-52e4   ENTER SQLFreeHandle 
        SQLSMALLINT                  2 <SQL_HANDLE_DBC>
        SQLHANDLE           0x00000255BEBBB490

test_pyodbc10_e 5df0-52e4   EXIT  SQLFreeHandle  with return code 0 (SQL_SUCCESS)
        SQLSMALLINT                  2 <SQL_HANDLE_DBC>
        SQLHANDLE           0x00000255BEBBB490

I expect the issue to be with SQLWCHAR, so here are other examples where it fails:

SQLWCHAR 0x000001BCEFF5EF40 [ 90] "[Oracle][ODBC][Ora]ORA-00936: Ausdruck fehlt\ a\ 0\ 0\ 0???\ 0???????\ 0???????\ 0???????\ 0???????\ 0????\ 0\ 0" SQLWCHAR 0x0000022D7D9C1270 [ 90] "[Oracle][ODBC][Ora]ORA-00936: Ausdruck fehlt\ a\ 0\10\ 0?\ 0\ 5\ 0\ d\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0?????!\ 0\ 0???\ 0?\ 0\ 0\ 0?\ 0\ 0\ 0\10\ 0\10\ 0?\ 0" SQLWCHAR 0x000002817A70B4E0 [ 90] "[Oracle][ODBC][Ora]ORA-00936: Ausdruck fehlt\ a\ 0?????\ 0????\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0???\ 0????\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0???\ 0??????" SQLWCHAR 0x0000023563BDA900 [ 90] "[Oracle][ODBC][Ora]ORA-00936: Ausdruck fehlt\ a\ 0\ 0\ 0?????!\ 0\ 0???\ 0?\ 0\ 0\ 0?\ 0\ 0\ 0\ 9\ 0\ 8\ 0?\ 1\ 5\ 0\ 6\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0??" SQLWCHAR * 0x000001CD63D8AF80 [ 90] "[Oracle][ODBC][Ora]ORA-00936: Ausdruck fehlt\ a\ 0???\ 0\ 0\ 0\ 0\ 0\ 0\ 0?\ 0\ 0\ 0?\ 0\ 0\ 0\ a\ 0\ 8\ 0\ff\ 0\ 5\ 0\ 6\ 0\ 0\ 0??\ 0\ 0?\ff\ 0\ 0?????!"

Here are "working" examples, maybe comparing them helps, but I guess the original byte code cannot be displayed:

SQLWCHAR 0x000001A98E408430 [ 90] "[Oracle][ODBC][Ora]ORA-00936: Ausdruck fehlt\ a\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0" SQLWCHAR 0x000001A98E40F510 [ 90] "[Oracle][ODBC][Ora]ORA-00936: Ausdruck fehlt\ a\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0\ 0?\ 0?\ 0???\ 0C:\Oracle\WINDOWS.X64_1930" SQLWCHAR 0x000001A98E407C20 [ 90] "[Oracle][ODBC][Ora]ORA-00936: Ausdruck fehlt\ a\ 0\ 1?????\ 1?????\ 1?????\ 1G????????????S???????\ 0\ 0??" SQLWCHAR 0x0000015A384FDD90 [ 90] "[Oracle][ODBC][Ora]ORA-00936: Ausdruck fehlt\ a\ 0???????\ff\ff\ff??????????????????????????????????" SQLWCHAR * 0x0000015A384FAD30 [ 90] "[Oracle][ODBC][Ora]ORA-00936: Ausdruck fehlt\ a\ 0???\ 0?\ 0?\ff\ 0?\ 0?L\ 0?\ 0?\ff\ 0?\ 0?\ 0\ 0???????\ff\ 0c\ 0\ 0\ 0\ 0\ 0\ 0\ 0?\ 0?"

I also suspect this - at least in case of oracle - to be related to https://github.com/mkleehammer/pyodbc/issues/489

I really don't wanna go into the discussion of "pyodbc is doing the correct thing by reading 90 characters instead of 90 bytes", but pyodbc should not fail with a SystemError either - if this is the source for this issue at hand.

v-chojas commented 2 years ago

Definitely driver bug.

mkleehammer / pyodbc