From f6b2ac73609faa5f7b031dd73af3279c1f8f7f6f Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Wed, 25 Sep 2019 16:42:49 +0100 Subject: [PATCH 01/14] queue deletes for deferred processing --- services/document-updater/app.coffee | 2 + .../app/coffee/DeleteQueueManager.coffee | 45 +++++++++++++++++++ .../app/coffee/HttpController.coffee | 41 ++++++++++++++--- .../app/coffee/ProjectManager.coffee | 16 +++++++ .../app/coffee/RedisManager.coffee | 24 ++++++++++ .../config/settings.defaults.coffee | 1 + .../coffee/DeletingAProjectTests.coffee | 8 +++- .../coffee/helpers/DocUpdaterClient.coffee | 3 ++ .../HttpController/HttpControllerTests.coffee | 11 ++--- 9 files changed, 138 insertions(+), 13 deletions(-) create mode 100644 services/document-updater/app/coffee/DeleteQueueManager.coffee diff --git a/services/document-updater/app.coffee b/services/document-updater/app.coffee index 6c1d8d1136..2962860027 100644 --- a/services/document-updater/app.coffee +++ b/services/document-updater/app.coffee @@ -55,6 +55,7 @@ app.post '/project/:project_id/doc/:doc_id', HttpCont app.post '/project/:project_id/doc/:doc_id/flush', HttpController.flushDocIfLoaded app.delete '/project/:project_id/doc/:doc_id', HttpController.flushAndDeleteDoc app.delete '/project/:project_id', HttpController.deleteProject +app.delete '/project', HttpController.deleteMultipleProjects app.post '/project/:project_id', HttpController.updateProject app.post '/project/:project_id/history/resync', HttpController.resyncProjectHistory app.post '/project/:project_id/flush', HttpController.flushProject @@ -63,6 +64,7 @@ app.post '/project/:project_id/doc/:doc_id/change/accept', HttpCont app.del '/project/:project_id/doc/:doc_id/comment/:comment_id', HttpController.deleteComment app.get '/flush_all_projects', HttpController.flushAllProjects +app.get '/flush_queued_projects', HttpController.flushQueuedProjects app.get '/total', (req, res)-> timer = new Metrics.Timer("http.allDocList") diff --git a/services/document-updater/app/coffee/DeleteQueueManager.coffee b/services/document-updater/app/coffee/DeleteQueueManager.coffee new file mode 100644 index 0000000000..0a122369c3 --- /dev/null +++ b/services/document-updater/app/coffee/DeleteQueueManager.coffee @@ -0,0 +1,45 @@ +RedisManager = require "./RedisManager" +ProjectManager = require "./ProjectManager" +logger = require "logger-sharelatex" +metrics = require "./Metrics" +async = require "async" + +module.exports = DeleteQueueManager = + flushAndDeleteOldProjects: (options, callback) -> + startTime = Date.now() + count = 0 + + flushProjectIfNotModified = (project_id, flushTimestamp, cb) -> + ProjectManager.getProjectDocsTimestamps project_id, (err, timestamps) -> + return callback(err) if err? + if !timestamps? + logger.log {project_id}, "skipping flush of queued project - no timestamps" + return cb() + # are any of the timestamps newer than the time the project was flushed? + for timestamp in timestamps or [] when timestamp > flushTimestamp + metrics.inc "queued-delete-skipped" + logger.debug {project_id, timestamps, flushTimestamp}, "found newer timestamp, will skip delete" + return cb() + logger.log {project_id, flushTimestamp}, "flushing queued project" + ProjectManager.flushAndDeleteProjectWithLocks project_id, {skip_history_flush: true}, (err) -> + logger.err {project_id, err}, "error flushing queued project" + metrics.inc "queued-delete-completed" + return cb(null, true) + + flushNextProject = () -> + now = Date.now() + if now - startTime > options.timeout + logger.log "hit time limit on flushing old projects" + return callback() + if count > options.limit + logger.log "hit count limit on flushing old projects" + return callback() + cutoffTime = now - options.min_delete_age + RedisManager.getNextProjectToFlushAndDelete cutoffTime, (err, project_id, flushTimestamp) -> + return callback(err) if err? + return callback() if !project_id? + flushProjectIfNotModified project_id, flushTimestamp, (err, flushed) -> + count++ if flushed + flushNextProject() + + flushNextProject() \ No newline at end of file diff --git a/services/document-updater/app/coffee/HttpController.coffee b/services/document-updater/app/coffee/HttpController.coffee index d2ef5043d0..96595c3449 100644 --- a/services/document-updater/app/coffee/HttpController.coffee +++ b/services/document-updater/app/coffee/HttpController.coffee @@ -5,7 +5,8 @@ Errors = require "./Errors" logger = require "logger-sharelatex" Metrics = require "./Metrics" ProjectFlusher = require("./ProjectFlusher") - +DeleteQueueManager = require("./DeleteQueueManager") +async = require "async" TWO_MEGABYTES = 2 * 1024 * 1024 @@ -130,14 +131,30 @@ module.exports = HttpController = deleteProject: (req, res, next = (error) ->) -> project_id = req.params.project_id logger.log project_id: project_id, "deleting project via http" - timer = new Metrics.Timer("http.deleteProject") options = {} options.background = true if req.query?.background # allow non-urgent flushes to be queued options.skip_history_flush = true if req.query?.shutdown # don't flush history when realtime shuts down - ProjectManager.flushAndDeleteProjectWithLocks project_id, options, (error) -> - timer.done() + if req.query?.background + ProjectManager.queueFlushAndDeleteProject project_id, (error) -> + return next(error) if error? + logger.log project_id: project_id, "queue delete of project via http" + res.send 204 # No Content + else + timer = new Metrics.Timer("http.deleteProject") + ProjectManager.flushAndDeleteProjectWithLocks project_id, options, (error) -> + timer.done() + return next(error) if error? + logger.log project_id: project_id, "deleted project via http" + res.send 204 # No Content + + deleteMultipleProjects: (req, res, next = (error) ->) -> + project_ids = req.body?.project_ids || [] + logger.log project_ids: project_ids, "deleting multiple projects via http" + async.eachSeries project_ids, (project_id, cb) -> + logger.log project_id: project_id, "queue delete of project via http" + ProjectManager.queueFlushAndDeleteProject project_id, cb + , (error) -> return next(error) if error? - logger.log project_id: project_id, "deleted project via http" res.send 204 # No Content acceptChanges: (req, res, next = (error) ->) -> @@ -198,4 +215,16 @@ module.exports = HttpController = else res.send project_ids - + flushQueuedProjects: (req, res, next = (error) ->) -> + res.setTimeout(5 * 60 * 1000) + options = + limit : req.query.limit || 1000 + timeout: 5 * 60 * 1000 + dryRun : req.query.dryRun || false + min_delete_age: req.query.min_delete_age || 5 * 60 * 1000 + DeleteQueueManager.flushAndDeleteOldProjects options, (err, project_ids)-> + if err? + logger.err err:err, "error flushing old projects" + res.send 500 + else + res.send project_ids diff --git a/services/document-updater/app/coffee/ProjectManager.coffee b/services/document-updater/app/coffee/ProjectManager.coffee index 4271186b7a..ca077ff60b 100644 --- a/services/document-updater/app/coffee/ProjectManager.coffee +++ b/services/document-updater/app/coffee/ProjectManager.coffee @@ -72,6 +72,22 @@ module.exports = ProjectManager = else callback(null) + queueFlushAndDeleteProject: (project_id, callback = (error) ->) -> + RedisManager.queueFlushAndDeleteProject project_id, (error) -> + if error? + logger.error {project_id: project_id, error:error}, "error adding project to flush and delete queue" + return callback(error) + Metrics.inc "queued-delete" + callback() + + getProjectDocsTimestamps: (project_id, callback = (error) ->) -> + RedisManager.getDocIdsInProject project_id, (error, doc_ids) -> + return callback(error) if error? + return callback() if !doc_ids?.length + RedisManager.getDocTimestamps doc_ids, (error, timestamps) -> + return callback(error) if error? + callback(null, timestamps) + getProjectDocsAndFlushIfOld: (project_id, projectStateHash, excludeVersions = {}, _callback = (error, docs) ->) -> timer = new Metrics.Timer("projectManager.getProjectDocsAndFlushIfOld") callback = (args...) -> diff --git a/services/document-updater/app/coffee/RedisManager.coffee b/services/document-updater/app/coffee/RedisManager.coffee index 82b6caccd7..799d5a7fc1 100644 --- a/services/document-updater/app/coffee/RedisManager.coffee +++ b/services/document-updater/app/coffee/RedisManager.coffee @@ -287,6 +287,30 @@ module.exports = RedisManager = getDocIdsInProject: (project_id, callback = (error, doc_ids) ->) -> rclient.smembers keys.docsInProject(project_id: project_id), callback + getDocTimestamps: (doc_ids, callback = (error, result) ->) -> + # get lastupdatedat timestamps for an array of doc_ids + multi = rclient.multi() + for doc_id in doc_ids + multi.get keys.lastUpdatedAt(doc_id: doc_id) + multi.exec callback + + queueFlushAndDeleteProject: (project_id, callback) -> + rclient.zadd keys.flushAndDeleteQueue(), Date.now(), project_id, callback + + getNextProjectToFlushAndDelete: (cutoffTime, callback = (error, key, timestamp)->) -> + # find the oldest queued flsus + rclient.zrangebyscore keys.flushAndDeleteQueue(), 0, cutoffTime, "WITHSCORES", "LIMIT", 0, 1, (err, reply) -> + return callback(err) if err? + return callback() if !reply?.length + multi = rclient.multi() + multi.zrange keys.flushAndDeleteQueue(), 0, 0, "WITHSCORES" + multi.zremrangebyrank keys.flushAndDeleteQueue(), 0, 0 + multi.exec (err, reply) -> + return callback(err) if err? + return callback() if !reply?.length + [key, timestamp] = reply[0] + callback(null, key, timestamp) + _serializeRanges: (ranges, callback = (error, serializedRanges) ->) -> jsonRanges = JSON.stringify(ranges) if jsonRanges? and jsonRanges.length > MAX_RANGES_SIZE diff --git a/services/document-updater/config/settings.defaults.coffee b/services/document-updater/config/settings.defaults.coffee index 6801c62a8b..3a376e3e66 100755 --- a/services/document-updater/config/settings.defaults.coffee +++ b/services/document-updater/config/settings.defaults.coffee @@ -80,6 +80,7 @@ module.exports = lastUpdatedBy: ({doc_id}) -> "lastUpdatedBy:{#{doc_id}}" lastUpdatedAt: ({doc_id}) -> "lastUpdatedAt:{#{doc_id}}" pendingUpdates: ({doc_id}) -> "PendingUpdates:{#{doc_id}}" + flushAndDeleteQueue: () -> "DocUpdaterFlushAndDeleteQueue" redisOptions: keepAlive: 100 diff --git a/services/document-updater/test/acceptance/coffee/DeletingAProjectTests.coffee b/services/document-updater/test/acceptance/coffee/DeletingAProjectTests.coffee index cb1d3495d8..7012f22fdb 100644 --- a/services/document-updater/test/acceptance/coffee/DeletingAProjectTests.coffee +++ b/services/document-updater/test/acceptance/coffee/DeletingAProjectTests.coffee @@ -97,7 +97,7 @@ describe "Deleting a project", -> it "should flush each doc in project history", -> MockProjectHistoryApi.flushProject.calledWith(@project_id).should.equal true - describe "with the shutdown=true parameter from realtime", -> + describe "with the background=true parameter from realtime", -> before (done) -> sinon.spy MockWebApi, "setDocument" sinon.spy MockTrackChangesApi, "flushDoc" @@ -111,7 +111,11 @@ describe "Deleting a project", -> setTimeout () => DocUpdaterClient.deleteProjectOnShutdown @project_id, (error, res, body) => @statusCode = res.statusCode - done() + # after deleting the project and putting it in the queue, flush the queue + setTimeout () -> + DocUpdaterClient.flushOldProjects (error, res, body) => + done() + , 100 , 200 after -> diff --git a/services/document-updater/test/acceptance/coffee/helpers/DocUpdaterClient.coffee b/services/document-updater/test/acceptance/coffee/helpers/DocUpdaterClient.coffee index 9525cc27e9..17067b5bf4 100644 --- a/services/document-updater/test/acceptance/coffee/helpers/DocUpdaterClient.coffee +++ b/services/document-updater/test/acceptance/coffee/helpers/DocUpdaterClient.coffee @@ -78,6 +78,9 @@ module.exports = DocUpdaterClient = deleteProjectOnShutdown: (project_id, callback = () ->) -> request.del "http://localhost:3003/project/#{project_id}?background=true&shutdown=true", callback + flushOldProjects: (callback = () ->) -> + request.get "http://localhost:3003/flush_queued_projects?min_delete_age=1", callback + acceptChange: (project_id, doc_id, change_id, callback = () ->) -> request.post "http://localhost:3003/project/#{project_id}/doc/#{doc_id}/change/#{change_id}/accept", callback diff --git a/services/document-updater/test/unit/coffee/HttpController/HttpControllerTests.coffee b/services/document-updater/test/unit/coffee/HttpController/HttpControllerTests.coffee index c1f5c5eca8..b8ace494f5 100644 --- a/services/document-updater/test/unit/coffee/HttpController/HttpControllerTests.coffee +++ b/services/document-updater/test/unit/coffee/HttpController/HttpControllerTests.coffee @@ -14,6 +14,7 @@ describe "HttpController", -> "./ProjectManager": @ProjectManager = {} "logger-sharelatex" : @logger = { log: sinon.stub() } "./ProjectFlusher": {flushAllProjects:->} + "./DeleteQueueManager": @DeleteQueueManager = {} "./Metrics": @Metrics = {} "./Errors" : Errors @Metrics.Timer = class Timer @@ -343,15 +344,15 @@ describe "HttpController", -> it "should time the request", -> @Metrics.Timer::done.called.should.equal true - describe "with the shutdown=true option from realtime", -> + describe "with the background=true option from realtime", -> beforeEach -> - @ProjectManager.flushAndDeleteProjectWithLocks = sinon.stub().callsArgWith(2) + @ProjectManager.queueFlushAndDeleteProject = sinon.stub().callsArgWith(1) @req.query = {background:true, shutdown:true} @HttpController.deleteProject(@req, @res, @next) - it "should pass the skip_history_flush option when flushing the project", -> - @ProjectManager.flushAndDeleteProjectWithLocks - .calledWith(@project_id, {background:true, skip_history_flush:true}) + it "should queue the flush and delete", -> + @ProjectManager.queueFlushAndDeleteProject + .calledWith(@project_id) .should.equal true describe "when an errors occurs", -> From 83dd43b809c34b48fed8d37c5bb82bdfdd2211a0 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Wed, 25 Sep 2019 17:04:36 +0100 Subject: [PATCH 02/14] add metric for queue length --- .../document-updater/app/coffee/DeleteQueueManager.coffee | 4 +++- services/document-updater/app/coffee/RedisManager.coffee | 6 ++++-- 2 files changed, 7 insertions(+), 3 deletions(-) diff --git a/services/document-updater/app/coffee/DeleteQueueManager.coffee b/services/document-updater/app/coffee/DeleteQueueManager.coffee index 0a122369c3..cad65ae2f5 100644 --- a/services/document-updater/app/coffee/DeleteQueueManager.coffee +++ b/services/document-updater/app/coffee/DeleteQueueManager.coffee @@ -35,9 +35,11 @@ module.exports = DeleteQueueManager = logger.log "hit count limit on flushing old projects" return callback() cutoffTime = now - options.min_delete_age - RedisManager.getNextProjectToFlushAndDelete cutoffTime, (err, project_id, flushTimestamp) -> + RedisManager.getNextProjectToFlushAndDelete cutoffTime, (err, project_id, flushTimestamp, queueLength) -> return callback(err) if err? return callback() if !project_id? + logger.log {project_id, queueLength: queueLength}, "flushing queued project" + metrics.globalGauge "queued-flush-backlog", queueLength flushProjectIfNotModified project_id, flushTimestamp, (err, flushed) -> count++ if flushed flushNextProject() diff --git a/services/document-updater/app/coffee/RedisManager.coffee b/services/document-updater/app/coffee/RedisManager.coffee index 799d5a7fc1..f5530b99fd 100644 --- a/services/document-updater/app/coffee/RedisManager.coffee +++ b/services/document-updater/app/coffee/RedisManager.coffee @@ -298,18 +298,20 @@ module.exports = RedisManager = rclient.zadd keys.flushAndDeleteQueue(), Date.now(), project_id, callback getNextProjectToFlushAndDelete: (cutoffTime, callback = (error, key, timestamp)->) -> - # find the oldest queued flsus + # find the oldest queued flush rclient.zrangebyscore keys.flushAndDeleteQueue(), 0, cutoffTime, "WITHSCORES", "LIMIT", 0, 1, (err, reply) -> return callback(err) if err? return callback() if !reply?.length multi = rclient.multi() multi.zrange keys.flushAndDeleteQueue(), 0, 0, "WITHSCORES" multi.zremrangebyrank keys.flushAndDeleteQueue(), 0, 0 + multi.zcard keys.flushAndDeleteQueue() multi.exec (err, reply) -> return callback(err) if err? return callback() if !reply?.length [key, timestamp] = reply[0] - callback(null, key, timestamp) + queueLength = reply[2] + callback(null, key, timestamp, queueLength) _serializeRanges: (ranges, callback = (error, serializedRanges) ->) -> jsonRanges = JSON.stringify(ranges) From b49621b3e9da275018fadabe929c9729d382acf3 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Thu, 26 Sep 2019 10:14:49 +0100 Subject: [PATCH 03/14] add comments --- .../app/coffee/DeleteQueueManager.coffee | 15 +++++++++++++++ .../app/coffee/RedisManager.coffee | 8 +++++--- 2 files changed, 20 insertions(+), 3 deletions(-) diff --git a/services/document-updater/app/coffee/DeleteQueueManager.coffee b/services/document-updater/app/coffee/DeleteQueueManager.coffee index cad65ae2f5..835f718615 100644 --- a/services/document-updater/app/coffee/DeleteQueueManager.coffee +++ b/services/document-updater/app/coffee/DeleteQueueManager.coffee @@ -4,6 +4,21 @@ logger = require "logger-sharelatex" metrics = require "./Metrics" async = require "async" +# Maintain a sorted set of project flushAndDelete requests, ordered by timestamp +# (ZADD), and process them from oldest to newest. A flushAndDelete request comes +# from real-time and is triggered when a user leaves a project. +# +# The aim is to remove the project from redis 5 minutes after the last request +# if there has been no activity (document updates) in that time. If there is +# activity we can expect a further flushAndDelete request when the editing user +# leaves the project. +# +# If a new flushAndDelete request comes in while an existing request is already +# in the queue we update the timestamp as we can postpone flushing further. +# +# Documents are processed by checking the queue, seeing if the first entry is +# older than 5 minutes, and popping it from the queue in that case. + module.exports = DeleteQueueManager = flushAndDeleteOldProjects: (options, callback) -> startTime = Date.now() diff --git a/services/document-updater/app/coffee/RedisManager.coffee b/services/document-updater/app/coffee/RedisManager.coffee index f5530b99fd..7f62fe1e7e 100644 --- a/services/document-updater/app/coffee/RedisManager.coffee +++ b/services/document-updater/app/coffee/RedisManager.coffee @@ -295,17 +295,19 @@ module.exports = RedisManager = multi.exec callback queueFlushAndDeleteProject: (project_id, callback) -> + # store the project id in a sorted set ordered by time rclient.zadd keys.flushAndDeleteQueue(), Date.now(), project_id, callback getNextProjectToFlushAndDelete: (cutoffTime, callback = (error, key, timestamp)->) -> - # find the oldest queued flush + # find the oldest queued flush that is before the cutoff time rclient.zrangebyscore keys.flushAndDeleteQueue(), 0, cutoffTime, "WITHSCORES", "LIMIT", 0, 1, (err, reply) -> return callback(err) if err? - return callback() if !reply?.length + return callback() if !reply?.length # return if no projects ready to be processed + # pop the oldest entry (get and remove in a multi) multi = rclient.multi() multi.zrange keys.flushAndDeleteQueue(), 0, 0, "WITHSCORES" multi.zremrangebyrank keys.flushAndDeleteQueue(), 0, 0 - multi.zcard keys.flushAndDeleteQueue() + multi.zcard keys.flushAndDeleteQueue() # the total length of the queue (for metrics) multi.exec (err, reply) -> return callback(err) if err? return callback() if !reply?.length From 9f358ead9f304b066438360e88833130b3123c60 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Thu, 26 Sep 2019 10:55:05 +0100 Subject: [PATCH 04/14] add an acceptance test for flush with queue processing --- .../coffee/DeletingAProjectTests.coffee | 36 ++++++++++++++++++- 1 file changed, 35 insertions(+), 1 deletion(-) diff --git a/services/document-updater/test/acceptance/coffee/DeletingAProjectTests.coffee b/services/document-updater/test/acceptance/coffee/DeletingAProjectTests.coffee index 7012f22fdb..45aab847e3 100644 --- a/services/document-updater/test/acceptance/coffee/DeletingAProjectTests.coffee +++ b/services/document-updater/test/acceptance/coffee/DeletingAProjectTests.coffee @@ -97,7 +97,41 @@ describe "Deleting a project", -> it "should flush each doc in project history", -> MockProjectHistoryApi.flushProject.calledWith(@project_id).should.equal true - describe "with the background=true parameter from realtime", -> + describe "with the background=true parameter from realtime and no request to flush the queue", -> + before (done) -> + sinon.spy MockWebApi, "setDocument" + sinon.spy MockTrackChangesApi, "flushDoc" + sinon.spy MockProjectHistoryApi, "flushProject" + + async.series @docs.map((doc) => + (callback) => + DocUpdaterClient.preloadDoc @project_id, doc.id, callback + ), (error) => + throw error if error? + setTimeout () => + DocUpdaterClient.deleteProjectOnShutdown @project_id, (error, res, body) => + @statusCode = res.statusCode + done() + , 200 + + after -> + MockWebApi.setDocument.restore() + MockTrackChangesApi.flushDoc.restore() + MockProjectHistoryApi.flushProject.restore() + + it "should return a 204 status code", -> + @statusCode.should.equal 204 + + it "should not send any documents to the web api", -> + MockWebApi.setDocument.called.should.equal false + + it "should not flush any docs in track changes", -> + MockTrackChangesApi.flushDoc.called.should.equal false + + it "should not flush to project history", -> + MockProjectHistoryApi.flushProject.called.should.equal false + + describe "with the background=true parameter from realtime and a request to flush the queue", -> before (done) -> sinon.spy MockWebApi, "setDocument" sinon.spy MockTrackChangesApi, "flushDoc" From eae4b352ca6d526b220084faa8e9d704c39020b7 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Thu, 26 Sep 2019 14:59:03 +0100 Subject: [PATCH 05/14] remove unnecessary check --- services/document-updater/app/coffee/DeleteQueueManager.coffee | 2 +- services/document-updater/app/coffee/ProjectManager.coffee | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/services/document-updater/app/coffee/DeleteQueueManager.coffee b/services/document-updater/app/coffee/DeleteQueueManager.coffee index 835f718615..3c8af6cd84 100644 --- a/services/document-updater/app/coffee/DeleteQueueManager.coffee +++ b/services/document-updater/app/coffee/DeleteQueueManager.coffee @@ -31,7 +31,7 @@ module.exports = DeleteQueueManager = logger.log {project_id}, "skipping flush of queued project - no timestamps" return cb() # are any of the timestamps newer than the time the project was flushed? - for timestamp in timestamps or [] when timestamp > flushTimestamp + for timestamp in timestamps when timestamp > flushTimestamp metrics.inc "queued-delete-skipped" logger.debug {project_id, timestamps, flushTimestamp}, "found newer timestamp, will skip delete" return cb() diff --git a/services/document-updater/app/coffee/ProjectManager.coffee b/services/document-updater/app/coffee/ProjectManager.coffee index ca077ff60b..0d57687668 100644 --- a/services/document-updater/app/coffee/ProjectManager.coffee +++ b/services/document-updater/app/coffee/ProjectManager.coffee @@ -83,7 +83,7 @@ module.exports = ProjectManager = getProjectDocsTimestamps: (project_id, callback = (error) ->) -> RedisManager.getDocIdsInProject project_id, (error, doc_ids) -> return callback(error) if error? - return callback() if !doc_ids?.length + return callback(null, []) if !doc_ids?.length RedisManager.getDocTimestamps doc_ids, (error, timestamps) -> return callback(error) if error? callback(null, timestamps) From a709a0adaa954e2a634ac0ad571a4cddf196f4d0 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Thu, 26 Sep 2019 15:05:38 +0100 Subject: [PATCH 06/14] for simplicity keep the cutoff time the same while flushing the queue --- services/document-updater/app/coffee/DeleteQueueManager.coffee | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/services/document-updater/app/coffee/DeleteQueueManager.coffee b/services/document-updater/app/coffee/DeleteQueueManager.coffee index 3c8af6cd84..db69fa4b2f 100644 --- a/services/document-updater/app/coffee/DeleteQueueManager.coffee +++ b/services/document-updater/app/coffee/DeleteQueueManager.coffee @@ -22,6 +22,7 @@ async = require "async" module.exports = DeleteQueueManager = flushAndDeleteOldProjects: (options, callback) -> startTime = Date.now() + cutoffTime = startTime - options.min_delete_age count = 0 flushProjectIfNotModified = (project_id, flushTimestamp, cb) -> @@ -49,7 +50,6 @@ module.exports = DeleteQueueManager = if count > options.limit logger.log "hit count limit on flushing old projects" return callback() - cutoffTime = now - options.min_delete_age RedisManager.getNextProjectToFlushAndDelete cutoffTime, (err, project_id, flushTimestamp, queueLength) -> return callback(err) if err? return callback() if !project_id? From ba35c73cb65491e2d579492626b987d7c84a88d0 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Thu, 26 Sep 2019 15:18:10 +0100 Subject: [PATCH 07/14] add comment about ZPOPMIN --- services/document-updater/app/coffee/RedisManager.coffee | 1 + 1 file changed, 1 insertion(+) diff --git a/services/document-updater/app/coffee/RedisManager.coffee b/services/document-updater/app/coffee/RedisManager.coffee index 7f62fe1e7e..1490ac87f4 100644 --- a/services/document-updater/app/coffee/RedisManager.coffee +++ b/services/document-updater/app/coffee/RedisManager.coffee @@ -305,6 +305,7 @@ module.exports = RedisManager = return callback() if !reply?.length # return if no projects ready to be processed # pop the oldest entry (get and remove in a multi) multi = rclient.multi() + # Poor man's version of ZPOPMIN, which is only available in Redis 5. multi.zrange keys.flushAndDeleteQueue(), 0, 0, "WITHSCORES" multi.zremrangebyrank keys.flushAndDeleteQueue(), 0, 0 multi.zcard keys.flushAndDeleteQueue() # the total length of the queue (for metrics) From fc62abfcfafb0f16d8250708457cdb02e4126f18 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Thu, 26 Sep 2019 15:46:14 +0100 Subject: [PATCH 08/14] run flush of queued projects in the background --- .../app/coffee/DeleteQueueManager.coffee | 6 +++--- .../document-updater/app/coffee/HttpController.coffee | 10 +++++----- 2 files changed, 8 insertions(+), 8 deletions(-) diff --git a/services/document-updater/app/coffee/DeleteQueueManager.coffee b/services/document-updater/app/coffee/DeleteQueueManager.coffee index db69fa4b2f..568d71bcdc 100644 --- a/services/document-updater/app/coffee/DeleteQueueManager.coffee +++ b/services/document-updater/app/coffee/DeleteQueueManager.coffee @@ -46,13 +46,13 @@ module.exports = DeleteQueueManager = now = Date.now() if now - startTime > options.timeout logger.log "hit time limit on flushing old projects" - return callback() + return callback(null, count) if count > options.limit logger.log "hit count limit on flushing old projects" - return callback() + return callback(null, count) RedisManager.getNextProjectToFlushAndDelete cutoffTime, (err, project_id, flushTimestamp, queueLength) -> return callback(err) if err? - return callback() if !project_id? + return callback(null, count) if !project_id? logger.log {project_id, queueLength: queueLength}, "flushing queued project" metrics.globalGauge "queued-flush-backlog", queueLength flushProjectIfNotModified project_id, flushTimestamp, (err, flushed) -> diff --git a/services/document-updater/app/coffee/HttpController.coffee b/services/document-updater/app/coffee/HttpController.coffee index 96595c3449..537dbd4903 100644 --- a/services/document-updater/app/coffee/HttpController.coffee +++ b/services/document-updater/app/coffee/HttpController.coffee @@ -216,15 +216,15 @@ module.exports = HttpController = res.send project_ids flushQueuedProjects: (req, res, next = (error) ->) -> - res.setTimeout(5 * 60 * 1000) options = limit : req.query.limit || 1000 timeout: 5 * 60 * 1000 dryRun : req.query.dryRun || false min_delete_age: req.query.min_delete_age || 5 * 60 * 1000 - DeleteQueueManager.flushAndDeleteOldProjects options, (err, project_ids)-> + res.send 204 + # run the flush in the background + DeleteQueueManager.flushAndDeleteOldProjects options, (err, flushed)-> if err? logger.err err:err, "error flushing old projects" - res.send 500 - else - res.send project_ids + else + logger.log {flushed: flushed}, "flush of queued projects completed" From 8cdc8c410aa63f47eb49c5f58b8539214e34a85a Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Thu, 26 Sep 2019 15:46:45 +0100 Subject: [PATCH 09/14] fix error logging --- services/document-updater/app/coffee/DeleteQueueManager.coffee | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/services/document-updater/app/coffee/DeleteQueueManager.coffee b/services/document-updater/app/coffee/DeleteQueueManager.coffee index 568d71bcdc..e9f2346909 100644 --- a/services/document-updater/app/coffee/DeleteQueueManager.coffee +++ b/services/document-updater/app/coffee/DeleteQueueManager.coffee @@ -38,7 +38,8 @@ module.exports = DeleteQueueManager = return cb() logger.log {project_id, flushTimestamp}, "flushing queued project" ProjectManager.flushAndDeleteProjectWithLocks project_id, {skip_history_flush: true}, (err) -> - logger.err {project_id, err}, "error flushing queued project" + if err? + logger.err {project_id, err}, "error flushing queued project" metrics.inc "queued-delete-completed" return cb(null, true) From 3bc176259b450449ea7bb7322a4ca1b6bf8f03e9 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Thu, 26 Sep 2019 15:46:54 +0100 Subject: [PATCH 10/14] fix log line --- services/document-updater/app/coffee/HistoryManager.coffee | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/services/document-updater/app/coffee/HistoryManager.coffee b/services/document-updater/app/coffee/HistoryManager.coffee index 7cfafa9ba0..6b68b4b676 100644 --- a/services/document-updater/app/coffee/HistoryManager.coffee +++ b/services/document-updater/app/coffee/HistoryManager.coffee @@ -29,7 +29,7 @@ module.exports = HistoryManager = flushProjectChanges: (project_id, options, callback = (error) ->) -> return callback() if !Settings.apis?.project_history?.enabled if options.skip_history_flush - logger.log {project_id}, "skipping flush of project history from realtime shutdown" + logger.log {project_id}, "skipping flush of project history" return callback() url = "#{Settings.apis.project_history.url}/project/#{project_id}/flush" qs = {} From b7f3b848afee67b5dfc0c46348abb6f5c7b635ac Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Thu, 26 Sep 2019 15:50:55 +0100 Subject: [PATCH 11/14] remove unused dryRun option Co-Authored-By: Jakob Ackermann --- services/document-updater/app/coffee/HttpController.coffee | 1 - 1 file changed, 1 deletion(-) diff --git a/services/document-updater/app/coffee/HttpController.coffee b/services/document-updater/app/coffee/HttpController.coffee index 537dbd4903..cf1d5f9aca 100644 --- a/services/document-updater/app/coffee/HttpController.coffee +++ b/services/document-updater/app/coffee/HttpController.coffee @@ -219,7 +219,6 @@ module.exports = HttpController = options = limit : req.query.limit || 1000 timeout: 5 * 60 * 1000 - dryRun : req.query.dryRun || false min_delete_age: req.query.min_delete_age || 5 * 60 * 1000 res.send 204 # run the flush in the background From 0f0682df43aba15171601608fb76214c012f1e04 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Thu, 26 Sep 2019 15:58:22 +0100 Subject: [PATCH 12/14] allow flush to complete in acceptance test --- .../test/acceptance/coffee/DeletingAProjectTests.coffee | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/services/document-updater/test/acceptance/coffee/DeletingAProjectTests.coffee b/services/document-updater/test/acceptance/coffee/DeletingAProjectTests.coffee index 45aab847e3..91e4378dc2 100644 --- a/services/document-updater/test/acceptance/coffee/DeletingAProjectTests.coffee +++ b/services/document-updater/test/acceptance/coffee/DeletingAProjectTests.coffee @@ -148,7 +148,7 @@ describe "Deleting a project", -> # after deleting the project and putting it in the queue, flush the queue setTimeout () -> DocUpdaterClient.flushOldProjects (error, res, body) => - done() + setTimeout done, 1000 # allow time for the flush to complete , 100 , 200 From 7561e05660d5c6ec509211e3862ed6e0f405e994 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Fri, 27 Sep 2019 10:39:56 +0100 Subject: [PATCH 13/14] check timestamps array length --- services/document-updater/app/coffee/DeleteQueueManager.coffee | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/services/document-updater/app/coffee/DeleteQueueManager.coffee b/services/document-updater/app/coffee/DeleteQueueManager.coffee index e9f2346909..f1af0ba244 100644 --- a/services/document-updater/app/coffee/DeleteQueueManager.coffee +++ b/services/document-updater/app/coffee/DeleteQueueManager.coffee @@ -28,7 +28,7 @@ module.exports = DeleteQueueManager = flushProjectIfNotModified = (project_id, flushTimestamp, cb) -> ProjectManager.getProjectDocsTimestamps project_id, (err, timestamps) -> return callback(err) if err? - if !timestamps? + if timestamps.length == 0 logger.log {project_id}, "skipping flush of queued project - no timestamps" return cb() # are any of the timestamps newer than the time the project was flushed? From 260923f291ac65d31ae64cefaf0da84eb6dc8237 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Fri, 27 Sep 2019 10:46:24 +0100 Subject: [PATCH 14/14] keep flushQueuedProjects in the foreground --- services/document-updater/app/coffee/HttpController.coffee | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/services/document-updater/app/coffee/HttpController.coffee b/services/document-updater/app/coffee/HttpController.coffee index cf1d5f9aca..e2e2e712bc 100644 --- a/services/document-updater/app/coffee/HttpController.coffee +++ b/services/document-updater/app/coffee/HttpController.coffee @@ -216,14 +216,15 @@ module.exports = HttpController = res.send project_ids flushQueuedProjects: (req, res, next = (error) ->) -> + res.setTimeout(10 * 60 * 1000) options = limit : req.query.limit || 1000 timeout: 5 * 60 * 1000 min_delete_age: req.query.min_delete_age || 5 * 60 * 1000 - res.send 204 - # run the flush in the background DeleteQueueManager.flushAndDeleteOldProjects options, (err, flushed)-> if err? logger.err err:err, "error flushing old projects" - else + res.send 500 + else logger.log {flushed: flushed}, "flush of queued projects completed" + res.send {flushed: flushed}