Skip to content

Commit

Permalink
fix: ensure errors are properly logged
Browse files Browse the repository at this point in the history
  • Loading branch information
Tom Kirkpatrick committed Mar 8, 2017
1 parent 722cab5 commit 09fdf72
Show file tree
Hide file tree
Showing 7 changed files with 71 additions and 81 deletions.
55 changes: 26 additions & 29 deletions lib/models/migration.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -63,7 +63,7 @@ module.exports = function(Migration, options) {
assert(typeof cb === 'function', 'The cb argument must be a function, not ' + typeof cb);

if (Migration.app.migrating) {
Migration.log.warn('Unable to start migration: already running');
Migration.log.warn('Migration: Unable to start migration (already running)');
process.nextTick(function() {
cb();
});
Expand All @@ -73,26 +73,22 @@ module.exports = function(Migration, options) {
Migration.hrstart = process.hrtime();
Migration.app.migrating = true;

Migration.log.info(name, 'running.');
Migration.log.info('Migration: running script', name);
const scriptPath = path.resolve(path.join(Migration.migrationsDir, name));

try {
require(scriptPath).up(Migration.app, function(err) {
if (err) {
Migration.log.error(`Error running migration script ${name}:`, err);
Migration.finish(err);
return cb(err);
} else if (record) {
if (record) {
Migration.create({
name: name,
runDtTm: new Date()
});
}
Migration.finish();
cb();
Migration.finish(err);
return cb();
});
} catch (err) {
Migration.log.error(`Error running migration script ${name}:`, err);
Migration.log.error(`Migration: Error running script ${name}:`, err);
Migration.finish(err);
cb(err);
}
Expand Down Expand Up @@ -123,7 +119,7 @@ module.exports = function(Migration, options) {
assert(typeof cb === 'function', 'The cb argument must be a function, not ' + typeof cb);

if (Migration.app.migrating) {
Migration.log.warn('Unable to start migrations: already running');
Migration.log.warn('Migration: Unable to start migrations (already running)');
process.nextTick(function() {
cb();
});
Expand All @@ -139,7 +135,7 @@ module.exports = function(Migration, options) {
var migrationCallIndex = 0;

if (scriptsToRun.length) {
Migration.log.info('Running migrations: \n', scriptsToRun);
Migration.log.info('Migration: Running migration scripts', scriptsToRun);
}

scriptsToRun.forEach(function(localScriptName) {
Expand All @@ -150,33 +146,30 @@ module.exports = function(Migration, options) {
// keep calling scripts recursively until we are done, then exit
function runNextScript(err) {
if (err) {
Migration.log.error('Error saving migration', localScriptName, 'to database!');
Migration.log.error(err);
Migration.log.error('Migration: Error saving migration %s to database', localScriptName);
Migration.finish(err);
return cb(err);
}

var migrationEndTime = process.hrtime(migrationStartTime);
Migration.log.info('%s finished sucessfully. Migration time was %ds %dms',
Migration.log.info('Migration: %s finished sucessfully. Migration time was %ds %dms',
localScriptName, migrationEndTime[0], migrationEndTime[1] / 1000000);
migrationCallIndex++;
if (migrationCallIndex < migrationCallStack.length) {
migrationCallStack[migrationCallIndex]();
} else {
Migration.finish();
Migration.finish(err);
return cb();
}
}

try {
// include the script, run the up/down function, update the migrations table, and continue
migrationStartTime = process.hrtime();
Migration.log.info(localScriptName, 'running.');
Migration.log.info('Migration: Running script', localScriptName);
const scriptPath = path.resolve(path.join(Migration.migrationsDir, localScriptName));
require(scriptPath)[upOrDown](Migration.app, function(err) {
if (err) {
Migration.log.error(localScriptName, 'error:');
Migration.log.error(err.stack);
Migration.finish(err);
return cb(err);
} else if (upOrDown === 'up') {
Expand All @@ -191,8 +184,6 @@ module.exports = function(Migration, options) {
}
});
} catch (err) {
Migration.log.error('Error running migration', localScriptName);
Migration.log.error(err.stack);
Migration.finish(err);
cb(err);
}
Expand All @@ -205,7 +196,7 @@ module.exports = function(Migration, options) {
} else {
delete Migration.app.migrating;
Migration.emit('complete');
Migration.log.info('No new migrations to run.');
Migration.log.info('Migration: No new migrations to run.');
return cb();
}
});
Expand All @@ -215,15 +206,10 @@ module.exports = function(Migration, options) {

Migration.finish = function(err) {
if (err) {
Migration.log.error('Migrations did not complete. An error was encountered:', err);
Migration.emit('error', err);
} else {
Migration.log.info('All migrations have run without any errors.');
Migration.emit('complete');
}
delete Migration.app.migrating;
var hrend = process.hrtime(Migration.hrstart);
Migration.log.info('Total migration time was %ds %dms', hrend[0], hrend[1] / 1000000);
};

Migration.findScriptsToRun = function(upOrDown, to, cb) {
Expand Down Expand Up @@ -321,8 +307,7 @@ module.exports = function(Migration, options) {
}
})
.catch(function(err) {
Migration.log.error('Error retrieving migrations:');
Migration.log.error(err.stack);
Migration.log.error('Migration: Error retrieving migrations', err);
cb(err);
});

Expand All @@ -333,5 +318,17 @@ module.exports = function(Migration, options) {
return scriptObj.name;
};

Migration.on('error', (err) => {
Migration.log.error('Migration: Migrations did not complete. An error was encountered:', err);
delete Migration.app.migrating;
});

Migration.on('complete', (err) => {
var hrend = process.hrtime(Migration.hrstart);
Migration.log.info('Migration: All migrations have run without any errors.');
Migration.log.info('Migration: Total migration time was %ds %dms', hrend[0], hrend[1] / 1000000);
delete Migration.app.migrating;
});

return Migration;
};
2 changes: 1 addition & 1 deletion package.json
View file
Original file line number Diff line number Diff line change
Expand Up @@ -56,7 +56,7 @@
"loopback": ">=2.22.0"
},
"devDependencies": {
"bluebird": "latest",
"bluebird": "^3.5.0",
"chai": "latest",
"condition-circle": "^1.5.0",
"ghooks": "^1.3.2",
Expand Down
6 changes: 6 additions & 0 deletions test/fixtures/simple-app/server/component-config.json
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,6 @@
{
"../../../../lib": {
"enableRest": false,
"migrationsDir": "./test/fixtures/simple-app/server/migrations"
}
}
8 changes: 8 additions & 0 deletions test/fixtures/simple-app/server/migrations/0000-error.js
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,8 @@
module.exports = {
up: function(dataSource, next) {
process.nextTick(() => next(new Error('some error in up')))
},
down: function(dataSource, next) {
process.nextTick(() => next())
}
};
3 changes: 0 additions & 3 deletions test/fixtures/simple-app/server/model-config.json
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2,9 +2,6 @@
"_meta": {
"sources": [
"../common/models"
],
"mixins": [
"../../../../"
]
},
"User": {
Expand Down
11 changes: 0 additions & 11 deletions test/fixtures/simple-app/server/server.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -21,17 +21,6 @@ app.start = function() {
boot(app, __dirname, function(err) {
if (err) throw err;

var migrate = require(path.join(__dirname, '..', '..', '..', '..', 'lib'));
var options = {
// dataSource: ds, // Data source for migrate data persistence,
migrationsDir: path.join(__dirname, 'migrations'), // Migrations directory.
enableRest: true
};
migrate(
app, // The app instance
options // The options
);

// Register explorer using component-centric API:
explorer(app, { basePath: '/api', mountPath: '/explorer' });

Expand Down
67 changes: 30 additions & 37 deletions test/test.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -74,15 +74,17 @@ describe('loopback db migrate', function() {
});

// Delete all data after each test.
beforeEach(function(done) {
Promise.all([
beforeEach(function() {
return Promise.all([
app.models.Migration.destroyAll(),
app.models.Migration.destroyAll()
])
.then(function() {
done();
return app.models.Migration.create({
name: '0000-error.js',
runDtTm: new Date()
})
})
.catch(done);
});

describe('migrateByName', function() {
Expand All @@ -97,50 +99,51 @@ describe('loopback db migrate', function() {
})
.catch(done);
});
});

it('should log errors', function() {
return app.models.Migration.migrateByName('0000-error.js')
.catch(function(err) {
expect(err).to.not.be.undefined;
})
});

});
describe('migrate', function() {
it('should set a property on app to indicate that migrations are running', function(done) {
it('should set a property on app to indicate that migrations are running', function() {
var self = this;
expect(app.migrating).to.be.undefined;
var promise = app.models.Migration.migrate();
expect(app.migrating).to.be.true;
promise.then(function() {
return promise.then(function() {
expect(app.migrating).to.be.undefined;
done();
})
.catch(done);
});
});

describe('up', function() {
it('should run all migration scripts', function(done) {
it('should run all migration scripts', function() {
var self = this;
app.models.Migration.migrate()
return app.models.Migration.migrate()
.then(function() {
expect(self.spies.m1Up).to.have.been.called;
expect(self.spies.m2Up).to.have.been.calledAfter(self.spies.m1Up);
expect(self.spies.m3Up).to.have.been.calledAfter(self.spies.m2Up);
self.expectNoDown();
done();
})
.catch(done);
});
it('should run migrations up to the specificed point only', function(done) {
it('should run migrations up to the specificed point only', function() {
var self = this;
app.models.Migration.migrate('up', '0002-somechanges')
return app.models.Migration.migrate('up', '0002-somechanges')
.then(function() {
expect(self.spies.m1Up).to.have.been.calledBefore(self.spies.m2Up);
expect(self.spies.m2Up).to.have.been.calledAfter(self.spies.m1Up);
expect(self.spies.m3Up).not.to.have.been.called;
self.expectNoDown();
done();
})
.catch(done);
});
it('should not rerun migrations that hae already been run', function(done) {
it('should not rerun migrations that hae already been run', function() {
var self = this;
app.models.Migration.migrate('up', '0002-somechanges')
return app.models.Migration.migrate('up', '0002-somechanges')
.then(function() {
self.resetSpies();
return app.models.Migration.migrate('up');
Expand All @@ -150,16 +153,14 @@ describe('loopback db migrate', function() {
expect(self.spies.m2Up).not.to.have.been.called;
expect(self.spies.m3Up).to.have.been.called;
self.expectNoDown();
done();
})
.catch(done);
});
});

describe('down', function() {
it('should run all rollback scripts in reverse order', function(done) {
it('should run all rollback scripts in reverse order', function() {
var self = this;
app.models.Migration.migrate('up')
return app.models.Migration.migrate('up')
.then(function() {
self.expectNoDown();
self.resetSpies();
Expand All @@ -170,13 +171,11 @@ describe('loopback db migrate', function() {
expect(self.spies.m2Down).to.have.been.calledAfter(self.spies.m3Down);
expect(self.spies.m1Down).to.have.been.calledAfter(self.spies.m2Down);
self.expectNoUp();
done();
})
.catch(done);
});
it('should run rollbacks up to the specificed point only', function(done) {
it('should run rollbacks up to the specificed point only', function() {
var self = this;
app.models.Migration.migrate('up')
return app.models.Migration.migrate('up')
.then(function() {
self.expectNoDown();
self.resetSpies();
Expand All @@ -187,13 +186,11 @@ describe('loopback db migrate', function() {
expect(self.spies.m2Down).to.have.been.calledAfter(self.spies.m3Down);
expect(self.spies.m1Down).not.to.have.been.called;
self.expectNoUp();
done();
})
.catch(done);
});
it('should not rerun rollbacks that hae already been run', function(done) {
it('should not rerun rollbacks that hae already been run', function() {
var self = this;
app.models.Migration.migrate('up')
return app.models.Migration.migrate('up')
.then(function() {
return app.models.Migration.migrate('down', '0001-initialize');
})
Expand All @@ -206,13 +203,11 @@ describe('loopback db migrate', function() {
expect(self.spies.m2Down).to.not.have.been.called;
expect(self.spies.m1Down).to.have.been.called;
self.expectNoUp();
done();
})
.catch(done);
});
it('should rollback a single migration that has not already run', function(done) {
it('should rollback a single migration that has not already run', function() {
var self = this;
app.models.Migration.migrate('up', '0002-somechanges')
return app.models.Migration.migrate('up', '0002-somechanges')
.then(function() {
self.resetSpies();
return app.models.Migration.migrate('down', '0003-morechanges');
Expand All @@ -222,9 +217,7 @@ describe('loopback db migrate', function() {
expect(self.spies.m2Down).to.not.have.been.called;
expect(self.spies.m1Down).to.not.have.been.called;
self.expectNoUp();
done();
})
.catch(done);
});
});
});
Expand Down

0 comments on commit 09fdf72

Please sign in to comment.