diff --git a/.changeset/early-dots-leave.md b/.changeset/early-dots-leave.md new file mode 100644 index 0000000000000..43b71a88ec2a0 --- /dev/null +++ b/.changeset/early-dots-leave.md @@ -0,0 +1,5 @@ +--- +'@rocket.chat/meteor': patch +--- + +Fixes an issue where cancelling a file upload results in an uncaught exception diff --git a/apps/meteor/.mocharc.js b/apps/meteor/.mocharc.js index f9f780024f964..cf4b306318cfc 100644 --- a/apps/meteor/.mocharc.js +++ b/apps/meteor/.mocharc.js @@ -28,5 +28,6 @@ module.exports = { 'tests/unit/server/**/*.spec.ts', 'app/api/server/lib/**/*.spec.ts', 'app/file-upload/server/**/*.spec.ts', + 'app/statistics/server/**/*.spec.ts', ], }; diff --git a/apps/meteor/app/api/server/lib/getUploadFormData.spec.ts b/apps/meteor/app/api/server/lib/getUploadFormData.spec.ts index 49cd58fd8ab1f..bcca1cf795f67 100644 --- a/apps/meteor/app/api/server/lib/getUploadFormData.spec.ts +++ b/apps/meteor/app/api/server/lib/getUploadFormData.spec.ts @@ -12,6 +12,7 @@ const createMockRequest = ( content: string | Buffer; mimetype?: string; }, + options: { simulateError?: boolean } = {}, ): Request => { const boundary = '----WebKitFormBoundary7MA4YWxkTrZu0gW'; const parts: string[] = []; @@ -40,6 +41,10 @@ const createMockRequest = ( }, body: new ReadableStream({ async pull(controller) { + if (options.simulateError) { + controller.error(new Error('aborted')); + return; + } controller.enqueue(buffer); controller.close(); }, @@ -177,4 +182,15 @@ describe('getUploadFormData', () => { expect((error as Error).message).to.equal('[error-file-too-large]'); } }); + + it('should handle an aborted request stream', async () => { + const mockRequest = createMockRequest({}, undefined, { simulateError: true }); + + try { + await getUploadFormData({ request: mockRequest }, { fileOptional: true }); + throw new Error('Expected function to throw'); + } catch (error) { + expect((error as Error).message).to.equal('aborted'); + } + }); }); diff --git a/apps/meteor/app/api/server/lib/getUploadFormData.ts b/apps/meteor/app/api/server/lib/getUploadFormData.ts index cf797ebf70af8..5841a5b58c32b 100644 --- a/apps/meteor/app/api/server/lib/getUploadFormData.ts +++ b/apps/meteor/app/api/server/lib/getUploadFormData.ts @@ -165,7 +165,9 @@ export async function getUploadFormData< }); // Unclear why typescript complains that the ReadableStream from request.body is incompatible here - Readable.fromWeb(request.body satisfies ReadableStream).pipe(bb); + Readable.fromWeb(request.body satisfies ReadableStream) + .on('error', (err) => reject(err)) + .pipe(bb); return resultPromise; } diff --git a/apps/meteor/app/integrations/server/lib/ScriptEngine.ts b/apps/meteor/app/integrations/server/lib/ScriptEngine.ts index 9a177029f26dd..906dbcd4024f3 100644 --- a/apps/meteor/app/integrations/server/lib/ScriptEngine.ts +++ b/apps/meteor/app/integrations/server/lib/ScriptEngine.ts @@ -276,7 +276,11 @@ export abstract class IntegrationScriptEngine { } if (!script[method]) { - this.logger.error(`Method "${method}" not found in the Integration "${integration.name}"`); + this.logger.error({ + msg: 'Script method not found in the Integration', + method, + integration: integration.name, + }); await updateHistory({ historyId, step: `execute-script-no-method-${method}` }); return; } @@ -327,12 +331,20 @@ export abstract class IntegrationScriptEngine { } const script = await wrapExceptions(() => this.getIntegrationScript(integration)).catch((e) => { - this.logger.error(e); + this.logger.error({ + msg: 'Error getting Integration script', + integration: integration.name, + err: e, + }); throw e; }); if (!script[method]) { - this.logger.error(`Method "${method}" not found in the Integration "${integration.name}"`); + this.logger.error({ + msg: 'Script method not found in the Integration', + method, + integration: integration.name, + }); return; } diff --git a/apps/meteor/app/lib/server/functions/getFullUserData.ts b/apps/meteor/app/lib/server/functions/getFullUserData.ts index f1e1be0af0499..df3b977a777e1 100644 --- a/apps/meteor/app/lib/server/functions/getFullUserData.ts +++ b/apps/meteor/app/lib/server/functions/getFullUserData.ts @@ -60,7 +60,10 @@ settings.watch('Accounts_CustomFields', (settingValue) => { customFields[`customFields.${key}`] = 1; }); } catch (e) { - logger.warn(`The JSON specified for "Accounts_CustomFields" is invalid. The following error was thrown: ${e}`); + logger.warn({ + msg: 'The JSON specified for "Accounts_CustomFields" is invalid. The following error was thrown', + err: e, + }); } }); diff --git a/apps/meteor/app/lib/server/lib/deprecationWarningLogger.ts b/apps/meteor/app/lib/server/lib/deprecationWarningLogger.ts index 6a7fc267caaa4..ee74d472ff05c 100644 --- a/apps/meteor/app/lib/server/lib/deprecationWarningLogger.ts +++ b/apps/meteor/app/lib/server/lib/deprecationWarningLogger.ts @@ -41,7 +41,7 @@ export const apiDeprecationLogger = ((logger) => { metrics.deprecations.inc({ type: 'deprecation', kind: 'endpoint', name: endpoint }); - logger.warn(message); + logger.warn({ msg: message, endpoint, version, info }); }, parameter: ( endpoint: string, @@ -66,7 +66,7 @@ export const apiDeprecationLogger = ((logger) => { writeDeprecationHeader(res, 'parameter-deprecation', message, version); - logger.warn(message); + logger.warn({ msg: message, endpoint, parameter, version }); }, deprecatedParameterUsage: ( @@ -95,7 +95,7 @@ export const apiDeprecationLogger = ((logger) => { writeDeprecationHeader(res, 'invalid-usage', message, version); - logger.warn(message); + logger.warn({ msg: message, endpoint, parameter, version }); }, }; })(deprecationLogger.section('API')); @@ -114,7 +114,7 @@ export const methodDeprecationLogger = ((logger) => { } compareVersions(version, message); metrics.deprecations.inc({ type: 'deprecation', name: method, kind: 'method' }); - logger.warn(message); + logger.warn({ msg: message, method, version, replacement }); }, parameter: (method: string, parameter: string, version: DeprecationLoggerNextPlannedVersion) => { const message = `The parameter "${parameter}" in the method "${method}" is deprecated and will be removed on version ${version}`; @@ -125,7 +125,7 @@ export const methodDeprecationLogger = ((logger) => { metrics.deprecations.inc({ type: 'parameter-deprecation', name: method, params: parameter }); compareVersions(version, message); - logger.warn(message); + logger.warn({ msg: message, method, parameter, version }); }, deprecatedParameterUsage: ( method: string, @@ -150,7 +150,7 @@ export const methodDeprecationLogger = ((logger) => { metrics.deprecations.inc({ type: 'invalid-usage', name: method, params: parameter, kind: 'method' }); - logger.warn(message); + logger.warn({ msg: message, method, parameter, version }); }, /** @deprecated */ warn: (message: string) => { @@ -159,7 +159,7 @@ export const methodDeprecationLogger = ((logger) => { } compareVersions('0.0.0', message); - logger.warn(message); + logger.warn({ msg: message }); }, }; })(deprecationLogger.section('METHOD')); diff --git a/apps/meteor/app/livechat/server/api/v1/room.ts b/apps/meteor/app/livechat/server/api/v1/room.ts index d8c751b17c9a1..a06c8c2743753 100644 --- a/apps/meteor/app/livechat/server/api/v1/room.ts +++ b/apps/meteor/app/livechat/server/api/v1/room.ts @@ -516,7 +516,7 @@ const livechatRoomsEndpoints = API.v1 body: isPOSTLivechatRoomsCloseAll, }, async function action() { - livechatLogger.info(`User ${this.userId} is removing all closed rooms`); + livechatLogger.info({ msg: 'User is removing all closed rooms', userId: this.userId }); const params = this.bodyParams; @@ -527,7 +527,7 @@ const livechatRoomsEndpoints = API.v1 }); await Promise.all(promises); - livechatLogger.info(`User ${this.userId} removed ${promises.length} closed rooms`); + livechatLogger.info({ msg: 'User removed closed rooms', userId: this.userId, removedRooms: promises.length }); return API.v1.success({ removedRooms: promises.length }); }, ); diff --git a/apps/meteor/app/livechat/server/api/v1/visitor.ts b/apps/meteor/app/livechat/server/api/v1/visitor.ts index be6a974db958f..706260f80afba 100644 --- a/apps/meteor/app/livechat/server/api/v1/visitor.ts +++ b/apps/meteor/app/livechat/server/api/v1/visitor.ts @@ -151,7 +151,7 @@ API.v1.addRoute('livechat/visitor/:token', { }, }); } catch (e) { - livechatLogger.error(e); + livechatLogger.error({ msg: 'Error removing visitor', err: e }); throw new Meteor.Error('error-removing-visitor', 'An error ocurred while deleting visitor'); } }, diff --git a/apps/meteor/app/livechat/server/api/v1/webhooks.ts b/apps/meteor/app/livechat/server/api/v1/webhooks.ts index af7c97d5145cb..917fbeeb43dbc 100644 --- a/apps/meteor/app/livechat/server/api/v1/webhooks.ts +++ b/apps/meteor/app/livechat/server/api/v1/webhooks.ts @@ -72,18 +72,18 @@ API.v1.addRoute( } try { - logger.debug(`Testing webhook ${webhookUrl}`); + logger.debug({ msg: 'Testing webhook', webhookUrl }); const request = await fetch(webhookUrl, options); const response = await request.text(); - logger.debug({ response }); + logger.debug({ msg: 'Webhook response', response }); if (request.status === 200) { return API.v1.success(); } throw new Error('Invalid status code'); } catch (error) { - logger.error(`Error testing webhook: ${error}`); + logger.error({ msg: 'Error testing webhook', err: error }); throw new Error('error-invalid-webhook-response'); } }, diff --git a/apps/meteor/app/livechat/server/business-hour/BusinessHourManager.ts b/apps/meteor/app/livechat/server/business-hour/BusinessHourManager.ts index 4fe6bff2d0d88..e83bb6bbf37a3 100644 --- a/apps/meteor/app/livechat/server/business-hour/BusinessHourManager.ts +++ b/apps/meteor/app/livechat/server/business-hour/BusinessHourManager.ts @@ -287,7 +287,7 @@ export class BusinessHourManager { const failed = result.filter((r) => r.status === 'rejected'); if (failed.length > 0) { failed.forEach((error: any) => { - businessHourLogger.error('Failed to update business hours with new timezone', error.reason); + businessHourLogger.error({ msg: 'Failed to update business hours with new timezone', err: error }); }); } diff --git a/apps/meteor/app/livechat/server/business-hour/Single.ts b/apps/meteor/app/livechat/server/business-hour/Single.ts index 13a8673ad7fab..e427db9d2f59f 100644 --- a/apps/meteor/app/livechat/server/business-hour/Single.ts +++ b/apps/meteor/app/livechat/server/business-hour/Single.ts @@ -30,7 +30,8 @@ export class SingleBusinessHourBehavior extends AbstractBusinessHourBehavior imp async onNewAgentCreated(agentId: string): Promise { const defaultBusinessHour = await LivechatBusinessHours.findOneDefaultBusinessHour(); if (!defaultBusinessHour) { - businessHourLogger.debug('No default business hour found for agentId', { + businessHourLogger.debug({ + msg: 'No default business hour found for agentId', agentId, }); return; diff --git a/apps/meteor/app/livechat/server/lib/Helper.ts b/apps/meteor/app/livechat/server/lib/Helper.ts index 440b77a934a31..2ce0a3a66fe40 100644 --- a/apps/meteor/app/livechat/server/lib/Helper.ts +++ b/apps/meteor/app/livechat/server/lib/Helper.ts @@ -109,7 +109,7 @@ export const prepareLivechatRoom = async ( const activity = guest.activity || contact.activity; logger.debug({ - msg: `Creating livechat room for visitor ${_id}`, + msg: 'Creating livechat room for visitor', visitor: { _id, username, departmentId, status, activity }, }); @@ -209,7 +209,7 @@ export const createLivechatInquiry = async ({ const ts = new Date(); logger.debug({ - msg: `Creating livechat inquiry for visitor`, + msg: 'Creating livechat inquiry for visitor', visitor: { _id, username, department, status, activity }, }); @@ -245,7 +245,11 @@ export const createLivechatInquiry = async ({ session, }, ); - logger.debug(`Inquiry ${result} created for visitor ${_id}`); + logger.debug({ + msg: 'Inquiry created for visitor', + inquiryId: result, + visitorId: _id, + }); if (!result) { throw new Error('Inquiry not created'); @@ -357,7 +361,7 @@ export const parseAgentCustomFields = (customFields?: Record) => { const parseCustomFields = JSON.parse(accountCustomFields); return Object.keys(parseCustomFields).filter((customFieldKey) => parseCustomFields[customFieldKey].sendToIntegrations === true); } catch (error) { - logger.error(error); + logger.error({ msg: 'Error parsing agent custom fields', err: error }); return []; } }; @@ -406,7 +410,11 @@ export const dispatchInquiryQueued = async (inquiry: ILivechatInquiryRecord, age if (!inquiry?._id) { return; } - logger.debug(`Notifying agents of new inquiry ${inquiry._id} queued`); + logger.debug({ + msg: 'Notifying agents of queued inquiry', + inquiryId: inquiry._id, + agentId: agent?.agentId, + }); const { department, rid, v } = inquiry; const room = await LivechatRooms.findOneById(rid); @@ -429,7 +437,7 @@ export const dispatchInquiryQueued = async (inquiry: ILivechatInquiryRecord, age // Alert only the online agents of the queued request const onlineAgents = await getOnlineAgents(department, agent); if (!onlineAgents) { - logger.debug('Cannot notify agents of queued inquiry. No online agents found'); + logger.debug({ msg: 'Cannot notify agents of queued inquiry. No online agents found' }); return; } @@ -475,7 +483,11 @@ export const forwardRoomToAgent = async (room: IOmnichannelRoom, transferData: T return false; } - logger.debug(`Forwarding room ${room._id} to agent ${transferData.userId}`); + logger.debug({ + msg: 'Forwarding room to agent', + roomId: room._id, + userId: transferData.userId, + }); const { userId: agentId, clientAction } = transferData; if (!agentId) { @@ -483,14 +495,20 @@ export const forwardRoomToAgent = async (room: IOmnichannelRoom, transferData: T } const user = await Users.findOneOnlineAgentById(agentId, settings.get('Livechat_enabled_when_agent_idle')); if (!user) { - logger.debug(`Agent ${agentId} is offline. Cannot forward`); + logger.debug({ + msg: 'Agent is offline. Cannot forward', + agentId, + }); throw new Error('error-user-is-offline'); } const { _id: rid, servedBy: oldServedBy } = room; const inquiry = await LivechatInquiry.findOneByRoomId(rid, {}); if (!inquiry) { - logger.debug(`No inquiries found for room ${room._id}. Cannot forward`); + logger.debug({ + msg: 'No inquiries found for room. Cannot forward', + roomId: room._id, + }); throw new Error('error-invalid-inquiry'); } @@ -504,7 +522,11 @@ export const forwardRoomToAgent = async (room: IOmnichannelRoom, transferData: T delete inquiry.department; // There are some Enterprise features that may interrupt the forwarding process // Due to that we need to check whether the agent has been changed or not - logger.debug(`Forwarding inquiry ${inquiry._id} to agent ${agent.agentId}`); + logger.debug({ + msg: 'Forwarding inquiry to agent', + inquiryId: inquiry._id, + agentId: agent.agentId, + }); const roomTaken = await RoutingManager.takeInquiry( inquiry, agent, @@ -514,7 +536,10 @@ export const forwardRoomToAgent = async (room: IOmnichannelRoom, transferData: T room, ); if (!roomTaken) { - logger.debug(`Cannot forward inquiry ${inquiry._id}`); + logger.debug({ + msg: 'Cannot forward inquiry', + inquiryId: inquiry._id, + }); return false; } @@ -536,7 +561,11 @@ export const forwardRoomToAgent = async (room: IOmnichannelRoom, transferData: T }); } - logger.debug(`Inquiry ${inquiry._id} taken by agent ${agent.agentId}`); + logger.debug({ + msg: 'Inquiry taken by agent after forwarding', + inquiryId: inquiry._id, + agentId: agent.agentId, + }); await callbacks.run('livechat.afterForwardChatToAgent', { rid, servedBy, oldServedBy }); return true; }; @@ -586,7 +615,11 @@ export const forwardRoomToDepartment = async (room: IOmnichannelRoom, guest: ILi if (!room?.open) { return false; } - logger.debug(`Attempting to forward room ${room._id} to department ${transferData.departmentId}`); + logger.debug({ + msg: 'Attempting to forward room to department', + roomId: room._id, + departmentId: transferData.departmentId, + }); await callbacks.run('livechat.beforeForwardRoomToDepartment', { room, transferData }); const { _id: rid, servedBy: oldServedBy, departmentId: oldDepartmentId } = room; @@ -594,13 +627,19 @@ export const forwardRoomToDepartment = async (room: IOmnichannelRoom, guest: ILi const inquiry = await LivechatInquiry.findOneByRoomId(rid, {}); if (!inquiry) { - logger.debug(`Cannot forward room ${room._id}. No inquiries found`); + logger.debug({ + msg: 'Cannot forward room. No inquiries found', + roomId: room._id, + }); throw new Error('error-transferring-inquiry'); } const { departmentId } = transferData; if (!departmentId) { - logger.debug(`Cannot forward room ${room._id}. No departmentId provided`); + logger.debug({ + msg: 'Cannot forward room. No departmentId provided', + roomId: room._id, + }); throw new Error('error-transferring-inquiry-no-department'); } if (oldDepartmentId === departmentId) { @@ -609,7 +648,12 @@ export const forwardRoomToDepartment = async (room: IOmnichannelRoom, guest: ILi const { userId: agentId, clientAction } = transferData; if (agentId) { - logger.debug(`Forwarding room ${room._id} to department ${departmentId} (to user ${agentId})`); + logger.debug({ + msg: 'Forwarding room to department and user', + roomId: room._id, + departmentId, + agentId, + }); const user = await Users.findOneOnlineAgentById(agentId, settings.get('Livechat_enabled_when_agent_idle')); if (!user) { throw new Error('error-user-is-offline'); @@ -672,14 +716,22 @@ export const forwardRoomToDepartment = async (room: IOmnichannelRoom, guest: ILi room, ); if (!roomTaken) { - logger.debug(`Cannot forward room ${room._id}. Unable to delegate inquiry`); + logger.debug({ + msg: 'Cannot forward room. Unable to delegate inquiry', + roomId: room._id, + }); return false; } const { servedBy, chatQueued } = roomTaken; if (!chatQueued && oldServedBy && servedBy && oldServedBy._id === servedBy._id) { if (!department?.fallbackForwardDepartment?.length) { - logger.debug(`Cannot forward room ${room._id}. Chat assigned to agent ${servedBy._id} (Previous was ${oldServedBy._id})`); + logger.debug({ + msg: 'Cannot forward room. Chat assigned to agent instead', + roomId: room._id, + agentId: servedBy._id, + previousAgentId: oldServedBy._id, + }); throw new Error('error-no-agents-available-for-service-on-department'); } @@ -690,7 +742,10 @@ export const forwardRoomToDepartment = async (room: IOmnichannelRoom, guest: ILi const transferSuccess = !!(await callbacks.run('livechat:onTransferFailure', room, { guest, transferData, department })); // On CE theres no callback so it will return the room if (typeof transferSuccess !== 'boolean' || !transferSuccess) { - logger.debug(`Cannot forward room ${room._id}. Unable to delegate inquiry`); + logger.debug({ + msg: 'Cannot forward room. Unable to delegate inquiry', + roomId: room._id, + }); return false; } @@ -725,18 +780,27 @@ export const forwardRoomToDepartment = async (room: IOmnichannelRoom, guest: ILi await updateChatDepartment({ rid, newDepartmentId: departmentId, oldDepartmentId }); if (chatQueued) { - logger.debug(`Forwarding succesful. Marking inquiry ${inquiry._id} as ready`); + logger.debug({ + msg: 'Forwarding successful. Marking inquiry as ready', + inquiryId: inquiry._id, + }); await LivechatInquiry.readyInquiry(inquiry._id); await LivechatRooms.removeAgentByRoomId(rid); await dispatchAgentDelegated(rid); const newInquiry = await LivechatInquiry.findOneById(inquiry._id); if (!newInquiry) { - logger.debug(`Inquiry ${inquiry._id} not found`); + logger.debug({ + msg: 'Inquiry not found after forwarding', + inquiryId: inquiry._id, + }); throw new Error('error-invalid-inquiry'); } await queueInquiry(newInquiry); - logger.debug(`Inquiry ${inquiry._id} queued succesfully`); + logger.debug({ + msg: 'Inquiry queued successfully after forwarding', + inquiryId: inquiry._id, + }); } return true; diff --git a/apps/meteor/app/livechat/server/lib/QueueManager.ts b/apps/meteor/app/livechat/server/lib/QueueManager.ts index 5fd12908f5b7b..8e28c3334a828 100644 --- a/apps/meteor/app/livechat/server/lib/QueueManager.ts +++ b/apps/meteor/app/livechat/server/lib/QueueManager.ts @@ -100,7 +100,11 @@ export class QueueManager { } const inquiryAgent = await RoutingManager.delegateAgent(defaultAgent, inquiry); - logger.debug(`Delegating inquiry with id ${inquiry._id} to agent ${defaultAgent?.username}`); + logger.debug({ + msg: 'Delegating inquiry', + inquiryId: inquiry._id, + defaultAgentUsername: defaultAgent?.username, + }); const dbInquiry = await beforeRouteChat(inquiry, inquiryAgent); if (!dbInquiry) { @@ -108,7 +112,11 @@ export class QueueManager { } if (dbInquiry.status === 'ready') { - logger.debug(`Inquiry with id ${inquiry._id} is ready. Delegating to agent ${inquiryAgent?.username}`); + logger.debug({ + msg: 'Inquiry is ready. Delegating to agent', + inquiryId: inquiry._id, + agentUsername: inquiryAgent?.username, + }); return RoutingManager.delegateInquiry(dbInquiry, inquiryAgent, undefined, room); } } @@ -160,7 +168,12 @@ export class QueueManager { static async processNewInquiry(inquiry: ILivechatInquiryRecord, room: IOmnichannelRoom, defaultAgent?: SelectedAgent | null) { if (inquiry.status === LivechatInquiryStatus.VERIFYING) { - logger.debug({ msg: 'Inquiry is waiting for contact verification. Ignoring it', inquiry, defaultAgent }); + logger.debug({ + msg: 'Inquiry is waiting for contact verification. Ignoring it', + inquiryId: inquiry._id, + defaultAgentUsername: defaultAgent?.username, + status: inquiry.status, + }); if (defaultAgent) { await LivechatInquiry.setDefaultAgentById(inquiry._id, defaultAgent); @@ -169,7 +182,12 @@ export class QueueManager { } if (inquiry.status === LivechatInquiryStatus.READY) { - logger.debug({ msg: 'Inquiry is ready. Delegating', inquiry, defaultAgent }); + logger.debug({ + msg: 'Inquiry is ready. Delegating', + inquiryId: inquiry._id, + defaultAgentUsername: defaultAgent?.username, + status: inquiry.status, + }); return RoutingManager.delegateInquiry(inquiry, defaultAgent, undefined, room); } diff --git a/apps/meteor/app/livechat/server/lib/RoutingManager.ts b/apps/meteor/app/livechat/server/lib/RoutingManager.ts index 20f7a82e4c664..655af9646f28a 100644 --- a/apps/meteor/app/livechat/server/lib/RoutingManager.ts +++ b/apps/meteor/app/livechat/server/lib/RoutingManager.ts @@ -101,16 +101,16 @@ export const RoutingManager: Routing = { async delegateInquiry(inquiry, agent, options = {}, room) { const { department, rid } = inquiry; - logger.debug(`Attempting to delegate inquiry ${inquiry._id}`); + logger.debug({ msg: 'Attempting to delegate inquiry', inquiryId: inquiry._id }); if ( !agent || (agent.username && !(await Users.findOneOnlineAgentByUserList(agent.username, {}, settings.get('Livechat_enabled_when_agent_idle'))) && !(await allowAgentSkipQueue(agent))) ) { - logger.debug(`Agent offline or invalid. Using routing method to get next agent for inquiry ${inquiry._id}`); + logger.debug({ msg: 'Agent offline or invalid. Using routing method to get next agent', inquiryId: inquiry._id }); agent = await this.getNextAgent(department); - logger.debug(`Routing method returned agent ${agent?.agentId} for inquiry ${inquiry._id}`); + logger.debug({ msg: 'Routing method returned agent for inquiry', inquiryId: inquiry._id, agentId: agent?.agentId }); } if (!agent) { @@ -124,7 +124,7 @@ export const RoutingManager: Routing = { throw new Meteor.Error('error-invalid-room'); } - logger.debug(`Inquiry ${inquiry._id} will be taken by agent ${agent.agentId}`); + logger.debug({ msg: 'Inquiry will be taken by agent', inquiryId: inquiry._id, agentId: agent.agentId }); return this.takeInquiry(inquiry, agent, options, room); }, @@ -137,7 +137,7 @@ export const RoutingManager: Routing = { }), ); - logger.debug(`Assigning agent ${agent.agentId} to inquiry ${inquiry._id}`); + logger.debug({ msg: 'Assigning agent to inquiry', agentId: agent.agentId, inquiryId: inquiry._id }); const { rid, name, v, department } = inquiry; if (!(await createLivechatSubscription(rid, name, v, agent, department))) { @@ -181,7 +181,12 @@ export const RoutingManager: Routing = { } if (departmentId && departmentId !== department) { - logger.debug(`Switching department for inquiry ${inquiry._id} [Current: ${department} | Next: ${departmentId}]`); + logger.debug({ + msg: 'Switching department for inquiry', + inquiryId: inquiry._id, + currentDepartment: department, + nextDepartment: departmentId, + }); await updateChatDepartment({ rid, newDepartmentId: departmentId, @@ -234,7 +239,7 @@ export const RoutingManager: Routing = { }), ); - logger.debug(`Attempting to take Inquiry ${inquiry._id} [Agent ${agent.agentId}] `); + logger.debug({ msg: 'Attempting to take Inquiry', inquiryId: inquiry._id, agentId: agent.agentId }); const { _id, rid } = inquiry; if (!room?.open) { @@ -271,11 +276,11 @@ export const RoutingManager: Routing = { const result = await LivechatInquiry.takeInquiry(_id, inquiry.lockedAt); if (result.modifiedCount === 0) { - logger.error('Failed to take inquiry, could not match lockedAt', { inquiryId: _id, lockedAt: inquiry.lockedAt }); + logger.error({ msg: 'Failed to take inquiry, could not match lockedAt', inquiryId: _id, lockedAt: inquiry.lockedAt }); throw new Error('error-taking-inquiry-lockedAt-mismatch'); } - logger.info(`Inquiry ${inquiry._id} taken by agent ${agent.agentId}`); + logger.info({ msg: 'Inquiry taken by agent', inquiryId: inquiry._id, agentId: agent.agentId }); // assignAgent changes the room data to add the agent serving the conversation. afterTakeInquiry expects room object to be updated const { inquiry: returnedInquiry, user } = await this.assignAgent(inquiry as InquiryWithAgentInfo, agent); @@ -301,9 +306,9 @@ export const RoutingManager: Routing = { }, async transferRoom(room, guest, transferData) { - logger.debug(`Transfering room ${room._id} by ${transferData.transferredBy._id}`); + logger.debug({ msg: 'Transferring room', roomId: room._id, transferredBy: transferData.transferredBy._id }); if (transferData.departmentId) { - logger.debug(`Transfering room ${room._id} to department ${transferData.departmentId}`); + logger.debug({ msg: 'Transferring room to department', roomId: room._id, departmentId: transferData.departmentId }); return forwardRoomToDepartment(room, guest, transferData); } @@ -322,12 +327,12 @@ export const RoutingManager: Routing = { }); if (defaultAgent) { - logger.debug(`Delegating Inquiry ${inquiry._id} to agent ${defaultAgent.username}`); + logger.debug({ msg: 'Delegating Inquiry to agent', inquiryId: inquiry._id, agentUsername: defaultAgent.username }); await LivechatInquiry.setDefaultAgentById(inquiry._id, defaultAgent); void notifyOnLivechatInquiryChanged(inquiry, 'updated', { defaultAgent }); } - logger.debug(`Queueing inquiry ${inquiry._id}`); + logger.debug({ msg: 'Queueing inquiry', inquiryId: inquiry._id }); await dispatchInquiryQueued(inquiry, defaultAgent); return defaultAgent; }, diff --git a/apps/meteor/app/livechat/server/lib/sendTranscript.ts b/apps/meteor/app/livechat/server/lib/sendTranscript.ts index ca0148742846d..8a6f861907488 100644 --- a/apps/meteor/app/livechat/server/lib/sendTranscript.ts +++ b/apps/meteor/app/livechat/server/lib/sendTranscript.ts @@ -41,7 +41,7 @@ export async function sendTranscript({ subject?: string; user?: Pick | null; }): Promise { - logger.debug(`Sending conversation transcript of room ${rid} to user with token ${token}`); + logger.debug({ msg: 'Sending conversation transcript', rid, token }); const room = await LivechatRooms.findOneById>(rid, { projection: { _id: 1, v: 1 } }); if (!room) { @@ -55,7 +55,7 @@ export async function sendTranscript({ const userLanguage = settings.get('Language') || 'en'; const timezone = getTimezone(user); - logger.debug(`Transcript will be sent using ${timezone} as timezone`); + logger.debug({ msg: 'Transcript will be sent using timezone', timezone }); const showAgentInfo = settings.get('Livechat_show_agent_info'); const showSystemMessages = settings.get('Livechat_transcript_show_system_messages'); diff --git a/apps/meteor/app/livechat/server/startup.ts b/apps/meteor/app/livechat/server/startup.ts index 73219b781bf4f..813644d5a51c9 100644 --- a/apps/meteor/app/livechat/server/startup.ts +++ b/apps/meteor/app/livechat/server/startup.ts @@ -113,7 +113,7 @@ Meteor.startup(async () => { settings.watch( 'Livechat_enable_business_hours', async (value) => { - logger.debug(`Starting business hour manager ${value}`); + logger.debug({ msg: 'Starting business hour manager', enabled: value }); if (value) { await businessHourManager.startManager(); return; diff --git a/apps/meteor/app/oembed/server/server.ts b/apps/meteor/app/oembed/server/server.ts index 4a4b6a8b30fe2..1018e7426d1d9 100644 --- a/apps/meteor/app/oembed/server/server.ts +++ b/apps/meteor/app/oembed/server/server.ts @@ -98,7 +98,7 @@ const getUrlContent = async (urlObj: URL, redirectCount = 5): Promise { - log.debug('Obtaining metadata for URL', url); + log.debug({ msg: 'Obtaining metadata for URL', url }); const urlObj = new URL(url); if (withFragment) { urlObj.searchParams.set('_escaped_fragment_', ''); } - log.debug('Fetching url content', urlObj.toString()); + log.debug({ msg: 'Fetching URL content', url: urlObj.toString() }); let content: OEmbedUrlContentResult | undefined; try { content = await getUrlContent(urlObj, 5); } catch (err) { - log.error({ msg: 'Error fetching url content', err }); + log.error({ msg: 'Error fetching URL content', url: urlObj.toString(), err }); } if (!content) { return; } - log.debug('Parsing metadata for URL', url); + log.debug({ msg: 'Parsing metadata for URL', url }); const metas: { [k: string]: string } = {}; if (content?.body) { @@ -245,11 +245,11 @@ const getUrlMetaWithCache = async function ( url: string, withFragment?: boolean, ): Promise { - log.debug('Getting oembed metadata for', url); + log.debug({ msg: 'Getting OEmbed metadata for URL', url }); const cache = await OEmbedCache.findOneById(url); if (cache) { - log.debug('Found oembed metadata in cache for', url); + log.debug({ msg: 'Found OEmbed metadata in cache for URL', url }); return cache.data; } @@ -260,7 +260,7 @@ const getUrlMetaWithCache = async function ( } try { - log.debug('Saving oembed metadata in cache for', url); + log.debug({ msg: 'Saving OEmbed metadata in cache for URL', url }); await OEmbedCache.createWithIdAndData(url, data); } catch (_error) { log.error({ msg: 'OEmbed duplicated record', url }); @@ -287,19 +287,19 @@ const insertMaxWidthInOembedHtml = (oembedHtml?: string): string | undefined => oembedHtml?.replace('iframe', 'iframe style="max-width: 100%;width:400px;height:225px"'); const rocketUrlParser = async function (message: IMessage): Promise { - log.debug('Parsing message URLs'); + log.debug({ msg: 'Parsing message URLs' }); if (!Array.isArray(message.urls)) { return message; } - log.debug('URLs found', message.urls.length); + log.debug({ msg: 'URLs found in message', count: message.urls.length }); if ( (message.attachments && message.attachments.length > 0) || message.urls.filter((item) => !item.url.includes(settings.get('Site_Url'))).length > MAX_EXTERNAL_URL_PREVIEWS ) { - log.debug('All URL ignored'); + log.debug({ msg: 'All URLs ignored for OEmbed' }); return message; } @@ -308,7 +308,7 @@ const rocketUrlParser = async function (message: IMessage): Promise { let changed = false; for await (const item of message.urls) { if (item.ignoreParse === true) { - log.debug('URL ignored', item.url); + log.debug({ msg: 'URL ignored for OEmbed', url: item.url }); continue; } diff --git a/apps/meteor/app/statistics/server/functions/sendUsageReport.spec.ts b/apps/meteor/app/statistics/server/functions/sendUsageReport.spec.ts new file mode 100644 index 0000000000000..2e9da97aa733f --- /dev/null +++ b/apps/meteor/app/statistics/server/functions/sendUsageReport.spec.ts @@ -0,0 +1,63 @@ +import { expect } from 'chai'; +import { describe, it, beforeEach, afterEach } from 'mocha'; +import proxyquire from 'proxyquire'; +import sinon from 'sinon'; + +const sandbox = sinon.createSandbox(); + +const mocks = { + Statistics: { + findLast: sandbox.stub(), + updateOne: sandbox.stub(), + }, + statistics: { + save: sandbox.stub(), + }, + serverFetch: sandbox.stub(), + getWorkspaceAccessToken: sandbox.stub().resolves('workspace-token'), + Meteor: { + absoluteUrl: sandbox.stub().returns('http://localhost:3000/'), + }, + logger: { + error: sandbox.stub(), + }, +}; + +const { sendUsageReport } = proxyquire.noCallThru().load('./sendUsageReport', { + '@rocket.chat/models': { Statistics: mocks.Statistics }, + '@rocket.chat/server-fetch': { serverFetch: mocks.serverFetch }, + '..': { statistics: mocks.statistics }, + '../../../cloud/server': { getWorkspaceAccessToken: mocks.getWorkspaceAccessToken }, + 'meteor/meteor': { Meteor: mocks.Meteor }, +}); + +describe('sendUsageReport', () => { + beforeEach(() => { + sandbox.resetHistory(); + }); + + afterEach(() => { + delete process.env.RC_DISABLE_STATISTICS_REPORTING; + }); + + it('should save statistics locally and not send to collector when RC_DISABLE_STATISTICS_REPORTING is true', async () => { + process.env.RC_DISABLE_STATISTICS_REPORTING = 'true'; + + const result = await sendUsageReport(mocks.logger); + + expect(mocks.statistics.save.called).to.be.true; + expect(mocks.serverFetch.called).to.be.false; + expect(result).to.be.undefined; + }); + + it('should save statistics locally and send to collector when RC_DISABLE_STATISTICS_REPORTING is false', async () => { + process.env.RC_DISABLE_STATISTICS_REPORTING = 'false'; + + const result = await sendUsageReport(mocks.logger); + + expect(mocks.statistics.save.called).to.be.true; + expect(mocks.serverFetch.calledOnce).to.be.true; + expect(mocks.serverFetch.calledWith('https://collector.rocket.chat/', sinon.match({ method: 'POST' }))).to.be.true; + expect(result).to.be.undefined; + }); +}); diff --git a/apps/meteor/app/statistics/server/functions/sendUsageReport.ts b/apps/meteor/app/statistics/server/functions/sendUsageReport.ts index c39276be6f357..a5bc91a639621 100644 --- a/apps/meteor/app/statistics/server/functions/sendUsageReport.ts +++ b/apps/meteor/app/statistics/server/functions/sendUsageReport.ts @@ -6,6 +6,7 @@ import { tracerSpan } from '@rocket.chat/tracing'; import { Meteor } from 'meteor/meteor'; import { statistics } from '..'; +import { shouldReportStatistics } from '../../../../server/cron/usageReport'; import { getWorkspaceAccessToken } from '../../../cloud/server'; async function sendStats(logger: Logger, cronStatistics: IStats): Promise { @@ -34,6 +35,10 @@ async function sendStats(logger: Logger, cronStatistics: IStats): Promise { + // Even when disabled, we still generate statistics locally to avoid breaking + // internal processes, such as restriction checks for air-gapped workspaces. + const shouldSendToCollector = shouldReportStatistics(); + return tracerSpan('generateStatistics', {}, async () => { const last = await Statistics.findLast(); if (last) { @@ -48,13 +53,18 @@ export async function sendUsageReport(logger: Logger): Promise { @@ -75,7 +75,7 @@ export class SAUMonitorClass { await this.scheduler.remove(this._dailyFinishSessionsJobName); } - logger.debug('[stop]'); + logger.debug({ msg: '[stop]' }); } isRunning(): boolean { @@ -131,13 +131,13 @@ export class SAUMonitorClass { } if (!userId) { - logger.warn(`Received 'accounts.logout' event without 'userId'`); + logger.warn({ msg: "Received 'accounts.logout' event without 'userId'" }); return; } const { id: sessionId } = connection; if (!sessionId) { - logger.warn(`Received 'accounts.logout' event without 'sessionId'`); + logger.warn({ msg: "Received 'accounts.logout' event without 'sessionId'" }); return; } @@ -148,7 +148,7 @@ export class SAUMonitorClass { if (!isProdEnv) { throw new Error('Session not found during logout'); } - logger.error('Session not found during logout', { userId, sessionId }); + logger.error({ msg: 'Session not found during logout', userId, sessionId }); return; } @@ -323,7 +323,7 @@ export class SAUMonitorClass { } private async _startCronjobs(): Promise { - logger.info('[aggregate] - Start Cron.'); + logger.info({ msg: '[aggregate] - Start Cron.' }); const dailyComputeProcessTime = '0 2 * * *'; const dailyFinishSessionProcessTime = '5 1 * * *'; await this.scheduler.add(this._dailyComputeJobName, dailyComputeProcessTime, async () => this._aggregate()); diff --git a/apps/meteor/server/cron/usageReport.ts b/apps/meteor/server/cron/usageReport.ts index 363ea4f308c77..c4afec47de1fc 100644 --- a/apps/meteor/server/cron/usageReport.ts +++ b/apps/meteor/server/cron/usageReport.ts @@ -13,12 +13,21 @@ export const sendUsageReportAndComputeRestriction = async (statsToken?: string) void AirGappedRestriction.computeRestriction(token); }; +export const shouldReportStatistics = () => process.env.RC_DISABLE_STATISTICS_REPORTING?.toLowerCase() !== 'true'; + export async function usageReportCron(logger: Logger): Promise { - const name = 'Generate and save statistics'; + // The actual send suppression happens inside `sendUsageReport`, but since this + // is the entry point, we log a warning here when reporting is disabled. + if (!shouldReportStatistics()) { + logger.warn( + 'Statistics reporting disabled via environment variable (RC_DISABLE_STATISTICS_REPORTING). This may impact product improvements.', + ); + } const statsToken = await sendUsageReport(logger); await sendUsageReportAndComputeRestriction(statsToken); + const name = 'Generate and save statistics'; const now = new Date(); return cronJobs.add(name, `12 ${now.getHours()} * * *`, async () => { diff --git a/apps/meteor/tests/unit/app/livechat/server/business-hour/BusinessHourManager.spec.ts b/apps/meteor/tests/unit/app/livechat/server/business-hour/BusinessHourManager.spec.ts index 6d08475555a6b..3b4637bcdfedb 100644 --- a/apps/meteor/tests/unit/app/livechat/server/business-hour/BusinessHourManager.spec.ts +++ b/apps/meteor/tests/unit/app/livechat/server/business-hour/BusinessHourManager.spec.ts @@ -182,7 +182,7 @@ describe('[OC] BusinessHourManager', () => { const error = new Error('update error'); saveBusinessHourStub.onSecondCall().rejects(error); await manager.startDaylightSavingTimeVerifier(); - expect(loggerStub.calledWith('Failed to update business hours with new timezone', error)).to.be.true; + expect(loggerStub.calledWith(sinon.match({ msg: 'Failed to update business hours with new timezone' }))).to.be.true; expect(manager.createCronJobsForWorkHours.called).to.be.true; });