mkleehammer / pyodbc

Python ODBC bridge
https://github.com/mkleehammer/pyodbc/wiki
MIT No Attribution
2.92k stars 563 forks source link

Connection using Tibco driver fetches only first row and segfaults on subsequent ones #1018

Closed tamersalama closed 2 years ago

tamersalama commented 2 years ago

Environment

Partial print_library_info() output (more further below)

python:  3.9.9 | packaged by conda-forge | (main, Dec 20 2021, 02:40:17)
[GCC 9.4.0]
pyodbc:  4.0.32 /home/<user>/miniforge3/envs/<env>/lib/python3.9/site-packages/pyodbc.cpython-39-x86_64-linux-gnu.so
odbc:    03.52
driver:  TIBCO(R) Data Virtualization ODBC Driver 8.5.0.00
         supports ODBC version 03.50
os:      Linux
unicode: Py_Unicode=4 SQLWCHAR=2
$> osbcinst -j

unixODBC 2.3.9
DRIVERS............: /etc/
SYSTEM DATA SOURCES: /etc/odbc.ini
FILE DATA SOURCES..: /etc/ODBCDataSources
USER DATA SOURCES..: /home/<user>/.odbc.ini
SQLULEN Size.......: 8
SQLLEN Size........: 8
SQLSETPOSIROW Size.: 8

not quite clear why unixODBC is not displaying the /etc/odbcinst.ini file - but the driver is defined there.

Issue

Expected Behavior:

call to cursor.fetchall() or multiple calls to cursor.fetchone() to not cause segmentation fault and return appropriate data. I'm not clear on where the segmentation fault is returned, from a failed SQLFetch or from a subsequent attempt at reading the message returned by the driver.

Observed Behavior:

Python segmentation fault caused when calling cursor.fetchall() or multiple calls to cursor.fetchone(). The first call to cursor.fetchone() succeeds and returns expected records.

Sample Code

import pyodbc
import time

connection = {
    'driver': '{composite85_x64}',
    'server': '<server>',
    'port': '9401',
    'dataSource': 'fds',
    'domain': 'hq',
    'TREATCHARASUNICODE': 'true',
    'uid': '<username>',
    'pwd': '<password>',
    'traceFile': f'/home/<user>/logs/trace_{time.time()}.log',
    'traceLevel': 'all'
}
connection_str = ';'.join(['='.join(kv) for kv in connection.items()])

conn = pyodbc.connect(connection_str, autocommit=True)
conn.setencoding(encoding='utf-8')
conn.setdecoding(pyodbc.SQL_CHAR, encoding='utf-8')
conn.setdecoding(pyodbc.SQL_WCHAR, encoding='utf-8')
# conn.setdecoding(pyodbc.SQL_WMETADATA, encoding='utf-16')
cur = conn.cursor()
cur.execute("select TOP 2 * FROM Maintenance.Forelog_History")
rows = cur.fetchall()
[r for r in rows]

The above causes segmentation fault on cur.fetchall() line

LOGS

driver_trace.log unixODBC.log

tamersalama commented 2 years ago

print_library_info() fails on the second cursor.fetchone() call (trying to fetch getTypeInfo for a SQL type.

import sys, os, platform, time
import pyodbc

def print_library_info(cnx):
    print('python:  %s' % sys.version)
    print('pyodbc:  %s %s' % (pyodbc.version, os.path.abspath(pyodbc.__file__)))
    print('odbc:    %s' % cnx.getinfo(pyodbc.SQL_ODBC_VER))
    print('driver:  %s %s' % (cnx.getinfo(pyodbc.SQL_DRIVER_NAME), cnx.getinfo(pyodbc.SQL_DRIVER_VER)))
    print('         supports ODBC version %s' % cnx.getinfo(pyodbc.SQL_DRIVER_ODBC_VER))
    print('os:      %s' % platform.system())
    print('unicode: Py_Unicode=%s SQLWCHAR=%s' % (pyodbc.UNICODE_SIZE, pyodbc.SQLWCHAR_SIZE))
    cursor = cnx.cursor()
    for typename in ['VARCHAR', 'WVARCHAR', 'BINARY']:
        t = getattr(pyodbc, 'SQL_' + typename)
        cursor.getTypeInfo(t)
        row = cursor.fetchone()
        print('Max %s = %s' % (typename, row and row[2] or '(not supported)'))

connection = {
    'driver': '{composite85_x64}',
    'server': '<server>',
    'port': '9401',
    'dataSource': 'fds',
    'domain': 'hq',
    'TREATCHARASUNICODE': 'true',
    'uid': '<username>',
    'pwd': '<password>',
    'traceFile': f'/home/<user>/logs/trace_{time.time()}.log',
    'traceLevel': 'all'
}
connection_str = ';'.join(['='.join(kv) for kv in connection.items()])

conn = pyodbc.connect(connection_str, autocommit=True)
conn.setencoding(encoding='utf-8')
conn.setdecoding(pyodbc.SQL_CHAR, encoding='utf-8')
conn.setdecoding(pyodbc.SQL_WCHAR, encoding='utf-8')

print_library_info(conn)

Seg Faults after partial printing

python:  3.9.9 | packaged by conda-forge | (main, Dec 20 2021, 02:40:17)
[GCC 9.4.0]
pyodbc:  4.0.32 /home/<user>/miniforge3/envs/<env>/lib/python3.9/site-packages/pyodbc.cpython-39-x86_64-linux-gnu.so
odbc:    03.52
driver:  TIBCO(R) Data Virtualization ODBC Driver 8.5.0.00
         supports ODBC version 03.50
os:      Linux
unicode: Py_Unicode=4 SQLWCHAR=2
Max VARCHAR = 256
Segmentation fault

The segmentation fault happens on the second call to cursor.fetchone()

Logs

unixODBC.log driver_trace.log

tamersalama commented 2 years ago

unixODBC isql and iusql

isql is capable of connecting and retrieving all records through a DSN to the data source. iusql on the other hand causes a [ISQL]ERROR: Could not SQLDriverConnect (without a W).

v-chojas commented 2 years ago

Attach a debugger and post a stack trace when it segfaults. I suspect this could be a bug in the ODBC driver.

gordthompson commented 2 years ago

@tamersalama - For better readability please upload large log files as attachments rather than posting them inline.

tamersalama commented 2 years ago

Running the same code with gdb for backtracing

import pyodbc
import time

connection = {
    'driver': '{composite85_x64}',
    'server': '<server>',
    'port': '9401',
    'dataSource': 'fds',
    'domain': 'hq',
    'TREATCHARASUNICODE': 'true',
    'uid': '<username>',
    'pwd': '<password>',
    'traceFile': f'/home/<user>/logs/trace_{time.time()}.log',
    'traceLevel': 'all'
}
connection_str = ';'.join(['='.join(kv) for kv in connection.items()])

conn = pyodbc.connect(connection_str, autocommit=True)
conn.setencoding(encoding='utf-8')
conn.setdecoding(pyodbc.SQL_CHAR, encoding='utf-8')
conn.setdecoding(pyodbc.SQL_WCHAR, encoding='utf-8')
# conn.setdecoding(pyodbc.SQL_WMETADATA, encoding='utf-16')
cur = conn.cursor()
cur.execute("select TOP 2 * FROM Maintenance.Forelog_History")
rows = cur.fetchall()
[r for r in rows]
(gdb) backtrace
#0  0x0000555555739d6a in _PyEval_EvalFrameDefault () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/ceval.c:3524
#1  0x000055555568d250 in _PyEval_EvalFrame (throwflag=0, f=0x55555599f7c0, tstate=0x555555948110)
    at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Include/internal/pycore_ceval.h:40
#2  _PyEval_EvalCode () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/ceval.c:4327
#3  0x0000555555773a97 in _PyEval_EvalCodeWithName (_co=<optimized out>, globals=<optimized out>, locals=<optimized out>, args=<optimized out>, argcount=argcount@entry=0,
    kwnames=<optimized out>, kwargs=0x0, kwcount=0, kwstep=2, defs=0x0, defcount=0, kwdefs=0x0, closure=0x0, name=0x0, qualname=0x0)
    at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/ceval.c:4359
