refactor(logging): decorate request object with metricsContext methods

#1503

r=seanmonstar
This commit is contained in:
Phil Booth 2016-10-16 10:02:36 +01:00 коммит произвёл GitHub
Родитель 230b85ee8f
Коммит 16cf030e91
12 изменённых файлов: 315 добавлений и 217 удалений

Просмотреть файл

@ -13,9 +13,6 @@ var log = require('../lib/log')(config.log.level)
var getGeoData = require('../lib/geodb')(log)
function main() {
var metricsContext = require('../lib/metrics/context')(log, config)
log.setMetricsContext(metricsContext)
// Force the geo to load and run at startup, not waiting for it to run on
// some route later.
var knownIp = '63.245.221.32' // Mozilla MTV
@ -108,8 +105,7 @@ function main() {
mailer,
Password,
config,
customs,
metricsContext
customs
)
server = Server.create(log, error, config, routes, db)

Просмотреть файл

@ -64,15 +64,6 @@ Lug.prototype.close = function() {
return this.statsd.close()
}
// Certain events can include contextual metrics data
// such as utm_* tracking parameters. This helper method
// is here to work around a circular dependency between
// this module and the `metricsContext` module.
Lug.prototype.setMetricsContext = function (metricsContext) {
this.metricsContext = metricsContext
}
// Expose the standard error/warn/info/debug/etc log methods.
Lug.prototype.trace = function (data) {
@ -176,16 +167,15 @@ Lug.prototype.summary = function (request, response) {
// and broadcast to relying services over SNS/SQS.
Lug.prototype.notifyAttachedServices = function (name, request, data) {
var self = this
return this.metricsContext.gather({}, request)
return request.gatherMetricsContext({})
.then(
function (metricsContextData) {
metricsContextData => {
var e = {
event: name,
data: unbuffer(data)
}
e.data.metricsContext = metricsContextData
self.stdout.write(JSON.stringify(e) + '\n')
this.stdout.write(JSON.stringify(e) + '\n')
}
)
}
@ -229,8 +219,6 @@ Lug.prototype.activityEvent = function (event, request, data) {
// These events help understand the user's sign-in or sign-up journey.
Lug.prototype.flowEvent = function (event, request) {
var self = this
if (! event) {
this.error({ op: 'log.flowEvent', missingEvent: true })
return P.resolve()
@ -247,18 +235,18 @@ Lug.prototype.flowEvent = function (event, request) {
return P.resolve()
}
return this.metricsContext.gather({
return request.gatherMetricsContext({
event: event,
userAgent: request.headers['user-agent']
}, request).then(
function (info) {
}).then(
info => {
if (info.flow_id) {
info.event = event
optionallySetService(info, request)
self.logger.info('flowEvent', info)
this.logger.info('flowEvent', info)
} else if (ALWAYS_ACTIVITY_FLOW_EVENTS[event]) {
self.error({ op: 'log.flowEvent', event: event, missingFlowId: true })
this.error({ op: 'log.flowEvent', event: event, missingFlowId: true })
}
}
)

Просмотреть файл

@ -42,7 +42,6 @@ module.exports = function (log, config) {
let _memcached
return {
schema: SCHEMA,
stash: stash,
gather: gather,
validate: validate
@ -52,10 +51,13 @@ module.exports = function (log, config) {
* Stashes metrics context metadata using a key derived from a token.
* Asynchronous, returns a promise.
*
* @name stashMetricsContext
* @this request
* @param token token to stash the metadata against
* @param metadata metrics context metadata
*/
function stash (token, metadata) {
function stash (token) {
const metadata = this.payload && this.payload.metricsContext
if (! metadata) {
return P.resolve()
}
@ -92,18 +94,18 @@ module.exports = function (log, config) {
/**
* Gathers metrics context metadata onto data, using either metadata
* passed in from a request or previously-stashed metadata for a
* token. Asynchronous, returns a promise that resolves to data,
* with metrics context metadata copied to it.
* passed in with a request or previously-stashed metadata for a
* token. Asynchronous, returns a promise that resolves to data, with
* metrics context metadata copied to it.
*
* @name gatherMetricsContext
* @this request
* @param data target object
* @param request request object
*/
function gather (data, request) {
const metadata = request.payload && request.payload.metricsContext
const token = request.auth && request.auth.credentials
const doNotTrack = request.headers && request.headers.dnt === '1'
const memcached = getMemcached()
function gather (data) {
const metadata = this.payload && this.payload.metricsContext
const doNotTrack = this.headers && this.headers.dnt === '1'
let token
return P.resolve()
.then(() => {
@ -111,7 +113,9 @@ module.exports = function (log, config) {
return metadata
}
return memcached.getAsync(getKey(token))
token = getToken(this)
return getMemcached().getAsync(getKey(token))
})
.then(metadata => {
if (metadata) {
@ -136,28 +140,44 @@ module.exports = function (log, config) {
.then(() => data)
}
function getToken (request) {
if (request.auth && request.auth.credentials) {
return request.auth.credentials
}
if (request.payload && request.payload.uid && request.payload.code) {
return {
uid: Buffer(request.payload.uid, 'hex'),
id: request.payload.code
}
}
throw new Error('Invalid credentials')
}
/**
* Checks whether a request's flowId and flowBeginTime are valid.
* Returns a boolean, `true` if the request is valid, `false` if
* it's invalid.
*
* @param request object
* @name validateMetricsContext
* @this request
*/
function validate(request) {
const metadata = request.payload.metricsContext
function validate() {
const metadata = this.payload.metricsContext
if (!metadata) {
return logInvalidContext(request, 'missing context')
return logInvalidContext(this, 'missing context')
}
if (!metadata.flowId) {
return logInvalidContext(request, 'missing flowId')
return logInvalidContext(this, 'missing flowId')
}
if (!metadata.flowBeginTime) {
return logInvalidContext(request, 'missing flowBeginTime')
return logInvalidContext(this, 'missing flowBeginTime')
}
if (Date.now() - metadata.flowBeginTime > config.metrics.flow_id_expiry) {
return logInvalidContext(request, 'expired flowBeginTime')
return logInvalidContext(this, 'expired flowBeginTime')
}
// The first half of the id is random bytes, the second half is a HMAC of
@ -166,15 +186,15 @@ module.exports = function (log, config) {
// share state between content-server and auth-server.
const flowSignature = metadata.flowId.substr(FLOW_ID_LENGTH / 2, FLOW_ID_LENGTH)
const flowSignatureBytes = new Buffer(flowSignature, 'hex')
const expectedSignatureBytes = calculateFlowSignatureBytes(request, metadata)
const expectedSignatureBytes = calculateFlowSignatureBytes(this, metadata)
if (! bufferEqualConstantTime(flowSignatureBytes, expectedSignatureBytes)) {
return logInvalidContext(request, 'invalid signature')
return logInvalidContext(this, 'invalid signature')
}
log.info({
op: 'metrics.context.validate',
valid: true,
agent: request.headers['user-agent']
agent: this.headers['user-agent']
})
log.increment('metrics.context.valid')
return true
@ -231,3 +251,6 @@ function calculateFlowTime (time, flowBeginTime) {
return time - flowBeginTime
}
module.exports.schema = SCHEMA

Просмотреть файл

@ -27,6 +27,8 @@ var butil = require('../crypto/butil')
var userAgent = require('../userAgent')
var requestHelper = require('../routes/utils/request_helper')
const METRICS_CONTEXT_SCHEMA = require('../metrics/context').schema
module.exports = function (
log,
crypto,
@ -42,7 +44,6 @@ module.exports = function (
isPreVerified,
checkPassword,
push,
metricsContext,
devices
) {
@ -77,7 +78,7 @@ module.exports = function (
redirectTo: validators.redirectTo(config.smtp.redirectDomain).optional(),
resume: isA.string().max(2048).optional(),
preVerifyToken: isA.string().max(2048).regex(BASE64_JWT).optional(),
metricsContext: metricsContext.schema
metricsContext: METRICS_CONTEXT_SCHEMA
}
},
response: {
@ -104,7 +105,7 @@ module.exports = function (
var tokenVerificationId = emailCode
var preVerified, password, verifyHash, account, sessionToken, keyFetchToken
metricsContext.validate(request)
request.validateMetricsContext()
customs.check(request, email, 'accountCreate')
.then(db.emailRecord.bind(db, email))
@ -239,17 +240,17 @@ module.exports = function (
.then(
function (result) {
sessionToken = result
return metricsContext.stash(sessionToken, form.metricsContext)
return request.stashMetricsContext(sessionToken)
}
)
.then(
function () {
// There is no session token when we emit account.verified
// so stash the data against a synthesized "token" instead.
return metricsContext.stash({
return request.stashMetricsContext({
uid: account.uid,
id: account.emailCode.toString('hex')
}, form.metricsContext)
})
}
)
}
@ -312,7 +313,7 @@ module.exports = function (
.then(
function (result) {
keyFetchToken = result
return metricsContext.stash(keyFetchToken, form.metricsContext)
return request.stashMetricsContext(keyFetchToken)
}
)
}
@ -360,7 +361,7 @@ module.exports = function (
resume: isA.string().optional(),
reason: isA.string().max(16).optional(),
unblockCode: isA.string().regex(BASE_36).length(unblockCodeLen).optional(),
metricsContext: metricsContext.schema
metricsContext: METRICS_CONTEXT_SCHEMA
}
},
response: {
@ -389,7 +390,7 @@ module.exports = function (
var emailRecord, sessions, sessionToken, keyFetchToken, mustVerifySession, doSigninConfirmation, emailSent, unblockCode, customsErr, allowSigninUnblock, didSigninUnblock
var ip = request.app.clientAddress
metricsContext.validate(request)
request.validateMetricsContext()
// Monitor for any clients still sending obsolete 'contentToken' param.
if (request.payload.contentToken) {
@ -639,7 +640,7 @@ module.exports = function (
.then(
function (result) {
sessionToken = result
return metricsContext.stash(sessionToken, form.metricsContext)
return request.stashMetricsContext(sessionToken)
}
)
.then(
@ -647,10 +648,10 @@ module.exports = function (
if (doSigninConfirmation) {
// There is no session token when we emit account.confirmed
// so stash the data against a synthesized "token" instead.
return metricsContext.stash({
return request.stashMetricsContext({
uid: emailRecord.uid,
id: tokenVerificationId.toString('hex')
}, form.metricsContext)
})
}
}
)
@ -677,7 +678,7 @@ module.exports = function (
.then(
function (result) {
keyFetchToken = result
return metricsContext.stash(keyFetchToken, form.metricsContext)
return request.stashMetricsContext(keyFetchToken)
}
)
}
@ -1454,22 +1455,6 @@ module.exports = function (
var service = request.payload.service || request.query.service
var reminder = request.payload.reminder || request.query.reminder
// Because we have no session token on this endpoint, metrics context
// metadata was stashed against a synthesized token for the benefit of
// the activity events. This fake request object allows the correct
// metadata to be gathered when we emit the events.
var fakeRequestObject = {
auth: {
credentials: {
uid: uid,
id: request.payload.code
}
},
headers: request.headers,
payload: request.payload,
query: request.query
}
log.begin('Account.RecoveryEmailVerify', request)
db.account(uid)
.then(
@ -1508,7 +1493,7 @@ module.exports = function (
uid: uidHex,
code: request.payload.code
})
log.activityEvent('account.confirmed', fakeRequestObject, {
log.activityEvent('account.confirmed', request, {
uid: uidHex
})
push.notifyUpdate(uid, 'accountConfirm')
@ -1544,14 +1529,14 @@ module.exports = function (
.then(function () {
log.timing('account.verified', Date.now() - account.createdAt)
log.increment('account.verified')
return log.notifyAttachedServices('verified', fakeRequestObject, {
return log.notifyAttachedServices('verified', request, {
email: account.email,
uid: account.uid,
locale: account.locale
})
})
.then(function () {
return log.activityEvent('account.verified', fakeRequestObject, {
return log.activityEvent('account.verified', request, {
uid: uidHex
})
})
@ -1627,7 +1612,7 @@ module.exports = function (
validate: {
payload: {
email: validators.email().required(),
metricsContext: metricsContext.schema
metricsContext: METRICS_CONTEXT_SCHEMA
}
}
},

Просмотреть файл

@ -18,8 +18,7 @@ module.exports = function (
mailer,
Password,
config,
customs,
metricsContext
customs
) {
var isPreVerified = require('../preverifier')(error, config)
var defaults = require('./defaults')(log, P, db, error)
@ -42,7 +41,6 @@ module.exports = function (
isPreVerified,
checkPassword,
push,
metricsContext,
devices
)
var password = require('./password')(
@ -56,8 +54,7 @@ module.exports = function (
config.verifierVersion,
customs,
checkPassword,
push,
metricsContext
push
)
var session = require('./session')(log, isA, error, db)
var sign = require('./sign')(log, P, isA, error, signer, db, config.domain, devices)

Просмотреть файл

@ -10,6 +10,8 @@ var butil = require('../crypto/butil')
var P = require('../promise')
var requestHelper = require('../routes/utils/request_helper')
const METRICS_CONTEXT_SCHEMA = require('../metrics/context').schema
module.exports = function (
log,
isA,
@ -21,8 +23,7 @@ module.exports = function (
verifierVersion,
customs,
checkPassword,
push,
metricsContext
push
) {
function failVerifyAttempt(passwordForgotToken) {
@ -304,7 +305,7 @@ module.exports = function (
service: isA.string().max(16).alphanum().optional(),
redirectTo: validators.redirectTo(redirectDomain).optional(),
resume: isA.string().max(2048).optional(),
metricsContext: metricsContext.schema
metricsContext: METRICS_CONTEXT_SCHEMA
}
},
response: {
@ -380,7 +381,7 @@ module.exports = function (
service: isA.string().max(16).alphanum().optional(),
redirectTo: validators.redirectTo(redirectDomain).optional(),
resume: isA.string().max(2048).optional(),
metricsContext: metricsContext.schema
metricsContext: METRICS_CONTEXT_SCHEMA
}
},
response: {
@ -438,7 +439,7 @@ module.exports = function (
validate: {
payload: {
code: isA.string().min(32).max(32).regex(HEX_STRING).required(),
metricsContext: metricsContext.schema
metricsContext: METRICS_CONTEXT_SCHEMA
}
},
response: {

Просмотреть файл

@ -296,6 +296,12 @@ function create(log, error, config, routes, db) {
}
)
const metricsContext = require('./metrics/context')(log, config)
server.decorate('request', 'stashMetricsContext', metricsContext.stash)
server.decorate('request', 'gatherMetricsContext', metricsContext.gather)
server.decorate('request', 'validateMetricsContext', metricsContext.validate)
server.stat = function() {
return {
stat: 'mem',

Просмотреть файл

@ -49,7 +49,6 @@ var makeRoutes = function (options, requireMocks) {
}
var checkPassword = options.checkPassword || require('../../lib/routes/utils/password_check')(log, config, Password, customs, db)
var push = options.push || require('../../lib/push')(log, db, {})
var metricsContext = options.metricsContext || log.metricsContext || require('../../lib/metrics/context')(log, config)
return proxyquire('../../lib/routes/account', requireMocks || {})(
log,
crypto,
@ -65,7 +64,6 @@ var makeRoutes = function (options, requireMocks) {
isPreVerified,
checkPassword,
push,
metricsContext,
options.devices || require('../../lib/devices')(log, db, push)
)
}
@ -566,7 +564,13 @@ test('/account/device/destroy', function (t) {
})
test('/account/create', function (t) {
var mockMetricsContext = mocks.mockMetricsContext({
gather: sinon.spy(function (data) {
return P.resolve(this.payload && this.payload.metricsContext)
})
})
var mockRequest = mocks.mockRequest({
metricsContext: mockMetricsContext,
payload: {
email: TEST_EMAIL,
authPW: crypto.randomBytes(32).toString('hex'),
@ -609,12 +613,6 @@ test('/account/create', function (t) {
write: sinon.spy()
}
})
var mockMetricsContext = mocks.mockMetricsContext({
gather: sinon.spy(function (data, request) {
return P.resolve(request.payload.metricsContext)
})
})
mockLog.setMetricsContext(mockMetricsContext)
mockLog.activityEvent = sinon.spy(function () {
return P.resolve()
})
@ -629,7 +627,6 @@ test('/account/create', function (t) {
db: mockDB,
log: mockLog,
mailer: mockMailer,
metricsContext: mockMetricsContext,
Password: function () {
return {
unwrap: function () {
@ -662,29 +659,27 @@ test('/account/create', function (t) {
t.deepEqual(args[2], { uid: uid.toString('hex') }, 'third argument contained uid')
t.equal(mockMetricsContext.validate.callCount, 1, 'metricsContext.validate was called')
args = mockMetricsContext.validate.args[0]
t.equal(args.length, 1, 'validate was called with a single argument')
t.deepEqual(args[0], mockRequest, 'validate was called with the request')
t.equal(mockMetricsContext.validate.args[0].length, 0, 'validate was called without arguments')
t.equal(mockMetricsContext.stash.callCount, 3, 'metricsContext.stash was called three times')
args = mockMetricsContext.stash.args[0]
t.equal(args.length, 2, 'metricsContext.stash was passed two arguments first time')
t.deepEqual(args[0].tokenId, sessionTokenId, 'first argument was session token')
t.equal(args.length, 1, 'metricsContext.stash was passed one argument first time')
t.deepEqual(args[0].tokenId, sessionTokenId, 'argument was session token')
t.deepEqual(args[0].uid, uid, 'sessionToken.uid was correct')
t.equal(args[1], mockRequest.payload.metricsContext, 'second argument was metrics context')
t.equal(mockMetricsContext.stash.thisValues[0], mockRequest, 'this was request')
args = mockMetricsContext.stash.args[1]
t.equal(args.length, 2, 'metricsContext.stash was passed two arguments second time')
t.equal(args[0].id, emailCode.toString('hex'), 'first argument was synthesized token')
t.equal(args.length, 1, 'metricsContext.stash was passed one argument second time')
t.equal(args[0].id, emailCode.toString('hex'), 'argument was synthesized token')
t.deepEqual(args[0].uid, uid, 'token.uid was correct')
t.equal(args[1], mockRequest.payload.metricsContext, 'second argument was metrics context')
t.equal(mockMetricsContext.stash.thisValues[1], mockRequest, 'this was request')
args = mockMetricsContext.stash.args[2]
t.equal(args.length, 2, 'metricsContext.stash was passed two arguments third time')
t.deepEqual(args[0].tokenId, keyFetchTokenId, 'first argument was key fetch token')
t.equal(args.length, 1, 'metricsContext.stash was passed one argument third time')
t.deepEqual(args[0].tokenId, keyFetchTokenId, 'argument was key fetch token')
t.deepEqual(args[0].uid, uid, 'keyFetchToken.uid was correct')
t.equal(args[1], mockRequest.payload.metricsContext, 'second argument was metrics context')
t.equal(mockMetricsContext.stash.thisValues[2], mockRequest, 'this was request')
var securityEvent = mockDB.securityEvent
t.equal(securityEvent.callCount, 1, 'db.securityEvent is called')
@ -711,10 +706,13 @@ test('/account/login', function (t) {
enabled: true
}
}
var mockMetricsContext = mocks.mockMetricsContext({
gather: sinon.spy(function (data) {
return P.resolve(this.payload && this.payload.metricsContext)
})
})
var mockRequest = mocks.mockRequest({
query: {
keys: 'true'
},
metricsContext: mockMetricsContext,
payload: {
authPW: crypto.randomBytes(32).toString('hex'),
email: TEST_EMAIL,
@ -727,10 +725,13 @@ test('/account/login', function (t) {
entrypoint: 'preferences',
utmContent: 'some-content-string'
}
},
query: {
keys: 'true'
}
})
var mockRequestNoKeys = mocks.mockRequest({
query: {},
metricsContext: mockMetricsContext,
payload: {
authPW: crypto.randomBytes(32).toString('hex'),
email: 'test@mozilla.com',
@ -741,7 +742,8 @@ test('/account/login', function (t) {
flowId: 'F1031DF1031DF1031DF1031DF1031DF1031DF1031DF1031DF1031DF1031DF103',
service: 'dcdb5ae7add825d2'
}
}
},
query: {}
})
var mockRequestWithUnblockCode = mocks.mockRequest({
query: {},
@ -779,12 +781,6 @@ test('/account/login', function (t) {
write: sinon.spy()
}
})
var mockMetricsContext = mocks.mockMetricsContext({
gather: sinon.spy(function (data, request) {
return P.resolve(request.payload.metricsContext)
})
})
mockLog.setMetricsContext(mockMetricsContext)
mockLog.activityEvent = sinon.spy(function () {
return P.resolve()
})
@ -802,7 +798,6 @@ test('/account/login', function (t) {
db: mockDB,
log: mockLog,
mailer: mockMailer,
metricsContext: mockMetricsContext,
push: mockPush
})
var route = getRoute(accountRoutes, '/account/login')
@ -833,23 +828,21 @@ test('/account/login', function (t) {
t.deepEqual(args[2], {uid: uid.toString('hex')}, 'third argument contained uid')
t.equal(mockMetricsContext.validate.callCount, 1, 'metricsContext.validate was called')
args = mockMetricsContext.validate.args[0]
t.equal(args.length, 1, 'validate was called with a single argument')
t.deepEqual(args[0], mockRequest, 'validate was called with the request')
t.equal(mockMetricsContext.validate.args[0].length, 0, 'validate was called without arguments')
t.equal(mockMetricsContext.stash.callCount, 2, 'metricsContext.stash was called twice')
args = mockMetricsContext.stash.args[0]
t.equal(args.length, 2, 'metricsContext.stash was passed two arguments first time')
t.deepEqual(args[0].tokenId, sessionTokenId, 'first argument was session token')
t.equal(args.length, 1, 'metricsContext.stash was passed one argument first time')
t.deepEqual(args[0].tokenId, sessionTokenId, 'argument was session token')
t.deepEqual(args[0].uid, uid, 'sessionToken.uid was correct')
t.equal(args[1], mockRequest.payload.metricsContext, 'second argument was metrics context')
t.equal(mockMetricsContext.stash.thisValues[0], mockRequest, 'this was request')
args = mockMetricsContext.stash.args[1]
t.equal(args.length, 2, 'metricsContext.stash was passed two arguments second time')
t.deepEqual(args[0].tokenId, keyFetchTokenId, 'first argument was key fetch token')
t.equal(args.length, 1, 'metricsContext.stash was passed one argument second time')
t.deepEqual(args[0].tokenId, keyFetchTokenId, 'argument was key fetch token')
t.deepEqual(args[0].uid, uid, 'keyFetchToken.uid was correct')
t.equal(args[1], mockRequest.payload.metricsContext, 'second argument was metrics context')
t.equal(mockMetricsContext.stash.thisValues[1], mockRequest, 'this was request')
t.equal(mockMailer.sendNewDeviceLoginNotification.callCount, 1, 'mailer.sendNewDeviceLoginNotification was called')
t.equal(mockMailer.sendNewDeviceLoginNotification.getCall(0).args[1].location.city, 'Mountain View')
@ -944,10 +937,10 @@ test('/account/login', function (t) {
t.equal(mockMetricsContext.stash.callCount, 3, 'metricsContext.stash was called three times')
var args = mockMetricsContext.stash.args[1]
t.equal(args.length, 2, 'metricsContext.stash was passed two arguments second time')
t.ok(/^[0-9a-f]{32}$/.test(args[0].id), 'first argument was synthesized token')
t.equal(args.length, 1, 'metricsContext.stash was passed one argument second time')
t.ok(/^[0-9a-f]{32}$/.test(args[0].id), 'argument was synthesized token')
t.deepEqual(args[0].uid, uid, 'token.uid was correct')
t.equal(args[1], mockRequest.payload.metricsContext, 'second argument was metrics context')
t.equal(mockMetricsContext.stash.thisValues[1], mockRequest, 'this was request')
t.equal(mockMailer.sendVerifyLoginEmail.callCount, 1, 'mailer.sendVerifyLoginEmail was called')
t.equal(mockMailer.sendVerifyLoginEmail.getCall(0).args[2].location.city, 'Mountain View')
@ -1453,17 +1446,7 @@ test('/recovery_email/verify_code', function (t) {
var args = mockLog.activityEvent.args[0]
t.equal(args.length, 3, 'activityEvent was passed three arguments')
t.equal(args[0], 'account.verified', 'first argument was event name')
t.deepEqual(args[1], {
auth: {
credentials: {
uid: Buffer(uid, 'hex'),
id: mockRequest.payload.code,
}
},
headers: mockRequest.headers,
payload: mockRequest.payload,
query: mockRequest.query
}, 'second argument was synthesized request object')
t.equal(args[1], mockRequest, 'second argument was request object')
t.deepEqual(args[2], { uid: uid }, 'third argument contained uid')
t.equal(mockPush.notifyUpdate.callCount, 1, 'mockPush.notifyUpdate should have been called once')
@ -1545,17 +1528,7 @@ test('/recovery_email/verify_code', function (t) {
var args = mockLog.activityEvent.args[0]
t.equal(args.length, 3, 'log.activityEvent was passed three arguments')
t.equal(args[0], 'account.confirmed', 'first argument was event name')
t.deepEqual(args[1], {
auth: {
credentials: {
uid: Buffer(uid, 'hex'),
id: mockRequest.payload.code,
}
},
headers: mockRequest.headers,
payload: mockRequest.payload,
query: mockRequest.query
}, 'second argument was synthesized request object')
t.equal(args[1], mockRequest, 'second argument was request object')
t.deepEqual(args[2], { uid: uid }, 'third argument contained uid')
t.equal(mockPush.notifyUpdate.callCount, 1, 'mockPush.notifyUpdate should have been called once')

Просмотреть файл

@ -19,10 +19,10 @@ var statsd = {
write: sinon.spy()
}
var metricsContext = {
gather: sinon.spy(function (data, request) {
return P.resolve(request.payload && {
flow_id: request.payload.metricsContext.flowId,
service: request.payload.metricsContext.service
gather: sinon.spy(function (data) {
return P.resolve(this.payload && {
flow_id: this.payload.metricsContext.flowId,
service: this.payload.metricsContext.service
})
})
}
@ -36,7 +36,6 @@ mocks['./metrics/statsd'] = function () {
return statsd
}
var log = proxyquire('../../lib/log', mocks)('foo', 'bar')
log.setMetricsContext(metricsContext)
test(
'initialised correctly',
@ -85,6 +84,7 @@ test(
'log.activityEvent',
function (t) {
var request = {
gatherMetricsContext: metricsContext.gather,
headers: {
'user-agent': 'foo'
},
@ -126,6 +126,7 @@ test(
'log.activityEvent with flow event',
function (t) {
var request = {
gatherMetricsContext: metricsContext.gather,
headers: {
'user-agent': 'foo'
},
@ -140,13 +141,13 @@ test(
}).then(function () {
t.equal(metricsContext.gather.callCount, 1, 'metricsContext.gather was called once')
var args = metricsContext.gather.args[0]
t.equal(args.length, 2, 'metricsContext.gather was passed two arguments')
t.equal(typeof args[0], 'object', 'first argument was object')
t.notEqual(args[0], null, 'first argument was not null')
t.equal(Object.keys(args[0]).length, 2, 'first argument had two properties')
t.equal(args.length, 1, 'metricsContext.gather was passed one argument')
t.equal(typeof args[0], 'object', 'argument was object')
t.notEqual(args[0], null, 'argument was not null')
t.equal(Object.keys(args[0]).length, 2, 'argument had two properties')
t.equal(args[0].event, 'account.created', 'event property was correct')
t.equal(args[0].userAgent, 'foo', 'userAgent property was correct')
t.equal(args[1], request, 'second argument was request object')
t.equal(metricsContext.gather.thisValues[0], request, 'this was request object')
t.equal(logger.info.callCount, 2, 'logger.info was called twice')
t.equal(logger.info.args[0][0], 'activityEvent', 'first call was activityEvent')
@ -171,6 +172,7 @@ test(
'log.activityEvent with flow event and missing flowId',
function (t) {
var request = {
gatherMetricsContext: metricsContext.gather,
headers: {
'user-agent': 'foo'
},
@ -214,6 +216,7 @@ test(
'log.activityEvent with optional flow event and missing flowId',
function (t) {
var request = {
gatherMetricsContext: metricsContext.gather,
headers: {
'user-agent': 'foo'
},
@ -249,6 +252,7 @@ test(
'log.activityEvent with service payload parameter',
function (t) {
return log.activityEvent('wibble', {
gatherMetricsContext: metricsContext.gather,
headers: {},
payload: {
metricsContext: {},
@ -267,6 +271,7 @@ test(
t.equal(statsd.write.callCount, 1, 'statsd.write was called once')
t.equal(statsd.write.args[0][0], args[1], 'statsd.write argument was correct')
t.equal(metricsContext.gather.callCount, 0, 'metricsContext.gather was not called')
t.equal(logger.debug.callCount, 0, 'logger.debug was not called')
t.equal(logger.error.callCount, 0, 'logger.error was not called')
t.equal(logger.critical.callCount, 0, 'logger.critical was not called')
@ -282,6 +287,7 @@ test(
'log.activityEvent with service query parameter',
function (t) {
return log.activityEvent('foo', {
gatherMetricsContext: metricsContext.gather,
headers: {},
payload: {
metricsContext: {}
@ -298,6 +304,7 @@ test(
t.equal(statsd.write.callCount, 1, 'statsd.write was called once')
t.equal(statsd.write.args[0][0], logger.info.args[0][1], 'statsd.write argument was correct')
t.equal(metricsContext.gather.callCount, 0, 'metricsContext.gather was not called')
t.equal(logger.debug.callCount, 0, 'logger.debug was not called')
t.equal(logger.error.callCount, 0, 'logger.error was not called')
t.equal(logger.critical.callCount, 0, 'logger.critical was not called')
@ -313,6 +320,7 @@ test(
'log.activityEvent with extra data',
function (t) {
return log.activityEvent('foo', {
gatherMetricsContext: metricsContext.gather,
headers: {
'user-agent': 'bar'
},
@ -333,6 +341,7 @@ test(
t.equal(statsd.write.callCount, 1, 'statsd.write was called once')
t.equal(statsd.write.args[0][0], args[1], 'statsd.write argument was correct')
t.equal(metricsContext.gather.callCount, 0, 'metricsContext.gather was not called')
t.equal(logger.debug.callCount, 0, 'logger.debug was not called')
t.equal(logger.error.callCount, 0, 'logger.error was not called')
t.equal(logger.critical.callCount, 0, 'logger.critical was not called')
@ -348,6 +357,7 @@ test(
'log.activityEvent with no data',
function (t) {
return log.activityEvent('foo', {
gatherMetricsContext: metricsContext.gather,
headers: {},
payload: {
metricsContext: {}
@ -376,6 +386,7 @@ test(
'log.activityEvent with no uid',
function (t) {
return log.activityEvent('foo', {
gatherMetricsContext: metricsContext.gather,
headers: {},
payload: {
metricsContext: {}
@ -403,7 +414,18 @@ test(
test(
'log.flowEvent with bad event name',
t => {
return log.flowEvent(undefined).then(() => {
return log.flowEvent(undefined, {
gatherMetricsContext: metricsContext.gather,
headers: {
'user-agent': 'foo'
},
payload: {
metricsContext: {
flowId: 'bar',
service: 'baz'
}
}
}).then(() => {
t.equal(logger.error.callCount, 1, 'logger.error was called once')
const args = logger.error.args[0]
t.equal(args[0], 'log.flowEvent', 'correct op')
@ -423,7 +445,15 @@ test(
test(
'log.flowEvent with a bad request',
t => {
return log.flowEvent('account.signed').then(() => {
return log.flowEvent('account.signed', {
gatherMetricsContext: metricsContext.gather,
payload: {
metricsContext: {
flowId: 'foo',
service: 'bar'
}
}
}).then(() => {
t.equal(logger.error.callCount, 1, 'logger.error was called once')
const args = logger.error.args[0]
t.equal(args[0], 'log.flowEvent', 'correct op')
@ -445,6 +475,7 @@ test(
'log.flowEvent with content server account.signed event',
t => {
return log.flowEvent('account.signed', {
gatherMetricsContext: metricsContext.gather,
headers: {
'user-agent': 'foo'
},
@ -473,6 +504,7 @@ test(
'log.flowEvent properly logs with no errors',
t => {
return log.flowEvent('account.signed', {
gatherMetricsContext: metricsContext.gather,
headers: {
'user-agent': 'foo'
},
@ -508,6 +540,7 @@ test(
'log.flowEvent with flow event and missing flowId',
t => {
return log.flowEvent('account.login', {
gatherMetricsContext: metricsContext.gather,
headers: {
'user-agent': 'foo'
},
@ -539,6 +572,7 @@ test(
'log.flowEvent with optional flow event and missing flowId',
t => {
return log.flowEvent('account.keyfetch', {
gatherMetricsContext: metricsContext.gather,
headers: {
'user-agent': 'foo'
},

Просмотреть файл

@ -10,7 +10,8 @@ const test = require('../ptaptest')
const mocks = require('../mocks')
const log = mocks.spyLog()
const Memcached = require('memcached')
const metricsContext = require('../../lib/metrics/context')(log, {
const metricsContextModule = require('../../lib/metrics/context')
const metricsContext = metricsContextModule(log, {
memcached: {
address: '127.0.0.1:1121',
idle: 500,
@ -22,21 +23,22 @@ const P = require('../../lib/promise')
test(
'metricsContext interface is correct',
function (t) {
t.equal(typeof metricsContextModule, 'function', 'function is exported')
t.equal(typeof metricsContextModule.schema, 'object', 'metricsContext.schema is object')
t.notEqual(metricsContextModule.schema, null, 'metricsContext.schema is not null')
t.equal(typeof metricsContext, 'object', 'metricsContext is object')
t.notEqual(metricsContext, null, 'metricsContext is not null')
t.equal(Object.keys(metricsContext).length, 4, 'metricsContext has 4 properties')
t.equal(typeof metricsContext.schema, 'object', 'metricsContext.schema is object')
t.notEqual(metricsContext.schema, null, 'metricsContext.schema is not null')
t.equal(Object.keys(metricsContext).length, 3, 'metricsContext has 3 properties')
t.equal(typeof metricsContext.stash, 'function', 'metricsContext.stash is function')
t.equal(metricsContext.stash.length, 2, 'metricsContext.stash expects 2 arguments')
t.equal(metricsContext.stash.length, 1, 'metricsContext.stash expects 1 argument')
t.equal(typeof metricsContext.gather, 'function', 'metricsContext.gather is function')
t.equal(metricsContext.gather.length, 2, 'metricsContext.gather expects 2 arguments')
t.equal(metricsContext.gather.length, 1, 'metricsContext.gather expects 1 argument')
t.equal(typeof metricsContext.validate, 'function', 'metricsContext.validate is function')
t.equal(metricsContext.validate.length, 1, 'metricsContext.validate expects 1 argument')
t.equal(metricsContext.validate.length, 0, 'metricsContext.validate expects no arguments')
t.end()
}
@ -53,10 +55,14 @@ test(
sinon.stub(Memcached.prototype, 'setAsync', function () {
return P.resolve('wibble')
})
metricsContext.stash({
metricsContext.stash.call({
payload: {
metricsContext: 'bar'
}
}, {
uid: uid,
id: id
}, 'bar').then(function (result) {
}).then(result => {
t.equal(result, 'wibble', 'result is correct')
t.equal(Memcached.prototype.setAsync.callCount, 1, 'memcached.setAsync was called once')
@ -80,10 +86,14 @@ test(
sinon.stub(Memcached.prototype, 'setAsync', function () {
return P.reject('wibble')
})
metricsContext.stash({
metricsContext.stash.call({
payload: {
metricsContext: 'bar'
}
}, {
uid: Buffer.alloc(32, 'cd'),
id: 'foo'
}, 'bar').then(function (result) {
}).then(result => {
t.equal(result, undefined, 'result is undefined')
t.equal(Memcached.prototype.setAsync.callCount, 1, 'memcached.setAsync was called once')
@ -102,14 +112,18 @@ test(
)
test(
'metricsContext.stash without token',
'metricsContext.stash with bad token',
function (t) {
sinon.stub(Memcached.prototype, 'setAsync', function () {
return P.resolve('wibble')
})
metricsContext.stash({
metricsContext.stash.call({
payload: {
metricsContext: 'bar'
}
}, {
id: 'foo'
}, 'bar').then(function (result) {
}).then(result => {
t.equal(result, undefined, 'result is undefined')
t.equal(log.error.callCount, 1, 'log.error was called once')
@ -134,10 +148,12 @@ test(
sinon.stub(Memcached.prototype, 'setAsync', function () {
return P.resolve('wibble')
})
metricsContext.stash({
metricsContext.stash.call({
payload: {}
}, {
uid: Buffer.alloc(32, 'cd'),
id: 'foo'
}).then(function (result) {
}).then(result => {
t.equal(result, undefined, 'result is undefined')
t.equal(Memcached.prototype.setAsync.callCount, 0, 'memcached.setAsync was not called')
@ -160,7 +176,7 @@ test(
})
})
var time = Date.now() - 1
metricsContext.gather({}, {
metricsContext.gather.call({
payload: {
metricsContext: {
flowId: 'mock flow id',
@ -177,7 +193,7 @@ test(
ignore: 'mock ignorable property'
}
}
}).then(function (result) {
}, {}).then(function (result) {
t.equal(typeof result, 'object', 'result is object')
t.notEqual(result, null, 'result is not null')
t.equal(Object.keys(result).length, 12, 'result has 12 properties')
@ -208,13 +224,13 @@ test(
test(
'metricsContext.gather with bad flowBeginTime',
function (t) {
metricsContext.gather({}, {
metricsContext.gather.call({
payload: {
metricsContext: {
flowBeginTime: Date.now() + 10000
}
}
}).then(function (result) {
}, {}).then(function (result) {
t.equal(typeof result, 'object', 'result is object')
t.notEqual(result, null, 'result is not null')
t.strictEqual(result.flow_time, 0, 'result.time is zero')
@ -230,7 +246,7 @@ test(
'metricsContext.gather with DNT header',
function (t) {
var time = Date.now() - 1
metricsContext.gather({}, {
metricsContext.gather.call({
headers: {
dnt: '1'
},
@ -250,7 +266,7 @@ test(
ignore: 'mock ignorable property'
}
}
}).then(function (result) {
}, {}).then(function (result) {
t.equal(Object.keys(result).length, 7, 'result has 7 properties')
t.equal(result.utm_campaign, undefined, 'result.utm_campaign is undefined')
t.equal(result.utm_content, undefined, 'result.utm_content is undefined')
@ -290,14 +306,14 @@ test(
ignore: 'ignore me'
})
})
metricsContext.gather({}, {
metricsContext.gather.call({
auth: {
credentials: {
uid: uid,
id: id
}
}
}).then(function (result) {
}, {}).then(function (result) {
t.equal(Memcached.prototype.getAsync.callCount, 1, 'memcached.getAsync was called once')
t.equal(Memcached.prototype.getAsync.args[0].length, 1, 'memcached.getAsync was passed one argument')
t.equal(Memcached.prototype.getAsync.args[0][0], hash.digest('base64'), 'memcached.getAsync argument was correct')
@ -328,6 +344,48 @@ test(
}
)
test(
'metricsContext.gather with fake token',
function (t) {
const time = Date.now() - 1
const uid = Buffer.alloc(32, '77')
const id = 'wibble'
const hash = crypto.createHash('sha256')
hash.update(uid)
hash.update(id)
sinon.stub(Memcached.prototype, 'getAsync', function () {
return P.resolve({
flowId: 'flowId',
flowBeginTime: time
})
})
metricsContext.gather.call({
payload: {
uid: uid.toString('hex'),
code: id
}
}, {}).then(function (result) {
t.equal(Memcached.prototype.getAsync.callCount, 1, 'memcached.getAsync was called once')
t.equal(Memcached.prototype.getAsync.args[0].length, 1, 'memcached.getAsync was passed one argument')
t.equal(Memcached.prototype.getAsync.args[0][0], hash.digest('base64'), 'memcached.getAsync argument was correct')
t.equal(typeof result, 'object', 'result is object')
t.notEqual(result, null, 'result is not null')
t.equal(Object.keys(result).length, 12, 'result has 12 properties')
t.ok(result.time > time, 'result.time seems correct')
t.equal(result.flow_id, 'flowId', 'result.flow_id is correct')
t.ok(result.flow_time > 0, 'result.flow_time is greater than zero')
t.ok(result.flow_time < time, 'result.flow_time is less than the current time')
t.equal(log.error.callCount, 0, 'log.error was not called')
Memcached.prototype.getAsync.restore()
t.end()
})
}
)
test(
'metricsContext.gather with bad token',
function (t) {
@ -337,13 +395,13 @@ test(
flowBeginTime: Date.now()
})
})
metricsContext.gather({}, {
metricsContext.gather.call({
auth: {
credentials: {
uid: Buffer.alloc(32, 'cd')
}
}
}).then(function (result) {
}, {}).then(function (result) {
t.equal(typeof result, 'object', 'result is object')
t.notEqual(result, null, 'result is not null')
t.equal(Object.keys(result).length, 0, 'result is empty')
@ -362,6 +420,36 @@ test(
}
)
test(
'metricsContext.gather with no token',
function (t) {
sinon.stub(Memcached.prototype, 'getAsync', function () {
return P.resolve({
flowId: 'flowId',
flowBeginTime: Date.now()
})
})
metricsContext.gather.call({
auth: {}
}, {}).then(function (result) {
t.equal(typeof result, 'object', 'result is object')
t.notEqual(result, null, 'result is not null')
t.equal(Object.keys(result).length, 0, 'result is empty')
t.equal(log.error.callCount, 1, 'log.error was called once')
t.equal(log.error.args[0].length, 1, 'log.error was passed one argument')
t.equal(log.error.args[0][0].op, 'metricsContext.gather', 'op property was correct')
t.equal(log.error.args[0][0].err.message, 'Invalid credentials', 'err.message property was correct')
t.equal(log.error.args[0][0].token, undefined, 'token property was correct')
Memcached.prototype.getAsync.restore()
log.error.reset()
t.end()
})
}
)
test(
'metricsContext.gather with metadata and token',
function (t) {
@ -372,7 +460,7 @@ test(
flowBeginTime: time
})
})
metricsContext.gather({}, {
metricsContext.gather.call({
auth: {
credentials: {
uid: Buffer.alloc(8, 'ff'),
@ -385,7 +473,7 @@ test(
flowBeginTime: time
}
}
}).then(function (result) {
}, {}).then(function (result) {
t.equal(typeof result, 'object', 'result is object')
t.notEqual(result, null, 'result is not null')
t.equal(result.flow_id, 'baz', 'result.flow_id is correct')
@ -406,14 +494,14 @@ test(
sinon.stub(Memcached.prototype, 'getAsync', function () {
return P.reject('foo')
})
metricsContext.gather({}, {
metricsContext.gather.call({
auth: {
credentials: {
uid: Buffer.alloc(8, 'ff'),
id: 'bar'
}
}
}).then(function () {
}, {}).then(function () {
t.equal(log.error.callCount, 1, 'log.error was called once')
t.equal(log.error.args[0].length, 1, 'log.error was passed one argument')
t.equal(log.error.args[0][0].op, 'metricsContext.gather', 'argument op property was correct')
@ -445,7 +533,11 @@ test(
metricsContextWithoutMemcached.stash({
uid: Buffer.alloc(8, 'ff'),
id: 'bar'
}, 'baz').then(function (result) {
}, {
payload: {
metricsContext: 'baz'
}
}).then(result => {
t.equal(result, undefined, 'result is undefined')
t.equal(Memcached.prototype.setAsync.callCount, 0, 'memcached.setAsync was not called')
@ -474,14 +566,14 @@ test(
flowBeginTime: 42
})
})
metricsContextWithoutMemcached.gather({}, {
metricsContextWithoutMemcached.gather.call({
auth: {
credentials: {
uid: Buffer.alloc(8, 'ff'),
id: 'baz'
}
}
}).then(function () {
}, {}).then(function () {
t.equal(Memcached.prototype.getAsync.callCount, 0, 'memcached.getAsync was not called')
t.equal(log.error.callCount, 0, 'log.error was not called')
@ -514,7 +606,7 @@ test(
}
var metricsContext = require('../../lib/metrics/context')(mockLog, mockConfig)
var valid = metricsContext.validate(mockRequest)
var valid = metricsContext.validate.call(mockRequest)
t.notOk(valid, 'the data is treated as invalid')
t.equal(mockLog.info.callCount, 0, 'log.info was not called')
@ -551,7 +643,7 @@ test(
}
var metricsContext = require('../../lib/metrics/context')(mockLog, mockConfig)
var valid = metricsContext.validate(mockRequest)
var valid = metricsContext.validate.call(mockRequest)
t.notOk(valid, 'the data is treated as invalid')
t.notOk(mockRequest.payload.metricsContext.flowBeginTime, 'the invalid flow data was removed')
@ -589,7 +681,7 @@ test(
}
var metricsContext = require('../../lib/metrics/context')(mockLog, mockConfig)
var valid = metricsContext.validate(mockRequest)
var valid = metricsContext.validate.call(mockRequest)
t.notOk(valid, 'the data is treated as invalid')
t.notOk(mockRequest.payload.metricsContext.flowId, 'the invalid flow data was removed')
@ -628,7 +720,7 @@ test(
}
var metricsContext = require('../../lib/metrics/context')(mockLog, mockConfig)
var valid = metricsContext.validate(mockRequest)
var valid = metricsContext.validate.call(mockRequest)
t.notOk(valid, 'the data is treated as invalid')
t.notOk(mockRequest.payload.metricsContext.flowId, 'the invalid flow data was removed')
@ -667,7 +759,7 @@ test(
}
var metricsContext = require('../../lib/metrics/context')(mockLog, mockConfig)
var valid = metricsContext.validate(mockRequest)
var valid = metricsContext.validate.call(mockRequest)
t.notOk(valid, 'the data is treated as invalid')
t.notOk(mockRequest.payload.metricsContext.flowId, 'the invalid flow data was removed')
@ -713,7 +805,7 @@ test(
try {
var metricsContext = require('../../lib/metrics/context')(mockLog, mockConfig)
var valid = metricsContext.validate(mockRequest)
var valid = metricsContext.validate.call(mockRequest)
} finally {
Date.now.restore()
}
@ -762,7 +854,7 @@ test(
try {
var metricsContext = require('../../lib/metrics/context')(mockLog, mockConfig)
var valid = metricsContext.validate(mockRequest)
var valid = metricsContext.validate.call(mockRequest)
} finally {
Date.now.restore()
}
@ -811,7 +903,7 @@ test(
try {
var metricsContext = require('../../lib/metrics/context')(mockLog, mockConfig)
var valid = metricsContext.validate(mockRequest)
var valid = metricsContext.validate.call(mockRequest)
} finally {
Date.now.restore()
}

Просмотреть файл

@ -26,7 +26,6 @@ var makeRoutes = function (options) {
var Password = require('../../lib/crypto/password')(log, config)
var customs = options.customs || {}
var checkPassword = require('../../lib/routes/utils/password_check')(log, config, Password, customs, db)
var metricsContext = options.metricsContext || log.metricsContext || require('../../lib/metrics/context')(log, config)
return require('../../lib/routes/password')(
log,
isA,
@ -38,8 +37,7 @@ var makeRoutes = function (options) {
config.verifierVersion,
options.customs || {},
checkPassword,
options.push || {},
metricsContext
options.push || {}
)
}

Просмотреть файл

@ -267,6 +267,8 @@ function spyLog (methods) {
}
function mockRequest (data) {
const metricsContext = data.metricsContext || module.exports.mockMetricsContext()
return {
app: {
acceptLanguage: 'en-US',
@ -275,11 +277,14 @@ function mockRequest (data) {
auth: {
credentials: data.credentials
},
gatherMetricsContext: metricsContext.gather,
headers: {
'user-agent': 'test user-agent'
},
payload: data.payload,
query: data.query,
payload: data.payload
stashMetricsContext: metricsContext.stash,
validateMetricsContext: metricsContext.validate
}
}