search

gremo / nest-winston

A Nest module wrapper form winston logger
MIT License
645 stars 94 forks source link

Write after end node error with winston and nest-winston logger #587

Closed suprith-s-reddy closed 1 year ago

suprith-s-reddy commented 2 years ago

Is there an existing issue for this?

Current behavior

I am using nest-winston and winston packages to invoke a global logger for my nestjs API.

So I have defined the below code as a winston logger config:

file: winston-logger.config.ts

import { utilities as nestWinstonModuleUtilities } from 'nest-winston';
import * as winston from 'winston';

export const loggerOptions = {
  transports: [
    new winston.transports.Console({
      format: winston.format.combine(
        winston.format.timestamp(),
        winston.format.ms(),
        nestWinstonModuleUtilities.format.nestLike(),
      ),
    }),
    new winston.transports.Http({
      format: winston.format.combine(
        winston.format.timestamp(),
        winston.format.ms(),
        nestWinstonModuleUtilities.format.nestLike(),
      ),
    }),
    new winston.transports.File({
      level: 'info',
      filename: './logs/all-logs.log',
      handleExceptions: true,
      maxsize: 5242880,
      maxFiles: 5,
    }),
    new winston.transports.File({
      level: 'error',
      filename: './logs/errors.log',
      handleExceptions: true,
      maxsize: 5242880,
      maxFiles: 5,
    }),
  ],
  exceptionHandlers: [
    new winston.transports.File({
      filename: './logs/exceptions.log',
      maxsize: 5242880,
    }),
  ],
  exitOnError: false,
};

file: main.ts

import { NestFactory } from '@nestjs/core';
import { ValidationPipe } from '@nestjs/common';
import { NestExpressApplication } from '@nestjs/platform-express';
import { DocumentBuilder, SwaggerModule } from '@nestjs/swagger';
import cookieParser from 'cookie-parser';
import helmet from 'helmet';
import { join } from 'path';
import { AppModule } from './app.module';
import { WinstonModule } from 'nest-winston';
import { loggerOptions } from './config/winston-logger.config';
import { validationPipeFactory } from './common/helpers/validation-pipe-factory.helper';
import appConfig from './config/app.config';

async function bootstrap() {
  const app = await NestFactory.create<NestExpressApplication>(AppModule, {
    logger: WinstonModule.createLogger(loggerOptions),
    bodyParser: true,
  });
  app.useGlobalPipes(
    new ValidationPipe({
      transform: true,
      exceptionFactory: validationPipeFactory,
    }),
  );
  app.enableCors();
  app.use(cookieParser());
  app.use(helmet());
  app.useStaticAssets(join(__dirname, '..', 'public'));
  app.setBaseViewsDir(join(__dirname, '..', 'views'));
  app.setViewEngine('hbs');

  /**
   * ===========================
   * Setup Swagger Documentation
   * ===========================
   */
  const config = new DocumentBuilder()
    .setTitle(appConfig().title)
    .setDescription(appConfig().description)
    .setVersion(appConfig().version)
    .build();
  const document = SwaggerModule.createDocument(app, config);
  SwaggerModule.setup(appConfig().swaggerRoute, app, document);
  /**
   * ===========================
   */

  await app.listen(appConfig().port);
}
bootstrap();

file: app.module.ts

import { Logger, Module } from '@nestjs/common';
import { ConfigModule } from '@nestjs/config';
import { MongooseModule } from '@nestjs/mongoose';
import { APP_FILTER } from '@nestjs/core';
import { EventEmitterModule } from '@nestjs/event-emitter';
import { CommonModule } from './common/common.module';
import { MongooseConfig } from './config/mongoose.config';
import { HttpErrorFilter } from './common/filters/http-error.filter';
import { WinstonModule } from 'nest-winston';
import { TerminusModule } from '@nestjs/terminus';
import { HttpModule } from '@nestjs/axios';
import { HealthController } from './health/health.controller';
import { AppController } from './app.controller';
import { AppService } from './app.service';
import { CoreModule } from './core/core.module';
import appConfig from './config/app.config';
import envConfig from './config/env.config';

