Skip to content

public / sequelize

Go to a project

不要怂，就是干，撸起袖子干！

Commit 4b2bc4a6 by Sushant Committed by Mick Hansen
Options

Fix #2852, Added DEBUG support and intensive connection logging (#6117) 

* (feat) DEBUG and depd

* query logging

* connection logging

* changelog for debug support

* oopps, need the use strict

* simplify debug and deprecation

* context based logs

* fixed variable name

* sql logging contexts, message changes

* message name change
1 parent 6326cb17
Inline Side-by-side
Showing with 113 additions and 8 deletions
changelog.md
...@@ -8,6 +8,8 @@ ...@@ -8,6 +8,8 @@
- [FIXED] `hasOne` throws error on update with a primary key [#6069](https://github.com/sequelize/sequelize/issues/6069) - [FIXED] `hasOne` throws error on update with a primary key [#6069](https://github.com/sequelize/sequelize/issues/6069)
- [FIXED] `Model.count` gives SQL syntax error when using `distinct` [#4840](https://github.com/sequelize/sequelize/issues/4840) - [FIXED] `Model.count` gives SQL syntax error when using `distinct` [#4840](https://github.com/sequelize/sequelize/issues/4840)
- [ADDED] `Model.count` now allow specifying column to count on, use `options.col` [#4442](https://github.com/sequelize/sequelize/issues/4442) - [ADDED] `Model.count` now allow specifying column to count on, use `options.col` [#4442](https://github.com/sequelize/sequelize/issues/4442)
- [ADDED] `DEBUG` support [#2852](https://github.com/sequelize/sequelize/issues/2852)
- [ADDED] Intensive connection logging [#851](https://github.com/sequelize/sequelize/issues/851)
## BC breaks: ## BC breaks:
- Range type bounds now default to [postgres default](https://www.postgresql.org/docs/9.5/static/rangetypes.html#RANGETYPES-CONSTRUCT) `[)` (inclusive, exclusive), previously was `()` (exclusive, exclusive) - Range type bounds now default to [postgres default](https://www.postgresql.org/docs/9.5/static/rangetypes.html#RANGETYPES-CONSTRUCT) `[)` (inclusive, exclusive), previously was `()` (exclusive, exclusive)
......
index.js
'use strict'; 'use strict';
/** /**
The entry point. * The entry point.
@module Sequelize *
**/ * @module Sequelize
*/
module.exports = require('./lib/sequelize'); module.exports = require('./lib/sequelize');
lib/dialects/abstract/connection-manager.js
...@@ -3,6 +3,8 @@ ...@@ -3,6 +3,8 @@
const Pooling = require('generic-pool'); const Pooling = require('generic-pool');
const Promise = require('../../promise'); const Promise = require('../../promise');
const _ = require('lodash'); const _ = require('lodash');
const Utils = require('../../utils');
const debug = Utils.getLogger().debugContext('pool');
const semver = require('semver'); const semver = require('semver');
const defaultPoolingConfig = { const defaultPoolingConfig = {
max: 5, max: 5,
...@@ -51,6 +53,7 @@ class ConnectionManager { ...@@ -51,6 +53,7 @@ class ConnectionManager {
onProcessExit() { onProcessExit() {
if (this.pool) { if (this.pool) {
this.pool.drain(() => { this.pool.drain(() => {
debug(`connection drain due to process exit`);
this.pool.destroyAllNow(); this.pool.destroyAllNow();
}); });
} }
...@@ -75,10 +78,12 @@ class ConnectionManager { ...@@ -75,10 +78,12 @@ class ConnectionManager {
name: 'sequelize-connection', name: 'sequelize-connection',
create: (callback) => { create: (callback) => {
this.$connect(config).nodeify((err, connection) => { this.$connect(config).nodeify((err, connection) => {
debug(`pool created max/min: ${config.pool.max}/${config.pool.min} with no replication`);
callback(err, connection); // For some reason this is needed, else generic-pool things err is a connection or some shit callback(err, connection); // For some reason this is needed, else generic-pool things err is a connection or some shit
}); });
}, },
destroy: (connection) => { destroy: (connection) => {
debug(`connection destroy`);
this.$disconnect(connection); this.$disconnect(connection);
return null; return null;
}, },
...@@ -122,9 +127,11 @@ class ConnectionManager { ...@@ -122,9 +127,11 @@ class ConnectionManager {
} }
}, },
destroy: (connection) => { destroy: (connection) => {
debug(`connection destroy`);
return this.pool[connection.queryType].destroy(connection); return this.pool[connection.queryType].destroy(connection);
}, },
destroyAllNow: () => { destroyAllNow: () => {
debug(`all connection destroy`);
this.pool.read.destroyAllNow(); this.pool.read.destroyAllNow();
this.pool.write.destroyAllNow(); this.pool.write.destroyAllNow();
}, },
...@@ -208,6 +215,7 @@ class ConnectionManager { ...@@ -208,6 +215,7 @@ class ConnectionManager {
return promise.then(() => new Promise((resolve, reject) => { return promise.then(() => new Promise((resolve, reject) => {
this.pool.acquire((err, connection) => { this.pool.acquire((err, connection) => {
if (err) return reject(err); if (err) return reject(err);
debug(`connection acquired`);
resolve(connection); resolve(connection);
}, options.priority, options.type, options.useMaster); }, options.priority, options.type, options.useMaster);
})); }));
...@@ -216,6 +224,7 @@ class ConnectionManager { ...@@ -216,6 +224,7 @@ class ConnectionManager {
releaseConnection(connection) { releaseConnection(connection) {
return new Promise((resolve, reject) => { return new Promise((resolve, reject) => {
this.pool.release(connection); this.pool.release(connection);
debug(`connection released`);
resolve(); resolve();
}); });
} }
......
lib/dialects/mssql/connection-manager.js
...@@ -3,6 +3,8 @@ ...@@ -3,6 +3,8 @@
const AbstractConnectionManager = require('../abstract/connection-manager'); const AbstractConnectionManager = require('../abstract/connection-manager');
const ResourceLock = require('./resource-lock'); const ResourceLock = require('./resource-lock');
const Promise = require('../../promise'); const Promise = require('../../promise');
const Utils = require('../../utils');
const debug = Utils.getLogger().debugContext('connection:mssql');
const sequelizeErrors = require('../../errors'); const sequelizeErrors = require('../../errors');
const parserStore = require('../parserStore')('mssql'); const parserStore = require('../parserStore')('mssql');
const _ = require('lodash'); const _ = require('lodash');
...@@ -66,6 +68,7 @@ class ConnectionManager extends AbstractConnectionManager { ...@@ -66,6 +68,7 @@ class ConnectionManager extends AbstractConnectionManager {
connection.on('connect', err => { connection.on('connect', err => {
if (!err) { if (!err) {
debug(`connection acquired`);
resolve(connectionLock); resolve(connectionLock);
return; return;
} }
...@@ -130,6 +133,7 @@ class ConnectionManager extends AbstractConnectionManager { ...@@ -130,6 +133,7 @@ class ConnectionManager extends AbstractConnectionManager {
return new Promise(resolve => { return new Promise(resolve => {
connection.on('end', resolve); connection.on('end', resolve);
connection.close(); connection.close();
debug(`connection closed`);
}); });
} }
......
lib/dialects/mssql/query.js
'use strict'; 'use strict';
const Utils = require('../../utils'); const Utils = require('../../utils');
const debug = Utils.getLogger().debugContext('sql:mssql');
const Promise = require('../../promise'); const Promise = require('../../promise');
const AbstractQuery = require('../abstract/query'); const AbstractQuery = require('../abstract/query');
const sequelizeErrors = require('../../errors.js'); const sequelizeErrors = require('../../errors.js');
...@@ -39,6 +40,8 @@ class Query extends AbstractQuery { ...@@ -39,6 +40,8 @@ class Query extends AbstractQuery {
this.sequelize.log('Executing (' + (connection.uuid || 'default') + '): ' + this.sql, this.options); this.sequelize.log('Executing (' + (connection.uuid || 'default') + '): ' + this.sql, this.options);
} }
debug(`executing(${connection.uuid || 'default'}) : ${this.sql}`);
return new Promise((resolve, reject) => { return new Promise((resolve, reject) => {
// TRANSACTION SUPPORT // TRANSACTION SUPPORT
if (_.includes(this.sql, 'BEGIN TRANSACTION')) { if (_.includes(this.sql, 'BEGIN TRANSACTION')) {
...@@ -71,6 +74,8 @@ class Query extends AbstractQuery { ...@@ -71,6 +74,8 @@ class Query extends AbstractQuery {
const request = new connection.lib.Request(this.sql, err => { const request = new connection.lib.Request(this.sql, err => {
debug(`executed(${connection.uuid || 'default'}) : ${this.sql}`);
if (benchmark) { if (benchmark) {
this.sequelize.log('Executed (' + (connection.uuid || 'default') + '): ' + this.sql, (Date.now() - queryBegin), this.options); this.sequelize.log('Executed (' + (connection.uuid || 'default') + '): ' + this.sql, (Date.now() - queryBegin), this.options);
} }
......
lib/dialects/mysql/connection-manager.js
...@@ -2,6 +2,7 @@ ...@@ -2,6 +2,7 @@
const AbstractConnectionManager = require('../abstract/connection-manager'); const AbstractConnectionManager = require('../abstract/connection-manager');
const Utils = require('../../utils'); const Utils = require('../../utils');
const debug = Utils.getLogger().debugContext('connection:mysql');
const Promise = require('../../promise'); const Promise = require('../../promise');
const sequelizeErrors = require('../../errors'); const sequelizeErrors = require('../../errors');
const dataTypes = require('../../data-types').mysql; const dataTypes = require('../../data-types').mysql;
...@@ -112,8 +113,10 @@ class ConnectionManager extends AbstractConnectionManager { ...@@ -112,8 +113,10 @@ class ConnectionManager extends AbstractConnectionManager {
// Remove it from read/write pool // Remove it from read/write pool
this.pool.destroy(connection); this.pool.destroy(connection);
} }
debug(`connection error ${err.code}`);
}); });
} }
debug(`connection acquired`);
resolve(connection); resolve(connection);
}); });
...@@ -127,12 +130,14 @@ class ConnectionManager extends AbstractConnectionManager { ...@@ -127,12 +130,14 @@ class ConnectionManager extends AbstractConnectionManager {
// Dont disconnect connections with an ended protocol // Dont disconnect connections with an ended protocol
// That wil trigger a connection error // That wil trigger a connection error
if (connection._protocol._ended) { if (connection._protocol._ended) {
debug(`connection tried to disconnect but was already at ENDED state`);
return Promise.resolve(); return Promise.resolve();
} }
return new Promise((resolve, reject) => { return new Promise((resolve, reject) => {
connection.end(err => { connection.end(err => {
if (err) return reject(new sequelizeErrors.ConnectionError(err)); if (err) return reject(new sequelizeErrors.ConnectionError(err));
debug(`connection disconnected`);
resolve(); resolve();
}); });
}); });
......
lib/dialects/mysql/query.js
'use strict'; 'use strict';
const Utils = require('../../utils'); const Utils = require('../../utils');
const debug = Utils.getLogger().debugContext('sql:mysql');
const AbstractQuery = require('../abstract/query'); const AbstractQuery = require('../abstract/query');
const uuid = require('node-uuid'); const uuid = require('node-uuid');
const sequelizeErrors = require('../../errors.js'); const sequelizeErrors = require('../../errors.js');
...@@ -38,9 +39,13 @@ class Query extends AbstractQuery { ...@@ -38,9 +39,13 @@ class Query extends AbstractQuery {
this.sequelize.log('Executing (' + (this.connection.uuid || 'default') + '): ' + this.sql, this.options); this.sequelize.log('Executing (' + (this.connection.uuid || 'default') + '): ' + this.sql, this.options);
} }
debug(`executing(${this.connection.uuid || 'default'}) : ${this.sql}`);
return new Utils.Promise((resolve, reject) => { return new Utils.Promise((resolve, reject) => {
this.connection.query(this.sql, (err, results) => { this.connection.query(this.sql, (err, results) => {
debug(`executed(${this.connection.uuid || 'default'}) : ${this.sql}`);
if (benchmark) { if (benchmark) {
this.sequelize.log('Executed (' + (this.connection.uuid || 'default') + '): ' + this.sql, (Date.now() - queryBegin), this.options); this.sequelize.log('Executed (' + (this.connection.uuid || 'default') + '): ' + this.sql, (Date.now() - queryBegin), this.options);
} }
......
lib/dialects/postgres/connection-manager.js
...@@ -2,6 +2,7 @@ ...@@ -2,6 +2,7 @@
const AbstractConnectionManager = require('../abstract/connection-manager'); const AbstractConnectionManager = require('../abstract/connection-manager');
const Utils = require('../../utils'); const Utils = require('../../utils');
const debug = Utils.getLogger().debugContext('connection:pg');
const Promise = require('../../promise'); const Promise = require('../../promise');
const sequelizeErrors = require('../../errors'); const sequelizeErrors = require('../../errors');
const semver = require('semver'); const semver = require('semver');
...@@ -109,18 +110,21 @@ class ConnectionManager extends AbstractConnectionManager { ...@@ -109,18 +110,21 @@ class ConnectionManager extends AbstractConnectionManager {
return; return;
} }
responded = true; responded = true;
debug(`connection acquired`);
resolve(connection); resolve(connection);
}); });
// If we didn't ever hear from the client.connect() callback the connection timeout, node-postgres does not treat this as an error since no active query was ever emitted // If we didn't ever hear from the client.connect() callback the connection timeout, node-postgres does not treat this as an error since no active query was ever emitted
connection.on('end', () => { connection.on('end', () => {
debug(`connection timeout`);
if (!responded) { if (!responded) {
reject(new sequelizeErrors.ConnectionTimedOutError(new Error('Connection timed out'))); reject(new sequelizeErrors.ConnectionTimedOutError(new Error('Connection timed out')));
} }
}); });
// Don't let a Postgres restart (or error) to take down the whole app // Don't let a Postgres restart (or error) to take down the whole app
connection.on('error', () => { connection.on('error', (err) => {
debug(`connection error ${err.code}`);
connection._invalid = true; connection._invalid = true;
}); });
}).tap(connection => { }).tap(connection => {
......
lib/dialects/postgres/query.js
'use strict'; 'use strict';
const Utils = require('../../utils'); const Utils = require('../../utils');
const debug = Utils.getLogger().debugContext('sql:pg');
const AbstractQuery = require('../abstract/query'); const AbstractQuery = require('../abstract/query');
const QueryTypes = require('../../query-types'); const QueryTypes = require('../../query-types');
const Promise = require('../../promise'); const Promise = require('../../promise');
...@@ -72,6 +73,8 @@ class Query extends AbstractQuery { ...@@ -72,6 +73,8 @@ class Query extends AbstractQuery {
this.sequelize.log('Executing (' + (this.client.uuid || 'default') + '): ' + this.sql, this.options); this.sequelize.log('Executing (' + (this.client.uuid || 'default') + '): ' + this.sql, this.options);
} }
debug(`executing(${this.client.uuid || 'default'}) : ${this.sql}`);
return new Promise((resolve, reject) => { return new Promise((resolve, reject) => {
query.on('row', row => { query.on('row', row => {
rows.push(row); rows.push(row);
...@@ -91,6 +94,8 @@ class Query extends AbstractQuery { ...@@ -91,6 +94,8 @@ class Query extends AbstractQuery {
query.on('end', result => { query.on('end', result => {
debug(`executed(${this.client.uuid || 'default'}) : ${this.sql}`);
if (benchmark) { if (benchmark) {
this.sequelize.log('Executed (' + (this.client.uuid || 'default') + '): ' + this.sql, (Date.now() - queryBegin), this.options); this.sequelize.log('Executed (' + (this.client.uuid || 'default') + '): ' + this.sql, (Date.now() - queryBegin), this.options);
} }
......
lib/dialects/sqlite/connection-manager.js
...@@ -2,6 +2,8 @@ ...@@ -2,6 +2,8 @@
const AbstractConnectionManager = require('../abstract/connection-manager'); const AbstractConnectionManager = require('../abstract/connection-manager');
const Promise = require('../../promise'); const Promise = require('../../promise');
const Utils = require('../../utils');
const debug = Utils.getLogger().debugContext('connection:sqlite');
const dataTypes = require('../../data-types').sqlite; const dataTypes = require('../../data-types').sqlite;
const sequelizeErrors = require('../../errors'); const sequelizeErrors = require('../../errors');
const parserStore = require('../parserStore')('sqlite'); const parserStore = require('../parserStore')('sqlite');
...@@ -60,6 +62,7 @@ class ConnectionManager extends AbstractConnectionManager { ...@@ -60,6 +62,7 @@ class ConnectionManager extends AbstractConnectionManager {
if (err.code === 'SQLITE_CANTOPEN') return reject(new sequelizeErrors.ConnectionError(err)); if (err.code === 'SQLITE_CANTOPEN') return reject(new sequelizeErrors.ConnectionError(err));
return reject(new sequelizeErrors.ConnectionError(err)); return reject(new sequelizeErrors.ConnectionError(err));
} }
debug(`connection acquired ${options.uuid}`);
resolve(this.connections[options.inMemory || options.uuid]); resolve(this.connections[options.inMemory || options.uuid]);
} }
); );
...@@ -77,6 +80,7 @@ class ConnectionManager extends AbstractConnectionManager { ...@@ -77,6 +80,7 @@ class ConnectionManager extends AbstractConnectionManager {
if (connection.uuid) { if (connection.uuid) {
connection.close(); connection.close();
debug(`connection released ${connection.uuid}`);
delete this.connections[connection.uuid]; delete this.connections[connection.uuid];
} }
} }
......
lib/dialects/sqlite/query.js
'use strict'; 'use strict';
const _ = require('lodash'); const _ = require('lodash');
const Utils = require('../../utils');
const debug = Utils.getLogger().debugContext('sql:sqlite');
const Promise = require('../../promise'); const Promise = require('../../promise');
const AbstractQuery = require('../abstract/query'); const AbstractQuery = require('../abstract/query');
const QueryTypes = require('../../query-types'); const QueryTypes = require('../../query-types');
...@@ -92,6 +94,8 @@ class Query extends AbstractQuery { ...@@ -92,6 +94,8 @@ class Query extends AbstractQuery {
this.sequelize.log('Executing (' + (this.database.uuid || 'default') + '): ' + this.sql, this.options); this.sequelize.log('Executing (' + (this.database.uuid || 'default') + '): ' + this.sql, this.options);
} }
debug(`executing(${this.database.uuid || 'default'}) : ${this.sql}`);
return new Promise(resolve => { return new Promise(resolve => {
const columnTypes = {}; const columnTypes = {};
this.database.serialize(() => { this.database.serialize(() => {
...@@ -104,6 +108,9 @@ class Query extends AbstractQuery { ...@@ -104,6 +108,9 @@ class Query extends AbstractQuery {
// cannot use arrow function here because the function is bound to the statement // cannot use arrow function here because the function is bound to the statement
function afterExecute(err, results) { function afterExecute(err, results) {
/* jshint validthis:true */ /* jshint validthis:true */
debug(`executed(${query.database.uuid || 'default'}) : ${query.sql}`);
if (benchmark) { if (benchmark) {
query.sequelize.log('Executed (' + (query.database.uuid || 'default') + '): ' + query.sql, (Date.now() - queryBegin), query.options); query.sequelize.log('Executed (' + (query.database.uuid || 'default') + '): ' + query.sql, (Date.now() - queryBegin), query.options);
} }
......
lib/hooks.js
'use strict'; 'use strict';
var Utils = require('./utils') const Utils = require('./utils')
, Promise = require('./promise'); , Promise = require('./promise')
, debug = Utils.getLogger().debugContext('hooks');
/** /**
* Hooks are function that are called before and after (bulk-) creation/updating/deletion and validation. Hooks can be added to you models in three ways: * Hooks are function that are called before and after (bulk-) creation/updating/deletion and validation. Hooks can be added to you models in three ways:
...@@ -118,6 +119,7 @@ var Hooks = { ...@@ -118,6 +119,7 @@ var Hooks = {
if (hookTypes[hookType] && hookTypes[hookType].sync) { if (hookTypes[hookType] && hookTypes[hookType].sync) {
hooks.forEach(function(hook) { hooks.forEach(function(hook) {
if (typeof hook === 'object') hook = hook.fn; if (typeof hook === 'object') hook = hook.fn;
debug(`running hook ${hookType}`); // log sync hooks
return hook.apply(self, fnArgs); return hook.apply(self, fnArgs);
}); });
return; return;
...@@ -132,7 +134,7 @@ var Hooks = { ...@@ -132,7 +134,7 @@ var Hooks = {
if (hookType && hook.length > hookTypes[hookType].params) { if (hookType && hook.length > hookTypes[hookType].params) {
hook = Promise.promisify(hook, self); hook = Promise.promisify(hook, self);
} }
debug(`running hook ${hookType}`); // log async hook
return hook.apply(self, fnArgs); return hook.apply(self, fnArgs);
}).return(); }).return();
...@@ -158,6 +160,7 @@ var Hooks = { ...@@ -158,6 +160,7 @@ var Hooks = {
name = null; name = null;
} }
debug(`adding hook ${hookType}`);
hookType = hookAliases[hookType] || hookType; hookType = hookAliases[hookType] || hookType;
this.options.hooks[hookType] = this.options.hooks[hookType] || []; this.options.hooks[hookType] = this.options.hooks[hookType] || [];
...@@ -178,6 +181,7 @@ var Hooks = { ...@@ -178,6 +181,7 @@ var Hooks = {
return this; return this;
} }
Utils.debug(`removing hook ${hookType}`);
this.options.hooks[hookType] = this.options.hooks[hookType].filter(function (hook) { this.options.hooks[hookType] = this.options.hooks[hookType].filter(function (hook) {
// don't remove unnamed hooks // don't remove unnamed hooks
if (typeof hook === 'function') { if (typeof hook === 'function') {
......
lib/sequelize.js
...@@ -187,7 +187,7 @@ class Sequelize { ...@@ -187,7 +187,7 @@ class Sequelize {
} }
if (this.options.logging === true) { if (this.options.logging === true) {
console.log('DEPRECATION WARNING: The logging-option should be either a function or false. Default: console.log'); Utils.deprecate('The logging-option should be either a function or false. Default: console.log');
this.options.logging = console.log; this.options.logging = console.log;
} }
......
lib/utils.js
...@@ -4,13 +4,19 @@ const DataTypes = require('./data-types'); ...@@ -4,13 +4,19 @@ const DataTypes = require('./data-types');
const SqlString = require('./sql-string'); const SqlString = require('./sql-string');
const _ = require('lodash').runInContext(); // Prevent anyone messing with template settings by creating a fresh copy const _ = require('lodash').runInContext(); // Prevent anyone messing with template settings by creating a fresh copy
const parameterValidator = require('./utils/parameter-validator'); const parameterValidator = require('./utils/parameter-validator');
const Logger = require('./utils/logger');
const uuid = require('node-uuid'); const uuid = require('node-uuid');
const Promise = require('./promise'); const Promise = require('./promise');
const primitives = ['string', 'number', 'boolean']; const primitives = ['string', 'number', 'boolean'];
let inflection = require('inflection'); let inflection = require('inflection');
let logger = new Logger();
exports.Promise = Promise; exports.Promise = Promise;
exports._ = _; exports._ = _;
exports.debug = logger.debug.bind(logger);
exports.deprecate = logger.deprecate.bind(logger);
exports.getLogger = () => ( logger );
function useInflection(_inflection) { function useInflection(_inflection) {
inflection = _inflection; inflection = _inflection;
......
lib/utils/logger.js 0 → 100644
'use strict';
/**
* Sequelize module for debug and deprecation messages.
* It require a `context` for which messages will be printed.
*
* @module logging
*/
/* jshint -W030 */
const depd = require('depd')
, debug = require('debug')
, _ = require('lodash');
class Logger {
constructor(config) {
this.config = _.extend({
context: 'sequelize',
debug: true
}, config || {});
this.depd = depd(this.config.context);
this.debug = debug(this.config.context);
}
deprecate(message) {
this.depd(message);
}
debug(message) {
this.config.debug && this.debug(message);
}
debugContext(childContext) {
if (!childContext) {
throw new Error('No context supplied to debug');
}
return debug([this.config.context, childContext].join(':'));
}
}
module.exports = Logger;
package.json
...@@ -33,6 +33,7 @@ ...@@ -33,6 +33,7 @@
}, },
"dependencies": { "dependencies": {
"bluebird": "^3.4.0", "bluebird": "^3.4.0",
"debug": "^2.2.0",
"depd": "^1.1.0", "depd": "^1.1.0",
"dottie": "^1.0.0", "dottie": "^1.0.0",
"generic-pool": "2.4.2", "generic-pool": "2.4.2",
......
Markdown is supported
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!