Merge branch 'develop' into new/omnichannel-source-fields

app/api/server/api.js

@@ -7,21 +7,15 @@ import { Restivus } from 'meteor/nimble:restivus';
 import { RateLimiter } from 'meteor/rate-limit';
 import _ from 'underscore';
 
-import { Logger } from '../../logger';
-import { settings } from '../../settings';
-import { metrics } from '../../metrics';
-import { hasPermission, hasAllPermission } from '../../authorization';
+import { Logger } from '../../../server/lib/logger/Logger';
+import { getRestPayload } from '../../../server/lib/logger/logPayloads';
+import { settings } from '../../settings/server';
+import { metrics } from '../../metrics/server';
+import { hasPermission, hasAllPermission } from '../../authorization/server';
 import { getDefaultUserFields } from '../../utils/server/functions/getDefaultUserFields';
 import { checkCodeForUser } from '../../2fa/server/code';
 
-const logger = new Logger('API', {});
-
-const {
-	LOG_REST_PAYLOAD = 'false',
-	LOG_REST_METHOD_PAYLOADS = 'false',
-} = process.env;
-
-const addPayloadToLog = LOG_REST_PAYLOAD !== 'false' || LOG_REST_METHOD_PAYLOADS !== 'false';
+const logger = new Logger('API');
 
 const rateLimiterDictionary = {};
 export const defaultRateLimiterOptions = {
@@ -134,8 +128,6 @@ export class APIClass extends Restivus {
 			body: result,
 		};
 
-		logger.debug('Success', result);
-
 		return result;
 	}
 
@@ -167,8 +159,6 @@ export class APIClass extends Restivus {
 			body: result,
 		};
 
-		logger.debug('Failure', result);
-
 		return result;
 	}
 
@@ -359,10 +349,26 @@ export class APIClass extends Restivus {
 					});
 
 					this.requestIp = getRequestIP(this.request);
+
+					const startTime = Date.now();
+
+					const log = logger.logger.child({
+						method: this.request.method,
+						url: this.request.url,
+						userId: this.request.headers['x-user-id'],
+						userAgent: this.request.headers['user-agent'],
+						length: this.request.headers['content-length'],
+						host: this.request.headers.host,
+						referer: this.request.headers.referer,
+						remoteIP: this.requestIp,
+						...getRestPayload(this.request.body),
+					});
+
 					const objectForRateLimitMatch = {
 						IPAddr: this.requestIp,
 						route: `${ this.request.route }${ this.request.method.toLowerCase() }`,
 					};
+
 					let result;
 
 					const connection = {
@@ -397,25 +403,29 @@ export class APIClass extends Restivus {
 							api.processTwoFactor({ userId: this.userId, request: this.request, invocation, options: _options.twoFactorOptions, connection });
 						}
 
-						result = DDP._CurrentInvocation.withValue(invocation, () => originalAction.apply(this));
-					} catch (e) {
-						logger.debug(`${ method } ${ route } threw an error:`, e.stack);
+						result = DDP._CurrentInvocation.withValue(invocation, () => originalAction.apply(this)) || API.v1.success();
 
+						log.http({
+							status: result.statusCode,
+							responseTime: Date.now() - startTime,
+						});
+					} catch (e) {
 						const apiMethod = {
 							'error-too-many-requests': 'tooManyRequests',
 							'error-unauthorized': 'unauthorized',
 						}[e.error] || 'failure';
 
 						result = API.v1[apiMethod](typeof e === 'string' ? e : e.message, e.error, process.env.TEST_MODE ? e.stack : undefined, e);
+
+						log.http({
+							err: e,
+							status: result.statusCode,
+							responseTime: Date.now() - startTime,
+						});
 					} finally {
 						delete Accounts._accountData[connection.id];
 					}
 
-					const dateTime = new Date().toISOString();
-					logger.info(() => `${ this.requestIp } - ${ this.userId } [${ dateTime }] "${ this.request.method } ${ this.request.url }" ${ result.statusCode } - "${ this.request.headers.referer }" "${ this.request.headers['user-agent'] }" | ${ addPayloadToLog ? JSON.stringify(this.request.body) : '' }`);
-
-					result = result || API.v1.success();
-
 					rocketchatRestApiEnd({
 						status: result.statusCode,
 					});

app/api/server/v1/misc.js

