overleaf/services/real-time/app/coffee/EventLogger.coffee

61 lines
2.1 KiB
CoffeeScript
Raw Normal View History

2019-03-19 06:55:12 -04:00
logger = require 'logger-sharelatex'
2019-03-21 10:56:31 -04:00
metrics = require 'metrics-sharelatex'
2019-04-11 10:00:25 -04:00
settings = require 'settings-sharelatex'
2019-03-19 06:55:12 -04:00
# keep track of message counters to detect duplicate and out of order events
# messsage ids have the format "UNIQUEHOSTKEY-COUNTER"
EVENT_LOG_COUNTER = {}
EVENT_LOG_TIMESTAMP = {}
2019-03-21 10:48:51 -04:00
EVENT_LAST_CLEAN_TIMESTAMP = 0
2019-03-19 06:55:12 -04:00
2019-04-11 10:00:25 -04:00
# counter for debug logs
COUNTER = 0
2019-03-19 06:55:12 -04:00
module.exports = EventLogger =
MAX_STALE_TIME_IN_MS: 3600 * 1000
2019-04-11 10:00:25 -04:00
debugEvent: (channel, message) ->
if settings.debugEvents > 0
logger.log {channel:channel, message:message, counter: COUNTER++}, "logging event"
settings.debugEvents--
2019-03-21 10:56:31 -04:00
checkEventOrder: (channel, message_id, message) ->
2019-03-19 06:55:12 -04:00
return if typeof(message_id) isnt 'string'
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
2019-03-19 06:55:12 -04:00
return
# store the last count in a hash for each host
previous = EventLogger._storeEventCount(key, count)
if !previous? || count == (previous + 1)
2019-03-22 07:18:34 -04:00
metrics.inc "event.#{channel}.valid", 0.001 # downsample high rate docupdater events
2019-03-19 06:55:12 -04:00
return # order is ok
if (count == previous)
2019-03-21 10:56:31 -04:00
metrics.inc "event.#{channel}.duplicate"
2019-04-11 11:25:42 -04:00
if Math.random() < 0.01
logger.warn {channel:channel, message_id:message_id}, "duplicate event (sampled at 1%)"
2019-03-19 06:55:12 -04:00
return "duplicate"
else
2019-03-21 10:56:31 -04:00
metrics.inc "event.#{channel}.out-of-order"
2019-04-11 11:25:42 -04:00
# logger.warn {channel:channel, message_id:message_id, key:key, previous: previous, count:count}, "out of order event"
return "out-of-order"
2019-03-19 06:55:12 -04:00
_storeEventCount: (key, count) ->
previous = EVENT_LOG_COUNTER[key]
now = Date.now()
EVENT_LOG_COUNTER[key] = count
EVENT_LOG_TIMESTAMP[key] = now
# periodically remove old counts
2019-03-21 10:48:51 -04:00
if (now - EVENT_LAST_CLEAN_TIMESTAMP) > EventLogger.MAX_STALE_TIME_IN_MS
2019-03-19 06:55:12 -04:00
EventLogger._cleanEventStream(now)
2019-03-21 10:48:51 -04:00
EVENT_LAST_CLEAN_TIMESTAMP = now
2019-03-19 06:55:12 -04:00
return previous
_cleanEventStream: (now) ->
for key, timestamp of EVENT_LOG_TIMESTAMP
if (now - timestamp) > EventLogger.MAX_STALE_TIME_IN_MS
delete EVENT_LOG_COUNTER[key]
delete EVENT_LOG_TIMESTAMP[key]