Server: Provide more logging information for each request to help debugging issues

packages/server/src/middleware/routeHandler.ts

@@ -7,6 +7,8 @@ import { createCsrfTag } from '../utils/csrf';
 import { getImpersonatorAdminSessionId } from '../routes/admin/utils/users/impersonate';
 import { onRequestComplete, onRequestStart } from '../utils/metrics';
 import { uuidgen } from '@joplin/lib/uuid';
+import { ApiError, ErrorTooManyRequests } from '../utils/errors';
+import { formatBytes } from '../utils/bytes';
 
 export default async function(ctx: AppContext) {
 	const requestStartTime = Date.now();
@@ -14,6 +16,34 @@ export default async function(ctx: AppContext) {
 
 	onRequestStart(requestId);
 
+	const logRequestInfo = (error: Error | string | null) => {
+		const owner = ctx.joplin.owner;
+		// Technically this is not the total request duration because there are
+		// other middlewares but that should give a good approximation
+		const requestDuration = Date.now() - requestStartTime;
+
+		const getLinePrefix = () => {
+			const prefix: string[] = [];
+			if (owner) prefix.push(owner.id);
+			prefix.push(userIp(ctx));
+			if (typeof ctx.request?.length === 'number') prefix.push(formatBytes(ctx.request.length));
+			return prefix;
+		};
+
+		// If it's a successful request or a user error (error code < 500) we display the
+		// information on a single line.
+		const line = getLinePrefix();
+		if (error && typeof error === 'string') line.push(error);
+		line.push(`${ctx.request.method} ${ctx.path} (${ctx.response.status}) (${requestDuration}ms)`);
+		ctx.joplin.appLogger().info(line.join(': '));
+
+		// If we have an error object (should be a server error), we log the full stack trace.
+		if (error && typeof error !== 'string' && error.message) {
+			const line = getLinePrefix();
+			ctx.joplin.appLogger().error(`${line.join(': ')}:`, error);
+		}
+	};
+
 	try {
 		const { response: responseObject, path } = await execRequest(ctx.joplin.routes, ctx);
 
@@ -37,32 +67,25 @@ export default async function(ctx: AppContext) {
 			ctx.response.status = 200;
 			ctx.response.body = [undefined, null].includes(responseObject) ? '' : responseObject;
 		}
-	} catch (error) {
-		if (error.httpCode >= 400 && error.httpCode < 500) {
-			const owner = ctx.joplin.owner;
 
-			const line: string[] = [
+		logRequestInfo(null);
-				error.httpCode,
+	} catch (e) {
-				`${ctx.request.method} ${ctx.path}`,
+		const error = e as ApiError;
-				owner ? owner.id : userIp(ctx),
-				error.message,
-			];
-
-			if (error.details) line.push(JSON.stringify(error.details));
-
-			ctx.joplin.appLogger().error(line.join(': '));
-		} else {
-			ctx.joplin.appLogger().error(userIp(ctx), error);
-		}
 
 		// Uncomment this when getting HTML blobs as errors while running tests.
 		// console.error(error);
 
 		ctx.response.status = error.httpCode ? error.httpCode : 500;
 
+		if (error.httpCode >= 400 && error.httpCode < 500) {
+			logRequestInfo(error.message);
+		} else {
+			logRequestInfo(error);
+		}
+
 		const responseFormat = routeResponseFormat(ctx);
 
-		if (error.retryAfterMs) ctx.response.set('Retry-After', Math.ceil(error.retryAfterMs / 1000).toString());
+		if ((error as ErrorTooManyRequests).retryAfterMs) ctx.response.set('Retry-After', Math.ceil((error as ErrorTooManyRequests).retryAfterMs / 1000).toString());
 
 		if (error.code === 'invalidOrigin') {
 			ctx.response.body = error.message;
@@ -87,11 +110,6 @@ export default async function(ctx: AppContext) {
 			if (error.code) r.code = error.code;
 			ctx.response.body = r;
 		}
-	} finally {
-		// Technically this is not the total request duration because there are
-		// other middlewares but that should give a good approximation
-		const requestDuration = Date.now() - requestStartTime;
-		ctx.joplin.appLogger().info(`${ctx.request.method} ${ctx.path} (${ctx.response.status}) (${requestDuration}ms)`);
 	}
 
 	onRequestComplete(requestId);