transports.File stops logger without any error message #1194
Comments
|
I have the same problem. But for mit only occures, when I'm logging something really long |
|
I test this case on mac os. The same case in linux are working fine. |
|
I'm having this issue on Arch Linux. However, it works fine with wintston@2.4.0. |
|
Hi, Same case here on a raspberry pi3 with I have 3 DailyRotateFile loggers with differents levels and a console logger in dev env. My config is the following const consoleFormat = winston.format.combine(
winston.format.colorize(),
winston.format.timestamp(),
winston.format.align(),
winston.format.splat(),
winston.format.printf((info) => {
const ts = info.timestamp.slice(0, 19).replace('T', ' ');
if (info.args) {
return `${ts} [${info.level}]: ${info.message} ${(info.level > 3 && (Object.keys(info.args).length || Object.getOwnPropertyNames(info.args).length)) ? JSON.stringify(info.args, null, 2) : ''}`;
} else {
return `${ts} [${process.pid}] [${info.level}]: ${info.message}`;
}
})
);
const fileFormat = winston.format.combine(
winston.format.timestamp(),
winston.format.align(),
winston.format.splat(),
winston.format.printf((info) => {
const ts = info.timestamp.slice(0, 19).replace('T', ' ');
if (info.args) {
return `${ts} [${process.pid}] [${info.level}]: ${info.message} ${(Object.keys(info.args).length || Object.getOwnPropertyNames(info.args).length) ? JSON.stringify(info.args, null, 2) : ''}`;
} else {
return `${ts} [${process.pid}] [${info.level}]: ${info.message}`;
}
})
);
winston.addColors(logLevels);
const LOG_LEVEL = process.env.NODE_LOG_LEVEL || 'verbose';
const CONSOLE_LEVEL = process.env.NODE_CONSOLE_LEVEL || 'info';
const logger = winston.createLogger({
level: LOG_LEVEL,
levels: logLevels.levels,
format: fileFormat,
transports: [
//
// - Write all logs error (and below) to `error.log`.
// - Write all silly logs (and below) to silly.log.
// - Write all %level% logs (and below) to main.log
//
new DailyRotateFile({ filename: path.join(LOGS_DIR, 'error.log'), level: 'error', handleExceptions: true }),
new DailyRotateFile({ filename: path.join(LOGS_DIR, 'silly.log'), level: 'silly' }),
new DailyRotateFile({ filename: path.join(LOGS_DIR, 'combined.log'), level: LOG_LEVEL })
]
});
if (process.env.NODE_ENV !== 'production') {
logger.add(new winston.transports.Console({
format: consoleFormat,
colorize: true,
level: CONSOLE_LEVEL
}));
}
logger.exitOnError = false;I have noticed that my file logger stops at 21:56 and my console logger continued until 22:43. I also notice that the error file is empty. How can i provide more traces related to winston ? Thanks |
|
I just ran into the same issue as @bouchezb and my setup is effectively identical: I similarly use The Anyone have any ideas as to what's going on? [I should note that I'm running my server process in a Node Docker container (currently at 7.8.0). When the issue appears, checking for open files does not show the expected log file. The expected log file does appear to be open when the process is restarted. Something, it seems, is causing the stream to be closed.] |
|
Hi, I haven't found a solution yet (better than cron restart). |
Yes, I believe you're correct. I noticed that it was possible to hook into the stream events in the main README.md:
So... I implemented them: // DEBUGGING.
rotateFileTransport.on('close', function () {
console.trace("Transport Stream Closing?!");
});
rotateFileTransport.on('finish', function () {
console.trace("Transport Stream Finished?!");
});
rotateFileTransport.on('error', function (err: Error) {
console.trace("Error with Transport [Stream?]?!");
console.dir(err);
});
rotateFileTransport.on('open', function (fd: any) {
console.trace("Transport Stream Opened?!");
console.dir(fd);
});
rotateFileTransport.on('rotate', function (oldFile: any, newFile: any) {
console.trace("Rotating Files?!");
console.dir(oldFile);
console.dir(newFile);
});[I used I then played the waiting game. At some point a log entry was triggered at 02:25 UTC and the following flow of output occurred: Express Endpoint Processing ErrorThe following error occurred. The important part is the timestamp (specifically 02:25:29): On Rotate TriggeredUp next is the Rotate event. The source is, unsurprisingly, here. This occurs after both The filenames output were as expected. On Close TriggeredThe starting point of this stack [fs.js:1973] looks a little odd at first (it's in a This is the point that I started finding the reported call-stacks oddly equal in length. It turns out, there's a default On Open TriggeredMy best guess is that this was triggered by the call to On Finish TriggeredI'm not entirely sure where this one came from, but it looks like finishMaybe is called once writing completes. Perhaps this occurs immediately after writing to the newly created file for the first time? On Close Triggered [again]This is the same callstack (top) as the last Closed event. My guess is that this is now the new file being closed. It seems that it's opened, written to once, and then immediately finalized and closed. This obviously isn't correct. No idea at present why this occurs (and am not 100% confident in this analysis). In the first part of this breakdown I showed the timestamp reported by the event (02:25:29). When listing the files in the log directory, I see the following: The important bit is the last modified time field: 02:25. It appears that the file is opened, written to, and then immediately closed. This is all triggered during the first event when file rotation occurs. I suspect that the same thing (or very similar) may be happening for people using the main File Transport. At this point I wish I'd added some timestamps to the logging. I'll add that and remove the stack trace limits to see what extra information I can glean from these events. |
I made those adjustments and modified some settings to make the file rotation occur every 2 minutes (and set FileStreamRotator to verbose). I immediately reproduced the issue. Here is what I got as output: On Open TriggeredThis is the initial file opening event. The number ( Log EventOne log event was triggered. File Rotation EventThat log event triggered the logic for the file rotation (I had waited more than the requisite 2min for file rotation). The first line is some of More Log EventsTwo more log events were triggered. They are downstream of (were triggered by) the previous log event. On Close TriggeredThe On Open TriggeredThe open event was triggered 1ms later. Note that the file descriptor is the same. On Finish TriggeredThe On Close TriggeredThe [Note]Several events quickly followed (<200ms) the final Removing the limit on call stack depth didn't reveal much extra with respect to the @indexzero, any thoughts here? If you've not seen these Issues yet, it seems that any Transport that attempts to close one file stream and open another (as the core File Transport does when you set a max size) will open the new file stream in such a manner that it is immediately closed. Is there a test that covers this scenario? This feels like a pretty serious showstopper for 3.0.0... |
|
One more note: I have been testing with Node 7.8.0. The file names and line numbers in the call stacks in my last two posts will resolve correctly with files in this commit of the main NodeJS repo. |
|
@bouchezb The While this good news is specifically related to the @billiebbb and @beac0n two questions for you:
I ask the second question because internal stream event bubbling with |
|
@ericdrobinson thanks for the fix. |
That would probably be best. This issue is specifically about the @indexzero What settings/event registrations would you recommend adding when attempting to figure out issues in |
|
Also seeing this issue on 3.0.0-rc3 I run the application and it works fine for some time, but then it fails to log to console or the log files with no exception or error generated - a "silent fail" Is there any work being done on this? |
|
@rcoedo commit fixes the issue but there is still an issue with formatting which I think is related to this. const winston = require('winston')
const winstonConfig = {
level: 'debug',
transports: [
new winston.transports.Console({
format: winston.format.printf(info => `${info.level}: ${info.message}`)
}),
new winston.transports.File({
filename: 'winston.log',
maxsize: 10 * 1024 * 1024,
maxFiles: 10,
format: winston.format.printf(info => `${info.level}: ${info.message}`)
})
]
}
const logger = winston.createLogger(winstonConfig)
for (let i = 0; i < 10000; i++) {
logger.debug(i)
}Produces this output to a file: Output in the console is formatted correctly. |
|
@jansteuer I can reproduce the behavior. When the stream.write tell us to wait for the drain event, the following 15 lines receive a non formatted message for some reason. I tried to find why but I failed. I believe this is related to how the Logger handles the transports but I'm not sure. Maybe someone with some expertise in winston can guide us to finally fix the file transport 😃 |
|
I implemented @rcoedo's fix, and the logger seemed stable for a few days, but today all of the logging for my application disappeared. There are no exceptions generated anywhere that I can see, and I can't find a way to reproduce it. Anybody at WinstonJS have an idea? The current workaround I am trying is to forcibly delete and reinstantiate the logger every 30 minutes. |
|
Hi Everyone, my team is also able to reproduce this issue with the latest version of winston@3.0.0-rc5. It's strange because when we first initialize our logger and run our application, everything is fine, or it seems... We log every time we receive a message from IBM MQLight and we noticed once around 600 messages (both from console and physical log file) winston inexplicably stops even though the application continues to run, just no logging at all?... We know the issue is coming from Winston because we modified this bit of code in our custom logging class library that instantiates our logger to use fs.createWriteStream instead of Winston and it always works: - vs - Does anyone have any solution as to why Winston stops randomly? |
|
@ericdrobinson Hmm, I was really hopeful.... I pulled the latest version from master in Winston as you recommended about an hour ago then manually dropped that version and referenced it in my code directly. Sadly, I received the same results. My test involved dumping 10000 messages at <5ms. After about 700 or 800 received and logged messages, Winston logging for file and console stopped. So I went into my logger class to again use my own little version of fs.createWriteStream (shown in my previous comment) and ran the exact same test, results showed that precisely 10000 messages were logged. Does Winston close the stream or something? The only difference I can see I'm doing with my little version of fs.createWriteStream in my test, is that I never close my stream or have any drain management. |
|
@ejaweb I've no idea. You could start digging into this yourself by adding some debug logging to your Winston setup to begin tracking things down. I did this previously for a different bug that was apparently specific to This bug report is missing good debug info from someone using the As you have a 100% repro-case, perhaps you could add in some debug output and provide further context? |
|
@ericdrobinson Oh man interesting news! Before I decided to make any additional changes to my code (to start tracking down the bug), I decided to try |
|
@indexzero Shouldn't this issue be Closed now? It's referenced as "Fixed" in the release notes for rc6... |
|
I think this still happens when using the |
|
I had same issue, today. What happened for me is the follwing
In my project I had deleted the folder containing the log files. In that case, winston was correctly logging stuff until it get to a specific point in the console! Always the same, don't know why. I fixed this by creating the containing folder. As soon as winston found a file to write in, console output was back to normal. Hope this helps. |
…ilable is set to true
|
@dlarr Yes I have observed the same thing myself. It seems to be caused by missing error handling code in winston. By my reckoning, when the file stream cannot be created because the parent folder is missing, the file transport is allowed to continue in a zombie state until the PassThrough fills up. At the end a pause() is called and waits for a drain that will never happen. |
|
In the particular case of @dlarr and me error handling in file.js!_createStream() and file.js!stat() should probably be looked at. |
|
In our project we have a derived logger that creates a Console transport and a File transport. If the logger is run in an environment where the parent folder of the file transport is missing, the logger stops logging as described above. Also the Console transport stops. Our workaround is to not let our derived logger to create the file transport if the parent folder of the log file is missing. |
* fix issue #1194 - where rotation of files isn't done when tailable is set to true * more fixes to tail rolling + fix & enable unit tests * fix unit tests interference from 01-file-maxsize - not sure why a new file gets created on an unrelated transport when adding a new Transport * Update 01-file-maxsize.test.js * Update file.js
|
Hopefully the case of tailable: true has also been fixed now, thanks to #1420. If someone could confirm or deny, testing against master, that would be awesome — would love to see this issue closed. The aforementioned fix will go out in the next release, which hopefully should be published very soon. |
|
I can confirm , the fix in master branch is working fine after setting tailable flag to true. Looking forward someone to publish this in npm. |
|
Going to go ahead and close this at last (3.1.0 was pushed to npm recently), but if anyone can reliably reproduce issues with the core File transport (or other core transports), please open a new issue and we'll work to get to the bottom of it. Thanks to everyone who contributed to documenting and solving this issue! |
* fix issue winstonjs#1194 - where rotation of files isn't done when tailable is set to true * more fixes to tail rolling + fix & enable unit tests * fix unit tests interference from 01-file-maxsize - not sure why a new file gets created on an unrelated transport when adding a new Transport * Update 01-file-maxsize.test.js * Update file.js
|
So, I'm using Winston 3.10.0 and Winston-daily-rotate-file 4.7.1 and have run into an issue very similar to this. My app has 5 asynchronous tasks to perform at startup and just as it's getting going, the logs stop abruptly. Console is not affected, but in production I don't keep console running. I had hoped that the daily rotate would trigger a reset and the logs would start being written, but this didn't happen. It's technically intermittent but only because it doesn't happen sometimes. I'm revving to Winston 3.11.0. Does anyone have any ideas how to debug this? If I turn off |
I'm trying to use transports.File to save log file in loop with logger. After several logs print out it stops to write log to file and print nothing in console without any error message.
Here is my test code:
Is it stdout buffer issue?
I'm using version 3.0.0-rc1 with node:8-alpine image in docker container
The text was updated successfully, but these errors were encountered: