bunyan-rotating-file-stream - npm Package Compare versions

Comparing version 1.3.1 to 1.4.0

CHANGES.md

 # bunyan Changelog
 
+## 1.4.0
+- New feature to allow the user to specify the order the fields of the log records are written to the log file, this can make manual browsing of the files easier if you put the timestamp and other relevant information first.
+- Some clean ups and refactorings to try to remove some flags.
+
 ## 1.3.1
@@ -4,0 +8,0 @@

lib/limitedqueue.js

@@ -115,2 +115,6 @@ 'use strict';
 
+    function isEmpty() {
+        return queue.length() === 0;
+    }
+
     function paused() {
@@ -134,3 +138,4 @@ return queue.paused;
         unshift: queue.unshift,
-        join
+        join,
+        isEmpty
     }, base);
@@ -137,0 +142,0 @@ }

lib/rotatingfilestream.js

@@ -34,11 +34,74 @@ // A rotating file stream will just
 
-    var forceWrite = false;
+    // Copied from bunyan source
+    function safeCycles() {
+        var seen = [];
+        return function (key, val) {
+            if (!val || typeof (val) !== 'object') {
+                return val;
+            }
+            if (seen.indexOf(val) !== -1) {
+                return '[Circular]';
+            }
+            seen.push(val);
+            return val;
+        };
+    }
+
+    function nullJsonify(textlog) {
+        return textlog;
+    }
+
+    function fastJsonify(rawlog) {
+        return JSON.stringify(rawlog, safeCycles()) + '\n';
+    }
+
+    function fastUnsafeJsonify(rawlog) {
+        return JSON.stringify(rawlog) + '\n';
+    }
+
+    function orderedJsonify(rawlog) {
+        var log = {};
+
+        var fo = options.fieldOrder;
+
+        for (var sortIndex = 0; fo && sortIndex < fo.length; sortIndex += 1) {
+            if (rawlog.hasOwnProperty(options.fieldOrder[sortIndex])) {
+                log[fo[sortIndex]] = rawlog[fo[sortIndex]];
+            }
+        }
+
+        for (var k in rawlog) {
+            log[k] = rawlog[k];
+        }
+
+        return JSON.stringify(log, safeCycles()) + '\n';
+    }
+
+    function chooseJsonify(log) {
+        if (typeof (log) === 'string' && options.fieldOrder) {
+            base.emit(
+                'error',
+                'Can only set fieldOrder with the stream set to "raw"'
+            );
+        }
+
+        if (typeof (log) === 'string') {
+            jsonify = nullJsonify;
+        } else if (options.fieldOrder) {
+            jsonify = orderedJsonify;
+        } else if (options.noCyclesCheck) {
+            jsonify = fastUnsafeJsonify;
+        } else {
+            jsonify = fastJsonify;
+        }
+
+        return jsonify(log);
+    };
+
+    var jsonify = chooseJsonify;
+
     function writer(logs, callback) {
+        var written = -1; // the index of the last successful write
         for (var i = 0; stream && i < logs.length; i += 1) {
-            var str;
-            if (typeof (logs[i]) === 'string') {
-                str = logs[i];
-            } else {
-                str = JSON.stringify(logs[i], bunyan.safeCycles()) + '\n';
-            }
+            var str = jsonify(logs[i]);
 
@@ -49,25 +112,16 @@ var writeBuffer = new Buffer(str, 'utf8');
 
-            if (forceWrite) {
-                // This log entry gets written regardless - don't emit
-                forceWrite = false;
-            } else {
-                base.emit('data', { bytesWritten: streambytesWritten });
-            }
+            base.emit('data', { bytesWritten: streambytesWritten });
 
-            if (!stream) {
-                // This log entry caused a rotation
-                // We can't write it, force it to be written
-                // Next time round
-                forceWrite = true;
-                break;
-            }
-
-            try {
-                stream.write(writeBuffer, function (err) {
-                if (err) {
+            if (stream) {
+                try {
+                    stream.write(writeBuffer, function (err) {
+                        if (err) {
+                            base.emit('error', err);
+                        }
+                    });
+                } catch (err) {
                     base.emit('error', err);
                 }
-                });
-            } catch (err) {
-                base.emit('error', err);
+
+                written = i;
             }
@@ -78,3 +132,3 @@ }
         // records back onto our queue in reverse order
-        for (var rollback = logs.length -1; rollback >= i; rollback -= 1) {
+        for (var rollback = logs.length -1; rollback > written; rollback -= 1) {
             writeQueue.unshift(logs[rollback]);
@@ -124,11 +178,27 @@ }
 
-    var rotating = false;
-    function rotate() {
-        if (rotating) {
-            return;
-        } else {
-            rotating = true;
-        }
+    function rotateActual() {
 
-        rotator.rotate(function (err, newstream, filePath) {
+        rotateFunction = function () {};
+
+        async.parallel([
+            function waitForWrite(next) {
+                rotator.once('newfile', function () {
+                    if (writeQueue.isEmpty()) {
+                        // No logs to write, so we're all clear to allow
+                        // rotations again
+                        next();
+                    } else {
+                        // We've got some logs to write, ensure we get at least
+                        // one log record into the file before allowing
+                        // another rotation
+                        base.once('data', function (info) {
+                            next();
+                        });
+                    }
+                });
+            },
+            function doRotation(next) {
+                rotator.rotate(next);
+            }
+        ], function allowRotationsAgain(err) {
             if (err) {
@@ -138,6 +208,12 @@ base.emit('error', err);
 
-            rotating = false;
+            rotateFunction = rotateActual;
         });
     }
 
+    var rotateFunction = rotateActual;
+
+    function rotate() {
+        rotateFunction();
+    }
+
     function write(s, callback) {
@@ -144,0 +220,0 @@ writeQueue.push(s, callback);

package.json

 {
   "name": "bunyan-rotating-file-stream",
-  "version": "1.3.1",
+  "version": "1.4.0",
   "description": "a rotating file stream for the bunyan logging system",
@@ -19,3 +19,2 @@ "author": "Jim Tupper <[e-mail]> (http://github.com/rcomian)",
     "json",
-    "bunyan",
     "rotating",
@@ -22,0 +21,0 @@ "rotate"

README.md

@@ -25,2 +25,7 @@ Bunyan is **a simple and fast JSON logging library** for node.js services:
 
+## 1.4
+
+Allow an option to specify the order that fields can be written to the file. Purely for visual purposes.
+
+
 ## 1.3
@@ -35,12 +40,3 @@
 
-## 1.2
 
-- Support non-raw streams. For some reason, raw streams are MUCH faster in high load scenarios (at least when this is the only stream).
-- Better guarantees over file rollover - we will write exactly one log record that goes over the size threshold before we rotate
-  The previous performance release meant that we couldn't rotate until the write had completed to the disk - in the meantime several other
-  logs could have been written. This made everything unpredictable.
-- Making better use of the cargo datatype to write multiple log records in a single event loop tick.
-- Using setImmediate rather than process.nextTick in the write loop to allow io and other operations time to happen rather than hog the event loop.
-- Other refactorings and minor bug fixes.
-
 # Current Status
@@ -61,3 +57,3 @@
 
-# Features
+# Main Features
 
@@ -72,3 +68,3 @@ - Rotate to a new log file periodically (can also rotate on startup to clean old log files)
 
-## stream type: `rotating-file`
+## How to use
 
@@ -92,3 +88,3 @@ **WARNING on node 0.8 usage:** Users should use at
 Add this stream directly to the bunyan logger.
-The logger supports being both a raw and normal stream modes. Raw streams can be faster
+The stream supports being both a raw and normal stream modes. Raw streams can be faster
 under some high-load scenarios but may serialize the json differently to bunyan.
@@ -100,2 +96,3 @@
         streams: [{
+            type: 'raw',
             stream: new RotatingFileStream({
@@ -132,2 +129,3 @@ path: '/var/log/foo.log',
 </tr>
+<tr>
 <td>path</td>
@@ -174,2 +172,3 @@ <td>Yes</td>
 </tr>
+<tr>
 <td>totalSize</td>
@@ -189,25 +188,24 @@ <td>No</td>
 </tr>
-</table>
+<tr>
+<td>fieldOrder</td>
+<td>No</td>
+<td></td>
+<td><p>An array of string that specify the order the log parameters are written to the file.</p>
 
+<p>This option allows certain keys in the log fields to be written first for each log entry in the file.
+For example, if you use the value ['time'], the timestamp will appear on the left of each row.
+This doesn't affect how programs read each log record if they just JSON.parse each line at a time, it's
+purely for visual browsing when you scan through the text file.
+For this to work, the stream must be set to "raw" mode. You can't use this option without that setting.
+This option has a measurable performance impact as it's copying each log entry object, so be aware if you're
+using this in heavily loaded systems.</p>
 
-**Note on log rotation**: Often you may be using external log rotation utilities
-like `logrotate` on Linux or `logadm` on SmartOS/Illumos. In those cases, unless
-your are ensuring "copy and truncate" semantics (via `copytruncate` with
-logrotate or `-c` with logadm) then the fd for your 'file' stream will change.
-You can tell bunyan to reopen the file stream with code like this in your
-app:
+<p>*note* This feature currently works using an undocumented and un-guaranteed side effect of how serialisation
+works. It may break for a time on new versions of node if the internals of serialisation change how things work.
+In that case, the replacement code will likely be even slower.</p>
+</td>
+</tr>
+</table>
 
-```js
-var log = bunyan.createLogger(...);
-...
-process.on('SIGUSR2', function () {
-    log.reopenFileStreams();
-});
-```
 
-where you'd configure your log rotation to send SIGUSR2 (or some other signal)
-to your process. Any other mechanism to signal your app to run
-`log.reopenFileStreams()` would work as well.
-
-
 The scheme I follow is most succinctly described by the bootstrap guys
@@ -214,0 +212,0 @@ [here](https://github.com/twitter/bootstrap#versioning).

test-perf.js

@@ -86,3 +86,3 @@ var bunyan = require('bunyan');
         function (next) { runTest (name, {
-            stream: { path: name + '/test.log' },
+            stream: { path: name + '/test.log', noCyclesCheck: true },
             batch: { iterations: 1000000, size: 1000 }
@@ -89,0 +89,0 @@ }, next); },

test.js

@@ -26,2 +26,3 @@ var bunyan = require('bunyan');
         streams: [{
+            type: 'raw',
             stream: rfs
@@ -88,3 +89,3 @@ }]
         function (next) { runTest (name, {
-            stream: { path: name + '/test.log', threshold: '1m' },
+            stream: { path: name + '/test.log', threshold: '1m', fieldOrder: ['pid', 'time'] },
             batch: { iterations: 100000 }
@@ -142,2 +143,22 @@ }, next); },
 
+function timerotationnologging(next) {
+    var name = 'testlogs/' + 'timerotationnologging';
+
+    async.series([
+        function (next) { rmdir(name, ignoreMissing(next)); },
+        function (next) { fx.mkdir(name, next); },
+        function (next) { runTest (name, {
+            stream: { path: name + '/test.log', period: '1000ms' },
+            batch: { size: 0, duration: 9500 }
+        }, next); },
+        function (next) {
+            var files = fs.readdirSync(name);
+            assert.equal(10, files.length);
+            console.log(name, 'passed');
+            next();
+        },
+        function (next) { rmdir(name, ignoreMissing(next)); }
+    ], next);
+}
+
 function gzippedfiles(next) {
@@ -368,2 +389,3 @@ var name = 'testlogs/' + 'gzippedfiles';
     timerotation,
+    timerotationnologging,
     gzippedfiles,
@@ -370,0 +392,0 @@ totalsize,

No alert changes

Improved metrics

Total package byte prevSize

70075894

increased by21.89%

Number of package files

551

increased by1389.19%

Lines of code

1377

increased by6.5%

Worsened metrics

Number of lines in readme file

216

decreased by-0.92%

No dependency changes