@Module({
  imports: [
    ConfigModule.forRoot({
      envFilePath: envConfig.envFilePath,
      load: [appConfig],
      isGlobal: true,
      expandVariables: true,
    }),
    WinstonModule.forRoot({}),
    TerminusModule,
    HttpModule,
    CommonModule,
    CoreModule,
    MongooseModule.forRootAsync({
      useClass: MongooseConfig,
    }),
    EventEmitterModule.forRoot({
      // set this to `true` to use wildcards
      wildcard: false,
      // the delimiter used to segment namespaces
      delimiter: '.',
      // set this to `true` if you want to emit the newListener event
      newListener: false,
      // set this to `true` if you want to emit the removeListener event
      removeListener: false,
      // the maximum amount of listeners that can be assigned to an event
      maxListeners: 10,
      // show event name in memory leak message when more than maximum amount of listeners is assigned
      verboseMemoryLeak: false,
      // disable throwing uncaughtException if an error event is emitted and it has no listeners
      ignoreErrors: false,
    }),
  ],
  controllers: [AppController, HealthController],
  providers: [
    Logger,
    AppService,
    {
      provide: APP_FILTER,
      useClass: HttpErrorFilter,
    },
  ],
})
export class AppModule {}

I am using postman to test my requests and responses. When I am hitting the send request button very quickly without a delay, there is a overhaul of a request which does not allow the winston to end its stream write operation, creating a write after end Node error which breaks the whole API. It also stops the server at the moment. Below is the output.

NodeError: write after end
    at writeAfterEnd (/Users/suprith.reddy/Documents/softhesis/softhesis-cloud-api/sc-auth-service/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:261:12)
    at PassThrough.Writable.write (/Users/suprith.reddy/Documents/softhesis/softhesis-cloud-api/sc-auth-service/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:305:21)
    at File.log (/Users/suprith.reddy/Documents/softhesis/softhesis-cloud-api/sc-auth-service/node_modules/winston/lib/winston/transports/file.js:185:34)
    at ExceptionStream._write (/Users/suprith.reddy/Documents/softhesis/softhesis-cloud-api/sc-auth-service/node_modules/winston/lib/winston/exception-stream.js:48:29)
    at doWrite (/Users/suprith.reddy/Documents/softhesis/softhesis-cloud-api/sc-auth-service/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:409:139)
    at writeOrBuffer (/Users/suprith.reddy/Documents/softhesis/softhesis-cloud-api/sc-auth-service/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:398:5)
    at ExceptionStream.Writable.write (/Users/suprith.reddy/Documents/softhesis/softhesis-cloud-api/sc-auth-service/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:307:11)
    at DerivedLogger.ondata (/Users/suprith.reddy/Documents/softhesis/softhesis-cloud-api/sc-auth-service/node_modules/winston/node_modules/readable-stream/lib/_stream_readable.js:681:20)
    at DerivedLogger.emit (node:events:525:35)
    at addChunk (/Users/suprith.reddy/Documents/softhesis/softhesis-cloud-api/sc-auth-service/node_modules/winston/node_modules/readable-stream/lib/_stream_readable.js:298:12)
Emitted 'error' event on PassThrough instance at:
    at errorOrDestroy (/Users/suprith.reddy/Documents/softhesis/softhesis-cloud-api/sc-auth-service/node_modules/winston/node_modules/readable-stream/lib/internal/streams/destroy.js:98:101)
    at writeAfterEnd (/Users/suprith.reddy/Documents/softhesis/softhesis-cloud-api/sc-auth-service/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:263:3)
    at PassThrough.Writable.write (/Users/suprith.reddy/Documents/softhesis/softhesis-cloud-api/sc-auth-service/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:305:21)
    [... lines matching original stack trace ...]
    at DerivedLogger.emit (node:events:525:35)

Node.js v18.11.0

The error occurs irrespective of the API call with the above configuration. I would like to know if this is a bug by nest-winston or the core winston package itself and if there is any workaround for the same.

package

nest-winston and winston

NestJS version

9.0.0

Packages versions

