Skip to content

Instantly share code, notes, and snippets.

@twolfson
Last active Jul 19, 2022
Embed
What would you like to do?
Audit logging via sequelize

We prefer to have audit logging in our services that leverage databases. It gives us clarity into sources of where ACL issues might originate as well as gives us a general timeline of activity in our application.

Audit logging is tedious to set up so this gist contains our latest iteration of audit logging support for a sequelize based service.

// Load in our dependencies
var assert = require('assert');
var _ = require('underscore');
var Sequelize = require('sequelize');
var sequelize = require('../index.js').sequelize;
// Define our constants
exports.ACTION_CREATE = 'create';
exports.ACTION_UPDATE = 'update';
exports.ACTION_DELETE = 'delete';
exports.VALID_ACTIONS = [exports.ACTION_CREATE, exports.ACTION_UPDATE, exports.ACTION_DELETE];
exports.SOURCE_USERS = 'users';
exports.SOURCE_SERVER = 'server';
exports.VALID_SOURCES = [exports.SOURCE_USERS, exports.SOURCE_SERVER];
// Define and export our model
// http://docs.sequelizejs.com/en/v3/docs/models-definition/
// DEV: We don't use `baseDefine` as this isn't a typical model
// (e.g. no fancy getters, no audit hooks)
// DEV: Based on memory, verified by http://stackoverflow.com/a/2015276
module.exports = _.extend(sequelize.define('audit_log', {
id: {type: Sequelize.UUID, defaultValue: Sequelize.UUIDV4, primaryKey: true},
// 'server', 'users', etc
// DEV: Validation for `source_id` being set for non-server type is in options
source_type: {
type: Sequelize.STRING(255), allowNull: false,
validate: {isIn: {args: [exports.VALID_SOURCES], msg: 'Source must be server or users'}}
},
source_id: {type: Sequelize.UUID, allowNull: true},
// 'users', 'items', etc
table_name: {type: Sequelize.STRING(255), allowNull: false},
table_row_id: {type: Sequelize.UUID, allowNull: false},
// 'create', 'update', 'delete'
action: {
type: Sequelize.STRING(32), allowNull: false,
validate: {isIn: {args: [exports.VALID_ACTIONS], msg: 'Action must be create, update, or delete'}}
},
// 2016-01-01T00:00:00Z
timestamp: {type: Sequelize.DATE, allowNull: false},
// DEV: We could store `changed_values_previous` and `changed_values_current`
// but for simplicity of querying, we are storing all values
// DEV: We wanted to use JSONB since writes only occur once whereas reads can occur many times
// However, PostgreSQL@9.3 lacks JSONB =(
// https://www.postgresql.org/docs/9.3/static/datatype-json.html
// {id: abc, email: abc1, password: hash1, ...}
previous_values: {type: Sequelize.JSON, allowNull: false},
// {id: abc, email: abc2, password: hash2, ...}
current_values: {type: Sequelize.JSON, allowNull: false},
transaction_id: {
// DEV: Since this isn't a foreign key, we can use UUID check for sanity
type: Sequelize.UUID, allowNull: true,
validate: {isUUID: 'all'}
}
}, {
validate: {
requireSourceId: function () {
if (this.getDataValue('source_type') !== exports.SOURCE_SERVER) {
assert(this.getDataValue('source_id'), 'source_id required for non-server sources in audit log');
}
}
},
// Disable `created_at`/`updated_at` timestamps
timestamps: false
}), exports);
// Add hooks for audit logging
// http://docs.sequelizejs.com/en/v3/docs/hooks/#declaring-hooks
// http://docs.sequelizejs.com/en/v3/docs/hooks/#model-hooks
function saveAuditLog(action, model, options) {
// Verify we are being run in a transaction
assert(options.transaction, 'All create/update/delete actions must be run in a transaction to ' +
'prevent orphaned AuditLogs or connected models on save. ' +
'Please add a transaction to your current "' + action + '" request');
// Resolve our model's constructor
var Model = model.Model;
var auditLog = AuditLog.build({
source_type: options._sourceType, // 'server', 'users'
source_id: options._sourceId, // NULL (server), user.id
table_name: Model.tableName,
table_row_id: model.get('id'),
action: action,
timestamp: new Date(),
// https://github.com/sequelize/sequelize/blob/v3.25.0/lib/instance.js#L86-L87
// https://github.com/sequelize/sequelize/blob/v3.25.0/lib/instance.js#L417-L433
previous_values: _.pick(model._previousDataValues, attributeKeys),
current_values: _.pick(model.dataValues, attributeKeys),
transaction_id: options.transaction ? options.transaction.id : null
});
return auditLog.save({transaction: options.transaction});
}
options.hooks = _.extend({
// DEV: We don't support bulk actions due to not knowing previous/current info for models
beforeBulkCreate: function () {
throw new Error('Audit logging not supported for bulk creation; either add support or use `create` directly');
},
beforeBulkUpdate: function () {
throw new Error('Audit logging not supported for bulk updates; either add support or use `create` directly');
},
beforeBulkDelete: function () {
throw new Error('Audit logging not supported for bulk deletion; either add support or use `create` directly');
},
afterCreate: function (model, options) {
return saveAuditLog('create', model, options);
},
afterUpdate: function (model, options) {
return saveAuditLog('update', model, options);
},
afterDelete: function (model, options) {
return saveAuditLog('delete', model, options);
}
}, options.hooks);
// Build our class
return sequelize.define(modelName, attributes, options);
// Load in our dependencies
var _ = require('underscore');
var expect = require('chai').expect;
var AuditLog = require('path/to/audit-log.js');
// Start our tests
describe('An audit log', function () {
it('doesn\'t have created_at/updated_at timestamps', function () {
expect(AuditLog.attributes).to.not.have.property('created_at');
expect(AuditLog.attributes).to.not.have.property('updated_at');
});
it('has a generic timestamp', function () {
expect(AuditLog.attributes).to.have.property('timestamp');
});
});
var validAuditLog = {
source_type: 'server',
action: 'create',
table_name: 'users',
table_row_id: 'mock-user-uuid',
timestamp: new Date(),
previous_values: {},
current_values: {}
};
describe('A valid audit log', function () {
it('receives no validation errors', function (done) {
var auditLog = AuditLog.build(_.clone(validAuditLog));
auditLog.validate().asCallback(function handleError (err, validationErr) {
expect(err).to.equal(null);
expect(validationErr).to.equal(null);
done();
});
});
});
describe('An audit log with an invalid source', function () {
it('receives validation errors', function (done) {
var auditLog = AuditLog.build(_.defaults({
source_type: 'invalid-source'
}, validAuditLog));
auditLog.validate().asCallback(function handleError (err, validationErr) {
expect(err).to.equal(null);
expect(validationErr.errors.length).to.be.at.least(1);
expect(validationErr.errors[1]).to.have.property('path', 'source_type');
expect(validationErr.errors[1]).to.have.property('message', 'Source must be server or users');
done();
});
});
});
describe('An audit log with an non-server source and no id', function () {
it('receives validation errors', function (done) {
var auditLog = AuditLog.build(_.defaults({
source_type: 'users'
}, validAuditLog));
auditLog.validate().asCallback(function handleError (err, validationErr) {
expect(err).to.equal(null);
expect(validationErr.errors).to.have.length(1);
expect(validationErr.errors[0]).to.have.property('path', 'requireSourceId');
expect(validationErr.errors[0]).to.have.property('message',
'source_id required for non-server sources in audit log');
done();
});
});
});
describe('An audit log with an non-server source and an id', function () {
it('receives no validation errors', function (done) {
var auditLog = AuditLog.build(_.defaults({
source_type: 'users',
source_id: 'mock-user-id'
}, validAuditLog));
auditLog.validate().asCallback(function handleError (err, validationErr) {
expect(err).to.equal(null);
expect(validationErr).to.equal(null);
done();
});
});
});
describe('An audit log with an invalid action', function () {
it('receives validation errors', function (done) {
var auditLog = AuditLog.build(_.defaults({
action: 'invalid-action'
}, validAuditLog));
auditLog.validate().asCallback(function handleError (err, validationErr) {
expect(err).to.equal(null);
expect(validationErr.errors).to.have.length(1);
expect(validationErr.errors[0]).to.have.property('path', 'action');
expect(validationErr.errors[0]).to.have.property('message', 'Action must be create, update, or delete');
done();
});
});
});
scenario('A Base model being created without a transaction', {
dbFixtures: [],
googleFixtures: null
}, function () {
it('receives an assertion error', function (done) {
var user = User.build({email: 'mock-email@mock-domain.test'});
return user.save({_sourceType: 'server'}).asCallback(function handleSave (err) {
expect(err).to.not.equal(null);
expect(err.message).to.contain('All create/update/delete actions must be run in a transaction');
done();
});
});
});
scenario('A Base model being created with a transaction', {
dbFixtures: [],
googleFixtures: null
}, function () {
before(function createUser (done) {
var user = User.build({email: 'mock-email@mock-domain.test'});
User.sequelize.transaction(function handleTransaction (t) {
return user.save({_sourceType: 'server', transaction: t});
}).asCallback(done);
});
it('is saved to an audit log', function (done) {
// Assert source user, table, id, previous, and new data
AuditLog.findAll().asCallback(function handleAuditLogs (err, auditLogs) {
if (err) { return done(err); }
expect(auditLogs).to.have.length(1);
expect(auditLogs[0].get('source_type')).to.equal('server');
expect(auditLogs[0].get('source_id')).to.equal(null);
expect(auditLogs[0].get('table_name')).to.equal('users');
expect(auditLogs[0].get('table_row_id')).to.be.a('String');
expect(auditLogs[0].get('action')).to.equal('create');
expect(auditLogs[0].get('timestamp')).to.be.a('Date');
expect(auditLogs[0].get('previous_values')).to.deep.equal({});
expect(auditLogs[0].get('current_values')).to.have.property('email',
'mock-email@mock-domain.test');
expect(auditLogs[0].get('transaction_id')).to.be.a('String');
done();
});
});
});
scenario('A Base model being updated without a transaction', {
dbFixtures: ['user-default'],
googleFixtures: null
}, function () {
it('receives an assertion error', function (done) {
User.find().asCallback(function handleFind (err, user) {
if (err) { return done(err); }
user.update({
email: 'mock-email2@mock-domain2.test'
}, {
_sourceType: 'users',
_sourceId: user.get('id'),
transaction: t
}).asCallback(function handleUpdate (err) {
expect(err).to.not.equal(null);
expect(err.message).to.contain('All create/update/delete actions must be run in a transaction');
done();
});
});
});
});
scenario('A Base model being updated with a transaction', {
dbFixtures: ['user-default'],
googleFixtures: null
}, function () {
before(function updateUser (done) {
User.find().asCallback(function handleFind (err, user) {
if (err) { return done(err); }
User.sequelize.transaction(function handleTransaction (t) {
return user.update({
email: 'mock-email2@mock-domain2.test'
}, {
_sourceType: 'users',
_sourceId: user.get('id'),
transaction: t
});
}).asCallback(done);
});
});
it('is saved to an audit log', function (done) {
// Assert source user, table, id, previous, and new data
AuditLog.findAll({where: {source_type: 'users'}}).asCallback(function handleAuditLogs (err, auditLogs) {
if (err) { return done(err); }
expect(auditLogs).to.have.length(1);
expect(auditLogs[0].get('source_type')).to.equal('users');
expect(auditLogs[0].get('source_id')).to.be.a('String');
expect(auditLogs[0].get('table_name')).to.equal('users');
expect(auditLogs[0].get('table_row_id')).to.be.a('String');
expect(auditLogs[0].get('action')).to.equal('update');
expect(auditLogs[0].get('timestamp')).to.be.a('Date');
expect(auditLogs[0].get('previous_values')).to.have.property('email',
'mock-email@mock-domain.test');
expect(auditLogs[0].get('current_values')).to.have.property('email',
'mock-email2@mock-domain2.test');
expect(auditLogs[0].get('transaction_id')).to.be.a('String');
done();
});
});
});
scenario('A Base model being deleted without a transaction', {
dbFixtures: ['user-default'],
googleFixtures: null
}, function () {
it('receives an assertion error', function (done) {
User.find().asCallback(function handleFind (err, user) {
if (err) { return done(err); }
user.destroy({
_sourceType: 'users',
_sourceId: user.get('id'),
}).asCallback(function handleSave (err) {
expect(err).to.not.equal(null);
expect(err.message).to.contain('All create/update/delete actions must be run in a transaction');
done();
});
});
});
});
scenario('A Base model being deleted with a transaction', {
dbFixtures: ['user-default'],
googleFixtures: null
}, function () {
before(function deleteUser (done) {
User.find().asCallback(function handleFind (err, user) {
if (err) { return done(err); }
User.sequelize.transaction(function handleTransaction (t) {
return user.destroy({
_sourceType: 'users',
_sourceId: user.get('id'),
transaction: t
});
}).asCallback(done);
});
});
it('is saved to an audit log', function (done) {
// Assert source user, table, id, previous, and new data
AuditLog.findAll({where: {source_type: 'users'}}).asCallback(function handleAuditLogs (err, auditLogs) {
if (err) { return done(err); }
expect(auditLogs).to.have.length(1);
expect(auditLogs[0].get('source_type')).to.equal('users');
expect(auditLogs[0].get('source_id')).to.be.a('String');
expect(auditLogs[0].get('table_name')).to.equal('users');
expect(auditLogs[0].get('table_row_id')).to.be.a('String');
expect(auditLogs[0].get('action')).to.equal('delete');
expect(auditLogs[0].get('timestamp')).to.be.a('Date');
expect(auditLogs[0].get('previous_values')).to.have.property('email',
'mock-email@mock-domain.test');
expect(auditLogs[0].get('current_values')).to.have.property('email',
'mock-email@mock-domain.test');
expect(auditLogs[0].get('transaction_id')).to.be.a('String');
done();
});
});
});
// http://docs.sequelizejs.com/en/v3/docs/instances/#working-in-bulk-creating-updating-and-destroying-multiple-rows-at-once
scenario('A Base model being bulk created', {
dbFixtures: [],
googleFixtures: null
}, function () {
it('is rejected due to lack of support', function (done) {
User.bulkCreate([
{email: 'mock-email@mock-domain.test'}
]).asCallback(function handleBulkCreate (err, users) {
expect(err.message).to.contain('Audit logging not supported for bulk creation');
done();
});
});
});
scenario('A Base model being bulk updated', {
dbFixtures: [],
googleFixtures: null
}, function () {
it('is rejected due to lack of support', function (done) {
User.update({
email: 'mock-email2@mock-domain2.test'
}, {
where: {email: 'mock-email@mock-domain.test'}
}).asCallback(function handleBulkUpdate (err, users) {
expect(err.message).to.contain('Audit logging not supported for bulk updates');
done();
});
});
});
scenario('A Base model being bulk deleted', {
dbFixtures: [],
googleFixtures: null
}, function () {
it('is rejected due to lack of support', function (done) {
User.destroy({
where: {email: 'mock-email@mock-domain.test'}
}).asCallback(function handleBulkDelete (err, users) {
expect(err.message).to.contain('Audit logging not supported for bulk deletion');
done();
});
});
});
// DEV: Test is currently skipped due to no items in database
scenario.skip('A Base model being created with a user source', {
dbFixtures: [],
googleFixtures: null
}, function () {
before(function createItem (done) {
var item = Item.build({name: 'User source item'});
item._sourceType = 'users';
item._sourceId = 'mock-user-id';
item.save().asCallback(done);
});
it('saves user source to its audit log', function (done) {
AuditLog.findAll().asCallback(function handleAuditLogs (err, auditLogs) {
if (err) { return done(err); }
expect(auditLogs).to.have.length(1);
expect(auditLogs[0].get('source_type')).to.equal('users');
expect(auditLogs[0].get('source_id')).to.equal('mock-user-id');
done();
});
});
});
@dondragon2
Copy link

