Skip to content

Commit 5c7035b

Browse files
draffenspergerstephenplusplus
draffensperger
authored and
stephenplusplus
committed
Add trace ID to log metadata when available (#2574)
1 parent 5c8973e commit 5c7035b

4 files changed

Lines changed: 304 additions & 3 deletions

File tree

‎packages/logging-bunyan/src/index.js‎

Lines changed: 56 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -40,6 +40,13 @@ var BUNYAN_TO_STACKDRIVER = {
4040
10: 'DEBUG'
4141
};
4242

43+
/**
44+
* Key to use in the Bunyan payload to allow users to indicate a trace for the
45+
* request, and to store as an intermediate value on the log entry before it
46+
* gets written to the Stackdriver logging API.
47+
*/
48+
var LOGGING_TRACE_KEY = 'logging.googleapis.com/trace';
49+
4350
/**
4451
* This module provides support for streaming your Bunyan logs to
4552
* [Stackdriver Logging](https://cloud.google.com/logging).
@@ -143,8 +150,6 @@ LoggingBunyan.prototype.formatEntry_ = function(record) {
143150
);
144151
}
145152

146-
record = extend({}, record);
147-
148153
// Stackdriver Log Viewer picks up the summary line from the 'message' field
149154
// of the payload. Unless the user has provided a 'message' property also,
150155
// move the 'msg' to 'message'.
@@ -181,9 +186,58 @@ LoggingBunyan.prototype.formatEntry_ = function(record) {
181186
delete record.httpRequest;
182187
}
183188

189+
if (record[LOGGING_TRACE_KEY]) {
190+
entryMetadata.trace = record[LOGGING_TRACE_KEY];
191+
delete record[LOGGING_TRACE_KEY];
192+
}
193+
184194
return this.log_.entry(entryMetadata, record);
185195
};
186196

197+
/**
198+
* Gets the current fully qualified trace ID when available from the
199+
* @google-cloud/trace-agent library in the LogEntry.trace field format of:
200+
* "projects/[PROJECT-ID]/traces/[TRACE-ID]".
201+
*/
202+
function getCurrentTraceFromAgent() {
203+
var agent = global._google_trace_agent;
204+
if (!agent || !agent.getCurrentContextId || !agent.getWriterProjectId) {
205+
return null;
206+
}
207+
208+
var traceId = agent.getCurrentContextId();
209+
if (!traceId) {
210+
return null;
211+
}
212+
213+
var traceProjectId = agent.getWriterProjectId();
214+
if (!traceProjectId) {
215+
return null;
216+
}
217+
218+
return `projects/${traceProjectId}/traces/${traceId}`;
219+
}
220+
221+
/**
222+
* Intercept log entries as they are written so we can attempt to add the trace
223+
* ID in the same continuation as the function that wrote the log, because the
224+
* trace agent currently uses continuation local storage for the trace context.
225+
*
226+
* By the time the Writable stream buffer gets flushed and _write gets called
227+
* we may well be in a different continuation.
228+
*/
229+
LoggingBunyan.prototype.write = function(record, encoding, callback) {
230+
record = extend({}, record);
231+
if (!record[LOGGING_TRACE_KEY]) {
232+
var trace = getCurrentTraceFromAgent();
233+
if (trace) {
234+
record[LOGGING_TRACE_KEY] = trace;
235+
}
236+
}
237+
238+
Writable.prototype.write.call(this, record, encoding, callback);
239+
};
240+
187241
/**
188242
* Relay a log entry to the logging agent. This is called by bunyan through
189243
* Writable#write.

‎packages/logging-bunyan/test/index.js‎

Lines changed: 130 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -231,6 +231,135 @@ describe('logging-bunyan', function() {
231231

232232
loggingBunyan.formatEntry_(recordWithRequest);
233233
});
234+
235+
it('should promote prefixed trace property to metadata', function(done) {
236+
var recordWithRequest = extend({
237+
'logging.googleapis.com/trace': 'trace1'
238+
}, RECORD);
239+
240+
loggingBunyan.log_.entry = function(entryMetadata, record) {
241+
assert.deepStrictEqual(entryMetadata, {
242+
resource: loggingBunyan.resource_,
243+
timestamp: RECORD.time,
244+
severity: LoggingBunyan.BUNYAN_TO_STACKDRIVER[RECORD.level],
245+
trace: 'trace1'
246+
});
247+
assert.deepStrictEqual(record, RECORD);
248+
done();
249+
};
250+
251+
loggingBunyan.formatEntry_(recordWithRequest);
252+
});
253+
});
254+
255+
describe('write', function() {
256+
var oldWritableWrite;
257+
var oldTraceAgent;
258+
259+
beforeEach(function() {
260+
oldWritableWrite = FakeWritable.prototype.write;
261+
oldTraceAgent = global._google_trace_agent;
262+
});
263+
264+
afterEach(function() {
265+
FakeWritable.prototype.write = oldWritableWrite;
266+
global._google_trace_agent = oldTraceAgent;
267+
});
268+
269+
it('should not set trace property if trace unavailable', function(done) {
270+
global._google_trace_agent = undefined;
271+
FakeWritable.prototype.write = function(record, encoding, callback) {
272+
assert.deepStrictEqual(record, RECORD);
273+
assert.strictEqual(encoding, 'encoding');
274+
assert.strictEqual(callback, assert.ifError);
275+
assert.strictEqual(this, loggingBunyan);
276+
done();
277+
};
278+
279+
loggingBunyan.write(RECORD, 'encoding', assert.ifError);
280+
});
281+
282+
it('should set prefixed trace property if trace available', function(done) {
283+
global._google_trace_agent = {
284+
getCurrentContextId: function() { return 'trace1'; },
285+
getWriterProjectId: function() { return 'project1'; }
286+
};
287+
const recordWithoutTrace = extend({}, RECORD);
288+
const recordWithTrace = extend({
289+
'logging.googleapis.com/trace': 'projects/project1/traces/trace1'
290+
}, RECORD);
291+
292+
FakeWritable.prototype.write = function(record, encoding, callback) {
293+
// Check that trace field added to record before calling Writable.write
294+
assert.deepStrictEqual(record, recordWithTrace);
295+
296+
// Check that the original record passed in was not mutated
297+
assert.deepStrictEqual(recordWithoutTrace, RECORD);
298+
299+
assert.strictEqual(encoding, 'encoding');
300+
assert.strictEqual(callback, assert.ifError);
301+
assert.strictEqual(this, loggingBunyan);
302+
done();
303+
};
304+
305+
loggingBunyan.write(recordWithoutTrace, 'encoding', assert.ifError);
306+
});
307+
308+
it('should leave prefixed trace property as is if set', function(done) {
309+
var oldTraceAgent = global._google_trace_agent;
310+
global._google_trace_agent = {
311+
getCurrentContextId: function() { return 'trace-from-agent'; },
312+
getWriterProjectId: function() { return 'project1'; }
313+
};
314+
const recordWithTraceAlreadySet = extend({
315+
'logging.googleapis.com/trace': 'trace-already-set'
316+
}, RECORD);
317+
318+
FakeWritable.prototype.write = function(record, encoding, callback) {
319+
assert.deepStrictEqual(record, recordWithTraceAlreadySet);
320+
assert.strictEqual(encoding, '');
321+
assert.strictEqual(callback, assert.ifError);
322+
assert.strictEqual(this, loggingBunyan);
323+
done();
324+
};
325+
326+
loggingBunyan.write(recordWithTraceAlreadySet, '', assert.ifError);
327+
328+
global._google_trace_agent = oldTraceAgent;
329+
});
330+
});
331+
332+
it('should not set prefixed trace property if trace unavailable', function() {
333+
FakeWritable.prototype.write = function(record, encoding, callback) {
334+
assert.deepStrictEqual(record, RECORD);
335+
assert.strictEqual(encoding, '');
336+
assert.strictEqual(callback, assert.ifError);
337+
assert.strictEqual(this, loggingBunyan);
338+
};
339+
var oldTraceAgent = global._google_trace_agent;
340+
341+
global._google_trace_agent = {};
342+
loggingBunyan.write(RECORD, '', assert.ifError);
343+
344+
global._google_trace_agent = {
345+
getCurrentContextId: function() { return null; },
346+
getWriterProjectId: function() { return null; }
347+
};
348+
loggingBunyan.write(RECORD, '', assert.ifError);
349+
350+
global._google_trace_agent = {
351+
getCurrentContextId: function() { return null; },
352+
getWriterProjectId: function() { return 'project1'; }
353+
};
354+
loggingBunyan.write(RECORD, '', assert.ifError);
355+
356+
global._google_trace_agent = {
357+
getCurrentContextId: function() { return 'trace1'; },
358+
getWriterProjectId: function() { return null; }
359+
};
360+
loggingBunyan.write(RECORD, '', assert.ifError);
361+
362+
global._google_trace_agent = oldTraceAgent;
234363
});
235364

236365
describe('_write', function() {
@@ -311,4 +440,4 @@ describe('logging-bunyan', function() {
311440
});
312441
});
313442
});
314-
});
443+
});

‎packages/logging-winston/src/index.js‎

Lines changed: 39 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -59,6 +59,11 @@ var STACKDRIVER_LOGGING_LEVEL_CODE_TO_NAME = {
5959
7: 'debug'
6060
};
6161

62+
/**
63+
* Log entry data key to allow users to indicate a trace for the request.
64+
*/
65+
var LOGGING_TRACE_KEY = 'logging.googleapis.com/trace';
66+
6267
/**
6368
* This module provides support for streaming your winston logs to
6469
* [Stackdriver Logging](https://cloud.google.com/logging).
@@ -135,6 +140,30 @@ function LoggingWinston(options) {
135140
winston.transports.StackdriverLogging = LoggingWinston;
136141
util.inherits(LoggingWinston, winston.Transport);
137142

143+
/**
144+
* Gets the current fully qualified trace ID when available from the
145+
* @google-cloud/trace-agent library in the LogEntry.trace field format of:
146+
* "projects/[PROJECT-ID]/traces/[TRACE-ID]".
147+
*/
148+
function getCurrentTraceFromAgent() {
149+
var agent = global._google_trace_agent;
150+
if (!agent || !agent.getCurrentContextId || !agent.getWriterProjectId) {
151+
return null;
152+
}
153+
154+
var traceId = agent.getCurrentContextId();
155+
if (!traceId) {
156+
return null;
157+
}
158+
159+
var traceProjectId = agent.getWriterProjectId();
160+
if (!traceProjectId) {
161+
return null;
162+
}
163+
164+
return `projects/${traceProjectId}/traces/${traceId}`;
165+
}
166+
138167
/**
139168
* Relay a log entry to the logging agent. This is normally called by winston.
140169
*
@@ -206,6 +235,16 @@ LoggingWinston.prototype.log = function(levelName, msg, metadata, callback) {
206235
}
207236
}
208237

238+
if (metadata && metadata[LOGGING_TRACE_KEY]) {
239+
entryMetadata.trace = metadata[LOGGING_TRACE_KEY];
240+
delete data.metadata[LOGGING_TRACE_KEY];
241+
} else {
242+
var trace = getCurrentTraceFromAgent();
243+
if (trace) {
244+
entryMetadata.trace = trace;
245+
}
246+
}
247+
209248
var entry = this.log_.entry(entryMetadata, data);
210249
this.log_[stackdriverLevel](entry, callback);
211250
};

‎packages/logging-winston/test/index.js‎

Lines changed: 79 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -318,6 +318,85 @@ describe('logging-winston', function() {
318318
loggingWinston.log(LEVEL, MESSAGE, metadataWithRequest, assert.ifError);
319319
});
320320

321+
it('should promote prefixed trace property to metadata', function(done) {
322+
const metadataWithTrace = extend({
323+
'logging.googleapis.com/trace': 'trace1'
324+
}, METADATA);
325+
326+
loggingWinston.log_.entry = function(entryMetadata, data) {
327+
assert.deepStrictEqual(entryMetadata, {
328+
resource: loggingWinston.resource_,
329+
trace: 'trace1'
330+
});
331+
assert.deepStrictEqual(data, {
332+
message: MESSAGE,
333+
metadata: METADATA
334+
});
335+
done();
336+
};
337+
loggingWinston.log(LEVEL, MESSAGE, metadataWithTrace, assert.ifError);
338+
});
339+
340+
it('should set trace metadata from agent if available', function(done) {
341+
var oldTraceAgent = global._google_trace_agent;
342+
global._google_trace_agent = {
343+
getCurrentContextId: function() { return 'trace1'; },
344+
getWriterProjectId: function() { return 'project1'; }
345+
};
346+
loggingWinston.log_.entry = function(entryMetadata, data) {
347+
assert.deepStrictEqual(entryMetadata, {
348+
resource: loggingWinston.resource_,
349+
trace: 'projects/project1/traces/trace1'
350+
});
351+
assert.deepStrictEqual(data, {
352+
message: MESSAGE,
353+
metadata: METADATA
354+
});
355+
done();
356+
};
357+
358+
loggingWinston.log(LEVEL, MESSAGE, METADATA, assert.ifError);
359+
360+
global._google_trace_agent = oldTraceAgent;
361+
});
362+
363+
it('should leave out trace metadata if trace unavailable', function() {
364+
loggingWinston.log_.entry = function(entryMetadata, data) {
365+
assert.deepStrictEqual(entryMetadata, {
366+
resource: loggingWinston.resource_,
367+
});
368+
assert.deepStrictEqual(data, {
369+
message: MESSAGE,
370+
metadata: METADATA
371+
});
372+
};
373+
374+
var oldTraceAgent = global._google_trace_agent;
375+
376+
global._google_trace_agent = {};
377+
loggingWinston.log(LEVEL, MESSAGE, METADATA, assert.ifError);
378+
379+
global._google_trace_agent = {
380+
getCurrentContextId: function() { return null; },
381+
getWriterProjectId: function() { return null; }
382+
};
383+
loggingWinston.log(LEVEL, MESSAGE, METADATA, assert.ifError);
384+
385+
global._google_trace_agent = {
386+
getCurrentContextId: function() { return null; },
387+
getWriterProjectId: function() { return 'project1'; }
388+
};
389+
loggingWinston.log(LEVEL, MESSAGE, METADATA, assert.ifError);
390+
391+
global._google_trace_agent = {
392+
getCurrentContextId: function() { return 'trace1'; },
393+
getWriterProjectId: function() { return null; }
394+
};
395+
loggingWinston.log(LEVEL, MESSAGE, METADATA, assert.ifError);
396+
397+
global._google_trace_agent = oldTraceAgent;
398+
});
399+
321400
it('should write to the log', function(done) {
322401
var entry = {};
323402

0 commit comments

Comments
 (0)