FEAT: Comprehensive Logging Framework with Python-C++ Bridge & Instrumentation #312
+2,880
−985
Conversation
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
![github-advanced-security[bot]](https://avatars.githubusercontent.com/in/57789?s=60&v=4){kind=small}
📊 Code Coverage Report
Diff CoverageDiff: main...HEAD, staged and unstaged changes
Summary
mssql_python/auth.pyLines 166-174 166 try:
167 token = AADAuth.get_token(auth_type)
168 logger.info('get_auth_token: Token acquired successfully - auth_type=%s', auth_type)
169 return token
! 170 except (ValueError, RuntimeError) as e:
171 logger.warning('get_auth_token: Token acquisition failed - auth_type=%s, error=%s', auth_type, str(e))
172 return None
173 mssql_python/helpers.pyLines 39-50 39 connection_attributes = connection_str.split(";")
40 final_connection_attributes = []
41
42 # Iterate through the attributes and exclude any existing driver attribute
! 43 driver_found = False
44 for attribute in connection_attributes:
45 if attribute.lower().split("=")[0] == "driver":
! 46 driver_found = True
47 logger.debug('add_driver_to_connection_str: Existing driver attribute found, removing')
48 continue
49 final_connection_attributes.append(attribute)mssql_python/logging.pyLines 38-48 38 """Add thread_id (OS native) attribute to log record."""
39 # Use OS native thread ID for debugging compatibility
40 try:
41 thread_id = threading.get_native_id()
! 42 except AttributeError:
43 # Fallback for Python < 3.8
! 44 thread_id = threading.current_thread().ident
45 record.thread_id = thread_id
46 return True
47 Lines 128-137 128 # Flush and close each handler while holding its lock
129 for handler in old_handlers:
130 try:
131 handler.flush() # Flush BEFORE close
! 132 except:
! 133 pass # Ignore flush errors
134 handler.close()
135 self._logger.removeHandler(handler)
136 finally:
137 # Release locks on old handlersLines 137-146 137 # Release locks on old handlers
138 for handler in old_handlers:
139 try:
140 handler.release()
! 141 except:
! 142 pass # Handler might already be closed
143
144 self._file_handler = None
145 self._stdout_handler = None
146 Lines 154-163 154 end_bracket = msg.index(']')
155 source = msg[1:end_bracket]
156 message = msg[end_bracket+2:].strip() # Skip '] '
157 else:
! 158 source = 'Unknown'
! 159 message = msg
160
161 # Format timestamp with milliseconds using period separator
162 timestamp = self.formatTime(record, '%Y-%m-%d %H:%M:%S')
163 timestamp_with_ms = f"{timestamp}.{int(record.msecs):03d}"Lines 226-234 226 """
227 Reconfigure handlers when output mode changes.
228 Closes existing handlers and creates new ones based on current output mode.
229 """
! 230 self._setup_handlers()
231
232 def _cleanup_handlers(self):
233 """
234 Cleanup all handlers on process exit.Lines 250-259 250 for handler in handlers:
251 try:
252 handler.flush()
253 handler.close()
! 254 except:
! 255 pass # Ignore errors during cleanup
256 self._logger.removeHandler(handler)
257 finally:
258 for handler in handlers:
259 try:Lines 257-266 257 finally:
258 for handler in handlers:
259 try:
260 handler.release()
! 261 except:
! 262 pass
263
264 def _validate_log_file_extension(self, file_path: str) -> None:
265 """
266 Validate that the log file has an allowed extension.Lines 286-294 286 Write CSV header and metadata to the log file.
287 Called once when log file is created.
288 """
289 if not self._log_file or not self._file_handler:
! 290 return
291
292 try:
293 # Get script name from sys.argv or __main__
294 script_name = os.path.basename(sys.argv[0]) if sys.argv else '<interactive>'Lines 298-306 298
299 # Get driver version (try to import from package)
300 try:
301 from mssql_python import __version__
! 302 driver_version = __version__
303 except:
304 driver_version = 'unknown'
305
306 # Get current timeLines 322-336 322 with open(self._log_file, 'a') as f:
323 f.write(header_line)
324 f.write(csv_header)
325
! 326 except Exception as e:
327 # Notify on stderr so user knows why header is missing
! 328 try:
! 329 sys.stderr.write(f"[MSSQL-Python] Warning: Failed to write log header to {self._log_file}: {type(e).__name__}\n")
! 330 sys.stderr.flush()
! 331 except:
! 332 pass # Even stderr notification failed
333 # Don't crash - logging continues without header
334
335 def _log(self, level: int, msg: str, add_prefix: bool = True, *args, **kwargs):
336 """Lines 379-388 379 import sys
380 level_name = logging.getLevelName(level)
381 sys.stderr.write(f"[MSSQL-Python Logging Failed - {level_name}] {msg if 'msg' in locals() else 'Unable to format message'}\n")
382 sys.stderr.flush()
! 383 except:
! 384 pass # Even stderr failed - give up silently
385
386 # Convenience methods for logging
387
388 def debug(self, msg: str, *args, **kwargs):Lines 470-484 470 # Handler management
471
472 def addHandler(self, handler: logging.Handler):
473 """Add a handler to the logger (thread-safe)"""
! 474 with self._handler_lock:
! 475 self._logger.addHandler(handler)
476
477 def removeHandler(self, handler: logging.Handler):
478 """Remove a handler from the logger (thread-safe)"""
! 479 with self._handler_lock:
! 480 self._logger.removeHandler(handler)
481
482 @property
483 def handlers(self) -> list:
484 """Get list of handlers attached to the logger (thread-safe)"""Lines 489-497 489 """
490 Reset/recreate handlers.
491 Useful when log file has been deleted or needs to be recreated.
492 """
! 493 self._setup_handlers()
494
495 def _notify_cpp_level_change(self, level: int):
496 """
497 Notify C++ bridge that log level has changed.Lines 504-514 504 # Import here to avoid circular dependency
505 from . import ddbc_bindings
506 if hasattr(ddbc_bindings, 'update_log_level'):
507 ddbc_bindings.update_log_level(level)
! 508 except (ImportError, AttributeError):
509 # C++ bindings not available or not yet initialized
! 510 pass
511
512 # Properties
513
514 @propertyLines 526-543 526
527 Raises:
528 ValueError: If mode is not a valid OutputMode value
529 """
! 530 if mode not in (FILE, STDOUT, BOTH):
! 531 raise ValueError(
532 f"Invalid output mode: {mode}. "
533 f"Must be one of: {FILE}, {STDOUT}, {BOTH}"
534 )
! 535 self._output_mode = mode
536
537 # Only reconfigure if handlers were already initialized
! 538 if self._handlers_initialized:
! 539 self._reconfigure_handlers()
540
541 @property
542 def log_file(self) -> Optional[str]:
543 """Get the current log file path (None if file output is disabled)"""mssql_python/pybind/connection/connection.cppLines 214-222 214
215 // Convert to wide string
216 std::wstring wstr = Utf8ToWString(utf8_str);
217 if (wstr.empty() && !utf8_str.empty()) {
! 218 LOG("Failed to convert string value to wide string for attribute=%d", attribute);
219 return SQL_ERROR;
220 }
221 this->wstrStringBuffer.clear();
222 this->wstrStringBuffer = std::move(wstr);Lines 227-235 227 #if defined(__APPLE__) || defined(__linux__)
228 // For macOS/Linux, convert wstring to SQLWCHAR buffer
229 std::vector<SQLWCHAR> sqlwcharBuffer = WStringToSQLWCHAR(this->wstrStringBuffer);
230 if (sqlwcharBuffer.empty() && !this->wstrStringBuffer.empty()) {
! 231 LOG("Failed to convert wide string to SQLWCHAR buffer for attribute=%d", attribute);
232 return SQL_ERROR;
233 }
234
235 ptr = sqlwcharBuffer.data();Lines 243-251 243
244 SQLRETURN ret = SQLSetConnectAttr_ptr(_dbcHandle->get(),
245 attribute, ptr, length);
246 if (!SQL_SUCCEEDED(ret)) {
! 247 LOG("Failed to set string attribute=%d, ret=%d", attribute, ret);
248 } else {
249 LOG("Set string attribute=%d successfully", attribute);
250 }
251 return ret;Lines 249-257 249 LOG("Set string attribute=%d successfully", attribute);
250 }
251 return ret;
252 } catch (const std::exception& e) {
! 253 LOG("Exception during string attribute=%d setting: %s", attribute, e.what());
254 return SQL_ERROR;
255 }
256 } else if (py::isinstance<py::bytes>(value) ||
257 py::isinstance<py::bytearray>(value)) {Lines 264-282 264
265 SQLRETURN ret = SQLSetConnectAttr_ptr(_dbcHandle->get(),
266 attribute, ptr, length);
267 if (!SQL_SUCCEEDED(ret)) {
! 268 LOG("Failed to set binary attribute=%d, ret=%d", attribute, ret);
269 } else {
! 270 LOG("Set binary attribute=%d successfully (length=%d)", attribute, length);
271 }
272 return ret;
273 } catch (const std::exception& e) {
! 274 LOG("Exception during binary attribute=%d setting: %s", attribute, e.what());
275 return SQL_ERROR;
276 }
277 } else {
! 278 LOG("Unsupported attribute value type for attribute=%d", attribute);
279 return SQL_ERROR;
280 }
281 }Lines 322-330 322 SQL_ATTR_RESET_CONNECTION,
323 (SQLPOINTER)SQL_RESET_CONNECTION_YES,
324 SQL_IS_INTEGER);
325 if (!SQL_SUCCEEDED(ret)) {
! 326 LOG("Failed to reset connection (ret=%d). Marking as dead.", ret);
327 disconnect();
328 return false;
329 }
330 updateLastUsed();mssql_python/pybind/connection/connection_pool.cppLines 71-79 71 for (auto& conn : to_disconnect) {
72 try {
73 conn->disconnect();
74 } catch (const std::exception& ex) {
! 75 LOG("Disconnect bad/expired connections failed: %s", ex.what());
76 }
77 }
78 return valid_conn;
79 }Lines 102-110 102 for (auto& conn : to_close) {
103 try {
104 conn->disconnect();
105 } catch (const std::exception& ex) {
! 106 LOG("ConnectionPool::close: disconnect failed: %s", ex.what());
107 }
108 }
109 }mssql_python/pybind/ddbc_bindings.cppLines 293-301 293 !py::isinstance<py::bytes>(param)) {
294 ThrowStdException(MakeParamMismatchErrorStr(paramInfo.paramCType, paramIndex));
295 }
296 if (paramInfo.isDAE) {
! 297 LOG("BindParameters: param[%d] SQL_C_CHAR - Using DAE (Data-At-Execution) for large string streaming", paramIndex);
298 dataPtr = const_cast<void*>(reinterpret_cast<const void*>(¶mInfos[paramIndex]));
299 strLenOrIndPtr = AllocateParamBuffer<SQLLEN>(paramBuffers);
300 *strLenOrIndPtr = SQL_LEN_DATA_AT_EXEC(0);
301 bufferLength = 0;Lines 395-403 395 &describedDigits,
396 &nullable
397 );
398 if (!SQL_SUCCEEDED(rc)) {
! 399 LOG("BindParameters: SQLDescribeParam failed for param[%d] (NULL parameter) - SQLRETURN=%d", paramIndex, rc);
400 return rc;
401 }
402 sqlType = describedType;
403 columnSize = describedSize;Lines 606-615 606 }
607 py::bytes uuid_bytes = param.cast<py::bytes>();
608 const unsigned char* uuid_data = reinterpret_cast<const unsigned char*>(PyBytes_AS_STRING(uuid_bytes.ptr()));
609 if (PyBytes_GET_SIZE(uuid_bytes.ptr()) != 16) {
! 610 LOG("BindParameters: param[%d] SQL_C_GUID - Invalid UUID length: expected 16 bytes, got %ld bytes",
! 611 paramIndex, PyBytes_GET_SIZE(uuid_bytes.ptr()));
612 ThrowStdException("UUID binary data must be exactly 16 bytes long.");
613 }
614 SQLGUID* guid_data_ptr = AllocateParamBuffer<SQLGUID>(paramBuffers);
615 guid_data_ptr->Data1 =Lines 655-668 655 if (paramInfo.paramCType == SQL_C_NUMERIC) {
656 SQLHDESC hDesc = nullptr;
657 rc = SQLGetStmtAttr_ptr(hStmt, SQL_ATTR_APP_PARAM_DESC, &hDesc, 0, NULL);
658 if(!SQL_SUCCEEDED(rc)) {
! 659 LOG("BindParameters: SQLGetStmtAttr(SQL_ATTR_APP_PARAM_DESC) failed for param[%d] - SQLRETURN=%d", paramIndex, rc);
660 return rc;
661 }
662 rc = SQLSetDescField_ptr(hDesc, 1, SQL_DESC_TYPE, (SQLPOINTER) SQL_C_NUMERIC, 0);
663 if(!SQL_SUCCEEDED(rc)) {
! 664 LOG("BindParameters: SQLSetDescField(SQL_DESC_TYPE) failed for param[%d] - SQLRETURN=%d", paramIndex, rc);
665 return rc;
666 }
667 SQL_NUMERIC_STRUCT* numericPtr = reinterpret_cast<SQL_NUMERIC_STRUCT*>(dataPtr);
668 rc = SQLSetDescField_ptr(hDesc, 1, SQL_DESC_PRECISION,Lines 667-675 667 SQL_NUMERIC_STRUCT* numericPtr = reinterpret_cast<SQL_NUMERIC_STRUCT*>(dataPtr);
668 rc = SQLSetDescField_ptr(hDesc, 1, SQL_DESC_PRECISION,
669 (SQLPOINTER) numericPtr->precision, 0);
670 if(!SQL_SUCCEEDED(rc)) {
! 671 LOG("BindParameters: SQLSetDescField(SQL_DESC_PRECISION) failed for param[%d] - SQLRETURN=%d", paramIndex, rc);
672 return rc;
673 }
674
675 rc = SQLSetDescField_ptr(hDesc, 1, SQL_DESC_SCALE,Lines 674-682 674
675 rc = SQLSetDescField_ptr(hDesc, 1, SQL_DESC_SCALE,
676 (SQLPOINTER) numericPtr->scale, 0);
677 if(!SQL_SUCCEEDED(rc)) {
! 678 LOG("BindParameters: SQLSetDescField(SQL_DESC_SCALE) failed for param[%d] - SQLRETURN=%d", paramIndex, rc);
679 return rc;
680 }
681
682 rc = SQLSetDescField_ptr(hDesc, 1, SQL_DESC_DATA_PTR, (SQLPOINTER) numericPtr, 0);Lines 680-688 680 }
681
682 rc = SQLSetDescField_ptr(hDesc, 1, SQL_DESC_DATA_PTR, (SQLPOINTER) numericPtr, 0);
683 if(!SQL_SUCCEEDED(rc)) {
! 684 LOG("BindParameters: SQLSetDescField(SQL_DESC_DATA_PTR) failed for param[%d] - SQLRETURN=%d", paramIndex, rc);
685 return rc;
686 }
687 }
688 }Lines 760-768 760 if (pos != std::string::npos) {
761 std::string dir = module_file.substr(0, pos);
762 return dir;
763 }
! 764 LOG("GetModuleDirectory: Could not extract directory from module path - path='%s'", module_file.c_str());
765 return module_file;
766 #endif
767 }Lines 783-792 783 #else
784 // macOS/Unix: Use dlopen
785 void* handle = dlopen(driverPath.c_str(), RTLD_LAZY);
786 if (!handle) {
! 787 LOG("LoadDriverLibrary: dlopen failed for path='%s' - %s",
! 788 driverPath.c_str(), dlerror() ? dlerror() : "unknown error");
789 }
790 return handle;
791 #endif
792 }Lines 928-937 928 }
929
930 DriverHandle handle = LoadDriverLibrary(driverPath.string());
931 if (!handle) {
! 932 LOG("LoadDriverOrThrowException: Failed to load ODBC driver - path='%s', error='%s'",
! 933 driverPath.string().c_str(), GetLastErrorMessage().c_str());
934 ThrowStdException("Failed to load the driver. Please read the documentation (https://github.com/microsoft/mssql-python#installation) to install the required dependencies.");
935 }
936 LOG("LoadDriverOrThrowException: ODBC driver library loaded successfully from '%s'", driverPath.string().c_str());Lines 1311-1319 1311 ErrorInfo SQLCheckError_Wrap(SQLSMALLINT handleType, SqlHandlePtr handle, SQLRETURN retcode) {
1312 LOG("SQLCheckError: Checking ODBC errors - handleType=%d, retcode=%d", handleType, retcode);
1313 ErrorInfo errorInfo;
1314 if (retcode == SQL_INVALID_HANDLE) {
! 1315 LOG("SQLCheckError: SQL_INVALID_HANDLE detected - handle is invalid");
1316 errorInfo.ddbcErrorMsg = std::wstring( L"Invalid handle!");
1317 return errorInfo;
1318 }
1319 assert(handle != 0);Lines 1319-1327 1319 assert(handle != 0);
1320 SQLHANDLE rawHandle = handle->get();
1321 if (!SQL_SUCCEEDED(retcode)) {
1322 if (!SQLGetDiagRec_ptr) {
! 1323 LOG("SQLCheckError: SQLGetDiagRec function pointer not initialized, loading driver");
1324 DriverLoader::getInstance().loadDriver(); // Load the driver
1325 }
1326
1327 SQLWCHAR sqlState[6], message[SQL_MAX_MESSAGE_LENGTH];Lines 1350-1358 1350 py::list SQLGetAllDiagRecords(SqlHandlePtr handle) {
1351 LOG("SQLGetAllDiagRecords: Retrieving all diagnostic records for handle %p, handleType=%d",
1352 (void*)handle->get(), handle->type());
1353 if (!SQLGetDiagRec_ptr) {
! 1354 LOG("SQLGetAllDiagRecords: SQLGetDiagRec function pointer not initialized, loading driver");
1355 DriverLoader::getInstance().loadDriver();
1356 }
1357
1358 py::list records;Lines 1414-1426 1414 }
1415
1416 // Wrap SQLExecDirect
1417 SQLRETURN SQLExecDirect_wrap(SqlHandlePtr StatementHandle, const std::wstring& Query) {
! 1418 std::string queryUtf8 = WideToUTF8(Query);
! 1419 LOG("SQLExecDirect: Executing query directly - statement_handle=%p, query_length=%zu chars",
! 1420 (void*)StatementHandle->get(), Query.length());
1421 if (!SQLExecDirect_ptr) {
! 1422 LOG("SQLExecDirect: Function pointer not initialized, loading driver");
1423 DriverLoader::getInstance().loadDriver(); // Load the driver
1424 }
1425
1426 // Configure forward-only cursorLines 1443-1451 1443 queryPtr = const_cast<SQLWCHAR*>(Query.c_str());
1444 #endif
1445 SQLRETURN ret = SQLExecDirect_ptr(StatementHandle->get(), queryPtr, SQL_NTS);
1446 if (!SQL_SUCCEEDED(ret)) {
! 1447 LOG("SQLExecDirect: Query execution failed - SQLRETURN=%d", ret);
1448 }
1449 return ret;
1450 }Lines 1456-1464 1456 const std::wstring& table,
1457 const std::wstring& tableType) {
1458
1459 if (!SQLTables_ptr) {
! 1460 LOG("SQLTables: Function pointer not initialized, loading driver");
1461 DriverLoader::getInstance().loadDriver();
1462 }
1463
1464 SQLWCHAR* catalogPtr = nullptr;Lines 1541-1549 1541 py::list& isStmtPrepared, const bool usePrepare = true) {
1542 LOG("SQLExecute: Executing %s query - statement_handle=%p, param_count=%zu, query_length=%zu chars",
1543 (params.size() > 0 ? "parameterized" : "direct"), (void*)statementHandle->get(), params.size(), query.length());
1544 if (!SQLPrepare_ptr) {
! 1545 LOG("SQLExecute: Function pointer not initialized, loading driver");
1546 DriverLoader::getInstance().loadDriver(); // Load the driver
1547 }
1548 assert(SQLPrepare_ptr && SQLBindParameter_ptr && SQLExecute_ptr && SQLExecDirect_ptr);Lines 1554-1562 1554
1555 RETCODE rc;
1556 SQLHANDLE hStmt = statementHandle->get();
1557 if (!statementHandle || !statementHandle->get()) {
! 1558 LOG("SQLExecute: Statement handle is null or invalid");
1559 }
1560
1561 // Configure forward-only cursor
1562 if (SQLSetStmtAttr_ptr && hStmt) {Lines 1594-1602 1594 assert(isStmtPrepared.size() == 1);
1595 if (usePrepare) {
1596 rc = SQLPrepare_ptr(hStmt, queryPtr, SQL_NTS);
1597 if (!SQL_SUCCEEDED(rc)) {
! 1598 LOG("SQLExecute: SQLPrepare failed - SQLRETURN=%d, statement_handle=%p", rc, (void*)hStmt);
1599 return rc;
1600 }
1601 isStmtPrepared[0] = py::cast(true);
1602 } else {Lines 1659-1668 1659 ThrowStdException("Chunk size exceeds maximum allowed by SQLLEN");
1660 }
1661 rc = SQLPutData_ptr(hStmt, (SQLPOINTER)(dataPtr + offset), static_cast<SQLLEN>(lenBytes));
1662 if (!SQL_SUCCEEDED(rc)) {
! 1663 LOG("SQLExecute: SQLPutData failed for SQL_C_WCHAR chunk - offset=%zu",
! 1664 offset, totalChars, lenBytes, rc);
1665 return rc;
1666 }
1667 offset += len;
1668 }Lines 1676-1685 1676 size_t len = std::min(chunkBytes, totalBytes - offset);
1677
1678 rc = SQLPutData_ptr(hStmt, (SQLPOINTER)(dataPtr + offset), static_cast<SQLLEN>(len));
1679 if (!SQL_SUCCEEDED(rc)) {
! 1680 LOG("SQLExecute: SQLPutData failed for SQL_C_CHAR chunk - offset=%zu",
! 1681 offset, totalBytes, len, rc);
1682 return rc;
1683 }
1684 offset += len;
1685 }Lines 1695-1704 1695 for (size_t offset = 0; offset < totalBytes; offset += chunkSize) {
1696 size_t len = std::min(chunkSize, totalBytes - offset);
1697 rc = SQLPutData_ptr(hStmt, (SQLPOINTER)(dataPtr + offset), static_cast<SQLLEN>(len));
1698 if (!SQL_SUCCEEDED(rc)) {
! 1699 LOG("SQLExecute: SQLPutData failed for binary/bytes chunk - offset=%zu",
! 1700 offset, totalBytes, len, rc);
1701 return rc;
1702 }
1703 }
1704 } else {Lines 1705-1714 1705 ThrowStdException("DAE only supported for str or bytes");
1706 }
1707 }
1708 if (!SQL_SUCCEEDED(rc)) {
! 1709 LOG("SQLExecute: SQLParamData final call %s - SQLRETURN=%d",
! 1710 (rc == SQL_NO_DATA ? "completed with no data" : "failed"), rc);
1711 return rc;
1712 }
1713 LOG("SQLExecute: DAE streaming completed successfully, SQLExecute resumed");
1714 }Lines 1740-1749 1740 const ParamInfo& info = paramInfos[paramIndex];
1741 LOG("BindParameterArray: Processing param_index=%d, C_type=%d, SQL_type=%d, column_size=%zu, decimal_digits=%d",
1742 paramIndex, info.paramCType, info.paramSQLType, info.columnSize, info.decimalDigits);
1743 if (columnValues.size() != paramSetSize) {
! 1744 LOG("BindParameterArray: Size mismatch - param_index=%d, expected=%zu, actual=%zu",
! 1745 paramIndex, paramSetSize, columnValues.size());
1746 ThrowStdException("Column " + std::to_string(paramIndex) + " has mismatched size.");
1747 }
1748 void* dataPtr = nullptr;
1749 SQLLEN* strLenOrIndArray = nullptr;Lines 1767-1775 1767 dataPtr = dataArray;
1768 break;
1769 }
1770 case SQL_C_DOUBLE: {
! 1771 LOG("BindParameterArray: Binding SQL_C_DOUBLE array - param_index=%d, count=%zu", paramIndex, paramSetSize);
1772 double* dataArray = AllocateParamBufferArray<double>(tempBuffers, paramSetSize);
1773 for (size_t i = 0; i < paramSetSize; ++i) {
1774 if (columnValues[i].is_none()) {
1775 if (!strLenOrIndArray)Lines 1780-1788 1780 dataArray[i] = columnValues[i].cast<double>();
1781 if (strLenOrIndArray) strLenOrIndArray[i] = 0;
1782 }
1783 }
! 1784 LOG("BindParameterArray: SQL_C_DOUBLE bound - param_index=%d", paramIndex);
1785 dataPtr = dataArray;
1786 break;
1787 }
1788 case SQL_C_WCHAR: {Lines 1802-1813 1802 size_t utf16_len = utf16Buf.size() > 0 ? utf16Buf.size() - 1 : 0;
1803 // Check UTF-16 length (excluding null terminator) against column size
1804 if (utf16Buf.size() > 0 && utf16_len > info.columnSize) {
1805 std::string offending = WideToUTF8(wstr);
! 1806 LOG("BindParameterArray: SQL_C_WCHAR string too long - param_index=%d, row=%zu, utf16_length=%zu, max=%zu",
! 1807 paramIndex, i, utf16_len, info.columnSize);
1808 ThrowStdException("Input string UTF-16 length exceeds allowed column size at parameter index " + std::to_string(paramIndex) +
! 1809 ". UTF-16 length: " + std::to_string(utf16_len) + ", Column size: " + std::to_string(info.columnSize));
1810 }
1811 // If we reach here, the UTF-16 string fits - copy it completely
1812 std::memcpy(wcharArray + i * (info.columnSize + 1), utf16Buf.data(), utf16Buf.size() * sizeof(SQLWCHAR));
1813 #elseLines 1838-1847 1838 strLenOrIndArray[i] = SQL_NULL_DATA;
1839 } else {
1840 int intVal = columnValues[i].cast<int>();
1841 if (intVal < 0 || intVal > 255) {
! 1842 LOG("BindParameterArray: TINYINT value out of range - param_index=%d, row=%zu, value=%d",
! 1843 paramIndex, i, intVal);
1844 ThrowStdException("UTINYINT value out of range at rowIndex " + std::to_string(i));
1845 }
1846 dataArray[i] = static_cast<unsigned char>(intVal);
1847 if (strLenOrIndArray) strLenOrIndArray[i] = 0;Lines 1864-1873 1864 } else {
1865 int intVal = columnValues[i].cast<int>();
1866 if (intVal < std::numeric_limits<short>::min() ||
1867 intVal > std::numeric_limits<short>::max()) {
! 1868 LOG("BindParameterArray: SHORT value out of range - param_index=%d, row=%zu, value=%d",
! 1869 paramIndex, i, intVal);
1870 ThrowStdException("SHORT value out of range at rowIndex " + std::to_string(i));
1871 }
1872 dataArray[i] = static_cast<short>(intVal);
1873 if (strLenOrIndArray) strLenOrIndArray[i] = 0;Lines 1890-1901 1890 std::memset(charArray + i * (info.columnSize + 1), 0, info.columnSize + 1);
1891 } else {
1892 std::string str = columnValues[i].cast<std::string>();
1893 if (str.size() > info.columnSize) {
! 1894 LOG("BindParameterArray: String/binary too long - param_index=%d, row=%zu, size=%zu, max=%zu",
! 1895 paramIndex, i, str.size(), info.columnSize);
1896 ThrowStdException("Input exceeds column size at index " + std::to_string(i));
! 1897 }
1898 std::memcpy(charArray + i * (info.columnSize + 1), str.c_str(), str.size());
1899 strLenOrIndArray[i] = static_cast<SQLLEN>(str.size());
1900 }
1901 }Lines 1904-1912 1904 bufferLength = info.columnSize + 1;
1905 break;
1906 }
1907 case SQL_C_BIT: {
! 1908 LOG("BindParameterArray: Binding SQL_C_BIT array - param_index=%d, count=%zu", paramIndex, paramSetSize);
1909 char* boolArray = AllocateParamBufferArray<char>(tempBuffers, paramSetSize);
1910 strLenOrIndArray = AllocateParamBufferArray<SQLLEN>(tempBuffers, paramSetSize);
1911 for (size_t i = 0; i < paramSetSize; ++i) {
1912 if (columnValues[i].is_none()) {Lines 1912-1925 1912 if (columnValues[i].is_none()) {
1913 boolArray[i] = 0;
1914 strLenOrIndArray[i] = SQL_NULL_DATA;
1915 } else {
! 1916 bool val = columnValues[i].cast<bool>();
! 1917 boolArray[i] = val ? 1 : 0;
1918 strLenOrIndArray[i] = 0;
1919 }
1920 }
! 1921 LOG("BindParameterArray: SQL_C_BIT bound - param_index=%d", paramIndex);
1922 dataPtr = boolArray;
1923 bufferLength = sizeof(char);
1924 break;
1925 }Lines 1924-1932 1924 break;
1925 }
1926 case SQL_C_STINYINT:
1927 case SQL_C_USHORT: {
! 1928 LOG("BindParameterArray: Binding SQL_C_USHORT/STINYINT array - param_index=%d, count=%zu", paramIndex, paramSetSize);
1929 unsigned short* dataArray = AllocateParamBufferArray<unsigned short>(tempBuffers, paramSetSize);
1930 strLenOrIndArray = AllocateParamBufferArray<SQLLEN>(tempBuffers, paramSetSize);
1931 for (size_t i = 0; i < paramSetSize; ++i) {
1932 if (columnValues[i].is_none()) {Lines 1936-1944 1936 dataArray[i] = columnValues[i].cast<unsigned short>();
1937 strLenOrIndArray[i] = 0;
1938 }
1939 }
! 1940 LOG("BindParameterArray: SQL_C_USHORT bound - param_index=%d", paramIndex);
1941 dataPtr = dataArray;
1942 bufferLength = sizeof(unsigned short);
1943 break;
1944 }Lines 1981-1989 1981 bufferLength = sizeof(float);
1982 break;
1983 }
1984 case SQL_C_TYPE_DATE: {
! 1985 LOG("BindParameterArray: Binding SQL_C_TYPE_DATE array - param_index=%d, count=%zu", paramIndex, paramSetSize);
1986 SQL_DATE_STRUCT* dateArray = AllocateParamBufferArray<SQL_DATE_STRUCT>(tempBuffers, paramSetSize);
1987 strLenOrIndArray = AllocateParamBufferArray<SQLLEN>(tempBuffers, paramSetSize);
1988 for (size_t i = 0; i < paramSetSize; ++i) {
1989 if (columnValues[i].is_none()) {Lines 1996-2004 1996 dateArray[i].day = dateObj.attr("day").cast<SQLUSMALLINT>();
1997 strLenOrIndArray[i] = 0;
1998 }
1999 }
! 2000 LOG("BindParameterArray: SQL_C_TYPE_DATE bound - param_index=%d", paramIndex);
2001 dataPtr = dateArray;
2002 bufferLength = sizeof(SQL_DATE_STRUCT);
2003 break;
2004 }Lines 2002-2010 2002 bufferLength = sizeof(SQL_DATE_STRUCT);
2003 break;
2004 }
2005 case SQL_C_TYPE_TIME: {
! 2006 LOG("BindParameterArray: Binding SQL_C_TYPE_TIME array - param_index=%d, count=%zu", paramIndex, paramSetSize);
2007 SQL_TIME_STRUCT* timeArray = AllocateParamBufferArray<SQL_TIME_STRUCT>(tempBuffers, paramSetSize);
2008 strLenOrIndArray = AllocateParamBufferArray<SQLLEN>(tempBuffers, paramSetSize);
2009 for (size_t i = 0; i < paramSetSize; ++i) {
2010 if (columnValues[i].is_none()) {Lines 2017-2025 2017 timeArray[i].second = timeObj.attr("second").cast<SQLUSMALLINT>();
2018 strLenOrIndArray[i] = 0;
2019 }
2020 }
! 2021 LOG("BindParameterArray: SQL_C_TYPE_TIME bound - param_index=%d", paramIndex);
2022 dataPtr = timeArray;
2023 bufferLength = sizeof(SQL_TIME_STRUCT);
2024 break;
2025 }Lines 2023-2031 2023 bufferLength = sizeof(SQL_TIME_STRUCT);
2024 break;
2025 }
2026 case SQL_C_TYPE_TIMESTAMP: {
! 2027 LOG("BindParameterArray: Binding SQL_C_TYPE_TIMESTAMP array - param_index=%d, count=%zu", paramIndex, paramSetSize);
2028 SQL_TIMESTAMP_STRUCT* tsArray = AllocateParamBufferArray<SQL_TIMESTAMP_STRUCT>(tempBuffers, paramSetSize);
2029 strLenOrIndArray = AllocateParamBufferArray<SQLLEN>(tempBuffers, paramSetSize);
2030 for (size_t i = 0; i < paramSetSize; ++i) {
2031 if (columnValues[i].is_none()) {Lines 2042-2050 2042 tsArray[i].fraction = static_cast<SQLUINTEGER>(dtObj.attr("microsecond").cast<int>() * 1000); // µs to ns
2043 strLenOrIndArray[i] = 0;
2044 }
2045 }
! 2046 LOG("BindParameterArray: SQL_C_TYPE_TIMESTAMP bound - param_index=%d", paramIndex);
2047 dataPtr = tsArray;
2048 bufferLength = sizeof(SQL_TIMESTAMP_STRUCT);
2049 break;
2050 }Lines 2097-2105 2097 bufferLength = sizeof(DateTimeOffset);
2098 break;
2099 }
2100 case SQL_C_NUMERIC: {
! 2101 LOG("BindParameterArray: Binding SQL_C_NUMERIC array - param_index=%d, count=%zu", paramIndex, paramSetSize);
2102 SQL_NUMERIC_STRUCT* numericArray = AllocateParamBufferArray<SQL_NUMERIC_STRUCT>(tempBuffers, paramSetSize);
2103 strLenOrIndArray = AllocateParamBufferArray<SQLLEN>(tempBuffers, paramSetSize);
2104 for (size_t i = 0; i < paramSetSize; ++i) {
2105 const py::handle& element = columnValues[i];Lines 2108-2121 2108 std::memset(&numericArray[i], 0, sizeof(SQL_NUMERIC_STRUCT));
2109 continue;
2110 }
2111 if (!py::isinstance<NumericData>(element)) {
! 2112 LOG("BindParameterArray: NUMERIC type mismatch - param_index=%d, row=%zu", paramIndex, i);
2113 throw std::runtime_error(MakeParamMismatchErrorStr(info.paramCType, paramIndex));
2114 }
2115 NumericData decimalParam = element.cast<NumericData>();
! 2116 LOG("BindParameterArray: NUMERIC value - param_index=%d, row=%zu, precision=%d, scale=%d, sign=%d",
! 2117 paramIndex, i, decimalParam.precision, decimalParam.scale, decimalParam.sign);
2118 SQL_NUMERIC_STRUCT& target = numericArray[i];
2119 std::memset(&target, 0, sizeof(SQL_NUMERIC_STRUCT));
2120 target.precision = decimalParam.precision;
2121 target.scale = decimalParam.scale;Lines 2125-2133 2125 std::memcpy(target.val, decimalParam.val.data(), copyLen);
2126 }
2127 strLenOrIndArray[i] = sizeof(SQL_NUMERIC_STRUCT);
2128 }
! 2129 LOG("BindParameterArray: SQL_C_NUMERIC bound - param_index=%d", paramIndex);
2130 dataPtr = numericArray;
2131 bufferLength = sizeof(SQL_NUMERIC_STRUCT);
2132 break;
2133 }Lines 2151-2160 2151 }
2152 else if (py::isinstance<py::bytes>(element)) {
2153 py::bytes b = element.cast<py::bytes>();
2154 if (PyBytes_GET_SIZE(b.ptr()) != 16) {
! 2155 LOG("BindParameterArray: GUID bytes wrong length - param_index=%d, row=%zu, length=%d",
! 2156 paramIndex, i, PyBytes_GET_SIZE(b.ptr()));
2157 ThrowStdException("UUID binary data must be exactly 16 bytes long.");
2158 }
2159 std::memcpy(uuid_bytes.data(), PyBytes_AS_STRING(b.ptr()), 16);
2160 }Lines 2162-2170 2162 py::bytes b = element.attr("bytes_le").cast<py::bytes>();
2163 std::memcpy(uuid_bytes.data(), PyBytes_AS_STRING(b.ptr()), 16);
2164 }
2165 else {
! 2166 LOG("BindParameterArray: GUID type mismatch - param_index=%d, row=%zu", paramIndex, i);
2167 ThrowStdException(MakeParamMismatchErrorStr(info.paramCType, paramIndex));
2168 }
2169 guidArray[i].Data1 = (static_cast<uint32_t>(uuid_bytes[3]) << 24) |
2170 (static_cast<uint32_t>(uuid_bytes[2]) << 16) |Lines 2183-2191 2183 bufferLength = sizeof(SQLGUID);
2184 break;
2185 }
2186 default: {
! 2187 LOG("BindParameterArray: Unsupported C type - param_index=%d, C_type=%d", paramIndex, info.paramCType);
2188 ThrowStdException("BindParameterArray: Unsupported C type: " + std::to_string(info.paramCType));
2189 }
2190 }
2191 LOG("BindParameterArray: Calling SQLBindParameter - param_index=%d, buffer_length=%lld", Lines 2202-2215 2202 bufferLength,
2203 strLenOrIndArray
2204 );
2205 if (!SQL_SUCCEEDED(rc)) {
! 2206 LOG("BindParameterArray: SQLBindParameter failed - param_index=%d, SQLRETURN=%d", paramIndex, rc);
2207 return rc;
2208 }
2209 }
2210 } catch (...) {
! 2211 LOG("BindParameterArray: Exception during binding, cleaning up buffers");
2212 throw;
2213 }
2214 paramBuffers.insert(paramBuffers.end(), tempBuffers.begin(), tempBuffers.end());
2215 LOG("BindParameterArray: Successfully bound all parameters - total_params=%zu, buffer_count=%zu",Lines 2236-2246 2236 LOG("SQLExecuteMany: Using wide string query directly");
2237 #endif
2238 RETCODE rc = SQLPrepare_ptr(hStmt, queryPtr, SQL_NTS);
2239 if (!SQL_SUCCEEDED(rc)) {
! 2240 LOG("SQLExecuteMany: SQLPrepare failed - rc=%d", rc);
! 2241 return rc;
! 2242 }
2243 LOG("SQLExecuteMany: Query prepared successfully");
2244
2245 bool hasDAE = false;
2246 for (const auto& p : paramInfos) {Lines 2254-2270 2254 LOG("SQLExecuteMany: Using array binding (non-DAE) - calling BindParameterArray");
2255 std::vector<std::shared_ptr<void>> paramBuffers;
2256 rc = BindParameterArray(hStmt, columnwise_params, paramInfos, paramSetSize, paramBuffers);
2257 if (!SQL_SUCCEEDED(rc)) {
! 2258 LOG("SQLExecuteMany: BindParameterArray failed - rc=%d", rc);
! 2259 return rc;
! 2260 }
2261
2262 rc = SQLSetStmtAttr_ptr(hStmt, SQL_ATTR_PARAMSET_SIZE, (SQLPOINTER)paramSetSize, 0);
2263 if (!SQL_SUCCEEDED(rc)) {
! 2264 LOG("SQLExecuteMany: SQLSetStmtAttr(PARAMSET_SIZE) failed - rc=%d", rc);
! 2265 return rc;
! 2266 }
2267 LOG("SQLExecuteMany: PARAMSET_SIZE set to %zu", paramSetSize);
2268
2269 rc = SQLExecute_ptr(hStmt);
2270 LOG("SQLExecuteMany: SQLExecute completed - rc=%d", rc);Lines 2269-2342 2269 rc = SQLExecute_ptr(hStmt);
2270 LOG("SQLExecuteMany: SQLExecute completed - rc=%d", rc);
2271 return rc;
2272 } else {
! 2273 LOG("SQLExecuteMany: Using DAE (data-at-execution) - row_count=%zu", columnwise_params.size());
2274 size_t rowCount = columnwise_params.size();
2275 for (size_t rowIndex = 0; rowIndex < rowCount; ++rowIndex) {
! 2276 LOG("SQLExecuteMany: Processing DAE row %zu of %zu", rowIndex + 1, rowCount);
2277 py::list rowParams = columnwise_params[rowIndex];
2278
2279 std::vector<std::shared_ptr<void>> paramBuffers;
2280 rc = BindParameters(hStmt, rowParams, const_cast<std::vector<ParamInfo>&>(paramInfos), paramBuffers);
! 2281 if (!SQL_SUCCEEDED(rc)) {
! 2282 LOG("SQLExecuteMany: BindParameters failed for row %zu - rc=%d", rowIndex, rc);
! 2283 return rc;
! 2284 }
! 2285 LOG("SQLExecuteMany: Parameters bound for row %zu", rowIndex);
2286
2287 rc = SQLExecute_ptr(hStmt);
! 2288 LOG("SQLExecuteMany: SQLExecute for row %zu - initial_rc=%d", rowIndex, rc);
! 2289 size_t dae_chunk_count = 0;
2290 while (rc == SQL_NEED_DATA) {
2291 SQLPOINTER token;
2292 rc = SQLParamData_ptr(hStmt, &token);
! 2293 LOG("SQLExecuteMany: SQLParamData called - chunk=%zu, rc=%d, token=%p",
! 2294 dae_chunk_count, rc, token);
! 2295 if (!SQL_SUCCEEDED(rc) && rc != SQL_NEED_DATA) {
! 2296 LOG("SQLExecuteMany: SQLParamData failed - chunk=%zu, rc=%d", dae_chunk_count, rc);
! 2297 return rc;
! 2298 }
2299
2300 py::object* py_obj_ptr = reinterpret_cast<py::object*>(token);
! 2301 if (!py_obj_ptr) {
! 2302 LOG("SQLExecuteMany: NULL token pointer in DAE - chunk=%zu", dae_chunk_count);
! 2303 return SQL_ERROR;
! 2304 }
2305
2306 if (py::isinstance<py::str>(*py_obj_ptr)) {
2307 std::string data = py_obj_ptr->cast<std::string>();
2308 SQLLEN data_len = static_cast<SQLLEN>(data.size());
! 2309 LOG("SQLExecuteMany: Sending string DAE data - chunk=%zu, length=%lld",
! 2310 dae_chunk_count, static_cast<long long>(data_len));
2311 rc = SQLPutData_ptr(hStmt, (SQLPOINTER)data.c_str(), data_len);
! 2312 if (!SQL_SUCCEEDED(rc) && rc != SQL_NEED_DATA) {
! 2313 LOG("SQLExecuteMany: SQLPutData(string) failed - chunk=%zu, rc=%d", dae_chunk_count, rc);
! 2314 }
2315 } else if (py::isinstance<py::bytes>(*py_obj_ptr) || py::isinstance<py::bytearray>(*py_obj_ptr)) {
2316 std::string data = py_obj_ptr->cast<std::string>();
2317 SQLLEN data_len = static_cast<SQLLEN>(data.size());
! 2318 LOG("SQLExecuteMany: Sending bytes/bytearray DAE data - chunk=%zu, length=%lld",
! 2319 dae_chunk_count, static_cast<long long>(data_len));
2320 rc = SQLPutData_ptr(hStmt, (SQLPOINTER)data.c_str(), data_len);
! 2321 if (!SQL_SUCCEEDED(rc) && rc != SQL_NEED_DATA) {
! 2322 LOG("SQLExecuteMany: SQLPutData(bytes) failed - chunk=%zu, rc=%d", dae_chunk_count, rc);
! 2323 }
2324 } else {
! 2325 LOG("SQLExecuteMany: Unsupported DAE data type - chunk=%zu", dae_chunk_count);
2326 return SQL_ERROR;
2327 }
! 2328 dae_chunk_count++;
2329 }
! 2330 LOG("SQLExecuteMany: DAE completed for row %zu - total_chunks=%zu, final_rc=%d",
! 2331 rowIndex, dae_chunk_count, rc);
2332
! 2333 if (!SQL_SUCCEEDED(rc)) {
! 2334 LOG("SQLExecuteMany: DAE row %zu failed - rc=%d", rowIndex, rc);
! 2335 return rc;
! 2336 }
2337 }
! 2338 LOG("SQLExecuteMany: All DAE rows processed successfully - total_rows=%zu", rowCount);
2339 return SQL_SUCCESS;
2340 }
2341 }Lines 2344-2352 2344 // Wrap SQLNumResultCols
2345 SQLSMALLINT SQLNumResultCols_wrap(SqlHandlePtr statementHandle) {
2346 LOG("SQLNumResultCols: Getting number of columns in result set for statement_handle=%p", (void*)statementHandle->get());
2347 if (!SQLNumResultCols_ptr) {
! 2348 LOG("SQLNumResultCols: Function pointer not initialized, loading driver");
2349 DriverLoader::getInstance().loadDriver(); // Load the driver
2350 }
2351
2352 SQLSMALLINT columnCount;Lines 2358-2366 2358 // Wrap SQLDescribeCol
2359 SQLRETURN SQLDescribeCol_wrap(SqlHandlePtr StatementHandle, py::list& ColumnMetadata) {
2360 LOG("SQLDescribeCol: Getting column descriptions for statement_handle=%p", (void*)StatementHandle->get());
2361 if (!SQLDescribeCol_ptr) {
! 2362 LOG("SQLDescribeCol: Function pointer not initialized, loading driver");
2363 DriverLoader::getInstance().loadDriver(); // Load the driver
2364 }
2365
2366 SQLSMALLINT ColumnCount;Lines 2366-2374 2366 SQLSMALLINT ColumnCount;
2367 SQLRETURN retcode =
2368 SQLNumResultCols_ptr(StatementHandle->get(), &ColumnCount);
2369 if (!SQL_SUCCEEDED(retcode)) {
! 2370 LOG("SQLDescribeCol: Failed to get number of columns - SQLRETURN=%d", retcode);
2371 return retcode;
2372 }
2373
2374 for (SQLUSMALLINT i = 1; i <= ColumnCount; ++i) {Lines 2450-2460 2450 }
2451
2452 // Wrap SQLFetch to retrieve rows
2453 SQLRETURN SQLFetch_wrap(SqlHandlePtr StatementHandle) {
! 2454 LOG("SQLFetch: Fetching next row for statement_handle=%p", (void*)StatementHandle->get());
2455 if (!SQLFetch_ptr) {
! 2456 LOG("SQLFetch: Function pointer not initialized, loading driver");
2457 DriverLoader::getInstance().loadDriver(); // Load the driver
2458 }
2459
2460 return SQLFetch_ptr(StatementHandle->get());Lines 2487-2495 2487 oss << "Error fetching LOB for column " << colIndex
2488 << ", cType=" << cType
2489 << ", loop=" << loopCount
2490 << ", SQLGetData return=" << ret;
! 2491 LOG("FetchLobColumnData: %s", oss.str().c_str());
2492 ThrowStdException(oss.str());
2493 }
2494 if (actualRead == SQL_NULL_DATA) {
2495 LOG("FetchLobColumnData: Column %d is NULL at loop %d", colIndex, loopCount);Lines 2581-2589 2581 // Helper function to retrieve column data
2582 SQLRETURN SQLGetData_wrap(SqlHandlePtr StatementHandle, SQLUSMALLINT colCount, py::list& row) {
2583 LOG("SQLGetData: Getting data from %d columns for statement_handle=%p", colCount, (void*)StatementHandle->get());
2584 if (!SQLGetData_ptr) {
! 2585 LOG("SQLGetData: Function pointer not initialized, loading driver");
2586 DriverLoader::getInstance().loadDriver(); // Load the driver
2587 }
2588
2589 SQLRETURN ret = SQL_SUCCESS;Lines 2602-2610 2602
2603 ret = SQLDescribeCol_ptr(hStmt, i, columnName, sizeof(columnName) / sizeof(SQLWCHAR),
2604 &columnNameLen, &dataType, &columnSize, &decimalDigits, &nullable);
2605 if (!SQL_SUCCEEDED(ret)) {
! 2606 LOG("SQLGetData: Error retrieving metadata for column %d - SQLDescribeCol SQLRETURN=%d", i, ret);
2607 row.append(py::none());
2608 continue;
2609 }Lines 2634-2642 2634 row.append(std::string(reinterpret_cast<char*>(dataBuffer.data())));
2635 #endif
2636 } else {
2637 // Buffer too small, fallback to streaming
! 2638 LOG("SQLGetData: CHAR column %d data truncated (buffer_size=%zu), using streaming LOB", i, dataBuffer.size());
2639 row.append(FetchLobColumnData(hStmt, i, SQL_C_CHAR, false, false));
2640 }
2641 } else if (dataLen == SQL_NULL_DATA) {
2642 LOG("SQLGetData: Column %d is NULL (CHAR)", i);Lines 2643-2658 2643 row.append(py::none());
2644 } else if (dataLen == 0) {
2645 row.append(py::str(""));
2646 } else if (dataLen == SQL_NO_TOTAL) {
! 2647 LOG("SQLGetData: Cannot determine data length (SQL_NO_TOTAL) for column %d (SQL_CHAR), returning NULL", i);
2648 row.append(py::none());
2649 } else if (dataLen < 0) {
! 2650 LOG("SQLGetData: Unexpected negative data length for column %d - dataType=%d, dataLen=%ld", i, dataType, (long)dataLen);
2651 ThrowStdException("SQLGetData returned an unexpected negative data length");
2652 }
2653 } else {
! 2654 LOG("SQLGetData: Error retrieving data for column %d (SQL_CHAR) - SQLRETURN=%d, returning NULL", i, ret);
2655 row.append(py::none());
2656 }
2657 }
2658 break;Lines 2697-2712 2697 row.append(py::none());
2698 } else if (dataLen == 0) {
2699 row.append(py::str(""));
2700 } else if (dataLen == SQL_NO_TOTAL) {
! 2701 LOG("SQLGetData: Cannot determine NVARCHAR data length (SQL_NO_TOTAL) for column %d, returning NULL", i);
2702 row.append(py::none());
2703 } else if (dataLen < 0) {
! 2704 LOG("SQLGetData: Unexpected negative data length for column %d (NVARCHAR) - dataLen=%ld", i, (long)dataLen);
2705 ThrowStdException("SQLGetData returned an unexpected negative data length");
2706 }
2707 } else {
! 2708 LOG("SQLGetData: Error retrieving data for column %d (NVARCHAR) - SQLRETURN=%d", i, ret);
2709 row.append(py::none());
2710 }
2711 }
2712 break;Lines 2726-2734 2726 ret = SQLGetData_ptr(hStmt, i, SQL_C_SHORT, &smallIntValue, 0, NULL);
2727 if (SQL_SUCCEEDED(ret)) {
2728 row.append(static_cast<int>(smallIntValue));
2729 } else {
! 2730 LOG("SQLGetData: Error retrieving SQL_SMALLINT for column %d - SQLRETURN=%d", i, ret);
2731 row.append(py::none());
2732 }
2733 break;
2734 }Lines 2737-2745 2737 ret = SQLGetData_ptr(hStmt, i, SQL_C_FLOAT, &realValue, 0, NULL);
2738 if (SQL_SUCCEEDED(ret)) {
2739 row.append(realValue);
2740 } else {
! 2741 LOG("SQLGetData: Error retrieving SQL_REAL for column %d - SQLRETURN=%d", i, ret);
2742 row.append(py::none());
2743 }
2744 break;
2745 }Lines 2780-2793 2780 py::object decimalObj = PythonObjectCache::get_decimal_class()(py::str(cnum, safeLen));
2781 row.append(decimalObj);
2782 } catch (const py::error_already_set& e) {
2783 // If conversion fails, append None
! 2784 LOG("SQLGetData: Error converting to decimal for column %d - %s", i, e.what());
2785 row.append(py::none());
2786 }
2787 }
2788 else {
! 2789 LOG("SQLGetData: Error retrieving SQL_NUMERIC/DECIMAL for column %d - SQLRETURN=%d", i, ret);
2790 row.append(py::none());
2791 }
2792 break;
2793 }Lines 2798-2806 2798 ret = SQLGetData_ptr(hStmt, i, SQL_C_DOUBLE, &doubleValue, 0, NULL);
2799 if (SQL_SUCCEEDED(ret)) {
2800 row.append(doubleValue);
2801 } else {
! 2802 LOG("SQLGetData: Error retrieving SQL_DOUBLE/FLOAT for column %d - SQLRETURN=%d", i, ret);
2803 row.append(py::none());
2804 }
2805 break;
2806 }Lines 2809-2817 2809 ret = SQLGetData_ptr(hStmt, i, SQL_C_SBIGINT, &bigintValue, 0, NULL);
2810 if (SQL_SUCCEEDED(ret)) {
2811 row.append(static_cast<long long>(bigintValue));
2812 } else {
! 2813 LOG("SQLGetData: Error retrieving SQL_BIGINT for column %d - SQLRETURN=%d", i, ret);
2814 row.append(py::none());
2815 }
2816 break;
2817 }Lines 2846-2854 2846 timeValue.second
2847 )
2848 );
2849 } else {
! 2850 LOG("SQLGetData: Error retrieving SQL_TYPE_TIME for column %d - SQLRETURN=%d", i, ret);
2851 row.append(py::none());
2852 }
2853 break;
2854 }Lines 2870-2878 2870 timestampValue.fraction / 1000 // Convert back ns to µs
2871 )
2872 );
2873 } else {
! 2874 LOG("SQLGetData: Error retrieving SQL_TYPE_TIMESTAMP for column %d - SQLRETURN=%d", i, ret);
2875 row.append(py::none());
2876 }
2877 break;
2878 }Lines 2919-2927 2919 tzinfo
2920 );
2921 row.append(py_dt);
2922 } else {
! 2923 LOG("SQLGetData: Error fetching DATETIMEOFFSET for column %d - SQLRETURN=%d, indicator=%ld", i, ret, (long)indicator);
2924 row.append(py::none());
2925 }
2926 break;
2927 }Lines 2952-2964 2952 } else {
2953 std::ostringstream oss;
2954 oss << "Unexpected negative length (" << dataLen << ") returned by SQLGetData. ColumnID="
2955 << i << ", dataType=" << dataType << ", bufferSize=" << columnSize;
! 2956 LOG("SQLGetData: %s", oss.str().c_str());
2957 ThrowStdException(oss.str());
2958 }
2959 } else {
! 2960 LOG("SQLGetData: Error retrieving VARBINARY data for column %d - SQLRETURN=%d", i, ret);
2961 row.append(py::none());
2962 }
2963 }
2964 break;Lines 2968-2976 2968 ret = SQLGetData_ptr(hStmt, i, SQL_C_TINYINT, &tinyIntValue, 0, NULL);
2969 if (SQL_SUCCEEDED(ret)) {
2970 row.append(static_cast<int>(tinyIntValue));
2971 } else {
! 2972 LOG("SQLGetData: Error retrieving SQL_TINYINT for column %d - SQLRETURN=%d", i, ret);
2973 row.append(py::none());
2974 }
2975 break;
2976 }Lines 2979-2987 2979 ret = SQLGetData_ptr(hStmt, i, SQL_C_BIT, &bitValue, 0, NULL);
2980 if (SQL_SUCCEEDED(ret)) {
2981 row.append(static_cast<bool>(bitValue));
2982 } else {
! 2983 LOG("SQLGetData: Error retrieving SQL_BIT for column %d - SQLRETURN=%d", i, ret);
2984 row.append(py::none());
2985 }
2986 break;
2987 }Lines 3008-3016 3008 row.append(uuid_obj);
3009 } else if (indicator == SQL_NULL_DATA) {
3010 row.append(py::none());
3011 } else {
! 3012 LOG("SQLGetData: Error retrieving SQL_GUID for column %d - SQLRETURN=%d, indicator=%ld", i, ret, (long)indicator);
3013 row.append(py::none());
3014 }
3015 break;
3016 }Lines 3018-3026 3018 default:
3019 std::ostringstream errorString;
3020 errorString << "Unsupported data type for column - " << columnName << ", Type - "
3021 << dataType << ", column ID - " << i;
! 3022 LOG("SQLGetData: %s", errorString.str().c_str());
3023 ThrowStdException(errorString.str());
3024 break;
3025 }
3026 }Lines 3029-3037 3029
3030 SQLRETURN SQLFetchScroll_wrap(SqlHandlePtr StatementHandle, SQLSMALLINT FetchOrientation, SQLLEN FetchOffset, py::list& row_data) {
3031 LOG("SQLFetchScroll_wrap: Fetching with scroll orientation=%d, offset=%ld", FetchOrientation, (long)FetchOffset);
3032 if (!SQLFetchScroll_ptr) {
! 3033 LOG("SQLFetchScroll_wrap: Function pointer not initialized. Loading the driver.");
3034 DriverLoader::getInstance().loadDriver(); // Load the driver
3035 }
3036
3037 // Unbind any columns from previous fetch operations to avoid memory corruptionLines 3191-3199 3191 std::wstring columnName = columnMeta["ColumnName"].cast<std::wstring>();
3192 std::ostringstream errorString;
3193 errorString << "Unsupported data type for column - " << columnName.c_str()
3194 << ", Type - " << dataType << ", column ID - " << col;
! 3195 LOG("SQLBindColums: %s", errorString.str().c_str());
3196 ThrowStdException(errorString.str());
3197 break;
3198 }
3199 if (!SQL_SUCCEEDED(ret)) {Lines 3200-3208 3200 std::wstring columnName = columnMeta["ColumnName"].cast<std::wstring>();
3201 std::ostringstream errorString;
3202 errorString << "Failed to bind column - " << columnName.c_str() << ", Type - "
3203 << dataType << ", column ID - " << col;
! 3204 LOG("SQLBindColums: %s", errorString.str().c_str());
3205 ThrowStdException(errorString.str());
3206 return ret;
3207 }
3208 }Lines 3370-3378 3370 PyList_SET_ITEM(row, col - 1, Py_None);
3371 continue;
3372 } else if (dataLen < 0) {
3373 // Negative value is unexpected, log column index, SQL type & raise exception
! 3374 LOG("FetchBatchData: Unexpected negative data length - column=%d, SQL_type=%d, dataLen=%ld", col, dataType, (long)dataLen);
3375 ThrowStdException("Unexpected negative data length, check logs for details");
3376 }
3377 assert(dataLen > 0 && "Data length must be > 0");Lines 3481-3489 3481 std::wstring columnName = columnMeta["ColumnName"].cast<std::wstring>();
3482 std::ostringstream errorString;
3483 errorString << "Unsupported data type for column - " << columnName.c_str()
3484 << ", Type - " << dataType << ", column ID - " << col;
! 3485 LOG("FetchBatchData: %s", errorString.str().c_str());
3486 ThrowStdException(errorString.str());
3487 break;
3488 }
3489 }Lines 3579-3587 3579 std::wstring columnName = columnMeta["ColumnName"].cast<std::wstring>();
3580 std::ostringstream errorString;
3581 errorString << "Unsupported data type for column - " << columnName.c_str()
3582 << ", Type - " << dataType << ", column ID - " << col;
! 3583 LOG("calculateRowSize: %s", errorString.str().c_str());
3584 ThrowStdException(errorString.str());
3585 break;
3586 }
3587 }Lines 3611-3619 3611 // Retrieve column metadata
3612 py::list columnNames;
3613 ret = SQLDescribeCol_wrap(StatementHandle, columnNames);
3614 if (!SQL_SUCCEEDED(ret)) {
! 3615 LOG("FetchMany_wrap: Failed to get column descriptions - SQLRETURN=%d", ret);
3616 return ret;
3617 }
3618
3619 std::vector<SQLUSMALLINT> lobColumns;Lines 3650-3658 3650
3651 // Bind columns
3652 ret = SQLBindColums(hStmt, buffers, columnNames, numCols, fetchSize);
3653 if (!SQL_SUCCEEDED(ret)) {
! 3654 LOG("FetchMany_wrap: Error when binding columns - SQLRETURN=%d", ret);
3655 return ret;
3656 }
3657
3658 SQLULEN numRowsFetched;Lines 3660-3668 3660 SQLSetStmtAttr_ptr(hStmt, SQL_ATTR_ROWS_FETCHED_PTR, &numRowsFetched, 0);
3661
3662 ret = FetchBatchData(hStmt, buffers, columnNames, rows, numCols, numRowsFetched, lobColumns);
3663 if (!SQL_SUCCEEDED(ret) && ret != SQL_NO_DATA) {
! 3664 LOG("FetchMany_wrap: Error when fetching data - SQLRETURN=%d", ret);
3665 return ret;
3666 }
3667
3668 // Reset attributes before returning to avoid using stack pointers laterLines 3693-3701 3693 // Retrieve column metadata
3694 py::list columnNames;
3695 ret = SQLDescribeCol_wrap(StatementHandle, columnNames);
3696 if (!SQL_SUCCEEDED(ret)) {
! 3697 LOG("FetchAll_wrap: Failed to get column descriptions - SQLRETURN=%d", ret);
3698 return ret;
3699 }
3700
3701 // Define a memory limit (1 GB)Lines 3770-3778 3770
3771 // Bind columns
3772 ret = SQLBindColums(hStmt, buffers, columnNames, numCols, fetchSize);
3773 if (!SQL_SUCCEEDED(ret)) {
! 3774 LOG("FetchAll_wrap: Error when binding columns - SQLRETURN=%d", ret);
3775 return ret;
3776 }
3777
3778 SQLULEN numRowsFetched;Lines 3826-3834 3826 // Wrap SQLMoreResults
3827 SQLRETURN SQLMoreResults_wrap(SqlHandlePtr StatementHandle) {
3828 LOG("SQLMoreResults_wrap: Check for more results");
3829 if (!SQLMoreResults_ptr) {
! 3830 LOG("SQLMoreResults_wrap: Function pointer not initialized. Loading the driver.");
3831 DriverLoader::getInstance().loadDriver(); // Load the driver
3832 }
3833
3834 return SQLMoreResults_ptr(StatementHandle->get());Lines 3835-3845 3835 }
3836
3837 // Wrap SQLFreeHandle
3838 SQLRETURN SQLFreeHandle_wrap(SQLSMALLINT HandleType, SqlHandlePtr Handle) {
! 3839 LOG("SQLFreeHandle_wrap: Free SQL handle type=%d", HandleType);
3840 if (!SQLAllocHandle_ptr) {
! 3841 LOG("SQLFreeHandle_wrap: Function pointer not initialized. Loading the driver.");
3842 DriverLoader::getInstance().loadDriver(); // Load the driver
3843 }
3844
3845 SQLRETURN ret = SQLFreeHandle_ptr(HandleType, Handle->get());Lines 3843-3851 3843 }
3844
3845 SQLRETURN ret = SQLFreeHandle_ptr(HandleType, Handle->get());
3846 if (!SQL_SUCCEEDED(ret)) {
! 3847 LOG("SQLFreeHandle_wrap: SQLFreeHandle failed with error code - %d", ret);
3848 return ret;
3849 }
3850 return ret;
3851 }Lines 3853-3861 3853 // Wrap SQLRowCount
3854 SQLLEN SQLRowCount_wrap(SqlHandlePtr StatementHandle) {
3855 LOG("SQLRowCount_wrap: Get number of rows affected by last execute");
3856 if (!SQLRowCount_ptr) {
! 3857 LOG("SQLRowCount_wrap: Function pointer not initialized. Loading the driver.");
3858 DriverLoader::getInstance().loadDriver(); // Load the driver
3859 }
3860
3861 SQLLEN rowCount;Lines 3860-3868 3860
3861 SQLLEN rowCount;
3862 SQLRETURN ret = SQLRowCount_ptr(StatementHandle->get(), &rowCount);
3863 if (!SQL_SUCCEEDED(ret)) {
! 3864 LOG("SQLRowCount_wrap: SQLRowCount failed with error code - %d", ret);
3865 return ret;
3866 }
3867 LOG("SQLRowCount_wrap: SQLRowCount returned %ld", (long)rowCount);
3868 return rowCount;Lines 4041-4050 4041 mssql_python::logging::LoggerBridge::initialize();
4042 } catch (const std::exception& e) {
4043 // Log initialization failure but don't throw
4044 // Use std::cerr instead of fprintf for type-safe output
! 4045 std::cerr << "Logger bridge initialization failed: " << e.what() << std::endl;
! 4046 }
4047
4048 try {
4049 // Try loading the ODBC driver when the module is imported
4050 LOG("Module initialization: Loading ODBC driver");Lines 4050-4057 4050 LOG("Module initialization: Loading ODBC driver");
4051 DriverLoader::getInstance().loadDriver(); // Load the driver
4052 } catch (const std::exception& e) {
4053 // Log the error but don't throw - let the error happen when functions are called
! 4054 LOG("Module initialization: Failed to load ODBC driver - %s", e.what());
4055 }
4056 }mssql_python/pybind/logger_bridge.cppLines 26-35 26 std::lock_guard<std::mutex> lock(mutex_);
27
28 // Skip if already initialized (check inside lock to prevent TOCTOU race)
29 if (initialized_) {
! 30 return;
! 31 }
32
33 try {
34 // Acquire GIL for Python API calls
35 py::gil_scoped_acquire gil;Lines 55-68 55
56 } catch (const py::error_already_set& e) {
57 // Failed to initialize - log to stderr and continue
58 // (logging will be disabled but won't crash)
! 59 std::cerr << "LoggerBridge initialization failed: " << e.what() << std::endl;
! 60 initialized_ = false;
! 61 } catch (const std::exception& e) {
! 62 std::cerr << "LoggerBridge initialization failed: " << e.what() << std::endl;
! 63 initialized_ = false;
! 64 }
65 }
66
67 void LoggerBridge::updateLevel(int level) {
68 // Update the cached level atomicallyLines 69-83 69 // This is lock-free and can be called from any thread
70 cached_level_.store(level, std::memory_order_relaxed);
71 }
72
! 73 int LoggerBridge::getLevel() {
! 74 return cached_level_.load(std::memory_order_relaxed);
! 75 }
76
! 77 bool LoggerBridge::isInitialized() {
! 78 return initialized_;
! 79 }
80
81 std::string LoggerBridge::formatMessage(const char* format, va_list args) {
82 // Use a stack buffer for most messages (4KB should be enough)
83 char buffer[4096];Lines 92-101 92 va_end(args_copy);
93
94 if (result < 0) {
95 // Error during formatting
! 96 return "[Formatting error]";
! 97 }
98
99 if (result < static_cast<int>(sizeof(buffer))) {
100 // Message fit in buffer (vsnprintf guarantees null-termination)
101 return std::string(buffer, std::min(static_cast<size_t>(result), sizeof(buffer) - 1));Lines 102-123 102 }
103
104 // Message was truncated - allocate larger buffer
105 // (This should be rare for typical log messages)
! 106 std::vector<char> large_buffer(result + 1);
! 107 va_copy(args_copy, args);
108 // Use std::vsnprintf with explicit size for safety (C++11 standard)
109 // This is the recommended safe alternative to vsprintf
110 // DevSkim: ignore DS185832 - std::vsnprintf with size is safe
! 111 int final_result = std::vsnprintf(large_buffer.data(), large_buffer.size(), format, args_copy);
! 112 va_end(args_copy);
113
114 // Ensure null termination even if formatting fails
! 115 if (final_result < 0 || final_result >= static_cast<int>(large_buffer.size())) {
! 116 large_buffer[large_buffer.size() - 1] = '\0';
! 117 }
118
! 119 return std::string(large_buffer.data());
120 }
121
122 const char* LoggerBridge::extractFilename(const char* path) {
123 // Extract just the filename from full path using safer C++ string searchLines 121-130 121
122 const char* LoggerBridge::extractFilename(const char* path) {
123 // Extract just the filename from full path using safer C++ string search
124 if (!path) {
! 125 return "";
! 126 }
127
128 // Find last occurrence of Unix path separator
129 const char* filename = std::strrchr(path, '/');
130 if (filename) {Lines 131-146 131 return filename + 1;
132 }
133
134 // Try Windows path separator
! 135 filename = std::strrchr(path, '\\');
! 136 if (filename) {
! 137 return filename + 1;
! 138 }
139
140 // No path separator found, return the whole string
! 141 return path;
! 142 }
143
144 void LoggerBridge::log(int level, const char* file, int line,
145 const char* format, ...) {
146 // Fast level check (should already be done by macro, but double-check)Lines 144-158 144 void LoggerBridge::log(int level, const char* file, int line,
145 const char* format, ...) {
146 // Fast level check (should already be done by macro, but double-check)
147 if (!isLoggable(level)) {
! 148 return;
! 149 }
150
151 // Check if initialized
152 if (!initialized_ || !cached_logger_) {
! 153 return;
! 154 }
155
156 // Format the message
157 va_list args;
158 va_start(args, format);Lines 172-184 172 // Warn if message exceeds reasonable size (critical for troubleshooting)
173 constexpr size_t MAX_LOG_SIZE = 4095; // Keep same limit for consistency
174 if (complete_message.size() > MAX_LOG_SIZE) {
175 // Use stderr to notify about truncation (logging may be the truncated call itself)
! 176 std::cerr << "[MSSQL-Python] Warning: Log message truncated from "
! 177 << complete_message.size() << " bytes to " << MAX_LOG_SIZE
! 178 << " bytes at " << file << ":" << line << std::endl;
! 179 complete_message.resize(MAX_LOG_SIZE);
! 180 }
181
182 // Lock for Python call (minimize critical section)
183 std::lock_guard<std::mutex> lock(mutex_);
184 Lines 211-226 211
212 } catch (const py::error_already_set& e) {
213 // Python error during logging - ignore to prevent cascading failures
214 // (Logging errors should not crash the application)
! 215 (void)e; // Suppress unused variable warning
! 216 } catch (const std::exception& e) {
217 // Standard C++ exception - ignore
! 218 (void)e;
! 219 } catch (...) {
220 // Catch-all for unknown exceptions (non-standard exceptions, corrupted state, etc.)
221 // Logging must NEVER crash the application
! 222 }
223 }
224
225 } // namespace logging
226 } // namespace mssql_python📋 Files Needing Attention📉 Files with overall lowest coverage (click to expand)mssql_python.pybind.logger_bridge.cpp: 59.2%
mssql_python.helpers.py: 66.6%
mssql_python.row.py: 67.4%
mssql_python.pybind.ddbc_bindings.cpp: 70.4%
mssql_python.pybind.connection.connection.cpp: 76.3%
mssql_python.ddbc_bindings.py: 79.6%
mssql_python.pybind.connection.connection_pool.cpp: 79.6%
mssql_python.pybind.ddbc_bindings.h: 79.7%
mssql_python.connection.py: 82.5%
mssql_python.cursor.py: 83.5%🔗 Quick Links
|
…nflict and include logger_bridge.hpp in ddbc_bindings.h
…e C++11 functions
- Changed log filename format: timestamp now has no separator (YYYYMMDDHHMMSS) - Added CSV header with metadata: script name, PID, Python version, OS info - Converted log format to CSV: Timestamp, ThreadID, Level, Location, Source, Message - Replaced trace ID with OS native thread ID for debugger compatibility - Updated Python formatter to parse [Python]/[DDBC] tags into Source column - Updated C++ logger_bridge to use makeRecord() for proper file/line attribution - Logs are now easily parseable as CSV for analysis in Excel/pandas - Counter logic for connection/cursor tracking kept internally but not displayed
- Updated LOGGING.md: * Changed log format examples from trace ID to CSV format * Updated filename format (YYYYMMDDHHMMSS with no separators) * Replaced trace ID section with Thread Tracking section * Added CSV parsing examples with pandas * Updated all log output samples to show CSV columns - Updated MSSQL-Python-Logging-Design.md: * Changed file handler config to describe CSV format * Replaced Trace ID System with Thread Tracking System * Updated architecture to reflect OS native thread IDs * Added CSV formatter implementation details * Updated all code examples to use setup_logging() API * Changed log output examples to CSV format - Thread tracking now uses OS native thread IDs (threading.get_native_id()) - CSV columns: Timestamp, ThreadID, Level, Location, Source, Message - File header includes metadata (PID, script name, Python version, etc.) - Easy analysis with pandas/Excel/CSV tools
- CSV format now mentioned only once as optional import capability - Focus on log structure and content, not format - Removed repetitive CSV parsing examples - Single section 'Importing Logs as CSV (Optional)' in LOGGING.md - Brief mention in design doc that format is importable as CSV
Features: - Whitelist log file extensions: .txt, .log, .csv only - Raise ValueError for invalid extensions - Export driver_logger for use in application code - Allow apps to use mssql-python's logger: from mssql_python.logging import driver_logger - Updated documentation with usage examples - Added validation in _setLevel() method Benefits: - Prevents accidental use of wrong file types - Clear error messages for invalid extensions - Unified logging - apps can use same logger as driver - Same format and thread tracking for app logs
- Added 'Executing query:' log at start of execute() method - Removed duplicate log statement that was causing queries to appear twice - executemany() uses existing detailed log (shows parameter set count) - Each query now logged exactly once at DEBUG level - Parameters excluded from basic query log (pending PII review)
… (Linux/macOS) Problem: - Linux/macOS performed double conversion for NVARCHAR columns - SQLWCHAR → std::wstring (via SQLWCHARToWString) → Python unicode - Created unnecessary intermediate std::wstring allocation Solution: - Use PyUnicode_DecodeUTF16() to convert UTF-16 directly to Python unicode - Single-step conversion eliminates intermediate allocation - Platform-specific optimization (Linux/macOS only) Impact: - Reduces memory allocations for wide-character string columns - Eliminates one full conversion step per NVARCHAR cell - Regular VARCHAR/CHAR columns unchanged (already optimal)
… (Linux/macOS) Problem: - Linux/macOS performed double conversion for NVARCHAR columns - SQLWCHAR → std::wstring (via SQLWCHARToWString) → Python unicode - Created unnecessary intermediate std::wstring allocation Solution: - Use PyUnicode_DecodeUTF16() to convert UTF-16 directly to Python unicode - Single-step conversion eliminates intermediate allocation - Platform-specific optimization (Linux/macOS only) Impact: - Reduces memory allocations for wide-character string columns - Eliminates one full conversion step per NVARCHAR cell - Regular VARCHAR/CHAR columns unchanged (already optimal)
Problem: - All numeric conversions used pybind11 wrappers with overhead: * Type detection, wrapper object creation, bounds checking * ~20-40 CPU cycles overhead per cell Solution: - Use direct Python C API calls: * PyLong_FromLong/PyLong_FromLongLong for integers * PyFloat_FromDouble for floats * PyBool_FromLong for booleans * PyList_SET_ITEM macro (no bounds check - list pre-sized) Changes: - SQL_INTEGER, SQL_SMALLINT, SQL_BIGINT, SQL_TINYINT → PyLong_* - SQL_BIT → PyBool_FromLong - SQL_REAL, SQL_DOUBLE, SQL_FLOAT → PyFloat_FromDouble - Added explicit NULL handling for each type Impact: - Eliminates pybind11 wrapper overhead for simple numeric types - Direct array access via PyList_SET_ITEM macro - Affects 7 common numeric SQL types
Problem: -------- Column metadata (dataType, columnSize, isLob, fetchBufferSize) was accessed from the columnInfos vector inside the hot row processing loop. For a query with 1,000 rows × 10 columns, this resulted in 10,000 struct field accesses. Each access involves: - Vector bounds checking - Large struct loading (~50+ bytes per ColumnInfo) - Poor cache locality (struct fields scattered in memory) - Cost: ~10-15 CPU cycles per access (L2 cache misses likely) Solution: --------- Prefetch metadata into tightly-packed local arrays before the row loop: - std::vector<SQLSMALLINT> dataTypes (2 bytes per element) - std::vector<SQLULEN> columnSizes (8 bytes per element) - std::vector<uint64_t> fetchBufferSizes (8 bytes per element) - std::vector<bool> isLobs (1 byte per element) Total: ~190 bytes for 10 columns vs 500+ bytes with structs. These arrays stay hot in L1 cache for the entire batch processing, eliminating repeated struct access overhead. Changes: -------- - Added 4 prefetch vectors before row processing loop - Added prefetch loop to populate metadata arrays (read columnInfos once) - Replaced all columnInfos[col-1].field accesses with array lookups - Updated SQL_CHAR/SQL_VARCHAR cases - Updated SQL_WCHAR/SQL_WVARCHAR cases - Updated SQL_BINARY/SQL_VARBINARY cases Impact: ------- - Eliminates O(rows × cols) metadata lookups - 10,000 array accesses @ 3-5 cycles vs 10,000 struct accesses @ 10-15 cycles - ~70% reduction in metadata access overhead - Better L1 cache utilization (190 bytes vs 500+ bytes) - Expected 15-25% overall performance improvement on large result sets
…icrosoft/mssql-python into bewithgaurav/logging_framework
sumitmsft
reviewed
Nov 12, 2025
sumitmsft
reviewed
Nov 12, 2025
sumitmsft
reviewed
Nov 12, 2025
Collaborator
Author
Coverage Note: LOG Statements Not CoveredCurrent coverage: ~77% excludes ~150 C++ LOG() statements Why? Tests don't initialize logging (disabled by default for performance), so LOG statements return early without executing: if (!s_pythonLogger) return; // Early exit when logging disabledAttempted solutions:
Decision: Accept the gap. LOG statements work correctly in production when enabled. Can revisit in future PRs dedicated to increase coverage. |
sumitmsft
previously approved these changes
Nov 13, 2025
sumitmsft
approved these changes
Nov 13, 2025
bewithgaurav
changed the title
subrata-ms
approved these changes
Nov 13, 2025
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Work Item / Issue Reference
Summary
Logging Framework Implementation
Overview
Implements a comprehensive logging system for mssql-python with both Python and C++ components, replacing the previous fragmented approach with a unified, performance-optimized solution.
Key Changes
🎯 Core Logging System
mssql_python/logging.py): Single DEBUG-level logger with file/stdout/both output modesmssql_python/pybind/logger_bridge.cpp): High-performance bridge from C++ to Python logging with zero overhead when disabledsetup_logging(output='file'|'stdout'|'both')- all-or-nothing DEBUG logging for troubleshooting🔧 Technical Improvements
📝 Logging Coverage
warnings.warn()calls with proper logging🧪 Testing & Quality
rownumberassertion (was expectingNone, should be-1)📚 Documentation
learnings/directoryPerformance Impact
Breaking Changes
logging_config.pyandget_logger()APIsetup_logging(output='file')for DEBUG loggingTesting
Related Work