Strange bug (value on stack changed)?

Hi,

I am using the ANSI ODBC driver (version 8.03.04.00, psqlodbc30a.dll)
on Windows XP and found a stack corruption.

My code uses the SQLSetPos to add a row and while this the bug occurs.
My bound columns are all malloc'ed on heap.
Now I am likely would find the reason for this, but have some problems:

My code is compiled with Open Watcom 1.7 and the bug only appears if I
compile with debug information
about the line numbers (-d1) or in release mode. The trouble is how to
debug MSVC driver (DLL) while debugging Watcom client code.

While trying more and more to get useful information for you I found
some interesting information:

The address on the stack that gets overwritten is at 0x0006ED18 and
this address is in the following log at PGAPI_SetStmtAttr.
The stack pointer ESP is about 39 dwords above the address that gets
shoot (smaller addresses are above). At this level I do a check
before calling SQLSetPos and after the call. After the call the stack
at ESP + (39*4 bytes) is shoot.

I have determined that I have a column binding problem with the
SQL_COLUMN_IGNORE flag in the last parameter of SQLBindCol that may
cause
this bug.

So basically I have two rows for each column. One for reading data to
be displayed in my GUI and another to be used to add new rows. This
corresponds
to my mode with is 0 = update and 1 = add.

if (mode == 1) {
retcode = SQLSetPos(hstmt, 2, SQL_ADD, SQL_LOCK_NO_CHANGE);
} else {
retcode = SQLSetPos(hstmt, 1, SQL_UPDATE, SQL_LOCK_NO_CHANGE);
}

It seems that I do not proper unbind the serial column:

ret = SQLBindCol(hstmt, _column, SQL_C_CHAR, NULL, (ColumnSize+1),
cbBufferLength);

While I think the value in add mode (cbBufferLength[1] is not
SQL_COLUMN_IGNORE) and the update mode (cbBufferLength[0]) is unrelated.

Is this correct?

Another question is: Do I have to use a cbBufferLength array or is one
long value enough regardless of having two working rows (update/add)?

But regardless, the shoot should not happen in either circumstance.

After my last test to correct my code at the proper place I do not get
it working in case of automatic binding - eg. bound column that is not
ignored.

At this stage I think, I cannot unbind columns to be ignored for the
next add command. I have to bind it correctly at the first time with
SQL_COLUMN_IGNORE
or it will fail with the shoot. Binding it to the buffer with
SQL_COLUMN_IGNORE also shoots my char array on stack.

I think, there is a bug in rebinding columns that causes a write to
value on stack of the caller of SQLSetPos or simply a crash without my
buffers to work around
for finding the bug. Do you agree?

void LB_STDCALL lbBoundColumn::unbindReadonlyColumns() {
SQLRETURN ret = SQL_SUCCESS;

if (isReadonly) {
if (mode == 1) {
cbBufferLength[1] = SQL_COLUMN_IGNORE; // Assumed having
to be set correctly
cbBufferLength[0] = SQL_COLUMN_IGNORE; // But this also
doesn't work
}
else
cbBufferLength[0] = SQL_COLUMN_IGNORE;

/*...sUnbind:16:*/
switch (_DataType) {
case SQL_DATE:
case SQL_TYPE_DATE:
_CL_VERBOSE << "Unbind date" LOG_
bound = 0;

ret = SQLBindCol(hstmt, _column, SQL_C_CHAR, NULL, (ColumnSize+1),
cbBufferLength);
break;
case SQL_FLOAT:
case SQL_CHAR:
case SQL_VARCHAR:
case SQL_LONGVARCHAR:
#ifndef BIND_BOOL_DEFAULT
case SQL_BIT:
case SQL_TINYINT:
#endif
_CL_VERBOSE << "Unbind char" LOG_
bound = 0;

ret = SQLBindCol(hstmt, _column, SQL_C_CHAR, NULL, (ColumnSize+1),
cbBufferLength);
break;
case SQL_BINARY:
_CL_VERBOSE << "Unbind binary" LOG_
bound = 0;

ret = SQLBindCol(hstmt, _column, SQL_C_DEFAULT, NULL, (ColumnSize
+1), cbBufferLength);
break;
case SQL_INTEGER:
_CL_LOG << "Unbind integer " << columnName LOG_
bound = 0;

SQLBindCol(hstmt, _column, SQL_C_DEFAULT, NULL, sizeof(long),
cbBufferLength);
break;
case SQL_BIGINT:
_CL_VERBOSE << "Unbind big integer" LOG_
bound = 0;
#ifndef _MSC_VER
SQLBindCol(hstmt, _column, SQL_C_DEFAULT, NULL, sizeof(long long),
cbBufferLength);
#endif
#ifdef _MSC_VER
SQLBindCol(hstmt, _column, SQL_C_DEFAULT, NULL, sizeof(__int64),
cbBufferLength);
#endif
break;
#ifdef BIND_BOOL_DEFAULT
case SQL_BIT:
case SQL_TINYINT:
_CL_VERBOSE << "Unbind bit" LOG_
bound = 0;
#ifdef OSX
SQLBindCol(hstmt, _column, SQL_BIT, NULL, sizeof(long),
cbBufferLength);
#endif
#ifndef OSX
SQLBindCol(hstmt, _column, SQL_BIT, NULL, sizeof(bool),
cbBufferLength);
#endif
if (ret != SQL_SUCCESS) {
printf("Error while unbinding a column!\n");
query->dbError("SQLBindCol()", hstmt);
}
break;
#endif
case SQL_LONGVARBINARY:
bound = 0;
break;
default:
_CL_LOG << "lbBoundColumn::unbindReadonlyColumns(...) failed:
Unknown or not supported datatype for column '" << columnName << "': "
<< _DataType LOG_
break;
}
/*...e*/
}

if (ret != SQL_SUCCESS) {
printf("Error while unbinding a column!\n");
query->dbError("SQLBindCol()", hstmt);
}
}

