Skip to content

Commit

Permalink
Logging enhancements (#2902)
Browse files Browse the repository at this point in the history 
* change debug namespace

* more

* change formatting

* more changes

* log response body

* fix server test
  • Loading branch information
@miherlosev
miherlosev authored Jun 13, 2023
1 parent a44e213 commit 7753bef
Show file tree
Hide file tree
Showing 4 changed files with 87 additions and 30 deletions.
5 changes: 5 additions & 0 deletions src/proxy/router.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,7 @@ import {
import md5 from 'crypto-md5';
import { getPathname } from '../utils/url';
import { isEqual } from 'lodash';
import logger from '../utils/logger';

const PARAM_RE = /^{(\S+)}$/;

Expand Down Expand Up @@ -42,6 +43,8 @@ export default abstract class Router {
}

_registerRoute (route: string, method: string, handler: StaticContent | Function): void {
logger.router('register route %s %s', method, route);

const tokens = route.split('/');
const isRouteWithParams = tokens.some(token => PARAM_RE.test(token));

Expand Down Expand Up @@ -143,6 +146,8 @@ export default abstract class Router {
}

unRegisterRoute (route: string, method: string): void {
logger.router('unregister route %s %s', method, route);

const tokens = route.split('/');
const isRouteWithParams = tokens.some(token => PARAM_RE.test(token));

Expand Down
2 changes: 2 additions & 0 deletions src/request-pipeline/stages.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -146,6 +146,8 @@ export default [
await ctx.onRequestHookResponse(ctx.session.requestHookEventProvider, ctx.eventFactory, eventData.rule, eventData.opts);
}));

logger.proxy.onSendResponseBody(ctx);

ctx.res.write(ctx.destResBody);
ctx.res.end();
});
Expand Down
108 changes: 79 additions & 29 deletions src/utils/logger.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -59,108 +59,149 @@ debug.formatters.i = (ctx: RequestPipelineContext): string => {
return `{ ${stringifiedInfoArr.join(', ')} }`;
};

const hammerhead = debug('hammerhead');
const testcafe = debug('testcafe');
const hammerhead = testcafe.extend('hammerhead');
const proxyLogger = hammerhead.extend('proxy');
const destinationLogger = hammerhead.extend('destination');
const http2DestinationLogger = destinationLogger.extend('http2');
const cachedDestinationLogger = destinationLogger.extend('cached');
const destinationSocketLogger = destinationLogger.extend('socket');
const serviceMsgLogger = hammerhead.extend('service-message');
const router = proxyLogger.extend('router');

const proxy = {
onRequest: (ctx: RequestPipelineContext) => {
proxyLogger('Proxy request %s %s %s %j', ctx.requestId, ctx.req.method, ctx.req.url, ctx.req.headers);
proxyLogger('request %O', {
requestId: ctx.requestId,
method: ctx.req.method,
url: ctx.req.url,
headers: ctx.req.headers,
});
},

onResponse: (ctx: RequestPipelineContext, headers: OutgoingHttpHeaders) => {
proxyLogger('Proxy response %s %d %j', ctx.requestId, ctx.destRes.statusCode, headers);
proxyLogger('response %O', {
requestId: ctx.requestId,
statusCode: ctx.destRes.statusCode,
headers,
});
},

onSendResponseBody: (ctx: RequestPipelineContext) => {
proxyLogger('send response body %O', {
requestId: ctx.requestId,
body: ctx.destResBody.toString(),
});
},

onRequestError: (ctx: RequestPipelineContext) => {
proxyLogger('Proxy error: request to proxy cannot be dispatched %s, responding 404', ctx.requestId);
proxyLogger('error: request to proxy cannot be dispatched %s, responding 404', ctx.requestId);
},

onWebSocketResponseError: (ctx: RequestPipelineContext, e: Error) => {
proxyLogger('Proxy error %s %o', ctx.requestId, e);
proxyLogger('error %s %o', ctx.requestId, e);
},

onCORSFailed: (ctx: RequestPipelineContext) => {
proxyLogger('Proxy CORS check failed %s', ctx.requestId);
proxyLogger('CORS check failed %s', ctx.requestId);
},

onContentInfoBuilt: (ctx: RequestPipelineContext) => {
proxyLogger('Proxy resource content info %s %i', ctx.requestId, ctx);
proxyLogger('resource content info %s %i', ctx.requestId, ctx);
},

onMockResponseError: (rule: RequestFilterRule, e: Error) => {
proxyLogger('Proxy error %s %s', rule, e);
proxyLogger('error %s %s', rule, e);
},
};

const serviceMsg = {
onMessage: (msg: ServiceMessage, result: object) => {
serviceMsgLogger('Service message %j, result %j', msg, result);
serviceMsgLogger('%j, result %j', msg, result);
},

onError: (msg: ServiceMessage, err: object) => {
const isError = err instanceof Error;
const errMsg = isError ? err : getIncorrectErrorTypeMessage(err);

serviceMsgLogger('Service message %j, error %o', msg, errMsg);
serviceMsgLogger('%j, error %o', msg, errMsg);
},
};

