feat: add slow query logging

CONTRIBUTING.md

@@ -363,6 +363,22 @@ If the commit reverts a previous commit, use the prefix `revert:`, followed by t
   This reverts commit 1234567890abcdef.
   ```
 
+⚠️ A `revert` prefix will *always* trigger a release. Generally, a commit that did not trigger a release when it was initially merged should also not trigger a release when it is reverted. For example, do not use the `revert` prefix when reverting a commit that has a `ci` prefix:
+
+  ```
+  ci: add something
+  ```
+  is reverted with:
+  ```
+  ci: remove something
+  ```
+  instead of:
+  ```
+  revert: ci: add something
+
+  This reverts commit 1234567890abcdef.
+  ```
+
 ### Major Release / Long-Term-Support
 
 Long-Term-Support (LTS) is provided for the previous Parse Server major version. For example, Parse Server 4.x will receive security updates until Parse Server 5.x is superseded by Parse Server 6.x and becomes the new LTS version. While the current major version is published on branch `release`, a LTS version is published on branch `release-#.x.x`, for example `release-4.x.x` for the Parse Server 4.x LTS branch. 

resources/buildConfigDefinitions.js

@@ -23,6 +23,7 @@ const nestedOptionTypes = [
   'PagesRoute',
   'PasswordPolicyOptions',
   'SecurityOptions',
+  'SlowQueryOptions'
 ];
 
 /** The prefix of environment variables for nested options. */