#4  0x0000555555773ad9 in PyEval_EvalCodeEx () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/ceval.c:4375
#5  0x0000555555773afb in PyEval_EvalCode (co=co@entry=0x7ffff7e4dd40, globals=globals@entry=0x7ffff7f1ca00, locals=locals@entry=0x7ffff7f1ca00)
    at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/ceval.c:826
#6  0x00005555557a5d69 in run_eval_code_obj () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/pythonrun.c:1221
#7  0x00005555557e11d4 in run_mod () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/pythonrun.c:1242
#8  0x0000555555668934 in pyrun_file (fp=0x55555597c130, filename=0x7ffff7eec4e0, start=257, globals=0x7ffff7f1ca00, locals=0x7ffff7f1ca00, closeit=1, flags=0x7fffffffe048)
    at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/pythonrun.c:1140
#9  0x00005555557e7442 in pyrun_simple_file (flags=0x7fffffffe048, closeit=1, filename=0x7ffff7eec4e0, fp=0x55555597c130)
    at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/pythonrun.c:450
#10 PyRun_SimpleFileExFlags () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/pythonrun.c:483
#11 0x00005555557e755b in PyRun_AnyFileExFlags () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/pythonrun.c:92
#12 0x00005555557e7b1c in pymain_run_file (cf=0x7fffffffe048, config=0x555555946760)
    at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Modules/main.c:377
#13 pymain_run_python (exitcode=0x7fffffffe040) at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Modules/main.c:602
#14 Py_RunMain () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Modules/main.c:681
#15 0x00005555557e7c20 in pymain_main () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Modules/main.c:1070
#16 0x00005555557e7c69 in Py_BytesMain (argc=<optimized out>, argv=<optimized out>)
    at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Modules/main.c:1094
#17 0x00007ffff6f02555 in __libc_start_main () from /lib64/libc.so.6
#18 0x0000555555760b51 in _start () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/pyarena.c:118

odbc_log.log driver_trace_1643386518.7425764.log

tamersalama commented 2 years ago

The second script (erroring at cursor.getTypeInfo()) has a more meaningful backtrace

import sys, os, platform, time
import pyodbc

def print_library_info(cnx):
    print('python:  %s' % sys.version)
    print('pyodbc:  %s %s' % (pyodbc.version, os.path.abspath(pyodbc.__file__)))
    print('odbc:    %s' % cnx.getinfo(pyodbc.SQL_ODBC_VER))
    print('driver:  %s %s' % (cnx.getinfo(pyodbc.SQL_DRIVER_NAME), cnx.getinfo(pyodbc.SQL_DRIVER_VER)))
    print('         supports ODBC version %s' % cnx.getinfo(pyodbc.SQL_DRIVER_ODBC_VER))
    print('os:      %s' % platform.system())
    print('unicode: Py_Unicode=%s SQLWCHAR=%s' % (pyodbc.UNICODE_SIZE, pyodbc.SQLWCHAR_SIZE))
    cursor = cnx.cursor()
    for typename in ['VARCHAR', 'WVARCHAR', 'BINARY']:
        t = getattr(pyodbc, 'SQL_' + typename)
        cursor.getTypeInfo(t)
        row = cursor.fetchone()
        print('Max %s = %s' % (typename, row and row[2] or '(not supported)'))

connection = {
    'driver': '{composite85_x64}',
    'server': '<server>',
    'port': '9401',
    'dataSource': 'fds',
    'domain': 'hq',
    'TREATCHARASUNICODE': 'true',
    'uid': '<username>',
    'pwd': '<password>',
    'traceFile': f'/home/<user>/logs/trace_{time.time()}.log',
    'traceLevel': 'all'
}
connection_str = ';'.join(['='.join(kv) for kv in connection.items()])