const destination = {
onMockedRequest: (ctx: RequestPipelineContext) => {
destinationLogger('Destination request is mocked %s %s %j', ctx.requestId, ctx.mock.statusCode, ctx.mock.headers);
destinationLogger('mocked %O', {
requestId: ctx.requestId,
statusCode: ctx.mock.statusCode,
headers: ctx.mock.headers,
});
},

onRequest: (opts: RequestOptions) => {
destinationLogger('Destination request %s %s %s %j', opts.requestId, opts.method, opts.url, opts.headers);
destinationLogger('%O', {
requestId: opts.requestId,
method: opts.method,
url: opts.url,
headers: opts.headers,
});
},

onCachedRequest: (opts: RequestOptions, hitCount: number) => {
cachedDestinationLogger('Cached destination request %s %s %s %j (hitCount: %d)', opts.requestId, opts.method, opts.url, opts.headers, hitCount);
cachedDestinationLogger('%O', {
requestId: opts.requestId,
method: opts.method,
url: opts.url,
headers: opts.headers,
hitCount,
});
},

onHttp2Stream: (requestId: string, headers: OutgoingHttpHeaders) => {
http2DestinationLogger('Destination stream %s %j', requestId, headers);
http2DestinationLogger('stream %s %j', requestId, headers);
},

onHttp2Unsupported: (requestId: string, origin: string) => {
http2DestinationLogger('Destination server does not support http2 %s %s', requestId, origin);
http2DestinationLogger('server does not support http2 %s %s', requestId, origin);
},

onHttp2SessionCreated: (requestId: string, origin: string, cacheSize: number, cacheTotalSize: number) => {
http2DestinationLogger('Destination session created %s %s (cache size %d of %d)', requestId, origin, cacheSize, cacheTotalSize);
http2DestinationLogger('session created %s %s (cache size %d of %d)', requestId, origin, cacheSize, cacheTotalSize);
},

onHttp2SessionClosed: (requestId: string, origin: string, cacheSize: number, cacheTotalSize: number) => {
http2DestinationLogger('Destination session closed %s %s (cache size %d of %d)', requestId, origin, cacheSize, cacheTotalSize);
http2DestinationLogger('session closed %s %s (cache size %d of %d)', requestId, origin, cacheSize, cacheTotalSize);
},

onHttp2Error: (requestId: string, origin: string, err: Error) => {
http2DestinationLogger('Destination error %s %s %o', requestId, origin, err);
http2DestinationLogger('error %s %s %o', requestId, origin, err);
},

onHttp2SessionTimeout: (origin: string, timeout: number) => {
http2DestinationLogger('Destination session is unused more than %d min and will be closed %s', timeout / 60_000, origin);
http2DestinationLogger('session is unused more than %d min and will be closed %s', timeout / 60_000, origin);
},

onUpgradeRequest: (opts: RequestOptions, res: IncomingMessage) => {
destinationLogger('Destination upgrade %s %d %j', opts.requestId, res.statusCode, res.headers);
destinationLogger('upgrade %O', {
requestId: opts.requestId,
statusCode: res.statusCode,
headers: res.headers,
});
},

onResponse: (opts: RequestOptions, res: IncomingMessage | Http2Response) => {
destinationLogger('Destination response %s %d %j', opts.requestId, res.statusCode, res.headers);
destinationLogger('response %O', {
requestId: opts.requestId,
statusCode: res.statusCode,
headers: res.headers,
});
},

onProxyAuthenticationError: (opts: RequestOptions) => {
destinationLogger('Destination error: Cannot authorize to proxy %s', opts.requestId);
destinationLogger('error: Cannot authorize to proxy %s', opts.requestId);
},

onResendWithCredentials: (opts: RequestOptions) => {
destinationLogger('Destination request resent with credentials %s', opts.requestId);
destinationLogger('request resent with credentials %s', opts.requestId);
},

onFileRead: (ctx: RequestPipelineContext) => {
Expand All @@ -172,25 +213,34 @@ const destination = {
},

onTimeoutError: (opts: RequestOptions, timeout: number) => {
destinationLogger('Destination request timeout %s (%d ms)', opts.requestId, timeout);
destinationLogger('request timeout %s (%d ms)', opts.requestId, timeout);
},

onError: (opts: RequestOptions, err: Error) => {
destinationLogger('Destination error %s %o', opts.requestId, err);
destinationLogger('error %s %o', opts.requestId, err);
},
};

const destinationSocket = {
enabled: destinationSocketLogger.enabled,

onFirstChunk: (opts: RequestOptions, data: Buffer) => {
destinationSocketLogger('Destination request socket first chunk of data %s %d %s',
opts.requestId, data.length, JSON.stringify(data.toString()));
destinationSocketLogger('socket first chunk of data %O', {
requestId: opts.requestId,
length: data.length,
data: JSON.stringify(data.toString()),
});
},

onError: (opts: RequestOptions, err: Error) => {
destinationSocketLogger('Destination request socket error %s %o', opts.requestId, err);
destinationSocketLogger('socket error %s %o', opts.requestId, err);
},
};

export default { proxy, destination, destinationSocket, serviceMsg };
export default {
proxy,
destination,
destinationSocket,
serviceMsg,
router,
};
2 changes: 1 addition & 1 deletion test/server/proxy/index-test.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -455,7 +455,7 @@ describe('Proxy', () => {
});

it('Should handle undefined/wrong-type error correctly', () => {
debug.enable('hammerhead:service-message');
debug.enable('testcafe:hammerhead:service-message');

const srderrWrite = process.stderr.write;
let log = '';
Expand Down

0 comments on commit 7753bef

Please sign in to comment.