implement graceful process shutdown, and clear logging as to the reas…

…on why processes are terminating. include winston handling of uncaught exceptions. this all goes into a library that all of our processes use. closes #529

bin/browserid

@@ -40,7 +40,8 @@ fs = require('fs'),
 path = require('path'),
 url = require('url'),
 http = require('http');
-sessions = require('connect-cookie-session');
+sessions = require('connect-cookie-session'),
+urlparse = require('urlparse');
 
 // add lib/ to the require path
 require.paths.unshift(path.join(__dirname, '..', 'lib'));
@@ -55,9 +56,9 @@ db = require('db.js'),
 config = require('configuration.js'),
 heartbeat = require('heartbeat.js'),
 metrics = require("metrics.js"),
-logger = require("logging.js").logger,
+logger = require("logging.js").logger
 forward = require('browserid/http_forward'),
-urlparse = require('urlparse');
+shutdown = require('shutdown');
 
 var app = undefined;
 
@@ -205,9 +206,9 @@ function router(app) {
     });
   });
 
-  app.get('/code_update', function(req, resp, next) {
-    logger.warn("code updated.  shutting down.");
-    process.exit();
+  shutdown.installUpdateHandler(app, function(readyForShutdown) {
+    logger.debug("closing database connection");
+    db.close(readyForShutdown)
   });
 };
 
@@ -364,6 +365,12 @@ app.use(express.static(path.join(__dirname, "..", "resources", "static")));
 
 // open the databse
 db.open(config.get('database'), function () {
+
+  // shut down express gracefully on SIGINT
+  shutdown.handleTerminationSignals(app, function(readyForShutdown) {
+    db.close(readyForShutdown)
+  });
+
   var bindTo = config.get('bind_to');
   app.listen(bindTo.port, bindTo.host, function() {
     logger.info("running on http://" + app.address().address + ":" + app.address().port);

bin/keysigner

@@ -50,7 +50,8 @@ validate = require('validate.js'),
 metrics = require("metrics.js"),
 logger = require("logging.js").logger,
 ca = require('keysigner/ca.js'),
-heartbeat = require('heartbeat');
+heartbeat = require('heartbeat'),
+shutdown = require('shutdown');
 
 // create an express server
 var app = express.createServer();
@@ -90,6 +91,12 @@ app.post('/wsapi/cert_key', validate(["email", "pubkey"]), function(req, resp) {
   resp.end();
 });
 
+// shutdown when code_update is invoked
+shutdown.installUpdateHandler(app);
+
+// shutdown nicely on signals
+shutdown.handleTerminationSignals(app);
+
 var bindTo = config.get('bind_to');
 app.listen(bindTo.port, bindTo.host, function() {
   logger.info("running on http://" + app.address().address + ":" + app.address().port);

bin/verifier

@@ -46,7 +46,8 @@ certassertion = require('../lib/verifier/certassertion.js'),
 metrics = require('../lib/metrics'),
 heartbeat = require('../lib/heartbeat'),
 logger = require('../lib/logging').logger,
-config = require('../lib/configuration');
+config = require('../lib/configuration'),
+shutdown = require('../lib/shutdown');
 
 logger.info("verifier server starting up");
 
@@ -64,13 +65,8 @@ app.use(express.logger({
 
 app.use(express.bodyParser());
 
-// code_update is an internal api that causes the node server to
-// shut down.  This should never be externally accessible and
-// is used during the dead simple deployment procedure.
-app.get("/code_update", function (req, resp) {
-  logger.warn("code updated.  shutting down.");
-  process.exit();
-});
+// shutdown when /code_update is invoked
+shutdown.installUpdateHandler(app);
 
 // setup health check / heartbeat
 heartbeat.setup(app);
@@ -119,6 +115,9 @@ app.post('/verify', function(req, resp, next) {
 
 });
 
+// shutdown nicely on signals
+shutdown.handleTerminationSignals(app);
+
 var bindTo = config.get('bind_to');
 app.listen(bindTo.port, bindTo.host, function(conn) {
   logger.info("running on http://" + app.address().address + ":" + app.address().port);

lib/logging.js

@@ -70,14 +70,18 @@ var filename = path.join(log_path, configuration.get('process_type') + ".log");
 exports.logger = new (winston.Logger)({
   transports: [new (winston.transports.File)({
     filename: filename,
-    colorize: true
+    colorize: true,
+    handleExceptions: true
   })]
 });
 
-exports.logger.emitErrs = false;
-
 exports.enableConsoleLogging = function() {
-  exports.logger.add(winston.transports.Console, { colorize: true });
+  exports.logger.add(winston.transports.Console, {
+    colorize: true,
+    handleExceptions: true
+  });
 };
 
+winston.handleExceptions();
+
 if (process.env['LOG_TO_CONSOLE']) exports.enableConsoleLogging();

lib/shutdown.js

@@ -0,0 +1,120 @@
+/* ***** BEGIN LICENSE BLOCK *****
+ * Version: MPL 1.1/GPL 2.0/LGPL 2.1
+ *
+ * The contents of this file are subject to the Mozilla Public License Version
+ * 1.1 (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ * http://www.mozilla.org/MPL/
+ *
+ * Software distributed under the License is distributed on an "AS IS" basis,
+ * WITHOUT WARRANTY OF ANY KIND, either express or implied. See the License
+ * for the specific language governing rights and limitations under the
+ * License.
+ *
+ * The Original Code is Mozilla BrowserID.
+ *
+ * The Initial Developer of the Original Code is Mozilla.
+ * Portions created by the Initial Developer are Copyright (C) 2011
+ * the Initial Developer. All Rights Reserved.
+ *
+ * Contributor(s):
+ *   Lloyd Hilaiel <lloyd@hilaiel.com>
+ *
+ * Alternatively, the contents of this file may be used under the terms of
+ * either the GNU General Public License Version 2 or later (the "GPL"), or
+ * the GNU Lesser General Public License Version 2.1 or later (the "LGPL"),
+ * in which case the provisions of the GPL or the LGPL are applicable instead
+ * of those above. If you wish to allow use of your version of this file only
+ * under the terms of either the GPL or the LGPL, and not to allow others to
+ * use your version of this file under the terms of the MPL, indicate your
+ * decision by deleting the provisions above and replace them with the notice
+ * and other provisions required by the GPL or the LGPL. If you do not delete
+ * the provisions above, a recipient may use your version of this file under
+ * the terms of any one of the MPL, the GPL or the LGPL.
+ *
+ * ***** END LICENSE BLOCK ***** */
+
+/* code_update is a tiny abstraction of a handler that can be
+ * used to shutdown gracefully upon signals, and can be used
+ * to install a 'code_update' hook into a running express
+ * server.
+ */
+
+const logger = require("./logging.js").logger;
+
+const MAX_WAIT_MS = 10000;
+const MAX_NICE_END_MS = 5000;
+
+function connectionListener(app) {
+  var connections = [];
+
+  app.on('connection', function(c) {
+    connections.push(c);
+    c.on('close', function() {
+      var where = connections.indexOf(c);
+      if (where >= 0) connections.splice(where, 1);
+    });
+  });
+
+  return function(callback) {
+    if (!callback) callback = function(cli) { cli(); };
+
+    var total_timeout = setTimeout(function() {
+      logger.warn(MAX_WAIT_MS + "ms exceeded, going down forcefully...");
+      setTimeout(function() { process.exit(1); }, 0);
+    }, MAX_WAIT_MS);
+
+    var nice_timeout = setTimeout(function() {
+      logger.warn("forcefully closing " + connections.length + " remaining connections...");
+      connections.forEach(function(c) { c.destroy() });
+    }, MAX_NICE_END_MS);
+
+    app.on('close', function() {
+      function clearTimeoutsAndCallClient() {
+        clearTimeout(nice_timeout);
+        clearTimeout(total_timeout);
+        callback(function() {
+          logger.info("graceful shutdown complete...");
+        });
+      }
+
+      // if there aren't any open connections, we're done!
+      if (connections.length === 0) clearTimeoutsAndCallClient();
+
+      connections.forEach(function(c) {
+        c.on('close', function() {
+          if (!app.connections && connections.length === 0) {
+            // once all connections are shutdown, let's call the client
+            // to let him shutdown all his open connections
+            clearTimeoutsAndCallClient();
+          }
+        });
+        c.end();
+      });
+    });
+    app.close();
+  }
+};
+
+exports.handleTerminationSignals = function(app, callback) {
+  var gotSignal = false;
+  var terminate = connectionListener(app);
+  function endIt(signame) {
+    return function() {
+      if (gotSignal) return;
+      gotSignal = true;
+      logger.warn("SIG" + signame + " received.  closing " + app.connections + " connections and shutting down.");
+      terminate(callback);
+    };
+  }
+
+  process.on('SIGINT', endIt('INT')).on('SIGTERM', endIt('TERM')).on('SIGQUIT', endIt('QUIT'));
+};
+
+exports.installUpdateHandler = function(app, callback) {
+  var terminate = connectionListener(app);
+  app.get('/code_update', function(req, resp, next) {
+    logger.warn("code updated.  closing " + app.connections + " connections and shutting down.");
+    terminate(callback);
+  });
+};

package.json

@@ -15,7 +15,7 @@
     , "express-csrf": "0.3.2"
     , "uglify-js": "1.0.6"
     , "JSONSelect": "0.2.1"
-    , "winston" : "0.3.3"
+    , "winston" : "0.5.6"
     , "connect-cookie-session" : "0.0.2"
     , "mysql" : "0.9.2"
     , "optimist" : "0.2.6"

scripts/run_locally.js

@@ -61,7 +61,7 @@ Object.keys(daemonsToRun).forEach(function(k) {
   daemons[k] = p;
 
   p.on('exit', function (code, signal) {
-    console.log(k, 'exited with code', code, (signal ? 'on signal ' + signal : ""));
+    console.log(k, 'exited(' + code + ') ', (signal ? 'on signal ' + signal : ""));
     delete daemons[k];
     Object.keys(daemons).forEach(function (k) { daemons[k].kill(); });
     if (Object.keys(daemons).length === 0) {