dondragon2 commented Aug 9, 2017

in base.js where you have
previous_values: _.pick(model._previousDataValues, attributeKeys),
current_values: _.pick(model.dataValues, attributeKeys),

line 21 & 22
where does attributeKeys come from?

@evancauwenberg
Copy link

evancauwenberg commented Dec 5, 2018

Hi @twolfson

Thnx for sharing this gist!
I still have a little problem, How can i attach the base.js to my model?

`
export default (sequelize, DataTypes) => {
const Thirdparty = sequelize.define(
'Thirdparty',
{
id: {
type: DataTypes.UUID,
defaultValue: DataTypes.UUIDV4,
primaryKey: true,
allowNull: false,
},
number: {
type: DataTypes.STRING,
allowNull: false,
},
createdBy: {
type: DataTypes.UUID,
allowNull: false,
},
updatedBy: {
type: DataTypes.UUID,
allowNull: true,
},
createdAt: {
type: DataTypes.DATE,
allowNull: false,
},
updatedAt: {
type: DataTypes.DATE,
allowNull: true,
},
},
{
freezeTableName: true,
timestamps: false,
tableName: 'thirdparty',
},
);

// Method 2 via the .hook() method (or its alias .addHook() method)
Thirdparty.hook('beforeValidate', async (thirdparty, options) => {
thirdparty.number = TP-${("0000" + 1).slice(-5)};
});

// Associations
Thirdparty.associate = models => {
models.Thirdparty.belongsTo(models.File, {
as: 'clientStatement',
});

return Thirdparty;
};
`

Thnx in advance!

@psaxde
Copy link

psaxde commented May 18, 2019

in base.js where you have
previous_values: _.pick(model._previousDataValues, attributeKeys),
current_values: _.pick(model.dataValues, attributeKeys),

line 21 & 22
where does attributeKeys come from?

Even if your question is that old, you could use options.defaultKeys here instead of attributeKeys, that should work in theory.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment