diff --git a/bin/browserid b/bin/browserid index 1f32f4c65..a0752e462 100755 --- a/bin/browserid +++ b/bin/browserid @@ -23,7 +23,7 @@ const forward = require('../lib/http_forward.js'); const heartbeat = require('../lib/heartbeat.js'); const httputils = require('../lib/httputils.js'); const i18n_check = require('../lib/i18n_client_check'); -const logger = require('../lib/logging/logging.js').logger; +const logger = require('../lib/logging/logging.js').getLogger('bid.bin.browserid'); const primary = require('../lib/primary'); const proxySecure = require('../lib/proxy-secure'); const shutdown = require('../lib/shutdown'); diff --git a/bin/dbwriter b/bin/dbwriter index 18e465330..94aa5918a 100755 --- a/bin/dbwriter +++ b/bin/dbwriter @@ -21,7 +21,7 @@ const assets = require('../lib/static_resources').all; const db = require('../lib/db.js'); const config = require('../lib/configuration.js'); const heartbeat = require('../lib/heartbeat.js'); -const logger = require('../lib/logging/logging.js').logger; +const logger = require('../lib/logging/logging.js').getLogger('bid.bin.dbwriter'); const primary = require('../lib/primary'); const proxySecure = require('../lib/proxy-secure'); const shutdown = require('../lib/shutdown'); diff --git a/bin/keysigner b/bin/keysigner index 15f6a1f31..70cb0f414 100755 --- a/bin/keysigner +++ b/bin/keysigner @@ -15,7 +15,7 @@ _ = require('underscore'), config = require('../lib/configuration.js'), httputils = require('../lib/httputils.js'), validate = require('../lib/validate.js'), -logger = require('../lib/logging/logging.js').logger, +logger = require('../lib/logging/logging.js').getLogger('bid.bin.keysigner'), heartbeat = require('../lib/heartbeat'), shutdown = require('../lib/shutdown'), computecluster = require('compute-cluster'), diff --git a/bin/load_gen b/bin/load_gen index f1d583391..0b64ddb1e 100755 --- a/bin/load_gen +++ b/bin/load_gen @@ -11,7 +11,7 @@ require('../lib/baseExceptions').addExceptionHandler(); var wsapi_client = require('../lib/wsapi_client'); -const winston = require('winston'); +const intel = require('intel'); // option processing with optimist var argv = require('optimist') @@ -219,7 +219,7 @@ function poll() { } else { completed[act][1]++; } - winston.error('('+act+') ' + err.toString()); + intel.error('('+act+') ' + err.toString()); } else { completed[act][0]++; } diff --git a/bin/router b/bin/router index 278e4a065..881a63e44 100755 --- a/bin/router +++ b/bin/router @@ -19,7 +19,7 @@ const addP3PHeader = require('../lib/p3p.js'); const config = require('../lib/configuration.js'); const forward = require('../lib/http_forward').forward; const heartbeat = require('../lib/heartbeat.js'); -const logger = require('../lib/logging/logging.js').logger; +const logger = require('../lib/logging/logging.js').getLogger('bid.bin.router'); const metrics = require('../lib/logging/middleware/metrics.js'); const proxySecure = require('../lib/proxy-secure'); const shutdown = require('../lib/shutdown.js'); diff --git a/bin/static b/bin/static index c1009674b..ed8d96791 100755 --- a/bin/static +++ b/bin/static @@ -27,7 +27,7 @@ const db = require('../lib/db.js'); const heartbeat = require('../lib/heartbeat.js'); const httputils = require('../lib/httputils.js'); const i18n_check = require('../lib/i18n_client_check'); -const logger = require('../lib/logging/logging.js').logger; +const logger = require('../lib/logging/logging.js').getLogger('bid.bin.static'); const proxySecure = require('../lib/proxy-secure'); const shutdown = require('../lib/shutdown.js'); const statsd = require("../lib/logging/middleware/statsd"); diff --git a/bin/verifier b/bin/verifier index 3f2341794..cb6716c78 100755 --- a/bin/verifier +++ b/bin/verifier @@ -15,7 +15,7 @@ fs = require('fs'), express = require('express'), computecluster = require('compute-cluster'), heartbeat = require('../lib/heartbeat'), -logger = require('../lib/logging/logging').logger, +logger = require('../lib/logging/logging').getLogger('bid.bin'), config = require('../lib/configuration'), shutdown = require('../lib/shutdown'), booleanQuery = require('../lib/boolean-query'), diff --git a/config/local.json b/config/local.json index dd69a2765..6a70f19f1 100644 --- a/config/local.json +++ b/config/local.json @@ -10,6 +10,13 @@ "database": { "driver": "json" }, + "logging": { + "loggers": { + "bid": { + "level": "VERBOSE" + } + } + }, "express_log_format": "dev_bid", "email_to_console": true, "env": "local", diff --git a/config/production.json b/config/production.json index d48a6a795..350d2b7fe 100644 --- a/config/production.json +++ b/config/production.json @@ -17,6 +17,13 @@ "statsd": { "enabled": true }, + "logging": { + "loggers": { + "bid": { + "level": "INFO" + } + } + }, "kpi": { "backend_sample_rate": 0.0 }, diff --git a/lib/bcrypt.js b/lib/bcrypt.js index 19e11688c..f8a1bbf31 100644 --- a/lib/bcrypt.js +++ b/lib/bcrypt.js @@ -5,7 +5,7 @@ const path = require('path'), computecluster = require('compute-cluster'), -logger = require('../lib/logging/logging.js').logger, +logger = require('../lib/logging/logging.js').getLogger('bid.bcrypt'), bcrypt = require('bcrypt'), config = require('./configuration.js'); diff --git a/lib/browserid/fake_verification.js b/lib/browserid/fake_verification.js index f212cf7fb..2b7bd8dbb 100644 --- a/lib/browserid/fake_verification.js +++ b/lib/browserid/fake_verification.js @@ -12,7 +12,7 @@ const configuration = require('../configuration.js'), url = require('url'), db = require('../db.js'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.fake_verification'), wsapi = require('../wsapi'); logger.warn("HEAR YE: Fake verfication enabled, aceess via /wsapi/fake_verification?email=foo@bar.com"); diff --git a/lib/configuration.js b/lib/configuration.js index f59810291..1d23fadde 100644 --- a/lib/configuration.js +++ b/lib/configuration.js @@ -221,6 +221,73 @@ var conf = module.exports = convict({ env: 'CEF_SYSLOG_PORT' } }, + logging: { + formatters: { + doc: 'Formatters for intel loggers.', + format: Object, + env: 'LOG_FORMATTERS', + default: { + "dev": { + "format": "%(levelname)s %(name)s: %(message)s", + "colorize": true + }, + "file": "%O", + "metrics": { + "class": "./logging/formatters/metrics", + "format": "%O" + } + } + }, + filters: { + doc: 'Filters log messages to handlers and loggers.', + format: Object, + default: { + "metrics": { + "class": "./logging/filters/metrics" + } + } + }, + handlers: { + doc: 'Handlers deliver log messages to different destinations.', + format: Object, + default: { + "null": { + "class": "intel/handlers/null" + }, + "console": { + "class": "intel/handlers/console", + "formatter": "dev" + }, + "file": { + "class": "intel/handlers/file", + "formatter": "file" + }, + "statsd": { + "class": "./logging/handlers/statsd" + }, + "metrics": { + "class": "intel/handlers/file", + "formatter": "metrics", + "filters": ["metrics"] + }, + "kpiggybank": { + "class": "./logging/handlers/kpi", + "filters": ["metrics"] + } + } + }, + loggers: { + default: { + "bid": { + "level": "DEBUG", + "handlers": ["file", "statsd", "metrics", "kpiggybank"], + "propagate": false, + "handleExceptions": true, + "exitOnError": false + } + } + } + }, kpi: { backend_sample_rate: { doc: "Float between 0 and 1 inclusive, for the % of user flows that should send back KPI JSON blobs. Example: 0.5 would be 50% traffic.", @@ -571,6 +638,6 @@ module.exports.performSubstitution = function(app) { // log the process_type process.nextTick(function() { - var logging = require("./logging/logging.js").logger; + var logging = require("./logging/logging.js").getLogger('bid.config'); logging.info("process type is " + conf.get("process_type")); }); diff --git a/lib/db.js b/lib/db.js index 2ddc07c04..522f47e5d 100644 --- a/lib/db.js +++ b/lib/db.js @@ -2,7 +2,7 @@ * License, v. 2.0. If a copy of the MPL was not distributed with this * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ -var logger = require('./logging/logging.js').logger; +var logger = require('./logging/logging.js').getLogger('bid.db'); const config = require('./configuration.js'); var driver; diff --git a/lib/db/dbutils.js b/lib/db/dbutils.js index 825e22789..8d3c87f15 100644 --- a/lib/db/dbutils.js +++ b/lib/db/dbutils.js @@ -3,7 +3,7 @@ * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ const -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.db.utils'), primary = require('../primary.js'); // Callback has the signature `function (type) {}` diff --git a/lib/db/json.js b/lib/db/json.js index 44fccb4e2..d88b57ff0 100644 --- a/lib/db/json.js +++ b/lib/db/json.js @@ -13,7 +13,7 @@ path = require('path'), fs = require('fs'), secrets = require('../secrets.js'), jsel = require('JSONSelect'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.db.json'), configuration = require('../configuration.js'), primary = require('../primary.js'), temp = require('temp'); diff --git a/lib/db/mysql.js b/lib/db/mysql.js index 122b8febf..908e92acc 100644 --- a/lib/db/mysql.js +++ b/lib/db/mysql.js @@ -34,7 +34,7 @@ const conf = require('../configuration.js'), dbutils = require('./dbutils.js'), mysql = require('./mysql_wrapper.js'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.db.mysql'), primary = require('../primary.js'), secrets = require('../secrets.js'); diff --git a/lib/db/mysql_wrapper.js b/lib/db/mysql_wrapper.js index b85d57999..f9373e703 100644 --- a/lib/db/mysql_wrapper.js +++ b/lib/db/mysql_wrapper.js @@ -9,7 +9,7 @@ const mysql = require('mysql'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.db.mysql.wrapper'), config = require('../configuration.js'); exports.createClient = function(options) { diff --git a/lib/email.js b/lib/email.js index 12db1ea23..2f70e9f19 100644 --- a/lib/email.js +++ b/lib/email.js @@ -7,7 +7,7 @@ const fs = require('fs'); const path = require('path'); const ejs = require('ejs'); const config = require('./configuration.js'); -const logger = require('./logging/logging.js').logger; +const logger = require('./logging/logging.js').getLogger('bid.email'); const url = require('url'); const cachify = require('connect-cachify').cachify; const underscore = require('underscore'); diff --git a/lib/generate_code_version.js b/lib/generate_code_version.js index 7fd35913b..f221c0904 100644 --- a/lib/generate_code_version.js +++ b/lib/generate_code_version.js @@ -7,7 +7,7 @@ const fs = require('fs'), path = require('path'), mkdirp = require('mkdirp'), -logger = require('../lib/logging/logging').logger, +logger = require('../lib/logging/logging').getLogger('bid.generate_version'), version = require('../lib/version.js'); const BUILD_DIR_PATH = path.join(__dirname, "..", "resources", "static", "build"); @@ -24,7 +24,7 @@ const CODE_VERSION_JS_PATH = path.join(BUILD_DIR_PATH, "code_version.js"); * 1) get the new version * 2) open code_version.js and read the already written version. * 3) if the new version is different than the already written version, update. - * + *') * A new code_version.js file is only written if the versions are different. * A needless update causes a re-compilation of all JS resources for all * enabled locales. diff --git a/lib/heartbeat.js b/lib/heartbeat.js index 6cd030e45..a861f335c 100644 --- a/lib/heartbeat.js +++ b/lib/heartbeat.js @@ -4,7 +4,7 @@ const urlparse = require('urlparse'), -logger = require('./logging/logging.js').logger, +logger = require('./logging/logging.js').getLogger('bid.middleware.heartbeat'), url = require('url'); // the path that heartbeats live at diff --git a/lib/http_forward.js b/lib/http_forward.js index dbe337346..1b052130f 100644 --- a/lib/http_forward.js +++ b/lib/http_forward.js @@ -6,7 +6,7 @@ const url = require('url'), http = require('http'), https = require('https'), -logger = require('./logging/logging.js').logger, +logger = require('./logging/logging.js').getLogger('bid.http_forward'), querystring = require('querystring'); var global_forward_timeout; diff --git a/lib/i18n_client_check.js b/lib/i18n_client_check.js index 5bc1ac7ec..00f9e3bac 100644 --- a/lib/i18n_client_check.js +++ b/lib/i18n_client_check.js @@ -18,7 +18,7 @@ var config = require('./configuration.js'), fs = require('fs'), i18n = require('i18n-abide'), - logger = require('./logging/logging.js').logger, + logger = require('./logging/logging.js').getLogger('bid.i18n'), path = require('path'), util = require('util'); diff --git a/lib/keysigner/ca.js b/lib/keysigner/ca.js index ffa13b646..289951a9d 100644 --- a/lib/keysigner/ca.js +++ b/lib/keysigner/ca.js @@ -7,7 +7,7 @@ var jwcrypto = require('jwcrypto'), cert = jwcrypto.cert, secrets = require('../secrets.js'), - logger = require('../logging/logging.js').logger; + logger = require('../logging/logging.js').getLogger('bid.keysigner.ca'); // load up the right algorithms require("jwcrypto/lib/algs/rs"); diff --git a/lib/kpi_data.js b/lib/kpi_data.js index d6a716076..75d572506 100644 --- a/lib/kpi_data.js +++ b/lib/kpi_data.js @@ -11,7 +11,7 @@ const querystring = require('querystring'); const und = require('underscore'); const urlparse = require('urlparse'); const config = require('./configuration'); -const logger = require('./logging/logging').logger; +const logger = require('./logging/logging').getLogger('bid.kpi'); const TEN_MIN_IN_MS = 10 * 60 * 1000; // http and https are vars to override for testing. @@ -55,7 +55,6 @@ function onResponse(cb, res) { + res.statusCode); return cb(null, false); } - logger.info('interaction data successfully posted to KPI Backend'); cb(null, true); } diff --git a/lib/load_gen/activities/add_email.js b/lib/load_gen/activities/add_email.js index 80a127aaf..246500480 100644 --- a/lib/load_gen/activities/add_email.js +++ b/lib/load_gen/activities/add_email.js @@ -8,7 +8,7 @@ const wcli = require("../../wsapi_client.js"), userdb = require("../user_db.js"), -winston = require('winston'), +intel = require('intel'), common = require('../common.js'); exports.startFunc = function(cfg, cb) { @@ -27,7 +27,7 @@ exports.startFunc = function(cfg, cb) { var user = userdb.getExistingUser(); if (!user) { - winston.warn("can't achieve desired concurrency! not enough users!"); + intel.warn("can't achieve desired concurrency! not enough users!"); return cb("not enough users"); } diff --git a/lib/load_gen/activities/change_pass.js b/lib/load_gen/activities/change_pass.js index 6d26c019c..1690c8782 100644 --- a/lib/load_gen/activities/change_pass.js +++ b/lib/load_gen/activities/change_pass.js @@ -9,7 +9,7 @@ const wcli = require("../../wsapi_client.js"), userdb = require("../user_db.js"), -winston = require('winston'), +intel = require('intel'), crypto = require('../crypto'), common = require('../common'); @@ -17,7 +17,7 @@ exports.startFunc = function(cfg, cb) { var user = userdb.getExistingUser(); if (!user) { - winston.warn("can't achieve desired concurrency! not enough users!"); + intel.warn("can't achieve desired concurrency! not enough users!"); return cb("not enough users"); } diff --git a/lib/load_gen/activities/reauth.js b/lib/load_gen/activities/reauth.js index 0d493502d..31f3d267c 100644 --- a/lib/load_gen/activities/reauth.js +++ b/lib/load_gen/activities/reauth.js @@ -9,7 +9,7 @@ const common = require("../common.js"), userdb = require("../user_db.js"), -winston = require('winston'), +intel = require('intel'), wcli = require('../../wsapi_client.js'); exports.startFunc = function(cfg, cb) { @@ -28,7 +28,7 @@ exports.startFunc = function(cfg, cb) { var user = userdb.getExistingUser(); if (!user) { - winston.warn("can't achieve desired concurrency! not enough users!"); + intel.warn("can't achieve desired concurrency! not enough users!"); return cb("concurrency error"); } diff --git a/lib/load_gen/activities/reset_pass.js b/lib/load_gen/activities/reset_pass.js index 650bff820..80e2ec112 100644 --- a/lib/load_gen/activities/reset_pass.js +++ b/lib/load_gen/activities/reset_pass.js @@ -8,7 +8,7 @@ const wcli = require("../../wsapi_client.js"), userdb = require("../user_db.js"), -winston = require('winston'), +intel = require('intel'), common = require('../common'); exports.startFunc = function(cfg, cb) { @@ -16,7 +16,7 @@ exports.startFunc = function(cfg, cb) { var origUser = userdb.getExistingUser(); if (!origUser) { - winston.warn("can't achieve desired concurrency! not enough users!"); + intel.warn("can't achieve desired concurrency! not enough users!"); return cb("not enough users"); } diff --git a/lib/load_gen/activities/signin.js b/lib/load_gen/activities/signin.js index 9e791fb96..ed9789476 100644 --- a/lib/load_gen/activities/signin.js +++ b/lib/load_gen/activities/signin.js @@ -9,7 +9,7 @@ const wcli = require("../../wsapi_client.js"), userdb = require("../user_db.js"), -winston = require('winston'), +intel = require('intel'), crypto = require('../crypto'), common = require('../common'); @@ -25,7 +25,7 @@ exports.startFunc = function(cfg, cb) { var user = userdb.getExistingUser(); if (!user) { - winston.warn("can't achieve desired concurrency! not enough users!"); + intel.warn("can't achieve desired concurrency! not enough users!"); return cb("not enough users"); } diff --git a/lib/load_gen/activities/signup.js b/lib/load_gen/activities/signup.js index df711b374..48a957850 100644 --- a/lib/load_gen/activities/signup.js +++ b/lib/load_gen/activities/signup.js @@ -5,7 +5,7 @@ const wcli = require("../../wsapi_client.js"), userdb = require("../user_db.js"), -winston = require('winston'), +intel = require('intel'), common = require('../common'); /* this file is the "signup" activity, which simulates the process of a new user @@ -36,7 +36,7 @@ exports.startFunc = function(cfg, cb) { var user = userdb.getNewUser(); if (!user) { - winston.error(".getNewUser() should *never* return undefined!"); + intel.error(".getNewUser() should *never* return undefined!"); process.exit(1); } diff --git a/lib/logging/cef_logger.js b/lib/logging/cef_logger.js index 7e858d600..03ac97479 100644 --- a/lib/logging/cef_logger.js +++ b/lib/logging/cef_logger.js @@ -14,7 +14,7 @@ const path = require('path'), http = require('http'), cef = require('cef'), - logger = require('./logging').logger; + logger = require('./logging').getLogger('bid.cef'); var Logger = function(options) { this.cef = cef.getInstance(options); @@ -38,6 +38,14 @@ var Logger = function(options) { * transactions. */ +const SEVERITY_MAP = { + // cef => intel + info: 'info', + warn: 'warn', + alert: 'error', + emergency: 'critical' +}; + Logger.prototype = { /** @@ -52,7 +60,8 @@ Logger.prototype = { extensions: extensions || {} }; - logger.info('cef.' + name, options); + var intelLevel = SEVERITY_MAP[severity] || 'info'; + logger[intelLevel](name, options); return this.cef[severity](options); }, diff --git a/lib/logging/transports/filters/metrics.js b/lib/logging/filters/metrics.js similarity index 79% rename from lib/logging/transports/filters/metrics.js rename to lib/logging/filters/metrics.js index 3d14c07f8..a818356e1 100644 --- a/lib/logging/transports/filters/metrics.js +++ b/lib/logging/filters/metrics.js @@ -22,15 +22,13 @@ * idp.create_new_user */ +const intel = require('intel'); const _ = require('underscore'); -const coarse = require('../../../coarse_user_agent_parser'); - -var MessageMatches = { - 'signin': true, - 'verify': true -}; +const coarse = require('../../coarse_user_agent_parser'); var RegExpMatches = [ + /^signin\b/, + /^verify\b/, /complete_(?:[^\.]+)\.success/, /stage_(?:[^\.]+)\.success/, /^metrics\.report\./, @@ -38,21 +36,22 @@ var RegExpMatches = [ /^idp\.create_new_user/ ]; -exports.test = function(msg) { - if (msg in MessageMatches) return true; - +function filter(record) { + var msg = record.message; for (var i = 0, regExp; regExp = RegExpMatches[i]; ++i) { if (regExp.test(msg)) return true; } return false; -}; +} -exports.toType = function(msg) { - return msg.replace(/^metrics\.report\./, ''); -}; +function MetricsFilter() { + return new intel.Filter(filter); +} + +module.exports = MetricsFilter; -exports.toEntry = function(msg, entry) { +module.exports.toEntry = function(msg, entry) { // create a copy of the entry so that changing fields does not have // side effects elsewhere. if (typeof entry === 'object') entry = _.extend({}, entry); @@ -61,7 +60,7 @@ exports.toEntry = function(msg, entry) { if (entry === null || typeof entry !== 'object') entry = { msg: entry }; if (entry.type) throw "reported metrics may not have a `type` property, that's reserved"; - entry.type = exports.toType(msg); + entry.type = String(msg).replace(/^metrics\.report\./, '').split(' ')[0]; // timestamp if (entry.at) @@ -76,4 +75,4 @@ exports.toEntry = function(msg, entry) { }; - +module.exports = MetricsFilter; diff --git a/lib/logging/transports/filters/statsd-increment.js b/lib/logging/filters/statsd-increment.js similarity index 69% rename from lib/logging/transports/filters/statsd-increment.js rename to lib/logging/filters/statsd-increment.js index 33388e1c5..c234d59d2 100644 --- a/lib/logging/transports/filters/statsd-increment.js +++ b/lib/logging/filters/statsd-increment.js @@ -2,23 +2,18 @@ * License, v. 2.0. If a copy of the MPL was not distributed with this * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ -const config = require('../../../configuration'); +const config = require('../../configuration'); const PREFIX = "browserid." + config.get('process_type') + "."; -var IncrementMessageMatches = { - "assertion_failure": true, - "uncaught_exception": true -}; - var IncrementRegExpMatches = [ + /^assertion_failure\b/, /^wsapi_code_mismatch\./, - /^wsapi\./ + /^wsapi\./, + /^uncaught_exception\b/ ]; exports.test = function(msg) { - if (msg in IncrementMessageMatches) return true; - for (var i = 0, regExp; regExp = IncrementRegExpMatches[i]; ++i) { if (regExp.test(msg)) return true; } @@ -27,7 +22,7 @@ exports.test = function(msg) { }; exports.toType = function(msg) { - return PREFIX + msg; + return PREFIX + String(msg); }; diff --git a/lib/logging/transports/filters/statsd-timing.js b/lib/logging/filters/statsd-timing.js similarity index 65% rename from lib/logging/transports/filters/statsd-timing.js rename to lib/logging/filters/statsd-timing.js index 576bb6198..513bc96da 100644 --- a/lib/logging/transports/filters/statsd-timing.js +++ b/lib/logging/filters/statsd-timing.js @@ -2,23 +2,18 @@ * License, v. 2.0. If a copy of the MPL was not distributed with this * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ -const config = require('../../../configuration'); +const config = require('../../configuration'); const PREFIX = "browserid." + config.get('process_type') + "."; -var TimingMessageMatches = { - "bcrypt.compare_time": true, - "query_time": true, - "certification_time": true, - "assertion_verification_time": true -}; - var TimingRegExpMatches = [ + /^bcrypt.compare_time\b/, + /^query_time\b/, + /^certification_time\b/, + /^assertion_verification_time\b/, /^elapsed_time\.(.*)/ ]; function getMatch(msg) { - if (msg in TimingMessageMatches) return true; - for (var i = 0, regExp; regExp = TimingRegExpMatches[i]; ++i) { if (regExp.test(msg)) return regExp; } @@ -32,10 +27,12 @@ exports.toType = function(msg) { var match = getMatch(msg); // Use the capturing part of the match for the message. - if (match instanceof RegExp) - msg = msg.match(match)[1]; + if (match instanceof RegExp) { + match = msg.match(match); + msg = match[1] || match[0]; + } - return PREFIX + msg; + return PREFIX + String(msg).split(' ')[0]; }; diff --git a/lib/logging/formatters/metrics.js b/lib/logging/formatters/metrics.js new file mode 100644 index 000000000..b125596f2 --- /dev/null +++ b/lib/logging/formatters/metrics.js @@ -0,0 +1,22 @@ +/* This Source Code Form is subject to the terms of the Mozilla Public + * License, v. 2.0. If a copy of the MPL was not distributed with this + * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ + +const util = require('util'); +const intel = require('intel'); +const filter = require('../filters/metrics'); + +function MetricsFormatter() { + intel.Formatter.apply(this, arguments); +} +util.inherits(MetricsFormatter, intel.Formatter); + +MetricsFormatter.prototype.format = function metricsFormat(record) { + // we want the message adjusted when outputting here + record.message = JSON.stringify(filter.toEntry(record.message, record.args[1])); + var ret = intel.Formatter.prototype.format.call(this, record); + record.message = record.args[0]; + return ret; +}; + +module.exports = MetricsFormatter; diff --git a/lib/logging/handlers/kpi.js b/lib/logging/handlers/kpi.js new file mode 100644 index 000000000..0a71a3a5c --- /dev/null +++ b/lib/logging/handlers/kpi.js @@ -0,0 +1,98 @@ +/* This Source Code Form is subject to the terms of the Mozilla Public + * License, v. 2.0. If a copy of the MPL was not distributed with this + * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ + +const _ = require('underscore'); +const util = require('util'); +const intel = require('intel'); +const kpi_data = require('../../kpi_data'); +const logger = require('../logging').logger; +const config = require('../../configuration'); +const filter = require('../filters/metrics'); + +const FIELDS_TO_SEND_TO_PIGGYBANK = [ + "type", + "at", + "user_agent", + "idp", + "rp" +]; + +function MetricsKpiggybankHandler(options) { + options = options || {}; + this.queue = []; + intel.Handler.call(this, options); +} +util.inherits(MetricsKpiggybankHandler, intel.Handler); + +MetricsKpiggybankHandler.BATCH_SIZE = config.get('kpi.metrics_batch_size'); + +_.extend(MetricsKpiggybankHandler.prototype, { + + emit: function piggyEmit(record, callback) { + // TODO config? + if (!config.get('kpi.send_metrics')) return callback(); + + + var entry = toEntry(record.message, record.args[record.args.length - 1]); + this.queue.push([entry, callback]); + + + if (this.isQueueFull()) { + this.flush(); + } + }, + + isQueueFull: function isQueueFull() { + return this.queue.length >= MetricsKpiggybankHandler.BATCH_SIZE; + }, + + // the queue is an array of tuples (entry, callback) + // so this.queue = [ + // [entry, callback], ... + // ] + // Getting an entry then is: queue[index][0], or queue[0][0] to get + // the first entry. + getQueue: function getQueue() { + return this.queue; + }, + + flush: function flush() { + var kpis = this.queue.map(function(q) { return q[0]; }); + var callbacks = this.queue.map(function(q) { return q[1]; }); + this.reset(); + kpi_data.store(kpis, function(err, success) { + if (!err) { + if (success) { + return callbacks.forEach(function(cb) { cb(); }); + } else { + err = new Error('failed to store interaction data'); + } + } + callbacks.forEach(function(cb) { cb(err); }); + }); + }, + + reset: function reset() { + this.queue = []; + } + +}); + +function toEntry(msg, entry) { + return whitelistedFields(filter.toEntry(msg, entry), + FIELDS_TO_SEND_TO_PIGGYBANK); +} + +function whitelistedFields(entry, whitelist) { + var allowed = {}; + + for (var key in entry) { + if (whitelist.indexOf(key) > -1) allowed[key] = entry[key]; + } + + return allowed; +} + + +module.exports = MetricsKpiggybankHandler; diff --git a/lib/logging/handlers/statsd.js b/lib/logging/handlers/statsd.js new file mode 100644 index 000000000..03774dde1 --- /dev/null +++ b/lib/logging/handlers/statsd.js @@ -0,0 +1,52 @@ +/* This Source Code Form is subject to the terms of the Mozilla Public + * License, v. 2.0. If a copy of the MPL was not distributed with this + * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ + +const util = require('util'); +const intel = require('intel'); +const StatsD = require('node-statsd').StatsD; +const logger = require('../logging').getLogger('bid.logging.statsd'); +const config = require('../../configuration'); +const timing_filter = require('../filters/statsd-timing'); +const increment_filter = require('../filters/statsd-increment'); + +"use strict"; + +function StatsdHandler(options) { + options = options || {}; + this.statsd = options.statsd || getStatsdIfEnabled(); + intel.Handler.call(this, options); +} +util.inherits(StatsdHandler, intel.Handler); + +StatsdHandler.prototype.emit = function(record, callback) { + if ( ! this.statsd) return callback(); + var meta = record.args[ record.args.length - 1 ]; + + if (increment_filter.test(record.message)) { + this.statsd.increment(increment_filter.toType(record.args[0]), meta); + } else if (timing_filter.test(record.message)) { + this.statsd.timing(timing_filter.toType(record.args[0]), meta, meta); + } else if (record.stack) { + // increment_filter will handle uncaught_exceptions + // this will increment all CAUGHT exceptions that are logged + this.statsd.increment(timing_filter.toType('exception'), record.stack); + } + + callback(); +}; + + +function getStatsdIfEnabled() { + var statsdConfig = config.get('statsd'); + if (statsdConfig && statsdConfig.enabled) { + var statsdOptions = {}; + statsdOptions.host = statsdConfig.host || "localhost"; + statsdOptions.port = statsdConfig.port || 8125; + + return new StatsD(statsdOptions.host, statsdOptions.port); + } +} + + +module.exports = StatsdHandler; diff --git a/lib/logging/logging.js b/lib/logging/logging.js index 01a333d3d..ffcbdeb1f 100644 --- a/lib/logging/logging.js +++ b/lib/logging/logging.js @@ -3,8 +3,8 @@ * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ /* - * A very thin wrapper around winston for general server logging. - * Exports a winston Logger instance in exports.logger with several functions + * A very thin wrapper around intel for general server logging. + * Exports an intel Logger instance in exports.logger with several functions * corresponding to different log levels. use it like this: * * const logger = require('../libs/logging.js').logger; @@ -21,31 +21,44 @@ * CEF is slightly different, all CEF messages are sent over the pipe but * the cef interface takes care of writing to cef directly. */ +const path = require('path'); -const -winston = require("winston"); +const intel = require("intel"); +const mkdirp = require('mkdirp'); -// Must be defined before including the transports. Some of the transports -// depend on the logger being available. -exports.logger = new winston.Logger({}); +const config = require('../configuration'); -const LogFileTransport = require('./transports/log-file'); -const StatsdTransport = require('./transports/statsd'); -const MetricsFileTransport = require('./transports/metrics-file'); -const MetricsKpiggybankTransport = require('./transports/metrics-kpi'); +module.exports = intel; +// go through the configuration and determine log location -exports.logger.add(LogFileTransport, {}); -exports.logger.add(StatsdTransport, {}); -exports.logger.add(MetricsFileTransport, {}); -exports.logger.add(MetricsKpiggybankTransport.getInstance(), {}, true); +var log_path = path.join(config.get('var_path'), 'log'); +if (!log_path) + return console.log('no log path! Not logging!'); +else + mkdirp.sync(log_path, '0755'); -exports.enableConsoleLogging = function() { - exports.logger.add(winston.transports.Console, { - colorize: true, - handleExceptions: true - }); -}; -if (process.env.LOG_TO_CONSOLE) exports.enableConsoleLogging(); -exports.logger.exitOnError = false; +var loggingOptions = config.get('logging'); +loggingOptions.root = path.join(__dirname, '..'); + +if (loggingOptions.handlers && loggingOptions.handlers.file) { + var filename = path.join(log_path, config.get('process_type') + '.log'); + loggingOptions.handlers.file.file = filename; +} + +if (loggingOptions.handlers && loggingOptions.handlers.metrics) { + var filename = path.join(log_path, config.get('process_type') + '-metrics.json'); + if (process.env.METRICS_LOG_FILE) { + filename = process.env.METRICS_LOG_FILE; + } + loggingOptions.handlers.metrics.file = filename; +} + +if (process.env.LOG_TO_CONSOLE) { + loggingOptions.loggers.bid.handlers.push('console'); +} + +intel.config(loggingOptions); + + diff --git a/lib/logging/middleware/metrics.js b/lib/logging/middleware/metrics.js index 95d3ebc86..137bafb96 100644 --- a/lib/logging/middleware/metrics.js +++ b/lib/logging/middleware/metrics.js @@ -8,7 +8,7 @@ const urlparse = require('urlparse'); const _ = require('underscore'); -const logger = require("../logging").logger; +const logger = require("../logging").getLogger('bid.middleware.metrics'); // utility function to log a bunch of stuff at user entry point diff --git a/lib/logging/middleware/statsd.js b/lib/logging/middleware/statsd.js index 91f813aa8..ba47421a3 100644 --- a/lib/logging/middleware/statsd.js +++ b/lib/logging/middleware/statsd.js @@ -4,7 +4,7 @@ const baseExceptions = require('../../baseExceptions'); const config = require('../../configuration'); -const logger = require('../logging').logger; +const logger = require('../logging').getLogger('bid.middleware.statsd'); const statsd_request_logger = require("connect-logger-statsd"); const PREFIX = "browserid." + config.get('process_type') + "."; @@ -32,8 +32,7 @@ module.exports = function(prefix) { baseExceptions.removeExceptionHandler(); process.on('uncaughtException', function(err) { - logger.info('uncaught_exception'); - logger.error(err.stack || err); + logger.error('uncaught_exception', err); }); diff --git a/lib/logging/transports/log-file.js b/lib/logging/transports/log-file.js deleted file mode 100644 index 688a9c543..000000000 --- a/lib/logging/transports/log-file.js +++ /dev/null @@ -1,45 +0,0 @@ -/* This Source Code Form is subject to the terms of the Mozilla Public - * License, v. 2.0. If a copy of the MPL was not distributed with this - * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ - -/** - * Winston transport that takes care of writing to the process specific log. - * Logs are generally found in /var/log/.log - */ - -const winston = require('winston'); -const File = winston.transports.File; -const util = require('util'); -const configuration = require("../../configuration"); -const path = require('path'); -const mkdirp = require('mkdirp'); -const _ = require('underscore'); - -"use strict"; - -// go through the configuration and determine log location -var log_path = path.join(configuration.get('var_path'), 'log'); -if (!log_path) - return console.log("no log path! Not logging!"); -else - mkdirp.sync(log_path, "0755"); - -var filename = path.join(log_path, configuration.get('process_type') + ".log"); - -var FileTransport = function(options) { - options = _.extend({ - timestamp: function () { return new Date().toISOString(); }, - filename: filename, - colorize: true, - handleExceptions: true - }, options); - - File.call(this, options); -}; -util.inherits(FileTransport, File); - -FileTransport.prototype.name = 'fileTransport'; - - -module.exports = FileTransport; - diff --git a/lib/logging/transports/metrics-file.js b/lib/logging/transports/metrics-file.js deleted file mode 100644 index 18c41c229..000000000 --- a/lib/logging/transports/metrics-file.js +++ /dev/null @@ -1,69 +0,0 @@ -/* This Source Code Form is subject to the terms of the Mozilla Public - * License, v. 2.0. If a copy of the MPL was not distributed with this - * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ - -/* - * The metrics module is designed to report interesting events to a file. - * Metrics files from different production servers can then be aggregated - * and post processed to get an idea of the degree and ways that browserid is - * being used by the world, to facilitate capacity planning and changes - * to the software. - * - * NOTE: This is *not* a generic logging mechanism for low level events - * interesting only to debug or assess the health of a server. - * - * DOUBLE NOTE: Sensitive information shouldn't be - * reported through this mechanism, and it isn't necesary to do so given - * we're after general trends, not specifics. - */ - -const winston = require('winston'); -const File = winston.transports.File; -const util = require('util'); -const path = require('path'); -const mkdirp = require('mkdirp'); -const _ = require('underscore'); -const configuration = require('../../configuration'); -const filter = require('./filters/metrics'); - -// go through the configuration and determine log location -// for now we only log to one place -// FIXME: separate logs depending on purpose? - -var log_path = path.join(configuration.get('var_path'), 'log'); -if (!log_path) - return console.log('no log path! Not logging!'); -else - mkdirp.sync(log_path, '0755'); - -var filename = path.join(log_path, - configuration.get('process_type') + '-metrics.json'); -if (process.env.METRICS_LOG_FILE) { - filename = process.env.METRICS_LOG_FILE; -} - -var MetricsFileTransport = function(options) { - options = _.extend({ - timestamp: function () { return new Date().toISOString(); }, - filename: filename, - colorize: false, - handleExceptions: false - }, options); - - File.call(this, options); -}; -util.inherits(MetricsFileTransport, File); - -MetricsFileTransport.prototype.name = 'metricsFileTransport'; - -MetricsFileTransport.prototype.log = function(level, msg, meta, callback) { - if ( ! filter.test(msg)) return callback(null, true); - - var entry = filter.toEntry(msg, meta); - return File.prototype.log.call(this, - level, JSON.stringify(entry), null, callback); -}; - -module.exports = MetricsFileTransport; - - diff --git a/lib/logging/transports/metrics-kpi.js b/lib/logging/transports/metrics-kpi.js deleted file mode 100644 index 2fb5d52f7..000000000 --- a/lib/logging/transports/metrics-kpi.js +++ /dev/null @@ -1,108 +0,0 @@ -/* This Source Code Form is subject to the terms of the Mozilla Public - * License, v. 2.0. If a copy of the MPL was not distributed with this - * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ - -const util = require('util'); -const winston = require('winston'); -const kpi_data = require('../../kpi_data'); -const logger = require('../logging').logger; -const config = require('../../configuration'); -const filter = require('./filters/metrics'); - -const FIELDS_TO_SEND_TO_PIGGYBANK = [ - "type", - "timestamp", - "user_agent", - "idp", - "rp" -]; - -var MetricsKpiggybankTransport = function(options) { - options = options || {}; - this.queue = []; - this.name = 'metricsKpiggybankTransport'; -}; -MetricsKpiggybankTransport.BATCH_SIZE = config.get('kpi.metrics_batch_size'); - -var instance; -MetricsKpiggybankTransport.getInstance = function() { - if (instance) return instance; - - instance = new MetricsKpiggybankTransport(); - return instance; -}; - -util.inherits(MetricsKpiggybankTransport, winston.Transport); - - -MetricsKpiggybankTransport.prototype.reset = function() { - this.queue = []; -}; - -MetricsKpiggybankTransport.prototype.log - = function(level, msg, meta, callback) { - if ( ! filter.test(msg)) return callback(null, true); - if ( ! config.get('kpi.send_metrics')) return callback(null, true); - - var entry = toEntry(msg, meta); - this.push(entry); - - callback(null, true); -}; - -MetricsKpiggybankTransport.prototype.push = function(entry) { - this.queue.push(entry); - - if (isQueueFull.call(this)) { - clearQueue.call(this); - } -}; - -MetricsKpiggybankTransport.prototype.getQueue = function() { - return this.queue; -}; - -// used for testing to see whether a metric was logged. -MetricsKpiggybankTransport.prototype.isLogged = function(msg) { - return this.queue.some(function(item) { - return item.type === msg; - }); -}; - -MetricsKpiggybankTransport.prototype.getItem = function(msg) { - return this.queue.filter(function(item) { - return item.type === msg; - })[0]; -}; - -function isQueueFull() { - return this.queue.length >= MetricsKpiggybankTransport.BATCH_SIZE; -} - - -function clearQueue() { - var kpis = this.queue; - this.queue = []; - kpi_data.store(kpis, function(err, success) { - if (err) return logger.warn(String(err)); - if (!success) logger.warn("failed to store interaction data"); - }); -} - -function toEntry(msg, entry) { - return whitelistedFields(filter.toEntry(msg, entry), - FIELDS_TO_SEND_TO_PIGGYBANK); -} - -function whitelistedFields(entry, whitelist) { - var allowed = {}; - - for (var key in entry) { - if (whitelist.indexOf(key) > -1) allowed[key] = entry[key]; - } - - return allowed; -} - - -module.exports = MetricsKpiggybankTransport; diff --git a/lib/logging/transports/statsd.js b/lib/logging/transports/statsd.js deleted file mode 100644 index 861967447..000000000 --- a/lib/logging/transports/statsd.js +++ /dev/null @@ -1,51 +0,0 @@ -/* This Source Code Form is subject to the terms of the Mozilla Public - * License, v. 2.0. If a copy of the MPL was not distributed with this - * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ - -const util = require('util'); -const winston = require('winston'); -const StatsD = require("node-statsd").StatsD; -const logger = require('../logging').logger; -const config = require('../../configuration'); -const timing_filter = require('./filters/statsd-timing'); -const increment_filter = require('./filters/statsd-increment'); - -"use strict"; - -var StatsdTransport = function(options) { - options = options || {}; - - this.name = 'statsdTransport'; - - this.statsd = options.statsd || getStatsdIfEnabled(); -}; - -util.inherits(StatsdTransport, winston.Transport); - -StatsdTransport.prototype.log = function(level, msg, meta, callback) { - if ( ! this.statsd) return callback(null, true); - - if (increment_filter.test(msg)) { - this.statsd.increment(increment_filter.toType(msg), meta); - } - else if (timing_filter.test(msg)) { - this.statsd.timing(timing_filter.toType(msg), meta, meta); - } - - callback(null, true); -}; - - -function getStatsdIfEnabled() { - var statsdConfig = config.get('statsd'); - if (statsdConfig && statsdConfig.enabled) { - var statsdOptions = {}; - statsdOptions.host = statsdConfig.host || "localhost"; - statsdOptions.port = statsdConfig.port || 8125; - - return new StatsD(statsdOptions.host, statsdOptions.port); - } -} - - -module.exports = StatsdTransport; diff --git a/lib/primary.js b/lib/primary.js index 8926d683a..ab3ec0f06 100644 --- a/lib/primary.js +++ b/lib/primary.js @@ -9,7 +9,7 @@ const https = require('https'), http = require('http'), -logger = require('./logging/logging.js').logger, +logger = require('./logging/logging.js').getLogger('bid.primary'), urlparse = require('urlparse'), jwcrypto = require("jwcrypto"), config = require("./configuration.js"), @@ -169,13 +169,13 @@ var fetchWellKnown = function (currentDomain, principalDomain, clientCB) { } // front-end shows xhr delay message after 10 sec; timeout sooner to avoid this - var reqTimeout = setTimeout(function() { + var reqTimeout = setTimeout(function abortReq() { req.abort(); handleProxyIDP('timeout trying to load well-known for ' + currentDomain); }, primaryTimeout); - req.on('response', function() { clearTimeout(reqTimeout); }); + req.on('response', function onReqResponse() { clearTimeout(reqTimeout); }); - req.on('error', function(e) { + req.on('error', function onReqError(e) { if (reqTimeout) { clearTimeout(reqTimeout); } handleProxyIDP(currentDomain + ' is not a browserid primary: ' + String(e)); }); @@ -188,7 +188,7 @@ function deepFetchWellKnown(principalDomain, cb, currentDomain, delegationChain) if (!currentDomain) currentDomain = principalDomain; if (!delegationChain) delegationChain = [ principalDomain ]; - fetchWellKnown(currentDomain, principalDomain, function(err, unparsedDoc) { + fetchWellKnown(currentDomain, principalDomain, function onWellKnownFetched(err, unparsedDoc) { if (err) return cb(err); var supportDoc; @@ -279,7 +279,7 @@ exports.checkSupport = function(principalDomain, cb) { } var startTime = new Date(); - deepFetchWellKnown(principalDomain, function (err, r) { + deepFetchWellKnown(principalDomain, function onDeepWellKnownFetched(err, r) { var reqTime = new Date() - startTime; if (err) { @@ -320,7 +320,7 @@ exports.getPublicKey = function(domain, cb) { // Is issuingDomain allowed to issue certifications for emails from // emailDomain. exports.delegatesAuthority = function (emailDomain, issuingDomain, cb) { - exports.checkSupport(emailDomain, function(err, r) { + exports.checkSupport(emailDomain, function onSupportChecked(err, r) { cb(!err && r && (r.authoritativeDomain === issuingDomain)); }); }; diff --git a/lib/shutdown.js b/lib/shutdown.js index 52b68df24..f2e0a9bf0 100644 --- a/lib/shutdown.js +++ b/lib/shutdown.js @@ -7,7 +7,7 @@ * signals. */ -const logger = require("./logging/logging.js").logger; +const logger = require("./logging/logging.js").getLogger('bid.shutdown'); const MAX_WAIT_MS = 10000; const MAX_NICE_END_MS = 5000; diff --git a/lib/static/views.js b/lib/static/views.js index 98e66c287..80af57f3b 100644 --- a/lib/static/views.js +++ b/lib/static/views.js @@ -4,7 +4,7 @@ const url = require('url'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.static.views'), fs = require('fs'), connect = require('connect'), config = require('../configuration.js'), diff --git a/lib/validate.js b/lib/validate.js index 40c58c2d7..6d2ca680a 100644 --- a/lib/validate.js +++ b/lib/validate.js @@ -13,7 +13,7 @@ // }); const -logger = require('./logging/logging.js').logger, +logger = require('./logging/logging.js').getLogger('bid.validate'), httputils = require('./httputils.js'), check = require('validator').check, url = require('url'); diff --git a/lib/verifier/certassertion.js b/lib/verifier/certassertion.js index 6d355faf6..18a55d4e5 100644 --- a/lib/verifier/certassertion.js +++ b/lib/verifier/certassertion.js @@ -8,7 +8,7 @@ https = require("https"), url = require("url"), jwcrypto = require("jwcrypto"), config = require("../configuration.js"), -logger = require("../logging/logging.js").logger, +logger = require("../logging/logging.js").getLogger('bid.verifier.certassertion'), secrets = require('../secrets.js'), primary = require('../primary.js'), urlparse = require('urlparse'); diff --git a/lib/version.js b/lib/version.js index 1df036e0d..194f0bfff 100644 --- a/lib/version.js +++ b/lib/version.js @@ -10,7 +10,7 @@ const fs = require('fs'), path = require('path'), -logger = require('./logging/logging.js').logger, +logger = require('./logging/logging.js').getLogger('bid.version'), spawn = require('child_process').spawn, secrets = require('./secrets.js'), config = require('./configuration'); diff --git a/lib/wsapi.js b/lib/wsapi.js index ebd77be0d..854048b9e 100644 --- a/lib/wsapi.js +++ b/lib/wsapi.js @@ -19,7 +19,7 @@ sessions = require('client-sessions'), express = require('express'), secrets = require('./secrets'), config = require('./configuration'), -logger = require('./logging/logging.js').logger, +logger = require('./logging/logging.js').getLogger('bid.wsapi'), httputils = require('./httputils.js'), forward = require('./http_forward.js').forward, url = require('url'), diff --git a/lib/wsapi/account_cancel.js b/lib/wsapi/account_cancel.js index 74316ee93..d4e4d2527 100644 --- a/lib/wsapi/account_cancel.js +++ b/lib/wsapi/account_cancel.js @@ -5,7 +5,6 @@ const db = require('../db.js'), wsapi = require('../wsapi'), -logger = require('../logging/logging.js').logger, cef_logger = require('../logging/cef_logger').getInstance(); exports.method = 'post'; diff --git a/lib/wsapi/add_email_with_assertion.js b/lib/wsapi/add_email_with_assertion.js index 2a0a4debd..56950b45b 100644 --- a/lib/wsapi/add_email_with_assertion.js +++ b/lib/wsapi/add_email_with_assertion.js @@ -6,7 +6,7 @@ const db = require('../db.js'), wsapi = require('../wsapi.js'), httputils = require('../httputils'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.wsapi.add_email_with_assertion'), querystring = require('querystring'), primary = require('../primary.js'), http = require('http'), diff --git a/lib/wsapi/address_info.js b/lib/wsapi/address_info.js index baa29e502..c251e7268 100644 --- a/lib/wsapi/address_info.js +++ b/lib/wsapi/address_info.js @@ -9,7 +9,7 @@ wsapi = require('../wsapi.js'), httputils = require('../httputils.js'), url = require('url'), urlparse = require('urlparse'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.wsapi.address_info'), config = require('../configuration.js'); // type: {primary, secondary} // indicates email type right now diff --git a/lib/wsapi/auth_with_assertion.js b/lib/wsapi/auth_with_assertion.js index 39b0da7fb..ac2d5404d 100644 --- a/lib/wsapi/auth_with_assertion.js +++ b/lib/wsapi/auth_with_assertion.js @@ -6,7 +6,7 @@ const db = require('../db.js'), wsapi = require('../wsapi.js'), httputils = require('../httputils'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.wsapi.auth_with_assertion'), querystring = require('querystring'), primary = require('../primary.js'), http = require('http'), diff --git a/lib/wsapi/authenticate_user.js b/lib/wsapi/authenticate_user.js index c5f55af32..4a904a472 100644 --- a/lib/wsapi/authenticate_user.js +++ b/lib/wsapi/authenticate_user.js @@ -6,7 +6,7 @@ const db = require('../db.js'), wsapi = require('../wsapi.js'), httputils = require('../httputils'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.wsapi.authenticate_user'), bcrypt = require('../bcrypt'), http = require('http'), https = require('https'), diff --git a/lib/wsapi/cert_key.js b/lib/wsapi/cert_key.js index 01de15ce7..5e9e1d89c 100644 --- a/lib/wsapi/cert_key.js +++ b/lib/wsapi/cert_key.js @@ -5,7 +5,7 @@ const db = require('../db.js'), httputils = require('../httputils'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.wsapi.cert_key'), forward = require('../http_forward.js').forward, config = require('../configuration.js'), urlparse = require('urlparse'), diff --git a/lib/wsapi/complete_email_confirmation.js b/lib/wsapi/complete_email_confirmation.js index f2d81252e..7b0126d05 100644 --- a/lib/wsapi/complete_email_confirmation.js +++ b/lib/wsapi/complete_email_confirmation.js @@ -10,7 +10,7 @@ const db = require('../db.js'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.wsapi.complete_email_confirmation'), wsapi = require('../wsapi.js'), bcrypt = require('../bcrypt.js'), httputils = require('../httputils.js'); diff --git a/lib/wsapi/complete_reset.js b/lib/wsapi/complete_reset.js index 4ea4c1958..492fbff11 100644 --- a/lib/wsapi/complete_reset.js +++ b/lib/wsapi/complete_reset.js @@ -4,7 +4,7 @@ const db = require('../db.js'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.wsapi.complete_reset'), wsapi = require('../wsapi.js'), bcrypt = require('../bcrypt.js'), httputils = require('../httputils.js'), diff --git a/lib/wsapi/complete_transition.js b/lib/wsapi/complete_transition.js index ddce6213d..8e5a8c614 100644 --- a/lib/wsapi/complete_transition.js +++ b/lib/wsapi/complete_transition.js @@ -4,7 +4,7 @@ const db = require('../db.js'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.wsapi.complete_transition'), wsapi = require('../wsapi.js'), bcrypt = require('../bcrypt.js'), httputils = require('../httputils.js'), diff --git a/lib/wsapi/complete_user_creation.js b/lib/wsapi/complete_user_creation.js index 0aeb69dfa..e91ee00eb 100644 --- a/lib/wsapi/complete_user_creation.js +++ b/lib/wsapi/complete_user_creation.js @@ -6,7 +6,7 @@ const db = require('../db.js'), wsapi = require('../wsapi.js'), httputils = require('../httputils'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.wsapi.complete_user_creation'), bcrypt = require('../bcrypt'), config = require('../configuration'), wsapiutils = require('../wsapiutils'); diff --git a/lib/wsapi/create_account_with_assertion.js b/lib/wsapi/create_account_with_assertion.js index 797479b7a..adaae68c1 100644 --- a/lib/wsapi/create_account_with_assertion.js +++ b/lib/wsapi/create_account_with_assertion.js @@ -7,7 +7,7 @@ db = require('../db.js'), wsapi = require('../wsapi.js'), httputils = require('../httputils'), primary = require('../primary.js'), -logger = require('../logging/logging.js').logger; +logger = require('../logging/logging.js').getLogger('bid.wsapi.create_account_with_assertion'); exports.method = 'post'; exports.writes_db = true; diff --git a/lib/wsapi/discovery.js b/lib/wsapi/discovery.js index ac6bd3929..cdab67966 100644 --- a/lib/wsapi/discovery.js +++ b/lib/wsapi/discovery.js @@ -4,7 +4,7 @@ const config = require('../configuration.js'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.wsapi.discovery'), primary = require('../primary.js'), secrets = require("../secrets.js"), urlparse = require('urlparse'); @@ -34,7 +34,7 @@ try { exports.process = function(req, res) { var domain = req.params.domain; var wellKnown; - primary.checkSupport(domain, function(err, r) { + primary.checkSupport(domain, function onSupport(err, r) { if (!err && r && r.urls) { wellKnown = { "public-key": JSON.parse(r.publicKey.serialize()), // gross diff --git a/lib/wsapi/email_for_token.js b/lib/wsapi/email_for_token.js index 1cf8cd8ae..ef8fbb78b 100644 --- a/lib/wsapi/email_for_token.js +++ b/lib/wsapi/email_for_token.js @@ -5,7 +5,7 @@ const db = require('../db.js'), httputils = require('../httputils.js'), -logger = require('../logging/logging.js').logger; +logger = require('../logging/logging.js').getLogger('bid.wsapi.email_for_token'); /* Given a verification secret (a "token", delivered via email), return the * email address associated with this token. diff --git a/lib/wsapi/forget_idp.js b/lib/wsapi/forget_idp.js index b96b978ae..e04607cde 100644 --- a/lib/wsapi/forget_idp.js +++ b/lib/wsapi/forget_idp.js @@ -9,10 +9,7 @@ const db = require('../db.js'), -wsapi = require('../wsapi.js'), -httputils = require('../httputils'), -primary = require('../primary.js'), -logger = require('../logging/logging.js').logger; +wsapi = require('../wsapi.js'); exports.method = 'get'; exports.writes_db = true; diff --git a/lib/wsapi/interaction_data.js b/lib/wsapi/interaction_data.js index d94e5ef1b..649125116 100644 --- a/lib/wsapi/interaction_data.js +++ b/lib/wsapi/interaction_data.js @@ -3,9 +3,8 @@ * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ const coarse = require('../coarse_user_agent_parser'), - logger = require('../logging/logging').logger, - und = require('underscore'), - kpiTransport = require('../logging/transports/metrics-kpi').getInstance(); + logger = require('../logging/logging').getLogger('bid.wsapi.interaction_data'), + und = require('underscore'); // Accept JSON formatted interaction data and send it to the KPI Backend @@ -38,7 +37,7 @@ exports.process = function(req, res) { }); } - kpiTransport.push(kpi_json); + logger.info(kpi_json); } else { logger.info("failed to store interaction data, client sent no .data"); } diff --git a/lib/wsapi/list_emails.js b/lib/wsapi/list_emails.js index c9574a109..bbbc84371 100644 --- a/lib/wsapi/list_emails.js +++ b/lib/wsapi/list_emails.js @@ -4,7 +4,7 @@ const db = require('../db.js'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.wspai.list_emails'), wsapi = require('../wsapi.js'); // returns a list of emails owned by the user: diff --git a/lib/wsapi/password_reset_status.js b/lib/wsapi/password_reset_status.js index 8a88bd1c2..9cc670638 100644 --- a/lib/wsapi/password_reset_status.js +++ b/lib/wsapi/password_reset_status.js @@ -4,9 +4,7 @@ const db = require('../db.js'), -wsapi = require('../wsapi.js'), -logger = require('../logging/logging.js').logger, -httputils = require('../httputils.js'); +wsapi = require('../wsapi.js'); exports.method = 'get'; exports.writes_db = false; diff --git a/lib/wsapi/remove_email.js b/lib/wsapi/remove_email.js index 4f22590c7..fda898cd0 100644 --- a/lib/wsapi/remove_email.js +++ b/lib/wsapi/remove_email.js @@ -6,7 +6,7 @@ const db = require('../db.js'), wsapi = require('../wsapi'), httputils = require('../httputils'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.wsapi.remove_email'), cef_logger = require('../logging/cef_logger').getInstance(); exports.method = 'post'; diff --git a/lib/wsapi/saw_idp.js b/lib/wsapi/saw_idp.js index cef1f48b5..910ead58b 100644 --- a/lib/wsapi/saw_idp.js +++ b/lib/wsapi/saw_idp.js @@ -9,10 +9,7 @@ const db = require('../db.js'), -wsapi = require('../wsapi.js'), -httputils = require('../httputils'), -primary = require('../primary.js'), -logger = require('../logging/logging.js').logger; +wsapi = require('../wsapi.js'); exports.method = 'get'; exports.writes_db = true; diff --git a/lib/wsapi/session_context.js b/lib/wsapi/session_context.js index 881af85dc..55de0f06c 100644 --- a/lib/wsapi/session_context.js +++ b/lib/wsapi/session_context.js @@ -4,7 +4,7 @@ const db = require('../db.js'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.wsapi.session_context'), crypto = require('crypto'), wsapi = require('../wsapi.js'), secrets = require('../secrets.js'), diff --git a/lib/wsapi/stage_email.js b/lib/wsapi/stage_email.js index a80deaeea..0a3997a99 100644 --- a/lib/wsapi/stage_email.js +++ b/lib/wsapi/stage_email.js @@ -6,7 +6,7 @@ const db = require('../db.js'), wsapi = require('../wsapi.js'), httputils = require('../httputils'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.wsapi.stage_email'), email = require('../email.js'), config = require('../configuration'); diff --git a/lib/wsapi/stage_reset.js b/lib/wsapi/stage_reset.js index d7ac556f7..a5928a1c8 100644 --- a/lib/wsapi/stage_reset.js +++ b/lib/wsapi/stage_reset.js @@ -6,7 +6,7 @@ const db = require('../db.js'), wsapi = require('../wsapi.js'), httputils = require('../httputils'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.wsapi.stage_reset'), email = require('../email.js'), config = require('../configuration'); diff --git a/lib/wsapi/stage_reverify.js b/lib/wsapi/stage_reverify.js index cb904ea3b..237e16f4a 100644 --- a/lib/wsapi/stage_reverify.js +++ b/lib/wsapi/stage_reverify.js @@ -6,7 +6,7 @@ const db = require('../db.js'), wsapi = require('../wsapi.js'), httputils = require('../httputils'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.wsapi.stage_reverify'), email = require('../email.js'), config = require('../configuration'); diff --git a/lib/wsapi/stage_transition.js b/lib/wsapi/stage_transition.js index ff93e7101..ea5f085e5 100644 --- a/lib/wsapi/stage_transition.js +++ b/lib/wsapi/stage_transition.js @@ -6,7 +6,7 @@ const db = require('../db.js'), wsapi = require('../wsapi.js'), httputils = require('../httputils'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.wsapi.stage_transition'), email = require('../email.js'), config = require('../configuration'); diff --git a/lib/wsapi/stage_user.js b/lib/wsapi/stage_user.js index 4a5622958..59e3f710c 100644 --- a/lib/wsapi/stage_user.js +++ b/lib/wsapi/stage_user.js @@ -6,7 +6,7 @@ const db = require('../db.js'), wsapi = require('../wsapi.js'), httputils = require('../httputils'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.wsapi.stage_user'), email = require('../email.js'), config = require('../configuration'), cef_logger = require('../logging/cef_logger').getInstance(); diff --git a/lib/wsapi/transition_status.js b/lib/wsapi/transition_status.js index 8a88bd1c2..9cc670638 100644 --- a/lib/wsapi/transition_status.js +++ b/lib/wsapi/transition_status.js @@ -4,9 +4,7 @@ const db = require('../db.js'), -wsapi = require('../wsapi.js'), -logger = require('../logging/logging.js').logger, -httputils = require('../httputils.js'); +wsapi = require('../wsapi.js'); exports.method = 'get'; exports.writes_db = false; diff --git a/lib/wsapi/update_password.js b/lib/wsapi/update_password.js index 96b8606e1..a87f14b20 100644 --- a/lib/wsapi/update_password.js +++ b/lib/wsapi/update_password.js @@ -6,7 +6,7 @@ const db = require('../db.js'), wsapi = require('../wsapi.js'), httputils = require('../httputils'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.wsapi.update_password'), bcrypt = require('../bcrypt'); exports.method = 'post'; diff --git a/lib/wsapi/used_address_as_primary.js b/lib/wsapi/used_address_as_primary.js index 448949f18..818f52a31 100644 --- a/lib/wsapi/used_address_as_primary.js +++ b/lib/wsapi/used_address_as_primary.js @@ -5,7 +5,7 @@ const db = require('../db.js'), httputils = require('../httputils'), -logger = require('../logging/logging.js').logger, +logger = require('../logging/logging.js').getLogger('bid.wsapi.used_address_as_primary'), primary = require('../primary.js'), wsapi = require('../wsapi.js'); diff --git a/lib/wsapi/user_used_email_as.js b/lib/wsapi/user_used_email_as.js index b85fc2c08..74ad590ce 100644 --- a/lib/wsapi/user_used_email_as.js +++ b/lib/wsapi/user_used_email_as.js @@ -9,9 +9,7 @@ const db = require('../db.js'), wsapi = require('../wsapi.js'), -httputils = require('../httputils'), -primary = require('../primary.js'), -logger = require('../logging/logging.js').logger; +httputils = require('../httputils'); exports.method = 'post'; exports.writes_db = true; diff --git a/lockdown.json b/lockdown.json index ebe0132be..63ba94a5e 100644 --- a/lockdown.json +++ b/lockdown.json @@ -11,6 +11,9 @@ "ansi": { "0.1.2": "2627e29498f06e2a1c2ece9c21e28fd494430827" }, + "ansi-styles": { + "0.2.0": "359ab4b15dcd64ba6d74734b72c36360a9af2c19" + }, "async": { "0.1.22": "0fc1aaa088a0e3ef0ebe2d8831bab0dcf8845061", "0.2.9": "df63060fbf3d33286a76aaf6d55a2986d9ff8619" @@ -43,6 +46,9 @@ "1.0.0": "c3ccde60e9de6807c6f1aa4ef4843af29191c828", "1.1.0": "f3cc4deec19fe31f255864eb1e6ffad857266ef0" }, + "bluebird": { + "0.11.5-0": "15e028b3d8169e85a60e590721cd1d4f23617813" + }, "boom": { "0.3.8": "c8cdb041435912741628c044ecc732d1d17c09ea" }, @@ -52,6 +58,9 @@ "cef": { "0.3.3": "74a521e3c5c702fe1dc240e6250a2583f885227f" }, + "chalk": { + "0.3.0": "1c98437737f1199ebcc1d4c48fd41b9f9c8e8f23" + }, "character-parser": { "1.0.2": "55384d6afcf8c6b9dd483e8347646a790e4545e7" }, @@ -212,6 +221,9 @@ "1.2.3": "15a4806a57547cb2d2dbf27f42e89a8c3451b364", "2.0.1": "7fd6e0a4837c35d0cc15330294d9584a3898cf84" }, + "has-color": { + "0.1.1": "28cc90127bc5448f99e76096dc97470a94a66720" + }, "hashish": { "0.0.4": "6d60bc6ffaf711b6afd60e426d077988014e6554" }, @@ -240,6 +252,9 @@ "1.0.0": "38e1975285bf1f7ba9c84da102bb12771322ac48", "2.0.1": "b17d08d326b4423e568eff719f91b0b1cbdf69f1" }, + "intel": { + "0.4.0": "cfa42f66d7ea3a948bf5ee2c90862b62e1fa0eff" + }, "irc": { "0.3.6": "eacfdb08c57971ea82c331178e2aaf34f1bab303" }, @@ -352,9 +367,6 @@ "osenv": { "0.0.3": "cd6ad8ddb290915ad9e22765576025d411f29cb6" }, - "pkginfo": { - "0.3.0": "726411401039fe9b009eea86614295d5f3a54276" - }, "plist": { "0.4.3": "812842a873aa57f98d0050bee6aaf3549b9d5798" }, @@ -384,9 +396,6 @@ "relative-date": { "1.1.1": "75c97c5446fa1146c1d250c47ca3629fb9a2e764" }, - "request": { - "2.16.6": "872fe445ae72de266b37879d6ad7dc948fa01cad" - }, "resolve": { "0.2.8": "fdb17d4abb0ecaf6f80d67ac03cf290088f6c0d0" }, @@ -425,6 +434,9 @@ "stack-trace": { "0.0.7": "c72e089744fc3659f508cdce3621af5634ec0fff" }, + "strftime": { + "0.6.2": "da4c12073cebee3cd60f4821940cc27b19d348a1" + }, "temp": { "0.4.0": "671ad63d57be0fe9d7294664b3fc400636678a60", "0.6.0": "6b13df5cddf370f2e3a606ca40f202c419173f07" @@ -473,6 +485,9 @@ "useragent": { "2.0.7": "a44c07d157a15e13d73d4af4ece6aab70f298224" }, + "utcstring": { + "0.1.0": "430fd510ab7fc95b5d5910c902d79880c208436b" + }, "validator": { "0.4.24": "9d88e88809114a861ec69bc0ddcb85322c98499a", "1.5.1": "7ab356cbbcbbb000ab85c43b8cda12621b1344c0" @@ -488,9 +503,6 @@ "which": { "1.0.5": "5630d6819dda692f1464462e7956cb42c0842739" }, - "winston": { - "0.7.2": "2570ae1aa1d8a9401e8d5a88362e1cf936550ceb" - }, "wordwrap": { "0.0.2": "b79669bb42ecb409f83d583cad52ca17eaa1643f" }, diff --git a/package.json b/package.json index b4a76dd35..1556e3781 100644 --- a/package.json +++ b/package.json @@ -39,6 +39,7 @@ "gobbledygook": "0.0.3", "hood": "0.2.1", "i18n-abide": "0.0.14", + "intel": "0.4.0", "lockdown": "0.0.5", "jwcrypto": "0.4.4", "mkdirp": "0.3.5", @@ -56,8 +57,7 @@ "underscore": "1.5.2", "urlparse": "0.0.1", "useragent": "2.0.7", - "validator": "1.5.1", - "winston": "0.7.2" + "validator": "1.5.1" }, "devDependencies": { "vows": "https://github.com/cloudhead/vows/tarball/253ca34c", diff --git a/scripts/compress-worker.js b/scripts/compress-worker.js index c8f640780..67b533c7e 100644 --- a/scripts/compress-worker.js +++ b/scripts/compress-worker.js @@ -7,7 +7,7 @@ cachify = require('connect-cachify'), config = require('../lib/configuration.js'), fs = require('fs'), jsp = require("uglify-js").parser, -logger = require('../lib/logging/logging.js').logger, +logger = require('../lib/logging/logging.js').getLogger('bid.scripts.compress'), pro = require("uglify-js").uglify, uglifycss = require('uglifycss'), mkdirp = require('mkdirp'), diff --git a/tests/kpi-test.js b/tests/kpi-test.js index 5a936912c..53629b449 100755 --- a/tests/kpi-test.js +++ b/tests/kpi-test.js @@ -11,8 +11,11 @@ const wsapi = require('./lib/wsapi'); const config = require('../lib/configuration'); const kpi_data = require('../lib/kpi_data'); const HttpMock = require('./lib/http-mock'); -const logger = require('../lib/logging/logging').logger; -const KpiTransport = require('../lib/logging/transports/metrics-kpi'); +const KpiHandler = require('../lib/logging/handlers/kpi'); +const intel = require('../lib/logging/logging'); +const _ = require('underscore'); + +const logger = intel.getLogger('bid.test.kpi'); require('./lib/test_env'); @@ -133,8 +136,6 @@ suite.addBatch({ } }); -function noOp() {} - suite.addBatch({ "staging and verification events": { topic: function() { @@ -155,13 +156,20 @@ suite.addBatch({ ]; config.set('kpi.send_metrics', true); - var kpiTransport = new KpiTransport(); + var bid = intel.getLogger('bid'); + var handler = _.find(bid._handlers, function(han) { + return han.constructor === KpiHandler; + }); + + if (!handler) { + throw new Error('kpiggybank handler not found on logger'); + } this.expectedEvents.forEach(function(event) { - kpiTransport.log('info', event, null, noOp); + logger.log('info', event); }); - return kpiTransport.getQueue(); + return handler.getQueue(); }, "are added to the KPI queue": function(queue) { var expectedEvents = this.expectedEvents; diff --git a/tests/lib/start-stop.js b/tests/lib/start-stop.js index b62dc7b8a..5ccd99a1a 100644 --- a/tests/lib/start-stop.js +++ b/tests/lib/start-stop.js @@ -45,7 +45,7 @@ function setupProc(proc) { proc.stdout.on('data', function(buf) { buf.toString().split('\n').forEach(function(x) { - if (process.env['LOG_TO_CONSOLE'] || /^.*error.*:/.test(x)) { + if (process.env['LOG_TO_CONSOLE'] || /^.*ERROR.*:/.test(x)) { var line = x.toString().trim(); if (line.length) { console.log(line); diff --git a/tests/metrics-header-test.js b/tests/metrics-header-test.js index ba53d8af5..0438936d2 100755 --- a/tests/metrics-header-test.js +++ b/tests/metrics-header-test.js @@ -5,19 +5,23 @@ * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ require('./lib/test_env.js'); +const path = require('path'); +process.env.METRICS_LOG_FILE = path.resolve(path.join(__dirname, 'data', 'metrics.json')); const assert = require('assert'); const fs = require('fs'); -const path = require('path'); const http = require('http'); const vows = require('vows'); const urlparse = require('urlparse'); -const logger = require('../lib/logging/logging').logger; const start_stop = require('./lib/start-stop'); const wsapi = require('./lib/wsapi'); const config = require('../lib/configuration'); const metrics_middleware = require('../lib/logging/middleware/metrics'); -const KpiTransport = require('../lib/logging/transports/metrics-kpi'); +const KpiHandler = require('../lib/logging/handlers/kpi'); +const intel = require('../lib/logging/logging'); +const _ = require('underscore'); + +const logger = intel.getLogger('bid.test.metrics_header'); var suite = vows.describe('metrics header test'); suite.options.error = false; @@ -25,7 +29,6 @@ suite.options.error = false; // allow this unit test to be targeted var SERVER_URL = process.env['SERVER_URL'] || 'http://127.0.0.1:10002/'; -process.env.METRICS_LOG_FILE = path.resolve(path.join(__dirname, 'data', 'metrics.json')); if (!process.env['SERVER_URL']) { // start up a pristine server if we're locally testing @@ -92,12 +95,19 @@ suite.addBatch({ // Listen for actual messages that are sent to the KPI transport. // reset the transport queue between each test run to ensure we only get the // messages we care about. -var kpiTransport = KpiTransport.getInstance(); +var bid = intel.getLogger('bid'); +var kpiHandler = _.find(bid._handlers, function(han) { + return han.constructor === KpiHandler; +}); + +if (!kpiHandler) { + throw new Error("kpiggybank not found on logger"); +} function noOp() {} function sendRequestToMetricsMiddleware(url, referer) { - kpiTransport.reset(); + kpiHandler.reset(); metrics_middleware({ connection: { @@ -109,7 +119,7 @@ function sendRequestToMetricsMiddleware(url, referer) { 'x-real-ip': '127.0.0.1', 'referer': referer || 'https://sendmypin.org/auth' } - }, noOp, noOp); + }, {}, noOp); } suite.addBatch({ @@ -119,7 +129,7 @@ suite.addBatch({ config.set('kpi.send_metrics', true); sendRequestToMetricsMiddleware('/sign_in', 'https://123done.org'); - return kpiTransport.getItem('signin'); + return kpiHandler.getQueue()[0][0]; }, "sends metrics fields to logger": function (entry) { assert.equal(entry.rp, 'https://123done.org'); @@ -137,7 +147,7 @@ suite.addBatch({ config.set('kpi.send_metrics', true); sendRequestToMetricsMiddleware('/sign_in?AUTH_RETURN'); - return kpiTransport.getItem('idp.auth_return'); + return kpiHandler.getQueue()[0][0]; }, "kpi transport logs metric": function(entry) { assert.equal(entry.idp, 'https://sendmypin.org'); @@ -155,7 +165,7 @@ suite.addBatch({ config.set('kpi.send_metrics', true); sendRequestToMetricsMiddleware('/sign_in?AUTH_RETURN_CANCEL'); - return kpiTransport.getItem('idp.auth_cancel'); + return kpiHandler.getQueue()[0][0]; }, "kpi transport logs metric": function(entry) { assert.equal(entry.idp, 'https://sendmypin.org'); diff --git a/tests/statsd-test.js b/tests/statsd-test.js index 7b1353973..9a3382ac9 100755 --- a/tests/statsd-test.js +++ b/tests/statsd-test.js @@ -8,10 +8,12 @@ const assert = require('assert'); const vows = require('vows'); const start_stop = require('./lib/start-stop'); const config = require('../lib/configuration'); -const StatsdTransport = require('../lib/logging/transports/statsd'); +const StatsdHandler = require('../lib/logging/handlers/statsd'); const StatsdMock = require('./lib/statsd-mock'); const HttpMock = require('./lib/http-mock'); +const logger = require('intel').getLogger('bid.test.statsd'); + require('./lib/test_env'); var suite = vows.describe('statsd'); @@ -21,12 +23,15 @@ suite.options.error = false; start_stop.addStartupBatches(suite); +function withProcess(name) { + return "browserid." + config.get('process_type') + "." + name; +} + var IncrementMessagesToTest = { - "assertion_failure": "browserid.vows.assertion_failure", - "wsapi_code_mismatch.wsapi_url": - "browserid.vows.wsapi_code_mismatch.wsapi_url", - "wsapi.wsapi_url": "browserid.vows.wsapi.wsapi_url", - "uncaught_exception": "browserid.vows.uncaught_exception" + "assertion_failure": withProcess("assertion_failure"), + "wsapi_code_mismatch.wsapi_url": withProcess("wsapi_code_mismatch.wsapi_url"), + "wsapi.wsapi_url": withProcess("wsapi.wsapi_url"), + "uncaught_exception": withProcess("uncaught_exception") }; for (var logMessage in IncrementMessagesToTest) { @@ -35,16 +40,15 @@ for (var logMessage in IncrementMessagesToTest) { batchConfig[logMessage + " - increments"] = { topic: function() { this.statsd = new StatsdMock(); - this.statsdTransport = new StatsdTransport({ + this.statsdTransport = new StatsdHandler({ statsd: this.statsd }); - this.statsdTransport.log('info', logMessage, { + this.statsdTransport.handle(logger.makeRecord(logger._name, logger.INFO, logMessage, [logMessage, { field: "value" - }, this.callback); + }])).done(this.callback); }, - "succeeds": function(err, success) { - assert.isNull(err); - assert.equal(true, success); + "succeeds": function(err) { + assert.ifError(err); }, "and reports to statsd": function() { // the process name is prepended onto the counter name @@ -71,17 +75,16 @@ var TimingMessagesToTest = { for (var logMessage in TimingMessagesToTest) { (function(logMessage, expectedCounterName) { var batchConfig = {}; - batchConfig[logMessage + " - increments"] = { + batchConfig[logMessage + " - times"] = { topic: function() { this.statsd = new StatsdMock(); - this.statsdTransport = new StatsdTransport({ + this.statsdTransport = new StatsdHandler({ statsd: this.statsd }); - this.statsdTransport.log('info', logMessage, 768, this.callback); + this.statsdTransport.handle(logger.makeRecord(logger._name, logger.INFO, logMessage, [logMessage, 768])).done(this.callback); }, - "succeeds": function(err, success) { - assert.isNull(err); - assert.equal(true, success); + "succeeds": function(err) { + assert.ifError(err); }, "and reports to statsd": function() { // the process name is prepended onto the counter name