Skip to content

Commit

Permalink
Fix failing tests for circular metadata
Browse files Browse the repository at this point in the history
  • Loading branch information
@coderarity
coderarity committed May 4, 2012
1 parent 67955a9 commit 7e74435
Show file tree
Hide file tree
Showing 4 changed files with 9 additions and 3 deletions.
3 changes: 2 additions & 1 deletion lib/winston/common.js
View file
Expand Up @@ -8,6 +8,7 @@

var util = require('util'),
crypto = require('crypto'),
cycle = require('cycle'),
config = require('./config');

//
Expand Down Expand Up @@ -108,7 +109,7 @@ exports.clone = function (obj) {
exports.log = function (options) {
var timestampFn = typeof options.timestamp === 'function' ? options.timestamp : exports.timestamp,
timestamp = options.timestamp ? timestampFn() : null,
meta = options.meta ? exports.clone(options.meta) : null,
meta = options.meta ? exports.clone(cycle.decycle(options.meta)) : null,
output;

//
Expand Down
4 changes: 3 additions & 1 deletion lib/winston/transports/couchdb.js
View file
Expand Up @@ -9,6 +9,7 @@
var events = require('events'),
http = require('http'),
util = require('util'),
cycle = require('cycle'),
common = require('../common'),
Transport = require('./transport').Transport;

Expand Down Expand Up @@ -66,6 +67,7 @@ Couchdb.prototype.log = function (level, msg, meta, callback) {
}

var self = this,
meta = cycle.decycle(meta),
message = common.clone(meta || {}),
options,
req;
Expand Down Expand Up @@ -119,4 +121,4 @@ Couchdb.prototype.log = function (level, msg, meta, callback) {

// Always return true, regardless of any errors
callback(null, true);
};
};
2 changes: 2 additions & 0 deletions lib/winston/transports/webhook.js
View file
Expand Up @@ -10,6 +10,7 @@ var events = require('events'),
http = require('http'),
https = require('https'),
util = require('util'),
cycle = require('cycle'),
common = require('../common'),
Transport = require('./transport').Transport;

Expand Down Expand Up @@ -67,6 +68,7 @@ Webhook.prototype.log = function (level, msg, meta, callback) {
}

var self = this,
meta = cycle.decycle(meta),
message = common.clone(meta),
options,
req;
Expand Down
3 changes: 2 additions & 1 deletion package.json
View file
Expand Up @@ -18,7 +18,8 @@
"eyes": "0.1.x",
"loggly": "0.3.x >=0.3.7",
"pkginfo": "0.2.x",
"stack-trace": "0.0.x"
"stack-trace": "0.0.x",
"cycle": "1.0.x"
},
"devDependencies": {
"vows": "0.6.x"
Expand Down

8 comments on commit 7e74435

@indexzero
Copy link
Member

Choose a reason for hiding this comment

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

@coderarity @dscape Do we have any idea of the performance implications of cycle.decycle? It's important to fix bugs, but this change hits the hot paths of all transports.

For example, if the performance of logging was impacted significantly I would prefer to just be explicit about not supporting cyclical JSON.

@coderarity
Copy link
Contributor Author

Choose a reason for hiding this comment

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

I think it's very similar to common.clone, except it deals with circular references well. Here's an option like util.inspect, but it doesn't allow you to put the object back like it was before like decycle does.

@coderarity
Copy link
Contributor Author

Choose a reason for hiding this comment

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

(the use case for this was a mongoose model, which you would have reason to put back like it was to make it usable)

@dscape
Copy link

@dscape dscape commented on 7e74435 May 4, 2012

Choose a reason for hiding this comment

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

Have no idea on performance, my guess: Pretty bad?

I would suggest making this an option

{ decycle: true }

And making that false by default, change it if people ask for a new default and don't mind the penalty.

@coderarity
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Make that a transport option? I can do that.

@coderarity
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Ok, I added an option in a branch for decycle here.

But I also created a benchmark that you can try comparing our clone method vs the decycle method. The decycle method takes twice as long, but with a reasonably sized meta object, that equates to a very small time difference (about 0.000006s). So, I'm not sure that we should be concerned with performance in this case.

@indexzero
Copy link
Member

Choose a reason for hiding this comment

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

@coderarity Now do the math with concurrency.

The time difference per logging statement, t(dc) is 0.000006. A nodejs process is running at (lets say) 1500 requests per second. A common use-case for winston is to log data about each request. In fact, often a single request will have multiple logging statements per request. For the sake of argument, lets say 5:

1500 (req) * 5 (log / req) * 0.000006 (sec / log) = 0.045 seconds.

Now we had already established that before it took 1 second (i.e. "per second") so the new speed relative to the old speed is:

(1 / 1.045) * 100% = 95.69%

So in a pretty average node web server process this change introduces a 4.31% slowdown. This is totally unacceptable. We can't be this slow. Make it an option which is configurable and turned off by default.

@coderarity
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Ok, well, I've got a branch with the options. Can you review it? https://github.com/flatiron/winston/tree/fix-decycle

Please sign in to comment.