Before I create a plain ODBC sample code to reproduce this, please
have a look at the log snippets.

Thanks

Lothar

The mylog snippets (failure / working) are as follows

Failure

[1072-0.641] stmt_with_params = 'select id, bezeichnung,
action_handler, module , "ctid", "oid" from action_types where ctid =
'(0,0)';select "ctid", "oid" from action_types where module =
'lbDMFXslt' and action_handler = 'instanceOflbDMFXslt''
[1072-0.641]about to begin SC_execute
[1072-0.641] Sending SELECT statement on stmt=03D12340,
cursor_name='SQL_CUR03D12340' qflag=2,3
[1072-0.641]CC_send_query: conn=03D14FD8, query='select id,
bezeichnung, action_handler, module , "ctid", "oid" from action_types
where ctid = '(0,0)';select "ctid", "oid" from action_types where
module = 'lbDMFXslt' and action_handler = 'instanceOflbDMFXslt''
[1072-0.641]send_query: done sending query 212bytes flushed
[1072-0.641]in QR_Constructor
[1072-0.641]exit QR_Constructor
[1072-0.641]read -1, global_socket_buffersize=4096
[1072-0.641]Lasterror=10035
[1072-0.641]read 172, global_socket_buffersize=4096
[1072-0.641]send_query: got id = 'P'
[1072-0.641]send_query: got id = 'T'
[1072-0.656]QR_fetch_tuples: cursor = '', self->cursor=00000000
[1072-0.656]num_fields = 6
[1072-0.656]READING ATTTYPMOD
[1072-0.656]CI_read_fields: fieldname='id', adtid=23, adtsize=4,
atttypmod=-1 (rel,att)=(0,0)
[1072-0.656]READING ATTTYPMOD
[1072-0.656]CI_read_fields: fieldname='bezeichnung', adtid=1042,
adtsize=-1, atttypmod=255 (rel,att)=(0,0)
[1072-0.656]READING ATTTYPMOD
[1072-0.656]CI_read_fields: fieldname='action_handler', adtid=1042,
adtsize=-1, atttypmod=255 (rel,att)=(0,0)
[1072-0.656]READING ATTTYPMOD
[1072-0.656]CI_read_fields: fieldname='module', adtid=1042,
adtsize=-1, atttypmod=255 (rel,att)=(0,0)
[1072-0.656]READING ATTTYPMOD
[1072-0.656]CI_read_fields: fieldname='ctid', adtid=27, adtsize=6,
atttypmod=-1 (rel,att)=(0,0)
[1072-0.656]READING ATTTYPMOD
[1072-0.656]CI_read_fields: fieldname='oid', adtid=26, adtsize=4,
atttypmod=-1 (rel,att)=(0,0)
[1072-0.656]QR_fetch_tuples: past CI_read_fields: num_fields = 4
[1072-0.656]MALLOC: tuple_size = 100, size = 3200
[1072-0.656]QR_next_tuple: inTuples = true, falling through: fcount =
0, fetch_number = 0
[1072-0.656]end of tuple list -- setting inUse to false: this =
04B53318 SELECT
[1072-0.656]_QR_next_tuple: 'C' fetch_total = 0 & this_fetch = 0
[1072-0.656]QR_next_tuple: backend_rows < CACHE_SIZE: brows = 0,
cache_size = 0
[1072-0.656]QR_next_tuple: reached eof now
[1072-0.656]_QR_next_tuple: 'C': DONE (fcount == 0)
[1072-0.656]send_query: got id = 'P'
[1072-0.656]send_query: got id = 'T'
[1072-0.656]in QR_Constructor
[1072-0.656]exit QR_Constructor
[1072-0.656]send_query: 'T' no result_in: res = 04B58DE0
[1072-0.656]QR_fetch_tuples: cursor = '', self->cursor=00000000
[1072-0.656]num_fields = 2
[1072-0.656]READING ATTTYPMOD
[1072-0.656]CI_read_fields: fieldname='ctid', adtid=27, adtsize=6,
atttypmod=-1 (rel,att)=(0,0)
[1072-0.656]READING ATTTYPMOD
[1072-0.656]CI_read_fields: fieldname='oid', adtid=26, adtsize=4,
atttypmod=-1 (rel,att)=(0,0)
[1072-0.656]QR_fetch_tuples: past CI_read_fields: num_fields = 0
[1072-0.672]MALLOC: tuple_size = 100, size = 0
[1072-0.672]QR_next_tuple: inTuples = true, falling through: fcount =
0, fetch_number = 0
[1072-0.672]end of tuple list -- setting inUse to false: this =
04B58DE0 SELECT
[1072-0.672]_QR_next_tuple: 'C' fetch_total = 0 & this_fetch = 0
[1072-0.672]QR_next_tuple: backend_rows < CACHE_SIZE: brows = 0,
cache_size = 0
[1072-0.672]QR_next_tuple: reached eof now
[1072-0.672]_QR_next_tuple: 'C': DONE (fcount == 0)
[1072-0.672]send_query: got id = 'Z'
[1072-0.672] done sending the query:
[1072-0.672]extend_column_bindings: entering ... self=03D123C8,
bindings_allocated=0, num_columns=6
[1072-0.672]exit extend_column_bindings=03D1AB70
[1072-0.672]QResult: enter DESTRUCTOR
[1072-0.672]QResult: in QR_close_result
[1072-0.672]QResult: free memory in, fcount=0
[1072-0.672]QResult: free memory out
[1072-0.672]QResult: enter DESTRUCTOR
[1072-0.672]QResult: exit close_result
[1072-0.672]QResult: exit DESTRUCTOR
[1072-0.672]SC_init_Result(3d12340)[1072-0.672]SC_set_Result(3d12340,
4b58de0)[1072-0.672]QResult: enter DESTRUCTOR
[1072-0.672]retval=0
[1072-0.672]PGAPI_ExecDirect: returned 0 from PGAPI_Execute
[1072-0.672][SQLGetCursorName][1072-0.672]PGAPI_GetCursorName:
hstmt=03D12340, szCursor=02393F50, cbCursorMax=200, pcbCursor=0006ED88
[1072-0.672][SQLNumResultCols][1072-0.672]PGAPI_NumResultCols:
entering...
[1072-0.672]SC_pre_execute: status = 3
[1072-0.672]PGAPI_NumResultCols: result = 04B58DE0, status = 3,
numcols = 6
[1072-0.672][[SQLSetStmtAttr]] Handle=03D12340 27,1
[1072-0.672]PGAPI_SetStmtAttr Handle=03D12340 27,1(00000001)
[1072-0.672][[SQLSetStmtAttr]] Handle=03D12340 5,0
[1072-0.672]PGAPI_SetStmtAttr Handle=03D12340 5,0(00000000)
[1072-0.672]PGAPI_SetStmtOption: entering...
[1072-0.672][[SQLSetStmtAttr]] Handle=03D12340 25,453912
[1072-0.672]PGAPI_SetStmtAttr Handle=03D12340 25,453912(0006ED18)

