rogerc / file-stream-rotator

NodeJS file stream rotator
MIT License
143 stars 69 forks source link

Concurrency issue with symlink feature #65

Closed Apollon77 closed 4 years ago

Apollon77 commented 4 years ago

When you have multiple processes writing to the same logfile and using the symlink feature we ended up in this exception sometimes:

Error: EEXIST: file already exists, symlink 'iobroker.2020-01-11.log' -> '/opt/iobroker/log/iobroker.current.log'
at Object.symlinkSync (fs.js:909:3)
at createCurrentSymLink (/opt/iobroker/node_modules/file-stream-rotator/FileStreamRotator.js:303:16)
at EventEmitter. (/opt/iobroker/node_modules/file-stream-rotator/FileStreamRotator.js:530:17)
at EventEmitter.emit (events.js:203:15)
at /opt/iobroker/node_modules/file-stream-rotator/FileStreamRotator.js:607:20
at process._tickCallback (internal/process/next_tick.js:61:11)
at Function.Module.runMain (internal/modules/cjs/loader.js:834:11)
at startup (internal/bootstrap/node.js:283:19)
at bootstrapNodeJSCore (internal/bootstrap/node.js:623:3)

From my Analysis the following happens: 1.) When multiple processes do their first write at "0:0:0" (in our case because daily rotate) then we execute https://github.com/rogerc/file-stream-rotator/blob/master/FileStreamRotator.js#L296-L299 partially multiple times and nearly each of these commands can produce an ENOENT 2.) When this happens multiple processes execute the problematic line and the first one will succeed, all the others will get an EEXISTS exception

Solution: 1.) In https://github.com/rogerc/file-stream-rotator/blob/master/FileStreamRotator.js#L303 there is no try/catch for the command and so it throws the uncatchable exception. So at least there should be a try/catch added 2.) This try catch normally should never happen, so question is what should be done when it happens?

Apollon77 commented 4 years ago

see really minimal PR ... or do we need somthing more fancy?

GermanBluefox commented 4 years ago

Other ideas:

Apollon77 commented 4 years ago

do not use symlink and manage it ourselves. yes but then we have the same challenge on our side ;-) or need to exactly do the same

We might remove the symlink feature again before next release if the PR needs too long here because becomes pressing. @rogerc @hx-markterry (sorry for the preasure but our application crashes because of this)

rogerc commented 4 years ago

I've pushed v0.5.6 with a previos PR that fixes this issue as the PR raised did. Thanks.

Apollon77 commented 4 years ago

Thank you very much!!

Apollon77 commented 4 years ago

PS: me personally would not have done the console.error because this might have implications because it is an error logged ... so with the knowledge of such concurrency issues and an EEXISTS it would be possible to only log that if it is not EEXISTS. In fact users will see error logs of clear false positives in this case ...

mattberther commented 4 years ago

Agreed, @Apollon77. I've created #67 to address this and only output to the log if the verbose option is set.

Apollon77 commented 4 years ago

Great idea. Thank you and also for catching up that fast.