On 07/01/2015 12:48 PM, Jakub Hrozek wrote:
On Wed, Jul 01, 2015 at 12:03:48PM +0200, Pavel Březina wrote:
On 06/29/2015 06:13 PM, Jakub Hrozek wrote:
Hi,
I spent many hours debugging SSSD in different scenarios last week and I
admit it wasn't always easy -- and I have the source code knowledge I
can use. I imagine it's considerably harder for users and admins..
So this is a brainstorm request on how can we make debugging with SSSD
easier. Maybe there are some low-hanging fruits that can be fixed
easily. Off the top of my head:
- it should be easier to see start and end of a request in the back end.
Instead of:
[be_get_account_info] (0x0200): Got request for [0x1001][1][name=admin]
[acctinfo_callback] (0x0100): Request processed. Returned 0,0,Success
(Success)
We could make the debug messages more explicit:
[be_get_account_info] (0x0200): Received request for
[object=user][key=name][value=admin]
[acctinfo_callback] (0x0200): Finished request for
[object=user][key=name][value=admin]. Returned 0,0,Success
Then we could document the messages in our troubleshooting document.
Please note I'm not proposing to turn debug messages into any kind of
API and keep them the same forever, but decorate the usual flow with
messages that make sense without source level knowledge.
- same for authentication
- same for responder cache requests. We seem to have gotten better with
the new cache_req code there, so this is mostly about using the new
code in all responders. But also the commands we receive from sockets
should be printed in human-readable form.
- Running sssd in environment where all actions complete successfully
should emit no debug messages. Default log level should be moved to
SSSDBG_OP_FAILURE or CRIT_FAILURE. (This basically amounts to checking
all OP, FATAL and CRIT failure messages..)
The reason is that sometimes sssd fails, but because logging is
totally silent, we don't know what happened at all. Currently we have
a couple of small bugs where we might print a loud DEBUG message just
because we search for an entry which is not there etc.
- anything that causes SSSD to fail to start should also emit a syslog
message. Admins don't really know about sssd debug logs.
- our man pages are not structured well, especially the LDAP man page is
too big and contains too many options.
One reason I'm bringing this up now is that we'll have a new SSSD developer
starting soon and these might be nice tasks to start with AND they're
also needed.
+1
I think the best way to start is to look at the existing debug messages and
take advantage of the bit-mask based log levels - it's been there for a
while and there is lots of space to increase its granularity but we still
use it as 1-9 levels. That beeing said, we should create more levels so we
can really distinguish between important trace parts (event start, event
end), information (object not found but this was expected), low level stuff
(ldb traces that brings lots of noice to the highest level), etc.
The ldb traces are a really good point.
OK, I like the suggestion with newer debug levels, but we should be
careful with not adding too many.
Yes, of course, the levels needs to be thought trough. In my opinion,
that requires deep analysis of existing debug messages to see how the
types can be grouped together. I can't do it from the top of my head
even though I have some ideas.
Having a larger granularity can be also a benefit while investigating
logs not just when obtaining them because we will be able to highlight
interesting parts (e.g. failover related messages when dealing with
server resolution).
Now, I'm just thinking loud because this would be much bigger scope than
what would like you to see. Maybe, we should rethink this completely
from the beginning. What I'd like to see in logs:
a) trace so we know where we are and what is happening
b) see all errors
c) get rid of too low level noise, unless it is a special case
a) and b) is something you always want to see, so there is actually no
point to create a level for that. It may beneficial to create a two-part
system (category: failover, ldap, request, ...; priority: warning,
error, information, trace, ...).
The other thing to be careful about is that admins are used to just set:
debug_level=10
Adding new debug levels to make life easier for admins but then not
enabling them if admins set what they're used to is also a bit
contradictory :0
The new levels are there for four years, or how long I am with the
project. It was the first thing I have developed. So it may be a time to
start enforcing it.
Now, I'd like to be honest but I don't mean to insult anyone. If an
administrator is able to actually read something from the logs, he will
be able to use other level format. The others just set whatever we tell
them anyway.
_______________________________________________
sssd-devel mailing list
sssd-devel@lists.fedorahosted.org
https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
