Skip to content

Commit d04cf34

Browse files
ofrobotsstephenplusplus
ofrobots
authored and
stephenplusplus
committed
logging-{winston,bunyan}: format logs to work better with Log Viewer and Error Reporting (#1997)
* logging-{winston,bunyan}: format logs to work better with Log Viewer and Error Reporting Stackdriver Logs Viewer picks up the summary line from the 'message' field of the jsonPayload or from the textPayload. See: https://cloud.google.com/logging/docs/view/logs_viewer_v2#expanding Furthermore, for error messages at severity 'error' and higher, Stackdriver Error Reporting will pick up error messages if the full stack trace is included in the textPayload or in the `message` property of the jsonPaylod. See: https://cloud.google.com/error-reporting/docs/formatting-error-messages Fixes: #1989 * error reporting prefers jsonPayload * drop devDep on async * add TODO about serviceContext.service and global resource types * bunyan: address comments * winston: address comments * winston: remove : when appending the stack * address comments * one liner * ensure test records have a level
1 parent fe5e880 commit d04cf34

8 files changed

Lines changed: 194 additions & 50 deletions

File tree

‎packages/logging-bunyan/package.json‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -28,7 +28,8 @@
2828
"winston"
2929
],
3030
"dependencies": {
31-
"@google-cloud/logging": "^0.7.0"
31+
"@google-cloud/logging": "^0.8.0",
32+
"extend": "^3.0.0"
3233
},
3334
"devDependencies": {
3435
"bunyan": "^1.8.5",

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

Lines changed: 25 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,7 @@
2020

2121
'use strict';
2222

23+
var extend = require('extend');
2324
var logging = require('@google-cloud/logging');
2425

2526
/**
@@ -133,6 +134,30 @@ LoggingBunyan.prototype.write = function(record) {
133134
);
134135
}
135136

137+
// Stackdriver Log Viewer picks up the summary line from the 'message' field
138+
// of the payload. Unless the user has provided a 'message' property also,
139+
// move the 'msg' to 'message'.
140+
if (!record.message) {
141+
// Clone the object before modifying it.
142+
record = extend({}, record);
143+
144+
// If this is an error, report the full stack trace. This allows Stackdriver
145+
// Error Reporting to pick up errors automatically (for severity 'error' or
146+
// higher). In this case we leave the 'msg' property intact.
147+
// https://cloud.google.com/error-reporting/docs/formatting-error-messages
148+
//
149+
// TODO(ofrobots): when resource.type is 'global' we need to additionally
150+
// provide serviceContext.service as part of the entry for Error Reporting
151+
// to automatically pick up the error.
152+
if (record.err && record.err.stack) {
153+
record.message = record.err.stack;
154+
} else if (record.msg) {
155+
// Simply rename `msg` to `message`.
156+
record.message = record.msg;
157+
delete record.msg;
158+
}
159+
}
160+
136161
var level = BUNYAN_TO_STACKDRIVER[record.level];
137162

138163
var entryMetadata = {

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

Lines changed: 8 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -44,8 +44,9 @@ describe.skip('LoggingBunyan', function() {
4444
args: [
4545
'first'
4646
],
47+
level: 'info',
4748
verify: function(entry) {
48-
assert.strictEqual(entry.data.msg, 'first');
49+
assert.strictEqual(entry.data.message, 'first');
4950
assert.strictEqual(entry.data.pid, process.pid);
5051
}
5152
},
@@ -54,9 +55,11 @@ describe.skip('LoggingBunyan', function() {
5455
args: [
5556
new Error('second')
5657
],
58+
level: 'error',
5759
verify: function(entry) {
5860
assert.strictEqual(entry.data.msg, 'second');
5961
assert.strictEqual(entry.data.pid, process.pid);
62+
assert.ok(entry.data.message.startsWith('Error: second'));
6063
}
6164
},
6265

@@ -84,8 +87,9 @@ describe.skip('LoggingBunyan', function() {
8487
},
8588
'earliest'
8689
],
90+
level: 'info',
8791
verify: function(entry) {
88-
assert.strictEqual(entry.data.msg, 'earliest');
92+
assert.strictEqual(entry.data.message, 'earliest');
8993
assert.strictEqual(entry.data.pid, process.pid);
9094
assert.strictEqual(
9195
entry.metadata.timestamp.toString(),
@@ -98,11 +102,11 @@ describe.skip('LoggingBunyan', function() {
98102
// earlier timestamp.
99103
setTimeout(function() {
100104
testData.forEach(function(test) {
101-
logger.info.apply(logger, test.args);
105+
logger[test.level].apply(logger, test.args);
102106
});
103107

104108
// `earliest` is sent last, but it should show up as the earliest entry.
105-
logger.info.apply(logger, earliest.args);
109+
logger[earliest.level].apply(logger, earliest.args);
106110

107111
// insert into list as the earliest entry.
108112
testData.unshift(earliest);

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

Lines changed: 54 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -124,12 +124,12 @@ describe('logging-bunyan', function() {
124124
});
125125

126126
it('should properly create an entry', function(done) {
127-
loggingBunyan.log_.entry = function(entryMetadata, message) {
127+
loggingBunyan.log_.entry = function(entryMetadata, record) {
128128
assert.deepEqual(entryMetadata, {
129129
resource: loggingBunyan.resource_,
130130
timestamp: RECORD.time
131131
});
132-
assert.strictEqual(message, RECORD);
132+
assert.deepStrictEqual(record, RECORD);
133133
done();
134134
};
135135

@@ -153,6 +153,58 @@ describe('logging-bunyan', function() {
153153

154154
loggingBunyan.write(RECORD);
155155
});
156+
157+
it('should rename the msg property to message', function(done) {
158+
var recordWithMsg = extend({ msg: 'msg' }, RECORD);
159+
var recordWithMessage = extend({ message: 'msg' }, RECORD);
160+
161+
loggingBunyan.log_.entry = function(entryMetadata, record) {
162+
assert.deepStrictEqual(record, recordWithMessage);
163+
done();
164+
};
165+
166+
loggingBunyan.write(recordWithMsg);
167+
});
168+
169+
it('should inject the error stack as the message', function(done) {
170+
var record = extend({
171+
msg: 'msg',
172+
err: {
173+
stack: 'the stack'
174+
}
175+
}, RECORD);
176+
var expectedRecord = extend({
177+
msg: 'msg',
178+
err: {
179+
stack: 'the stack'
180+
},
181+
message: 'the stack'
182+
}, RECORD);
183+
184+
loggingBunyan.log_.entry = function(entryMetadata, record_) {
185+
assert.deepStrictEqual(record_, expectedRecord);
186+
done();
187+
};
188+
189+
loggingBunyan.write(record);
190+
});
191+
192+
it('should leave message property intact when present', function(done) {
193+
var record = extend({
194+
msg: 'msg',
195+
message: 'message',
196+
err: {
197+
stack: 'the stack'
198+
}
199+
}, RECORD);
200+
201+
loggingBunyan.log_.entry = function(entryMetadata, record_) {
202+
assert.deepStrictEqual(record_, record);
203+
done();
204+
};
205+
206+
loggingBunyan.write(record);
207+
});
156208
});
157209

158210
describe('BUNYAN_TO_STACKDRIVER', function() {

‎packages/logging-winston/package.json‎

Lines changed: 0 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -34,7 +34,6 @@
3434
"winston": "^2.2.0"
3535
},
3636
"devDependencies": {
37-
"async": "^2.1.4",
3837
"extend": "^3.0.0",
3938
"mocha": "^3.2.0",
4039
"proxyquire": "^1.7.10"

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

Lines changed: 25 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -156,9 +156,9 @@ LoggingWinston.prototype.log = function(levelName, msg, metadata, callback) {
156156

157157
var labels = {};
158158

159-
// Logging proto requires that the label values be strings, so we convert
160-
// using util.inspect.
161159
if (is.object(metadata)) {
160+
// We attach properties as labels on the log entry. Logging proto requires
161+
// that the label values be strings, so we convert using util.inspect.
162162
for (var key in metadata) {
163163
labels[key] = util.inspect(metadata[key]);
164164
}
@@ -169,7 +169,29 @@ LoggingWinston.prototype.log = function(levelName, msg, metadata, callback) {
169169
labels: labels
170170
};
171171

172-
var entry = this.log_.entry(entryMetadata, msg);
172+
// Stackdriver Logs Viewer picks up the summary line from the `message`
173+
// property of the jsonPayload.
174+
// https://cloud.google.com/logging/docs/view/logs_viewer_v2#expanding.
175+
//
176+
// For error messages at severity 'error' and higher, Stackdriver
177+
// Error Reporting will pick up error messages if the full stack trace is
178+
// included in the textPayload or the message property of the jsonPayload.
179+
// https://cloud.google.com/error-reporting/docs/formatting-error-messages
180+
// We prefer to format messages as jsonPayload (by putting it as a message
181+
// property on an object) as that works is accepted by Error Reporting in
182+
// for more resource types.
183+
//
184+
// TODO(ofrobots): when resource.type is 'global' we need to additionally
185+
// provide serviceContext.service as part of the entry for Error Reporting to
186+
// automatically pick up the error.
187+
if (metadata && metadata.stack) {
188+
msg += (msg ? ' ' : '') + metadata.stack;
189+
}
190+
191+
var data = {
192+
message: msg
193+
};
194+
var entry = this.log_.entry(entryMetadata, data);
173195
this.log_[stackdriverLevel](entry, callback);
174196
};
175197

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

Lines changed: 45 additions & 34 deletions
Original file line numberDiff line numberDiff line change
@@ -17,7 +17,6 @@
1717
'use strict';
1818

1919
var assert = require('assert');
20-
var async = require('async');
2120
var util = require('util');
2221
var winston = require('winston');
2322

@@ -41,61 +40,73 @@ describe('LoggingWinston', function() {
4140
var testData = [
4241
{
4342
args: ['first'],
43+
level: 'info',
4444
verify: function(entry) {
45-
assert.strictEqual(entry.data, 'first');
45+
assert.deepStrictEqual(entry.data, {message: 'first'});
4646
}
4747
},
4848

4949
{
5050
args: ['second'],
51+
level: 'info',
5152
verify: function(entry) {
52-
assert.strictEqual(entry.data, 'second');
53+
assert.deepStrictEqual(entry.data, {message: 'second'});
5354
}
5455
},
5556

5657
{
57-
args: [
58-
'third',
59-
{
60-
testTimestamp: testTimestamp
61-
}
62-
],
58+
args: ['third', {testTimestamp: testTimestamp}],
59+
level: 'info',
6360
verify: function(entry) {
64-
assert.strictEqual(entry.data, 'third');
61+
assert.deepStrictEqual(entry.data, {message: 'third'});
6562

6663
assert.strictEqual(
6764
entry.metadata.labels.testTimestamp,
6865
util.inspect(testTimestamp)
6966
);
7067
}
71-
}
68+
},
69+
70+
{
71+
args: [new Error('forth')],
72+
level: 'error',
73+
verify: function(entry) {
74+
assert(entry.data.message.startsWith('Error: forth'));
75+
}
76+
},
77+
78+
{
79+
args: ['fifth message', new Error('fifth')],
80+
level: 'error',
81+
verify: function(entry) {
82+
assert(entry.data.message.startsWith('fifth message Error: fifth'));
83+
}
84+
},
7285
];
7386

7487
it('should properly write log entries', function(done) {
75-
async.each(testData, function(test, callback) {
76-
logger.info.apply(logger, test.args.concat(callback));
77-
}, function(err) {
78-
assert.ifError(err);
79-
80-
setTimeout(function() {
81-
logging.log('winston_log').getEntries({
82-
pageSize: testData.length
83-
}, function(err, entries) {
84-
assert.ifError(err);
85-
86-
assert.strictEqual(entries.length, testData.length);
87-
88-
entries
89-
.reverse()
90-
.forEach(function(entry, index) {
91-
var test = testData[index];
92-
test.verify(entry);
93-
});
94-
95-
done();
96-
});
97-
}, WRITE_CONSISTENCY_DELAY_MS);
88+
testData.forEach(function(test) {
89+
logger[test.level].apply(logger, test.args);
9890
});
91+
92+
setTimeout(function() {
93+
logging.log('winston_log').getEntries({
94+
pageSize: testData.length
95+
}, function(err, entries) {
96+
assert.ifError(err);
97+
98+
assert.strictEqual(entries.length, testData.length);
99+
100+
entries
101+
.reverse()
102+
.forEach(function(entry, index) {
103+
var test = testData[index];
104+
test.verify(entry);
105+
});
106+
107+
done();
108+
});
109+
}, WRITE_CONSISTENCY_DELAY_MS);
99110
});
100111
});
101112
});

0 commit comments

Comments
 (0)