Exception during initialization

[clusterberries]

Hi all!

I am using bunyan and bunyan-rotating-file-stream for loggin in an Electron app. The code is pretty simple:

    var rotatingStream = new RotatingStream({
        path: LOG_DIR + logFile, // logFile is 'app%Y-%m-%dT%H_%M_%S.%LZ.log'
        threshold: LOG_MAX_FILE_SIZE,
        totalFiles: LOG_MAX_NUM_OF_FILES
    });
    var outputStream = bFormat({ outputMode: 'long', color: false }, rotatingStream);

    var currentLogLevel = LOG_LEVEL.MAXIMUM;
    var config = {
        name: 'app',
        level: LOG_LEVEL.MAXIMUM.level,
        stream: outputStream
    };

    var logger = bunyan.createLogger(config);

I faced with a strange issue: some users reported that they got 2 exceptions during app start. The first exception is ENOENT: no such file or directory, stat 'C:\Users\...\AppData\Roaming\...\app2018-03-21T16_49_45.909Z.log' The second one is:

TypeError: Cannot read property 'mtime' of undefined
    at D:\...\app\node_modules\bunyan-rotating-file-stream\lib\datestampedfileops.js:94:37
    at D:\...\app\node_modules\bunyan-rotating-file-stream\node_modules\async\lib\async.js:486:13
    at D:\...\app\node_modules\bunyan-rotating-file-stream\node_modules\async\lib\async.js:356:13
    at async.forEachOf.async.eachOf (D:\...\app\node_modules\bunyan-rotating-file-stream\node_modules\async\lib\async.js:233:13)
    at _asyncMap (D:\...\app\node_modules\bunyan-rotating-file-stream\node_modules\async\lib\async.js:355:9)
    at Object.map (D:\...\app\node_modules\bunyan-rotating-file-stream\node_modules\async\lib\async.js:337:20)
    at Object.async.sortBy (D:\...\app\node_modules\bunyan-rotating-file-stream\node_modules\async\lib\async.js:485:15)
    at sortFilesByModifiedTime (D:\...\app\node_modules\bunyan-rotating-file-stream\lib\datestampedfileops.js:93:15)
    at fn (D:\...\app\node_modules\bunyan-rotating-file-stream\node_modules\async\lib\async.js:746:34)
    at D:\...\app\node_modules\bunyan-rotating-file-stream\node_modules\async\lib\async.js:1213:16

Unfortunately I wasn't able to reproduce this bug. The only thing that works is to change some of the files names in filterJustOurLogFiles function. In this case some log files cannot be found, as a result stat object is undefined and exception occurs.

Do you have any ideas how to avoid this exception? If no, then this issue is only for proper exception handling.

[Rcomian]

That's interesting, the only thing that jumps out at me is the bFormat usage. I'm not familiar with that, could it be we're not playing well with that module?

[Rcomian]

It looks like we're getting the list of files in the directory, going over the files and getting the modified times of them and in the time between the two operations, the files have been deleted.

Actually, I'd not thought about electron apps. Is it possible your users are running multiple instances of the app?

If so, multiple processes talking to the same directory just won't work. We can harden the areas involved so that they don't fail so badly - this will need doing, but there's a fundamental issue with multiple processes talking to the same files.

Could you maybe put a PID folder in the path to logs.

Ugh, but I guess this breaks the model of controlling how much space log files take up, especially as the path PID means that log files will continually pile up.

I'll think about this. If you have any thoughts let me know.

[clusterberries]

Hi @Rcomian! I also have thoughts that some log file is deleted or renamed after we get list or files. But I don't know how, because my app doesn't touch log files. Application instance can't be run multiple times, I prevent it. Bunyan-format also shouldn't cause this issue, because it works only with writable stream.

I have full logs from one of the users. Its number is maximum possible (5), and I can see that file from ENOENT error is older than existing ones. The situation seems to be as the following: app is started, logs are full, so the oldest file is deleted, but the list of files wasn't updated.

Only 3 users were able to reproduce it and they can't do it now. I tried different scenarios, but I couldn't reproduce the errors. It is a very rare case, so I began to think that it is some kind of Windows glitch. Maybe when unlink callback is called, the actual file still exists, because Windows need some time for this operation... Fyi, some time ago there was similar issue in node https://github.com/nodejs/node-v0.x-archive/issues/7164

[clusterberries]

@Rcomian I received a feedback from one user and he said that he gets the error after every reboot. I know that Windows can mark files "for deletion" and remove them after reboot, but it is true only for locked files. I believe so...

[clusterberries]

Hi @Rcomian ! Could you please take a look at my comments? Thanks!