{
  "name": "oauth-service",
  "version": "0.0.1",
  "description": "",
  "author": "",
  "private": true,
  "license": "UNLICENSED",
  "scripts": {
    "prebuild": "rimraf dist",
    "build": "nest build",
    "format": "prettier --write \"src/**/*.ts\" \"test/**/*.ts\"",
    "start": "nest start",
    "start:dev": "NODE_ENV=development nest start --watch",
    "start:debug": "nest start --debug --watch",
    "start:staging": "NODE_ENV=staging node dist/main",
    "start:prod": "node dist/main",
    "lint": "eslint \"{src,apps,libs,test}/**/*.ts\" --fix",
    "test": "jest",
    "test:watch": "jest --watch",
    "test:cov": "jest --coverage",
    "test:debug": "node --inspect-brk -r tsconfig-paths/register -r ts-node/register node_modules/.bin/jest --runInBand",
    "test:e2e": "jest --config ./test/jest-e2e.json"
  },
  "dependencies": {
    "@casl/ability": "^6.1.1",
    "@casl/mongoose": "^7.1.0",
    "@google-cloud/storage": "^6.5.0",
    "@nestjs/axios": "^0.1.0",
    "@nestjs/common": "^9.0.0",
    "@nestjs/config": "^2.2.0",
    "@nestjs/core": "^9.0.0",
    "@nestjs/event-emitter": "^1.3.1",
    "@nestjs/jwt": "^9.0.0",
    "@nestjs/mapped-types": "^1.1.0",
    "@nestjs/mongoose": "^9.2.0",
    "@nestjs/passport": "^9.0.0",
    "@nestjs/platform-express": "^9.0.0",
    "@nestjs/swagger": "^6.1.2",
    "@nestjs/terminus": "^9.1.1",
    "@types/mime-types": "^2.1.1",
    "@types/multer": "^1.4.7",
    "bcrypt": "^5.0.1",
    "class-transformer": "^0.5.1",
    "class-validator": "^0.13.2",
    "cookie-parser": "^1.4.6",
    "form-data": "^4.0.0",
    "googleapis": "^107.0.0",
    "hbs": "^4.2.0",
    "helmet": "^6.0.0",
    "mongoose": "^6.6.1",
    "nest-winston": "^1.7.0",
    "passport-jwt": "^4.0.0",
    "reflect-metadata": "^0.1.13",
    "rimraf": "^3.0.2",
    "rxjs": "^7.2.0",
    "winston": "^3.8.2"
  },
  "devDependencies": {
    "@nestjs/cli": "^9.0.0",
    "@nestjs/schematics": "^9.0.0",
    "@nestjs/testing": "^9.0.0",
    "@types/cookie-parser": "^1.4.3",
    "@types/express": "^4.17.13",
    "@types/jest": "28.1.8",
    "@types/node": "^16.0.0",
    "@types/passport-jwt": "^3.0.6",
    "@types/supertest": "^2.0.11",
    "@typescript-eslint/eslint-plugin": "^5.0.0",
    "@typescript-eslint/parser": "^5.0.0",
    "eslint": "^8.0.1",
    "eslint-config-prettier": "^8.3.0",
    "eslint-plugin-prettier": "^4.0.0",
    "jest": "28.1.3",
    "prettier": "^2.3.2",
    "source-map-support": "^0.5.20",
    "supertest": "^6.1.3",
    "ts-jest": "28.0.8",
    "ts-loader": "^9.2.3",
    "ts-node": "^10.0.0",
    "tsconfig-paths": "4.1.0",
    "typescript": "^4.7.4"
  },
  "jest": {
    "moduleFileExtensions": [
      "js",
      "json",
      "ts"
    ],
    "rootDir": "src",
    "testRegex": ".*\\.spec\\.ts$",
    "transform": {
      "^.+\\.(t|j)s$": "ts-jest"
    },
    "collectCoverageFrom": [
      "**/*.(t|j)s"
    ],
    "coverageDirectory": "../coverage",
    "testEnvironment": "node"
  }
}

Node.js version

18.11.0

In which operating systems have you tested?

amine0909 commented 1 year ago

same problem here

amine0909 commented 1 year ago

@gremo Is there any fix for this, because i'm facing the same problem.

FYI: i'm using nodejs 16, nestJS version 9

github-actions[bot] commented 1 year ago

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 7 days.

github-actions[bot] commented 1 year ago

This issue was closed because it has been stalled for 7 days with no activity.