conn = pyodbc.connect(connection_str, autocommit=True)
conn.setencoding(encoding='utf-8')
conn.setdecoding(pyodbc.SQL_CHAR, encoding='utf-8')
conn.setdecoding(pyodbc.SQL_WCHAR, encoding='utf-8')

print_library_info(conn)
(gdb) backtrace
#0  0x00007ffff6f627b4 in _int_malloc () from /lib64/libc.so.6
#1  0x00007ffff6f6578c in malloc () from /lib64/libc.so.6
#2  0x00007ffff089a3be in ReadVarColumn(Cursor*, long, short, bool&, unsigned char*&, long&) [clone .constprop.0] ()
   from /home/<user>/miniforge3/envs/<env>/lib/python3.9/site-packages/pyodbc.cpython-39-x86_64-linux-gnu.so
#3  0x00007ffff089a64d in GetText(Cursor*, long) () from /home/<user>/miniforge3/envs/<env>/lib/python3.9/site-packages/pyodbc.cpython-39-x86_64-linux-gnu.so
#4  0x00007ffff089a8e8 in GetData(Cursor*, long) () from /home/<user>/miniforge3/envs/<env>/lib/python3.9/site-packages/pyodbc.cpython-39-x86_64-linux-gnu.so
#5  0x00007ffff0896430 in Cursor_fetch(Cursor*) () from /home/<user>/miniforge3/envs/<env>/lib/python3.9/site-packages/pyodbc.cpython-39-x86_64-linux-gnu.so
#6  0x00007ffff0896beb in Cursor_fetchone(_object*, _object*) ()
   from /home/<user>/miniforge3/envs/<env>/lib/python3.9/site-packages/pyodbc.cpython-39-x86_64-linux-gnu.so
#7  0x00005555556ef2d0 in method_vectorcall_NOARGS () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Objects/descrobject.c:436
#8  0x000055555573597a in _PyObject_VectorcallTstate (kwnames=0x0, nargsf=<optimized out>, args=0x555555a892f0, callable=0x7ffff09259f0, tstate=0x555555948110)
    at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Include/cpython/abstract.h:127
#9  PyObject_Vectorcall (kwnames=0x0, nargsf=<optimized out>, args=0x555555a892f0, callable=0x7ffff09259f0)
    at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Include/cpython/abstract.h:127
#10 call_function (kwnames=0x0, oparg=<optimized out>, pp_stack=<synthetic pointer>, tstate=0x555555948110)
    at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/ceval.c:5075
#11 _PyEval_EvalFrameDefault () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/ceval.c:3504
#12 0x00005555556f576a in _PyEval_EvalFrame (throwflag=0, f=0x555555a89150, tstate=0x555555948110)
    at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Objects/object.c:1822
#13 function_code_fastcall (globals=0x7ffff7f1ca00, nargs=<optimized out>, args=<optimized out>, co=<optimized out>, tstate=0x555555948110)
    at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Objects/call.c:330
#14 _PyFunction_Vectorcall () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Objects/call.c:367
#15 0x000055555573572d in _PyObject_VectorcallTstate (kwnames=0x0, nargsf=<optimized out>, args=0x55555599f930, callable=0x7ffff7e5b4c0, tstate=0x555555948110)
    at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Include/cpython/abstract.h:127
#16 PyObject_Vectorcall (kwnames=0x0, nargsf=<optimized out>, args=0x55555599f930, callable=0x7ffff7e5b4c0)
    at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Include/cpython/abstract.h:127
#17 call_function (kwnames=0x0, oparg=<optimized out>, pp_stack=<synthetic pointer>, tstate=0x555555948110)
    at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/ceval.c:5075
#18 _PyEval_EvalFrameDefault () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/ceval.c:3518
#19 0x000055555568d250 in _PyEval_EvalFrame (throwflag=0, f=0x55555599f7c0, tstate=0x555555948110)
    at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Include/internal/pycore_ceval.h:40
