Hello Ceki, Thank you for the suggestion. We added the debug="true" option and Logback gave us a clue about the problem: ERROR in ch.qos.logback.core.rolling.RollingFileAppender[DS_QUERY_PROFILE_FILE] - openFile(sD:/logs/query_profile_dataservice.log,true) call failed. java.io.FileNotFoundException: sD:\logs\query_profile_dataservice.log (The filename, directory name, or volume label syntax is incorrect) Apparently, when somebody modified the logging configuration, they added a redundant 's' at the beginning of the log file path. This caused Logback to fall back to letting that appender use the log file used by another appender. In the end, two different appenders started using the same log file (by using Process Explorer, we also saw that the same JVM was holding *two* handles to file D:\logs\product.log), and eventually, when Logback tried to roll over the log files, the problems started. We could see the following in the logs: Failed to rename file [D:\logs\product.log] to [D:\logs\product_0.log]. Normally, only one file handle to file D:\logs\product.log is used. When I added a similar 's' in a test environment, I got two file handles too, and eventually Logback became super-slow. We asked the customer to remove the redundant 's' and to restart the product and then to wait until the next roll-over and to tell us if things were okay. I just received the following feedback from our support people: "Customer has been running with new serviceability.xml file since last change. So far, it appears the files are rolling over and there is no longer any slowness once the file reaches 50mb. We'll continue to monitor thru next week, but it appears the issue may have been resolved by fixing the file." It will be great if Logback gets fixed, so that: 1. Two appenders should never write to the same file, or if they do, then the code should be fixed in such a way that this causes no problems 2. Logback should not become so slow. Perhaps some non-(b)locking algorithm should be used, if possible. Thank you for your help! ---------------------------------------------------------------------- Hello Vesuvius, Enabling logback's internal status messages [1] is an investigative step of *first* resort. I would start there. Any computing system can be brought to its knees if sufficiently stressed. From what I could gather from your previous messages, the application in question generates massive amounts of logs. If so, my suggestion would be to reduce logging output by setting the root logger level to WARN for example. As a side note, I would suggest using SizeAndTimeBasedRollingPolicy [2] which provides a much nicer archiving policy than the FixedWindowRollingPolicy+SizeBasedTriggeringPolicy combination. -- Ceki [1] http://logback.qos.ch/manual/configuration.html#automaticStatusPrinting [2] http://logback.qos.ch/manual/appenders.html#SizeAndTimeBasedRollingPolicy On 5/11/2016 12:02, Vesuvius Prime wrote:
Hi,
Thank you for the suggestion. This was the first thing I had suggested to the customer during the live session with them but then they said they didn't want to be a "testbed" for us, so they didn't do it. Now I asked our support guys to ask the customer again to do this and this time the customer agreed. After waiting a while for the logs to roll over, here's the feedback:
"Hello, Customer just provided an update. Log file is not rolling over, however it has grown to over 90mb, but the [product] has not slowed down."
So, there's an improvement -- at least now we're not becoming unusable due to excessive slowness. However, the log grows without a limit. The bottom line is that this is an improvement, but not a solution.
I would still love somebody with deep knowledge of Logback (presumably its authors) to provide some feedback here. For example, if this is a known problem and it has been solved in some version of Logback, we may go ahead an modify the Virgo server to use that version. Alternatively, if Logback is unreliable, we may have to switch to some other logging framework. I've been seeing various reports about rollover problems, even in this mail list. We can't afford to lose customers due to logging. Besides, this creates a really bad image to Logback itself.
Thank you for reading this.
------------------------------ Message: 2 Date: Thu, 12 May 2016 08:25:56 +0100 From: David Roussel <nabble@diroussel.xsmail.com> To: logback users list <logback-user@qos.ch> Subject: Re: [logback-user] Change FixedWindowRollingPolicy rolling behaviour Message-ID: <1B78DD98-75AA-43AB-BEA5-D291673026C2@diroussel.xsmail.com> Content-Type: text/plain; charset=us-ascii Hi DK, It's not clear what you are asking for. Currently the files are renamed in reverse order so that there is no name clash. What other strategy are you suggesting? David
On 27 Apr 2016, at 15:05, DK <desmond.kirrane@gmail.com> wrote:
Hi can I change FixedWindowRollingPolicy to rollover as follows:
foo.log active log file foo1.log first rollover foo2.log second rollover foo3.log third rollover
Current behaviour is second rollover. foo1.log is renamed as foo2.log. foo.log is renamed as foo1.log
-- View this message in context: http://logback.10977.n7.nabble.com/Change-FixedWindowRollingPolicy-rolling-b... Sent from the Users mailing list archive at Nabble.com. _______________________________________________ logback-user mailing list logback-user@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-user
------------------------------ Subject: Digest Footer _______________________________________________ logback-user mailing list logback-user@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-user ------------------------------ End of logback-user Digest, Vol 56, Issue 4 *******************************************