Audit log timer values should accumulate not overwrite

[lrowe]

Bug Report

Restify Version

5.x

Node.js Version

6.x

Expected behaviour

Audit log timers should accumulate their value when startHandlerTimer/endHandlerTimer is called more than once for the same timer name.

Actual behaviour

Audit log timer is overwritten.

Repro case

See test in #1443.

Cause

node-restify/lib/plugins/audit.js

Lines 85 to 90 in 5169db7

	var timers = {};
	(req.timers || []).forEach(function (time) {
	var t = time.time;
	var _t = Math.floor((1000000 * t[0]) + (t[1] / 1000));
	timers[time.name] = _t;
	});

Are you willing and able to fix this?

Yes.

[retrohacker]

Hey @lrowe,

Could you give some context around why the proposed behavior is desirable? I don't know much about how audit log timers are used.

[lrowe]

@retrohacker I'm using handler timers to provide insight into where time is spent within my endpoint handler (since almost all the cpu time is spent in the endpoint handler rather than middleware.)

Let's say I have an expensive function, 'collapse' and I call req.startHandlerTimer("collapse") / req.endHandlerTimer("collapse") around its invocation to record the time spent within a request. I collapse gets called multiple times in a single request its audit timer no longer shows what proportion of the request was spent executing collapse, only the duration of the final execution.

Ideally each individual time might be logged to an array, though that would involve downstream logging changes.