implement graceful process shutdown, and clear logging as to the reason why...

implement graceful process shutdown, and clear logging as to the reason 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

+/* ***** 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) {