From a8dd29cd8291153f70cce0194b6f1bd0f941ef3a Mon Sep 17 00:00:00 2001 From: Pablo Carranza Velez Date: Wed, 13 Jul 2016 11:55:50 -0300 Subject: [PATCH 1/3] Change the logger to send at a specific interval and with a different message format Log messages to PubNub are now an array instead of an object. Each element of the array is an object with m (message), t (timestamp) and s (isSystem, optional) attributes. Logs are sent at a specific interval (110ms, fit with some margin to PubNub's approximated 10 messages/s limit), and truncated to PubNub's 32KB limit. --- CHANGELOG.md | 2 ++ src/application.coffee | 2 +- src/lib/logger.coffee | 41 +++++++++++++++++++++++++---------------- 3 files changed, 28 insertions(+), 17 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 04f48441..ecbaa29a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,5 @@ +* **[Breaking]** Change the logger to send at a specific interval and with a different message format [Pablo] + # v1.14.0 * Allow using an HTTP header for auth [Pablo] diff --git a/src/application.coffee b/src/application.coffee index e7a379be..b25fda5e 100644 --- a/src/application.coffee +++ b/src/application.coffee @@ -77,7 +77,7 @@ logTypes = humanName: 'Restarting application' logSystemMessage = (message, obj, eventName) -> - logger.log({ message, isSystem: true }) + logger.log({ m: message, s: true }) utils.mixpanelTrack(eventName ? message, obj) logSystemEvent = (logType, app, error) -> diff --git a/src/lib/logger.coffee b/src/lib/logger.coffee index eb6ae7b0..f5a438e2 100644 --- a/src/lib/logger.coffee +++ b/src/lib/logger.coffee @@ -5,6 +5,13 @@ Promise = require 'bluebird' es = require 'event-stream' Lock = require 'rwlock' +LOG_PUBLISH_INTERVAL = 110 + +# Pubnub's message size limit is 32KB (unclear on whether it's KB or actually KiB, +# but we'll be conservative). So we limit a log message to 2 bytes less to account +# for the [ and ] in the array. +MAX_LOG_BYTE_SIZE = 31998 + disableLogs = false initialised = new Promise (resolve) -> @@ -21,6 +28,7 @@ dockerPromise = initialised.then (config) -> # Queue up any calls to publish logs whilst we wait to be initialised. publish = do -> publishQueue = [] + publishQueueRemainingBytes = MAX_LOG_BYTE_SIZE initialised.then (config) -> if config.offlineMode @@ -29,25 +37,26 @@ publish = do -> return pubnub = PUBNUB.init(config.pubnub) channel = config.channel + doPublish = -> + return if publishQueue.length is 0 + pubnub.publish({ channel, message: publishQueue }) + publishQueue = [] + publishQueueRemainingBytes = MAX_LOG_BYTE_SIZE + setInterval(doPublish, LOG_PUBLISH_INTERVAL) - # Redefine original function - publish = (message) -> - # Disable sending logs for bandwidth control - return if disableLogs - if _.isString(message) - message = { message } + return (message) -> + # Disable sending logs for bandwidth control + return if disableLogs or publishQueueRemainingBytes <= 0 + if _.isString(message) + message = { m: message } - _.defaults message, - timestamp: Date.now() - # Stop pubnub logging loads of "Missing Message" errors, as they are quite distracting - message: ' ' + _.defaults message, + t: Date.now() + m: '' + msgLength = Buffer.byteLength(JSON.stringify(message), 'utf8') + publishQueueRemainingBytes -= msgLength + publishQueue.push(message) if publishQueueRemainingBytes >= 0 - pubnub.publish({ channel, message }) - - # Replay queue now that we have initialised the publish function - publish(args...) for args in publishQueue - - return -> publishQueue.push(arguments) # disable: A Boolean to pause the Log Publishing - Logs are lost when paused. exports.disableLogPublishing = (disable) -> From 78b4570b93cda9ae35c9678200568ae451638fd5 Mon Sep 17 00:00:00 2001 From: Pablo Carranza Velez Date: Tue, 19 Jul 2016 22:27:42 +0000 Subject: [PATCH 2/3] Allow storing several messages, will allow us to withstand log bursts better Also, send a warning message when we start dropping logs. --- src/application.coffee | 2 +- src/lib/logger.coffee | 36 +++++++++++++++++++++++++++--------- 2 files changed, 28 insertions(+), 10 deletions(-) diff --git a/src/application.coffee b/src/application.coffee index b25fda5e..0b99eedd 100644 --- a/src/application.coffee +++ b/src/application.coffee @@ -77,7 +77,7 @@ logTypes = humanName: 'Restarting application' logSystemMessage = (message, obj, eventName) -> - logger.log({ m: message, s: true }) + logger.log({ m: message, s: 1 }) utils.mixpanelTrack(eventName ? message, obj) logSystemEvent = (logType, app, error) -> diff --git a/src/lib/logger.coffee b/src/lib/logger.coffee index f5a438e2..15ab2099 100644 --- a/src/lib/logger.coffee +++ b/src/lib/logger.coffee @@ -11,6 +11,7 @@ LOG_PUBLISH_INTERVAL = 110 # but we'll be conservative). So we limit a log message to 2 bytes less to account # for the [ and ] in the array. MAX_LOG_BYTE_SIZE = 31998 +MAX_MESSAGE_INDEX = 9 disableLogs = false @@ -27,8 +28,10 @@ dockerPromise = initialised.then (config) -> # Queue up any calls to publish logs whilst we wait to be initialised. publish = do -> - publishQueue = [] + publishQueue = [[]] + messageIndex = 0 publishQueueRemainingBytes = MAX_LOG_BYTE_SIZE + logsOverflow = false initialised.then (config) -> if config.offlineMode @@ -38,15 +41,19 @@ publish = do -> pubnub = PUBNUB.init(config.pubnub) channel = config.channel doPublish = -> - return if publishQueue.length is 0 - pubnub.publish({ channel, message: publishQueue }) - publishQueue = [] - publishQueueRemainingBytes = MAX_LOG_BYTE_SIZE + return if publishQueue[0].length is 0 + message = publishQueue.shift() + pubnub.publish({ channel, message }) + if publishQueue.length is 0 + publishQueue = [[]] + publishQueueRemainingBytes = MAX_LOG_BYTE_SIZE + messageIndex = Math.max(messageIndex - 1, 0) + logsOverflow = false if messageIndex < MAX_MESSAGE_INDEX setInterval(doPublish, LOG_PUBLISH_INTERVAL) return (message) -> # Disable sending logs for bandwidth control - return if disableLogs or publishQueueRemainingBytes <= 0 + return if disableLogs or (messageIndex >= MAX_MESSAGE_INDEX and publishQueueRemainingBytes <= 0) if _.isString(message) message = { m: message } @@ -54,9 +61,20 @@ publish = do -> t: Date.now() m: '' msgLength = Buffer.byteLength(JSON.stringify(message), 'utf8') - publishQueueRemainingBytes -= msgLength - publishQueue.push(message) if publishQueueRemainingBytes >= 0 - + return if msgLength > MAX_LOG_BYTE_SIZE # Unlikely, but we can't allow this + remaining = publishQueueRemainingBytes - msgLength + if remaining >= 0 + publishQueue[messageIndex].push(message) + publishQueueRemainingBytes = remaining + else if messageIndex < MAX_MESSAGE_INDEX + messageIndex += 1 + publishQueue[messageIndex] = [ message ] + publishQueueRemainingBytes = MAX_LOG_BYTE_SIZE - msgLength + else if !logsOverflow + logsOverflow = true + messageIndex += 1 + publishQueue[messageIndex] = [ { m: 'Warning! Some logs dropped due to high load', t: Date.now(), s: 1 } ] + publishQueueRemainingBytes = 0 # disable: A Boolean to pause the Log Publishing - Logs are lost when paused. exports.disableLogPublishing = (disable) -> From ec178f7a7fc3ec062f26965f892ee968a6a2c4de Mon Sep 17 00:00:00 2001 From: Pablo Carranza Velez Date: Wed, 31 Aug 2016 16:28:42 +0000 Subject: [PATCH 3/3] Use a more conservative message size, and properly account for URI encoding --- src/lib/logger.coffee | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/lib/logger.coffee b/src/lib/logger.coffee index 15ab2099..6c2bd227 100644 --- a/src/lib/logger.coffee +++ b/src/lib/logger.coffee @@ -10,7 +10,7 @@ LOG_PUBLISH_INTERVAL = 110 # Pubnub's message size limit is 32KB (unclear on whether it's KB or actually KiB, # but we'll be conservative). So we limit a log message to 2 bytes less to account # for the [ and ] in the array. -MAX_LOG_BYTE_SIZE = 31998 +MAX_LOG_BYTE_SIZE = 30000 MAX_MESSAGE_INDEX = 9 disableLogs = false @@ -60,7 +60,7 @@ publish = do -> _.defaults message, t: Date.now() m: '' - msgLength = Buffer.byteLength(JSON.stringify(message), 'utf8') + msgLength = Buffer.byteLength(encodeURIComponent(JSON.stringify(message)), 'utf8') return if msgLength > MAX_LOG_BYTE_SIZE # Unlikely, but we can't allow this remaining = publishQueueRemainingBytes - msgLength if remaining >= 0