Log entries may be show up in the wrong order (#1815)

If a timestamp doesn't exist on the Log Entry, the Logging service
inserts a timestamp based on the time it receives the message. Local
and network queuing / latency may cause logs to be delivered in an
order different from the originating source.

Attaching a timestamp at Entry creation time makes avoids this
problem.

Author: ofrobots

handwritten/logging/src/entry.js

@@ -83,7 +83,10 @@ var isCircular = require('is-circular');
  * });
  */
 function Entry(metadata, data) {
-  this.metadata = metadata;
+  this.metadata = extend({
+    timestamp: new Date()
+  }, metadata);
+
   this.data = data;
 }
 

handwritten/logging/system-test/logging.js

@@ -347,6 +347,28 @@ describe('Logging', function() {
       });
     });
 
+    it('should preserve order of entries', function(done) {
+      var entry1 = log.entry('1');
+
+      setTimeout(function() {
+        var entry3 = log.entry('3');
+        var entry2 = log.entry({ timestamp: entry3.metadata.timestamp }, '2');
+
+        // Re-arrange to confirm the timestamp is sent and honored.
+        log.write([entry2, entry3, entry1], options, function(err) {
+          assert.ifError(err);
+
+          setTimeout(function() {
+            log.getEntries({ pageSize: 3 }, function(err, entries) {
+              assert.ifError(err);
+              assert.deepEqual(entries.map(prop('data')), [ '3', '2', '1' ]);
+              done();
+            });
+          }, WRITE_CONSISTENCY_DELAY_MS);
+        });
+      }, 1000);
+    });
+
     it('should write an entry with primitive values', function(done) {
       var logEntry = log.entry({
         when: new Date(),

handwritten/logging/test/entry.js

@@ -44,8 +44,29 @@ describe('Entry', function() {
   });
 
   describe('instantiation', function() {
-    it('should localize metadata and data', function() {
-      assert.strictEqual(entry.metadata, METADATA);
+    it('should assign timestamp to metadata', function() {
+      var now = new Date();
+
+      var expectedTimestampBoundaries = {
+        start: new Date(now.getTime() - 1000),
+        end: new Date(now.getTime() + 1000)
+      };
+
+      assert(entry.metadata.timestamp >= expectedTimestampBoundaries.start);
+      assert(entry.metadata.timestamp <= expectedTimestampBoundaries.end);
+    });
+
+    it('should not assign timestamp if one is already set', function() {
+      var timestamp = new Date('2012');
+
+      var entry = new Entry({
+        timestamp: timestamp
+      });
+
+      assert.strictEqual(entry.metadata.timestamp, timestamp);
+    });
+
+    it('should localize data', function() {
       assert.strictEqual(entry.data, DATA);
     });
   });

handwritten/logging/test/log.js

@@ -19,6 +19,7 @@
 var assert = require('assert');
 var extend = require('extend');
 var GrpcServiceObject = require('@google-cloud/common').GrpcServiceObject;
+var prop = require('propprop');
 var proxyquire = require('proxyquire');
 var util = require('@google-cloud/common').util;
 
@@ -138,31 +139,21 @@ describe('Log', function() {
 
     it('should assign severity to a single entry', function() {
       assert.deepEqual(
-        Log.assignSeverityToEntries_(ENTRIES[0], SEVERITY),
-        [
-          extend(true, {}, ENTRIES[0], {
-            metadata: {
-              severity: SEVERITY
-            }
-          })
-        ]
+        Log.assignSeverityToEntries_(ENTRIES[0], SEVERITY)
+          .map(prop('metadata'))
+          .map(prop('severity')),
+        [ SEVERITY ]
       );
     });
 
     it('should assign severity property to multiple entries', function() {
       assert.deepEqual(
-        Log.assignSeverityToEntries_(ENTRIES, SEVERITY),
+        Log.assignSeverityToEntries_(ENTRIES, SEVERITY)
+          .map(prop('metadata'))
+          .map(prop('severity')),
         [
-          extend(true, {}, ENTRIES[0], {
-            metadata: {
-              severity: SEVERITY
-            }
-          }),
-          extend(true, {}, ENTRIES[1], {
-            metadata: {
-              severity: SEVERITY
-            }
-          })
+          SEVERITY,
+          SEVERITY
         ]
       );
     });