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.