#20 _PyEval_EvalCode () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/ceval.c:4327
#21 0x0000555555773a97 in _PyEval_EvalCodeWithName (_co=<optimized out>, globals=<optimized out>, locals=<optimized out>, args=<optimized out>, argcount=argcount@entry=0,
    kwnames=<optimized out>, kwargs=0x0, kwcount=0, kwstep=2, defs=0x0, defcount=0, kwdefs=0x0, closure=0x0, name=0x0, qualname=0x0)
    at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/ceval.c:4359
#22 0x0000555555773ad9 in PyEval_EvalCodeEx () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/ceval.c:4375
#23 0x0000555555773afb in PyEval_EvalCode (co=co@entry=0x7ffff7e4d660, globals=globals@entry=0x7ffff7f1ca00, locals=locals@entry=0x7ffff7f1ca00)
    at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/ceval.c:826
#24 0x00005555557a5d69 in run_eval_code_obj () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/pythonrun.c:1221
#25 0x00005555557e11d4 in run_mod () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/pythonrun.c:1242
#26 0x0000555555668934 in pyrun_file (fp=0x55555597c130, filename=0x7ffff7eec4e0, start=257, globals=0x7ffff7f1ca00, locals=0x7ffff7f1ca00, closeit=1, flags=0x7fffffffe048)
    at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/pythonrun.c:1140
#27 0x00005555557e7442 in pyrun_simple_file (flags=0x7fffffffe048, closeit=1, filename=0x7ffff7eec4e0, fp=0x55555597c130)
    at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/pythonrun.c:450
#28 PyRun_SimpleFileExFlags () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/pythonrun.c:483
#29 0x00005555557e755b in PyRun_AnyFileExFlags () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/pythonrun.c:92
#30 0x00005555557e7b1c in pymain_run_file (cf=0x7fffffffe048, config=0x555555946760)
    at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Modules/main.c:377
#31 pymain_run_python (exitcode=0x7fffffffe040) at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Modules/main.c:602
#32 Py_RunMain () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Modules/main.c:681
#33 0x00005555557e7c20 in pymain_main () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Modules/main.c:1070
#34 0x00005555557e7c69 in Py_BytesMain (argc=<optimized out>, argv=<optimized out>)
    at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Modules/main.c:1094
#35 0x00007ffff6f02555 in __libc_start_main () from /lib64/libc.so.6
#36 0x0000555555760b51 in _start () at /home/conda/feedstock_root/build_artifacts/python-split_1639967288117/work/Python/pyarena.c:118
v-chojas commented 2 years ago

What's the actual segfault caused by? I don't see that in your output. Something like "access violation reading/writing xxxx" would show what actually happened. If/when it does do that, run x/i $rip and you'll see the exact instruction that caused it.

tamersalama commented 2 years ago

@v-chojas is this what you mean?

(gdb) x $rip
0x7ffff6f627b4 <_int_malloc+2100>:      0x18683b4c
v-chojas commented 2 years ago

x/i $rip will show the faulting instruction. The fact that it's happening inside a malloc suggests something was corrupted before.

tamersalama commented 2 years ago

We received a recommendation from the Tibco support to use the driver 8.4 (with Hotfix 3) instead of the 8.5. It now works as expected (without a segmentation fault). We are waiting to see if we have a better understanding of what causes the segmentation fault in the more recent versions.

Here's the reference code (again using the 8.4 driver with HF3):


import pyodbc

connection = {
    'driver': '{composite84_x64}',
    'server': '<server>',
    'port': '9401',
    'dataSource': 'fds',
    'domain': 'hq',
    'uid': '<username>',
    'pwd': '<password>',
    'locale': 'utf8',
}
connection_str = ';'.join(['='.join(kv) for kv in connection.items()])

conn = pyodbc.connect(connection_str)
conn.setencoding(encoding='utf-8')
conn.setdecoding(pyodbc.SQL_CHAR, encoding='utf-8')
conn.setdecoding(pyodbc.SQL_WCHAR, encoding='utf-8')
# conn.setdecoding(pyodbc.SQL_WMETADATA, encoding='utf-8')
cur = conn.cursor()
cur.execute("select TOP 200 * FROM <database>.<table>")
rows = cur.fetchall()
[r for r in rows]