I am working with nestjs for a project, and want to log as much information as possible, one such thing being the body of the response and request of every http request. I made a nest middleware for that end:
import {token} from 'gen-uid';
import { inspect } from 'util';
import { Injectable, NestMiddleware, MiddlewareFunction } from '@nestjs/mon';
import { Stream } from 'stream';
import { createWriteStream, existsSync, mkdirSync } from 'fs';
@Injectable()
export class LoggerMiddleware implements NestMiddleware {
logfileStream: Stream;
constructor() {
if (!existsSync('./logs')) mkdirSync('./logs');
this.logfileStream = createWriteStream("./logs/serviceName-"+ new Date().toISOString() + ".log", {flags:'a'});
}
resolve(...args: any[]): MiddlewareFunction {
return (req, res, next) => {
let reqToken = token();
let startTime = new Date();
let logreq = {
"@timestamp": startTime.toISOString(),
"@Id": reqToken,
query: req.query,
params: req.params,
url: req.url,
fullUrl: req.originalUrl,
method: req.method,
headers: req.headers,
_parsedUrl: req._parsedUrl,
}
console.log(
"timestamp: " + logreq["@timestamp"] + "\t" +
"request id: " + logreq["@Id"] + "\t" +
"method: " + req.method + "\t" +
"URL: " + req.originalUrl);
this.logfileStream.write(JSON.stringify(logreq));
const cleanup = () => {
res.removeListener('finish', logFn)
res.removeListener('close', abortFn)
res.removeListener('error', errorFn)
}
const logFn = () => {
let endTime = new Date();
cleanup()
let logres = {
"@timestamp": endTime.toISOString(),
"@Id": reqToken,
"queryTime": endTime.valueOf() - startTime.valueOf(),
}
console.log(inspect(res));
}
const abortFn = () => {
cleanup()
console.warn('Request aborted by the client')
}
const errorFn = err => {
cleanup()
console.error(`Request pipeline error: ${err}`)
}
res.on('finish', logFn) // successful pipeline (regardless of its response)
res.on('close', abortFn) // aborted pipeline
res.on('error', errorFn) // pipeline internal error
next();
};
}
}
Then I set this middleware as a global middleware to log all request, but looking at the res and req object, neither of them have a property.
In the code sample I set the response object to be printed, running a hello world endpoint on my project that returns {"message":"Hello World"} I get the following output:
timestamp: 2019-01-09T00:37:00.912Z request id: 2852f925f987 method: GET URL: /hello-world
ServerResponse { domain: null, _events: { finish: [Function: bound resOnFinish] }, _eventsCount: 1, _maxListeners: undefined, output: [], outputEncodings: [], outputCallbacks: [], outputSize: 0, writable: true, _last: false, upgrading: false, chunkedEncoding: false, shouldKeepAlive: true, useChunkedEncodingByDefault: true, sendDate: true, _removedConnection: false, _removedContLen: true, _removedTE: true, _contentLength: 0, _hasBody: false, _trailer: '', finished: true, _headerSent: true, socket: null, connection: null, _header: 'HTTP/1.1 304 Not Modified\r\nX-Powered-By: Express\r\nETag: W/"19-c6Hfa5VVP+Ghysj+6y9cPi5QQbk"\r\nDate: Wed, 09 Jan 2019 00:37:00 GMT\r\nConnection: keep-alive\r\n\r\n', _onPendingData: [Function: bound updateOutgoingData], _sent100: false, _expect_continue: false, req: IningMessage { _readableState: ReadableState { objectMode: false, highWaterMark: 16384, buffer: [Object], length: 0, pipes: null, pipesCount: 0, flowing: true, ended: true, endEmitted: false, reading: false, sync: true, needReadable: false, emittedReadable: true, readableListening: false, resumeScheduled: true, destroyed: false, defaultEncoding: 'utf8', awaitDrain: 0, readingMore: true, decoder: null, encoding: null }, readable: true, domain: null, _events: {}, _eventsCount: 0, _maxListeners: undefined, socket: Socket { connecting: false, _hadError: false, _handle: [Object], _parent: null, _host: null, _readableState: [Object], readable: true, domain: null, _events: [Object], _eventsCount: 10, _maxListeners: undefined, _writableState: [Object], writable: true, allowHalfOpen: true, _bytesDispatched: 155, _sockname: null, _pendingData: null, _pendingEncoding: '', server: [Object], _server: [Object], _idleTimeout: 5000, _idleNext: [Object], _idlePrev: [Object], _idleStart: 12562, _destroyed: false, parser: [Object], on: [Function: socketOnWrap], _paused: false, read: [Function], _consuming: true, _httpMessage: null, [Symbol(asyncId)]: 151, [Symbol(bytesRead)]: 0, [Symbol(asyncId)]: 153, [Symbol(triggerAsyncId)]: 151 }, connection: Socket { connecting: false, _hadError: false, _handle: [Object], _parent: null, _host: null, _readableState: [Object], readable: true, domain: null, _events: [Object], _eventsCount: 10, _maxListeners: undefined, _writableState: [Object], writable: true, allowHalfOpen: true, _bytesDispatched: 155, _sockname: null, _pendingData: null, _pendingEncoding: '', server: [Object], _server: [Object], _idleTimeout: 5000, _idleNext: [Object], _idlePrev: [Object], _idleStart: 12562, _destroyed: false, parser: [Object], on: [Function: socketOnWrap], _paused: false, read: [Function], _consuming: true, _httpMessage: null, [Symbol(asyncId)]: 151, [Symbol(bytesRead)]: 0, [Symbol(asyncId)]: 153, [Symbol(triggerAsyncId)]: 151 }, httpVersionMajor: 1, httpVersionMinor: 1, httpVersion: '1.1', plete: true, headers: { host: 'localhost:5500', 'user-agent': 'Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:64.0) Gecko/20100101 Firefox/64.0', accept: 'text/html,application/xhtml+xml,application/xml;q=0.9,/;q=0.8', 'accept-language': 'en-US,en;q=0.5', 'accept-encoding': 'gzip, deflate', connection: 'keep-alive', 'upgrade-insecure-requests': '1', 'if-none-match': 'W/"19-c6Hfa5VVP+Ghysj+6y9cPi5QQbk"' }, rawHeaders: [ 'Host', 'localhost:5500', 'User-Agent', 'Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:64.0) Gecko/20100101 Firefox/64.0', 'Accept', 'text/html,application/xhtml+xml,application/xml;q=0.9,/;q=0.8', 'Accept-Language', 'en-US,en;q=0.5', 'Accept-Encoding', 'gzip, deflate', 'Connection', 'keep-alive', 'Upgrade-Insecure-Requests', '1', 'If-None-Match', 'W/"19-c6Hfa5VVP+Ghysj+6y9cPi5QQbk"' ], trailers: {}, rawTrailers: [], upgrade: false, url: '/hello-world', method: 'GET', statusCode: null, statusMessage: null, client: Socket { connecting: false, _hadError: false, _handle: [Object], _parent: null, _host: null, _readableState: [Object], readable: true, domain: null, _events: [Object], _eventsCount: 10, _maxListeners: undefined, _writableState: [Object], writable: true, allowHalfOpen: true, _bytesDispatched: 155, _sockname: null, _pendingData: null, _pendingEncoding: '', server: [Object], _server: [Object], _idleTimeout: 5000, _idleNext: [Object], _idlePrev: [Object], _idleStart: 12562, _destroyed: false, parser: [Object], on: [Function: socketOnWrap], _paused: false, read: [Function], _consuming: true, _httpMessage: null, [Symbol(asyncId)]: 151, [Symbol(bytesRead)]: 0, [Symbol(asyncId)]: 153, [Symbol(triggerAsyncId)]: 151 }, _consuming: false, _dumped: true, next: [Function: next], baseUrl: '', originalUrl: '/hello-world', _parsedUrl: Url { protocol: null, slashes: null, auth: null, host: null, port: null, hostname: null, hash: null, search: null, query: null, pathname: '/hello-world', path: '/hello-world', href: '/hello-world', _raw: '/hello-world' }, params: {}, query: {}, res: [Circular], body: {}, route: Route { path: '/hello-world', stack: [Array], methods: [Object] } }, locals: {}, statusCode: 304, statusMessage: 'Not Modified', [Symbol(outHeadersKey)]: { 'x-powered-by': [ 'X-Powered-By', 'Express' ], etag: [ 'ETag', 'W/"19-c6Hfa5VVP+Ghysj+6y9cPi5QQbk"' ] } }
In no place in the response object does the {"message":"Hello World"} message appears, I would like to know how to obtain the body from the res and req objects if it is possible please.
Note: I know that nestjs has Interceptors, but following what the documentation says, middleware should be the solution for this problem.
I am working with nestjs for a project, and want to log as much information as possible, one such thing being the body of the response and request of every http request. I made a nest middleware for that end:
import {token} from 'gen-uid';
import { inspect } from 'util';
import { Injectable, NestMiddleware, MiddlewareFunction } from '@nestjs/mon';
import { Stream } from 'stream';
import { createWriteStream, existsSync, mkdirSync } from 'fs';
@Injectable()
export class LoggerMiddleware implements NestMiddleware {
logfileStream: Stream;
constructor() {
if (!existsSync('./logs')) mkdirSync('./logs');
this.logfileStream = createWriteStream("./logs/serviceName-"+ new Date().toISOString() + ".log", {flags:'a'});
}
resolve(...args: any[]): MiddlewareFunction {
return (req, res, next) => {
let reqToken = token();
let startTime = new Date();
let logreq = {
"@timestamp": startTime.toISOString(),
"@Id": reqToken,
query: req.query,
params: req.params,
url: req.url,
fullUrl: req.originalUrl,
method: req.method,
headers: req.headers,
_parsedUrl: req._parsedUrl,
}
console.log(
"timestamp: " + logreq["@timestamp"] + "\t" +
"request id: " + logreq["@Id"] + "\t" +
"method: " + req.method + "\t" +
"URL: " + req.originalUrl);
this.logfileStream.write(JSON.stringify(logreq));
const cleanup = () => {
res.removeListener('finish', logFn)
res.removeListener('close', abortFn)
res.removeListener('error', errorFn)
}
const logFn = () => {
let endTime = new Date();
cleanup()
let logres = {
"@timestamp": endTime.toISOString(),
"@Id": reqToken,
"queryTime": endTime.valueOf() - startTime.valueOf(),
}
console.log(inspect(res));
}
const abortFn = () => {
cleanup()
console.warn('Request aborted by the client')
}
const errorFn = err => {
cleanup()
console.error(`Request pipeline error: ${err}`)
}
res.on('finish', logFn) // successful pipeline (regardless of its response)
res.on('close', abortFn) // aborted pipeline
res.on('error', errorFn) // pipeline internal error
next();
};
}
}
Then I set this middleware as a global middleware to log all request, but looking at the res and req object, neither of them have a property.
In the code sample I set the response object to be printed, running a hello world endpoint on my project that returns {"message":"Hello World"} I get the following output:
timestamp: 2019-01-09T00:37:00.912Z request id: 2852f925f987 method: GET URL: /hello-world
ServerResponse { domain: null, _events: { finish: [Function: bound resOnFinish] }, _eventsCount: 1, _maxListeners: undefined, output: [], outputEncodings: [], outputCallbacks: [], outputSize: 0, writable: true, _last: false, upgrading: false, chunkedEncoding: false, shouldKeepAlive: true, useChunkedEncodingByDefault: true, sendDate: true, _removedConnection: false, _removedContLen: true, _removedTE: true, _contentLength: 0, _hasBody: false, _trailer: '', finished: true, _headerSent: true, socket: null, connection: null, _header: 'HTTP/1.1 304 Not Modified\r\nX-Powered-By: Express\r\nETag: W/"19-c6Hfa5VVP+Ghysj+6y9cPi5QQbk"\r\nDate: Wed, 09 Jan 2019 00:37:00 GMT\r\nConnection: keep-alive\r\n\r\n', _onPendingData: [Function: bound updateOutgoingData], _sent100: false, _expect_continue: false, req: IningMessage { _readableState: ReadableState { objectMode: false, highWaterMark: 16384, buffer: [Object], length: 0, pipes: null, pipesCount: 0, flowing: true, ended: true, endEmitted: false, reading: false, sync: true, needReadable: false, emittedReadable: true, readableListening: false, resumeScheduled: true, destroyed: false, defaultEncoding: 'utf8', awaitDrain: 0, readingMore: true, decoder: null, encoding: null }, readable: true, domain: null, _events: {}, _eventsCount: 0, _maxListeners: undefined, socket: Socket { connecting: false, _hadError: false, _handle: [Object], _parent: null, _host: null, _readableState: [Object], readable: true, domain: null, _events: [Object], _eventsCount: 10, _maxListeners: undefined, _writableState: [Object], writable: true, allowHalfOpen: true, _bytesDispatched: 155, _sockname: null, _pendingData: null, _pendingEncoding: '', server: [Object], _server: [Object], _idleTimeout: 5000, _idleNext: [Object], _idlePrev: [Object], _idleStart: 12562, _destroyed: false, parser: [Object], on: [Function: socketOnWrap], _paused: false, read: [Function], _consuming: true, _httpMessage: null, [Symbol(asyncId)]: 151, [Symbol(bytesRead)]: 0, [Symbol(asyncId)]: 153, [Symbol(triggerAsyncId)]: 151 }, connection: Socket { connecting: false, _hadError: false, _handle: [Object], _parent: null, _host: null, _readableState: [Object], readable: true, domain: null, _events: [Object], _eventsCount: 10, _maxListeners: undefined, _writableState: [Object], writable: true, allowHalfOpen: true, _bytesDispatched: 155, _sockname: null, _pendingData: null, _pendingEncoding: '', server: [Object], _server: [Object], _idleTimeout: 5000, _idleNext: [Object], _idlePrev: [Object], _idleStart: 12562, _destroyed: false, parser: [Object], on: [Function: socketOnWrap], _paused: false, read: [Function], _consuming: true, _httpMessage: null, [Symbol(asyncId)]: 151, [Symbol(bytesRead)]: 0, [Symbol(asyncId)]: 153, [Symbol(triggerAsyncId)]: 151 }, httpVersionMajor: 1, httpVersionMinor: 1, httpVersion: '1.1', plete: true, headers: { host: 'localhost:5500', 'user-agent': 'Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:64.0) Gecko/20100101 Firefox/64.0', accept: 'text/html,application/xhtml+xml,application/xml;q=0.9,/;q=0.8', 'accept-language': 'en-US,en;q=0.5', 'accept-encoding': 'gzip, deflate', connection: 'keep-alive', 'upgrade-insecure-requests': '1', 'if-none-match': 'W/"19-c6Hfa5VVP+Ghysj+6y9cPi5QQbk"' }, rawHeaders: [ 'Host', 'localhost:5500', 'User-Agent', 'Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:64.0) Gecko/20100101 Firefox/64.0', 'Accept', 'text/html,application/xhtml+xml,application/xml;q=0.9,/;q=0.8', 'Accept-Language', 'en-US,en;q=0.5', 'Accept-Encoding', 'gzip, deflate', 'Connection', 'keep-alive', 'Upgrade-Insecure-Requests', '1', 'If-None-Match', 'W/"19-c6Hfa5VVP+Ghysj+6y9cPi5QQbk"' ], trailers: {}, rawTrailers: [], upgrade: false, url: '/hello-world', method: 'GET', statusCode: null, statusMessage: null, client: Socket { connecting: false, _hadError: false, _handle: [Object], _parent: null, _host: null, _readableState: [Object], readable: true, domain: null, _events: [Object], _eventsCount: 10, _maxListeners: undefined, _writableState: [Object], writable: true, allowHalfOpen: true, _bytesDispatched: 155, _sockname: null, _pendingData: null, _pendingEncoding: '', server: [Object], _server: [Object], _idleTimeout: 5000, _idleNext: [Object], _idlePrev: [Object], _idleStart: 12562, _destroyed: false, parser: [Object], on: [Function: socketOnWrap], _paused: false, read: [Function], _consuming: true, _httpMessage: null, [Symbol(asyncId)]: 151, [Symbol(bytesRead)]: 0, [Symbol(asyncId)]: 153, [Symbol(triggerAsyncId)]: 151 }, _consuming: false, _dumped: true, next: [Function: next], baseUrl: '', originalUrl: '/hello-world', _parsedUrl: Url { protocol: null, slashes: null, auth: null, host: null, port: null, hostname: null, hash: null, search: null, query: null, pathname: '/hello-world', path: '/hello-world', href: '/hello-world', _raw: '/hello-world' }, params: {}, query: {}, res: [Circular], body: {}, route: Route { path: '/hello-world', stack: [Array], methods: [Object] } }, locals: {}, statusCode: 304, statusMessage: 'Not Modified', [Symbol(outHeadersKey)]: { 'x-powered-by': [ 'X-Powered-By', 'Express' ], etag: [ 'ETag', 'W/"19-c6Hfa5VVP+Ghysj+6y9cPi5QQbk"' ] } }
In no place in the response object does the {"message":"Hello World"} message appears, I would like to know how to obtain the body from the res and req objects if it is possible please.
Note: I know that nestjs has Interceptors, but following what the documentation says, middleware should be the solution for this problem.
- Still having problems? :-) – Kim Kern Commented Feb 10, 2019 at 23:08
3 Answers
Reset to default 5I've run against this question accidentally, it was listed in "related" to my question.
I can extend Kim Kern's answer a bit more, about responses.
Problem with response is that response body ain't a property of response object, but stream. To be able to get it, you need to override methods, which writes to that stream.
Like Kim Kern already said, you can look onto this thread, there is accepted answer how to do this.
Or you can take express-mung middleware, which will do it for you, for example:
var mung = require('express-mung');
app.use(mung.json(
function transform(body, req, res) {
console.log(body); // or whatever logger you use
return body;
}
));
And there are two other different ways, which NestJS can offer you:
- Interceptors, like you said. There is example of
LoggingInterceptorin documentation. - You can write decorator for controller's methods, which will intercept their responses.
import { isObservable, from, of } from 'rxjs';
import { mergeMap } from 'rxjs/operators';
/**
* Logging decorator for controller's methods
*/
export const LogReponse = (): MethodDecorator =>
(target: object, propertyKey: string | symbol, descriptor: TypedPropertyDescriptor<any>) => {
// save original method
const original = descriptor.value;
// replace original method
descriptor.value = function() { // must be ordinary function, not arrow function, to have `this` and `arguments`
// get original result from original method
const ret = original.apply(this, arguments);
// if it is null or undefined -> just pass it further
if (ret == null) {
return ret;
}
// transform result to Observable
const ret$ = convert(ret);
// do what you need with response data
return ret$.pipe(
map(data => {
console.log(data); // or whatever logger you use
return data;
})
);
};
// return modified method descriptor
return descriptor;
};
function convert(value: any) {
// is this already Observable? -> just get it
if (isObservable(value)) {
return value;
}
// is this array? -> convert from array
if (Array.isArray(value)) {
return from(value);
}
// is this Promise-like? -> convert from promise, also convert promise result
if (typeof value.then === 'function') {
return from(value).pipe(mergeMap(convert));
}
// other? -> create stream from given value
return of(value);
}
Note though, that this will executes before interceptors, because this decorator change methods behaviour.
And I don't think this is nice way to do logging, just mentioned it for variety :)
It's incredible how something so trivial is so hard to do.
The easier way to log response body is to create an Interceptor (https://docs.nestjs./interceptors):
AppModule:
providers: [
{
provide: APP_INTERCEPTOR,
useClass: HttpInterceptor,
}
]
HttpInterceptor:
import { CallHandler, ExecutionContext, Injectable, Logger, NestInterceptor } from '@nestjs/mon';
import { Observable } from 'rxjs';
import { map } from 'rxjs/operators';
@Injectable()
export class HttpInterceptor implements NestInterceptor {
private readonly logger = new Logger(HttpInterceptor.name);
intercept(
context: ExecutionContext,
next: CallHandler<any>,
): Observable<any> | Promise<Observable<any>> {
return next.handle().pipe(
map(data => {
this.logger.debug(data);
return data;
}),
);
}
}
The response body will not be accessible as a property. See this thread for a solution.
You should however be able to access the request body with req.body since nest uses bodyParser by default.