@@ -40,6 +41,7 @@ const nestedOptionEnvPrefix = {
   'ParseServerOptions' : 'PARSE_SERVER_',
   'PasswordPolicyOptions' : 'PARSE_SERVER_PASSWORD_POLICY_',
   'SecurityOptions': 'PARSE_SERVER_SECURITY_',
+  'SlowQueryOptions': 'PARSE_SERVER_SLOW_QUERY_'
 };
 
 function last(array) {

spec/SlowQuery.spec.js

@@ -0,0 +1,140 @@
+const delay = duration => new Promise(resolve => setTimeout(resolve, duration));
+describe('Slow Queries', () => {
+  it('can enable slow queries', async () => {
+    await reconfigureServer({
+      slowQuery: {
+        enable: true,
+        threshold: 300,
+        log: true,
+      },
+    });
+    Parse.Cloud.beforeSave('TestObject', async () => {
+      await delay(500);
+    });
+    const logger = require('../lib/logger').logger;
+    let call = '';
+    spyOn(logger, 'warn').and.callFake(warn => {
+      call = warn;
+    });
+    await new Parse.Object('TestObject').save();
+    expect(call.includes('Detected a slow query on path /classes/TestObject.')).toBeTrue();
+    await delay(1000);
+    const slowQuery = await new Parse.Query('_SlowQuery').first({ useMasterKey: true });
+    expect(slowQuery).toBeDefined();
+    expect(slowQuery.get('method')).toBe('POST');
+    expect(slowQuery.get('path')).toBe('/classes/TestObject');
+    expect(slowQuery.get('body')).toEqual({});
+    expect(slowQuery.get('query')).toEqual({});
+    expect(slowQuery.get('duration')).toBeGreaterThan(500);
+  });
+
+  it('needs masterKey for slow queries', async () => {
+    await reconfigureServer({
+      slowQuery: {
+        enable: true,
+        threshold: 300,
+        log: true,
+      },
+    });
+    Parse.Cloud.beforeSave('TestObject', async () => {
+      await delay(500);
+    });
+    await new Parse.Object('TestObject').save();
+    await delay(1000);
+    await expectAsync(new Parse.Query('_SlowQuery').first()).toBeRejectedWith(
+      new Parse.Error(
+        Parse.Error.OPERATION_FORBIDDEN,
+        "Clients aren't allowed to perform the find operation on the _SlowQuery collection."
+      )
+    );
+  });
+
+  it('does record cloud functions', async () => {
+    await reconfigureServer({
+      slowQuery: {
+        enable: true,
+        threshold: 300,
+        log: true,
+      },
+    });
+    Parse.Cloud.define('TestFunction', async () => {
+      await delay(500);
+    });
+    await Parse.Cloud.run('TestFunction', { foo: 'bar' });
+    await delay(1000);
+    const slowQuery = await new Parse.Query('_SlowQuery').first({ useMasterKey: true });
+    expect(slowQuery).toBeDefined();
+    expect(slowQuery.get('method')).toBe('POST');
+    expect(slowQuery.get('path')).toBe('/functions/TestFunction');
+    expect(slowQuery.get('body')).toEqual({ foo: 'bar' });
+    expect(slowQuery.get('query')).toEqual({});
+    expect(slowQuery.get('duration')).toBeGreaterThan(500);
+  });
+
+  it('does record slow find', async () => {
+    await reconfigureServer({
+      slowQuery: {
+        enable: true,
+        threshold: 300,
+        log: true,
+      },
+    });
+    Parse.Cloud.beforeFind('TestFunction', async () => {
+      await delay(500);
+    });
+    await new Parse.Query('TestFunction').first();
+    await delay(1000);
+    const slowQuery = await new Parse.Query('_SlowQuery').first({ useMasterKey: true });
+    expect(slowQuery).toBeDefined();
+    expect(slowQuery.get('method')).toBe('GET');
+    expect(slowQuery.get('path')).toBe('/classes/TestFunction');
+    expect(slowQuery.get('body')).toEqual({ where: {}, limit: 1 });
+    expect(slowQuery.get('query')).toEqual({});
+    expect(slowQuery.get('duration')).toBeGreaterThan(500);
+  });
+
+  it('does record slow delete', async () => {
+    await reconfigureServer({
+      slowQuery: {
+        enable: true,
+        threshold: 300,
+        log: true,
+      },
+    });
+    Parse.Cloud.beforeDelete('TestObject', async () => {
+      await delay(500);
+    });
+    const testObj = await new Parse.Object('TestObject').save();
+    await testObj.destroy();
+    await delay(1000);
+    const slowQuery = await new Parse.Query('_SlowQuery').first({ useMasterKey: true });
+    expect(slowQuery).toBeDefined();
+    expect(slowQuery.get('method')).toBe('DELETE');
+    expect(slowQuery.get('path')).toBe(`/classes/TestObject/${testObj.id}`);
+    expect(slowQuery.get('body')).toEqual({});
+    expect(slowQuery.get('query')).toEqual({});
+    expect(slowQuery.get('duration')).toBeGreaterThan(500);
+  });
+
+  it('does record slow file save', async () => {
+    await reconfigureServer({
+      slowQuery: {
+        enable: true,
+        threshold: 300,
+        log: true,
+      },
+    });
+    Parse.Cloud.beforeSaveFile(async () => {
+      await delay(500);
+    });
+    await new Parse.File('yolo.txt', [1, 2, 3], 'text/plain').save();
+    await delay(1000);
+    const slowQuery = await new Parse.Query('_SlowQuery').first({ useMasterKey: true });
+    expect(slowQuery).toBeDefined();
+    expect(slowQuery.get('method')).toBe('POST');
+    expect(slowQuery.get('path')).toBe('/files/yolo.txt');
+    expect(slowQuery.get('body')).toEqual({ '0': 1, '1': 2, '2': 3 });
+    expect(slowQuery.get('query')).toEqual({});
+    expect(slowQuery.get('duration')).toBeGreaterThan(500);
+  });
+});

src/Controllers/SchemaController.js

@@ -148,6 +148,13 @@ const defaultColumns: { [string]: SchemaFields } = Object.freeze({
     reqId: { type: 'String' },
     expire: { type: 'Date' },
   },
+  _SlowQuery: {
+    method: { type: 'String' },
+    path: { type: 'String' },
+    body: { type: 'Object' },
+    query: { type: 'Object' },
+    duration: { type: 'Number' },
+  },
 });
 
 const requiredColumns = Object.freeze({
@@ -168,6 +175,7 @@ const systemClasses = Object.freeze([
   '_JobSchedule',
   '_Audience',
   '_Idempotency',
+  '_SlowQuery',
 ]);
 
 const volatileClasses = Object.freeze([
@@ -179,6 +187,7 @@ const volatileClasses = Object.freeze([
   '_JobSchedule',
   '_Audience',
   '_Idempotency',
+  '_SlowQuery',
 ]);
 
 // Anything that start with role
@@ -648,6 +657,13 @@ const _IdempotencySchema = convertSchemaToAdapterSchema(
     classLevelPermissions: {},
   })
 );
+const _SlowQuerySchema = convertSchemaToAdapterSchema(
+  injectDefaultSchema({
+    className: '_SlowQuery',
+    fields: defaultColumns._SlowQuery,
+    classLevelPermissions: {},
+  })
+);
 const VolatileClassesSchemas = [
   _HooksSchema,
   _JobStatusSchema,
@@ -657,6 +673,7 @@ const VolatileClassesSchemas = [
   _GraphQLConfigSchema,
   _AudienceSchema,
   _IdempotencySchema,
+  _SlowQuerySchema,
 ];
 
 const dbTypeMatchesObjectType = (dbType: SchemaField | string, objectType: SchemaField) => {

src/Options/Definitions.js

@@ -415,6 +415,12 @@ module.exports.ParseServerOptions = {
     help: 'Disables console output',
     action: parsers.booleanParser,
   },
+  slowQuery: {
+    env: 'PARSE_SERVER_SLOW_QUERY',
+    help: 'The slow query options to identify and report slow endpoints',
+    action: parsers.objectParser,
+    default: {},
+  },
   startLiveQueryServer: {
     env: 'PARSE_SERVER_START_LIVE_QUERY_SERVER',
     help: 'Starts the liveQuery server',
@@ -443,6 +449,25 @@ module.exports.ParseServerOptions = {
     help: 'Key sent with outgoing webhook calls',
   },
 };
+module.exports.SlowQueryOptions = {
+  enable: {
+    env: 'PARSE_SERVER_SLOW_QUERY_ENABLE',
+    help: 'Is true if Parse Server should record slow endpoints',
+    action: parsers.booleanParser,
+    default: false,
+  },
+  log: {
+    env: 'PARSE_SERVER_SLOW_QUERY_LOG',
+    help: 'Is true if Slow Queries should display in the console log',
+    action: parsers.booleanParser,
+  },
+  threshold: {
+    env: 'PARSE_SERVER_SLOW_QUERY_THRESHOLD',
+    help: 'The threshold for how long a query shoud take before it is considered slow',
+    action: parsers.numberParser('threshold'),
+    default: 3000,
+  },
+};
 module.exports.SecurityOptions = {
   checkGroups: {
     env: 'PARSE_SERVER_SECURITY_CHECK_GROUPS',

src/Options/docs.js

@@ -74,13 +74,21 @@
  * @property {String} serverURL URL to your parse server with http:// or https://.
  * @property {Number} sessionLength Session duration, in seconds, defaults to 1 year
  * @property {Boolean} silent Disables console output
+ * @property {SlowQueryOptions} slowQuery The slow query options to identify and report slow endpoints
  * @property {Boolean} startLiveQueryServer Starts the liveQuery server
  * @property {String[]} userSensitiveFields Personally identifiable information fields in the user table the should be removed for non-authorized users. Deprecated @see protectedFields
  * @property {Boolean} verbose Set the logging to verbose
  * @property {Boolean} verifyUserEmails Set to `true` to require users to verify their email address to complete the sign-up process.<br><br>Default is `false`.
  * @property {String} webhookKey Key sent with outgoing webhook calls
  */
 
+/**
+ * @interface SlowQueryOptions
+ * @property {Boolean} enable Is true if Parse Server should record slow endpoints
+ * @property {Boolean} log Is true if Slow Queries should display in the console log
+ * @property {Number} threshold The threshold for how long a query shoud take before it is considered slow
+ */
+
 /**
  * @interface SecurityOptions
  * @property {CheckGroup[]} checkGroups The security check groups to run. This allows to add custom security checks or override existing ones. Default are the groups defined in `CheckGroups.js`.

src/Options/index.js

@@ -253,6 +253,9 @@ export interface ParseServerOptions {
   /* The security options to identify and report weak security settings.
   :DEFAULT: {} */
   security: ?SecurityOptions;
+  /* The slow query options to identify and report slow endpoints
+  :DEFAULT: {} */
+  slowQuery: ?SlowQueryOptions;
   /* Set to true if new users should be created without public read and write access.
   :DEFAULT: false */
   enforcePrivateUsers: ?boolean;
@@ -261,6 +264,17 @@ export interface ParseServerOptions {
   requestKeywordDenylist: ?(RequestKeywordDenylist[]);
 }
 
+export interface SlowQueryOptions {
+  /* Is true if Parse Server should record slow endpoints
+  :DEFAULT: false */
+  enable: ?boolean;
+  /* The threshold for how long a query shoud take before it is considered slow
+  :DEFAULT: 3000 */
+  threshold: ?number;
+  /* Is true if Slow Queries should display in the console log */
+  log: ?boolean;
+}
+
 export interface SecurityOptions {
   /* Is true if Parse Server should check for weak security settings.
   :DEFAULT: false */

src/ParseServer.js

@@ -42,6 +42,7 @@ import { ParseServerRESTController } from './ParseServerRESTController';
 import * as controllers from './Controllers';
 import { ParseGraphQLServer } from './GraphQL/ParseGraphQLServer';
 import { SecurityRouter } from './Routers/SecurityRouter';
+import { registerSlowQueryListener } from './SlowQuery';
 import CheckRunner from './Security/CheckRunner';
 import Deprecator from './Deprecator/Deprecator';
 import { DefinedSchemas } from './SchemaMigrations/DefinedSchemas';
@@ -256,6 +257,11 @@ class ParseServer {
    */
   start(options: ParseServerOptions, callback: ?() => void) {
     const app = express();
+
+    if (options.slowQuery?.enable) {
+      registerSlowQueryListener(app, options);
+    }
+
     if (options.middleware) {
       let middleware;
       if (typeof options.middleware == 'string') {

src/SlowQuery.js

@@ -0,0 +1,35 @@
+import { performance } from 'perf_hooks';
+import logger from './logger';
+import rest from './rest';
+import auth from './Auth';
+
+export const registerSlowQueryListener = (app, options) => {
+  const slowQueryOptions = options.slowQuery;
+  app.use((req, res, next) => {
+    const startTime = performance.now();
+    res.on('finish', async () => {
+      const endTime = performance.now();
+      const duration = endTime - startTime;
+      const config = req.config;
+      if (duration > (options.slowQuery.threshold ?? 3000)) {
+        if (slowQueryOptions?.log) {
+          logger.warn(
+            `Detected a slow query on path ${req.path}. Duration: ${duration.toFixed(0)}ms`
+          );
+        }
+        try {
+          await rest.create(config, auth.master(config), '_SlowQuery', {
+            method: req.method,
+            path: req.path,
+            body: req.body,
+            query: req.query,
+            duration,
+          });
+        } catch (e) {
+          logger.error('Could not save Slow Query object.');
+        }
+      }
+    });
+    next();
+  });
+};

src/rest.js

@@ -250,6 +250,7 @@ const classesWithMasterOnlyAccess = [
   '_GlobalConfig',
   '_JobSchedule',
   '_Idempotency',
+  '_SlowQuery',
 ];
 // Disallowing access to the _Role collection except by master key
 function enforceRoleSecurity(method, className, auth) {