diff --git a/app/gen-server/lib/DocWorkerMap.ts b/app/gen-server/lib/DocWorkerMap.ts index 8a694fd3..a22e45a5 100644 --- a/app/gen-server/lib/DocWorkerMap.ts +++ b/app/gen-server/lib/DocWorkerMap.ts @@ -190,6 +190,9 @@ export class DocWorkerMap implements IDocWorkerMap { this._clients = _clients || [createClient(process.env.REDIS_URL)]; this._redlock = new Redlock(this._clients); this._client = this._clients[0]!; + this._client.on('error', (err) => log.warn(`DocWorkerMap: redisClient error`, String(err))); + this._client.on('end', () => log.warn(`DocWorkerMap: redisClient connection closed`)); + this._client.on('reconnecting', () => log.warn(`DocWorkerMap: redisClient reconnecting`)); } public async addWorker(info: DocWorkerInfo): Promise { diff --git a/app/gen-server/lib/TypeORMPatches.ts b/app/gen-server/lib/TypeORMPatches.ts index ab1ca9a2..f8f0c39a 100644 --- a/app/gen-server/lib/TypeORMPatches.ts +++ b/app/gen-server/lib/TypeORMPatches.ts @@ -25,6 +25,8 @@ import { } from 'typeorm/error/QueryRunnerProviderAlreadyReleasedError'; import {QueryBuilder} from 'typeorm/query-builder/QueryBuilder'; +// Print a warning for transactions that take longer than this. +const SLOW_TRANSACTION_MS = 5000; /********************** * Patch 1 @@ -103,9 +105,21 @@ export function applyPatch() { async function runOrRollback() { try { await queryRunner.startTransaction(); - const result = await runInTransaction(queryRunner.manager); - await queryRunner.commitTransaction(); - return result; + + const start = Date.now(); + + const timer = setInterval(() => { + const timeMs = Date.now() - start; + log.warn(`TypeORM transaction slow: [${arg1} ${arg2}]`, {timeMs}); + }, SLOW_TRANSACTION_MS); + + try { + const result = await runInTransaction(queryRunner.manager); + await queryRunner.commitTransaction(); + return result; + } finally { + clearInterval(timer); + } } catch (err) { log.debug(`TypeORM transaction error [${arg1} ${arg2}] - ${err}`); try { diff --git a/app/server/lib/FlexServer.ts b/app/server/lib/FlexServer.ts index 2f7674f9..30a72f17 100644 --- a/app/server/lib/FlexServer.ts +++ b/app/server/lib/FlexServer.ts @@ -53,11 +53,11 @@ import {getAppPathTo, getAppRoot, getUnpackedAppRoot} from 'app/server/lib/place import {addPluginEndpoints, limitToPlugins} from 'app/server/lib/PluginEndpoint'; import {PluginManager} from 'app/server/lib/PluginManager'; import * as ProcessMonitor from 'app/server/lib/ProcessMonitor'; -import {adaptServerUrl, getOrgUrl, getOriginUrl, getScope, integerParam, isDefaultUser, optStringParam, - RequestWithGristInfo, sendOkReply, stringArrayParam, stringParam, TEST_HTTPS_OFFSET, +import {adaptServerUrl, getOrgUrl, getOriginUrl, getScope, integerParam, isDefaultUser, isParameterOn, optIntegerParam, + optStringParam, RequestWithGristInfo, sendOkReply, stringArrayParam, stringParam, TEST_HTTPS_OFFSET, trustOrigin} from 'app/server/lib/requestUtils'; import {ISendAppPageOptions, makeGristConfig, makeMessagePage, makeSendAppPage} from 'app/server/lib/sendAppPage'; -import {getDatabaseUrl, listenPromise} from 'app/server/lib/serverUtils'; +import {getDatabaseUrl, listenPromise, timeoutReached} from 'app/server/lib/serverUtils'; import {Sessions} from 'app/server/lib/Sessions'; import * as shutdown from 'app/server/lib/shutdown'; import {TagChecker} from 'app/server/lib/TagChecker'; @@ -374,6 +374,10 @@ export class FlexServer implements GristServer { return this._widgetRepository; } + public hasNotifier(): boolean { + return Boolean(this._notifier); + } + public getNotifier(): INotifier { if (!this._notifier) { throw new Error('no notifier available'); } return this._notifier; @@ -425,13 +429,45 @@ export class FlexServer implements GristServer { // Health check endpoint. if called with /hooks, testing hooks are required in order to be // considered healthy. Testing hooks are used only in server started for tests, and // /status/hooks allows the tests to wait for them to be ready. - this.app.get('/status(/hooks)?', (req, res) => { - if (this._healthy && (this._hasTestingHooks || !req.url.endsWith('/hooks'))) { + // If db=1 query parameter is included, status will include the status of DB connection. + // If redis=1 query parameter is included, status will include the status of the Redis connection. + this.app.get('/status(/hooks)?', async (req, res) => { + const checks = new Map|boolean>(); + const timeout = optIntegerParam(req.query.timeout, 'timeout') || 10_000; + + // Check that the given promise resolves with no error within our timeout. + const asyncCheck = async (promise: Promise|undefined) => { + if (!promise || await timeoutReached(timeout, promise) === true) { + return false; + } + return promise.then(() => true, () => false); // Success => true, rejection => false + }; + + if (req.path.endsWith('/hooks')) { + checks.set('hooks', this._hasTestingHooks); + } + if (isParameterOn(req.query.db)) { + checks.set('db', asyncCheck(this._dbManager.connection.query('SELECT 1'))); + } + if (isParameterOn(req.query.redis)) { + checks.set('redis', asyncCheck(this._docWorkerMap.getRedisClient()?.pingAsync())); + } + let extra = ''; + let ok = true; + // If we had any extra check, collect their status to report them. + if (checks.size > 0) { + const results = await Promise.all(checks.values()); + ok = ok && results.every(r => r === true); + const notes = Array.from(checks.keys(), (key, i) => `${key} ${results[i] ? 'ok' : 'not ok'}`); + extra = ` (${notes.join(", ")})`; + } + + if (this._healthy && ok) { this._healthCheckCounter++; - res.status(200).send(`Grist ${this.name} is alive.`); + res.status(200).send(`Grist ${this.name} is alive${extra}.`); } else { this._healthCheckCounter = 0; // reset counter if we ever go internally unhealthy. - res.status(500).send(`Grist ${this.name} is unhealthy.`); + res.status(500).send(`Grist ${this.name} is unhealthy${extra}.`); } }); } diff --git a/app/server/lib/gristSessions.ts b/app/server/lib/gristSessions.ts index 4abea09c..987fae58 100644 --- a/app/server/lib/gristSessions.ts +++ b/app/server/lib/gristSessions.ts @@ -3,6 +3,7 @@ import {parseSubdomain} from 'app/common/gristUrls'; import {isNumber} from 'app/common/gutil'; import {RequestWithOrg} from 'app/server/lib/extractOrg'; import {GristServer} from 'app/server/lib/GristServer'; +import {fromCallback} from 'app/server/lib/serverUtils'; import {Sessions} from 'app/server/lib/Sessions'; import {promisifyAll} from 'bluebird'; import * as express from 'express'; @@ -62,8 +63,9 @@ function createSessionStoreFactory(sessionsDB: string): () => SessionStore { }); return assignIn(store, { async close() { - // Doesn't actually close, just unrefs stream so node becomes close-able. - store.client.unref(); + // Quit the client, so that it doesn't attempt to reconnect (which matters for some + // tests), and so that node becomes close-able. + await fromCallback(cb => store.client.quit(cb)); }}); }; } else { diff --git a/stubs/app/server/declarations.d.ts b/stubs/app/server/declarations.d.ts index 0ef34298..ce415255 100644 --- a/stubs/app/server/declarations.d.ts +++ b/stubs/app/server/declarations.d.ts @@ -58,6 +58,7 @@ declare module "redis" { public watchAsync(key: string): Promise; public lrangeAsync(key: string, start: number, end: number): Promise; public rpushAsync(key: string, ...vals: string[]): Promise; + public pingAsync(): Promise; } class Multi { diff --git a/test/gen-server/apiUtils.ts b/test/gen-server/apiUtils.ts index 29efa773..33976052 100644 --- a/test/gen-server/apiUtils.ts +++ b/test/gen-server/apiUtils.ts @@ -51,9 +51,11 @@ export class TestServer { // TypeORM doesn't give us a very clean way to shut down the db connection, // and node-sqlite3 has become fussier about this, and in regular tests // we substitute sqlite for postgres. - for (let i = 0; i < 30; i++) { - if (!this.server.getNotifier().testPending) { break; } - await delay(100); + if (this.server.hasNotifier()) { + for (let i = 0; i < 30; i++) { + if (!this.server.getNotifier().testPending) { break; } + await delay(100); + } } await removeConnection(); } diff --git a/test/server/Comm.ts b/test/server/Comm.ts index 8beac886..9e81e4a7 100644 --- a/test/server/Comm.ts +++ b/test/server/Comm.ts @@ -2,7 +2,7 @@ import {Events as BackboneEvents} from 'backbone'; import {promisifyAll} from 'bluebird'; import {assert} from 'chai'; import * as http from 'http'; -import {AddressInfo, Server, Socket} from 'net'; +import {AddressInfo} from 'net'; import * as sinon from 'sinon'; import WebSocket from 'ws'; import * as path from 'path'; @@ -16,8 +16,9 @@ import {Client, ClientMethod} from 'app/server/lib/Client'; import {CommClientConnect} from 'app/common/CommTypes'; import {delay} from 'app/common/delay'; import {isLongerThan} from 'app/common/gutil'; -import {connect as connectSock, fromCallback, getAvailablePort, listenPromise} from 'app/server/lib/serverUtils'; +import {fromCallback, listenPromise} from 'app/server/lib/serverUtils'; import {Sessions} from 'app/server/lib/Sessions'; +import {TcpForwarder} from 'test/server/tcpForwarder'; import * as testUtils from 'test/server/testUtils'; import * as session from '@gristlabs/express-session'; @@ -494,62 +495,3 @@ function getWSSettings(docWorkerUrl: string): GristWSSettings { warn() { (log as any).warn(...arguments); }, }; } - -// We'll test reconnects by making a connection through this TcpForwarder, which we'll use to -// simulate disconnects. -export class TcpForwarder { - public port: number|null = null; - private _connections = new Map(); - private _server: Server|null = null; - - constructor(private _serverPort: number) {} - - public async pickForwarderPort(): Promise { - this.port = await getAvailablePort(5834); - return this.port; - } - public async connect() { - await this.disconnect(); - this._server = new Server((sock) => this._onConnect(sock)); - await listenPromise(this._server.listen(this.port)); - } - public async disconnectClientSide() { - await Promise.all(Array.from(this._connections.keys(), destroySock)); - if (this._server) { - await new Promise((resolve) => this._server!.close(resolve)); - this._server = null; - } - this.cleanup(); - } - public async disconnectServerSide() { - await Promise.all(Array.from(this._connections.values(), destroySock)); - this.cleanup(); - } - public async disconnect() { - await this.disconnectClientSide(); - await this.disconnectServerSide(); - } - public cleanup() { - const pairs = Array.from(this._connections.entries()); - for (const [clientSock, serverSock] of pairs) { - if (clientSock.destroyed && serverSock.destroyed) { - this._connections.delete(clientSock); - } - } - } - private async _onConnect(clientSock: Socket) { - const serverSock = await connectSock(this._serverPort); - clientSock.pipe(serverSock); - serverSock.pipe(clientSock); - clientSock.on('error', (err) => serverSock.destroy(err)); - serverSock.on('error', (err) => clientSock.destroy(err)); - this._connections.set(clientSock, serverSock); - } -} - -async function destroySock(sock: Socket): Promise { - if (!sock.destroyed) { - await new Promise((resolve, reject) => - sock.on('close', resolve).destroy()); - } -} diff --git a/test/server/tcpForwarder.ts b/test/server/tcpForwarder.ts new file mode 100644 index 00000000..3e2fe69d --- /dev/null +++ b/test/server/tcpForwarder.ts @@ -0,0 +1,61 @@ +import {Server, Socket} from 'net'; +import {connect as connectSock, getAvailablePort, listenPromise} from 'app/server/lib/serverUtils'; + +// We'll test reconnects by making a connection through this TcpForwarder, which we'll use to +// simulate disconnects. +export class TcpForwarder { + public port: number|null = null; + private _connections = new Map(); + private _server: Server|null = null; + + constructor(private _serverPort: number, private _serverHost?: string) {} + + public async pickForwarderPort(): Promise { + this.port = await getAvailablePort(5834); + return this.port; + } + public async connect() { + await this.disconnect(); + this._server = new Server((sock) => this._onConnect(sock)); + await listenPromise(this._server.listen(this.port)); + } + public async disconnectClientSide() { + await Promise.all(Array.from(this._connections.keys(), destroySock)); + if (this._server) { + await new Promise((resolve) => this._server!.close(resolve)); + this._server = null; + } + this.cleanup(); + } + public async disconnectServerSide() { + await Promise.all(Array.from(this._connections.values(), destroySock)); + this.cleanup(); + } + public async disconnect() { + await this.disconnectClientSide(); + await this.disconnectServerSide(); + } + public cleanup() { + const pairs = Array.from(this._connections.entries()); + for (const [clientSock, serverSock] of pairs) { + if (clientSock.destroyed && serverSock.destroyed) { + this._connections.delete(clientSock); + } + } + } + private async _onConnect(clientSock: Socket) { + const serverSock = await connectSock(this._serverPort, this._serverHost); + clientSock.pipe(serverSock); + serverSock.pipe(clientSock); + clientSock.on('error', (err) => serverSock.destroy(err)); + serverSock.on('error', (err) => clientSock.destroy(err)); + this._connections.set(clientSock, serverSock); + } +} + +async function destroySock(sock: Socket): Promise { + if (!sock.destroyed) { + await new Promise((resolve, reject) => + sock.on('close', resolve).destroy()); + } +}