Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

FT: Logs should not be able to overwrite reserved fields #69

Closed
wants to merge 2 commits into from
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 2 additions & 2 deletions lib/Logger.js
Original file line number Diff line number Diff line change
Expand Up @@ -61,7 +61,7 @@ class Logger {
const rLog = new RequestLogger(Config.logger,
Config.level, Config.dump, Config.end,
uids);
rLog.addDefaultFields({name: this.name});
rLog.setName(this.name);
return rLog;
}

Expand All @@ -77,7 +77,7 @@ class Logger {
const rLog = new RequestLogger(Config.logger,
Config.level, Config.dump, Config.end,
unserializeUids(serializedUids));
rLog.addDefaultFields({name: this.name});
rLog.setName(this.name);
return rLog;
}

Expand Down
25 changes: 19 additions & 6 deletions lib/RequestLogger.js
Original file line number Diff line number Diff line change
Expand Up @@ -205,6 +205,19 @@ class RequestLogger {
this.elapsedTime = null;
}

/**
* This function sets the name field for the request logger.
*
* @note As this is a protected field, it will not be copied/overwritten
* while logging objects.
* @param {string} name - name to be set for the request logger
* @returns {string} - name field of the request logger
*/
setName(name) {
this.fields.name = name;
return name;

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

shouldn't return this instead of name ?

}

/**
* This function returns a copy of the local uid list, in order for
* requests to a sub-component to be sent with the parent request's UID
Expand Down Expand Up @@ -434,26 +447,26 @@ class RequestLogger {
});
return;
}
const fields = objectCopy({}, this.fields, logFields || {});
objectCopy(this.fields, logFields || {});
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So we keep augmenting this.fields, alterating it, and thus corrupting future log entries ?

const endFlag = isEnd || false;

/*
* using Date.now() as it's faster than new Date(). logstash component
* uses this field to generate ISO 8601 timestamp
*/
if (fields.time === undefined) {
fields.time = Date.now();
if (this.fields.time === undefined) {
this.fields.time = Date.now();
Copy link

@ghost ghost Jun 8, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So, we're only setting one "date" for the whole Logger ? It sounds like a mistake to me. The previous condition helped avoid not setting the time, but we do not want to set it only once per logger.
ie: we want to set it for each log entry.

}

fields.req_id = serializeUids(this.uids);
this.fields.req_id = serializeUids(this.uids);
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So you want to update "this" for every log entry ? I'm not sure that's what you actually aim for ? (And I wouldn't see the point)

if (endFlag) {
this.elapsedTime = process.hrtime(this.startTime);
fields.elapsed_ms = this.elapsedTime[0] * 1000
this.fields.elapsed_ms = this.elapsedTime[0] * 1000
+ this.elapsedTime[1] / 1000000;
}
const logEntry = {
level,
fields,
fields: this.fields,
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Since we're setting a reference to this.fields, and we're updating this.fields for each log entry, this means that this object will be constantly modified.
All log entries will thus reference one and only one fields object ? I don't think this was done willingly, but this won't make it through.

msg,
};
this.entries.push(logEntry);
Expand Down
16 changes: 15 additions & 1 deletion lib/Utils.js
Original file line number Diff line number Diff line change
Expand Up @@ -40,6 +40,17 @@ function unserializeUids(stringdata) {
return stringdata.split(':');
}

/** This function checks if a field name collides with internal data field name
* @param {string} field - field name being logged
*
* @returns {bool} - Returns true if it collides with reserved fields
* and false otherwise
*/
const _reservedFields = new Set([ 'name', 'level', 'time', 'message',
'req_id', 'hostname', 'elapsed_ms', 'pid', 'tags', '@timestamp' ]);
function _isReservedField(field) {
return _reservedFields.has(field);
}
/**
* This function copies the properties from the source object to the target object
* @param {...object} target - object to be copied to
Expand All @@ -49,7 +60,10 @@ function objectCopy(target) {
const result = target;
let source;
function copy(f) {
result[f] = source[f];
// do not copy reserved fields
if (!_isReservedField(f)) {
result[f] = source[f];
}
}
for (let i = 1; i < arguments.length; i++) {
source = arguments[i];
Expand Down
27 changes: 21 additions & 6 deletions tests/unit/Utils.js
Original file line number Diff line number Diff line change
Expand Up @@ -47,21 +47,36 @@ describe('Utils: serializeUids', () => {
describe('Utils: objectCopy', () => {
it('copies all the properties from source to target object', (done) => {
const target = { foo: 'bar' };
const source = { id: 1, name: 'demo', value: { a: 1, b: 2, c: 3 } };
const result = { foo: 'bar', id: 1, name: 'demo', value: { a: 1, b: 2, c: 3 } };
const source = { id: 1, prj: 'demo', value: { a: 1, b: 2, c: 3 } };
const result = { foo: 'bar', id: 1, prj: 'demo', value: { a: 1, b: 2, c: 3 } };
objectCopy(target, source);
assert.deepStrictEqual(target, result, 'target should have the same properties as source');
done();
});

it('copies all the properties from multiple sources to target object', (done) => {
const target = { foo: 'bar' };
const source1 = { id: 1, name: 'demo1', value: { a: 1, b: 2, c: 3 } };
const source2 = { req_id: 2, method: 'test', err: { code: 'error', msg: 'test' } };
const result = { foo: 'bar', id: 1, name: 'demo1', value: { a: 1, b: 2, c: 3 },
req_id: 2, method: 'test', err: { code: 'error', msg: 'test' }};
const source1 = { id: 1, prj: 'demo1', value: { a: 1, b: 2, c: 3 } };
const source2 = { uid: 2, method: 'test', err: { code: 'error', msg: 'test' } };
const result = { foo: 'bar', id: 1, prj: 'demo1', value: { a: 1, b: 2, c: 3 },
uid: 2, method: 'test', err: { code: 'error', msg: 'test' }};
objectCopy(target, source1, source2);
assert.deepStrictEqual(target, result, 'target should have the same properties as source');
done();
});

it('should not copy reserved fields from source to target object', done => {
const target = { name: 'werelogs', level: 'info', message: 'hello',
time: 12345, hostname: 'host', pid: 1234, elapsed_ms: 100 };
const source = { foo: 'bar', method: 'test', name: 'demo', pid: 41,
message: 'hello', hostname: 'machine', time: 7890, elapsed_ms: 200,
};
const result = { name: 'werelogs', level: 'info', message: 'hello',
time: 12345, hostname: 'host', pid: 1234, elapsed_ms: 100,
foo: 'bar', method: 'test'};
objectCopy(target, source);
assert.deepStrictEqual(target, result, 'target\'s reserved fields' +
' should not be overwritten');
done();
});
});