Rolling File Operation : Failing with Source does not exist

classic Classic list List threaded Threaded
12 messages Options
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Rolling File Operation : Failing with Source does not exist

Kinnar
Hi All,

We are using log4net in our multi threaded windows service since last 3 years or so.  We have recently encountered that our device became unresponsive/went into hanging state couple of time. While analyzing crash dump of the service of that time, we have encountered that one of our thread has failed during rolling file operation. The stack trace of failed thread as follows :
  log4net.Util.LogLog.EmitErrorLine(System.String)
  log4net.Util.LogLog.Warn(System.Type, System.String)
  log4net.Appender.RollingFileAppender.RollFile(System.String, System.String)
  log4net.Appender.RollingFileAppender.RollOverTime(Boolean)
  log4net.Appender.RollingFileAppender.AdjustFileBeforeAppend()
  log4net.Appender.RollingFileAppender.Append(log4net.Core.LoggingEvent)
  log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent)
  ....
  ....

While going through error thrown by above stack trace, we have encountered following error message :
  log4net:WARN Cannot RollFile [....] -> [....]. Source does not exist

All other threads are waiting at following log4net method :
  log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent)
  log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent)
  ....
  ....

Rolling File Pattern is as following :
    <datePattern value=".yyyyMMdd-HH&quot;.log&quot;"/>

We are not able to understand what is exactly wrong over here which causes service to become unresponsive. Does rolling file operation cause the thread, which is using it, to go into unresponsive state if some error occurs ? We have gone through other posts which are telling to use different datepattern but changing datepattern is not solving problem for everybody. We would like to know what is the full proof way to solve this issue.

Thanks.
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Rolling File Operation : Failing with Source does not exist

Dominik Psenner
Hi,

which exact log4net version did cause this issue? log4net older than
"last 3 years or so" leaves huge room for guessing. :-)

Cheers

On 2016-03-14 13:01, Kinnar wrote:

> Hi All,
>
> We are using log4net in our multi threaded windows service since last 3
> years or so.  We have recently encountered that our device became
> unresponsive/went into hanging state couple of time. While analyzing crash
> dump of the service of that time, we have encountered that one of our thread
> has failed during rolling file operation. The stack trace of failed thread
> as follows :
>    log4net.Util.LogLog.EmitErrorLine(System.String)
>    log4net.Util.LogLog.Warn(System.Type, System.String)
>    log4net.Appender.RollingFileAppender.RollFile(System.String,
> System.String)
>    log4net.Appender.RollingFileAppender.RollOverTime(Boolean)
>    log4net.Appender.RollingFileAppender.AdjustFileBeforeAppend()
>    log4net.Appender.RollingFileAppender.Append(log4net.Core.LoggingEvent)
>    log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent)
>    ....
>    ....
>
> While going through error thrown by above stack trace, we have encountered
> following error message :
>    log4net:WARN Cannot RollFile [....] -> [....]. Source does not exist
>
> All other threads are waiting at following log4net method :
>    log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent)
>  
> log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent)
>    ....
>    ....
>
> Rolling File Pattern is as following :
>      <datePattern value=".yyyyMMdd-HH&quot;.log&quot;"/>
>
> We are not able to understand what is exactly wrong over here which causes
> service to become unresponsive. Does rolling file operation cause the
> thread, which is using it, to go into unresponsive state if some error
> occurs ? We have gone through other posts which are telling to use different
> datepattern but changing datepattern is not solving problem for everybody.
> We would like to know what is the full proof way to solve this issue.
>
> Thanks.
>
>
>
> --
> View this message in context: http://apache-logging.6191.n7.nabble.com/Rolling-File-Operation-Failing-with-Source-does-not-exist-tp62802.html
> Sent from the Log4net - Users mailing list archive at Nabble.com.

Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Rolling File Operation : Failing with Source does not exist

Kinnar
Hi Dominik,

Thanks for your feedback.

We are using 1.2.13.0 version of log4net.

We just like to have your view on whether the problem which we are facing can get the service into unresponsive state ? If yes, then changing date pattern won't help as it is still not solving problem as per other posts in same forum.

Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Rolling File Operation : Failing with Source does not exist

Dominik Psenner
Hi Kinnar,

The logging framework should never stop the show and such reports are treated as serious bugs. Would you please share more information about your log4net configuration?

Cheers

2016-03-15 14:39 GMT+01:00 Kinnar <[hidden email]>:
Hi Dominik,

Thanks for your feedback.

We are using 1.2.13.0 version of log4net.

We just like to have your view on whether the problem which we are facing
can get the service into unresponsive state ? If yes, then changing date
pattern won't help as it is still not solving problem as per other posts in
same forum.





--
View this message in context: http://apache-logging.6191.n7.nabble.com/Rolling-File-Operation-Failing-with-Source-does-not-exist-tp62802p62843.html
Sent from the Log4net - Users mailing list archive at Nabble.com.



--
Dominik Psenner
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Rolling File Operation : Failing with Source does not exist

Kinnar
Hi Dominik,

Please find appender configuration for which we are facing the problem as below :

 <appender name="MessageAppender" type="log4net.Appender.RollingFileAppender">
      <threshold value="INFO"/>
      <file value="${SystemDrive}\[some folder name]\[file name].txt"/>
      <appendToFile value="true"/>
      <maximumFileSize value="500MB"/>
      <staticLogFileName value="true"/>
      <maxSizeRollBackups value="10"/>
      <datePattern value="_yyyyMMdd-HH&quot;.txt&quot;"/>
      <rollingStyle value="Composite"/>
      <preserveLogFileNameExtension value="true"/>
      <layout type="log4net.Layout.PatternLayout">
       
      </layout>
      <dateTimeStrategy type="log4net.Appender.RollingFileAppender+UniversalDateTime" />
    </appender>

Thanks in advance.

Kinnar
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Rolling File Operation : Failing with Source does not exist

Dominik Psenner
Hi again,

based on the information that you have multiple processes running, I think that two processes decided to roll files at the same time. This probably has caused a race condition and that again caused the show to stop.

The good news is that this scenario has been adressed in the latest log4net release (1.2.15) and for you this means that you could try to update log4net and see if the issue does no longer occur. Let us know what you try and what the outcome was.

Cheers,
Dominik

2016-03-17 6:12 GMT+01:00 Kinnar <[hidden email]>:
Hi Dominik,

Please find appender configuration for which we are facing the problem as
below :

 <appender name="MessageAppender"
type="log4net.Appender.RollingFileAppender">
      <threshold value="INFO"/>
      <file value="${SystemDrive}\[some folder name]\[file name].txt"/>
      <appendToFile value="true"/>
      <maximumFileSize value="500MB"/>
      <staticLogFileName value="true"/>
      <maxSizeRollBackups value="10"/>
      <datePattern value="_yyyyMMdd-HH&quot;.txt&quot;"/>
      <rollingStyle value="Composite"/>
      <preserveLogFileNameExtension value="true"/>
      <layout type="log4net.Layout.PatternLayout">

      </layout>
      <dateTimeStrategy
type="log4net.Appender.RollingFileAppender+UniversalDateTime" />
    </appender>

Thanks in advance.

Kinnar



--
View this message in context: http://apache-logging.6191.n7.nabble.com/Rolling-File-Operation-Failing-with-Source-does-not-exist-tp62802p62877.html
Sent from the Log4net - Users mailing list archive at Nabble.com.



--
Dominik Psenner
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Rolling File Operation : Failing with Source does not exist

Kinnar
Hi Dominik,

Thanks for your updates. We will try out and let you know. Thanks for your directions.

Regards,
Kinnar
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Rolling File Operation : Failing with Source does not exist

Dominik Psenner
You're welcome!

Happy hacking,
Cheers

On 2016-03-18 09:14, Kinnar wrote:

> Hi Dominik,
>
> Thanks for your updates. We will try out and let you know. Thanks for your
> directions.
>
> Regards,
> Kinnar
>
>
>
>
> --
> View this message in context: http://apache-logging.6191.n7.nabble.com/Rolling-File-Operation-Failing-with-Source-does-not-exist-tp62802p62906.html
> Sent from the Log4net - Users mailing list archive at Nabble.com.

Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Rolling File Operation : Failing with Source does not exist

Kinnar
Hi Dominink,

We think that the setting the "preserveLogFileNameExtension" configuration to True may be leading the log4net to race condition while performing rolling file operation and the error/exception mentioned in this thread may be occurring. We have added "preserveLogFileNameExtension" configuration into our service later point of time.

We would like to know your view whether setting "preserveLogFileNameExtension" configuration to True may lead log4net to race condition.

Thanks in advance,
Kinnar
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Rolling File Operation : Failing with Source does not exist

Dominik Psenner
Hi Kinnar,

I'll look at it as soon as possible.

Cheers,
Dominik

On 2016-04-06 15:47, Kinnar wrote:

> Hi Dominink,
>
> We think that the setting the "preserveLogFileNameExtension" configuration
> to True may be leading the log4net to race condition while performing
> rolling file operation and the error/exception mentioned in this thread may
> be occurring. We have added "preserveLogFileNameExtension" configuration
> into our service later point of time.
>
> We would like to know your view whether setting
> "preserveLogFileNameExtension" configuration to True may lead log4net to
> race condition.
>
> Thanks in advance,
> Kinnar
>
>
>
> --
> View this message in context: http://apache-logging.6191.n7.nabble.com/Rolling-File-Operation-Failing-with-Source-does-not-exist-tp62802p63481.html
> Sent from the Log4net - Users mailing list archive at Nabble.com.

Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Rolling File Operation : Failing with Source does not exist

Kinnar
Hi Dominink,

We had asked this query originally with regards to race condition observed in multi threaded windows service and you had provided solution to it as follows :

"
Hi again,

based on the information that you have multiple processes running, I think that two processes decided to roll files at the same time. This probably has caused a race condition and that again caused the show to stop.

The good news is that this scenario has been adressed in the latest log4net release (1.2.15) and for you this means that you could try to update log4net and see if the issue does no longer occur. Let us know what you try and what the outcome was.

Cheers,
Dominik
"

As per your response above, the solution which you had suggested will going to work only when there is a  race condition among multiple processes and not among multiple threads of the same process ? Please confirm.

With addition to above confirmation, we are still looking for your reply on following :

"whether setting "preserveLogFileNameExtension" configuration to True may lead log4net to race condition. "

Let us know your feedback on this as soon as possible as we want to decide our further direction depending on this.

Regards,
Kinnar
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Rolling File Operation : Failing with Source does not exist

Dominik Psenner
Hi!

Apologies, I've completely lost track of your question.

The preserveLogFileNameExtension := true should not cause any race
condition, because the mutex lock introduced in 1.2.15 completely
surrounds the method RollingFileAppender.AdjustFileBeforeAppend().
Further, given that it is a Mutex, it synchronizes both Threads and
Processes that run on the same operating system. However, I've no idea
whether preserveLogFileNameExtension := True breaks the detection of
existing rolled files and maybe that is the actual source of your issue.

Please note that Stefan Bodewig and I agree that the existing
RollingFileAppender implementation is broken in too many ways to fix it.
Patching it further could finally break the few things it does well and
therefore we avoid to patch it any further. We have plans to rewrite the
RollingFileAppender from scratch [1] and the work I've done so far dates
back to the late 2011 [2]. This is the thing we would like to tackle as
soon as possible. The problem is that we lack the manpower to complete
the job anytime soon. If you or your team would like to pick up the work
and finish it, we would gladly assist you with all that we can do.

Cheers,
Dominik

[1] https://issues.apache.org/jira/browse/LOG4NET-367
[2]
https://bitbucket.org/NachbarsLumpi/log4net-patches/src/1250c817e2620c89789b70fd2fb29f9334dc77b1/RFA-NG?at=default&fileviewer=file-view-default

On 2017-03-08 14:43, Kinnar wrote:

> Hi Dominink,
>
> We had asked this query originally with regards to race condition observed
> in multi threaded windows service and you had provided solution to it as
> follows :
>
> "
> Hi again,
>
> based on the information that you have multiple processes running, I think
> that two processes decided to roll files at the same time. This probably has
> caused a race condition and that again caused the show to stop.
>
> The good news is that this scenario has been adressed in the latest log4net
> release (1.2.15) and for you this means that you could try to update log4net
> and see if the issue does no longer occur. Let us know what you try and what
> the outcome was.
>
> Cheers,
> Dominik
> "
>
> As per your response above, the solution which you had suggested will going
> to work only when there is a  race condition among multiple processes and
> not among multiple threads of the same process ? Please confirm.
>
> With addition to above confirmation, we are still looking for your reply on
> following :
>
> "whether setting "preserveLogFileNameExtension" configuration to True may
> lead log4net to race condition. "
>
> Let us know your feedback on this as soon as possible as we want to decide
> our further direction depending on this.
>
> Regards,
> Kinnar
>
>
>
>
> --
> View this message in context: http://apache-logging.6191.n7.nabble.com/Rolling-File-Operation-Failing-with-Source-does-not-exist-tp62802p74840.html
> Sent from the Log4net - Users mailing list archive at Nabble.com.

Loading...