Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 3 additions & 1 deletion lib/mysql.js
Original file line number Diff line number Diff line change
Expand Up @@ -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 = {
Expand All @@ -106,6 +107,7 @@ class Mysql extends Sql {
input: this.input,
params: {},
_logger: loggerToUse,
_sqlDialect: 'mysql',
};
return request;
}
Expand Down
287 changes: 269 additions & 18 deletions lib/sql.js
Original file line number Diff line number Diff line change
@@ -1,4 +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';
Expand All @@ -7,18 +9,262 @@ 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 createQueryLogger = function ({ queryLogThreshold, timeoutLogLevel, logger }) {
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 maxLengthSqlTypes = new Set(['VARCHAR', 'NVARCHAR', 'VARBINARY']);
const inferredLengthSqlTypes = new Set(['CHAR', 'NCHAR', 'BINARY']);

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 === 'bigint') {
return value.toString();
}
if (typeof value === 'boolean') {
return value ? '1' : '0';
}
if (value instanceof Date) {
return `'${dayjs(value).utc().format('YYYY-MM-DD HH:mm:ss.SSS[Z]')}'`;
}
Comment on lines +66 to +68
if (Buffer.isBuffer(value)) {
return `0x${value.toString('hex')}`;
}
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 value';
return `'[Unserializable: ${safeMessage}]'`;
}
};
Comment on lines +69 to +82

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)) {
// The mssql package uses mssql.MAX as the sentinel for MAX-length variable types.
if (parameter?.length === mssql.MAX) {
return `${sqlType}(MAX)`;
}
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)) {
if (Number.isFinite(parameter?.length)) {
return `${sqlType}(${parameter.length})`;
}
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)) {
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 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]));
Comment on lines +154 to +158
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The log messages should be complete.

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 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 || ''}`;
};

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 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 [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 [parameterName, normalizeValueForJsonLog(descriptor.value)];
}));
};
Comment on lines +232 to +247

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';
};

const createQueryLogger = function ({ queryLogThreshold, timeoutLogLevel, logger, dialect = 'mssql' }) {
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 = 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`
);
Comment on lines +258 to +267
}
};
}
Expand Down Expand Up @@ -121,22 +367,25 @@ 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 });
return { success: false, err, data: {} };
const parameters = summarizeParametersForLog(request.parameters);
const formattedQuery = formatSqlQueryForLog({ query, parameters: request.parameters });
loggerToUse.error({ err, type, query, parameters, formattedQuery }, 'SQL query failed');
return { success: false, err, data: {} };
}
}

logSlowQuery({ startTime, query, type, request }) {
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 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}]`
);
}
}

Expand Down Expand Up @@ -790,7 +1039,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;
}
});
Expand All @@ -801,12 +1050,14 @@ 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);
request.execute = this.createProxy(request.execute, queryLogger);
request._logger = loggerToUse;
request._sqlDialect = 'mssql';

return request;
}
Expand Down Expand Up @@ -896,4 +1147,4 @@ class Sql {

export default Sql;

export { mssql, createQueryLogger };
export { mssql, createQueryLogger, formatSqlQueryForLog };
2 changes: 2 additions & 0 deletions tests/mysql-create-request.test.js
Original file line number Diff line number Diff line change
Expand Up @@ -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);
});
Expand Down
Loading