search

winstonjs / winston

A logger for just about everything.
http://github.com/winstonjs/winston
MIT License
22.7k stars 1.8k forks source link

[Bug]: Write after end node error with winston logger #2219

Open suprith-s-reddy opened 1 year ago

suprith-s-reddy commented 1 year ago

🔎 Search Terms

Write after end node error

The problem

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.

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 an overhaul of requests which does not allow 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

Node.js version

18.11.0

In which operating systems have you tested?

What version of Winston presents the issue?

v3.8.2

What version of Node are you using?

v18.11.0

If this worked in a previous version of Winston, which was it?

No response

Minimum Working Example

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 {}

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"
  }
}

Additional information

No response

tashoecraft commented 1 year ago

I'm hitting this same error without nest.js. I'm seeing it on windows only when I blow through the maxFiles and maxSize during a single run. So if node is constantly running it seems to maintain reference to the original log file and that file's permissions prevent me from modifying the file. This triggers the write after end error (which goes uncaught even with handleExceptions).

tashoecraft commented 1 year ago

I'm wondering if this issue is linked too: https://github.com/winstonjs/winston/pull/2115/files

suprith-s-reddy commented 1 year ago

I'm wondering if this issue is linked too: https://github.com/winstonjs/winston/pull/2115/files

I am not sure, this issue only appeared when there was an overload of requests. You can just click the post option multiple times and see it in your code. I think its a bug with Winston and it hasn't been fixed. Did you find a solution for this one?

bdoyle0182 commented 1 year ago

Has any workaround been figured out for this issue?

DABH commented 1 year ago

A PR would be welcomed if anyone has time to investigate this further!

iradofurioso commented 10 months ago

Has anyone found a solution? latest version 3.11.0 on NPM with same problem.

madtisa commented 7 months ago

I've found the solution: switched to pino logger instead of waiting this (2-years old) issue to be fixed

paul-uz commented 3 months ago

Any updates on this? Hitting this on AWS Lambda