From d771340847ccdb46b3cfb58c3e3207f49eebfc6b Mon Sep 17 00:00:00 2001 From: Alena Khineika Date: Fri, 7 Feb 2025 10:39:49 +0100 Subject: [PATCH 1/6] fix(mongodb-log-writer): issues with parallel mongosh executions MONGOSH-1914 --- .../src/mongo-log-manager.spec.ts | 25 ++++++ .../src/mongo-log-manager.ts | 81 +++++++++++-------- 2 files changed, 71 insertions(+), 35 deletions(-) diff --git a/packages/mongodb-log-writer/src/mongo-log-manager.spec.ts b/packages/mongodb-log-writer/src/mongo-log-manager.spec.ts index b4652864..b3b4966d 100644 --- a/packages/mongodb-log-writer/src/mongo-log-manager.spec.ts +++ b/packages/mongodb-log-writer/src/mongo-log-manager.spec.ts @@ -25,7 +25,9 @@ describe('MongoLogManager', function () { ); await fs.mkdir(directory, { recursive: true }); }); + afterEach(async function () { + sinon.restore(); await fs.rmdir(directory, { recursive: true }); }); @@ -213,4 +215,27 @@ describe('MongoLogManager', function () { writer.end(); await once(writer, 'finish'); }); + + it('retries cleaning up old log files', async function () { + const fakeDirHandle = { + [Symbol.asyncIterator]: () => { + throw Object.assign(new Error('File not found'), { code: 'ENOENT' }); + }, + close: sinon.stub().resolves(), + }; + + const opendirStub = sinon.stub(fs, 'opendir').resolves(fakeDirHandle as any); + sinon.replace(fs, 'opendir', opendirStub); + + retentionDays = 0.000001; // 86.4 ms + const manager = new MongoLogManager({ + directory, + retentionDays, + onwarn, + onerror, + }); + + await manager.cleanupOldLogFiles(); + expect(opendirStub).to.have.been.calledTwice; + }); }); diff --git a/packages/mongodb-log-writer/src/mongo-log-manager.ts b/packages/mongodb-log-writer/src/mongo-log-manager.ts index 487c6a2d..40a7b369 100644 --- a/packages/mongodb-log-writer/src/mongo-log-manager.ts +++ b/packages/mongodb-log-writer/src/mongo-log-manager.ts @@ -36,7 +36,7 @@ export class MongoLogManager { } /** Clean up log files older than `retentionDays`. */ - async cleanupOldLogFiles(maxDurationMs = 5_000): Promise { + async cleanupOldLogFiles(maxDurationMs = 5_000, remainingRetries = 1): Promise { const dir = this._options.directory; let dirHandle; try { @@ -56,43 +56,54 @@ export class MongoLogManager { fullPath: string; }>((a, b) => a.fileTimestamp - b.fileTimestamp); - for await (const dirent of dirHandle) { - // Cap the overall time spent inside this function. Consider situations like - // a large number of machines using a shared network-mounted $HOME directory - // where lots and lots of log files end up and filesystem operations happen - // with network latency. - if (Date.now() - deletionStartTimestamp > maxDurationMs) break; - - if (!dirent.isFile()) continue; - const { id } = - /^(?[a-f0-9]{24})_log(\.gz)?$/i.exec(dirent.name)?.groups ?? {}; - if (!id) continue; - const fileTimestamp = +new ObjectId(id).getTimestamp(); - const fullPath = path.join(dir, dirent.name); - let toDelete: string | undefined; - - // If the file is older than expected, delete it. If the file is recent, - // add it to the list of seen files, and if that list is too large, remove - // the least recent file we've seen so far. - if (fileTimestamp < deletionCutoffTimestamp) { - toDelete = fullPath; - } else if (this._options.maxLogFileCount) { - leastRecentFileHeap.push({ fullPath, fileTimestamp }); - if (leastRecentFileHeap.size() > this._options.maxLogFileCount) { - toDelete = leastRecentFileHeap.pop()?.fullPath; + try { + for await (const dirent of dirHandle) { + // Cap the overall time spent inside this function. Consider situations like + // a large number of machines using a shared network-mounted $HOME directory + // where lots and lots of log files end up and filesystem operations happen + // with network latency. + if (Date.now() - deletionStartTimestamp > maxDurationMs) break; + + if (!dirent.isFile()) continue; + const { id } = + /^(?[a-f0-9]{24})_log(\.gz)?$/i.exec(dirent.name)?.groups ?? {}; + if (!id) continue; + const fileTimestamp = +new ObjectId(id).getTimestamp(); + const fullPath = path.join(dir, dirent.name); + let toDelete: string | undefined; + + // If the file is older than expected, delete it. If the file is recent, + // add it to the list of seen files, and if that list is too large, remove + // the least recent file we've seen so far. + if (fileTimestamp < deletionCutoffTimestamp) { + toDelete = fullPath; + } else if (this._options.maxLogFileCount) { + leastRecentFileHeap.push({ fullPath, fileTimestamp }); + if (leastRecentFileHeap.size() > this._options.maxLogFileCount) { + toDelete = leastRecentFileHeap.pop()?.fullPath; + } } - } - - if (!toDelete) continue; - try { - await fs.unlink(toDelete); - // eslint-disable-next-line @typescript-eslint/no-explicit-any - } catch (err: any) { - if (err?.code !== 'ENOENT') { - // eslint-disable-next-line @typescript-eslint/no-unsafe-argument - this._options.onerror(err, fullPath); + + if (!toDelete) continue; + try { + await fs.unlink(toDelete); + // eslint-disable-next-line @typescript-eslint/no-explicit-any + } catch (err: any) { + if (err.code !== 'ENOENT') { + // eslint-disable-next-line @typescript-eslint/no-unsafe-argument + this._options.onerror(err, fullPath); + } } } + } catch (statErr: any) { + // Multiple processes may attempt to clean up log files in parallel. + // A situation can arise where one process tries to read a file + // that another process has already unlinked (see MONGOSH-1914). + // To handle such scenarios, we will catch lstat errors and retry cleaning up + // to let different processes reach out to different log files. + if (statErr.code === 'ENOENT' && remainingRetries > 0) { + await this.cleanupOldLogFiles(maxDurationMs, remainingRetries - 1); + } } } From a07e7027cd5812315ac75d88912803c09a4d46cb Mon Sep 17 00:00:00 2001 From: Alena Khineika Date: Fri, 7 Feb 2025 10:49:19 +0100 Subject: [PATCH 2/6] test: clean up --- packages/mongodb-log-writer/src/mongo-log-manager.spec.ts | 2 -- 1 file changed, 2 deletions(-) diff --git a/packages/mongodb-log-writer/src/mongo-log-manager.spec.ts b/packages/mongodb-log-writer/src/mongo-log-manager.spec.ts index b3b4966d..ade15f74 100644 --- a/packages/mongodb-log-writer/src/mongo-log-manager.spec.ts +++ b/packages/mongodb-log-writer/src/mongo-log-manager.spec.ts @@ -223,9 +223,7 @@ describe('MongoLogManager', function () { }, close: sinon.stub().resolves(), }; - const opendirStub = sinon.stub(fs, 'opendir').resolves(fakeDirHandle as any); - sinon.replace(fs, 'opendir', opendirStub); retentionDays = 0.000001; // 86.4 ms const manager = new MongoLogManager({ From 34a3e48b5f0161b8d7478cbda5dda5c9d3e24a25 Mon Sep 17 00:00:00 2001 From: Alena Khineika Date: Fri, 7 Feb 2025 14:04:10 +0100 Subject: [PATCH 3/6] feat: adjust maxDurationMs --- packages/mongodb-log-writer/src/mongo-log-manager.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/mongodb-log-writer/src/mongo-log-manager.ts b/packages/mongodb-log-writer/src/mongo-log-manager.ts index 40a7b369..a6a2dfc0 100644 --- a/packages/mongodb-log-writer/src/mongo-log-manager.ts +++ b/packages/mongodb-log-writer/src/mongo-log-manager.ts @@ -102,7 +102,7 @@ export class MongoLogManager { // To handle such scenarios, we will catch lstat errors and retry cleaning up // to let different processes reach out to different log files. if (statErr.code === 'ENOENT' && remainingRetries > 0) { - await this.cleanupOldLogFiles(maxDurationMs, remainingRetries - 1); + await this.cleanupOldLogFiles(maxDurationMs - Date.now() - deletionStartTimestamp, remainingRetries - 1); } } } From 478527aa088d122a4575b7f31ab63ea523466cff Mon Sep 17 00:00:00 2001 From: Alena Khineika Date: Tue, 11 Feb 2025 10:43:39 +0100 Subject: [PATCH 4/6] test: remove extra sinon restore after rebase --- packages/mongodb-log-writer/src/mongo-log-manager.spec.ts | 1 - 1 file changed, 1 deletion(-) diff --git a/packages/mongodb-log-writer/src/mongo-log-manager.spec.ts b/packages/mongodb-log-writer/src/mongo-log-manager.spec.ts index c8381536..9f9848c7 100644 --- a/packages/mongodb-log-writer/src/mongo-log-manager.spec.ts +++ b/packages/mongodb-log-writer/src/mongo-log-manager.spec.ts @@ -28,7 +28,6 @@ describe('MongoLogManager', function () { }); afterEach(async function () { - sinon.restore(); await fs.rmdir(directory, { recursive: true }); sinon.restore(); }); From 3eab205b18db206b3e8ca5ff897d5c5cc93b2d52 Mon Sep 17 00:00:00 2001 From: Alena Khineika Date: Tue, 11 Feb 2025 11:40:01 +0100 Subject: [PATCH 5/6] Update packages/mongodb-log-writer/src/mongo-log-manager.ts Co-authored-by: Anna Henningsen --- packages/mongodb-log-writer/src/mongo-log-manager.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/mongodb-log-writer/src/mongo-log-manager.ts b/packages/mongodb-log-writer/src/mongo-log-manager.ts index f3e51a68..07b9f591 100644 --- a/packages/mongodb-log-writer/src/mongo-log-manager.ts +++ b/packages/mongodb-log-writer/src/mongo-log-manager.ts @@ -144,7 +144,7 @@ export class MongoLogManager { // To handle such scenarios, we will catch lstat errors and retry cleaning up // to let different processes reach out to different log files. if (statErr.code === 'ENOENT' && remainingRetries > 0) { - await this.cleanupOldLogFiles(maxDurationMs - Date.now() - deletionStartTimestamp, remainingRetries - 1); + await this.cleanupOldLogFiles(maxDurationMs - (Date.now() - deletionStartTimestamp), remainingRetries - 1); } } From 9c7853f9b8876912cc5c6743f60c6d31b8902d8a Mon Sep 17 00:00:00 2001 From: Alena Khineika Date: Tue, 11 Feb 2025 11:42:40 +0100 Subject: [PATCH 6/6] refactor: compute deletionStartTimestamp and deletionCutoffTimestamp as the first thing --- packages/mongodb-log-writer/src/mongo-log-manager.ts | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/packages/mongodb-log-writer/src/mongo-log-manager.ts b/packages/mongodb-log-writer/src/mongo-log-manager.ts index 07b9f591..942a7521 100644 --- a/packages/mongodb-log-writer/src/mongo-log-manager.ts +++ b/packages/mongodb-log-writer/src/mongo-log-manager.ts @@ -63,6 +63,11 @@ export class MongoLogManager { /** Clean up log files older than `retentionDays`. */ async cleanupOldLogFiles(maxDurationMs = 5_000, remainingRetries = 1): Promise { + const deletionStartTimestamp = Date.now(); + // Delete files older than N days + const deletionCutoffTimestamp = + deletionStartTimestamp - this._options.retentionDays * 86400 * 1000; + const dir = this._options.directory; let dirHandle; try { @@ -71,10 +76,6 @@ export class MongoLogManager { return; } - const deletionStartTimestamp = Date.now(); - // Delete files older than N days - const deletionCutoffTimestamp = - deletionStartTimestamp - this._options.retentionDays * 86400 * 1000; // Store the known set of least recent files in a heap in order to be able to // delete all but the most recent N files. const leastRecentFileHeap = new Heap<{