From ceb6e971db6795b84e28abb1c3f95967c56aee00 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 20 May 2026 06:37:05 +0000 Subject: [PATCH 01/31] Initial plan From 4b6d98ee54017159dc3840191fec7f9b71a61a74 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 20 May 2026 06:41:50 +0000 Subject: [PATCH 02/31] feat: format SQL logs with DECLARE statements for readable output Agent-Logs-Url: https://github.com/durlabhjain/dframework-node/sessions/d09a10ce-2641-4551-b0a7-b3f28054ec3b Co-authored-by: tushar-singh-spraxa <231176744+tushar-singh-spraxa@users.noreply.github.com> --- lib/sql.js | 122 +++++++++++++++++++++++++++++++---- tests/sql-log-format.test.js | 98 ++++++++++++++++++++++++++++ 2 files changed, 206 insertions(+), 14 deletions(-) create mode 100644 tests/sql-log-format.test.js diff --git a/lib/sql.js b/lib/sql.js index 2202fcb..6b9c968 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -1,4 +1,5 @@ import mssql from 'mssql'; +import dayjs from 'dayjs'; import fs from 'fs-extra'; import zlib from 'zlib'; import logger from './logger.js'; @@ -12,15 +13,112 @@ const isNullNotNullOperators = ['IS NOT NULL', 'IS NULL']; const whereClauseRegex = /\bWHERE\b/i; const appendAndBoundaryRegex = /\b(?:ORDER\s+BY|GROUP\s+BY|HAVING|OFFSET|FETCH)\b/i; +const mssqlSqlTypeMap = { + BigInt: 'BIGINT', + Binary: 'BINARY', + Bit: 'BIT', + Char: 'CHAR', + Date: 'DATE', + DateTime: 'DATETIME', + DateTime2: 'DATETIME2', + DateTimeOffset: 'DATETIMEOFFSET', + Decimal: 'DECIMAL', + Float: 'FLOAT', + Image: 'IMAGE', + Int: 'INT', + Money: 'MONEY', + NChar: 'NCHAR', + NText: 'NTEXT', + Numeric: 'NUMERIC', + NVarChar: 'NVARCHAR', + Real: 'REAL', + SmallDateTime: 'SMALLDATETIME', + SmallInt: 'SMALLINT', + SmallMoney: 'SMALLMONEY', + Text: 'TEXT', + Time: 'TIME', + TinyInt: 'TINYINT', + UniqueIdentifier: 'UNIQUEIDENTIFIER', + VarBinary: 'VARBINARY', + VarChar: 'VARCHAR', + Xml: 'XML' +}; + +const stringifySqlValue = (value) => { + if (value === null || value === undefined) { + return 'NULL'; + } + if (typeof value === 'string') { + return `'${value.replace(/'/g, "''")}'`; + } + if (typeof value === 'number') { + return Number.isFinite(value) ? String(value) : 'NULL'; + } + if (typeof value === 'boolean') { + return value ? '1' : '0'; + } + if (value instanceof Date) { + return `'${dayjs(value).format('YYYY-MM-DD HH:mm:ss.SSS')}'`; + } + if (Buffer.isBuffer(value)) { + return `0x${value.toString('hex')}`; + } + return `'${JSON.stringify(value).replace(/'/g, "''")}'`; +}; + +const getSqlTypeFromParameter = (parameter) => { + const type = parameter?.type?.type || parameter?.type; + const typeName = type?.name; + const sqlType = mssqlSqlTypeMap[typeName] || typeName?.toUpperCase() || 'NVARCHAR(MAX)'; + if (sqlType === 'VARCHAR' || sqlType === 'NVARCHAR' || sqlType === 'VARBINARY' || sqlType === 'CHAR' || sqlType === 'NCHAR' || sqlType === 'BINARY') { + if (parameter?.length === mssql.MAX) { + return `${sqlType}(MAX)`; + } + if (Number.isFinite(parameter?.length)) { + return `${sqlType}(${parameter.length})`; + } + } + if (sqlType === 'DECIMAL' || sqlType === 'NUMERIC') { + if (Number.isFinite(parameter?.precision) && Number.isFinite(parameter?.scale)) { + return `${sqlType}(${parameter.precision},${parameter.scale})`; + } + if (Number.isFinite(parameter?.precision)) { + return `${sqlType}(${parameter.precision})`; + } + } + if ((sqlType === 'DATETIME2' || sqlType === 'TIME' || sqlType === 'DATETIMEOFFSET') && Number.isFinite(parameter?.scale)) { + return `${sqlType}(${parameter.scale})`; + } + return sqlType; +}; + +const toParameterDescriptor = (name, parameter) => { + if (parameter && typeof parameter === 'object' && ('value' in parameter || 'type' in parameter)) { + return { name: parameter.name || name, ...parameter }; + } + return { name, value: parameter }; +}; + +const formatSqlQueryForLog = ({ query, parameters } = {}) => { + const params = parameters || {}; + const declareLines = Object.entries(params).map(([name, parameter]) => { + const descriptor = toParameterDescriptor(name, parameter); + const sqlType = getSqlTypeFromParameter(descriptor); + const sqlValue = stringifySqlValue(descriptor.value); + return `DECLARE @${descriptor.name} ${sqlType} = ${sqlValue}`; + }); + if (declareLines.length === 0) { + return query || ''; + } + return `${declareLines.join('\n')}\n\n${query || ''}`; +}; + const createQueryLogger = function ({ queryLogThreshold, timeoutLogLevel, logger }) { return async function ({ query, start, end = Date.now(), parameters }) { const queryDurationInMs = (end - start); if (queryDurationInMs > queryLogThreshold) { - logger[timeoutLogLevel]({ - query: query, - duration: `${queryDurationInMs}ms`, - parameters: parameters - }); + const formattedQuery = formatSqlQueryForLog({ query, parameters }); + logger[timeoutLogLevel](`SQL query duration ${queryDurationInMs}ms\n${formattedQuery}`); } }; } @@ -165,7 +263,8 @@ class Sql { return { success: true, data: result.recordset, ...result }; } catch (err) { const loggerToUse = request._logger || this.logger; - loggerToUse.error({ err, query, parameters: request.parameters, type }); + const formattedQuery = formatSqlQueryForLog({ query, parameters: request.parameters }); + loggerToUse.error({ err, type }, `SQL query failed\n${formattedQuery}`); return { success: false, err, data: {} }; } } @@ -174,13 +273,8 @@ class Sql { const executionTime = Date.now() - startTime; if (executionTime > maxQueryTime) { // 500 milliseconds const loggerToUse = request._logger || this.logger; - loggerToUse.warn({ - message: `Query execution exceeded ${maxQueryTime} milliseconds`, - query, - executionTime: `${executionTime}ms`, - type, - parameters: request.parameters || request.params - }); + const formattedQuery = formatSqlQueryForLog({ query, parameters: request.parameters || request.params }); + loggerToUse.warn(`Query execution exceeded ${maxQueryTime} milliseconds (${executionTime}ms) [${type}]\n${formattedQuery}`); } } @@ -1146,4 +1240,4 @@ class Sql { export default Sql; -export { mssql, createQueryLogger }; +export { mssql, createQueryLogger, formatSqlQueryForLog }; diff --git a/tests/sql-log-format.test.js b/tests/sql-log-format.test.js new file mode 100644 index 0000000..18e24f6 --- /dev/null +++ b/tests/sql-log-format.test.js @@ -0,0 +1,98 @@ +import { test } from 'node:test'; +import assert from 'node:assert/strict'; +import Sql, { createQueryLogger, formatSqlQueryForLog, mssql } from '../lib/sql.js'; + +const buildParameters = () => { + const request = new mssql.Request(); + request.input('Id', mssql.Int, 5); + request.input('Name', mssql.VarChar(20), "O'Brien"); + request.input('CreatedOn', mssql.DateTime2, new Date('2025-01-02T03:04:05.678Z')); + request.input('IsActive', mssql.Bit, true); + request.input('OptionalValue', mssql.Int, null); + return request.parameters; +}; + +test('formatSqlQueryForLog prints DECLARE statements and readable SQL', () => { + const query = 'SELECT *\nFROM Users\tWHERE Id = @Id'; + const formattedQuery = formatSqlQueryForLog({ query, parameters: buildParameters() }); + + assert.match(formattedQuery, /DECLARE @Id INT = 5/); + assert.match(formattedQuery, /DECLARE @Name VARCHAR\(20\) = 'O''Brien'/); + assert.match(formattedQuery, /DECLARE @CreatedOn DATETIME2 = '2025-01-02 03:04:05\.678'/); + assert.match(formattedQuery, /DECLARE @IsActive BIT = 1/); + assert.match(formattedQuery, /DECLARE @OptionalValue INT = NULL/); + assert.ok(formattedQuery.endsWith(query)); +}); + +test('createQueryLogger logs formatted multiline SQL when threshold is exceeded', async () => { + const calls = []; + const logger = { + warn: (...args) => calls.push(args) + }; + const queryLogger = createQueryLogger({ queryLogThreshold: 5, timeoutLogLevel: 'warn', logger }); + const query = 'SELECT *\nFROM Users\tWHERE Id = @Id'; + + await queryLogger({ + query, + start: 100, + end: 200, + parameters: buildParameters() + }); + + assert.strictEqual(calls.length, 1); + assert.match(calls[0][0], /SQL query duration 100ms/); + assert.match(calls[0][0], /DECLARE @Id INT = 5/); + assert.ok(calls[0][0].includes('\nFROM Users\tWHERE Id = @Id')); +}); + +test('slow-query and error log sites use formatted SQL output', async () => { + const warnCalls = []; + const errorCalls = []; + const mockLogger = { + warn: (...args) => warnCalls.push(args), + error: (...args) => errorCalls.push(args) + }; + const sql = new Sql(); + const query = 'SELECT *\nFROM Users\tWHERE Id = @Id'; + const parameters = buildParameters(); + + const originalDateNow = Date.now; + Date.now = () => 1000; + try { + sql.logSlowQuery({ + startTime: 100, + query, + type: 'query', + request: { _logger: mockLogger, parameters } + }); + } finally { + Date.now = originalDateNow; + } + + assert.strictEqual(warnCalls.length, 1); + assert.match(warnCalls[0][0], /Query execution exceeded 500 milliseconds/); + assert.match(warnCalls[0][0], /DECLARE @Id INT = 5/); + assert.ok(warnCalls[0][0].includes('\nFROM Users\tWHERE Id = @Id')); + + const expectedError = new Error('forced failure'); + const result = await sql.runQuery({ + request: { + _logger: mockLogger, + parameters, + query: async () => { + throw expectedError; + } + }, + type: 'query', + query + }); + + assert.strictEqual(result.success, false); + assert.strictEqual(result.err, expectedError); + assert.strictEqual(errorCalls.length, 1); + assert.strictEqual(errorCalls[0][0].err, expectedError); + assert.strictEqual(errorCalls[0][0].type, 'query'); + assert.match(errorCalls[0][1], /SQL query failed/); + assert.match(errorCalls[0][1], /DECLARE @Id INT = 5/); + assert.ok(errorCalls[0][1].includes('\nFROM Users\tWHERE Id = @Id')); +}); From ab9962ebc16cda842325842f3ff3481b7bfe6f21 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Thu, 21 May 2026 13:11:00 +0000 Subject: [PATCH 03/31] feat: format TVP params in SQL log output as DECLARE and INSERT Agent-Logs-Url: https://github.com/durlabhjain/dframework-node/sessions/fb06d526-c59d-401a-bcc5-1c8281924f0e Co-authored-by: tushar-singh-spraxa <231176744+tushar-singh-spraxa@users.noreply.github.com> --- lib/sql.js | 41 ++++++++++++++++++++++++++++++++++-- tests/sql-log-format.test.js | 39 ++++++++++++++++++++++++++++++++++ 2 files changed, 78 insertions(+), 2 deletions(-) diff --git a/lib/sql.js b/lib/sql.js index 6b9c968..4bf188f 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -99,14 +99,51 @@ const toParameterDescriptor = (name, parameter) => { return { name, value: parameter }; }; +const getTvpPath = (table) => { + if (table?.path) { + return table.path; + } + if (table?.schema && table?.name) { + return `[${table.schema}].[${table.name}]`; + } + if (table?.name) { + return `[${table.name}]`; + } + return '[dbo].[UnknownTableType]'; +}; + +const formatTvpParameter = (descriptor) => { + const tvp = descriptor.value; + const columnNames = (tvp.columns || []).map((column) => column.name); + const rows = tvp.rows || []; + const lines = [`DECLARE @${descriptor.name} ${getTvpPath(tvp)}`]; + if (columnNames.length === 0 || rows.length === 0) { + return lines; + } + const columnsClause = columnNames.map((name) => `[${name}]`).join(', '); + const rowBatchSize = 100; + for (let index = 0; index < rows.length; index += rowBatchSize) { + const batchRows = rows.slice(index, index + rowBatchSize); + const valuesClause = batchRows.map((row) => { + const values = columnNames.map((_, colIndex) => stringifySqlValue(row[colIndex])); + return `(${values.join(', ')})`; + }).join(',\n'); + lines.push(`INSERT INTO @${descriptor.name} (${columnsClause}) VALUES\n${valuesClause};`); + } + return lines; +}; + const formatSqlQueryForLog = ({ query, parameters } = {}) => { const params = parameters || {}; - const declareLines = Object.entries(params).map(([name, parameter]) => { - const descriptor = toParameterDescriptor(name, parameter); + const descriptors = Object.entries(params).map(([name, parameter]) => toParameterDescriptor(name, parameter)); + const tvpDescriptors = descriptors.filter((descriptor) => descriptor.value instanceof mssql.Table); + const scalarDeclareLines = descriptors.filter((descriptor) => !(descriptor.value instanceof mssql.Table)).map((descriptor) => { const sqlType = getSqlTypeFromParameter(descriptor); const sqlValue = stringifySqlValue(descriptor.value); return `DECLARE @${descriptor.name} ${sqlType} = ${sqlValue}`; }); + const tvpLines = tvpDescriptors.flatMap((descriptor) => formatTvpParameter(descriptor)); + const declareLines = [...tvpLines, ...scalarDeclareLines]; if (declareLines.length === 0) { return query || ''; } diff --git a/tests/sql-log-format.test.js b/tests/sql-log-format.test.js index 18e24f6..0fe60be 100644 --- a/tests/sql-log-format.test.js +++ b/tests/sql-log-format.test.js @@ -24,6 +24,45 @@ test('formatSqlQueryForLog prints DECLARE statements and readable SQL', () => { assert.ok(formattedQuery.endsWith(query)); }); +test('formatSqlQueryForLog renders TVP as DECLARE + INSERT statements (not JSON)', () => { + const request = new mssql.Request(); + const tvp = new mssql.Table('dbo.StringList'); + tvp.columns.add('Value', mssql.VarChar(500), { nullable: false }); + tvp.rows.add('Alpha'); + tvp.rows.add("Bob's Item"); + request.input('ListParam', tvp); + request.input('Id', mssql.Int, 7); + + const query = 'SELECT *\nFROM dbo.Users\tWHERE UserId = @Id'; + const formattedQuery = formatSqlQueryForLog({ query, parameters: request.parameters }); + + assert.match(formattedQuery, /DECLARE @ListParam \[dbo\]\.\[StringList\]/); + assert.match(formattedQuery, /INSERT INTO @ListParam \(\[Value\]\) VALUES/); + assert.match(formattedQuery, /\('Alpha'\),\n\('Bob''s Item'\);/); + assert.match(formattedQuery, /DECLARE @Id INT = 7/); + assert.ok(!formattedQuery.includes('"columns"')); + assert.ok(!formattedQuery.includes('"rows"')); + assert.ok(formattedQuery.endsWith(query)); +}); + +test('TVP INSERT statements are batched at 100 rows', () => { + const request = new mssql.Request(); + const tvp = new mssql.Table('dbo.IntList'); + tvp.columns.add('Value', mssql.Int, { nullable: false }); + tvp.columns.add('Sequence', mssql.Int, { nullable: false }); + for (let i = 1; i <= 101; i++) { + tvp.rows.add(i, i); + } + request.input('Ids', tvp); + + const formattedQuery = formatSqlQueryForLog({ query: 'SELECT 1', parameters: request.parameters }); + + const insertStatementCount = (formattedQuery.match(/INSERT INTO @Ids/g) || []).length; + assert.strictEqual(insertStatementCount, 2); + assert.match(formattedQuery, /\(100, 100\)/); + assert.match(formattedQuery, /\(101, 101\)/); +}); + test('createQueryLogger logs formatted multiline SQL when threshold is exceeded', async () => { const calls = []; const logger = { From 0a8fac70677249a34cf4735e76c283258ba93276 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Fri, 22 May 2026 16:36:53 +0000 Subject: [PATCH 04/31] fix: address sql logging review feedback Agent-Logs-Url: https://github.com/durlabhjain/dframework-node/sessions/28fa513a-6c28-4e31-9dd0-1fb6d20ff402 Co-authored-by: durlabhjain <18685657+durlabhjain@users.noreply.github.com> --- lib/mysql.js | 3 ++- lib/sql.js | 40 +++++++++++++++++++++++------- tests/sql-log-format.test.js | 48 ++++++++++++++++++++++++++++++------ 3 files changed, 74 insertions(+), 17 deletions(-) diff --git a/lib/mysql.js b/lib/mysql.js index 89487a0..e9043c4 100644 --- a/lib/mysql.js +++ b/lib/mysql.js @@ -97,7 +97,8 @@ class Mysql extends Sql { const queryLogger = createQueryLogger({ queryLogThreshold: this.queryLogThreshold, timeoutLogLevel: this.timeoutLogLevel, - logger: loggerToUse + logger: loggerToUse, + dialect: 'mysql' }); const pool = this.pool; const request = { diff --git a/lib/sql.js b/lib/sql.js index 4bf188f..5809d33 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -1,5 +1,6 @@ import mssql from 'mssql'; import dayjs from 'dayjs'; +import utc from 'dayjs/plugin/utc.js'; import fs from 'fs-extra'; import zlib from 'zlib'; import logger from './logger.js'; @@ -8,6 +9,7 @@ import config from './appConfig.mjs'; import enums from './enums.mjs'; const { maxQueryTime = 500 } = config || {}; const { inOperatorStrategies, dateTimeFields, columnTypes } = enums; +dayjs.extend(utc); const isNullNotNullOperators = ['IS NOT NULL', 'IS NULL']; const whereClauseRegex = /\bWHERE\b/i; @@ -54,16 +56,28 @@ const stringifySqlValue = (value) => { if (typeof value === 'number') { return Number.isFinite(value) ? String(value) : 'NULL'; } + if (typeof value === 'bigint') { + return value.toString(); + } if (typeof value === 'boolean') { return value ? '1' : '0'; } if (value instanceof Date) { - return `'${dayjs(value).format('YYYY-MM-DD HH:mm:ss.SSS')}'`; + return `'${dayjs(value).utc().format('YYYY-MM-DD HH:mm:ss.SSS[Z]')}'`; } if (Buffer.isBuffer(value)) { return `0x${value.toString('hex')}`; } - return `'${JSON.stringify(value).replace(/'/g, "''")}'`; + try { + const serialized = JSON.stringify(value); + if (serialized === undefined) { + return `'[Unserializable]'`; + } + return `'${serialized.replace(/'/g, "''")}'`; + } catch (err) { + const safeMessage = err?.message ? String(err.message).replace(/'/g, "''") : 'Unable to serialize'; + return `'[Unserializable: ${safeMessage}]'`; + } }; const getSqlTypeFromParameter = (parameter) => { @@ -150,12 +164,15 @@ const formatSqlQueryForLog = ({ query, parameters } = {}) => { return `${declareLines.join('\n')}\n\n${query || ''}`; }; -const createQueryLogger = function ({ queryLogThreshold, timeoutLogLevel, logger }) { +const createQueryLogger = function ({ queryLogThreshold, timeoutLogLevel, logger, dialect = 'mssql' }) { return async function ({ query, start, end = Date.now(), parameters }) { const queryDurationInMs = (end - start); if (queryDurationInMs > queryLogThreshold) { - const formattedQuery = formatSqlQueryForLog({ query, parameters }); - logger[timeoutLogLevel](`SQL query duration ${queryDurationInMs}ms\n${formattedQuery}`); + const formattedQuery = dialect === 'mssql' ? formatSqlQueryForLog({ query, parameters }) : (query || ''); + logger[timeoutLogLevel]( + { query, duration: queryDurationInMs, parameters, formattedQuery, dialect }, + `SQL query duration ${queryDurationInMs}ms\n${formattedQuery}` + ); } }; } @@ -310,8 +327,12 @@ class Sql { const executionTime = Date.now() - startTime; if (executionTime > maxQueryTime) { // 500 milliseconds const loggerToUse = request._logger || this.logger; - const formattedQuery = formatSqlQueryForLog({ query, parameters: request.parameters || request.params }); - loggerToUse.warn(`Query execution exceeded ${maxQueryTime} milliseconds (${executionTime}ms) [${type}]\n${formattedQuery}`); + const parameters = request.parameters || request.params; + const formattedQuery = formatSqlQueryForLog({ query, parameters }); + loggerToUse.warn( + { query, type, executionTime, parameters, formattedQuery }, + `Query execution exceeded ${maxQueryTime} milliseconds (${executionTime}ms) [${type}]\n${formattedQuery}` + ); } } @@ -1171,7 +1192,7 @@ class Sql { const queryStartTime = Date.now(); const returnValue = await Reflect.apply(target, thisArg, args); const [query] = args; - queryLogger({ query, start: queryStartTime, end: Date.now(), parameters: thisArg.parameters }); + queryLogger({ query, start: queryStartTime, end: Date.now(), parameters: thisArg.parameters || thisArg.params }); return returnValue; } }); @@ -1182,7 +1203,8 @@ class Sql { const queryLogger = createQueryLogger({ queryLogThreshold: this.queryLogThreshold, timeoutLogLevel: this.timeoutLogLevel, - logger: loggerToUse + logger: loggerToUse, + dialect: 'mssql' }); const request = this.pool.request(); request.query = this.createProxy(request.query, queryLogger); diff --git a/tests/sql-log-format.test.js b/tests/sql-log-format.test.js index 0fe60be..83bef9c 100644 --- a/tests/sql-log-format.test.js +++ b/tests/sql-log-format.test.js @@ -18,7 +18,7 @@ test('formatSqlQueryForLog prints DECLARE statements and readable SQL', () => { assert.match(formattedQuery, /DECLARE @Id INT = 5/); assert.match(formattedQuery, /DECLARE @Name VARCHAR\(20\) = 'O''Brien'/); - assert.match(formattedQuery, /DECLARE @CreatedOn DATETIME2 = '2025-01-02 03:04:05\.678'/); + assert.match(formattedQuery, /DECLARE @CreatedOn DATETIME2 = '2025-01-02 03:04:05\.678Z'/); assert.match(formattedQuery, /DECLARE @IsActive BIT = 1/); assert.match(formattedQuery, /DECLARE @OptionalValue INT = NULL/); assert.ok(formattedQuery.endsWith(query)); @@ -79,9 +79,11 @@ test('createQueryLogger logs formatted multiline SQL when threshold is exceeded' }); assert.strictEqual(calls.length, 1); - assert.match(calls[0][0], /SQL query duration 100ms/); - assert.match(calls[0][0], /DECLARE @Id INT = 5/); - assert.ok(calls[0][0].includes('\nFROM Users\tWHERE Id = @Id')); + assert.strictEqual(calls[0][0].duration, 100); + assert.strictEqual(calls[0][0].dialect, 'mssql'); + assert.match(calls[0][0].formattedQuery, /DECLARE @Id INT = 5/); + assert.match(calls[0][1], /SQL query duration 100ms/); + assert.ok(calls[0][1].includes('\nFROM Users\tWHERE Id = @Id')); }); test('slow-query and error log sites use formatted SQL output', async () => { @@ -109,9 +111,11 @@ test('slow-query and error log sites use formatted SQL output', async () => { } assert.strictEqual(warnCalls.length, 1); - assert.match(warnCalls[0][0], /Query execution exceeded 500 milliseconds/); - assert.match(warnCalls[0][0], /DECLARE @Id INT = 5/); - assert.ok(warnCalls[0][0].includes('\nFROM Users\tWHERE Id = @Id')); + assert.strictEqual(warnCalls[0][0].executionTime, 900); + assert.strictEqual(warnCalls[0][0].type, 'query'); + assert.match(warnCalls[0][0].formattedQuery, /DECLARE @Id INT = 5/); + assert.match(warnCalls[0][1], /Query execution exceeded 500 milliseconds/); + assert.ok(warnCalls[0][1].includes('\nFROM Users\tWHERE Id = @Id')); const expectedError = new Error('forced failure'); const result = await sql.runQuery({ @@ -135,3 +139,33 @@ test('slow-query and error log sites use formatted SQL output', async () => { assert.match(errorCalls[0][1], /DECLARE @Id INT = 5/); assert.ok(errorCalls[0][1].includes('\nFROM Users\tWHERE Id = @Id')); }); + +test('formatSqlQueryForLog safely handles bigint and unserializable values', () => { + const circular = {}; + circular.self = circular; + const query = formatSqlQueryForLog({ + query: 'SELECT @Big, @Circular', + parameters: { + Big: { type: mssql.BigInt, value: 9007199254740993n }, + Circular: { value: circular } + } + }); + assert.match(query, /DECLARE @Big BIGINT = 9007199254740993/); + assert.match(query, /DECLARE @Circular NVARCHAR\(MAX\) = '\[Unserializable:/); +}); + +test('createQueryLogger preserves raw SQL formatting for mysql dialect', async () => { + const calls = []; + const logger = { warn: (...args) => calls.push(args) }; + const queryLogger = createQueryLogger({ queryLogThreshold: 1, timeoutLogLevel: 'warn', logger, dialect: 'mysql' }); + await queryLogger({ + query: 'SELECT * FROM users WHERE id = :id', + start: 10, + end: 20, + parameters: { id: 5 } + }); + assert.strictEqual(calls.length, 1); + assert.strictEqual(calls[0][0].dialect, 'mysql'); + assert.strictEqual(calls[0][0].formattedQuery, 'SELECT * FROM users WHERE id = :id'); + assert.ok(!calls[0][1].includes('DECLARE @')); +}); From 6ccdfffbe3da2d265545b04b7b80e48a6a8d6092 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Fri, 22 May 2026 16:38:07 +0000 Subject: [PATCH 05/31] chore: refine utc/log serialization wording from validation feedback Agent-Logs-Url: https://github.com/durlabhjain/dframework-node/sessions/28fa513a-6c28-4e31-9dd0-1fb6d20ff402 Co-authored-by: durlabhjain <18685657+durlabhjain@users.noreply.github.com> --- lib/sql.js | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/sql.js b/lib/sql.js index 5809d33..9e2b655 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -63,7 +63,7 @@ const stringifySqlValue = (value) => { return value ? '1' : '0'; } if (value instanceof Date) { - return `'${dayjs(value).utc().format('YYYY-MM-DD HH:mm:ss.SSS[Z]')}'`; + return `'${dayjs(value).utc().format('YYYY-MM-DD HH:mm:ss.SSS')}Z'`; } if (Buffer.isBuffer(value)) { return `0x${value.toString('hex')}`; @@ -75,7 +75,7 @@ const stringifySqlValue = (value) => { } return `'${serialized.replace(/'/g, "''")}'`; } catch (err) { - const safeMessage = err?.message ? String(err.message).replace(/'/g, "''") : 'Unable to serialize'; + const safeMessage = err?.message ? String(err.message).replace(/'/g, "''") : 'Unable to serialize value'; return `'[Unserializable: ${safeMessage}]'`; } }; From 7c716ae3037594678c9df736843baa71069cf6ca Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Fri, 22 May 2026 16:39:03 +0000 Subject: [PATCH 06/31] fix: keep explicit utc suffix in sql date log formatting Agent-Logs-Url: https://github.com/durlabhjain/dframework-node/sessions/28fa513a-6c28-4e31-9dd0-1fb6d20ff402 Co-authored-by: durlabhjain <18685657+durlabhjain@users.noreply.github.com> --- lib/sql.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/sql.js b/lib/sql.js index 9e2b655..757e010 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -63,7 +63,7 @@ const stringifySqlValue = (value) => { return value ? '1' : '0'; } if (value instanceof Date) { - return `'${dayjs(value).utc().format('YYYY-MM-DD HH:mm:ss.SSS')}Z'`; + return `'${dayjs(value).utc().format('YYYY-MM-DD HH:mm:ss.SSS[Z]')}'`; } if (Buffer.isBuffer(value)) { return `0x${value.toString('hex')}`; From cae884541f3594b742c7d7263b92e4f101ec5044 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Fri, 22 May 2026 17:02:57 +0000 Subject: [PATCH 07/31] fix sql log review feedback Agent-Logs-Url: https://github.com/durlabhjain/dframework-node/sessions/6ce515d1-55d5-4f7a-9226-4aa9431a66b3 Co-authored-by: durlabhjain <18685657+durlabhjain@users.noreply.github.com> --- lib/sql.js | 52 +++++++++++++++++++++++---- tests/sql-log-format.test.js | 68 ++++++++++++++++++++++++++++++++++-- 2 files changed, 112 insertions(+), 8 deletions(-) diff --git a/lib/sql.js b/lib/sql.js index 757e010..bf157a2 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -46,6 +46,9 @@ const mssqlSqlTypeMap = { Xml: 'XML' }; +const maxLengthSqlTypes = new Set(['VARCHAR', 'NVARCHAR', 'VARBINARY']); +const inferredLengthSqlTypes = new Set(['CHAR', 'NCHAR', 'BINARY']); + const stringifySqlValue = (value) => { if (value === null || value === undefined) { return 'NULL'; @@ -84,13 +87,23 @@ const getSqlTypeFromParameter = (parameter) => { const type = parameter?.type?.type || parameter?.type; const typeName = type?.name; const sqlType = mssqlSqlTypeMap[typeName] || typeName?.toUpperCase() || 'NVARCHAR(MAX)'; - if (sqlType === 'VARCHAR' || sqlType === 'NVARCHAR' || sqlType === 'VARBINARY' || sqlType === 'CHAR' || sqlType === 'NCHAR' || sqlType === 'BINARY') { + if (maxLengthSqlTypes.has(sqlType) || inferredLengthSqlTypes.has(sqlType)) { if (parameter?.length === mssql.MAX) { return `${sqlType}(MAX)`; } if (Number.isFinite(parameter?.length)) { return `${sqlType}(${parameter.length})`; } + if (maxLengthSqlTypes.has(sqlType)) { + return `${sqlType}(MAX)`; + } + if (typeof parameter?.value === 'string') { + return `${sqlType}(${Math.max(parameter.value.length, 1)})`; + } + if (Buffer.isBuffer(parameter?.value)) { + return `${sqlType}(${Math.max(parameter.value.length, 1)})`; + } + return `${sqlType}(1)`; } if (sqlType === 'DECIMAL' || sqlType === 'NUMERIC') { if (Number.isFinite(parameter?.precision) && Number.isFinite(parameter?.scale)) { @@ -164,13 +177,37 @@ const formatSqlQueryForLog = ({ query, parameters } = {}) => { return `${declareLines.join('\n')}\n\n${query || ''}`; }; +const formatQueryForLog = ({ query, parameters, dialect = 'mssql' } = {}) => { + return dialect === 'mssql' ? formatSqlQueryForLog({ query, parameters }) : (query || ''); +}; + +const summarizeTvpParameter = (table) => ({ + type: getTvpPath(table), + columns: (table?.columns || []).map((column) => column.name), + rowCount: table?.rows?.length || 0 +}); + +const summarizeParametersForLog = (parameters) => { + if (!parameters || typeof parameters !== 'object') { + return parameters; + } + return Object.fromEntries(Object.entries(parameters).map(([name, parameter]) => { + const descriptor = toParameterDescriptor(name, parameter); + if (descriptor.value instanceof mssql.Table) { + return [descriptor.name || name, summarizeTvpParameter(descriptor.value)]; + } + return [name, parameter]; + })); +}; + const createQueryLogger = function ({ queryLogThreshold, timeoutLogLevel, logger, dialect = 'mssql' }) { return async function ({ query, start, end = Date.now(), parameters }) { const queryDurationInMs = (end - start); if (queryDurationInMs > queryLogThreshold) { - const formattedQuery = dialect === 'mssql' ? formatSqlQueryForLog({ query, parameters }) : (query || ''); + const formattedQuery = formatQueryForLog({ query, parameters, dialect }); + const parametersForLog = summarizeParametersForLog(parameters); logger[timeoutLogLevel]( - { query, duration: queryDurationInMs, parameters, formattedQuery, dialect }, + { query, duration: `${queryDurationInMs}ms`, durationMs: queryDurationInMs, parameters: parametersForLog, formattedQuery, dialect }, `SQL query duration ${queryDurationInMs}ms\n${formattedQuery}` ); } @@ -317,8 +354,9 @@ class Sql { return { success: true, data: result.recordset, ...result }; } catch (err) { const loggerToUse = request._logger || this.logger; + const parameters = summarizeParametersForLog(request.parameters); const formattedQuery = formatSqlQueryForLog({ query, parameters: request.parameters }); - loggerToUse.error({ err, type }, `SQL query failed\n${formattedQuery}`); + loggerToUse.error({ err, type, query, parameters, formattedQuery }, `SQL query failed\n${formattedQuery}`); return { success: false, err, data: {} }; } } @@ -328,9 +366,11 @@ class Sql { if (executionTime > maxQueryTime) { // 500 milliseconds const loggerToUse = request._logger || this.logger; const parameters = request.parameters || request.params; - const formattedQuery = formatSqlQueryForLog({ query, parameters }); + const dialect = request.parameters ? 'mssql' : 'mysql'; + const formattedQuery = formatQueryForLog({ query, parameters, dialect }); + const parametersForLog = summarizeParametersForLog(parameters); loggerToUse.warn( - { query, type, executionTime, parameters, formattedQuery }, + { query, type, executionTime: `${executionTime}ms`, executionTimeMs: executionTime, parameters: parametersForLog, formattedQuery, dialect }, `Query execution exceeded ${maxQueryTime} milliseconds (${executionTime}ms) [${type}]\n${formattedQuery}` ); } diff --git a/tests/sql-log-format.test.js b/tests/sql-log-format.test.js index 83bef9c..18eca59 100644 --- a/tests/sql-log-format.test.js +++ b/tests/sql-log-format.test.js @@ -79,7 +79,8 @@ test('createQueryLogger logs formatted multiline SQL when threshold is exceeded' }); assert.strictEqual(calls.length, 1); - assert.strictEqual(calls[0][0].duration, 100); + assert.strictEqual(calls[0][0].duration, '100ms'); + assert.strictEqual(calls[0][0].durationMs, 100); assert.strictEqual(calls[0][0].dialect, 'mssql'); assert.match(calls[0][0].formattedQuery, /DECLARE @Id INT = 5/); assert.match(calls[0][1], /SQL query duration 100ms/); @@ -111,7 +112,8 @@ test('slow-query and error log sites use formatted SQL output', async () => { } assert.strictEqual(warnCalls.length, 1); - assert.strictEqual(warnCalls[0][0].executionTime, 900); + assert.strictEqual(warnCalls[0][0].executionTime, '900ms'); + assert.strictEqual(warnCalls[0][0].executionTimeMs, 900); assert.strictEqual(warnCalls[0][0].type, 'query'); assert.match(warnCalls[0][0].formattedQuery, /DECLARE @Id INT = 5/); assert.match(warnCalls[0][1], /Query execution exceeded 500 milliseconds/); @@ -135,6 +137,9 @@ test('slow-query and error log sites use formatted SQL output', async () => { assert.strictEqual(errorCalls.length, 1); assert.strictEqual(errorCalls[0][0].err, expectedError); assert.strictEqual(errorCalls[0][0].type, 'query'); + assert.strictEqual(errorCalls[0][0].query, query); + assert.match(errorCalls[0][0].formattedQuery, /DECLARE @Id INT = 5/); + assert.strictEqual(errorCalls[0][0].parameters.Id.value, 5); assert.match(errorCalls[0][1], /SQL query failed/); assert.match(errorCalls[0][1], /DECLARE @Id INT = 5/); assert.ok(errorCalls[0][1].includes('\nFROM Users\tWHERE Id = @Id')); @@ -169,3 +174,62 @@ test('createQueryLogger preserves raw SQL formatting for mysql dialect', async ( assert.strictEqual(calls[0][0].formattedQuery, 'SELECT * FROM users WHERE id = :id'); assert.ok(!calls[0][1].includes('DECLARE @')); }); + +test('formatSqlQueryForLog uses safe default lengths when MSSQL parameter length is omitted', () => { + const formattedQuery = formatSqlQueryForLog({ + query: 'SELECT @Name, @Code', + parameters: { + Name: { type: mssql.VarChar, value: 'Alpha' }, + Code: { type: mssql.Char, value: 'AB' } + } + }); + + assert.match(formattedQuery, /DECLARE @Name VARCHAR\(MAX\) = 'Alpha'/); + assert.match(formattedQuery, /DECLARE @Code CHAR\(2\) = 'AB'/); +}); + +test('structured logs summarize TVPs and keep mysql slow-query SQL raw', () => { + const tvp = new mssql.Table('dbo.IntList'); + tvp.columns.add('Value', mssql.Int, { nullable: false }); + tvp.rows.add(1); + tvp.rows.add(2); + + const durationCalls = []; + const durationLogger = { warn: (...args) => durationCalls.push(args) }; + const queryLogger = createQueryLogger({ queryLogThreshold: 1, timeoutLogLevel: 'warn', logger: durationLogger }); + + return Promise.resolve(queryLogger({ + query: 'SELECT * FROM dbo.Users WHERE Id IN (SELECT Value FROM @Ids)', + start: 0, + end: 25, + parameters: { + Ids: { name: 'Ids', value: tvp } + } + })).then(() => { + assert.deepStrictEqual(durationCalls[0][0].parameters.Ids, { + type: '[dbo].[IntList]', + columns: ['Value'], + rowCount: 2 + }); + + const warnCalls = []; + const mysqlLogger = { warn: (...args) => warnCalls.push(args) }; + const sql = new Sql(); + const originalDateNow = Date.now; + Date.now = () => 1000; + try { + sql.logSlowQuery({ + startTime: 100, + query: 'SELECT * FROM users WHERE id = :id', + type: 'query', + request: { _logger: mysqlLogger, params: { id: 5 } } + }); + } finally { + Date.now = originalDateNow; + } + + assert.strictEqual(warnCalls[0][0].dialect, 'mysql'); + assert.strictEqual(warnCalls[0][0].formattedQuery, 'SELECT * FROM users WHERE id = :id'); + assert.ok(!warnCalls[0][1].includes('DECLARE @')); + }); +}); From 4ab691935f03396c55f2efc316004002048dc152 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Fri, 22 May 2026 17:04:35 +0000 Subject: [PATCH 08/31] refine sql dialect log handling Agent-Logs-Url: https://github.com/durlabhjain/dframework-node/sessions/6ce515d1-55d5-4f7a-9226-4aa9431a66b3 Co-authored-by: durlabhjain <18685657+durlabhjain@users.noreply.github.com> --- lib/mysql.js | 1 + lib/sql.js | 19 +++++++++++++++---- tests/mysql-create-request.test.js | 2 ++ tests/sql-log-format.test.js | 2 +- 4 files changed, 19 insertions(+), 5 deletions(-) diff --git a/lib/mysql.js b/lib/mysql.js index e9043c4..9fb778d 100644 --- a/lib/mysql.js +++ b/lib/mysql.js @@ -107,6 +107,7 @@ class Mysql extends Sql { input: this.input, params: {}, _logger: loggerToUse, + _sqlDialect: 'mysql', }; return request; } diff --git a/lib/sql.js b/lib/sql.js index bf157a2..be7b588 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -87,15 +87,18 @@ const getSqlTypeFromParameter = (parameter) => { const type = parameter?.type?.type || parameter?.type; const typeName = type?.name; const sqlType = mssqlSqlTypeMap[typeName] || typeName?.toUpperCase() || 'NVARCHAR(MAX)'; - if (maxLengthSqlTypes.has(sqlType) || inferredLengthSqlTypes.has(sqlType)) { + if (maxLengthSqlTypes.has(sqlType)) { if (parameter?.length === mssql.MAX) { return `${sqlType}(MAX)`; } if (Number.isFinite(parameter?.length)) { return `${sqlType}(${parameter.length})`; } - if (maxLengthSqlTypes.has(sqlType)) { - return `${sqlType}(MAX)`; + return `${sqlType}(MAX)`; + } + if (inferredLengthSqlTypes.has(sqlType)) { + if (Number.isFinite(parameter?.length)) { + return `${sqlType}(${parameter.length})`; } if (typeof parameter?.value === 'string') { return `${sqlType}(${Math.max(parameter.value.length, 1)})`; @@ -200,6 +203,13 @@ const summarizeParametersForLog = (parameters) => { })); }; +const getRequestDialect = (request) => { + if (request?._sqlDialect) { + return request._sqlDialect; + } + return Object.prototype.hasOwnProperty.call(request || {}, 'params') ? 'mysql' : 'mssql'; +}; + const createQueryLogger = function ({ queryLogThreshold, timeoutLogLevel, logger, dialect = 'mssql' }) { return async function ({ query, start, end = Date.now(), parameters }) { const queryDurationInMs = (end - start); @@ -366,7 +376,7 @@ class Sql { if (executionTime > maxQueryTime) { // 500 milliseconds const loggerToUse = request._logger || this.logger; const parameters = request.parameters || request.params; - const dialect = request.parameters ? 'mssql' : 'mysql'; + const dialect = getRequestDialect(request); const formattedQuery = formatQueryForLog({ query, parameters, dialect }); const parametersForLog = summarizeParametersForLog(parameters); loggerToUse.warn( @@ -1250,6 +1260,7 @@ class Sql { request.query = this.createProxy(request.query, queryLogger); request.execute = this.createProxy(request.execute, queryLogger); request._logger = loggerToUse; + request._sqlDialect = 'mssql'; return request; } diff --git a/tests/mysql-create-request.test.js b/tests/mysql-create-request.test.js index eda91ff..91bf6df 100644 --- a/tests/mysql-create-request.test.js +++ b/tests/mysql-create-request.test.js @@ -51,6 +51,8 @@ test('Each createRequest returns a fresh independent object with its own params' const req1 = mysql2.createRequest(); const req2 = mysql2.createRequest(); + assert.strictEqual(req1._sqlDialect, 'mysql'); + assert.strictEqual(req2._sqlDialect, 'mysql'); req1.params['a'] = 1; assert.strictEqual(req2.params['a'], undefined); }); diff --git a/tests/sql-log-format.test.js b/tests/sql-log-format.test.js index 18eca59..8546a26 100644 --- a/tests/sql-log-format.test.js +++ b/tests/sql-log-format.test.js @@ -222,7 +222,7 @@ test('structured logs summarize TVPs and keep mysql slow-query SQL raw', () => { startTime: 100, query: 'SELECT * FROM users WHERE id = :id', type: 'query', - request: { _logger: mysqlLogger, params: { id: 5 } } + request: { _logger: mysqlLogger, _sqlDialect: 'mysql', params: { id: 5 } } }); } finally { Date.now = originalDateNow; From d188cca86d08e184ad99cc8d29b2f4537eadd133 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Fri, 22 May 2026 17:05:34 +0000 Subject: [PATCH 09/31] document sql log dialect assumptions Agent-Logs-Url: https://github.com/durlabhjain/dframework-node/sessions/6ce515d1-55d5-4f7a-9226-4aa9431a66b3 Co-authored-by: durlabhjain <18685657+durlabhjain@users.noreply.github.com> --- lib/sql.js | 3 +++ 1 file changed, 3 insertions(+) diff --git a/lib/sql.js b/lib/sql.js index be7b588..815f8c9 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -88,6 +88,7 @@ const getSqlTypeFromParameter = (parameter) => { const typeName = type?.name; const sqlType = mssqlSqlTypeMap[typeName] || typeName?.toUpperCase() || 'NVARCHAR(MAX)'; if (maxLengthSqlTypes.has(sqlType)) { + // The mssql package uses mssql.MAX as the sentinel for MAX-length variable types. if (parameter?.length === mssql.MAX) { return `${sqlType}(MAX)`; } @@ -207,6 +208,8 @@ const getRequestDialect = (request) => { if (request?._sqlDialect) { return request._sqlDialect; } + // Fallback for older/custom request objects that do not set _sqlDialect: + // MySQL requests in this codebase carry plain `params`, while MSSQL requests carry `parameters`. return Object.prototype.hasOwnProperty.call(request || {}, 'params') ? 'mysql' : 'mssql'; }; From 4d2e1cd17a6c32d425e68afc4f71a649d2ec006e Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Fri, 22 May 2026 17:06:30 +0000 Subject: [PATCH 10/31] clarify sql max length fallback Agent-Logs-Url: https://github.com/durlabhjain/dframework-node/sessions/6ce515d1-55d5-4f7a-9226-4aa9431a66b3 Co-authored-by: durlabhjain <18685657+durlabhjain@users.noreply.github.com> --- lib/sql.js | 1 + 1 file changed, 1 insertion(+) diff --git a/lib/sql.js b/lib/sql.js index 815f8c9..934ad01 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -95,6 +95,7 @@ const getSqlTypeFromParameter = (parameter) => { if (Number.isFinite(parameter?.length)) { return `${sqlType}(${parameter.length})`; } + // Default to MAX when length is omitted so the logged SQL stays executable without truncation. return `${sqlType}(MAX)`; } if (inferredLengthSqlTypes.has(sqlType)) { From 2b7acf97e40dea630c72eafbb6065519cde81951 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 27 May 2026 21:53:22 +0000 Subject: [PATCH 11/31] Fix review comments: indentation in catch block, remove duplicate SQL from log messages --- lib/sql.js | 6 +++--- tests/sql-log-format.test.js | 2 -- 2 files changed, 3 insertions(+), 5 deletions(-) diff --git a/lib/sql.js b/lib/sql.js index 934ad01..42fb25e 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -222,7 +222,7 @@ const createQueryLogger = function ({ queryLogThreshold, timeoutLogLevel, logger const parametersForLog = summarizeParametersForLog(parameters); logger[timeoutLogLevel]( { query, duration: `${queryDurationInMs}ms`, durationMs: queryDurationInMs, parameters: parametersForLog, formattedQuery, dialect }, - `SQL query duration ${queryDurationInMs}ms\n${formattedQuery}` + `SQL query duration ${queryDurationInMs}ms` ); } }; @@ -371,7 +371,7 @@ class Sql { const parameters = summarizeParametersForLog(request.parameters); const formattedQuery = formatSqlQueryForLog({ query, parameters: request.parameters }); loggerToUse.error({ err, type, query, parameters, formattedQuery }, `SQL query failed\n${formattedQuery}`); - return { success: false, err, data: {} }; + return { success: false, err, data: {} }; } } @@ -385,7 +385,7 @@ class Sql { const parametersForLog = summarizeParametersForLog(parameters); loggerToUse.warn( { query, type, executionTime: `${executionTime}ms`, executionTimeMs: executionTime, parameters: parametersForLog, formattedQuery, dialect }, - `Query execution exceeded ${maxQueryTime} milliseconds (${executionTime}ms) [${type}]\n${formattedQuery}` + `Query execution exceeded ${maxQueryTime} milliseconds (${executionTime}ms) [${type}]` ); } } diff --git a/tests/sql-log-format.test.js b/tests/sql-log-format.test.js index 8546a26..cb4dac3 100644 --- a/tests/sql-log-format.test.js +++ b/tests/sql-log-format.test.js @@ -84,7 +84,6 @@ test('createQueryLogger logs formatted multiline SQL when threshold is exceeded' assert.strictEqual(calls[0][0].dialect, 'mssql'); assert.match(calls[0][0].formattedQuery, /DECLARE @Id INT = 5/); assert.match(calls[0][1], /SQL query duration 100ms/); - assert.ok(calls[0][1].includes('\nFROM Users\tWHERE Id = @Id')); }); test('slow-query and error log sites use formatted SQL output', async () => { @@ -117,7 +116,6 @@ test('slow-query and error log sites use formatted SQL output', async () => { assert.strictEqual(warnCalls[0][0].type, 'query'); assert.match(warnCalls[0][0].formattedQuery, /DECLARE @Id INT = 5/); assert.match(warnCalls[0][1], /Query execution exceeded 500 milliseconds/); - assert.ok(warnCalls[0][1].includes('\nFROM Users\tWHERE Id = @Id')); const expectedError = new Error('forced failure'); const result = await sql.runQuery({ From 2545176c412e4f125394fa7c8e3ed516437c360e Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 27 May 2026 23:15:08 +0000 Subject: [PATCH 12/31] Address latest SQL log review feedback --- lib/sql.js | 49 +++++++++++++++++++++++++++++++++--- tests/sql-log-format.test.js | 32 +++++++++++++++++++++-- 2 files changed, 76 insertions(+), 5 deletions(-) diff --git a/lib/sql.js b/lib/sql.js index 42fb25e..f36aa8e 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -192,16 +192,59 @@ const summarizeTvpParameter = (table) => ({ rowCount: table?.rows?.length || 0 }); +const normalizeValueForJsonLog = (value) => { + if (typeof value === 'bigint') { + return value.toString(); + } + if (value instanceof Date) { + return value.toISOString(); + } + if (Buffer.isBuffer(value)) { + return `0x${value.toString('hex')}`; + } + if (value === null || value === undefined || typeof value === 'string' || typeof value === 'number' || typeof value === 'boolean') { + return value; + } + const seen = new WeakSet(); + try { + const serialized = JSON.stringify(value, (_, currentValue) => { + if (typeof currentValue === 'bigint') { + return currentValue.toString(); + } + if (typeof currentValue === 'function' || typeof currentValue === 'symbol') { + return '[Unserializable]'; + } + if (currentValue && typeof currentValue === 'object') { + if (seen.has(currentValue)) { + return '[Circular]'; + } + seen.add(currentValue); + } + return currentValue; + }); + if (serialized === undefined) { + return '[Unserializable]'; + } + return JSON.parse(serialized); + } catch { + return '[Unserializable]'; + } +}; + const summarizeParametersForLog = (parameters) => { if (!parameters || typeof parameters !== 'object') { return parameters; } return Object.fromEntries(Object.entries(parameters).map(([name, parameter]) => { const descriptor = toParameterDescriptor(name, parameter); + const parameterName = descriptor.name || name; if (descriptor.value instanceof mssql.Table) { - return [descriptor.name || name, summarizeTvpParameter(descriptor.value)]; + return [parameterName, summarizeTvpParameter(descriptor.value)]; + } + if (parameter && typeof parameter === 'object' && ('value' in parameter || 'type' in parameter)) { + return [parameterName, { ...parameter, name: parameterName, value: normalizeValueForJsonLog(descriptor.value) }]; } - return [name, parameter]; + return [parameterName, normalizeValueForJsonLog(descriptor.value)]; })); }; @@ -370,7 +413,7 @@ class Sql { const loggerToUse = request._logger || this.logger; const parameters = summarizeParametersForLog(request.parameters); const formattedQuery = formatSqlQueryForLog({ query, parameters: request.parameters }); - loggerToUse.error({ err, type, query, parameters, formattedQuery }, `SQL query failed\n${formattedQuery}`); + loggerToUse.error({ err, type, query, parameters, formattedQuery }, 'SQL query failed'); return { success: false, err, data: {} }; } } diff --git a/tests/sql-log-format.test.js b/tests/sql-log-format.test.js index cb4dac3..84c0e93 100644 --- a/tests/sql-log-format.test.js +++ b/tests/sql-log-format.test.js @@ -139,8 +139,7 @@ test('slow-query and error log sites use formatted SQL output', async () => { assert.match(errorCalls[0][0].formattedQuery, /DECLARE @Id INT = 5/); assert.strictEqual(errorCalls[0][0].parameters.Id.value, 5); assert.match(errorCalls[0][1], /SQL query failed/); - assert.match(errorCalls[0][1], /DECLARE @Id INT = 5/); - assert.ok(errorCalls[0][1].includes('\nFROM Users\tWHERE Id = @Id')); + assert.strictEqual(errorCalls[0][1], 'SQL query failed'); }); test('formatSqlQueryForLog safely handles bigint and unserializable values', () => { @@ -231,3 +230,32 @@ test('structured logs summarize TVPs and keep mysql slow-query SQL raw', () => { assert.ok(!warnCalls[0][1].includes('DECLARE @')); }); }); + +test('summarizeParametersForLog uses descriptor name and JSON-safe scalar values', () => { + const calls = []; + const log = { error: (...args) => calls.push(args) }; + const sql = new Sql(); + const circular = {}; + circular.self = circular; + + return sql.runQuery({ + request: { + _logger: log, + parameters: { + Alias: { name: 'ActualAlias', type: mssql.Int, value: 9 }, + BigValue: { type: mssql.BigInt, value: 9007199254740993n }, + Circular: { value: circular } + }, + query: async () => { + throw new Error('boom'); + } + }, + type: 'query', + query: 'SELECT 1' + }).then(() => { + assert.ok(calls[0][0].parameters.ActualAlias); + assert.strictEqual(calls[0][0].parameters.Alias, undefined); + assert.strictEqual(calls[0][0].parameters.BigValue.value, '9007199254740993'); + assert.strictEqual(calls[0][0].parameters.Circular.value.self, '[Circular]'); + }); +}); From 18490ae877e7f60ce795a3a087fc2389da8d74b5 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 1 Jun 2026 16:22:47 +0000 Subject: [PATCH 13/31] fix: make query logger callback synchronous --- lib/sql.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/sql.js b/lib/sql.js index f36aa8e..c549878 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -258,7 +258,7 @@ const getRequestDialect = (request) => { }; const createQueryLogger = function ({ queryLogThreshold, timeoutLogLevel, logger, dialect = 'mssql' }) { - return async function ({ query, start, end = Date.now(), parameters }) { + return function ({ query, start, end = Date.now(), parameters }) { const queryDurationInMs = (end - start); if (queryDurationInMs > queryLogThreshold) { const formattedQuery = formatQueryForLog({ query, parameters, dialect }); From babb249a3c57d028de9dc76f137560b169ad0a15 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 1 Jun 2026 16:47:00 +0000 Subject: [PATCH 14/31] fix: harden query duration logger --- lib/sql.js | 21 +++++++++++----- tests/sql-log-format.test.js | 48 ++++++++++++++++++++++++++++++++++++ 2 files changed, 63 insertions(+), 6 deletions(-) diff --git a/lib/sql.js b/lib/sql.js index c549878..6176f24 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -261,12 +261,21 @@ const createQueryLogger = function ({ queryLogThreshold, timeoutLogLevel, logger return function ({ query, start, end = Date.now(), parameters }) { const queryDurationInMs = (end - start); if (queryDurationInMs > queryLogThreshold) { - const formattedQuery = formatQueryForLog({ query, parameters, dialect }); - const parametersForLog = summarizeParametersForLog(parameters); - logger[timeoutLogLevel]( - { query, duration: `${queryDurationInMs}ms`, durationMs: queryDurationInMs, parameters: parametersForLog, formattedQuery, dialect }, - `SQL query duration ${queryDurationInMs}ms` - ); + try { + const logFunction = logger?.[timeoutLogLevel]; + if (typeof logFunction !== 'function') { + return; + } + const formattedQuery = formatQueryForLog({ query, parameters, dialect }); + const parametersForLog = summarizeParametersForLog(parameters); + logFunction.call( + logger, + { query, duration: `${queryDurationInMs}ms`, durationMs: queryDurationInMs, parameters: parametersForLog, formattedQuery, dialect }, + `SQL query duration ${queryDurationInMs}ms` + ); + } catch { + // Never let logging failures affect query execution. + } } }; } diff --git a/tests/sql-log-format.test.js b/tests/sql-log-format.test.js index 84c0e93..1cda3c2 100644 --- a/tests/sql-log-format.test.js +++ b/tests/sql-log-format.test.js @@ -86,6 +86,54 @@ test('createQueryLogger logs formatted multiline SQL when threshold is exceeded' assert.match(calls[0][1], /SQL query duration 100ms/); }); +test('createQueryLogger never lets logging failures affect the caller', async () => { + const invalidLogLevelLogger = createQueryLogger({ queryLogThreshold: 1, timeoutLogLevel: 'warn', logger: {} }); + assert.doesNotThrow(() => invalidLogLevelLogger({ + query: 'SELECT 1', + start: 0, + end: 10, + parameters: buildParameters() + })); + + const throwingParameters = new Proxy({}, { + ownKeys() { + throw new Error('bad params'); + } + }); + + const throwingLogger = createQueryLogger({ + queryLogThreshold: 1, + timeoutLogLevel: 'warn', + logger: { + warn() { + throw new Error('log failure'); + } + } + }); + + assert.doesNotThrow(() => throwingLogger({ + query: 'SELECT 1', + start: 0, + end: 10, + parameters: buildParameters() + })); + + assert.doesNotThrow(() => invalidLogLevelLogger({ + query: 'SELECT 1', + start: 0, + end: 10, + parameters: throwingParameters + })); + + const sql = new Sql(); + const proxiedQuery = sql.createProxy(async function (query) { + return { query }; + }, invalidLogLevelLogger); + + const result = await proxiedQuery.call({ parameters: throwingParameters }, 'SELECT 1'); + assert.deepStrictEqual(result, { query: 'SELECT 1' }); +}); + test('slow-query and error log sites use formatted SQL output', async () => { const warnCalls = []; const errorCalls = []; From b7637bdafc3257bd07fdee78605958b494d1622c Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 1 Jun 2026 17:40:31 +0000 Subject: [PATCH 15/31] Fix defensive logging in runQuery catch block and logSlowQuery --- lib/sql.js | 33 ++++++++++++++++++++++----------- 1 file changed, 22 insertions(+), 11 deletions(-) diff --git a/lib/sql.js b/lib/sql.js index 6176f24..38f14f8 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -420,9 +420,13 @@ class Sql { return { success: true, data: result.recordset, ...result }; } catch (err) { const loggerToUse = request._logger || this.logger; - const parameters = summarizeParametersForLog(request.parameters); - const formattedQuery = formatSqlQueryForLog({ query, parameters: request.parameters }); - loggerToUse.error({ err, type, query, parameters, formattedQuery }, 'SQL query failed'); + try { + const parameters = summarizeParametersForLog(request.parameters); + const formattedQuery = formatSqlQueryForLog({ query, parameters: request.parameters }); + loggerToUse.error({ err, type, query, parameters, formattedQuery }, 'SQL query failed'); + } catch { + loggerToUse.error({ err, type }, 'SQL query failed'); + } return { success: false, err, data: {} }; } } @@ -431,14 +435,21 @@ class Sql { const executionTime = Date.now() - startTime; if (executionTime > maxQueryTime) { // 500 milliseconds const loggerToUse = request._logger || this.logger; - const parameters = request.parameters || request.params; - const dialect = getRequestDialect(request); - const formattedQuery = formatQueryForLog({ query, parameters, dialect }); - const parametersForLog = summarizeParametersForLog(parameters); - loggerToUse.warn( - { query, type, executionTime: `${executionTime}ms`, executionTimeMs: executionTime, parameters: parametersForLog, formattedQuery, dialect }, - `Query execution exceeded ${maxQueryTime} milliseconds (${executionTime}ms) [${type}]` - ); + try { + if (typeof loggerToUse?.warn !== 'function') { + return; + } + const parameters = request.parameters || request.params; + const dialect = getRequestDialect(request); + const formattedQuery = formatQueryForLog({ query, parameters, dialect }); + const parametersForLog = summarizeParametersForLog(parameters); + loggerToUse.warn( + { query, type, executionTime: `${executionTime}ms`, executionTimeMs: executionTime, parameters: parametersForLog, formattedQuery, dialect }, + `Query execution exceeded ${maxQueryTime} milliseconds (${executionTime}ms) [${type}]` + ); + } catch { + // Never let logging failures affect query execution. + } } } From b931b31b951163027a7dec938b279712de87f639 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 1 Jun 2026 18:28:01 +0000 Subject: [PATCH 16/31] fix: harden runQuery error logging fallback --- lib/sql.js | 19 +++++++++++++------ 1 file changed, 13 insertions(+), 6 deletions(-) diff --git a/lib/sql.js b/lib/sql.js index 38f14f8..0a459de 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -420,12 +420,19 @@ class Sql { return { success: true, data: result.recordset, ...result }; } catch (err) { const loggerToUse = request._logger || this.logger; - try { - const parameters = summarizeParametersForLog(request.parameters); - const formattedQuery = formatSqlQueryForLog({ query, parameters: request.parameters }); - loggerToUse.error({ err, type, query, parameters, formattedQuery }, 'SQL query failed'); - } catch { - loggerToUse.error({ err, type }, 'SQL query failed'); + const errorLog = loggerToUse?.error; + if (typeof errorLog === 'function') { + try { + const parameters = summarizeParametersForLog(request.parameters); + const formattedQuery = formatSqlQueryForLog({ query, parameters: request.parameters }); + errorLog.call(loggerToUse, { err, type, query, parameters, formattedQuery }, 'SQL query failed'); + } catch { + try { + errorLog.call(loggerToUse, { err, type }, 'SQL query failed'); + } catch { + // Never let logging failures affect query execution. + } + } } return { success: false, err, data: {} }; } From ea77a3a24dbae698be42232fd979fc31820bbc6b Mon Sep 17 00:00:00 2001 From: durlabhjain Date: Mon, 1 Jun 2026 15:08:14 -0400 Subject: [PATCH 17/31] formatSqlQueryForLog clean-up Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com> --- lib/sql.js | 28 ++++++++++++++++------------ 1 file changed, 16 insertions(+), 12 deletions(-) diff --git a/lib/sql.js b/lib/sql.js index 0a459de..c2af383 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -166,20 +166,24 @@ const formatTvpParameter = (descriptor) => { }; const formatSqlQueryForLog = ({ query, parameters } = {}) => { - const params = parameters || {}; - const descriptors = Object.entries(params).map(([name, parameter]) => toParameterDescriptor(name, parameter)); - const tvpDescriptors = descriptors.filter((descriptor) => descriptor.value instanceof mssql.Table); - const scalarDeclareLines = descriptors.filter((descriptor) => !(descriptor.value instanceof mssql.Table)).map((descriptor) => { - const sqlType = getSqlTypeFromParameter(descriptor); - const sqlValue = stringifySqlValue(descriptor.value); - return `DECLARE @${descriptor.name} ${sqlType} = ${sqlValue}`; - }); - const tvpLines = tvpDescriptors.flatMap((descriptor) => formatTvpParameter(descriptor)); - const declareLines = [...tvpLines, ...scalarDeclareLines]; - if (declareLines.length === 0) { + try { + const params = parameters || {}; + const descriptors = Object.entries(params).map(([name, parameter]) => toParameterDescriptor(name, parameter)); + const tvpDescriptors = descriptors.filter((descriptor) => descriptor.value instanceof mssql.Table); + const scalarDeclareLines = descriptors.filter((descriptor) => !(descriptor.value instanceof mssql.Table)).map((descriptor) => { + const sqlType = getSqlTypeFromParameter(descriptor); + const sqlValue = stringifySqlValue(descriptor.value); + return `DECLARE @${descriptor.name} ${sqlType} = ${sqlValue}`; + }); + const tvpLines = tvpDescriptors.flatMap((descriptor) => formatTvpParameter(descriptor)); + const declareLines = [...tvpLines, ...scalarDeclareLines]; + if (declareLines.length === 0) { + return query || ''; + } + return `${declareLines.join('\n')}\n\n${query || ''}`; + } catch { return query || ''; } - return `${declareLines.join('\n')}\n\n${query || ''}`; }; const formatQueryForLog = ({ query, parameters, dialect = 'mssql' } = {}) => { From c7de66b011f168aaa15dd338b39400156fd255ee Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Tue, 2 Jun 2026 00:41:02 +0000 Subject: [PATCH 18/31] Fix execute logging format for proxied stored procedure calls --- lib/sql.js | 26 +++++++++++++++++++++++--- tests/sql-log-format.test.js | 33 +++++++++++++++++++++++++++++++++ 2 files changed, 56 insertions(+), 3 deletions(-) diff --git a/lib/sql.js b/lib/sql.js index c2af383..f3e7647 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -190,6 +190,24 @@ const formatQueryForLog = ({ query, parameters, dialect = 'mssql' } = {}) => { return dialect === 'mssql' ? formatSqlQueryForLog({ query, parameters }) : (query || ''); }; +const buildExecuteStatementForLog = ({ query, parameters } = {}) => { + if (typeof query !== 'string' || !query.trim()) { + return query || ''; + } + if (/^\s*EXEC(?:UTE)?\b/i.test(query)) { + return query; + } + if (!parameters || typeof parameters !== 'object') { + return `EXEC ${query}`; + } + const bindings = Object.entries(parameters).map(([name, parameter]) => { + const descriptor = toParameterDescriptor(name, parameter); + const parameterName = descriptor.name || name; + return `@${parameterName} = @${parameterName}`; + }); + return bindings.length > 0 ? `EXEC ${query} ${bindings.join(', ')}` : `EXEC ${query}`; +}; + const summarizeTvpParameter = (table) => ({ type: getTvpPath(table), columns: (table?.columns || []).map((column) => column.name), @@ -1314,13 +1332,15 @@ class Sql { return this.runQuery({ request, type, query }); } - createProxy = (originalFunction, queryLogger) => { + createProxy = (originalFunction, queryLogger, { callType = 'query' } = {}) => { return new Proxy(originalFunction, { apply: async function (target, thisArg, args) { const queryStartTime = Date.now(); const returnValue = await Reflect.apply(target, thisArg, args); const [query] = args; - queryLogger({ query, start: queryStartTime, end: Date.now(), parameters: thisArg.parameters || thisArg.params }); + const parameters = thisArg.parameters || thisArg.params; + const queryForLog = callType === 'execute' ? buildExecuteStatementForLog({ query, parameters }) : query; + queryLogger({ query: queryForLog, start: queryStartTime, end: Date.now(), parameters }); return returnValue; } }); @@ -1336,7 +1356,7 @@ class Sql { }); const request = this.pool.request(); request.query = this.createProxy(request.query, queryLogger); - request.execute = this.createProxy(request.execute, queryLogger); + request.execute = this.createProxy(request.execute, queryLogger, { callType: 'execute' }); request._logger = loggerToUse; request._sqlDialect = 'mssql'; diff --git a/tests/sql-log-format.test.js b/tests/sql-log-format.test.js index 1cda3c2..f30d53f 100644 --- a/tests/sql-log-format.test.js +++ b/tests/sql-log-format.test.js @@ -134,6 +134,39 @@ test('createQueryLogger never lets logging failures affect the caller', async () assert.deepStrictEqual(result, { query: 'SELECT 1' }); }); +test('createProxy logs executable EXEC statement for execute calls', async () => { + const calls = []; + const logger = { warn: (...args) => calls.push(args) }; + const queryLogger = createQueryLogger({ queryLogThreshold: -1, timeoutLogLevel: 'warn', logger }); + const sql = new Sql(); + const proxiedExecute = sql.createProxy(async function (query) { + return { query }; + }, queryLogger, { callType: 'execute' }); + + await proxiedExecute.call({ parameters: buildParameters() }, 'dbo.GetUsers'); + + assert.strictEqual(calls.length, 1); + assert.match(calls[0][0].formattedQuery, /EXEC dbo\.GetUsers @Id = @Id, @Name = @Name, @CreatedOn = @CreatedOn, @IsActive = @IsActive, @OptionalValue = @OptionalValue/); +}); + +test('createRequest passes execute callType to createProxy for request.execute', () => { + const sql = new Sql(); + const proxyOptions = []; + const request = { + query: async () => ({}), + execute: async () => ({}) + }; + sql.pool = { request: () => request }; + sql.createProxy = (originalFunction, queryLogger, options) => { + proxyOptions.push(options); + return originalFunction; + }; + + sql.createRequest(); + + assert.deepStrictEqual(proxyOptions, [undefined, { callType: 'execute' }]); +}); + test('slow-query and error log sites use formatted SQL output', async () => { const warnCalls = []; const errorCalls = []; From f0627cd6e43bb70d7518281cb5837cc9273d57fa Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Tue, 2 Jun 2026 00:50:13 +0000 Subject: [PATCH 19/31] Guard createProxy logging path --- lib/sql.js | 12 ++++++++---- tests/sql-log-format.test.js | 7 +++++++ 2 files changed, 15 insertions(+), 4 deletions(-) diff --git a/lib/sql.js b/lib/sql.js index f3e7647..5054092 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -1337,10 +1337,14 @@ class Sql { apply: async function (target, thisArg, args) { const queryStartTime = Date.now(); const returnValue = await Reflect.apply(target, thisArg, args); - const [query] = args; - const parameters = thisArg.parameters || thisArg.params; - const queryForLog = callType === 'execute' ? buildExecuteStatementForLog({ query, parameters }) : query; - queryLogger({ query: queryForLog, start: queryStartTime, end: Date.now(), parameters }); + try { + if (typeof queryLogger === 'function') { + const [query] = args; + const parameters = thisArg.parameters || thisArg.params; + const queryForLog = callType === 'execute' ? buildExecuteStatementForLog({ query, parameters }) : query; + queryLogger({ query: queryForLog, start: queryStartTime, end: Date.now(), parameters }); + } + } catch {} return returnValue; } }); diff --git a/tests/sql-log-format.test.js b/tests/sql-log-format.test.js index f30d53f..8316e5c 100644 --- a/tests/sql-log-format.test.js +++ b/tests/sql-log-format.test.js @@ -132,6 +132,13 @@ test('createQueryLogger never lets logging failures affect the caller', async () const result = await proxiedQuery.call({ parameters: throwingParameters }, 'SELECT 1'); assert.deepStrictEqual(result, { query: 'SELECT 1' }); + + const proxiedExecute = sql.createProxy(async function (query) { + return { query }; + }, invalidLogLevelLogger, { callType: 'execute' }); + + const executeResult = await proxiedExecute.call({ parameters: throwingParameters }, 'dbo.GetUsers'); + assert.deepStrictEqual(executeResult, { query: 'dbo.GetUsers' }); }); test('createProxy logs executable EXEC statement for execute calls', async () => { From d6ad4ca5db8fe61179745cf18000a47c3ff4c510 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Tue, 2 Jun 2026 08:54:06 +0000 Subject: [PATCH 20/31] Preserve async createQueryLogger contract --- lib/sql.js | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/sql.js b/lib/sql.js index 5054092..48458a3 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -280,7 +280,7 @@ const getRequestDialect = (request) => { }; const createQueryLogger = function ({ queryLogThreshold, timeoutLogLevel, logger, dialect = 'mssql' }) { - return function ({ query, start, end = Date.now(), parameters }) { + return async function ({ query, start, end = Date.now(), parameters }) { const queryDurationInMs = (end - start); if (queryDurationInMs > queryLogThreshold) { try { @@ -300,7 +300,7 @@ const createQueryLogger = function ({ queryLogThreshold, timeoutLogLevel, logger } } }; -} +}; class Sql { From 89c5bb83533b6b469699a836cd2e01176ec48085 Mon Sep 17 00:00:00 2001 From: yash-sharma-spraxa Date: Tue, 2 Jun 2026 14:28:48 +0530 Subject: [PATCH 21/31] Potential fix for pull request finding Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com> --- lib/sql.js | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/lib/sql.js b/lib/sql.js index 48458a3..76d91ba 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -445,8 +445,11 @@ class Sql { const errorLog = loggerToUse?.error; if (typeof errorLog === 'function') { try { - const parameters = summarizeParametersForLog(request.parameters); - const formattedQuery = formatSqlQueryForLog({ query, parameters: request.parameters }); + const rawParameters = request.parameters || request.params; + const dialect = getRequestDialect(request); + const queryForLog = type === 'execute' ? buildExecuteStatementForLog({ query, parameters: rawParameters }) : query; + const parameters = summarizeParametersForLog(rawParameters); + const formattedQuery = formatQueryForLog({ query: queryForLog, parameters: rawParameters, dialect }); errorLog.call(loggerToUse, { err, type, query, parameters, formattedQuery }, 'SQL query failed'); } catch { try { From 66b437a9700fdd4db1c5e14f5a5175550e8b3266 Mon Sep 17 00:00:00 2001 From: yash-sharma-spraxa Date: Tue, 2 Jun 2026 14:29:00 +0530 Subject: [PATCH 22/31] Potential fix for pull request finding Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com> --- lib/sql.js | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/lib/sql.js b/lib/sql.js index 76d91ba..9b5c489 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -473,7 +473,8 @@ class Sql { } const parameters = request.parameters || request.params; const dialect = getRequestDialect(request); - const formattedQuery = formatQueryForLog({ query, parameters, dialect }); + const queryForLog = type === 'execute' ? buildExecuteStatementForLog({ query, parameters }) : query; + const formattedQuery = formatQueryForLog({ query: queryForLog, parameters, dialect }); const parametersForLog = summarizeParametersForLog(parameters); loggerToUse.warn( { query, type, executionTime: `${executionTime}ms`, executionTimeMs: executionTime, parameters: parametersForLog, formattedQuery, dialect }, From 29199b49c067e6b82b0d6dc834b94baea2da21bf Mon Sep 17 00:00:00 2001 From: yash-sharma-spraxa Date: Wed, 3 Jun 2026 13:47:58 +0530 Subject: [PATCH 23/31] Potential fix for pull request finding Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com> --- lib/sql.js | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/lib/sql.js b/lib/sql.js index 9b5c489..06406bb 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -447,7 +447,9 @@ class Sql { try { const rawParameters = request.parameters || request.params; const dialect = getRequestDialect(request); - const queryForLog = type === 'execute' ? buildExecuteStatementForLog({ query, parameters: rawParameters }) : query; + const queryForLog = dialect === 'mssql' && type === 'execute' + ? buildExecuteStatementForLog({ query, parameters: rawParameters }) + : query; const parameters = summarizeParametersForLog(rawParameters); const formattedQuery = formatQueryForLog({ query: queryForLog, parameters: rawParameters, dialect }); errorLog.call(loggerToUse, { err, type, query, parameters, formattedQuery }, 'SQL query failed'); From 7b9a058b3559773a3312189ef5562fe050b53aed Mon Sep 17 00:00:00 2001 From: yash-sharma-spraxa Date: Wed, 3 Jun 2026 13:48:12 +0530 Subject: [PATCH 24/31] Potential fix for pull request finding Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com> --- lib/sql.js | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/lib/sql.js b/lib/sql.js index 06406bb..c2c83a6 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -475,9 +475,10 @@ class Sql { } const parameters = request.parameters || request.params; const dialect = getRequestDialect(request); - const queryForLog = type === 'execute' ? buildExecuteStatementForLog({ query, parameters }) : query; + const queryForLog = dialect === 'mssql' && type === 'execute' + ? buildExecuteStatementForLog({ query, parameters }) + : query; const formattedQuery = formatQueryForLog({ query: queryForLog, parameters, dialect }); - const parametersForLog = summarizeParametersForLog(parameters); loggerToUse.warn( { query, type, executionTime: `${executionTime}ms`, executionTimeMs: executionTime, parameters: parametersForLog, formattedQuery, dialect }, `Query execution exceeded ${maxQueryTime} milliseconds (${executionTime}ms) [${type}]` From 2770c86bb1d56622e7b8dc92342f407028253ad1 Mon Sep 17 00:00:00 2001 From: yash-sharma-spraxa Date: Wed, 3 Jun 2026 17:11:21 +0530 Subject: [PATCH 25/31] Potential fix for pull request finding Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com> --- tests/sql-log-format.test.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/sql-log-format.test.js b/tests/sql-log-format.test.js index 8316e5c..601f8ac 100644 --- a/tests/sql-log-format.test.js +++ b/tests/sql-log-format.test.js @@ -18,7 +18,7 @@ test('formatSqlQueryForLog prints DECLARE statements and readable SQL', () => { assert.match(formattedQuery, /DECLARE @Id INT = 5/); assert.match(formattedQuery, /DECLARE @Name VARCHAR\(20\) = 'O''Brien'/); - assert.match(formattedQuery, /DECLARE @CreatedOn DATETIME2 = '2025-01-02 03:04:05\.678Z'/); + assert.match(formattedQuery, /DECLARE @CreatedOn DATETIME2 = '2025-01-02 03:04:05\.678'/); assert.match(formattedQuery, /DECLARE @IsActive BIT = 1/); assert.match(formattedQuery, /DECLARE @OptionalValue INT = NULL/); assert.ok(formattedQuery.endsWith(query)); From 1e2108270af1a79218087b8a578412b955b607af Mon Sep 17 00:00:00 2001 From: yash-sharma-spraxa Date: Wed, 3 Jun 2026 17:12:29 +0530 Subject: [PATCH 26/31] Potential fix for pull request finding Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com> --- lib/sql.js | 1 + 1 file changed, 1 insertion(+) diff --git a/lib/sql.js b/lib/sql.js index c2c83a6..d48a617 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -479,6 +479,7 @@ class Sql { ? buildExecuteStatementForLog({ query, parameters }) : query; const formattedQuery = formatQueryForLog({ query: queryForLog, parameters, dialect }); + const parametersForLog = summarizeParametersForLog(parameters); loggerToUse.warn( { query, type, executionTime: `${executionTime}ms`, executionTimeMs: executionTime, parameters: parametersForLog, formattedQuery, dialect }, `Query execution exceeded ${maxQueryTime} milliseconds (${executionTime}ms) [${type}]` From 87a8034deeb588e0e8301c267a8776358be19294 Mon Sep 17 00:00:00 2001 From: yash-sharma-spraxa Date: Wed, 3 Jun 2026 17:12:47 +0530 Subject: [PATCH 27/31] Potential fix for pull request finding Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com> --- lib/sql.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/sql.js b/lib/sql.js index d48a617..c534e1b 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -66,7 +66,7 @@ const stringifySqlValue = (value) => { return value ? '1' : '0'; } if (value instanceof Date) { - return `'${dayjs(value).utc().format('YYYY-MM-DD HH:mm:ss.SSS[Z]')}'`; + return `'${dayjs(value).utc().format('YYYY-MM-DD HH:mm:ss.SSS')}'`; } if (Buffer.isBuffer(value)) { return `0x${value.toString('hex')}`; From 7fad43e411803e0204260c1b7a0cfa8f636bddcf Mon Sep 17 00:00:00 2001 From: yash-sharma-spraxa Date: Thu, 4 Jun 2026 21:02:06 +0530 Subject: [PATCH 28/31] Potential fix for pull request finding Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com> --- tests/sql-log-format.test.js | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/tests/sql-log-format.test.js b/tests/sql-log-format.test.js index 601f8ac..8c437b4 100644 --- a/tests/sql-log-format.test.js +++ b/tests/sql-log-format.test.js @@ -87,8 +87,7 @@ test('createQueryLogger logs formatted multiline SQL when threshold is exceeded' }); test('createQueryLogger never lets logging failures affect the caller', async () => { - const invalidLogLevelLogger = createQueryLogger({ queryLogThreshold: 1, timeoutLogLevel: 'warn', logger: {} }); - assert.doesNotThrow(() => invalidLogLevelLogger({ + await assert.doesNotReject(invalidLogLevelLogger({ query: 'SELECT 1', start: 0, end: 10, From 6594692ff2b4e93276ae490b4f9283edd2e5d37a Mon Sep 17 00:00:00 2001 From: yash-sharma-spraxa Date: Thu, 4 Jun 2026 21:02:18 +0530 Subject: [PATCH 29/31] Potential fix for pull request finding Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com> --- tests/sql-log-format.test.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/sql-log-format.test.js b/tests/sql-log-format.test.js index 8c437b4..1b06474 100644 --- a/tests/sql-log-format.test.js +++ b/tests/sql-log-format.test.js @@ -110,7 +110,7 @@ test('createQueryLogger never lets logging failures affect the caller', async () } }); - assert.doesNotThrow(() => throwingLogger({ + await assert.doesNotReject(throwingLogger({ query: 'SELECT 1', start: 0, end: 10, From 0843113f0038f08781117664d1a96447b59b3748 Mon Sep 17 00:00:00 2001 From: yash-sharma-spraxa Date: Thu, 4 Jun 2026 21:02:30 +0530 Subject: [PATCH 30/31] Potential fix for pull request finding Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com> --- tests/sql-log-format.test.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/sql-log-format.test.js b/tests/sql-log-format.test.js index 1b06474..f9c7ae5 100644 --- a/tests/sql-log-format.test.js +++ b/tests/sql-log-format.test.js @@ -117,7 +117,7 @@ test('createQueryLogger never lets logging failures affect the caller', async () parameters: buildParameters() })); - assert.doesNotThrow(() => invalidLogLevelLogger({ + await assert.doesNotReject(invalidLogLevelLogger({ query: 'SELECT 1', start: 0, end: 10, From f2ac8d8a88fff4916940dc0bd55b35c302907627 Mon Sep 17 00:00:00 2001 From: Yash Sharma Date: Thu, 4 Jun 2026 21:12:45 +0530 Subject: [PATCH 31/31] emit N'...' literals for Unicode SQL types in query log output DECLARE statements for NVARCHAR/NCHAR/NTEXT parameters and TVP columns now use the correct N'...' prefix instead of VARCHAR literals, preventing silent corruption of non-ASCII characters in logged executable SQL. --- lib/sql.js | 21 ++++++++++++++------- 1 file changed, 14 insertions(+), 7 deletions(-) diff --git a/lib/sql.js b/lib/sql.js index c534e1b..c95f430 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -48,13 +48,14 @@ const mssqlSqlTypeMap = { const maxLengthSqlTypes = new Set(['VARCHAR', 'NVARCHAR', 'VARBINARY']); const inferredLengthSqlTypes = new Set(['CHAR', 'NCHAR', 'BINARY']); +const unicodeSqlTypes = new Set(['NVARCHAR', 'NCHAR', 'NTEXT']); -const stringifySqlValue = (value) => { +const stringifySqlValue = (value, unicode = false) => { if (value === null || value === undefined) { return 'NULL'; } if (typeof value === 'string') { - return `'${value.replace(/'/g, "''")}'`; + return `${unicode ? 'N' : ''}'${value.replace(/'/g, "''")}'`; } if (typeof value === 'number') { return Number.isFinite(value) ? String(value) : 'NULL'; @@ -71,15 +72,16 @@ const stringifySqlValue = (value) => { if (Buffer.isBuffer(value)) { return `0x${value.toString('hex')}`; } + const prefix = unicode ? 'N' : ''; try { const serialized = JSON.stringify(value); if (serialized === undefined) { - return `'[Unserializable]'`; + return `${prefix}'[Unserializable]'`; } - return `'${serialized.replace(/'/g, "''")}'`; + return `${prefix}'${serialized.replace(/'/g, "''")}'`; } catch (err) { const safeMessage = err?.message ? String(err.message).replace(/'/g, "''") : 'Unable to serialize value'; - return `'[Unserializable: ${safeMessage}]'`; + return `${prefix}'[Unserializable: ${safeMessage}]'`; } }; @@ -153,11 +155,15 @@ const formatTvpParameter = (descriptor) => { return lines; } const columnsClause = columnNames.map((name) => `[${name}]`).join(', '); + const columnIsUnicode = (tvp.columns || []).map((column) => { + const typeName = column?.type?.type?.name || column?.type?.name; + return typeName === 'NVarChar' || typeName === 'NChar' || typeName === 'NText'; + }); const rowBatchSize = 100; for (let index = 0; index < rows.length; index += rowBatchSize) { const batchRows = rows.slice(index, index + rowBatchSize); const valuesClause = batchRows.map((row) => { - const values = columnNames.map((_, colIndex) => stringifySqlValue(row[colIndex])); + const values = columnNames.map((_, colIndex) => stringifySqlValue(row[colIndex], columnIsUnicode[colIndex])); return `(${values.join(', ')})`; }).join(',\n'); lines.push(`INSERT INTO @${descriptor.name} (${columnsClause}) VALUES\n${valuesClause};`); @@ -172,7 +178,8 @@ const formatSqlQueryForLog = ({ query, parameters } = {}) => { const tvpDescriptors = descriptors.filter((descriptor) => descriptor.value instanceof mssql.Table); const scalarDeclareLines = descriptors.filter((descriptor) => !(descriptor.value instanceof mssql.Table)).map((descriptor) => { const sqlType = getSqlTypeFromParameter(descriptor); - const sqlValue = stringifySqlValue(descriptor.value); + const isUnicode = unicodeSqlTypes.has(sqlType.split('(')[0]); + const sqlValue = stringifySqlValue(descriptor.value, isUnicode); return `DECLARE @${descriptor.name} ${sqlType} = ${sqlValue}`; }); const tvpLines = tvpDescriptors.flatMap((descriptor) => formatTvpParameter(descriptor));