From 695472a8aaad6ec72c2595a55e5c161833fa8894 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Fri, 22 Mar 2019 11:18:19 +0000 Subject: [PATCH 1/5] fix event id parsing to allow for dashes in keys --- services/real-time/app/coffee/EventLogger.coffee | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/services/real-time/app/coffee/EventLogger.coffee b/services/real-time/app/coffee/EventLogger.coffee index cf412c1904..1852f0d03d 100644 --- a/services/real-time/app/coffee/EventLogger.coffee +++ b/services/real-time/app/coffee/EventLogger.coffee @@ -14,8 +14,9 @@ module.exports = EventLogger = checkEventOrder: (channel, message_id, message) -> return if typeof(message_id) isnt 'string' - [key, count] = message_id.split("-", 2) - count = parseInt(count, 10) + return if !(result = message_id.match(/^(.*)-(\d+)$/)) + key = result[1] + count = parseInt(result[2], 0) if !(count >= 0)# ignore checks if counter is not present return # store the last count in a hash for each host From c5a09fcf0a78fe6adae0744cd1dfb9eefe5abf93 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Fri, 22 Mar 2019 11:18:34 +0000 Subject: [PATCH 2/5] add comment about downsampling --- services/real-time/app/coffee/EventLogger.coffee | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/services/real-time/app/coffee/EventLogger.coffee b/services/real-time/app/coffee/EventLogger.coffee index 1852f0d03d..bab9dbaa8c 100644 --- a/services/real-time/app/coffee/EventLogger.coffee +++ b/services/real-time/app/coffee/EventLogger.coffee @@ -22,7 +22,7 @@ module.exports = EventLogger = # store the last count in a hash for each host previous = EventLogger._storeEventCount(key, count) if !previous? || count == (previous + 1) - metrics.inc "event.#{channel}.valid", 0.001 + metrics.inc "event.#{channel}.valid", 0.001 # downsample high rate docupdater events return # order is ok if (count == previous) metrics.inc "event.#{channel}.duplicate" From 6c71ae172b7f0759a3c270f755134a5494a05dea Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Fri, 22 Mar 2019 11:19:08 +0000 Subject: [PATCH 3/5] return out of order events for consistency --- services/real-time/app/coffee/EventLogger.coffee | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/services/real-time/app/coffee/EventLogger.coffee b/services/real-time/app/coffee/EventLogger.coffee index bab9dbaa8c..3baf734ead 100644 --- a/services/real-time/app/coffee/EventLogger.coffee +++ b/services/real-time/app/coffee/EventLogger.coffee @@ -31,7 +31,7 @@ module.exports = EventLogger = else metrics.inc "event.#{channel}.out-of-order" # logger.error {key:key, previous: previous, count:count, message:message}, "events out of order" - return # out of order + return "out-of-order" _storeEventCount: (key, count) -> previous = EVENT_LOG_COUNTER[key] From efa83b4cdeabf42c2b38a8c47c4874056bd0e00a Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Fri, 22 Mar 2019 11:19:31 +0000 Subject: [PATCH 4/5] stub out eventlogger in unit test --- .../test/unit/coffee/DocumentUpdaterControllerTests.coffee | 1 + 1 file changed, 1 insertion(+) diff --git a/services/real-time/test/unit/coffee/DocumentUpdaterControllerTests.coffee b/services/real-time/test/unit/coffee/DocumentUpdaterControllerTests.coffee index fdd2f5fd5c..a2aee89cc0 100644 --- a/services/real-time/test/unit/coffee/DocumentUpdaterControllerTests.coffee +++ b/services/real-time/test/unit/coffee/DocumentUpdaterControllerTests.coffee @@ -22,6 +22,7 @@ describe "DocumentUpdaterController", -> @rclient = {} "./SafeJsonParse": @SafeJsonParse = parse: (data, cb) => cb null, JSON.parse(data) + "./EventLogger": @EventLogger = {checkEventOrder: sinon.stub()} describe "listenForUpdatesFromDocumentUpdater", -> beforeEach -> From 936311f1fb2ec043435b95c7d502350d8f07eef6 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Fri, 22 Mar 2019 11:20:38 +0000 Subject: [PATCH 5/5] fix eventlogger tests to use name with dashes --- .../test/unit/coffee/EventLoggerTests.coffee | 80 ++++++++++++------- 1 file changed, 52 insertions(+), 28 deletions(-) diff --git a/services/real-time/test/unit/coffee/EventLoggerTests.coffee b/services/real-time/test/unit/coffee/EventLoggerTests.coffee index ce955a8e7d..b0ba546067 100644 --- a/services/real-time/test/unit/coffee/EventLoggerTests.coffee +++ b/services/real-time/test/unit/coffee/EventLoggerTests.coffee @@ -11,9 +11,11 @@ describe 'EventLogger', -> tk.freeze(new Date(@start)) @EventLogger = SandboxedModule.require modulePath, requires: "logger-sharelatex": @logger = {error: sinon.stub()} - @id_1 = "abc-1" + "metrics-sharelatex": @metrics = {inc: sinon.stub()} + @channel = "applied-ops" + @id_1 = "random-hostname:abc-1" @message_1 = "message-1" - @id_2 = "abc-2" + @id_2 = "random-hostname:abc-2" @message_2 = "message-2" afterEach -> @@ -21,32 +23,54 @@ describe 'EventLogger', -> describe 'checkEventOrder', -> - it 'should accept events in order', -> - @EventLogger.checkEventOrder(@id_1, @message_1) - status = @EventLogger.checkEventOrder(@id_2, @message_2) - expect(status).to.be.undefined + describe 'when the events are in order', -> + beforeEach -> + @EventLogger.checkEventOrder(@channel, @id_1, @message_1) + @status = @EventLogger.checkEventOrder(@channel, @id_2, @message_2) - it 'should return "duplicate" for the same event', -> - @EventLogger.checkEventOrder(@id_1, @message_1) - status = @EventLogger.checkEventOrder(@id_1, @message_1) - expect(status).to.equal "duplicate" + it 'should accept events in order', -> + expect(@status).to.be.undefined - it 'should log an error for out of order events', -> - @EventLogger.checkEventOrder(@id_1, @message_1) - @EventLogger.checkEventOrder(@id_2, @message_2) - status = @EventLogger.checkEventOrder(@id_1, @message_1) - expect(status).to.be.undefined + it 'should increment the valid event metric', -> + @metrics.inc.calledWith("event.#{@channel}.valid", 1) + .should.equal.true - it 'should flush old entries', -> - @EventLogger.MAX_EVENTS_BEFORE_CLEAN = 10 - @EventLogger.checkEventOrder(@id_1, @message_1) - for i in [1..8] - status = @EventLogger.checkEventOrder(@id_1, @message_1) - expect(status).to.equal "duplicate" - # the next event should flush the old entries aboce - @EventLogger.MAX_STALE_TIME_IN_MS=1000 - tk.freeze(new Date(@start + 5 * 1000)) - # because we flushed the entries this should not be a duplicate - @EventLogger.checkEventOrder('other-1', @message_2) - status = @EventLogger.checkEventOrder(@id_1, @message_1) - expect(status).to.be.undefined \ No newline at end of file + describe 'when there is a duplicate events', -> + beforeEach -> + @EventLogger.checkEventOrder(@channel, @id_1, @message_1) + @status = @EventLogger.checkEventOrder(@channel, @id_1, @message_1) + + it 'should return "duplicate" for the same event', -> + expect(@status).to.equal "duplicate" + + it 'should increment the duplicate event metric', -> + @metrics.inc.calledWith("event.#{@channel}.duplicate", 1) + .should.equal.true + + describe 'when there are out of order events', -> + beforeEach -> + @EventLogger.checkEventOrder(@channel, @id_1, @message_1) + @EventLogger.checkEventOrder(@channel, @id_2, @message_2) + @status = @EventLogger.checkEventOrder(@channel, @id_1, @message_1) + + it 'should return "out-of-order" for the event', -> + expect(@status).to.equal "out-of-order" + + it 'should increment the out-of-order event metric', -> + @metrics.inc.calledWith("event.#{@channel}.out-of-order", 1) + .should.equal.true + + describe 'after MAX_STALE_TIME_IN_MS', -> + it 'should flush old entries', -> + @EventLogger.MAX_EVENTS_BEFORE_CLEAN = 10 + @EventLogger.checkEventOrder(@channel, @id_1, @message_1) + for i in [1..8] + status = @EventLogger.checkEventOrder(@channel, @id_1, @message_1) + expect(status).to.equal "duplicate" + # the next event should flush the old entries aboce + @EventLogger.MAX_STALE_TIME_IN_MS=1000 + tk.freeze(new Date(@start + 5 * 1000)) + # because we flushed the entries this should not be a duplicate + @EventLogger.checkEventOrder(@channel, 'other-1', @message_2) + status = @EventLogger.checkEventOrder(@channel, @id_1, @message_1) + expect(status).to.be.undefined \ No newline at end of file