@@ -15,7 +15,7 @@ import { API } from '../api';
 import { getDefaultUserFields } from '../../../utils/server/functions/getDefaultUserFields';
 import { getURL } from '../../../utils/lib/getURL';
 import { StdOut } from '../../../logger/server/streamer';
-import { SystemLogger } from '../../../logger/server';
+import { SystemLogger } from '../../../../server/lib/logger/system';
 
 
 // DEPRECATED

app/apps/server/bridges/scheduler.ts

@@ -1,4 +1,5 @@
 import Agenda from 'agenda';
+import { ObjectID } from 'bson';
 import { MongoInternals } from 'meteor/mongo';
 import {
 	StartupType,
@@ -10,13 +11,15 @@ import { SchedulerBridge } from '@rocket.chat/apps-engine/server/bridges/Schedul
 
 import { AppServerOrchestrator } from '../orchestrator';
 
-function _callProcessor(processor: Function): (job: { attrs?: { data: object } }) => void {
+function _callProcessor(processor: Function): (job: Agenda.Job) => void {
 	return (job): void => {
 		const data = job?.attrs?.data || {};
 
 		// This field is for internal use, no need to leak to app processor
 		delete (data as any).appId;
 
+		data.jobId = job.attrs._id.toString();
+
 		return processor(data);
 	};
 }
@@ -68,10 +71,10 @@ export class AppSchedulerBridge extends SchedulerBridge {
 	 * @param {Array.<Processor>} processors An array of processors
 	 * @param {string} appId
 	 *
-	 * @returns Promise<void>
+	 * @returns {string[]} List of task ids run at startup, or void no startup run is set
 	 */
-	protected async registerProcessors(processors: Array<IProcessor> = [], appId: string): Promise<void> {
-		const runAfterRegister: Promise<void>[] = [];
+	protected async registerProcessors(processors: Array<IProcessor> = [], appId: string): Promise<void | Array<string>> {
+		const runAfterRegister: Promise<string>[] = [];
 		this.orch.debugLog(`The App ${ appId } is registering job processors`, processors);
 		processors.forEach(({ id, processor, startupSetting }: IProcessor) => {
 			this.scheduler.define(id, _callProcessor(processor));
@@ -82,10 +85,10 @@ export class AppSchedulerBridge extends SchedulerBridge {
 
 			switch (startupSetting.type) {
 				case StartupType.ONETIME:
-					runAfterRegister.push(this.scheduleOnceAfterRegister({ id, when: startupSetting.when, data: startupSetting.data }, appId));
+					runAfterRegister.push(this.scheduleOnceAfterRegister({ id, when: startupSetting.when, data: startupSetting.data }, appId) as Promise<string>);
 					break;
 				case StartupType.RECURRING:
-					runAfterRegister.push(this.scheduleRecurring({ id, interval: startupSetting.interval, skipImmediate: startupSetting.skipImmediate, data: startupSetting.data }, appId));
+					runAfterRegister.push(this.scheduleRecurring({ id, interval: startupSetting.interval, skipImmediate: startupSetting.skipImmediate, data: startupSetting.data }, appId) as Promise<string>);
 					break;
 				default:
 					this.orch.getRocketChatLogger().error(`Invalid startup setting type (${ String((startupSetting as any).type) }) for the processor ${ id }`);
@@ -94,7 +97,7 @@ export class AppSchedulerBridge extends SchedulerBridge {
 		});
 
 		if (runAfterRegister.length) {
-			await Promise.all(runAfterRegister);
+			return Promise.all(runAfterRegister) as Promise<Array<string>>;
 		}
 	}
 
@@ -107,22 +110,23 @@ export class AppSchedulerBridge extends SchedulerBridge {
 	 * @param {Object} [job.data] An optional object that is passed to the processor
 	 * @param {string} appId
 	 *
-	 * @returns Promise<void>
+	 * @returns {string} taskid
 	 */
-	protected async scheduleOnce(job: IOnetimeSchedule, appId: string): Promise<void> {
-		this.orch.debugLog(`The App ${ appId } is scheduling an onetime job`, job);
+	protected async scheduleOnce({ id, when, data }: IOnetimeSchedule, appId: string): Promise<void | string> {
+		this.orch.debugLog(`The App ${ appId } is scheduling an onetime job (processor ${ id })`);
 		try {
 			await this.startScheduler();
-			await this.scheduler.schedule(job.when, job.id, this.decorateJobData(job.data, appId));
+			const job = await this.scheduler.schedule(when, id, this.decorateJobData(data, appId));
+			return job.attrs._id.toString();
 		} catch (e) {
 			this.orch.getRocketChatLogger().error(e);
 		}
 	}
 
-	private async scheduleOnceAfterRegister(job: IOnetimeSchedule, appId: string): Promise<void> {
+	private async scheduleOnceAfterRegister(job: IOnetimeSchedule, appId: string): Promise<void | string> {
 		const scheduledJobs = await this.scheduler.jobs({ name: job.id, type: 'normal' });
 		if (!scheduledJobs.length) {
-			await this.scheduleOnce(job, appId);
+			return this.scheduleOnce(job, appId);
 		}
 	}
 
@@ -136,13 +140,14 @@ export class AppSchedulerBridge extends SchedulerBridge {
 	 * @param {Object} [job.data] An optional object that is passed to the processor
 	 * @param {string} appId
 	 *
-	 * @returns Promise<void>
+	 * @returns {string} taskid
 	 */
-	protected async scheduleRecurring({ id, interval, skipImmediate = false, data }: IRecurringSchedule, appId: string): Promise<void> {
-		this.orch.debugLog(`The App ${ appId } is scheduling a recurring job`, id);
+	protected async scheduleRecurring({ id, interval, skipImmediate = false, data }: IRecurringSchedule, appId: string): Promise<void | string> {
+		this.orch.debugLog(`The App ${ appId } is scheduling a recurring job (processor ${ id })`);
 		try {
 			await this.startScheduler();
-			await this.scheduler.every(interval, id, this.decorateJobData(data, appId), { skipImmediate });
+			const job = await this.scheduler.every(interval, id, this.decorateJobData(data, appId), { skipImmediate });
+			return job.attrs._id.toString();
 		} catch (e) {
 			this.orch.getRocketChatLogger().error(e);
 		}
@@ -159,8 +164,17 @@ export class AppSchedulerBridge extends SchedulerBridge {
 	protected async cancelJob(jobId: string, appId: string): Promise<void> {
 		this.orch.debugLog(`The App ${ appId } is canceling a job`, jobId);
 		await this.startScheduler();
+
+		let cancelQuery;
+		try {
+			cancelQuery = { _id: new ObjectID(jobId.split('_')[0]) };
+		} catch (jobDocIdError) {
+			// it is not a valid objectid, so it won't try to cancel by document id
+			cancelQuery = { name: jobId };
+		}
+
 		try {
-			await this.scheduler.cancel({ name: jobId });
+			await this.scheduler.cancel(cancelQuery);
 		} catch (e) {
 			this.orch.getRocketChatLogger().error(e);
 		}

app/apps/server/communication/uikit.js

@@ -263,7 +263,6 @@ const appsRoutes = (orch) => (req, res) => {
 
 				res.sendStatus(200);
 			} catch (e) {
-				console.error(e);
 				res.status(500).send(e.message);
 			}
 			break;
@@ -297,6 +296,10 @@ const appsRoutes = (orch) => (req, res) => {
 			}
 			break;
 		}
+
+		default: {
+			res.status(500).send({ error: 'Unknown action' });
+		}
 	}
 
 	// TODO: validate payloads per type

app/apps/server/communication/websockets.js

@@ -1,5 +1,6 @@
 import { AppStatusUtils } from '@rocket.chat/apps-engine/definition/AppStatus';
 
+import { SystemLogger } from '../../../../server/lib/logger/system';
 import notifications from '../../../notifications/server/lib/Notifications';
 
 export const AppEvents = Object.freeze({
@@ -49,10 +50,10 @@ export class AppServerListener {
 		this.received.set(`${ AppEvents.APP_STATUS_CHANGE }_${ appId }`, { appId, status, when: new Date() });
 
 		if (AppStatusUtils.isEnabled(status)) {
-			await this.orch.getManager().enable(appId).catch(console.error);
+			await this.orch.getManager().enable(appId).catch(SystemLogger.error);
 			this.clientStreamer.emitWithoutBroadcast(AppEvents.APP_STATUS_CHANGE, { appId, status });
 		} else if (AppStatusUtils.isDisabled(status)) {
-			await this.orch.getManager().disable(appId, status, true).catch(console.error);
+			await this.orch.getManager().disable(appId, status, true).catch(SystemLogger.error);
 			this.clientStreamer.emitWithoutBroadcast(AppEvents.APP_STATUS_CHANGE, { appId, status });
 		}
 	}

app/authentication/server/lib/logLoginAttempts.ts

@@ -1,5 +1,6 @@
 import { ILoginAttempt } from '../ILoginAttempt';
 import { settings } from '../../../settings/server';
+import { SystemLogger } from '../../../../server/lib/logger/system';
 
 export const logFailedLoginAttempts = (login: ILoginAttempt): void => {
 	if (!settings.get('Login_Logs_Enabled')) {
@@ -25,5 +26,5 @@ export const logFailedLoginAttempts = (login: ILoginAttempt): void => {
 	if (!settings.get('Login_Logs_UserAgent')) {
 		userAgent = '-';
 	}
-	console.log('Failed login detected - Username[%s] ClientAddress[%s] ForwardedFor[%s] XRealIp[%s] UserAgent[%s]', user, clientAddress, forwardedFor, realIp, userAgent);
+	SystemLogger.info(`Failed login detected - Username[${ user }] ClientAddress[${ clientAddress }] ForwardedFor[${ forwardedFor }] XRealIp[${ realIp }] UserAgent[${ userAgent }]`);
 };

app/authentication/server/lib/restrictLoginAttempts.ts

@@ -16,15 +16,13 @@ const logger = new Logger('LoginProtection');
 export const notifyFailedLogin = async (ipOrUsername: string, blockedUntil: Date, failedAttempts: number): Promise<void> => {
 	const channelToNotify = settings.get('Block_Multiple_Failed_Logins_Notify_Failed_Channel');
 	if (!channelToNotify) {
-		/* @ts-expect-error */
 		logger.error('Cannot notify failed logins: channel provided is invalid');
 		return;
 	}
 	// verify channel exists
 	// to avoid issues when "fname" is presented in the UI, check if the name matches it as well
 	const room = await Rooms.findOneByNameOrFname(channelToNotify);
 	if (!room) {
-		/* @ts-expect-error */
 		logger.error('Cannot notify failed logins: channel provided doesn\'t exists');
 		return;
 	}

app/autotranslate/server/deeplTranslate.js

@@ -7,7 +7,7 @@ import { HTTP } from 'meteor/http';
 import _ from 'underscore';
 
 import { TranslationProviderRegistry, AutoTranslate } from './autotranslate';
-import { SystemLogger } from '../../logger/server';
+import { SystemLogger } from '../../../server/lib/logger/system';
 import { settings } from '../../settings';
 
 /**

app/autotranslate/server/googleTranslate.js

@@ -7,7 +7,7 @@ import { HTTP } from 'meteor/http';
 import _ from 'underscore';
 
 import { AutoTranslate,	TranslationProviderRegistry } from './autotranslate';
-import { SystemLogger } from '../../logger/server';
+import { SystemLogger } from '../../../server/lib/logger/system';
 import { settings } from '../../settings';
 
 /**

app/autotranslate/server/logger.js

@@ -1,9 +1,5 @@
-import { Logger } from '../../logger';
+import { Logger } from '../../logger/server';
 
-export const logger = new Logger('AutoTranslate', {
-	sections: {
-		google: 'Google',
-		deepl: 'DeepL',
-		microsoft: 'Microsoft',
-	},
-});
+const logger = new Logger('AutoTranslate');
+
+export const msLogger = logger.section('Microsoft');

app/autotranslate/server/msTranslate.js

@@ -7,7 +7,7 @@ import { HTTP } from 'meteor/http';
 import _ from 'underscore';
 
 import { TranslationProviderRegistry, AutoTranslate } from './autotranslate';
-import { logger } from './logger';
+import { msLogger } from './logger';
 import { settings } from '../../settings';
 
 /**
@@ -137,7 +137,7 @@ class MsAutoTranslate extends AutoTranslate {
 		try {
 			return this._translate(msgs, targetLanguages);
 		} catch (e) {
-			logger.microsoft.error('Error translating message', e);
+			msLogger.error({ err: e, msg: 'Error translating message' });
 		}
 		return {};
 	}
@@ -155,7 +155,7 @@ class MsAutoTranslate extends AutoTranslate {
 				Text: attachment.description || attachment.text,
 			}], targetLanguages);
 		} catch (e) {
-			logger.microsoft.error('Error translating message attachment', e);
+			msLogger.error({ err: e, msg: 'Error translating message attachment' });
 		}
 		return {};
 	}