From 536decff7c876c471fa66ffaf1579fa50cc6be91 Mon Sep 17 00:00:00 2001 From: Leonardo Crauss Daronco Date: Fri, 14 Nov 2014 14:12:37 -0200 Subject: [PATCH] Webhooks: use winston for logging and rotate log files --- labs/bbb-callback/.gitignore | 1 + labs/bbb-callback/README.md | 13 +++++++++-- labs/bbb-callback/application.coffee | 1 + labs/bbb-callback/callback_emitter.coffee | 13 ++++++----- .../config/bbb-webhooks.logrotate | 8 +++++++ labs/bbb-callback/hook.coffee | 23 ++++++++++--------- labs/bbb-callback/id_mapping.coffee | 21 +++++++++-------- labs/bbb-callback/log/.gitkeep | 0 labs/bbb-callback/logger.coffee | 10 ++++++++ labs/bbb-callback/package.json | 3 ++- labs/bbb-callback/web_hooks.coffee | 15 ++++++------ labs/bbb-callback/web_server.coffee | 13 ++++++----- 12 files changed, 78 insertions(+), 43 deletions(-) create mode 100644 labs/bbb-callback/config/bbb-webhooks.logrotate create mode 100644 labs/bbb-callback/log/.gitkeep create mode 100644 labs/bbb-callback/logger.coffee diff --git a/labs/bbb-callback/.gitignore b/labs/bbb-callback/.gitignore index da92316c63..a058abd33c 100644 --- a/labs/bbb-callback/.gitignore +++ b/labs/bbb-callback/.gitignore @@ -3,3 +3,4 @@ *.log node_modules/ config_local.coffee +log/* diff --git a/labs/bbb-callback/README.md b/labs/bbb-callback/README.md index 0db7602436..46a4a3586a 100644 --- a/labs/bbb-callback/README.md +++ b/labs/bbb-callback/README.md @@ -229,7 +229,7 @@ More details * Hooks are only removed if a call to `/destroy` is made or if the callbacks for the hook fail too many times (~12) for a long period of time (~5min). They are never removed otherwise. Valid for both global hooks and hooks for specific meetings. * If a meeting is created while the webhooks app is down, callbacks will never be triggered for this meeting. The app needs to detect the create event (`meeting_created_message`) to have a mapping of internal to external meeting IDs. * Mappings are removed after 24 hours of inactivity. If there are no events at all for a given meeting, it will be assumed dead. This is done to prevent data from being stored forever on redis. -* External URLs are expected to respond with an HTTP status 200. Anything different from it will be considered an error and the callback will be called again. This includes URLs that redirect to some other place. +* External URLs are expected to respond with the HTTP status 200, 201 or 202. Anything different from these values will be considered an error and the callback will be called again. This includes URLs that redirect to some other place. Development ----------- @@ -296,7 +296,16 @@ sudo chown root:root /etc/monit/conf.d/bbb-webhooks Open the file and edit it. You might need to change things like the port used by the application. -8. Start the application: +8. Copy logrotate's configuration file and install it: + + ```bash +sudo cp config/bbb-webhooks.logrotate /etc/logrotate.d/bbb-webhooks +sudo chown root:root /etc/logrotate.d/bbb-webhooks +sudo chmod 644 /etc/logrotate.d/bbb-webhooks +sudo logrotate -s /var/lib/logrotate/status /etc/logrotate.d/bbb-webhooks + ``` + +9. Start the application: ```bash sudo service bbb-webhooks start diff --git a/labs/bbb-callback/application.coffee b/labs/bbb-callback/application.coffee index f3ab6a12e5..8046dedeb0 100644 --- a/labs/bbb-callback/application.coffee +++ b/labs/bbb-callback/application.coffee @@ -6,6 +6,7 @@ WebServer = require("./web_server") # Class that defines the application. Listens for events on redis and starts the # process to perform the callback calls. +# TODO: add port (-p) and log level (-l) to the command line args module.exports = class Application constructor: -> diff --git a/labs/bbb-callback/callback_emitter.coffee b/labs/bbb-callback/callback_emitter.coffee index 2d039bd05b..9ee20ad201 100644 --- a/labs/bbb-callback/callback_emitter.coffee +++ b/labs/bbb-callback/callback_emitter.coffee @@ -4,6 +4,7 @@ url = require('url') EventEmitter = require('events').EventEmitter config = require("./config") +Logger = require("./logger") Utils = require("./utils") # Use to perform a callback. Will try several times until the callback is @@ -33,7 +34,7 @@ module.exports = class CallbackEmitter extends EventEmitter # get the next interval we have to wait and schedule a new try interval = config.hooks.retryIntervals[@nextInterval] if interval? - console.log "xx> Trying the callback again in #{interval/1000.0} secs" + Logger.warn "xx> Trying the callback again in #{interval/1000.0} secs" @nextInterval++ @_scheduleNext(interval) @@ -67,13 +68,13 @@ module.exports = class CallbackEmitter extends EventEmitter request requestOptions, (error, response, body) -> # TODO: treat redirects - if error? or response.statusCode != 200 - console.log "xx> Error in the callback call to: [#{requestOptions.uri}] for #{simplifiedEvent(data.event)}" - console.log "xx> Error:", error - console.log "xx> Status:", response.statusCode + if error? or response.statusCode not in [200, 201, 202] + Logger.warn "xx> Error in the callback call to: [#{requestOptions.uri}] for #{simplifiedEvent(data.event)}" + Logger.warn "xx> Error:", error + Logger.warn "xx> Status:", response.statusCode callback error, false else - console.log "==> Successful callback call to: [#{requestOptions.uri}] for #{simplifiedEvent(data.event)}" + Logger.info "==> Successful callback call to: [#{requestOptions.uri}] for #{simplifiedEvent(data.event)}" callback null, true # A simple string that identifies the event diff --git a/labs/bbb-callback/config/bbb-webhooks.logrotate b/labs/bbb-callback/config/bbb-webhooks.logrotate new file mode 100644 index 0000000000..c01f43723b --- /dev/null +++ b/labs/bbb-callback/config/bbb-webhooks.logrotate @@ -0,0 +1,8 @@ +/usr/local/bigbluebutton/bbb-webhooks/log/*.log { + size 300M + copytruncate + rotate 30 + compress + missingok + notifempty +} diff --git a/labs/bbb-callback/hook.coffee b/labs/bbb-callback/hook.coffee index 49882fcd1e..8b2f6fe85f 100644 --- a/labs/bbb-callback/hook.coffee +++ b/labs/bbb-callback/hook.coffee @@ -5,6 +5,7 @@ redis = require("redis") config = require("./config") CallbackEmitter = require("./callback_emitter") IDMapping = require("./id_mapping") +Logger = require("./logger") # The database of hooks. # Used always from memory, but saved to redis for persistence. @@ -35,18 +36,18 @@ module.exports = class Hook save: (callback) -> @redisClient.hmset config.redis.keys.hook(@id), @toRedis(), (error, reply) => - console.log "Hook: error saving hook to redis!", error, reply if error? + Logger.error "Hook: error saving hook to redis!", error, reply if error? @redisClient.sadd config.redis.keys.hooks, @id, (error, reply) => - console.log "Hook: error saving hookID to the list of hooks!", error, reply if error? + Logger.error "Hook: error saving hookID to the list of hooks!", error, reply if error? db[@id] = this callback?(error, db[@id]) destroy: (callback) -> @redisClient.srem config.redis.keys.hooks, @id, (error, reply) => - console.log "Hook: error removing hookID from the list of hooks!", error, reply if error? + Logger.error "Hook: error removing hookID from the list of hooks!", error, reply if error? @redisClient.del config.redis.keys.hook(@id), (error) => - console.log "Hook: error removing hook from redis!", error if error? + Logger.error "Hook: error removing hook from redis!", error if error? if db[@id] delete db[@id] @@ -65,7 +66,7 @@ module.exports = class Hook # Puts a new message in the queue. Will also trigger a processing in the queue so this # message might be processed instantly. enqueue: (message) -> - console.log "Hook: enqueueing message", JSON.stringify(message) + Logger.info "Hook: enqueueing message", JSON.stringify(message) @queue.push message @_processQueue() @@ -100,7 +101,7 @@ module.exports = class Hook # gave up trying to perform the callback, remove the hook forever @emitter.on "stopped", (error) => - console.log "Hook: too many failed attempts to perform a callback call, removing the hook", JSON.stringify(hook) + Logger.warn "Hook: too many failed attempts to perform a callback call, removing the hook", JSON.stringify(hook) @destroy() @addSubscription = (callbackURL, meetingID=null, callback) -> @@ -110,7 +111,7 @@ module.exports = class Hook else msg = "Hook: adding a hook with callback URL [#{callbackURL}]" msg += " for the meeting [#{meetingID}]" if meetingID? - console.log msg + Logger.info msg hook = new Hook() hook.id = nextID++ @@ -123,7 +124,7 @@ module.exports = class Hook if hook? msg = "Hook: removing the hook with callback URL [#{hook.callbackURL}]" msg += " for the meeting [#{hook.externalMeetingID}]" if hook.externalMeetingID? - console.log msg + Logger.info msg hook.destroy (error, removed) -> callback?(error, removed) else @@ -179,12 +180,12 @@ module.exports = class Hook tasks = [] client.smembers config.redis.keys.hooks, (error, hooks) => - console.log "Hook: error getting list of hooks from redis", error if error? + Logger.error "Hook: error getting list of hooks from redis", error if error? hooks.forEach (id) => tasks.push (done) => client.hgetall config.redis.keys.hook(id), (error, hookData) -> - console.log "Hook: error getting information for a hook from redis", error if error? + Logger.error "Hook: error getting information for a hook from redis", error if error? if hookData? hook = new Hook() @@ -197,5 +198,5 @@ module.exports = class Hook async.series tasks, (errors, result) -> hooks = _.map(Hook.allSync(), (hook) -> "[#{hook.id}] #{hook.callbackURL}") - console.log "Hook: finished resync, hooks registered:", hooks + Logger.info "Hook: finished resync, hooks registered:", hooks callback?() diff --git a/labs/bbb-callback/id_mapping.coffee b/labs/bbb-callback/id_mapping.coffee index f162f0b9ab..74d704bc00 100644 --- a/labs/bbb-callback/id_mapping.coffee +++ b/labs/bbb-callback/id_mapping.coffee @@ -3,6 +3,7 @@ async = require("async") redis = require("redis") config = require("./config") +Logger = require("./logger") # The database of mappings. Uses the externalID as key because it changes less than # the internal ID (e.g. the internalID can change for different meetings in the same @@ -35,18 +36,18 @@ module.exports = class IDMapping save: (callback) -> @redisClient.hmset config.redis.keys.mapping(@id), @toRedis(), (error, reply) => - console.log "Hook: error saving mapping to redis!", error, reply if error? + Logger.error "Hook: error saving mapping to redis!", error, reply if error? @redisClient.sadd config.redis.keys.mappings, @id, (error, reply) => - console.log "Hook: error saving mapping ID to the list of mappings!", error, reply if error? + Logger.error "Hook: error saving mapping ID to the list of mappings!", error, reply if error? db[@externalMeetingID] = this callback?(error, db[@externalMeetingID]) destroy: (callback) -> @redisClient.srem config.redis.keys.mappings, @id, (error, reply) => - console.log "Hook: error removing mapping ID from the list of mappings!", error, reply if error? + Logger.error "Hook: error removing mapping ID from the list of mappings!", error, reply if error? @redisClient.del config.redis.keys.mapping(@id), (error) => - console.log "Hook: error removing mapping from redis!", error if error? + Logger.error "Hook: error removing mapping from redis!", error if error? if db[@externalMeetingID] delete db[@externalMeetingID] @@ -78,14 +79,14 @@ module.exports = class IDMapping mapping.externalMeetingID = externalMeetingID mapping.lastActivity = new Date().getTime() mapping.save (error, result) -> - console.log "IDMapping: added or changed meeting mapping to the list #{externalMeetingID}:", mapping.print() + Logger.info "IDMapping: added or changed meeting mapping to the list #{externalMeetingID}:", mapping.print() callback?(error, result) @removeMapping = (internalMeetingID, callback) -> for external, mapping of db if mapping.internalMeetingID is internalMeetingID mapping.destroy (error, result) -> - console.log "IDMapping: removing meeting mapping from the list #{external}:", mapping.print() + Logger.info "IDMapping: removing meeting mapping from the list #{external}:", mapping.print() callback?(error, result) @getInternalMeetingID = (externalMeetingID) -> @@ -125,7 +126,7 @@ module.exports = class IDMapping mapping.lastActivity < now - config.mappings.timeout ) unless _.isEmpty(toRemove) - console.log "IDMapping: expiring the mappings:", _.map(toRemove, (map) -> map.print()) + Logger.info "IDMapping: expiring the mappings:", _.map(toRemove, (map) -> map.print()) toRemove.forEach (mapping) -> mapping.destroy() # Initializes global methods for this model. @@ -140,12 +141,12 @@ module.exports = class IDMapping tasks = [] client.smembers config.redis.keys.mappings, (error, mappings) => - console.log "Hook: error getting list of mappings from redis", error if error? + Logger.error "Hook: error getting list of mappings from redis", error if error? mappings.forEach (id) => tasks.push (done) => client.hgetall config.redis.keys.mapping(id), (error, mappingData) -> - console.log "Hook: error getting information for a mapping from redis", error if error? + Logger.error "Hook: error getting information for a mapping from redis", error if error? if mappingData? mapping = new IDMapping() @@ -158,5 +159,5 @@ module.exports = class IDMapping async.series tasks, (errors, result) -> mappings = _.map(IDMapping.allSync(), (m) -> m.print()) - console.log "IDMapping: finished resync, mappings registered:", mappings + Logger.info "IDMapping: finished resync, mappings registered:", mappings callback?() diff --git a/labs/bbb-callback/log/.gitkeep b/labs/bbb-callback/log/.gitkeep new file mode 100644 index 0000000000..e69de29bb2 diff --git a/labs/bbb-callback/logger.coffee b/labs/bbb-callback/logger.coffee new file mode 100644 index 0000000000..3846611243 --- /dev/null +++ b/labs/bbb-callback/logger.coffee @@ -0,0 +1,10 @@ +winston = require("winston") + +logger = new (winston.Logger)( + transports: [ + new (winston.transports.Console)({ timestamp: true, colorize: true }), + new (winston.transports.File)({ filename: "log/application.log", timestamp: true }) + ] +) + +module.exports = logger diff --git a/labs/bbb-callback/package.json b/labs/bbb-callback/package.json index 282e709455..f77dfb3643 100755 --- a/labs/bbb-callback/package.json +++ b/labs/bbb-callback/package.json @@ -14,7 +14,8 @@ "lodash": "2.4.1", "async": "0.9.0", "express": "4.10.2", - "sha1": "1.1.0" + "sha1": "1.1.0", + "winston": "0.8.3" }, "engines": { "node": "0.10.26" diff --git a/labs/bbb-callback/web_hooks.coffee b/labs/bbb-callback/web_hooks.coffee index b15ebc02fb..2923f8f195 100644 --- a/labs/bbb-callback/web_hooks.coffee +++ b/labs/bbb-callback/web_hooks.coffee @@ -6,6 +6,7 @@ request = require("request") config = require("./config") Hook = require("./hook") IDMapping = require("./id_mapping") +Logger = require("./logger") # Web hooks will listen for events on redis coming from BigBlueButton and # perform HTTP calls with them to all registered hooks. @@ -24,7 +25,7 @@ module.exports = class WebHooks # Subscribe to the events on pubsub that might need to be sent in callback calls. _subscribeToEvents: -> @subscriberEvents.on "psubscribe", (channel, count) -> - console.log "WebHooks: subscribed to " + channel + Logger.info "WebHooks: subscribed to " + channel @subscriberEvents.on "pmessage", (pattern, channel, message) => try @@ -34,11 +35,11 @@ module.exports = class WebHooks IDMapping.reportActivity(id) if @_filterMessage(channel, message) - console.log "WebHooks: processing message on [#{channel}]:", JSON.stringify(message) + Logger.info "WebHooks: processing message on [#{channel}]:", JSON.stringify(message) @_processEvent(message) catch e - console.log "WebHooks: error processing the message", message, ":", e + Logger.error "WebHooks: error processing the message", message, ":", e @subscriberEvents.psubscribe config.hooks.pchannel @@ -64,17 +65,17 @@ module.exports = class WebHooks hooks = hooks.concat(Hook.findByExternalMeetingIDSync(eMeetingID)) hooks.forEach (hook) -> - console.log "WebHooks: enqueueing a message in the hook:", hook.callbackURL + Logger.info "WebHooks: enqueueing a message in the hook:", hook.callbackURL hook.enqueue message # Subscribe to the meeting events on pubsub to keep track of the mapping # of meeting IDs. _subscribeToMeetings: -> @subscriberMeetings.on "subscribe", (channel, count) -> - console.log "WebHooks: subscribed to meetings channel ", channel + Logger.info "WebHooks: subscribed to meetings channel ", channel @subscriberMeetings.on "message", (channel, message) => - console.log "WebHooks: got message on meetings channel [#{channel}]", message + Logger.info "WebHooks: got message on meetings channel [#{channel}]", message try message = JSON.parse(message) if message.header?.name is "meeting_created_message" @@ -83,6 +84,6 @@ module.exports = class WebHooks IDMapping.removeMapping(message.payload?.meeting_id) catch e - console.log "WebHooks: error processing the message", JSON.stringify(message), ":", e + Logger.error.log "WebHooks: error processing the message", JSON.stringify(message), ":", e @subscriberMeetings.subscribe config.hooks.meetingsChannel diff --git a/labs/bbb-callback/web_server.coffee b/labs/bbb-callback/web_server.coffee index 8124e93942..6164f4ecad 100644 --- a/labs/bbb-callback/web_server.coffee +++ b/labs/bbb-callback/web_server.coffee @@ -4,6 +4,7 @@ url = require("url") config = require("./config") Hook = require("./hook") +Logger = require("./logger") Utils = require("./utils") # Web server that listens for API calls and process them. @@ -16,16 +17,16 @@ module.exports = class WebServer start: (port) -> @server = @app.listen(port) unless @server.address()? - console.log "Could not bind to port", port - console.log "Aborting." + Logger.error "Could not bind to port", port + Logger.error "Aborting." process.exit(1) - console.log "== Server listening on port", port, "in", @app.settings.env.toUpperCase(), "mode" + Logger.info "Server listening on port", port, "in", @app.settings.env.toUpperCase(), "mode" _registerRoutes: -> # Request logger @app.all "*", (req, res, next) -> unless fromMonit(req) - console.log "<==", req.method, "request to", req.url, "from:", clientDataSimple(req) + Logger.info "<==", req.method, "request to", req.url, "from:", clientDataSimple(req) next() @app.get "/bigbluebutton/api/hooks/create", @_validateChecksum, @_create @@ -105,13 +106,13 @@ module.exports = class WebServer if checksum is Utils.checksumAPI(req.url, config.bbb.sharedSecret) next() else - console.log "checksum check failed, sending a checksumError response" + Logger.info "checksum check failed, sending a checksumError response" res.setHeader("Content-Type", "text/xml") res.send cleanupXML(config.api.responses.checksumError) respondWithXML = (res, msg) -> msg = cleanupXML(msg) - console.log "==> respond with:", msg + Logger.info "==> respond with:", msg res.setHeader("Content-Type", "text/xml") res.send msg