HBASE-24686 [LOG] Log improvement in Connection#close #2219
Conversation
|
🎊 +1 overall
This message was automatically generated. |
|
🎊 +1 overall
This message was automatically generated. |
|
🎊 +1 overall
This message was automatically generated. |
|
@busbey please have a look. |
| @@ -199,6 +199,10 @@ public void close() { | |||
| if (!closed.compareAndSet(false, true)) { | |||
| return; | |||
| } | |||
| LOG.info("Connection has been closed by {}.", Thread.currentThread().getName()); | |||
There was a problem hiding this comment.
I think this should also be at debug level.
There was a problem hiding this comment.
It is helpful to identify who closed the connection improperly in production env.
Level debug is inconvenient since we have to re-run the user application to reproduce it. Meanwhile, it should not be called frequently.
Maybe I did not get your concern.
There was a problem hiding this comment.
I'd also like to keep this at INFO. Connection objects are supposed to be long lived so we should see this message rarely. Ideally once per cluster per JVM.
There was a problem hiding this comment.
I didn't mean to correlate with no of occurrences of this log, I meant to say user who is interested to know which thread closed the connection would also likely want to check out call stacktrace. So if call stack is at debug level, let's also keep thread name at debug level.
But yeah, not everyone enables debug log for production use-case and hence, maybe we should keep both at info level? Stacktrace is also equally interesting right?
There was a problem hiding this comment.
Sorry for lack of clarification in previous comment. Also, changes look good, just that once we have both at info level, we should be good to go ahead.
There was a problem hiding this comment.
Oh wait, how about first we gather stack trace and then log both threadname and stacktrace together in same log?
There was a problem hiding this comment.
I think the stacktrace is an option if the thread name is helpless. It's almost enough with meaningful name. I'm also worried log stack at info level is confusing since the format is like an exception.
There was a problem hiding this comment.
I'm also worried log stack at info level is confusing since the format is like an exception.
Even though it is Exception, but we do want to log which Exception caused Connection closure (once in a while) right? If so, then keeping threadname at info level and stacktrace at debug somehow doesn't fit well IMHO.
If we know for certain that threadname is useful to get sufficient info, then we should not log stacktrace at all, and if stacktrace is required for debugging, then it should be at the same level as threadname.
Level debug is inconvenient since we have to re-run the user application to reproduce it.
This is exactly applicable to stacktrace also. If application is running with info level and if threadname is not sufficient to know the cause, then we can't get stacktrace either because our application was running with info level at that time and stacktrace is present at debug level in code. ¯\_(ツ)_/¯
There was a problem hiding this comment.
For background, I left a longer comment awhile ago on HBASE-24686 where I asked for some indication of the close at info and the stack trace at debug.
we already have other things that get logged at INFO when a connection is closing, but it's incidental and could happen in other ways. so an INFO message that clearly demarcates connection close is a thing I really want from this change. Enough so that I am sure I'll be back requesting it again the very next time I run into a production problem where I don't see the message, because almost no one I support runs DEBUG in production as a matter of course. Most of the times where this log message would have helped me in the last ~6 months the thread name and an unambiguous "we closed the connection" would suffice.
the stack trace would help with a specific problem we hit in a dev set up with an apparent bug in the hmaster. It did not happen often but it did happen regularly, so changing the log level to DEBUG to see a stack trace would have worked fine for us.
If you feel strongly about not having the messages at different log levels, @virajjasani, I'd rather see both at INFO then both at DEBUG, even though I generally am against non-error related stack traces at log levels above DEBUG.
There was a problem hiding this comment.
Most of the times where this log message would have helped me in the last ~6 months the thread name and an unambiguous "we closed the connection" would suffice.
That's perfectly fine, if thread name is enough for prod env and if we have a way to repro in dev env, we can let stacktrace be at debug. The only thing I was concerned about was whether not finding stacktrace in prod env would still keep things unclear for user. However, here I believe once we get the thread name, we can find recent logs of that thread to find more.
I generally am against non-error related stack traces at log levels above DEBUG.
+1 for this unless the non-error trace is useful for detailed debugging, in which case maybe we can write something specifically to indicate to not treat this as erroneous condition.
However, for our current PR, it seems thread-name is most likely going to provide sufficient info.
|
@busbey @pankaj72981 @virajjasani Thanks for the reviews. Who can help to merge this PR if there is no more comment? |
|
@busbey just to confirm, you have +1 for this PR right? (I mean no other concerns than DEBUG and INFO level discussions) |
Signed-off-by: Pankaj Kumar <pankajkumar@apache.org> Signed-off-by: Viraj Jasani <vjasani@apache.org> Signed-off-by: Sean Busbey <busbey@apache.org>
Signed-off-by: Pankaj Kumar <pankajkumar@apache.org> Signed-off-by: Viraj Jasani <vjasani@apache.org> Signed-off-by: Sean Busbey <busbey@apache.org>
Signed-off-by: Pankaj Kumar <pankajkumar@apache.org> Signed-off-by: Viraj Jasani <vjasani@apache.org> Signed-off-by: Sean Busbey <busbey@apache.org>
Signed-off-by: Pankaj Kumar <pankajkumar@apache.org> Signed-off-by: Viraj Jasani <vjasani@apache.org> Signed-off-by: Sean Busbey <busbey@apache.org>
Signed-off-by: Pankaj Kumar <pankajkumar@apache.org> Signed-off-by: Viraj Jasani <vjasani@apache.org> Signed-off-by: Sean Busbey <busbey@apache.org> (cherry picked from commit 31fb9fc) Change-Id: I04f188d582df7c32ad62115beecbb140d3f5b395
No description provided.