feat(server): emit new activity events for kpi dashboards

r=rfk
This commit is contained in:
Phil Booth 2016-06-27 11:02:10 +01:00 коммит произвёл GitHub
Родитель 64f76d9b0c
Коммит ace64e7071
15 изменённых файлов: 2242 добавлений и 1121 удалений

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

@ -7,6 +7,8 @@ var jwtool = require('fxa-jwtool')
function main() {
var log = require('../lib/log')(config.log.level)
var metricsContext = require('../lib/metrics/context')(log, config)
log.setMetricsContext(metricsContext)
process.stdout.write(JSON.stringify({
event: 'config',
@ -87,7 +89,8 @@ function main() {
mailer,
Password,
config,
customs
customs,
metricsContext
)
server = Server.create(log, error, config, routes, db)

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

@ -28,6 +28,25 @@ var conf = convict({
env: 'LOG_FORMAT'
}
},
memcached: {
address: {
doc: 'Address:port of the memcached server (or `none` to disable memcached)',
default: '127.0.0.1:11211',
env: 'MEMCACHE_METRICS_CONTEXT_ADDRESS'
},
idle: {
doc: 'Idle timeout for memcached connections (milliseconds)',
format: Number,
default: 30000,
env: 'MEMCACHE_METRICS_CONTEXT_IDLE'
},
lifetime: {
doc: 'Lifetime for memcached values (seconds)',
format: 'nat',
default: 1800,
env: 'MEMCACHE_METRICS_CONTEXT_LIFETIME'
}
},
publicUrl: {
format: 'url',
default: 'http://127.0.0.1:9000',

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

@ -5,9 +5,9 @@
var EventEmitter = require('events').EventEmitter
var util = require('util')
var mozlog = require('mozlog')
var config = require('../config')
var logConfig = config.get('log')
var P = require('./promise')
var StatsDCollector = require('./metrics/statsd')
function unbuffer(object) {
@ -36,10 +36,13 @@ function Lug(options) {
this.statsd = new StatsDCollector(this.logger)
this.statsd.init()
this.metricsContext = require('./metrics/context')(this, config.getProperties())
}
util.inherits(Lug, EventEmitter)
Lug.prototype.setMetricsContext = function (metricsContext) {
this.metricsContext = metricsContext
}
Lug.prototype.trace = function (data) {
this.logger.debug(data.op, data)
}
@ -74,32 +77,43 @@ Lug.prototype.begin = function (op, request) {
}
Lug.prototype.event = function (name, request, data) {
var e = {
event: name,
data: unbuffer(data)
}
e.data.metricsContext = this.metricsContext.add({},
request.payload.metricsContext, request.headers.dnt === '1')
this.stdout.write(JSON.stringify(e) + '\n')
var self = this
return this.metricsContext.gather({}, request, name)
.then(
function (metricsContextData) {
var e = {
event: name,
data: unbuffer(data)
}
e.data.metricsContext = metricsContextData
self.stdout.write(JSON.stringify(e) + '\n')
}
)
}
Lug.prototype.activityEvent = function (event, request, data) {
if (! data || ! data.uid) {
return this.error({ op: 'log.activityEvent', data: data })
this.error({ op: 'log.activityEvent', data: data })
return P.resolve()
}
var info = this.metricsContext.add({
var self = this
return this.metricsContext.gather({
event: event,
userAgent: request.headers['user-agent']
}, request.payload.metricsContext, request.headers.dnt === '1')
optionallySetService(info, request)
}, request, event).then(
function (info) {
optionallySetService(info, request)
Object.keys(data).forEach(function (key) {
info[key] = data[key]
})
Object.keys(data).forEach(function (key) {
info[key] = data[key]
})
this.logger.info('activityEvent', info)
this.statsd.write(info)
self.logger.info('activityEvent', info)
self.statsd.write(info)
}
)
}
function optionallySetService (data, request) {

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

@ -8,6 +8,9 @@ var crypto = require('crypto')
var isA = require('joi')
var bufferEqualConstantTime = require('buffer-equal-constant-time')
var HEX = require('../routes/validators').HEX_STRING
var P = require('../promise')
var Memcached = require('memcached')
P.promisifyAll(Memcached.prototype)
var FLOW_ID_LENGTH = 64
@ -25,36 +28,157 @@ var SCHEMA = isA.object({
utmTerm: isA.string().optional()
}).and('flowId', 'flowBeginTime').optional()
var NOP = function () {
return P.resolve()
}
var NULL_MEMCACHED = {
delAsync: NOP,
getAsync: NOP,
setAsync: NOP
}
module.exports = function (log, config) {
var _memcached
return {
schema: SCHEMA,
add: add,
stash: stash,
gather: gather,
validate: validate
}
function add(data, metadata, doNotTrack) {
if (metadata) {
data.time = Date.now()
data.flow_id = metadata.flowId
data.flow_time = calculateFlowTime(data.time, metadata.flowBeginTime)
data.context = metadata.context
data.entrypoint = metadata.entrypoint
data.migration = metadata.migration
data.service = metadata.service
if (! doNotTrack) {
data.utm_campaign = metadata.utmCampaign
data.utm_content = metadata.utmContent
data.utm_medium = metadata.utmMedium
data.utm_source = metadata.utmSource
data.utm_term = metadata.utmTerm
}
/**
* Stashes metrics context metadata using a key derived from a token
* and an event. Asynchronous, returns a promise.
*
* @param token token to stash the metadata against
* @param events array of event names that constitute a flow
* @param metadata metrics context metadata
*/
function stash (token, events, metadata) {
if (! metadata) {
return P.resolve()
}
return data
if (events && typeof events === 'string') {
events = [ events ]
}
if (! token || ! Array.isArray(events)) {
log.error({
op: 'metricsContext.stash',
err: new Error('Invalid argument'),
token: token,
events: events
})
return P.resolve()
}
var memcached = getMemcached()
return P.all(events.map(function (event) {
return memcached.setAsync(getKey(token, event), metadata, config.memcached.lifetime)
.catch(function (err) {
log.error({ op: 'metricsContext.stash', err: err })
})
}))
}
function getMemcached () {
if (_memcached) {
return _memcached
}
try {
if (config.memcached.address !== 'none') {
_memcached = new Memcached(config.memcached.address, {
timeout: 500,
retries: 1,
retry: 1000,
reconnect: 1000,
idle: config.memcached.idle,
namespace: 'fxa-metrics~'
})
return _memcached
}
} catch (err) {
log.error({ op: 'metricsContext.getMemcached', err: err })
}
return NULL_MEMCACHED
}
/**
* 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.
*
* @param data target object
* @param request request object
* @param event event name
*/
function gather (data, request, event) {
var metadata = request.payload && request.payload.metricsContext
var token = request.auth && request.auth.credentials
var doNotTrack = request.headers && request.headers.dnt === '1'
var memcached = getMemcached()
var key = getKey(token, event)
return P.resolve()
.then(function () {
if (metadata) {
return metadata
}
if (key) {
return memcached.getAsync(key)
}
})
.catch(function (err) {
log.error({ op: 'memcached.get', err: err })
})
.then(function (metadata) {
if (metadata) {
data.time = Date.now()
data.flow_id = metadata.flowId
data.flow_time = calculateFlowTime(data.time, metadata.flowBeginTime)
data.context = metadata.context
data.entrypoint = metadata.entrypoint
data.migration = metadata.migration
data.service = metadata.service
if (! doNotTrack) {
data.utm_campaign = metadata.utmCampaign
data.utm_content = metadata.utmContent
data.utm_medium = metadata.utmMedium
data.utm_source = metadata.utmSource
data.utm_term = metadata.utmTerm
}
}
})
.then(function () {
if (key) {
return memcached.delAsync(key)
}
})
.catch(function (err) {
log.error({ op: 'memcached.del', err: err })
})
.then(function () {
return data
})
}
/**
* 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
*/
function validate(request) {
var metadata = request.payload.metricsContext
@ -119,6 +243,12 @@ module.exports = function (log, config) {
}
}
function getKey (token, event) {
if (token && event) {
return [ token.uid.toString('hex'), token.id, event ].join(':')
}
}
function calculateFlowTime (time, flowBeginTime) {
if (time <= flowBeginTime) {
return 0

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

@ -177,20 +177,26 @@ module.exports = function (
function (result) {
account = result
log.activityEvent('account.created', request, {
return log.activityEvent('account.created', request, {
uid: account.uid.toString('hex')
})
}
)
.then(
function () {
if (account.emailVerified) {
log.event('verified', request, {
return log.event('verified', request, {
email: account.email,
uid: account.uid,
locale: account.locale
})
}
}
)
.then(
function () {
if (service === 'sync') {
log.event('login', request, {
return log.event('login', request, {
service: 'sync',
uid: account.uid,
email: account.email,
@ -223,6 +229,20 @@ module.exports = function (
.then(
function (result) {
sessionToken = result
return metricsContext.stash(sessionToken, [
'device.created',
'account.signed'
], form.metricsContext)
}
)
.then(
function () {
// There is no session token when we emit account.verified
// so stash the data against a synthesized "token" instead.
return metricsContext.stash({
uid: account.uid,
id: account.emailCode.toString('hex')
}, 'account.verified', form.metricsContext)
}
)
}
@ -270,8 +290,9 @@ module.exports = function (
}
)
.then(
function (keyFetchTokenData) {
keyFetchToken = keyFetchTokenData.data.toString('hex')
function (result) {
keyFetchToken = result
return metricsContext.stash(keyFetchToken, 'account.keyfetch', form.metricsContext)
}
)
}
@ -285,7 +306,7 @@ module.exports = function (
}
if (keyFetchToken) {
response.keyFetchToken = keyFetchToken
response.keyFetchToken = keyFetchToken.data.toString('hex')
}
return P.resolve(response)
@ -380,6 +401,10 @@ module.exports = function (
if (! match) {
throw error.incorrectPassword(emailRecord.email, email)
}
return log.activityEvent('account.login', request, {
uid: emailRecord.uid.toString('hex')
})
}
)
},
@ -416,10 +441,6 @@ module.exports = function (
}
function createSessionToken () {
log.activityEvent('account.login', request, {
uid: emailRecord.uid.toString('hex')
})
var sessionTokenOptions = {
uid: emailRecord.uid,
email: emailRecord.email,
@ -433,6 +454,10 @@ module.exports = function (
.then(
function (result) {
sessionToken = result
return metricsContext.stash(sessionToken, [
'device.created',
'account.signed'
], form.metricsContext)
}
)
}
@ -457,6 +482,7 @@ module.exports = function (
.then(
function (result) {
keyFetchToken = result
return metricsContext.stash(keyFetchToken, 'account.keyfetch', form.metricsContext)
}
)
}
@ -466,7 +492,7 @@ module.exports = function (
function emitSyncLoginEvent () {
if (service === 'sync' && request.payload.reason === 'signin') {
log.event('login', request, {
return log.event('login', request, {
service: 'sync',
uid: emailRecord.uid,
email: emailRecord.email,
@ -833,6 +859,13 @@ module.exports = function (
return reply(error.unverifiedAccount())
}
db.deleteKeyFetchToken(keyFetchToken)
.then(
function () {
return log.activityEvent('account.keyfetch', request, {
uid: keyFetchToken.uid.toString('hex')
})
}
)
.then(
function () {
return {
@ -887,6 +920,7 @@ module.exports = function (
log.begin('Account.device', request)
var payload = request.payload
var sessionToken = request.auth.credentials
if (payload.id) {
// Don't write out the update if nothing has actually changed.
if (isSpuriousUpdate(payload, sessionToken)) {
@ -899,21 +933,14 @@ module.exports = function (
throw error.featureNotEnabled()
}
}
if (payload.pushCallback && (!payload.pushPublicKey || !payload.pushAuthKey)) {
payload.pushPublicKey = ''
payload.pushAuthKey = ''
}
var operation = payload.id ? 'updateDevice' : 'createDevice'
db[operation](sessionToken.uid, sessionToken.tokenId, payload).then(
upsertDevice().then(
function (device) {
if (operation === 'createDevice') {
log.event('device:create', request, {
uid: sessionToken.uid,
id: device.id,
type: device.type,
timestamp: device.createdAt
})
}
reply(butil.unbuffer(device))
push.notifyDeviceConnected(sessionToken.uid, device.name, device.id.toString('hex'))
},
@ -948,6 +975,44 @@ module.exports = function (
return spurious
}
function upsertDevice () {
var operation, event, result
if (payload.id) {
operation = 'updateDevice'
event = 'device.updated'
} else {
operation = 'createDevice'
event = 'device.created'
}
return db[operation](sessionToken.uid, sessionToken.tokenId, payload)
.then(
function (res) {
result = res
return log.activityEvent(event, request, {
uid: sessionToken.uid.toString('hex'),
device_id: result.id.toString('hex')
})
}
)
.then(
function () {
if (operation === 'createDevice') {
return log.event('device:create', request, {
uid: sessionToken.uid,
id: result.id,
type: result.type,
timestamp: result.createdAt
})
}
}
)
.then(
function () {
return result
}
)
}
}
},
{
@ -998,7 +1063,8 @@ module.exports = function (
},
validate: {
payload: {
id: isA.string().length(32).regex(HEX_STRING).required()
id: isA.string().length(32).regex(HEX_STRING).required(),
metricsContext: metricsContext.schema
}
},
response: {
@ -1010,21 +1076,37 @@ module.exports = function (
var sessionToken = request.auth.credentials
var uid = sessionToken.uid
var id = request.payload.id
push.notifyDeviceDisconnected(uid, id).then(deleteDbDevice, deleteDbDevice)
var result
function deleteDbDevice() {
db.deleteDevice(uid, id).then(
function (result) {
log.event('device:delete', request, {
return push.notifyDeviceDisconnected(uid, id)
.catch(function () {})
.then(
function () {
return db.deleteDevice(uid, id)
}
)
.then(
function (res) {
result = res
return log.activityEvent('device.deleted', request, {
uid: uid.toString('hex'),
device_id: id
})
}
)
.then(
function () {
return log.event('device:delete', request, {
uid: uid,
id: id,
timestamp: Date.now()
})
reply(result)
},
reply
}
)
}
.then(function () {
return result
})
.then(reply, reply)
}
},
{
@ -1173,7 +1255,8 @@ module.exports = function (
uid: isA.string().max(32).regex(HEX_STRING).required(),
code: isA.string().min(32).max(32).regex(HEX_STRING).required(),
service: isA.string().max(16).alphanum().optional(),
reminder: isA.string().max(32).alphanum().optional()
reminder: isA.string().max(32).alphanum().optional(),
metricsContext: metricsContext.schema
}
}
},
@ -1222,28 +1305,50 @@ module.exports = function (
return db.verifyEmail(account)
.then(function () {
log.timing('account.verified', Date.now() - account.createdAt)
log.event('verified', request, {
log.increment('account.verified')
return log.event('verified', request, {
email: account.email,
uid: account.uid,
locale: account.locale
})
log.increment('account.verified')
})
.then(function () {
// Because we have no session token on this endpoint,
// the metrics context metadata was stashed against a
// synthesized token for the benefit of this event.
// Hence we're passing in a synthesized request object
// rather than the real thing.
return log.activityEvent('account.verified', {
auth: {
credentials: {
uid: uid,
id: request.payload.code
}
},
headers: request.headers,
payload: request.payload,
query: request.query
}, {
uid: account.uid.toString('hex')
})
})
.then(function () {
if (reminder === 'first' || reminder === 'second') {
// if verified using a known reminder
var reminderOp = 'account.verified_reminder.' + reminder
log.increment(reminderOp)
log.activityEvent('account.reminder', request, {
uid: account.uid.toString('hex')
})
// log to the mailer namespace that account was verified via a reminder
log.info({
op: 'mailer.send',
name: reminderOp
})
return log.activityEvent('account.reminder', request, {
uid: account.uid.toString('hex')
})
}
})
.then(function () {
// send a push notification to all devices that the account changed
push.notifyUpdate(uid, 'accountVerify')
// remove verification reminders
@ -1440,13 +1545,21 @@ module.exports = function (
.then(
function (accountData) {
account = accountData
log.activityEvent('account.reset', request, {
return log.activityEvent('account.reset', request, {
uid: account.uid.toString('hex')
})
log.event('reset', request, {
}
)
.then(
function () {
return log.event('reset', request, {
uid: account.uid.toString('hex') + '@' + config.domain,
generation: account.verifierSetAt
})
}
)
.then(
function () {
return customs.reset(account.email)
}
)
@ -1478,6 +1591,10 @@ module.exports = function (
.then(
function (result) {
sessionToken = result
return metricsContext.stash(sessionToken, [
'device.created',
'account.signed'
], request.payload.metricsContext)
}
)
}
@ -1499,6 +1616,7 @@ module.exports = function (
.then(
function (result) {
keyFetchToken = result
return metricsContext.stash(keyFetchToken, 'account.keyfetch', request.payload.metricsContext)
}
)
}
@ -1563,9 +1681,13 @@ module.exports = function (
)
.then(
function () {
log.event('delete', request, {
return log.event('delete', request, {
uid: emailRecord.uid.toString('hex') + '@' + config.domain
})
}
)
.then(
function () {
return {}
}
)

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

@ -18,17 +18,14 @@ module.exports = function (
mailer,
Password,
config,
customs
customs,
metricsContext
) {
var isPreVerified = require('../preverifier')(error, config)
var defaults = require('./defaults')(log, P, db, error)
var idp = require('./idp')(log, serverPublicKeys)
var checkPassword = require('./utils/password_check')(log, config, Password, customs, db)
var push = require('../push')(log, db)
var metricsContext = log.metricsContext
if (!metricsContext) {
metricsContext = require('../metrics/context')(log, config.getProperties())
}
var account = require('./account')(
log,
crypto,
@ -59,7 +56,7 @@ module.exports = function (
checkPassword,
push
)
var session = require('./session')(log, isA, error, db)
var session = require('./session')(log, isA, error, db, metricsContext)
var sign = require('./sign')(log, isA, error, signer, db, config.domain, metricsContext)
var util = require('./util')(
log,

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

@ -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/. */
module.exports = function (log, isA, error, db) {
module.exports = function (log, isA, error, db, metricsContext) {
var routes = [
{
@ -17,7 +17,7 @@ module.exports = function (log, isA, error, db) {
log.begin('Session.destroy', request)
var sessionToken = request.auth.credentials
db.deleteSessionToken(sessionToken)
.done(
.then(
function () {
reply({})
},

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

@ -90,6 +90,7 @@ module.exports = function (log, isA, error, signer, db, domain, metricsContext)
}
var uid = sessionToken.uid.toString('hex')
var deviceId = sessionToken.deviceId ? sessionToken.deviceId.toString('hex') : null
var certResult
return signer.sign(
{
@ -105,8 +106,9 @@ module.exports = function (log, isA, error, signer, db, domain, metricsContext)
}
)
.then(
function(certResult) {
log.activityEvent(
function(result) {
certResult = result
return log.activityEvent(
'account.signed',
request,
{
@ -115,6 +117,10 @@ module.exports = function (log, isA, error, signer, db, domain, metricsContext)
device_id: deviceId
}
)
}
)
.then(
function () {
reply(certResult)
},
reply

1442
npm-shrinkwrap.json сгенерированный

Разница между файлами не показана из-за своего большого размера Загрузить разницу

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

@ -43,6 +43,7 @@
"hapi-fxa-oauth": "2.2.0",
"hkdf": "0.0.2",
"joi": "6.9.1",
"memcached": "2.2.2",
"mozlog": "2.0.5",
"node-statsd": "0.1.1",
"node-uap": "git+https://github.com/vladikoff/node-uap.git#9cdd16247",

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

@ -26,10 +26,15 @@ var makeRoutes = function (options) {
var config = options.config || {}
config.verifierVersion = config.verifierVersion || 0
config.smtp = config.smtp || {}
config.memcached = config.memcached || {
address: '127.0.0.1:1121',
idle: 500,
lifetime: 30
}
var log = options.log || mocks.mockLog()
var Password = require('../../lib/crypto/password')(log, config)
var db = options.db || {}
var Password = options.Password || require('../../lib/crypto/password')(log, config)
var db = options.db || mocks.mockDB()
var isPreVerified = require('../../lib/preverifier')(error, config)
var customs = options.customs || {
check: function () { return P.resolve(true) }
@ -211,10 +216,12 @@ test('/account/reset', function (t) {
return P.resolve()
})
}
var mockLog = mocks.spyLog()
var mockPush = mocks.mockPush()
var accountRoutes = makeRoutes({
db: mockDB,
customs: mockCustoms,
db: mockDB,
log: mockLog,
push: mockPush
})
var route = getRoute(accountRoutes, '/account/reset')
@ -228,6 +235,13 @@ test('/account/reset', function (t) {
t.equal(mockDB.account.callCount, 1)
t.equal(mockCustoms.reset.callCount, 1)
t.equal(mockLog.activityEvent.callCount, 1, 'log.activityEvent was called once')
var args = mockLog.activityEvent.args[0]
t.equal(args.length, 3, 'log.activityEvent was passed three arguments')
t.equal(args[0], 'account.reset', 'first argument was event name')
t.equal(args[1], mockRequest, 'second argument was request object')
t.deepEqual(args[2], { uid: uid.toString('hex') }, 'third argument contained uid')
})
})
@ -271,16 +285,29 @@ test('/account/device', function (t) {
t.equal(mockPush.notifyDeviceConnected.firstCall.args[1], device.name)
t.equal(mockPush.notifyDeviceConnected.firstCall.args[2], deviceId)
t.equal(mockLog.activityEvent.callCount, 1, 'log.activityEvent was called once')
var args = mockLog.activityEvent.args[0]
t.equal(args.length, 3, 'log.activityEvent was passed three arguments')
t.equal(args[0], 'device.created', 'first argument was event name')
t.equal(args[1], mockRequest, 'second argument was request object')
t.deepEqual(args[2], { uid: uid.toString('hex'), device_id: deviceId }, 'third argument contained uid')
t.equal(mockLog.event.callCount, 1)
t.equal(mockLog.event.args[0].length, 3)
t.equal(mockLog.event.args[0][0], 'device:create')
t.deepEqual(mockLog.event.args[0][2], {
args = mockLog.event.args[0]
t.equal(args.length, 3)
t.equal(args[0], 'device:create')
t.equal(args[1], mockRequest)
t.deepEqual(args[2], {
uid: uid.toString('hex'),
id: deviceId,
type: 'mobile',
timestamp: deviceCreatedAt
})
})
.then(function () {
mockLog.activityEvent.reset()
mockLog.event.reset()
})
}, t)
test('update', function (t) {
@ -322,6 +349,15 @@ test('/account/device', function (t) {
return runTest(route, mockRequest, function (response) {
t.equal(mockDB.updateDevice.callCount, 1, 'updateDevice was called')
t.equal(mockLog.activityEvent.callCount, 1, 'log.activityEvent was called once')
var args = mockLog.activityEvent.args[0]
t.equal(args.length, 3, 'log.activityEvent was passed three arguments')
t.equal(args[0], 'device.updated', 'first argument was event name')
t.equal(args[1], mockRequest, 'second argument was request object')
t.deepEqual(args[2], { uid: uid.toString('hex'), device_id: deviceId.toString('hex') }, 'third argument contained uid')
t.equal(mockLog.event.callCount, 0, 'log.event was not called')
t.equal(mockLog.increment.callCount, 5, 'the counters were incremented')
t.equal(mockLog.increment.getCall(0).args[0], 'device.update.sessionToken')
t.equal(mockLog.increment.getCall(1).args[0], 'device.update.name')
@ -348,9 +384,7 @@ test('/account/device', function (t) {
test('/account/device/destroy', function (t) {
var uid = uuid.v4('binary')
var deviceId = crypto.randomBytes(16).toString('hex')
var mockLog = mocks.mockLog({
event: sinon.spy()
})
var mockLog = mocks.spyLog()
var mockDB = mocks.mockDB()
var mockRequest = mocks.mockRequest({
credentials: {
@ -375,10 +409,19 @@ test('/account/device/destroy', function (t) {
t.equal(mockPush.notifyDeviceDisconnected.firstCall.args[0], mockRequest.auth.credentials.uid)
t.equal(mockPush.notifyDeviceDisconnected.firstCall.args[1], deviceId)
t.equal(mockLog.activityEvent.callCount, 1, 'log.activityEvent was called once')
var args = mockLog.activityEvent.args[0]
t.equal(args.length, 3, 'log.activityEvent was passed three arguments')
t.equal(args[0], 'device.deleted', 'first argument was event name')
t.equal(args[1], mockRequest, 'second argument was request object')
t.deepEqual(args[2], { uid: uid.toString('hex'), device_id: deviceId }, 'third argument contained uid and deviceId')
t.equal(mockLog.event.callCount, 1)
t.equal(mockLog.event.args[0].length, 3)
t.equal(mockLog.event.args[0][0], 'device:delete')
var details = mockLog.event.args[0][2]
args = mockLog.event.args[0]
t.equal(args.length, 3)
t.equal(args[0], 'device:delete')
t.equal(args[1], mockRequest)
var details = args[2]
t.equal(details.uid, uid.toString('hex'))
t.equal(details.id, deviceId)
t.ok(Date.now() - details.timestamp < 100)
@ -397,12 +440,23 @@ test('/account/create', function (t) {
entrypoint: 'preferences',
utmContent: 'some-content-string'
}
},
query: {
keys: 'true'
}
})
var emailCode = crypto.randomBytes(16)
var keyFetchTokenId = crypto.randomBytes(16)
var sessionTokenId = crypto.randomBytes(16)
var uid = uuid.v4('binary')
var mockDB = mocks.mockDB({
email: TEST_EMAIL,
emailCode: emailCode,
emailVerified: false,
uid: uuid.v4('binary')
keyFetchTokenId: keyFetchTokenId,
sessionTokenId: sessionTokenId,
uid: uid,
wrapWrapKb: 'wibble'
}, {
emailRecord: new error.unknownAccount()
})
@ -417,10 +471,31 @@ test('/account/create', function (t) {
write: sinon.spy()
}
})
mockLog.metricsContext.validate = 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()
})
var mockMailer = mocks.mockMailer()
var accountRoutes = makeRoutes({
db: mockDB,
log: mockLog
log: mockLog,
mailer: mockMailer,
metricsContext: mockMetricsContext,
Password: function () {
return {
unwrap: function () {
return P.resolve('wibble')
},
verifyHash: function () {
return P.resolve('wibble')
}
}
}
})
var route = getRoute(accountRoutes, '/account/create')
@ -432,13 +507,42 @@ test('/account/create', function (t) {
t.equal(eventData.event, 'login', 'it was a login event')
t.equal(eventData.data.service, 'sync', 'it was for sync')
t.equal(eventData.data.email, TEST_EMAIL, 'it was for the correct email')
t.equal(eventData.data.metricsContext.entrypoint, 'preferences', 'it contained the entrypoint metrics field')
t.equal(eventData.data.metricsContext.utm_content, 'some-content-string', 'it contained the utm_content metrics field')
t.deepEqual(eventData.data.metricsContext, mockRequest.payload.metricsContext, 'it contained the correct metrics context metadata')
t.equal(mockLog.metricsContext.validate.callCount, 1, 'metricsContext.validate was called')
var call = mockLog.metricsContext.validate.getCall(0)
t.equal(call.args.length, 1, 'validate was called with a single argument')
t.deepEqual(call.args[0], mockRequest, 'validate was called with the request')
t.equal(mockLog.activityEvent.callCount, 1, 'log.activityEvent was called once')
var args = mockLog.activityEvent.args[0]
t.equal(args.length, 3, 'log.activityEvent was passed three arguments')
t.equal(args[0], 'account.created', 'first argument was event name')
t.equal(args[1], mockRequest, 'second argument was request object')
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.stash.callCount, 3, 'metricsContext.stash was called three times')
args = mockMetricsContext.stash.args[0]
t.equal(args.length, 3, 'metricsContext.stash was passed three arguments first time')
t.deepEqual(args[0].tokenId, sessionTokenId, 'first argument was session token')
t.deepEqual(args[0].uid, uid, 'sessionToken.uid was correct')
t.deepEqual(args[1], [ 'device.created', 'account.signed' ], 'second argument was event array')
t.equal(args[2], mockRequest.payload.metricsContext, 'third argument was metrics context')
args = mockMetricsContext.stash.args[1]
t.equal(args.length, 3, 'metricsContext.stash was passed three arguments second time')
t.equal(args[0].id, emailCode.toString('hex'), 'first argument was synthesized token')
t.deepEqual(args[0].uid, uid, 'token.uid was correct')
t.deepEqual(args[1], 'account.verified', 'second argument was event name')
t.equal(args[2], mockRequest.payload.metricsContext, 'third argument was metrics context')
args = mockMetricsContext.stash.args[2]
t.equal(args.length, 3, 'metricsContext.stash was passed three arguments third time')
t.deepEqual(args[0].tokenId, keyFetchTokenId, 'first argument was key fetch token')
t.deepEqual(args[0].uid, uid, 'keyFetchToken.uid was correct')
t.deepEqual(args[1], 'account.keyfetch', 'second argument was event name')
t.equal(args[2], mockRequest.payload.metricsContext, 'third argument was metrics context')
}).finally(function () {
mockLog.close()
})
@ -466,10 +570,14 @@ test('/account/login', function (t) {
}
}
})
var keyFetchTokenId = crypto.randomBytes(16)
var sessionTokenId = crypto.randomBytes(16)
var uid = uuid.v4('binary')
var mockDB = mocks.mockDB({
email: TEST_EMAIL,
emailVerified: true,
keyFetchTokenId: keyFetchTokenId,
sessionTokenId: sessionTokenId,
uid: uid
})
// We want to test what's actually written to stdout by the logger.
@ -483,7 +591,15 @@ test('/account/login', function (t) {
write: sinon.spy()
}
})
mockLog.metricsContext.validate = 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()
})
var mockMailer = mocks.mockMailer()
var accountRoutes = makeRoutes({
checkPassword: function () {
@ -497,7 +613,8 @@ test('/account/login', function (t) {
},
db: mockDB,
log: mockLog,
mailer: mockMailer
mailer: mockMailer,
metricsContext: mockMetricsContext
})
var route = getRoute(accountRoutes, '/account/login')
@ -512,13 +629,35 @@ test('/account/login', function (t) {
t.equal(eventData.event, 'login', 'it was a login event')
t.equal(eventData.data.service, 'sync', 'it was for sync')
t.equal(eventData.data.email, TEST_EMAIL, 'it was for the correct email')
t.equal(eventData.data.metricsContext.entrypoint, 'preferences', 'it contained the entrypoint metrics field')
t.equal(eventData.data.metricsContext.utm_content, 'some-content-string', 'it contained the utm_content metrics field')
t.deepEqual(eventData.data.metricsContext, mockRequest.payload.metricsContext, 'it contained the metrics context')
t.equal(mockLog.metricsContext.validate.callCount, 1, 'metricsContext.validate was called')
var call = mockLog.metricsContext.validate.getCall(0)
t.equal(call.args.length, 1, 'validate was called with a single argument')
t.deepEqual(call.args[0], mockRequest, 'validate was called with the request')
t.equal(mockLog.activityEvent.callCount, 1, 'log.activityEvent was called once')
var args = mockLog.activityEvent.args[0]
t.equal(args.length, 3, 'log.activityEvent was passed three arguments')
t.equal(args[0], 'account.login', 'first argument was event name')
t.equal(args[1], mockRequest, 'second argument was request object')
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.stash.callCount, 2, 'metricsContext.stash was called twice')
args = mockMetricsContext.stash.args[0]
t.equal(args.length, 3, 'metricsContext.stash was passed three arguments first time')
t.deepEqual(args[0].tokenId, sessionTokenId, 'first argument was session token')
t.deepEqual(args[0].uid, uid, 'sessionToken.uid was correct')
t.deepEqual(args[1], [ 'device.created', 'account.signed' ], 'second argument was event array')
t.equal(args[2], mockRequest.payload.metricsContext, 'third argument was metrics context')
args = mockMetricsContext.stash.args[1]
t.equal(args.length, 3, 'metricsContext.stash was passed three arguments second time')
t.deepEqual(args[0].tokenId, keyFetchTokenId, 'first argument was key fetch token')
t.deepEqual(args[0].uid, uid, 'keyFetchToken.uid was correct')
t.deepEqual(args[1], 'account.keyfetch', 'second argument was event name')
t.equal(args[2], mockRequest.payload.metricsContext, 'third argument was metrics context')
t.equal(mockMailer.sendNewDeviceLoginNotification.callCount, 1, 'mailer.sendNewDeviceLoginNotification was called')
t.equal(mockMailer.sendVerifyLoginEmail.callCount, 0, 'mailer.sendVerifyLoginEmail was not called')
@ -696,7 +835,6 @@ test('/account/login', function (t) {
}, t)
})
test('/recovery_email/verify_code', function (t) {
var uid = uuid.v4('binary').toString('hex')
var mockRequest = mocks.mockRequest({
@ -736,20 +874,91 @@ test('/recovery_email/verify_code', function (t) {
t.equal(mockDB.verifyTokens.callCount, 1, 'calls verifyTokens')
t.equal(mockDB.verifyEmail.callCount, 1, 'calls verifyEmail')
t.equal(mockLog.event.callCount, 1, 'logs verified')
t.equal(mockLog.activityEvent.callCount, 1, 'activityEvent was called once')
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: uid,
id: mockRequest.payload.code,
}
},
headers: mockRequest.headers,
payload: mockRequest.payload,
query: mockRequest.query
}, 'second argument was synthesized request object')
t.deepEqual(args[2], {
uid: uid.toString('hex')
}, 'third argument contained uid')
t.equal(JSON.stringify(response), '{}')
})
.then(function () {
mockLog.activityEvent.reset()
})
}, t)
test('verifies account with a reminder payload', function (t) {
mockRequest.payload.reminder = 'second'
return runTest(route, mockRequest, function (response) {
t.equal(mockLog.activityEvent.callCount, 1, 'calls activityEvent')
var activityCall = mockLog.activityEvent.getCall(0).args
t.equal(activityCall[0], 'account.reminder')
t.equal(activityCall[2].uid, uid)
t.equal(mockLog.activityEvent.callCount, 2, 'activityEvent was called twice')
t.equal(mockLog.activityEvent.args[0][0], 'account.verified', 'first call was account.verified')
var args = mockLog.activityEvent.args[1]
t.equal(args.length, 3, 'activityEvent was passed three arguments second time')
t.equal(args[0], 'account.reminder', 'first argument was event name')
t.equal(args[1], mockRequest, 'second argument was request object')
t.deepEqual(args[2], {
uid: uid.toString('hex')
}, 'third argument contained uid')
t.equal(JSON.stringify(response), '{}')
})
.then(function () {
mockLog.activityEvent.reset()
})
}, t)
})
test('/account/keys', function (t) {
var keyFetchTokenId = crypto.randomBytes(16)
var uid = uuid.v4('binary')
var mockRequest = mocks.mockRequest({
credentials: {
emailVerified: true,
id: keyFetchTokenId.toString('hex'),
keyBundle: crypto.randomBytes(16),
tokenId: keyFetchTokenId,
uid: uid
}
})
var mockDB = mocks.mockDB()
var mockLog = mocks.spyLog()
var accountRoutes = makeRoutes({
db: mockDB,
log: mockLog
})
var route = getRoute(accountRoutes, '/account/keys')
return runTest(route, mockRequest, function (response) {
t.deepEqual(response, { bundle: mockRequest.auth.credentials.keyBundle.toString('hex') }, 'response was correct')
t.equal(mockDB.deleteKeyFetchToken.callCount, 1, 'db.deleteKeyFetchToken was called once')
var args = mockDB.deleteKeyFetchToken.args[0]
t.equal(args.length, 1, 'db.deleteKeyFetchToken was passed one argument')
t.equal(args[0], mockRequest.auth.credentials, 'db.deleteKeyFetchToken was passed key fetch token')
t.equal(mockLog.activityEvent.callCount, 1, 'log.activityEvent was called once')
args = mockLog.activityEvent.args[0]
t.equal(args.length, 3, 'log.activityEvent was passed three arguments')
t.equal(args[0], 'account.keyfetch', 'first argument was event name')
t.equal(args[1], mockRequest, 'second argument was request object')
t.deepEqual(args[2], { uid: uid.toString('hex') }, 'third argument contained uid')
})
})

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

@ -6,6 +6,7 @@ var test = require('../ptaptest')
var path = require('path')
var sinon = require('sinon')
var proxyquire = require('proxyquire')
var P = require('../../lib/promise')
var logger = {
debug: sinon.spy(),
@ -18,12 +19,11 @@ var statsd = {
init: sinon.spy(),
write: sinon.spy()
}
var metricsContext = function () {
return metricsContext
var metricsContext = {
gather: sinon.spy(function (data, request) {
return P.resolve(request.payload && request.payload.metricsContext)
})
}
metricsContext.add = sinon.spy(function (data, context) {
return context
})
var mocks = {
mozlog: sinon.spy(function () {
return logger
@ -33,8 +33,8 @@ mocks.mozlog.config = sinon.spy()
mocks[path.resolve(__dirname, '../../lib') + '/./metrics/statsd'] = function () {
return statsd
}
mocks[path.resolve(__dirname, '../../lib') + '/./metrics/context'] = metricsContext
var log = proxyquire('../../lib/log', mocks)('foo', 'bar')
log.setMetricsContext(metricsContext)
test(
'initialised correctly',
@ -55,7 +55,7 @@ test(
t.equal(statsd.init.args[0].length, 0, 'statsd.init was passed no arguments')
t.equal(statsd.write.callCount, 0, 'statsd.write was not called')
t.equal(metricsContext.add.callCount, 0, 'metricsContext.add was not called')
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')
@ -81,58 +81,58 @@ test(
test(
'log.activityEvent',
function (t) {
var payload = { metricsContext: {} }
log.activityEvent('foo', {
var request = {
headers: {
'user-agent': 'bar'
'user-agent': 'foo'
},
payload: payload
}, {
payload: {
metricsContext: {}
}
}
return log.activityEvent('bar', request, {
uid: 'baz'
}).then(function () {
t.equal(metricsContext.gather.callCount, 1, 'metricsContext.gather was called once')
var args = metricsContext.gather.args[0]
t.equal(args.length, 3, 'metricsContext.gather was passed three 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[0].event, 'bar', '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(args[2], 'bar', 'third argument was event name')
t.equal(logger.info.callCount, 1, 'logger.info was called once')
args = logger.info.args[0]
t.equal(args.length, 2, 'logger.info was passed two arguments')
t.equal(args[0], 'activityEvent', 'first argument was correct')
t.equal(typeof args[1], 'object', 'second argument was object')
t.notEqual(args[1], null, 'second argument was not null')
t.equal(Object.keys(args[1]).length, 1, 'second argument had three properties')
t.equal(args[1].uid, 'baz', 'uid property was correct')
t.equal(statsd.write.callCount, 1, 'statsd.write was called once')
args = statsd.write.args[0]
t.equal(args.length, 1, 'statsd.write was passed one argument')
t.equal(args[0], logger.info.args[0][1], 'statsd.write argument was correct')
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')
t.equal(logger.warn.callCount, 0, 'logger.warn was not called')
metricsContext.gather.reset()
logger.info.reset()
statsd.write.reset()
})
t.equal(metricsContext.add.callCount, 1, 'metricsContext.add was called once')
var args = metricsContext.add.args[0]
t.equal(args.length, 3, 'metricsContext.add was passed three 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[0].event, 'foo', 'event property was correct')
t.equal(args[0].userAgent, 'bar', 'userAgent property was correct')
t.equal(args[1], payload.metricsContext, 'second argument was metricsContext payload')
t.equal(args[2], false, 'third argument was correct')
t.equal(logger.info.callCount, 1, 'logger.info was called once')
args = logger.info.args[0]
t.equal(args.length, 2, 'logger.info was passed two arguments')
t.equal(args[0], 'activityEvent', 'first argument was correct')
t.equal(typeof args[1], 'object', 'second argument was object')
t.notEqual(args[1], null, 'second argument was not null')
t.equal(Object.keys(args[1]).length, 1, 'second argument had one property')
t.equal(args[1].uid, 'baz', 'uid property was correct')
t.equal(statsd.write.callCount, 1, 'statsd.write was called once')
args = statsd.write.args[0]
t.equal(args.length, 1, 'statsd.write was passed one argument')
t.equal(args[0], logger.info.args[0][1], 'statsd.write argument was correct')
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')
t.equal(logger.warn.callCount, 0, 'logger.warn was not called')
t.end()
metricsContext.add.reset()
logger.info.reset()
statsd.write.reset()
}
)
test(
'log.activityEvent with service payload parameter',
function (t) {
log.activityEvent('wibble', {
return log.activityEvent('wibble', {
headers: {},
payload: {
metricsContext: {},
@ -140,40 +140,38 @@ test(
}
}, {
uid: 'ugg'
}).then(function () {
t.equal(metricsContext.gather.callCount, 1, 'metricsContext.gather was called once')
var args = metricsContext.gather.args[0]
t.equal(args[0].event, 'wibble', 'event property was correct')
t.equal(args[0].userAgent, undefined, 'userAgent property was undefined')
t.equal(typeof args[1], 'object', 'second argument was object')
t.notEqual(args[1], null, 'second argument was not null')
t.equal(logger.info.callCount, 1, 'logger.info was called once')
args = logger.info.args[0]
t.equal(Object.keys(args[1]).length, 2, 'second argument had four properties')
t.equal(args[1].service, 'blee', 'service property was correct')
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(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')
t.equal(logger.warn.callCount, 0, 'logger.warn was not called')
metricsContext.gather.reset()
logger.info.reset()
statsd.write.reset()
})
t.equal(metricsContext.add.callCount, 1, 'metricsContext.add was called once')
var args = metricsContext.add.args[0]
t.equal(args[0].event, 'wibble', 'event property was correct')
t.equal(args[0].userAgent, undefined, 'userAgent property was undefined')
t.equal(typeof args[1], 'object', 'second argument was object')
t.notEqual(args[1], null, 'second argument was not null')
t.equal(logger.info.callCount, 1, 'logger.info was called once')
args = logger.info.args[0]
t.equal(Object.keys(args[1]).length, 2, 'second argument had two properties')
t.equal(args[1].service, 'blee', 'service property was correct')
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(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')
t.equal(logger.warn.callCount, 0, 'logger.warn was not called')
t.end()
metricsContext.add.reset()
logger.info.reset()
statsd.write.reset()
}
)
test(
'log.activityEvent with service query parameter',
function (t) {
log.activityEvent('foo', {
return log.activityEvent('foo', {
headers: {},
payload: {
metricsContext: {}
@ -183,34 +181,32 @@ test(
}
}, {
uid: 'baz'
}).then(function () {
t.equal(metricsContext.gather.callCount, 1, 'metricsContext.gather was called once')
t.equal(metricsContext.gather.args[0][0].event, 'foo', 'event property was correct')
t.equal(logger.info.callCount, 1, 'logger.info was called once')
t.equal(logger.info.args[0][1].service, 'bar', 'service property was correct')
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(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')
t.equal(logger.warn.callCount, 0, 'logger.warn was not called')
metricsContext.gather.reset()
logger.info.reset()
statsd.write.reset()
})
t.equal(metricsContext.add.callCount, 1, 'metricsContext.add was called once')
t.equal(metricsContext.add.args[0][0].event, 'foo', 'event property was correct')
t.equal(logger.info.callCount, 1, 'logger.info was called once')
t.equal(logger.info.args[0][1].service, 'bar', 'service property was correct')
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(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')
t.equal(logger.warn.callCount, 0, 'logger.warn was not called')
t.end()
metricsContext.add.reset()
logger.info.reset()
statsd.write.reset()
}
)
test(
'log.activityEvent with service metricsContext property and service payload parameter',
function (t) {
log.activityEvent('foo', {
return log.activityEvent('foo', {
headers: {},
payload: {
metricsContext: {
@ -220,33 +216,31 @@ test(
}
}, {
uid: 'qux'
}).then(function () {
t.equal(metricsContext.gather.callCount, 1, 'metricsContext.gather was called once')
t.equal(logger.info.callCount, 1, 'logger.info was called once')
t.equal(logger.info.args[0][1].service, 'bar', 'service property was correct')
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(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')
t.equal(logger.warn.callCount, 0, 'logger.warn was not called')
metricsContext.gather.reset()
logger.info.reset()
statsd.write.reset()
})
t.equal(metricsContext.add.callCount, 1, 'metricsContext.add was called once')
t.equal(logger.info.callCount, 1, 'logger.info was called once')
t.equal(logger.info.args[0][1].service, 'bar', 'service property was correct')
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(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')
t.equal(logger.warn.callCount, 0, 'logger.warn was not called')
t.end()
metricsContext.add.reset()
logger.info.reset()
statsd.write.reset()
}
)
test(
'log.activityEvent with extra data',
function (t) {
log.activityEvent('foo', {
return log.activityEvent('foo', {
headers: {
'user-agent': 'bar'
},
@ -257,124 +251,84 @@ test(
baz: 'qux',
uid: 42,
wibble: 'blee'
}).then(function () {
t.equal(metricsContext.gather.callCount, 1, 'metricsContext.gather was called once')
t.equal(Object.keys(metricsContext.gather.args[0][0]).length, 2, 'first argument had two properties')
t.equal(logger.info.callCount, 1, 'logger.info was called once')
var args = logger.info.args[0]
t.equal(Object.keys(args[1]).length, 3, 'second argument had three properties')
t.equal(args[1].baz, 'qux', 'first extra data property was correct')
t.equal(args[1].wibble, 'blee', 'second extra data property was correct')
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(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')
t.equal(logger.warn.callCount, 0, 'logger.warn was not called')
metricsContext.gather.reset()
logger.info.reset()
statsd.write.reset()
})
t.equal(metricsContext.add.callCount, 1, 'metricsContext.add was called once')
t.equal(Object.keys(metricsContext.add.args[0][0]).length, 2, 'first argument had two properties')
t.equal(logger.info.callCount, 1, 'logger.info was called once')
var args = logger.info.args[0]
t.equal(Object.keys(args[1]).length, 3, 'second argument had three properties')
t.equal(args[1].baz, 'qux', 'first extra data property was correct')
t.equal(args[1].wibble, 'blee', 'second extra data property was correct')
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(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')
t.equal(logger.warn.callCount, 0, 'logger.warn was not called')
t.end()
metricsContext.add.reset()
logger.info.reset()
statsd.write.reset()
}
)
test(
'log.activityEvent with DNT header',
function (t) {
log.activityEvent('foo', {
headers: {
'dnt': '1'
},
payload: {
metricsContext: {}
}
}, {
uid: 42
})
t.equal(metricsContext.add.callCount, 1, 'metricsContext.add was called once')
t.equal(metricsContext.add.args[0][2], true, 'third argument was correct')
t.equal(logger.info.callCount, 1, 'logger.info was called once')
t.equal(statsd.write.callCount, 1, 'statsd.write was called once')
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')
t.equal(logger.warn.callCount, 0, 'logger.warn was not called')
t.end()
metricsContext.add.reset()
logger.info.reset()
statsd.write.reset()
}
)
test(
'log.activityEvent with no data',
function (t) {
log.activityEvent('foo', {
return log.activityEvent('foo', {
headers: {},
payload: {
metricsContext: {}
}
}).then(function () {
t.equal(logger.error.callCount, 1, 'logger.error was called once')
var args = logger.error.args[0]
t.equal(args.length, 2, 'logger.error was passed two arguments')
t.equal(args[0], 'log.activityEvent', 'first argument was correct')
t.equal(Object.keys(args[1]).length, 2, 'second argument had two properties')
t.equal(args[1].data, undefined, 'data property was undefined')
t.equal(metricsContext.gather.callCount, 0, 'metricsContext.gather was not called')
t.equal(statsd.write.callCount, 0, 'statsd.write was not called')
t.equal(logger.debug.callCount, 0, 'logger.debug was not called')
t.equal(logger.critical.callCount, 0, 'logger.critical was not called')
t.equal(logger.warn.callCount, 0, 'logger.warn was not called')
t.equal(logger.info.callCount, 0, 'logger.info was not called')
logger.error.reset()
})
t.equal(logger.error.callCount, 1, 'logger.error was called once')
var args = logger.error.args[0]
t.equal(args.length, 2, 'logger.error was passed two arguments')
t.equal(args[0], 'log.activityEvent', 'first argument was correct')
t.equal(Object.keys(args[1]).length, 2, 'second argument had two properties')
t.equal(args[1].data, undefined, 'data property was undefined')
t.equal(metricsContext.add.callCount, 0, 'metricsContext.add was not called')
t.equal(statsd.write.callCount, 0, 'statsd.write was not called')
t.equal(logger.debug.callCount, 0, 'logger.debug was not called')
t.equal(logger.critical.callCount, 0, 'logger.critical was not called')
t.equal(logger.warn.callCount, 0, 'logger.warn was not called')
t.equal(logger.info.callCount, 0, 'logger.info was not called')
t.end()
logger.error.reset()
}
)
test(
'log.activityEvent with no uid',
function (t) {
log.activityEvent('foo', {
return log.activityEvent('foo', {
headers: {},
payload: {
metricsContext: {}
}
}, {
foo: 'bar'
}).then(function () {
t.equal(logger.error.callCount, 1, 'logger.error was called once')
var args = logger.error.args[0]
t.equal(Object.keys(args[1].data).length, 1, 'data property had one property')
t.equal(args[1].data.foo, 'bar', 'data property had correct property')
t.equal(metricsContext.gather.callCount, 0, 'metricsContext.gather was not called')
t.equal(statsd.write.callCount, 0, 'statsd.write was not called')
t.equal(logger.debug.callCount, 0, 'logger.debug was not called')
t.equal(logger.critical.callCount, 0, 'logger.critical was not called')
t.equal(logger.warn.callCount, 0, 'logger.warn was not called')
t.equal(logger.info.callCount, 0, 'logger.info was not called')
logger.error.reset()
})
t.equal(logger.error.callCount, 1, 'logger.error was called once')
var args = logger.error.args[0]
t.equal(Object.keys(args[1].data).length, 1, 'data property had one property')
t.equal(args[1].data.foo, 'bar', 'data property had correct property')
t.equal(metricsContext.add.callCount, 0, 'metricsContext.add was not called')
t.equal(statsd.write.callCount, 0, 'statsd.write was not called')
t.equal(logger.debug.callCount, 0, 'logger.debug was not called')
t.equal(logger.critical.callCount, 0, 'logger.critical was not called')
t.equal(logger.warn.callCount, 0, 'logger.warn was not called')
t.equal(logger.info.callCount, 0, 'logger.info was not called')
t.end()
logger.error.reset()
}
)

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

@ -7,168 +7,589 @@
var sinon = require('sinon')
var test = require('../ptaptest')
var mocks = require('../mocks')
var metricsContext = require('../../lib/metrics/context')(mocks.mockLog(), {})
var log = mocks.spyLog()
var Memcached = require('memcached')
var metricsContext = require('../../lib/metrics/context')(log, {
memcached: {
address: '127.0.0.1:1121',
idle: 500,
lifetime: 30
}
})
var P = require('../../lib/promise')
test(
'metricsContext interface is correct',
function (t) {
t.equal(typeof metricsContext, 'object', 'metricsContext is object')
t.notEqual(metricsContext, null, 'metricsContext is not null')
t.equal(Object.keys(metricsContext).length, 3, 'metricsContext has 3 properties')
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(typeof metricsContext.add, 'function', 'metricsContext.add is function')
t.equal(metricsContext.add.length, 3, 'metricsContext.add expects 3 arguments')
t.equal(typeof metricsContext.stash, 'function', 'metricsContext.stash is function')
t.equal(metricsContext.stash.length, 3, 'metricsContext.stash expects 3 arguments')
t.equal(typeof metricsContext.gather, 'function', 'metricsContext.gather is function')
t.equal(metricsContext.gather.length, 3, 'metricsContext.gather expects 3 arguments')
t.equal(typeof metricsContext.validate, 'function', 'metricsContext.validate is function')
t.equal(metricsContext.validate.length, 1, 'metricsContext.validate expects 1 argument')
t.end()
}
)
test(
'metricsContext.add without metadata',
'metricsContext.stash',
function (t) {
var result = metricsContext.add({})
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.end()
}
)
test(
'metricsContext.add with metadata',
function (t) {
var time = Date.now() - 1
var result = metricsContext.add({}, {
flowId: 'mock flow id',
flowBeginTime: time,
context: 'mock context',
entrypoint: 'mock entry point',
migration: 'mock migration',
service: 'mock service',
utmCampaign: 'mock utm_campaign',
utmContent: 'mock utm_content',
utmMedium: 'mock utm_medium',
utmSource: 'mock utm_source',
utmTerm: 'mock utm_term',
ignore: 'mock ignorable property'
sinon.stub(Memcached.prototype, 'setAsync', function () {
return P.resolve('wibble')
})
metricsContext.stash({
uid: 'foo',
id: 'bar'
}, 'baz', 'qux').then(function (result) {
t.deepEqual(result, [ 'wibble' ], 'result is 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, 'mock flow id', '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(result.context, 'mock context', 'result.context is correct')
t.equal(result.entrypoint, 'mock entry point', 'result.entrypoint is correct')
t.equal(result.migration, 'mock migration', 'result.migration is correct')
t.equal(result.service, 'mock service', 'result.service is correct')
t.equal(result.utm_campaign, 'mock utm_campaign', 'result.utm_campaign is correct')
t.equal(result.utm_content, 'mock utm_content', 'result.utm_content is correct')
t.equal(result.utm_medium, 'mock utm_medium', 'result.utm_medium is correct')
t.equal(result.utm_source, 'mock utm_source', 'result.utm_source is correct')
t.equal(result.utm_term, 'mock utm_term', 'result.utm_term is correct')
t.equal(Memcached.prototype.setAsync.callCount, 1, 'memcached.setAsync was called once')
t.equal(Memcached.prototype.setAsync.args[0].length, 3, 'memcached.setAsync was passed three arguments')
t.equal(Memcached.prototype.setAsync.args[0][0], 'foo:bar:baz', 'first argument was correct')
t.equal(Memcached.prototype.setAsync.args[0][1], 'qux', 'second argument was correct')
t.equal(Memcached.prototype.setAsync.args[0][2], 30, 'third argument was correct')
t.end()
}
)
t.equal(log.error.callCount, 0, 'log.error was not called')
test(
'metricsContext.add with bad flowBeginTime',
function (t) {
var result = metricsContext.add({}, {
flowBeginTime: Date.now() + 10000
Memcached.prototype.setAsync.restore()
t.end()
})
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')
t.end()
}
)
test(
'metricsContext.add with DNT header',
'metricsContext.stash with two events',
function (t) {
sinon.stub(Memcached.prototype, 'setAsync', function () {
return P.resolve('wibble')
})
metricsContext.stash({
uid: 'foo',
id: 'bar'
}, [ 'baz', 'qux' ], 'blee').then(function (result) {
t.deepEqual(result, [ 'wibble', 'wibble' ], 'result is correct')
t.equal(Memcached.prototype.setAsync.callCount, 2, 'memcached.setAsync was called twice')
t.equal(Memcached.prototype.setAsync.args[0][0], 'foo:bar:baz', 'first argument was correct in first call')
t.equal(Memcached.prototype.setAsync.args[0][1], 'blee', 'second argument was correct in first call')
t.equal(Memcached.prototype.setAsync.args[0][2], 30, 'third argument was correct in first call')
t.equal(Memcached.prototype.setAsync.args[1][0], 'foo:bar:qux', 'first argument was correct in second call')
t.equal(Memcached.prototype.setAsync.args[1][1], 'blee', 'second argument was correct in second call')
t.equal(Memcached.prototype.setAsync.args[1][2], 30, 'third argument was correct in second call')
t.equal(log.error.callCount, 0, 'log.error was not called')
Memcached.prototype.setAsync.restore()
t.end()
})
}
)
test(
'metricsContext.stash error',
function (t) {
sinon.stub(Memcached.prototype, 'setAsync', function () {
return P.reject('wibble')
})
metricsContext.stash({
uid: 'foo',
id: 'bar'
}, 'baz', 'qux').then(function (result) {
t.deepEqual(result, [ undefined ], 'result is undefined')
t.equal(Memcached.prototype.setAsync.callCount, 1, 'memcached.setAsync was called once')
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.stash', 'argument op property was correct')
t.equal(log.error.args[0][0].err, 'wibble', 'argument err property was correct')
Memcached.prototype.setAsync.restore()
log.error.reset()
t.end()
})
}
)
test(
'metricsContext.stash without token',
function (t) {
sinon.stub(Memcached.prototype, 'setAsync', function () {
return P.resolve('wibble')
})
metricsContext.stash(null, 'foo', 'bar').then(function (result) {
t.equal(result, undefined, 'result is undefined')
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.stash', 'op property was correct')
t.equal(log.error.args[0][0].err.message, 'Invalid argument', 'err.message property was correct')
t.equal(log.error.args[0][0].token, null, 'token property was correct')
t.deepEqual(log.error.args[0][0].events, ['foo'], 'events property was correct')
t.equal(Memcached.prototype.setAsync.callCount, 0, 'memcached.setAsync was not called')
Memcached.prototype.setAsync.restore()
log.error.reset()
t.end()
})
}
)
test(
'metricsContext.stash without event',
function (t) {
sinon.stub(Memcached.prototype, 'setAsync', function () {
return P.resolve('wibble')
})
metricsContext.stash({
uid: 'foo',
id: 'bar'
}, '', 'baz').then(function (result) {
t.equal(result, undefined, 'result is undefined')
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.stash', 'op property was correct')
t.equal(log.error.args[0][0].err.message, 'Invalid argument', 'err.message property was correct')
t.equal(log.error.args[0][0].token.uid, 'foo', 'token.uid property was correct')
t.equal(log.error.args[0][0].token.id, 'bar', 'token.id property was correct')
t.equal(log.error.args[0][0].events, '', 'events property was correct')
t.equal(Memcached.prototype.setAsync.callCount, 0, 'memcached.setAsync was not called')
Memcached.prototype.setAsync.restore()
log.error.reset()
t.end()
})
}
)
test(
'metricsContext.stash without metadata',
function (t) {
sinon.stub(Memcached.prototype, 'setAsync', function () {
return P.resolve('wibble')
})
metricsContext.stash({
uid: 'foo',
id: 'bar'
}, 'baz').then(function (result) {
t.equal(result, undefined, 'result is undefined')
t.equal(Memcached.prototype.setAsync.callCount, 0, 'memcached.setAsync was not called')
t.equal(log.error.callCount, 0, 'log.error was not called')
Memcached.prototype.setAsync.restore()
t.end()
})
}
)
test(
'metricsContext.gather without metadata or session token',
function (t) {
metricsContext.gather({}, {}).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, 0, 'log.error was not called')
t.end()
})
}
)
test(
'metricsContext.gather with metadata',
function (t) {
sinon.stub(Memcached.prototype, 'getAsync', function () {
return P.resolve({
flowId: 'not this flow id',
flowBeginTime: 0
})
})
sinon.stub(Memcached.prototype, 'delAsync', function () {
return P.resolve()
})
var time = Date.now() - 1
var result = metricsContext.add({}, {
flowId: 'mock flow id',
flowBeginTime: time,
context: 'mock context',
entrypoint: 'mock entry point',
migration: 'mock migration',
service: 'mock service',
utmCampaign: 'mock utm_campaign',
utmContent: 'mock utm_content',
utmMedium: 'mock utm_medium',
utmSource: 'mock utm_source',
utmTerm: 'mock utm_term',
ignore: 'mock ignorable property'
}, true)
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')
t.equal(result.utm_medium, undefined, 'result.utm_medium is undefined')
t.equal(result.utm_source, undefined, 'result.utm_source is undefined')
t.equal(result.utm_term, undefined, 'result.utm_term is undefined')
t.end()
}
)
test(
'metricsContext.validate with known good data',
function (t) {
var expectedTime = 1451566800000
var expectedSalt = '4d6f7a696c6c6146697265666f782121'
var expectedHmac = 'c89d56556d22039fbbf54d34e0baf206'
var mockLog = mocks.spyLog()
var mockConfig = {
metrics: {
flow_id_expiry: 60000,
flow_id_key: 'S3CR37'
metricsContext.gather({}, {
payload: {
metricsContext: {
flowId: 'mock flow id',
flowBeginTime: time,
context: 'mock context',
entrypoint: 'mock entry point',
migration: 'mock migration',
service: 'mock service',
utmCampaign: 'mock utm_campaign',
utmContent: 'mock utm_content',
utmMedium: 'mock utm_medium',
utmSource: 'mock utm_source',
utmTerm: 'mock utm_term',
ignore: 'mock ignorable property'
}
}
}
var mockRequest = {
}).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')
t.ok(result.time > time, 'result.time seems correct')
t.equal(result.flow_id, 'mock flow id', '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(result.context, 'mock context', 'result.context is correct')
t.equal(result.entrypoint, 'mock entry point', 'result.entrypoint is correct')
t.equal(result.migration, 'mock migration', 'result.migration is correct')
t.equal(result.service, 'mock service', 'result.service is correct')
t.equal(result.utm_campaign, 'mock utm_campaign', 'result.utm_campaign is correct')
t.equal(result.utm_content, 'mock utm_content', 'result.utm_content is correct')
t.equal(result.utm_medium, 'mock utm_medium', 'result.utm_medium is correct')
t.equal(result.utm_source, 'mock utm_source', 'result.utm_source is correct')
t.equal(result.utm_term, 'mock utm_term', 'result.utm_term is correct')
t.equal(Memcached.prototype.getAsync.callCount, 0, 'memcached.getAsync was not called')
t.equal(Memcached.prototype.delAsync.callCount, 0, 'memcached.delAsync was not called')
t.equal(log.error.callCount, 0, 'log.error was not called')
Memcached.prototype.getAsync.restore()
Memcached.prototype.delAsync.restore()
t.end()
})
}
)
test(
'metricsContext.gather with bad flowBeginTime',
function (t) {
metricsContext.gather({}, {
payload: {
metricsContext: {
flowBeginTime: Date.now() + 10000
}
}
}).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')
t.equal(log.error.callCount, 0, 'log.error was not called')
t.end()
})
}
)
test(
'metricsContext.gather with DNT header',
function (t) {
var time = Date.now() - 1
metricsContext.gather({}, {
headers: {
'user-agent': 'Firefox'
dnt: '1'
},
payload: {
metricsContext: {
flowId: expectedSalt + expectedHmac,
flowBeginTime: expectedTime
flowId: 'mock flow id',
flowBeginTime: time,
context: 'mock context',
entrypoint: 'mock entry point',
migration: 'mock migration',
service: 'mock service',
utmCampaign: 'mock utm_campaign',
utmContent: 'mock utm_content',
utmMedium: 'mock utm_medium',
utmSource: 'mock utm_source',
utmTerm: 'mock utm_term',
ignore: 'mock ignorable property'
}
}
}
sinon.stub(Date, 'now', function() {
return expectedTime + 20000
}).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')
t.equal(result.utm_medium, undefined, 'result.utm_medium is undefined')
t.equal(result.utm_source, undefined, 'result.utm_source is undefined')
t.equal(result.utm_term, undefined, 'result.utm_term is undefined')
t.equal(log.error.callCount, 0, 'log.error was not called')
t.end()
})
}
)
try {
var metricsContext = require('../../lib/metrics/context')(mockLog, mockConfig)
var valid = metricsContext.validate(mockRequest)
} finally {
Date.now.restore()
}
test(
'metricsContext.gather with session token',
function (t) {
var time = Date.now() - 1
sinon.stub(Memcached.prototype, 'getAsync', function () {
return P.resolve({
flowId: 'flowId',
flowBeginTime: time,
context: 'context',
entrypoint: 'entrypoint',
migration: 'migration',
service: 'service',
utmCampaign: 'utm_campaign',
utmContent: 'utm_content',
utmMedium: 'utm_medium',
utmSource: 'utm_source',
utmTerm: 'utm_term',
ignore: 'ignore me'
})
})
sinon.stub(Memcached.prototype, 'delAsync', function () {
return P.resolve()
})
metricsContext.gather({}, {
auth: {
credentials: {
uid: 'foo',
id: 'bar'
}
}
}, 'baz').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], 'foo:bar:baz', 'memcached.getAsync argument was correct')
t.ok(valid, 'the known good data is treated as valid')
t.equal(mockLog.warn.callCount, 0, 'log.warn was not called')
t.equal(mockLog.info.callCount, 1, 'log.info was called once')
t.ok(mockLog.info.calledWithExactly({
op: 'metrics.context.validate',
valid: true,
agent: 'Firefox'
}), 'log.info was called with the expected log data')
t.end()
t.equal(Memcached.prototype.delAsync.callCount, 1, 'memcached.delAsync was called once')
t.equal(Memcached.prototype.delAsync.args[0].length, 1, 'memcached.delAsync was passed one argument')
t.equal(Memcached.prototype.delAsync.args[0][0], 'foo:bar:baz', 'memcached.delAsync 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(result.context, 'context', 'result.context is correct')
t.equal(result.entrypoint, 'entrypoint', 'result.entry point is correct')
t.equal(result.migration, 'migration', 'result.migration is correct')
t.equal(result.service, 'service', 'result.service is correct')
t.equal(result.utm_campaign, 'utm_campaign', 'result.utm_campaign is correct')
t.equal(result.utm_content, 'utm_content', 'result.utm_content is correct')
t.equal(result.utm_medium, 'utm_medium', 'result.utm_medium is correct')
t.equal(result.utm_source, 'utm_source', 'result.utm_source is correct')
t.equal(result.utm_term, 'utm_term', 'result.utm_term is correct')
t.equal(log.error.callCount, 0, 'log.error was not called')
Memcached.prototype.getAsync.restore()
Memcached.prototype.delAsync.restore()
t.end()
})
}
)
test(
'metricsContext.gather with metadata and session token',
function (t) {
var time = Date.now() - 1
sinon.stub(Memcached.prototype, 'getAsync', function () {
return P.resolve({
flowId: 'foo',
flowBeginTime: time
})
})
sinon.stub(Memcached.prototype, 'delAsync', function () {
return P.resolve()
})
metricsContext.gather({}, {
auth: {
credentials: {
uid: 'bar',
id: 'baz'
}
},
payload: {
metricsContext: {
flowId: 'qux',
flowBeginTime: time
}
}
}, 'blee').then(function (result) {
t.equal(typeof result, 'object', 'result is object')
t.notEqual(result, null, 'result is not null')
t.equal(result.flow_id, 'qux', 'result.flow_id is correct')
t.equal(Memcached.prototype.delAsync.callCount, 1, 'memcached.delAsync was called once')
t.equal(Memcached.prototype.delAsync.args[0].length, 1, 'memcached.delAsync was called once')
t.equal(Memcached.prototype.delAsync.args[0][0], 'bar:baz:blee', 'memcached.delAsync argument was correct')
t.equal(Memcached.prototype.getAsync.callCount, 0, 'memcached.getAsync was not called')
t.equal(log.error.callCount, 0, 'log.error was not called')
Memcached.prototype.getAsync.restore()
Memcached.prototype.delAsync.restore()
t.end()
})
}
)
test(
'metricsContext.gather with get error',
function (t) {
sinon.stub(Memcached.prototype, 'getAsync', function () {
return P.reject('foo')
})
sinon.stub(Memcached.prototype, 'delAsync', function () {
return P.resolve()
})
metricsContext.gather({}, {
auth: {
credentials: {
uid: 'bar',
id: 'baz'
}
}
}, 'qux').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, 'memcached.get', 'argument op property was correct')
t.equal(log.error.args[0][0].err, 'foo', 'argument err property was correct')
t.equal(Memcached.prototype.getAsync.callCount, 1, 'memcached.getAsync was called once')
t.equal(Memcached.prototype.delAsync.callCount, 1, 'memcached.delAsync was called once')
Memcached.prototype.getAsync.restore()
Memcached.prototype.delAsync.restore()
log.error.reset()
t.end()
})
}
)
test(
'metricsContext.gather with del error',
function (t) {
sinon.stub(Memcached.prototype, 'getAsync', function () {
return P.resolve({
flowId: 'foo',
flowBeginTime: 42
})
})
sinon.stub(Memcached.prototype, 'delAsync', function () {
return P.reject('bar')
})
metricsContext.gather({}, {
auth: {
credentials: {
uid: 'baz',
id: 'qux'
}
}
}, 'blee').then(function (result) {
t.equal(typeof result, 'object', 'result is object')
t.notEqual(result, null, 'result is not null')
t.equal(result.flow_id, 'foo', 'result.flow_id is correct')
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, 'memcached.del', 'argument op property was correct')
t.equal(log.error.args[0][0].err, 'bar', 'argument err property was correct')
t.equal(Memcached.prototype.getAsync.callCount, 1, 'memcached.getAsync was called once')
t.equal(Memcached.prototype.delAsync.callCount, 1, 'memcached.delAsync was called once')
Memcached.prototype.getAsync.restore()
Memcached.prototype.delAsync.restore()
log.error.reset()
t.end()
})
}
)
test(
'metricsContext.stash with config.memcached.address === "none"',
function (t) {
var metricsContextWithoutMemcached = require('../../lib/metrics/context')(log, {
memcached: {
address: 'none',
idle: 500,
lifetime: 30
}
})
sinon.stub(Memcached.prototype, 'setAsync', function () {
return P.reject('wibble')
})
metricsContextWithoutMemcached.stash({
uid: 'foo',
id: 'bar'
}, 'baz', 'qux').then(function (result) {
t.deepEqual(result, [ undefined ], 'result is undefined')
t.equal(Memcached.prototype.setAsync.callCount, 0, 'memcached.setAsync was not called')
t.equal(log.error.callCount, 0, 'log.error was not called')
Memcached.prototype.setAsync.restore()
t.end()
})
}
)
test(
'metricsContext.gather with config.memcached.address === "none"',
function (t) {
var metricsContextWithoutMemcached = require('../../lib/metrics/context')(log, {
memcached: {
address: 'none',
idle: 500,
lifetime: 30
}
})
sinon.stub(Memcached.prototype, 'getAsync', function () {
return P.resolve({
flowId: 'foo',
flowBeginTime: 42
})
})
sinon.stub(Memcached.prototype, 'delAsync', function () {
return P.resolve()
})
metricsContextWithoutMemcached.gather({}, {
auth: {
credentials: {
uid: 'bar',
id: 'baz'
}
}
}, 'qux').then(function () {
t.equal(Memcached.prototype.getAsync.callCount, 0, 'memcached.getAsync was not called')
t.equal(Memcached.prototype.delAsync.callCount, 0, 'memcached.getAsync was not called')
t.equal(log.error.callCount, 0, 'log.error was not called')
Memcached.prototype.getAsync.restore()
Memcached.prototype.delAsync.restore()
log.error.reset()
t.end()
})
}
)

103
test/local/sign_routes.js Normal file
Просмотреть файл

@ -0,0 +1,103 @@
/* 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/. */
require('ass')
var crypto = require('crypto')
var error = require('../../lib/error')
var getRoute = require('../routes_helpers').getRoute
var isA = require('joi')
var mocks = require('../mocks')
var P = require('../../lib/promise')
var sinon = require('sinon')
var test = require('../ptaptest')
test(
'/certificate/sign emits account.signed activity event',
function (t) {
var mockLog = mocks.mockLog({
activityEvent: sinon.spy()
})
var mockRequest = {
auth: {
credentials: {
accountCreatedAt: Date.now(),
deviceId: crypto.randomBytes(16),
emailVerified: true,
lastAuthAt: function () {
return Date.now()
},
locale: 'en',
tokenId: crypto.randomBytes(16),
uid: crypto.randomBytes(16)
}
},
headers: {},
payload: {
duration: 0,
publicKey: {
algorithm: 'RS',
n: 'bar',
e: 'baz'
}
},
query: {}
}
var signRoutes = makeRoutes({
config: {
memcache: {
address: '127.0.0.1:11211',
idle: 100
}
},
log: mockLog
})
return new P(function (resolve) {
getRoute(signRoutes, '/certificate/sign')
.handler(mockRequest, resolve)
})
.then(
function () {
t.equal(mockLog.activityEvent.callCount, 1)
t.equal(mockLog.activityEvent.args[0].length, 3)
t.equal(mockLog.activityEvent.args[0][0], 'account.signed')
t.equal(mockLog.activityEvent.args[0][1], mockRequest)
t.deepEqual(mockLog.activityEvent.args[0][2], {
uid: mockRequest.auth.credentials.uid.toString('hex'),
account_created_at: mockRequest.auth.credentials.accountCreatedAt,
device_id: mockRequest.auth.credentials.deviceId.toString('hex')
})
},
function () {
t.fail('request should have succeeded')
}
)
}
)
function makeRoutes (options) {
options = options || {}
var log = options.log || mocks.mockLog()
var config = options.config || {}
return require('../../lib/routes/sign')(
log,
isA,
error,
options.signer || {
sign: function () {
return P.resolve({})
}
},
options.db || {
updateSessionToken: function () {},
updateLocale: function () {}
},
options.domain || 'wibble',
options.metricsContext || require('../../lib/metrics/context')(log, config)
)
}

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

@ -12,18 +12,19 @@ var P = require('../lib/promise')
var crypto = require('crypto')
var DB_METHOD_NAMES = ['account', 'createAccount', 'createDevice', 'createKeyFetchToken',
'createSessionToken', 'devices', 'deleteAccount', 'deleteDevice',
'deletePasswordChangeToken', 'deleteVerificationReminder', 'emailRecord', 'resetAccount',
'sessionTokenWithVerificationStatus', 'sessions', 'updateDevice', 'verifyTokens', 'verifyEmail']
'createSessionToken', 'deleteAccount', 'deleteDevice', 'deleteKeyFetchToken',
'deletePasswordChangeToken', 'deleteVerificationReminder', 'devices',
'emailRecord', 'resetAccount', 'sessions', 'sessionTokenWithVerificationStatus',
'updateDevice', 'verifyEmail', 'verifyTokens']
var LOG_METHOD_NAMES = ['trace', 'increment', 'info', 'error', 'begin', 'warn',
'activityEvent', 'event', 'timing']
var LOG_METHOD_NAMES = ['trace', 'increment', 'info', 'error', 'begin', 'warn', 'timing',
'activityEvent', 'event']
var MAILER_METHOD_NAMES = ['sendVerifyCode', 'sendVerifyLoginEmail',
'sendNewDeviceLoginNotification', 'sendPasswordChangedNotification',
'sendPostVerifyEmail']
var METRICS_CONTEXT_METHOD_NAMES = ['add', 'validate']
var METRICS_CONTEXT_METHOD_NAMES = ['stash', 'gather', 'validate']
var PUSH_METHOD_NAMES = ['notifyDeviceConnected', 'notifyDeviceDisconnected', 'notifyUpdate']
@ -53,7 +54,9 @@ function mockDB (data, errors) {
return P.resolve({
uid: data.uid,
email: data.email,
emailVerified: data.emailVerified
emailCode: data.emailCode,
emailVerified: data.emailVerified,
wrapWrapKb: data.wrapWrapKb
})
}),
createDevice: sinon.spy(function () {
@ -67,7 +70,9 @@ function mockDB (data, errors) {
}),
createKeyFetchToken: sinon.spy(function () {
return P.resolve({
data: crypto.randomBytes(32)
data: crypto.randomBytes(32),
tokenId: data.keyFetchTokenId,
uid: data.uid
})
}),
createSessionToken: sinon.spy(function () {
@ -78,6 +83,7 @@ function mockDB (data, errors) {
lastAuthAt: function () {
return Date.now()
},
tokenId: data.sessionTokenId,
tokenVerificationId: data.tokenVerificationId,
tokenVerified: ! data.tokenVerificationId,
uid: data.uid