diff --git a/package-lock.json b/package-lock.json index 347d80f26f..ae6860fe0e 100644 --- a/package-lock.json +++ b/package-lock.json @@ -68,7 +68,8 @@ "ua-parser-js": "^1.0.35", "unset-value": "^2.0.1", "uuid": "^9.0.0", - "valid-url": "^1.0.9" + "valid-url": "^1.0.9", + "winston": "^3.11.0" }, "devDependencies": { "@commitlint/config-conventional": "^17.6.3", @@ -17353,10 +17354,11 @@ } }, "node_modules/winston": { - "version": "3.8.2", - "license": "MIT", + "version": "3.11.0", + "resolved": "https://registry.npmjs.org/winston/-/winston-3.11.0.tgz", + "integrity": "sha512-L3yR6/MzZAOl0DsysUXHVjOwv8mKZ71TrA/41EIduGpOOV5LQVodqN+QdQ6BS6PJ/RdIshZhq84P/fStEZkk7g==", "dependencies": { - "@colors/colors": "1.5.0", + "@colors/colors": "^1.6.0", "@dabh/diagnostics": "^2.0.2", "async": "^3.2.3", "is-stream": "^2.0.0", @@ -17396,6 +17398,14 @@ "node": ">= 6" } }, + "node_modules/winston/node_modules/@colors/colors": { + "version": "1.6.0", + "resolved": "https://registry.npmjs.org/@colors/colors/-/colors-1.6.0.tgz", + "integrity": "sha512-Ir+AOibqzrIsL6ajt3Rz3LskB7OiMVHqltZmspbW/TJuTVuyOMirVqAkjfY6JISiLHgyNqicAC8AyHHGzNd/dA==", + "engines": { + "node": ">=0.1.90" + } + }, "node_modules/winston/node_modules/readable-stream": { "version": "3.6.0", "license": "MIT", diff --git a/package.json b/package.json index 114751ab69..15daedbdd8 100644 --- a/package.json +++ b/package.json @@ -113,7 +113,8 @@ "ua-parser-js": "^1.0.35", "unset-value": "^2.0.1", "uuid": "^9.0.0", - "valid-url": "^1.0.9" + "valid-url": "^1.0.9", + "winston": "^3.11.0" }, "devDependencies": { "@commitlint/config-conventional": "^17.6.3", diff --git a/src/controllers/bulkUpload.ts b/src/controllers/bulkUpload.ts index babb8b6db1..8f225f1b61 100644 --- a/src/controllers/bulkUpload.ts +++ b/src/controllers/bulkUpload.ts @@ -1,6 +1,6 @@ /* eslint-disable global-require, import/no-dynamic-require, @typescript-eslint/no-unused-vars */ import { client as errNotificationClient } from '../util/errorNotifier'; -import logger from '../logger'; +import logger from '../logger/structured-logger'; import { CatchErr, ContextBodySimple } from '../util/types'; // TODO: To be refactored and redisgned diff --git a/src/controllers/delivery.ts b/src/controllers/delivery.ts index eba24ccf58..7be92d6318 100644 --- a/src/controllers/delivery.ts +++ b/src/controllers/delivery.ts @@ -12,7 +12,7 @@ import { import { ServiceSelector } from '../helpers/serviceSelector'; import { DeliveryTestService } from '../services/delivertTest/deliveryTest'; import { ControllerUtility } from './util'; -import logger from '../logger'; +import logger from '../logger/structured-logger'; import { DestinationPostTransformationService } from '../services/destination/postTransformation'; import tags from '../v0/util/tags'; import { FixMe } from '../util/types'; diff --git a/src/controllers/destination.ts b/src/controllers/destination.ts index 71075d1b4c..183cee35e5 100644 --- a/src/controllers/destination.ts +++ b/src/controllers/destination.ts @@ -11,7 +11,7 @@ import { import { ServiceSelector } from '../helpers/serviceSelector'; import { ControllerUtility } from './util'; import stats from '../util/stats'; -import logger from '../logger'; +import logger from '../logger/structured-logger'; import { getIntegrationVersion } from '../util/utils'; import tags from '../v0/util/tags'; import { DynamicConfigParser } from '../util/dynamicConfigParser'; diff --git a/src/controllers/regulation.ts b/src/controllers/regulation.ts index a50541780d..24139d6d34 100644 --- a/src/controllers/regulation.ts +++ b/src/controllers/regulation.ts @@ -1,5 +1,5 @@ import { Context } from 'koa'; -import logger from '../logger'; +import logger from '../logger/structured-logger'; import { UserDeletionRequest, UserDeletionResponse } from '../types'; import { ServiceSelector } from '../helpers/serviceSelector'; import tags from '../v0/util/tags'; diff --git a/src/controllers/source.ts b/src/controllers/source.ts index ef5483a756..ad174959a1 100644 --- a/src/controllers/source.ts +++ b/src/controllers/source.ts @@ -2,7 +2,7 @@ import { Context } from 'koa'; import { MiscService } from '../services/misc'; import { ServiceSelector } from '../helpers/serviceSelector'; import { ControllerUtility } from './util'; -import logger from '../logger'; +import logger from '../logger/structured-logger'; import { SourcePostTransformationService } from '../services/source/postTransformation'; export class SourceController { diff --git a/src/index.ts b/src/index.ts index 36f32f1aed..69813c54a3 100644 --- a/src/index.ts +++ b/src/index.ts @@ -2,7 +2,7 @@ import Koa from 'koa'; import bodyParser from 'koa-bodyparser'; import gracefulShutdown from 'http-graceful-shutdown'; import dotenv from 'dotenv'; -import logger from './logger'; +import logger from './logger/structured-logger'; import cluster from './util/cluster'; import { metricsRouter } from './routes/metricsRouter'; import { addStatMiddleware, addRequestSizeMiddleware, initPyroscope } from './middleware'; diff --git a/src/logger/structured-logger.ts b/src/logger/structured-logger.ts new file mode 100644 index 0000000000..dba75d0c57 --- /dev/null +++ b/src/logger/structured-logger.ts @@ -0,0 +1,90 @@ +import { createLogger, transports, format } from 'winston'; +import { LoggableExtraData } from '../types'; + +const { timestamp, combine, metadata, printf, align, errors, json } = format; + +const metadataKey = 'extraData'; + +const { LOG_LEVEL } = process.env; + +const envLevelInt = parseInt(LOG_LEVEL ?? '1', 10); +const winstonConfigLevel = ['debug', 'info', 'warn', 'error']; + +const logger = createLogger({ + level: winstonConfigLevel[envLevelInt], + format: combine( + timestamp({ + format: 'MMM-DD-YYYY HH:mm:ss', + }), + errors({ stack: true }), + align(), + metadata({ + key: metadataKey, + fillExcept: [ + 'timestamp', + 'level', + 'message', + 'stack', + 'destinationResponse', + 'authErrorCategory', + ], + }), + printf((info) => { + let extraData = ''; + if (info?.[metadataKey]) { + extraData += ` ${JSON.stringify(info[metadataKey])}`; + } + return `${info.timestamp} ${info.level}: ${info.message}${extraData}`; + }), + json(), + ), + transports: [new transports.Console()], +}); + +interface LeveledLogMethod { + (message: string, extraData?: Partial): void; + (infoObject: { message: string } & Partial): void; +} + +interface CustLogger { + errorw: LeveledLogMethod; + infow: LeveledLogMethod; + debugw: LeveledLogMethod; + warnw: LeveledLogMethod; +} + +const objectLogger: CustLogger = Object.entries({ + debugw: 'debug', + infow: 'info', + warnw: 'warning', + errorw: 'error', +}).reduce( + (agg, curr) => { + const [custLogMethod, winstonLogLevel] = curr; + + const method = ( + msg: string | ({ message: string } & Partial), + ex?: Partial, + ) => { + const loggableExtraData: Partial = { + ...(ex?.destinationId && { destinationId: ex.destinationId }), + ...(ex?.workspaceId && { workspaceId: ex.workspaceId }), + ...(ex?.destType && { destType: ex.destType }), + ...(ex?.sourceId && { sourceId: ex.sourceId }), + ...(ex?.module && { module: ex.module }), + ...(ex?.implementation && { implementation: ex.implementation }), + }; + if (typeof msg === 'object') { + logger.log(winstonLogLevel, msg.message, loggableExtraData); + return; + } + logger.log(winstonLogLevel, msg, loggableExtraData); + }; + return { ...agg, [custLogMethod]: method }; + }, + { errorw: () => {}, infow: () => {}, debugw: () => {}, warnw: () => {} }, +); + +const customLogger = Object.assign(logger, objectLogger); + +export default customLogger; diff --git a/src/services/destination/cdkV2Integration.ts b/src/services/destination/cdkV2Integration.ts index be7f0e51d5..fcca2dd116 100644 --- a/src/services/destination/cdkV2Integration.ts +++ b/src/services/destination/cdkV2Integration.ts @@ -22,6 +22,7 @@ import tags from '../../v0/util/tags'; import { DestinationPostTransformationService } from './postTransformation'; import stats from '../../util/stats'; import { CatchErr } from '../../util/types'; +import { MiscService } from '../misc'; export class CDKV2DestinationService implements DestinationService { public init() {} @@ -59,6 +60,17 @@ export class CDKV2DestinationService implements DestinationService { // TODO: Change the promise type const respList: ProcessorTransformationResponse[][] = await Promise.all( events.map(async (event) => { + const metaTo = this.getTags( + destinationType, + event.metadata.destinationId, + event.metadata.workspaceId, + tags.FEATURES.PROCESSOR, + ); + metaTo.metadata = event.metadata; + const metadataWithSvcCtx = { + ...requestMetadata, + serviceContext: MiscService.getLoggableData(metaTo.errorDetails), + }; try { const transformedPayloads: | ProcessorTransformationOutput @@ -66,7 +78,7 @@ export class CDKV2DestinationService implements DestinationService { destinationType, event, tags.FEATURES.PROCESSOR, - requestMetadata, + metadataWithSvcCtx, ); stats.increment('event_transform_success', { @@ -85,13 +97,6 @@ export class CDKV2DestinationService implements DestinationService { undefined, ); } catch (error: CatchErr) { - const metaTo = this.getTags( - destinationType, - event.metadata.destinationId, - event.metadata.workspaceId, - tags.FEATURES.PROCESSOR, - ); - metaTo.metadata = event.metadata; const erroredResp = DestinationPostTransformationService.handleProcessorTransformFailureEvents( error, @@ -127,13 +132,17 @@ export class CDKV2DestinationService implements DestinationService { tags.FEATURES.ROUTER, ); metaTo.metadata = destInputArray[0].metadata; + const metadataWithSvcCtx = { + ...requestMetadata, + serviceContext: MiscService.getLoggableData(metaTo.errorDetails), + }; try { const doRouterTransformationResponse: RouterTransformationResponse[] = await processCdkV2Workflow( destinationType, destInputArray, tags.FEATURES.ROUTER, - requestMetadata, + metadataWithSvcCtx, ); return DestinationPostTransformationService.handleRouterTransformSuccessEvents( doRouterTransformationResponse, diff --git a/src/services/destination/nativeIntegration.ts b/src/services/destination/nativeIntegration.ts index 6b680e3f4a..4f8c6e0209 100644 --- a/src/services/destination/nativeIntegration.ts +++ b/src/services/destination/nativeIntegration.ts @@ -26,6 +26,7 @@ import networkHandlerFactory from '../../adapters/networkHandlerFactory'; import { FetchHandler } from '../../helpers/fetchHandlers'; import tags from '../../v0/util/tags'; import stats from '../../util/stats'; +import { MiscService } from '../misc'; export class NativeIntegrationDestinationService implements DestinationService { public init() {} @@ -63,23 +64,30 @@ export class NativeIntegrationDestinationService implements DestinationService { const destHandler = FetchHandler.getDestHandler(destinationType, version); const respList: ProcessorTransformationResponse[][] = await Promise.all( events.map(async (event) => { + const metaTO = this.getTags( + destinationType, + event.metadata?.destinationId, + event.metadata?.workspaceId, + tags.FEATURES.PROCESSOR, + ); + metaTO.metadata = event.metadata; + const metadataWithSvcCtx = { + ...requestMetadata, + serviceContext: MiscService.getLoggableData(metaTO.errorDetails), + }; try { const transformedPayloads: | ProcessorTransformationOutput - | ProcessorTransformationOutput[] = await destHandler.process(event, requestMetadata); + | ProcessorTransformationOutput[] = await destHandler.process( + event, + metadataWithSvcCtx, + ); return DestinationPostTransformationService.handleProcessorTransformSucessEvents( event, transformedPayloads, destHandler, ); } catch (error: any) { - const metaTO = this.getTags( - destinationType, - event.metadata?.destinationId, - event.metadata?.workspaceId, - tags.FEATURES.PROCESSOR, - ); - metaTO.metadata = event.metadata; const erroredResp = DestinationPostTransformationService.handleProcessorTransformFailureEvents( error, @@ -113,8 +121,12 @@ export class NativeIntegrationDestinationService implements DestinationService { tags.FEATURES.ROUTER, ); try { + const metadataWithSvcCtx = { + ...requestMetadata, + serviceContext: MiscService.getLoggableData(metaTO.errorDetails), + }; const doRouterTransformationResponse: RouterTransformationResponse[] = - await destHandler.processRouterDest(cloneDeep(destInputArray), requestMetadata); + await destHandler.processRouterDest(cloneDeep(destInputArray), metadataWithSvcCtx); metaTO.metadata = destInputArray[0].metadata; return DestinationPostTransformationService.handleRouterTransformSuccessEvents( doRouterTransformationResponse, @@ -152,20 +164,24 @@ export class NativeIntegrationDestinationService implements DestinationService { ); const groupedEvents: RouterTransformationRequestData[][] = Object.values(allDestEvents); const response = groupedEvents.map((destEvents) => { + const metaTO = this.getTags( + destinationType, + destEvents[0].metadata.destinationId, + destEvents[0].metadata.workspaceId, + tags.FEATURES.BATCH, + ); + metaTO.metadatas = events.map((event) => event.metadata); + const metadataWithSvcCtx = { + ...requestMetadata, + serviceContext: MiscService.getLoggableData(metaTO.errorDetails), + }; try { const destBatchedRequests: RouterTransformationResponse[] = destHandler.batch( destEvents, - requestMetadata, + metadataWithSvcCtx, ); return destBatchedRequests; } catch (error: any) { - const metaTO = this.getTags( - destinationType, - destEvents[0].metadata.destinationId, - destEvents[0].metadata.workspaceId, - tags.FEATURES.BATCH, - ); - metaTO.metadatas = events.map((event) => event.metadata); const errResp = DestinationPostTransformationService.handleBatchTransformFailureEvents( error, metaTO, @@ -262,10 +278,12 @@ export class NativeIntegrationDestinationService implements DestinationService { error: `${destType}: Doesn't support deletion of users`, } as UserDeletionResponse; } + const metaTO = this.getTags(destType, 'unknown', 'unknown', tags.FEATURES.USER_DELETION); try { const result: UserDeletionResponse = await destUserDeletionHandler.processDeleteUsers({ ...request, rudderDestInfo, + serviceContext: MiscService.getLoggableData(metaTO.errorDetails), }); stats.timing('regulation_worker_requests_dest_latency', startTime, { feature: tags.FEATURES.USER_DELETION, @@ -274,7 +292,6 @@ export class NativeIntegrationDestinationService implements DestinationService { }); return result; } catch (error: any) { - const metaTO = this.getTags(destType, 'unknown', 'unknown', tags.FEATURES.USER_DELETION); return DestinationPostTransformationService.handleUserDeletionFailureEvents( error, metaTO, diff --git a/src/services/destination/postTransformation.ts b/src/services/destination/postTransformation.ts index eef4152b2b..bd4c4afd63 100644 --- a/src/services/destination/postTransformation.ts +++ b/src/services/destination/postTransformation.ts @@ -19,6 +19,12 @@ import { ErrorReportingService } from '../errorReporting'; import tags from '../../v0/util/tags'; import stats from '../../util/stats'; import { FixMe } from '../../util/types'; +import { MiscService } from '../misc'; + +const defaultErrorMessages = { + router: '[Router Transform] Error occurred while processing the payload.', + delivery: '[Delivery] Error occured while processing payload', +} as const; export class DestinationPostTransformationService { public static handleProcessorTransformSucessEvents( @@ -62,6 +68,10 @@ export class DestinationPostTransformationService { error: errObj.message || '[Processor Transform] Error occurred while processing the payload.', statTags: errObj.statTags, } as ProcessorTransformationResponse; + MiscService.logError( + errObj.message || '[Processor Transform] Error occurred while processing the payload.', + metaTo.errorDetails, + ); ErrorReportingService.reportError(error, metaTo.errorContext, resp); return resp; } @@ -87,12 +97,13 @@ export class DestinationPostTransformationService { }); } - resultantPayloads.forEach((resp) => { + resultantPayloads.forEach((resp: RouterTransformationResponse) => { if ('error' in resp && isObject(resp.statTags) && !isEmpty(resp.statTags)) { resp.statTags = { ...resp.statTags, ...metaTo.errorDetails, }; + MiscService.logError(resp.error || defaultErrorMessages.router, metaTo.errorDetails); stats.increment('event_transform_failure', metaTo.errorDetails); } else { stats.increment('event_transform_success', { @@ -118,9 +129,10 @@ export class DestinationPostTransformationService { metadata: metaTo.metadatas, batched: false, statusCode: errObj.status, - error: errObj.message || '[Router Transform] Error occurred while processing the payload.', + error: errObj.message || defaultErrorMessages.router, statTags: errObj.statTags, } as RouterTransformationResponse; + MiscService.logError(errObj.message || defaultErrorMessages.router, metaTo.errorDetails); ErrorReportingService.reportError(error, metaTo.errorContext, resp); stats.increment('event_transform_failure', metaTo.errorDetails); return resp; @@ -138,6 +150,10 @@ export class DestinationPostTransformationService { error: errObj.message || '[Batch Transform] Error occurred while processing payload.', statTags: errObj.statTags, } as RouterTransformationResponse; + MiscService.logError( + errObj.message || '[Batch Transform] Error occurred while processing payload.', + metaTo.errorDetails, + ); ErrorReportingService.reportError(error, metaTo.errorContext, resp); return resp; } @@ -149,14 +165,14 @@ export class DestinationPostTransformationService { const errObj = generateErrorObject(error, metaTo.errorDetails, false); const resp = { status: errObj.status, - message: errObj.message || '[Delivery] Error occured while processing payload', + message: errObj.message || defaultErrorMessages.delivery, destinationResponse: errObj.destinationResponse, statTags: errObj.statTags, ...(errObj.authErrorCategory && { authErrorCategory: errObj.authErrorCategory, }), } as DeliveryResponse; - + MiscService.logError(errObj.message || defaultErrorMessages.delivery, metaTo.errorDetails); ErrorReportingService.reportError(error, metaTo.errorContext, resp); return resp; } @@ -168,6 +184,10 @@ export class DestinationPostTransformationService { const errObj = generateErrorObject(error, metaTo.errorDetails, false); const metadataArray = metaTo.metadatas; if (!Array.isArray(metadataArray)) { + MiscService.logError( + 'Proxy v1 endpoint error : metadataArray is not an array', + metaTo.errorDetails, + ); // Panic throw new PlatformError('Proxy v1 endpoint error : metadataArray is not an array'); } @@ -176,7 +196,7 @@ export class DestinationPostTransformationService { error: JSON.stringify(error.destinationResponse?.response) || errObj.message || - '[Delivery] Error occured while processing payload', + defaultErrorMessages.delivery, statusCode: errObj.status, metadata, } as DeliveryJobState; @@ -190,7 +210,7 @@ export class DestinationPostTransformationService { message: errObj.message.toString(), status: errObj.status, } as DeliveriesResponse; - + MiscService.logError(errObj.message, metaTo.errorDetails); ErrorReportingService.reportError(error, metaTo.errorContext, resp); return resp; } @@ -208,6 +228,7 @@ export class DestinationPostTransformationService { authErrorCategory: errObj.authErrorCategory, }), } as UserDeletionResponse; + MiscService.logError(errObj.message, metaTo.errorDetails); ErrorReportingService.reportError(error, metaTo.errorContext, resp); return resp; } diff --git a/src/services/misc.ts b/src/services/misc.ts index e0953d08bf..ee8a46e9c4 100644 --- a/src/services/misc.ts +++ b/src/services/misc.ts @@ -3,8 +3,9 @@ import fs from 'fs'; import path from 'path'; import { Context } from 'koa'; import { DestHandlerMap } from '../constants/destinationCanonicalNames'; -import { Metadata } from '../types'; +import { ErrorDetailer, LoggableExtraData, Metadata } from '../types'; import { getCPUProfile, getHeapProfile } from '../middleware'; +import customLogger from '../logger/structured-logger'; export class MiscService { public static getDestHandler(dest: string, version: string) { @@ -31,6 +32,7 @@ export class MiscService { namespace: 'Unknown', cluster: 'Unknown', features: ctx.state?.features || {}, + serviceContext: {}, }; } @@ -74,4 +76,20 @@ export class MiscService { public static async getHeapProfile() { return getHeapProfile(); } + + public static getLoggableData(errorDetailer: ErrorDetailer): Partial { + return { + ...(errorDetailer?.destinationId && { destinationId: errorDetailer.destinationId }), + ...(errorDetailer?.sourceId && { sourceId: errorDetailer.sourceId }), + ...(errorDetailer?.workspaceId && { workspaceId: errorDetailer.workspaceId }), + ...(errorDetailer?.destType && { destType: errorDetailer.destType }), + module: errorDetailer.module, + implementation: errorDetailer.implementation, + }; + } + + public static logError(errorMessage: string, errorDetailer: ErrorDetailer) { + const loggableExtraData: Partial = this.getLoggableData(errorDetailer); + customLogger.errorw(errorMessage || '', loggableExtraData); + } } diff --git a/src/services/profile.ts b/src/services/profile.ts index d71826e251..79185d1c77 100644 --- a/src/services/profile.ts +++ b/src/services/profile.ts @@ -6,7 +6,7 @@ import v8 from 'v8'; import pprof, { heap } from '@datadog/pprof'; import { promisify } from 'util'; -import logger from '../logger'; +import logger from '../logger/structured-logger'; // eslint-disable-next-line @typescript-eslint/no-unused-vars import { CatchErr } from '../util/types'; diff --git a/src/services/trackingPlan.ts b/src/services/trackingPlan.ts index 2e68df55e9..c07541e840 100644 --- a/src/services/trackingPlan.ts +++ b/src/services/trackingPlan.ts @@ -1,4 +1,4 @@ -import logger from '../logger'; +import logger from '../logger/structured-logger'; import { RetryRequestError, RespStatusError, constructValidationErrors } from '../util/utils'; import { getMetadata } from '../v0/util'; import eventValidator from '../util/eventValidation'; diff --git a/src/services/userTransform.ts b/src/services/userTransform.ts index bf34e3d82a..5ffd75a263 100644 --- a/src/services/userTransform.ts +++ b/src/services/userTransform.ts @@ -16,7 +16,7 @@ import { } from '../util/utils'; import { getMetadata, isNonFuncObject } from '../v0/util'; import { SUPPORTED_FUNC_NAMES } from '../util/ivmFactory'; -import logger from '../logger'; +import logger from '../logger/structured-logger'; import stats from '../util/stats'; import { CommonUtils } from '../util/common'; // eslint-disable-next-line @typescript-eslint/no-unused-vars diff --git a/src/types/index.ts b/src/types/index.ts index f4432e5c2a..99cf6052aa 100644 --- a/src/types/index.ts +++ b/src/types/index.ts @@ -304,6 +304,14 @@ type SourceInput = { event: NonNullable[]; source?: Source; }; +type LoggableExtraData = { + destinationId: string; + workspaceId: string; + module: string; + implementation: string; + sourceId: string; + destType: string; +}; export { ComparatorInput, DeliveryJobState, @@ -332,4 +340,5 @@ export { UserTransformationLibrary, UserTransformationResponse, UserTransformationServiceResponse, + LoggableExtraData, };