EACCESS error is masked with ERR_MULTIPLE_CALLBACK error

[rooftopsparrow]

Hi!

I was looking at an issue in a new deployment which was crashing on startup and the only error present in the stderr logs was ERR_MULTIPLE_CALLBACK from rotating-file-stream.

After patching the utils.js file with an error log to print out where I suspected the error was occurring, I uncovered the real error:

ERROR: { [Error: EACCES: permission denied, mkdir 'log']
  [stack]: 'Error: EACCES: permission denied, mkdir \'log\'',
  [message]: 'EACCES: permission denied, mkdir \'log\'',
  errno: -13,
  code: 'EACCES',
  syscall: 'mkdir',
  path: 'log' }
_stream_writable.js:456
    throw new ERR_MULTIPLE_CALLBACK();
    ^
Error [ERR_MULTIPLE_CALLBACK]: Callback called multiple times
    at onwrite (_stream_writable.js:456:11)
    at RotatingFileStream._rewrite (/opt/service/node_modules/rotating-file-stream/index.js:66:66)
    at RotatingFileStream._write (/opt/service/node_modules/rotating-file-stream/index.js:100:7)
    at doWrite (_stream_writable.js:415:12)
    at clearBuffer (_stream_writable.js:545:7)
    at onwrite (_stream_writable.js:470:7)
    at RotatingFileStream._rewrite (/opt/service/node_modules/rotating-file-stream/index.js:66:66)
    at RotatingFileStream.end (/opt/service/node_modules/rotating-file-stream/index.js:127:12)
    at RotatingFileStream.<anonymous> (/opt/service/node_modules/rotating-file-stream/utils.js:216:8)
    at Object.onceWrapper (events.js:286:20)

Furthermore, the error event was not fired. This is on nodejs v10.16.0. I will try to make a PR with a failing test to replicate this behavior.

Thanks for your module!

[iccicci]

Hi @rooftopsparrow ,

can you please provide me a not trunked stack trace?
As you can see the piece you pasted is missing of importante info.

Thank you,
iCC

[rooftopsparrow]

Sorry about that! I updated the description of the issue to contain the full lines.

[iccicci]

Thank you,

in my timezone is over midnight, tomorrow I'll check it.

[iccicci]

Hi @rooftopsparrow ,

I found something possibly generating the reported problem.
Could you please test the master branch in your environment to check if my change really solves the problem or send me a code piece to reproduce the error to let me check my change by myself?

Thank you,
iCC

[rooftopsparrow]

Hi @iccicci,

I can't get tests to pass from a clean checkout of master. Do you happen to know why this is the case? I can dig into the problem but I thought I'd ask you first if you've seen this before. I am on macOS. Tried with both nodejs v8 and v10 versions.

  8 failing

  1) compression
       external
         rotated file content:

      Uncaught AssertionError [ERR_ASSERTION]: '' == 'test\ntest\n'
      + expected - actual

      +test
      +test

      at /usr/local/workspace/github/rotating-file-stream/test/07compression.js:53:12
      at ChildProcess.exithandler (child_process.js:301:5)
      at maybeClose (internal/child_process.js:970:16)
      at Socket.stream.socket.on (internal/child_process.js:389:11)
      at Pipe._handle.close (net.js:597:12)

  2) compression
       external custom
         rotated file content:

      Uncaught AssertionError [ERR_ASSERTION]: '' == 'test\ntest\n'
      + expected - actual

      +test
      +test

      at /usr/local/workspace/github/rotating-file-stream/test/07compression.js:101:12
      at ChildProcess.exithandler (child_process.js:301:5)
      at maybeClose (internal/child_process.js:970:16)
      at Socket.stream.socket.on (internal/child_process.js:389:11)
      at Pipe._handle.close (net.js:597:12)

  3) compression
       internal (gzip)
         rotated file content:

      Uncaught AssertionError [ERR_ASSERTION]: '' == 'test\ntest\n'
      + expected - actual

      +test
      +test

      at /usr/local/workspace/github/rotating-file-stream/test/07compression.js:144:12
      at ChildProcess.exithandler (child_process.js:301:5)
      at maybeClose (internal/child_process.js:970:16)
      at Socket.stream.socket.on (internal/child_process.js:389:11)
      at Pipe._handle.close (net.js:597:12)

  4) compression
       missing path
         rotated file content:

      Uncaught AssertionError [ERR_ASSERTION]: '' == 'test\ntest\n'
      + expected - actual

      +test
      +test

      at /usr/local/workspace/github/rotating-file-stream/test/07compression.js:190:12
      at ChildProcess.exithandler (child_process.js:301:5)
      at maybeClose (internal/child_process.js:970:16)
      at Socket.stream.socket.on (internal/child_process.js:389:11)
      at Pipe._handle.close (net.js:597:12)

  5) use cases
       use case
         rotated file content:

      Uncaught AssertionError [ERR_ASSERTION]: '' == 'test\n'
      + expected - actual

      +test

      at /usr/local/workspace/github/rotating-file-stream/test/08use_case.js:80:12
      at ChildProcess.exithandler (child_process.js:301:5)
      at maybeClose (internal/child_process.js:970:16)
      at Process.ChildProcess._handle.onexit (internal/child_process.js:259:5)

  6) classical
       compression
         rotated file content 1:

      Uncaught AssertionError [ERR_ASSERTION]: '' == 'test\ntest\ntest\n'
      + expected - actual

      +test
      +test
      +test

      at /usr/local/workspace/github/rotating-file-stream/test/09classical.js:185:12
      at ChildProcess.exithandler (child_process.js:301:5)
      at maybeClose (internal/child_process.js:970:16)
      at Process.ChildProcess._handle.onexit (internal/child_process.js:259:5)

  7) classical
       compression
         rotated file content 2:

      Uncaught AssertionError [ERR_ASSERTION]: '' == 'test\ntest\n'
      + expected - actual

      +test
      +test

      at /usr/local/workspace/github/rotating-file-stream/test/09classical.js:192:12
      at ChildProcess.exithandler (child_process.js:301:5)
      at maybeClose (internal/child_process.js:970:16)
      at Socket.stream.socket.on (internal/child_process.js:389:11)
      at Pipe._handle.close (net.js:597:12)

  8) history
       maxFiles
         warning:
     AssertionError [ERR_ASSERTION]: undefined == 'File \'test\' contained in history is not a regular file'
      at Context.<anonymous> (test/10history.js:45:11)

[iccicci]

Hi @rooftopsparrow ,

I'm sorry, I never tested the package in macOS neither I can't say why tests don't work under it. :(
I suggest anyway to try to solve one problem by time: let's focus on the original problem reported in this issue, then (why not?) let's open a new issue about tests not running under macOS.

What do you think about?

[rooftopsparrow]

Yeah @iccicci that's no problem, I'll work on verifying your fix on my environment and I'll open an issue and PR for whatever this macOS problem is.

[rooftopsparrow]

Sorry for the delay!

I am happy to report that packaging up the current master and deploying in the environment shows the correct error.

Jun 27 15:47:18 start.sh[3862]: Rotating File Stream error: { [Error: EACCES: permission denied, mkdir 'log']
Jun 27 15:47:18 start.sh[3862]:   [stack]: 'Error: EACCES: permission denied, mkdir \'log\'',
Jun 27 15:47:18 start.sh[3862]:   [message]: 'EACCES: permission denied, mkdir \'log\'',
Jun 27 15:47:18 start.sh[3862]:   errno: -13,
Jun 27 15:47:18 start.sh[3862]:   code: 'EACCES',
Jun 27 15:47:18 start.sh[3862]:   syscall: 'mkdir',
Jun 27 15:47:18 start.sh[3862]:   path: 'log' }
Jun 27 15:47:18 start.sh[3862]: Rotating File Stream error: { Error [ERR_STREAM_WRITE_AFTER_END]: write after end
Jun 27 15:47:18 start.sh[3862]:     at writeAfterEnd (_stream_writable.js:248:12)
Jun 27 15:47:18 start.sh[3862]:     at RotatingFileStream.Writable.write (_stream_writable.js:296:5)
Jun 27 15:47:18 start.sh[3862]:     at Object.write (/opt/service/src/logger/index.js:47:16)
Jun 27 15:47:18 start.sh[3862]:     at Logger._log (/opt/service/node_modules/@bloom42/astro/lib/logger.js:95:20)
Jun 27 15:47:18 start.sh[3862]:     at Logger.info (/opt/service/node_modules/@bloom42/astro/lib/logger.js:170:12)
Jun 27 15:47:18 start.sh[3862]:     at Array.onFinished (/opt/service/src/logger/accessMiddleware.js:36:29)
Jun 27 15:47:18 start.sh[3862]:     at listener (/opt/service/node_modules/on-finished/index.js:169:15)
Jun 27 15:47:18 start.sh[3862]:     at onFinish (/opt/service/node_modules/on-finished/index.js:100:5)
Jun 27 15:47:18 start.sh[3862]:     at callback (/opt/service/node_modules/ee-first/index.js:55:10)
Jun 27 15:47:18 start.sh[3862]:     at ServerResponse.onevent (/opt/service/node_modules/ee-first/index.js:93:5)
Jun 27 15:47:18 start.sh[3862]:   [stack]:
Jun 27 15:47:18 start.sh[3862]:    'Error [ERR_STREAM_WRITE_AFTER_END]: write after end\n    at writeAfterEnd (_stream_writable.js:248:12)\n    at RotatingFileStream.Writable.write (_stream_writable.js:296:5)\n    at Objec
Jun 27 15:47:18 start.sh[3862]:   [message]: 'write after end' }

[iccicci]

Thank you @rooftopsparrow ,

released version 1.4.2
iCC