From b7167552ecf066ba4fc339fdc7493bf9267e1e48 Mon Sep 17 00:00:00 2001 From: Laurent Cozic Date: Tue, 19 Apr 2022 15:52:32 +0100 Subject: [PATCH] Desktop: Enabled plugin throttling logic to prevent certain plugins from freezing the app --- packages/app-desktop/app.ts | 1 + .../services/plugins/BackOffHandler.ts | 45 +++++++++++-------- .../services/plugins/PluginRunner.ts | 2 + .../lib/services/plugins/BasePluginRunner.ts | 38 +++++++++++++++- .../lib/services/plugins/PluginService.ts | 4 ++ 5 files changed, 71 insertions(+), 19 deletions(-) diff --git a/packages/app-desktop/app.ts b/packages/app-desktop/app.ts index 05aeb6a9d..183291ba2 100644 --- a/packages/app-desktop/app.ts +++ b/packages/app-desktop/app.ts @@ -521,6 +521,7 @@ class Application extends BaseApplication { migrationService: MigrationService.instance(), decryptionWorker: DecryptionWorker.instance(), commandService: CommandService.instance(), + pluginService: PluginService.instance(), bridge: bridge(), debug: new DebugService(reg.db()), }; diff --git a/packages/app-desktop/services/plugins/BackOffHandler.ts b/packages/app-desktop/services/plugins/BackOffHandler.ts index 21f82e1af..5c1b69ef4 100644 --- a/packages/app-desktop/services/plugins/BackOffHandler.ts +++ b/packages/app-desktop/services/plugins/BackOffHandler.ts @@ -1,4 +1,5 @@ import Logger from '@joplin/lib/Logger'; +import time from '@joplin/lib/time'; const logger = Logger.create('BackOffHandler'); @@ -9,23 +10,39 @@ const logger = Logger.create('BackOffHandler'); // When a plugin needs to be throttled that way a warning is displayed so // that the author gets an opportunity to fix it. // -// 2. If the plugin makes many simultaneous calls (over 100), the handler throws -// an exception to stop the plugin. In that case the plugin will be broken, -// but most plugins will not get this error anyway because call are usually -// made in sequence. It might reveal a bug though - for example if the plugin +// 2. If the plugin makes many simultaneous calls, the handler throws an +// exception to stop the plugin. In that case the plugin will be broken, but +// most plugins will not get this error anyway because call are usually made +// in sequence. It might reveal a bug though - for example if the plugin // makes a call every 1 second, but does not wait for the response (or assume // the response will come in less than one second). In that case, the back // off intervals combined with the incorrect code will make the plugin fail. export default class BackOffHandler { - private backOffIntervals_ = Array(100).fill(0).concat([0, 1, 1, 2, 3, 5, 8]); + // The current logic is: + // + // - Up to 200 calls per 10 seconds without restrictions + // - For calls 200 to 300, a 1 second wait time is applied + // - Over 300 calls, a 2 seconds wait time is applied + // - After 10 seconds without making any call, the limits are reset (back to + // 0 second between calls). + // + // If more than 50 simultaneous calls are being throttled, it's a bug in the + // plugin (not waiting for API responses), so we stop responding and throw + // an error. + + private backOffIntervals_ = + Array(200).fill(0).concat( + Array(100).fill(1)).concat( + [2]); + private lastRequestTime_ = 0; private pluginId_: string; - private resetBackOffInterval_ = (this.backOffIntervals_[this.backOffIntervals_.length - 1] + 1) * 1000; + private resetBackOffInterval_ = 10 * 1000; // (this.backOffIntervals_[this.backOffIntervals_.length - 1] + 1) * 1000; private backOffIndex_ = 0; private waitCount_ = 0; - private maxWaitCount_ = 100; + private maxWaitCount_ = 50; public constructor(pluginId: string) { this.pluginId_ = pluginId; @@ -51,21 +68,13 @@ export default class BackOffHandler { this.waitCount_++; - // For now don't actually apply a backoff and don't abort. - logger.warn(`Plugin ${this.pluginId_}: Applying a backoff of ${interval} seconds due to frequent plugin API calls. Consider reducing the number of calls, caching the data, or requesting more data per call. API call was: `, path, args, `[Wait count: ${this.waitCount_}]`); - if (this.waitCount_ > this.maxWaitCount_) logger.error(`Plugin ${this.pluginId_}: More than ${this.maxWaitCount_} API alls are waiting - aborting. Please consider queuing the API calls in your plugins to reduce the load on the application.`); + if (this.waitCount_ > this.maxWaitCount_) throw new Error(`Plugin ${this.pluginId_}: More than ${this.maxWaitCount_} API calls are waiting - aborting. Please consider queuing the API calls in your plugins to reduce the load on the application.`); + + await time.sleep(interval); this.waitCount_--; - - - - // if (this.waitCount_ > this.maxWaitCount_) throw new Error(`Plugin ${this.pluginId_}: More than ${this.maxWaitCount_} API alls are waiting - aborting. Please consider queuing the API calls in your plugins to reduce the load on the application.`); - - // await time.sleep(interval); - - // this.waitCount_--; } } diff --git a/packages/app-desktop/services/plugins/PluginRunner.ts b/packages/app-desktop/services/plugins/PluginRunner.ts index 6931648de..946741860 100644 --- a/packages/app-desktop/services/plugins/PluginRunner.ts +++ b/packages/app-desktop/services/plugins/PluginRunner.ts @@ -157,6 +157,8 @@ export default class PluginRunner extends BasePluginRunner { const debugMappedArgs = fullPath.includes('setHtml') ? '' : mappedArgs; logger.debug(`Got message (3): ${fullPath}`, debugMappedArgs); + this.recordCallStat(plugin.id); + try { await this.backOffHandler(plugin.id).wait(fullPath, debugMappedArgs); } catch (error) { diff --git a/packages/lib/services/plugins/BasePluginRunner.ts b/packages/lib/services/plugins/BasePluginRunner.ts index fb0e43182..72bb459f5 100644 --- a/packages/lib/services/plugins/BasePluginRunner.ts +++ b/packages/lib/services/plugins/BasePluginRunner.ts @@ -4,7 +4,21 @@ import Global from './api/Global'; export default abstract class BasePluginRunner extends BaseService { - async run(plugin: Plugin, sandbox: Global): Promise { + // A dictionary with the plugin ID as key. Then each entry has a list + // of timestamp/call counts. + // + // 'org.joplinapp.plugins.ExamplePlugin': { + // 1650375620: 5, // 5 calls at second 1650375620 + // 1650375621: 19, // 19 calls at second 1650375621 + // 1650375623: 12, + // }, + // 'org.joplinapp.plugins.AnotherOne': { + // 1650375620: 1, + // 1650375623: 4, + // }; + private callStats_: Record> = {}; + + public async run(plugin: Plugin, sandbox: Global): Promise { throw new Error(`Not implemented: ${plugin} / ${sandbox}`); } @@ -12,4 +26,26 @@ export default abstract class BasePluginRunner extends BaseService { throw new Error('Not implemented: waitForSandboxCalls'); } + protected recordCallStat(pluginId: string) { + const timeSeconds = Math.floor(Date.now() / 1000); + if (!this.callStats_[pluginId]) this.callStats_[pluginId] = {}; + if (!this.callStats_[pluginId][timeSeconds]) this.callStats_[pluginId][timeSeconds] = 0; + this.callStats_[pluginId][timeSeconds]++; + } + + // Duration in seconds + public callStatsSummary(pluginId: string, duration: number): number[] { + const output: number[] = []; + + const startTime = Math.floor(Date.now() / 1000 - duration); + const endTime = startTime + duration; + + for (let t = startTime; t <= endTime; t++) { + const callCount = this.callStats_[pluginId][t]; + output.push(callCount ? callCount : 0); + } + + return output; + } + } diff --git a/packages/lib/services/plugins/PluginService.ts b/packages/lib/services/plugins/PluginService.ts index 97a9ec6b6..5a784a8cc 100644 --- a/packages/lib/services/plugins/PluginService.ts +++ b/packages/lib/services/plugins/PluginService.ts @@ -315,6 +315,10 @@ export default class PluginService extends BaseService { return settings[pluginId].enabled !== false; } + public callStatsSummary(pluginId: string, duration: number) { + return this.runner_.callStatsSummary(pluginId, duration); + } + public async loadAndRunPlugins(pluginDirOrPaths: string | string[], settings: PluginSettings, devMode: boolean = false) { let pluginPaths = [];