[logback-dev] Question: AsyncAppender's thread safety?

[Aaron Curley]

Hi Ceki,

Thanks for your responses.  Absolutely; I'll create a JIRA shortly.

As to your question about a test case, I'll see if I can get something 
working over the next 1-2 days.  Unfortunately, even if I am successful, 
the test case is likely to only sometimes detect this particular problem 
(since threads are generally not deterministic).

The performance questions (i.e. the costs of volatile) are a bit harder 
to answer and I'm not sure I'm presently equipped to execute the 
necessary performance testing.  I'll give this more thought.

Aaron



On 3/3/2016 3:13 AM, Ceki Gulcu wrote:
>
> Hi again,
>
> Would you please create a JIRA issue for the problem you raised on the 
> mailing list?
>
> -- 
> Ceki
>
> On 3/3/2016 9:16, Ceki Gulcu wrote:
>> Hi Aaron,
>>
>> Comments inline.
>>
>> On 3/2/2016 23:40, Aaron Curley wrote:
>>
>>  > Hello all,
>>  >
>>  > I’m most likely missing something here, but reviewing 
>> AsyncAppender in
>>  > logback classic 1.1.6, I’m not sure how it’s entirely thread safe,
>>  > especially with respect to the “started” flag in its grandparent
>>  > class (UnsynchronizedAppenderBase).
>>  >
>>  > In particular, the doAppend() method in UnsynchronizedAppenderBase
>>  > checks the “started” boolean member's value (line 72) before
>>  > actually appending, yet, no synchronization primitives are (or appear
>>  > to be, from my perspective) used to ensure that the “started”
>>  > member is visible to all threads once it is updated via start().  I
>>  > would have thought that AsyncAppender would have inherited from
>>  > AppenderBase (which is thread safe and does mark “started” as
>>  > volatile) rather than extending UnsynchronizedAppenderBase.  Baring
>>  > this, I would have thought that the “started” member would be
>>  > “overridden” with AsyncAppender’s own volatile version of this
>>  > flag or access to started would be protected with a lock.
>>  >
>>  > As a result, isn’t it possible that if one thread calls start() and
>>  > then another thread immediately logs something (calling doAppend()),
>>  > the logging thread would see “started” as false?  Wouldn’t this
>>  > result in “skipping” certain log messages entirely (if the
>>  > appender was very recently started)?
>>
>> You are absolutely right. Events generated in other threads could be
>> lost until the new value (true) of start was propagated to those
>> threads. Good catch.
>>
>>  > I think I must be missing something.  Can someone clarify how this
>>  > works?  Thanks in advance!
>>  >
>>  > Best Regards,
>>  >
>>  > Aaron Curley
>>  > accwebs at gmail.com
>>  >
>>  > P. S.  I would have also expected start() and stop() (in
>>  > AsyncAppender or its parent) to be overridden to introduce
>>  > synchronization, since AsyncAppender is generally used by multiple
>>  > threads.  Right now, it appears that start & stop operations are not
>>  > idempotent nor are multiple (simultaneous) calls prevented.
>>
>> The idempotency could be enforced by introducing a check if(isStarted())
>> {return;} at the top of the start() method. But again, good catch.
>>
>> Here are a couple of questions for you.
>>
>> 1) How would you write a test case for asserting the correct propagation
>> of start?
>> 2) What would be the computational cost of having a volatile start?
>> 3) What would you suggest to minimize the cost if the cost was elevated?
>>
>> Best regards,
>>
>> -- 
>> Ceki
>>
>> _______________________________________________
>> logback-dev mailing list
>> logback-dev at qos.ch
>> http://mailman.qos.ch/mailman/listinfo/logback-dev
> _______________________________________________
> logback-dev mailing list
> logback-dev at qos.ch
> http://mailman.qos.ch/mailman/listinfo/logback-dev