From 71c7d7e22f9ed881947050c42da03eaedd88fdc4 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/12] Initial plan From be4423dbd747f61b9d40d546f2c9c2612af78ce3 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/12] 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 3c2a25e..0dd7d6a 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'; @@ -10,15 +11,112 @@ const { inOperatorStrategies, dateTimeFields, columnTypes } = enums; const isNullNotNullOperators = ['IS NOT NULL', 'IS NULL']; +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}`); } }; } @@ -121,7 +219,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: {} }; } } @@ -130,13 +229,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}`); } } @@ -896,4 +990,4 @@ class Sql { export default Sql; -export { mssql, createQueryLogger }; \ No newline at end of file +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 2c2023e9b3bdb9413ebf35945913b94e23bc9a72 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/12] 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 0dd7d6a..942db79 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -97,14 +97,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 535059dac2d377ab9391c0c57b750cba9e87798e 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/12] 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 942db79..bed4f81 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']; @@ -52,16 +54,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) => { @@ -148,12 +162,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}` + ); } }; } @@ -266,8 +283,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}` + ); } } @@ -921,7 +942,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; } }); @@ -932,7 +953,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 9401e7eb46b53f543cdfecb7c4a8dd1154797b1b 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/12] 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 bed4f81..f846590 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -61,7 +61,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')}`; @@ -73,7 +73,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 f836c8ab2c360111c596a8fb39e61efcc1f25edf 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/12] 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 f846590..676b08f 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -61,7 +61,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 ca319be4133f107ac35f51b3412f143e955da864 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/12] 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 676b08f..297bb10 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -44,6 +44,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'; @@ -82,13 +85,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)) { @@ -162,13 +175,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}` ); } @@ -273,8 +310,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: {} }; } } @@ -284,9 +322,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 1e180db51dcd8ce678f0d679735f61ff3c819111 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/12] 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 297bb10..106be5b 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -85,15 +85,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)})`; @@ -198,6 +201,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); @@ -322,7 +332,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( @@ -1000,6 +1010,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 eb47d1e0308955fce8b9504554ea6869d84c0a40 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/12] 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 106be5b..71ae7ed 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -86,6 +86,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)`; } @@ -205,6 +206,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 b1b913ad35668353298c5a04c62f5b029283c353 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/12] 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 71ae7ed..bfc49ec 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -93,6 +93,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 4f891c127471f04dc09fd45e16428945529cc27a 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/12] 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 bfc49ec..bb29cbd 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -220,7 +220,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` ); } }; @@ -327,7 +327,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: {} }; } } @@ -341,7 +341,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 909c303a56b189c25bc349358bb811db445bfed8 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/12] 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 bb29cbd..b01e40d 100644 --- a/lib/sql.js +++ b/lib/sql.js @@ -190,16 +190,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)]; })); }; @@ -326,7 +369,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]'); + }); +});