Audit logging via sequelize

README.md

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.

audit-log.js

// 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, [email protected] 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);

base.js

// 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);

test-audit-log.js

// 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();
    });
  });
});

test-base.js

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: '[email protected]'});
    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: '[email protected]'});
    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',
        '[email protected]');
      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: '[email protected]'
      }, {
        _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: '[email protected]'
        }, {
          _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',
        '[email protected]');
      expect(auditLogs[0].get('current_values')).to.have.property('email',
        '[email protected]');
      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',
        '[email protected]');
      expect(auditLogs[0].get('current_values')).to.have.property('email',
        '[email protected]');
      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: '[email protected]'}
    ]).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: '[email protected]'
    }, {
      where: {email: '[email protected]'}
    }).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: '[email protected]'}
    }).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();
    });
  });
});