Review request 8153912: StackFrame::getFileName and StackFrame::getLineNumber not needed

[Daniel Fuchs]

Hi Ralph,

On 11/05/16 21:00, Ralph Goers wrote:
> I am not at all familiar with how the stack is actually managed. I was hoping it was just an array and that the index into it was being kept track of. Since we know that we will only be adding more stack elements I would think that deferring use of that index wouldn’t be a problem. But since I have no idea how it is managed all I can really do is guess and hope.
>
> As far as the appender calling a logger, it happens all the time.
> Log4j 1 had serious problems with it and could get itself in a deadlock.
> In Log4j 2 we handle that by wrapping each appender with an
> AppenderControl.The AppenderControl has a thread local guard. If the guard
> is set then  the appenderControl just ignores the event.
> But if logging for the stuff going on inside of an appender is routed
> to a different appender there is no problem. So recursion is not a problem.
> Without this most of the interesting things users do with Log4j wouldn’t
> be possible or at least would be hard to debug.
>  I have to believe that jul will have the same problem with custom handlers
> written by users.

Yes JUL would have exactly the same kind of problem.
However putting guards in place can be costly so I believe it's best
to leave that to the concrete Handler implementation - where you
best know whether such guards will be needed or not,
(in that case - to the custom handler).

Concerning your scenario - then if I understand correctly there are
two cases:

Foo::method1—>Logger.log("foo1")—>BarAppender.append—>Foo::method2 (or 
even method1 again)—>Logger.log("foo2")->XAppender.append->Foo::method3...

case #1: XAppender == BarAppender
case #2: XAppender != BarAppender

in case #1, for Logger.log("foo2"), the guards should prevent prevent
recursion and hopefully this will happen before trying to get the caller
information.

in case #2, for Logger.log("foo2"), then I believe you would want the
caller identified as Foo::method2 - not as Foo::method1.
Identifying the caller as Foo::method1 would IMHO be very confusing,
as you wouldn't be able to find any trace of the log message
"foo2" in the code of that method.

so it seems to me that even in this case, starting at frame 0 and
stopping at frame Foo::method2 would be a better strategy than
starting at frame N and stopping at frame Foo::method1?

But maybe I misunderstood.

Best regards,

-- daniel

>
> Ralph
>
>> On May 11, 2016, at 10:20 AM, Daniel Fuchs <daniel.fuchs at oracle.com> wrote:
>>
>> Hi,
>>
>> On 11/05/16 18:57, Ralph Goers wrote:
>>> But my point is that if obtaining the StackFrame and Class
>>> could be done so quickly that it wouldn’t add any noticeable
>>> overhead we could do that in every Logger.info, debug, etc. call.
>>> If we could just get the stack frame index so that we could obtain
>>> the StackFrame and Class later by using the index that would be even
>>> better since we would only be creating the StackFrame, etc if it is really required.
>>
>> Working with stack frame indexes is at best fragile, unless
>> you make a snapshot of the stack first and only used the
>> index in relation to that snapshot. So I wouldn't recommend
>> going that way. Furthermore to obtain such an index you
>> would need to count the frames - which would mean walking the
>> whole stack.
>>
>> I'm still not sure I understand why an appender would
>> call Logger.log. That sounds like a recipe for stack
>> overflow or endless ping pong loops.
>> I understand that could theoretically happen but then the
>> appender would need to protect itself against 'logging
>> while logging'. Or am I misunderstanding?
>>
>> best regards,
>>
>> -- daniel
>>
>
>