Working:

[1632-50.797] stmt_with_params = 'select id, bezeichnung,
action_handler, module , "ctid", "oid" from action_types where ctid =
'(0,0)';select "ctid", "oid" from action_types'
[1632-50.797]about to begin SC_execute
[1632-50.797] Sending SELECT statement on stmt=05F02AD8,
cursor_name='SQL_CUR05F02AD8' qflag=2,3
[1632-50.797]CC_send_query: conn=03D04248, query='select id,
bezeichnung, action_handler, module , "ctid", "oid" from action_types
where ctid = '(0,0)';select "ctid", "oid" from action_types'
[1632-50.797]send_query: done sending query 142bytes flushed
[1632-50.797]in QR_Constructor
[1632-50.797]exit QR_Constructor
[1632-50.797]read -1, global_socket_buffersize=4096
[1632-50.797]Lasterror=10035
[1632-50.797]read 457, global_socket_buffersize=4096
[1632-50.812]send_query: got id = 'P'
[1632-50.812]send_query: got id = 'T'
[1632-50.812]QR_fetch_tuples: cursor = '', self->cursor=00000000
[1632-50.812]num_fields = 6
[1632-50.812]READING ATTTYPMOD
[1632-50.812]CI_read_fields: fieldname='id', adtid=23, adtsize=4,
atttypmod=-1 (rel,att)=(0,0)
[1632-50.812]READING ATTTYPMOD
[1632-50.812]CI_read_fields: fieldname='bezeichnung', adtid=1042,
adtsize=-1, atttypmod=255 (rel,att)=(0,0)
[1632-50.812]READING ATTTYPMOD
[1632-50.812]CI_read_fields: fieldname='action_handler', adtid=1042,
adtsize=-1, atttypmod=255 (rel,att)=(0,0)
[1632-50.812]READING ATTTYPMOD
[1632-50.812]CI_read_fields: fieldname='module', adtid=1042,
adtsize=-1, atttypmod=255 (rel,att)=(0,0)
[1632-50.812]READING ATTTYPMOD
[1632-50.812]CI_read_fields: fieldname='ctid', adtid=27, adtsize=6,
atttypmod=-1 (rel,att)=(0,0)
[1632-50.812]READING ATTTYPMOD
[1632-50.812]CI_read_fields: fieldname='oid', adtid=26, adtsize=4,
atttypmod=-1 (rel,att)=(0,0)
[1632-50.812]QR_fetch_tuples: past CI_read_fields: num_fields = 4
[1632-50.812]MALLOC: tuple_size = 100, size = 3200
[1632-50.812]QR_next_tuple: inTuples = true, falling through: fcount =
0, fetch_number = 0
[1632-50.812]end of tuple list -- setting inUse to false: this =
04B31C88 SELECT
[1632-50.812]_QR_next_tuple: 'C' fetch_total = 0 & this_fetch = 0
[1632-50.812]QR_next_tuple: backend_rows < CACHE_SIZE: brows = 0,
cache_size = 0
[1632-50.812]QR_next_tuple: reached eof now
[1632-50.812]_QR_next_tuple: 'C': DONE (fcount == 0)
[1632-50.812]send_query: got id = 'P'
[1632-50.812]send_query: got id = 'T'
[1632-50.812]in QR_Constructor
[1632-50.812]exit QR_Constructor
[1632-50.812]send_query: 'T' no result_in: res = 05F08E40
[1632-50.812]QR_fetch_tuples: cursor = '', self->cursor=00000000
[1632-50.828]num_fields = 2
[1632-50.828]READING ATTTYPMOD
[1632-50.828]CI_read_fields: fieldname='ctid', adtid=27, adtsize=6,
atttypmod=-1 (rel,att)=(0,0)
[1632-50.828]READING ATTTYPMOD
[1632-50.828]CI_read_fields: fieldname='oid', adtid=26, adtsize=4,
atttypmod=-1 (rel,att)=(0,0)
[1632-50.828]QR_fetch_tuples: past CI_read_fields: num_fields = 0
[1632-50.828]MALLOC: tuple_size = 100, size = 0
[1632-50.828]QR_next_tuple: inTuples = true, falling through: fcount =
0, fetch_number = 0
[1632-50.828]qresult: len=6, buffer='(0,11)'
[1632-50.828]qresult: len=6, buffer='194598'
[1632-50.828]qresult: len=6, buffer='(0,12)'
[1632-50.828]qresult: len=6, buffer='194592'
[1632-50.828]qresult: len=6, buffer='(0,13)'
[1632-50.828]qresult: len=6, buffer='194591'
[1632-50.828]qresult: len=6, buffer='(0,14)'
[1632-50.828]qresult: len=6, buffer='194597'
[1632-50.828]qresult: len=6, buffer='(0,15)'
[1632-50.828]qresult: len=6, buffer='194594'
[1632-50.828]qresult: len=6, buffer='(0,17)'
[1632-50.828]qresult: len=6, buffer='194593'
[1632-50.828]qresult: len=6, buffer='(0,18)'
[1632-50.828]qresult: len=6, buffer='194590'
[1632-50.828]qresult: len=6, buffer='(0,19)'
[1632-50.828]qresult: len=6, buffer='194596'
[1632-50.828]qresult: len=5, buffer='(1,7)'
[1632-50.828]qresult: len=6, buffer='194601'
[1632-50.828]qresult: len=6, buffer='(1,14)'
[1632-50.828]qresult: len=6, buffer='194600'
[1632-50.828]qresult: len=6, buffer='(2,10)'
[1632-50.828]qresult: len=6, buffer='194599'
[1632-50.828]qresult: len=6, buffer='(2,13)'
[1632-50.828]qresult: len=6, buffer='194589'
[1632-50.828]qresult: len=6, buffer='(2,25)'
[1632-50.828]qresult: len=6, buffer='195070'
[1632-50.828]end of tuple list -- setting inUse to false: this =
05F08E40 SELECT
[1632-50.828]_QR_next_tuple: 'C' fetch_total = 13 & this_fetch = 0
[1632-50.828]QR_next_tuple: backend_rows < CACHE_SIZE: brows = 0,
cache_size = 0
[1632-50.828]QR_next_tuple: reached eof now
[1632-50.828]_QR_next_tuple: 'C': DONE (fcount == 0)
[1632-50.828]send_query: got id = 'Z'
[1632-50.844] done sending the query:
[1632-50.844]extend_column_bindings: entering ... self=05F02B60,
bindings_allocated=0, num_columns=6
[1632-50.844]exit extend_column_bindings=05F08F10
[1632-50.844]QResult: enter DESTRUCTOR
[1632-50.844]QResult: in QR_close_result
[1632-50.844]QResult: free memory in, fcount=0
[1632-50.844]QResult: free memory out
[1632-50.844]QResult: enter DESTRUCTOR
[1632-50.844]QResult: exit close_result
[1632-50.844]QResult: exit DESTRUCTOR
[1632-50.844]SC_init_Result(5f02ad8)
[1632-50.844]SC_set_Result(5f02ad8, 5f08e40)[1632-50.844]QResult:
enter DESTRUCTOR
[1632-50.844]retval=0
[1632-50.844]PGAPI_ExecDirect: returned 0 from PGAPI_Execute
[1632-50.844][SQLGetCursorName][1632-50.844]PGAPI_GetCursorName:
hstmt=05F02AD8, szCursor=023939E0, cbCursorMax=200, pcbCursor=0006C524
[1632-50.844][SQLNumResultCols][1632-50.844]PGAPI_NumResultCols:
entering...
[1632-50.844]SC_pre_execute: status = 3
[1632-50.844]PGAPI_NumResultCols: result = 05F08E40, status = 3,
numcols = 6
[1632-50.844][[SQLSetStmtAttr]] Handle=05F02AD8 27,1
[1632-50.844]PGAPI_SetStmtAttr Handle=05F02AD8 27,1(00000001)
[1632-50.844][[SQLSetStmtAttr]] Handle=05F02AD8 5,0
[1632-50.844]PGAPI_SetStmtAttr Handle=05F02AD8 5,0(00000000)
[1632-50.844]PGAPI_SetStmtOption: entering...
[1632-50.844][[SQLSetStmtAttr]] Handle=05F02AD8 25,443572
[1632-50.844]PGAPI_SetStmtAttr Handle=05F02AD8 25,443572(0006C4B4)

-- | Rapid Prototyping | XSLT Codegeneration | http://www.lollisoft.de
Lothar Behrens
Heinrich-Scheufelen-Platz 2
73252 Lenningen