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.
On Mon, 2015-06-29 at 18:13 +0200, 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
Simo.
I've been watching various logs for the past few minutes, FWIW, I think a more casual message will help people better understand what SSSD is doing. Look at debug level 4, the first instance of a user name look up (getent passwd dlavu) a common command we tell folks to test to see if SSSD is working
(Mon Jun 29 22:10:59 2015) [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (0x0200): Got request for [0x1001][1][name=dlavu]
Just imagine if you knew nothing about SSSD and how it worked, what can you gather from this line of text? Timestamp, process, domain, get_account_info, got_request and userid and the rest is sort of gibberish and what is the difference between be_get_account_info and got_request_for? I think it's confusing, now looking at some other logs messages.
Jun 29 21:50:37 freeipa named-pkcs11[2101]: validating @0x7f1a1c60cfc0: fedorahosted.org NSEC: no valid signature found
Jun 29 22:04:15 freeipa puppet-agent[2661]: The package type's allow_virtual parameter will be changing its default value from false to true in a future release. If you do not want to allow virtual packages, please explicitly set allow_virtual to false.
[28/Jun/2015:15:45:27 -0400] NSMMReplicationPlugin - agmt="cn=meTofreebeer.lab.runlevelone.lan" (freebeer:389): Replication bind with GSSAPI auth failed: LDAP error -2 (Local error) (SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure. Minor code may provide more information (Cannot contact any KDC for realm 'LAB.RUNLEVELONE.LAN'))
The following messages are pretty clear in what they are doing and what the issue is, also some logs have a structure to help readability (not sure if it was intentional or not) but it would be a few short messages, then the long message, something to break it up. I'm not saying we remove any of the logs, but maybe insert more layman descriptions that way people can use them as markers. So they can find the relevant event and look after that message.
Maybe we format those as a standard syslog message (timestamp,loghost,application,level,message_id,message) and enable it by default? It might help administrators catch errors early and might help because its a little more familiar, I don't think we should roll with systemd just yet. ;)
Also I'll take a look at the ldap man page and see if I can do anything to make it easier to follow.
Dan
----- Original Message -----
From: "Simo Sorce" simo@redhat.com To: "Development of the System Security Services Daemon" sssd-devel@lists.fedorahosted.org Cc: "George Agriogiannis" gagriogi@redhat.com, "Dan Lavu" dlavu@redhat.com Sent: Monday, June 29, 2015 5:53:45 PM Subject: Re: [SSSD] RFC: Improving the debug messages
On Mon, 2015-06-29 at 18:13 +0200, 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
Simo.
-- Simo Sorce * Red Hat, Inc * New York
sssd-devel mailing list sssd-devel@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
On Mon, Jun 29, 2015 at 11:07:30PM -0400, Dan Lavu wrote:
I've been watching various logs for the past few minutes, FWIW, I think a more casual message will help people better understand what SSSD is doing. Look at debug level 4, the first instance of a user name look up (getent passwd dlavu) a common command we tell folks to test to see if SSSD is working
(Mon Jun 29 22:10:59 2015) [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (0x0200): Got request for [0x1001][1][name=dlavu]
Just imagine if you knew nothing about SSSD and how it worked, what can you gather from this line of text? Timestamp, process, domain, get_account_info, got_request and userid and the rest is sort of gibberish and what is the difference between be_get_account_info and got_request_for? I think it's confusing, now looking at some other logs messages.
What is missing in the list of components above is '(0x0200)' which is the debug_level. We recently had a number of questions about messages from a high debug level which in general have an information character, but since it not easy to identify the level of the message it was considered as an error message. Maybe it would be good to have a some translations here as well to make it easier to separate errors from infos.
bye, Sumit
Jun 29 21:50:37 freeipa named-pkcs11[2101]: validating @0x7f1a1c60cfc0: fedorahosted.org NSEC: no valid signature found
Jun 29 22:04:15 freeipa puppet-agent[2661]: The package type's allow_virtual parameter will be changing its default value from false to true in a future release. If you do not want to allow virtual packages, please explicitly set allow_virtual to false.
[28/Jun/2015:15:45:27 -0400] NSMMReplicationPlugin - agmt="cn=meTofreebeer.lab.runlevelone.lan" (freebeer:389): Replication bind with GSSAPI auth failed: LDAP error -2 (Local error) (SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure. Minor code may provide more information (Cannot contact any KDC for realm 'LAB.RUNLEVELONE.LAN'))
The following messages are pretty clear in what they are doing and what the issue is, also some logs have a structure to help readability (not sure if it was intentional or not) but it would be a few short messages, then the long message, something to break it up. I'm not saying we remove any of the logs, but maybe insert more layman descriptions that way people can use them as markers. So they can find the relevant event and look after that message.
Maybe we format those as a standard syslog message (timestamp,loghost,application,level,message_id,message) and enable it by default? It might help administrators catch errors early and might help because its a little more familiar, I don't think we should roll with systemd just yet. ;)
Also I'll take a look at the ldap man page and see if I can do anything to make it easier to follow.
Dan
----- Original Message -----
From: "Simo Sorce" simo@redhat.com To: "Development of the System Security Services Daemon" sssd-devel@lists.fedorahosted.org Cc: "George Agriogiannis" gagriogi@redhat.com, "Dan Lavu" dlavu@redhat.com Sent: Monday, June 29, 2015 5:53:45 PM Subject: Re: [SSSD] RFC: Improving the debug messages
On Mon, 2015-06-29 at 18:13 +0200, 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
Simo.
-- Simo Sorce * Red Hat, Inc * New York
sssd-devel mailing list sssd-devel@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
sssd-devel mailing list sssd-devel@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
On Mon, Sep 28, 2015 at 10:18:07AM +0200, Sumit Bose wrote:
On Mon, Jun 29, 2015 at 11:07:30PM -0400, Dan Lavu wrote:
I've been watching various logs for the past few minutes, FWIW, I think a more casual message will help people better understand what SSSD is doing. Look at debug level 4, the first instance of a user name look up (getent passwd dlavu) a common command we tell folks to test to see if SSSD is working
(Mon Jun 29 22:10:59 2015) [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (0x0200): Got request for [0x1001][1][name=dlavu]
Just imagine if you knew nothing about SSSD and how it worked, what can you gather from this line of text? Timestamp, process, domain, get_account_info, got_request and userid and the rest is sort of gibberish and what is the difference between be_get_account_info and got_request_for? I think it's confusing, now looking at some other logs messages.
What is missing in the list of components above is '(0x0200)' which is the debug_level. We recently had a number of questions about messages from a high debug level which in general have an information character, but since it not easy to identify the level of the message it was considered as an error message. Maybe it would be good to have a some translations here as well to make it easier to separate errors from infos.
Do you mean printing the level as string, so that instead of: [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (0x0200): Got request for [0x1001][1][name=dlavu] we would have: [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (SSSDBG_FUNC_DATA): Got request for [0x1001][1][name=dlavu]
?
If yes, then I agree. But at the same time, I think it's more irritating that so many debug levels (mainly those that were mass-converted) are misplaced.
On Tue, Sep 29, 2015 at 05:57:32PM +0200, Jakub Hrozek wrote:
On Mon, Sep 28, 2015 at 10:18:07AM +0200, Sumit Bose wrote:
On Mon, Jun 29, 2015 at 11:07:30PM -0400, Dan Lavu wrote:
I've been watching various logs for the past few minutes, FWIW, I think a more casual message will help people better understand what SSSD is doing. Look at debug level 4, the first instance of a user name look up (getent passwd dlavu) a common command we tell folks to test to see if SSSD is working
(Mon Jun 29 22:10:59 2015) [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (0x0200): Got request for [0x1001][1][name=dlavu]
Just imagine if you knew nothing about SSSD and how it worked, what can you gather from this line of text? Timestamp, process, domain, get_account_info, got_request and userid and the rest is sort of gibberish and what is the difference between be_get_account_info and got_request_for? I think it's confusing, now looking at some other logs messages.
What is missing in the list of components above is '(0x0200)' which is the debug_level. We recently had a number of questions about messages from a high debug level which in general have an information character, but since it not easy to identify the level of the message it was considered as an error message. Maybe it would be good to have a some translations here as well to make it easier to separate errors from infos.
Do you mean printing the level as string, so that instead of: [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (0x0200): Got request for [0x1001][1][name=dlavu] we would have: [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (SSSDBG_FUNC_DATA): Got request for [0x1001][1][name=dlavu]
?
If yes, then I agree. But at the same time, I think it's more irritating
yes, that's what I meant, but maybe we should not use the internal macros here, but something more explicit like ERR_CRIT, ERR_FUNC, INF_CONFIG, INF_DATA, TRACE_... to make it more obvious what the message might be about.
that so many debug levels (mainly those that were mass-converted) are misplaced.
of course, but maybe having the level spelled out will help to identify the ones that are misplaced more easy?
bye, Sumit
sssd-devel mailing list sssd-devel@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
On Tue, Sep 29, 2015 at 06:15:35PM +0200, Sumit Bose wrote:
On Tue, Sep 29, 2015 at 05:57:32PM +0200, Jakub Hrozek wrote:
On Mon, Sep 28, 2015 at 10:18:07AM +0200, Sumit Bose wrote:
On Mon, Jun 29, 2015 at 11:07:30PM -0400, Dan Lavu wrote:
I've been watching various logs for the past few minutes, FWIW, I think a more casual message will help people better understand what SSSD is doing. Look at debug level 4, the first instance of a user name look up (getent passwd dlavu) a common command we tell folks to test to see if SSSD is working
(Mon Jun 29 22:10:59 2015) [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (0x0200): Got request for [0x1001][1][name=dlavu]
Just imagine if you knew nothing about SSSD and how it worked, what can you gather from this line of text? Timestamp, process, domain, get_account_info, got_request and userid and the rest is sort of gibberish and what is the difference between be_get_account_info and got_request_for? I think it's confusing, now looking at some other logs messages.
What is missing in the list of components above is '(0x0200)' which is the debug_level. We recently had a number of questions about messages from a high debug level which in general have an information character, but since it not easy to identify the level of the message it was considered as an error message. Maybe it would be good to have a some translations here as well to make it easier to separate errors from infos.
Do you mean printing the level as string, so that instead of: [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (0x0200): Got request for [0x1001][1][name=dlavu] we would have: [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (SSSDBG_FUNC_DATA): Got request for [0x1001][1][name=dlavu]
?
If yes, then I agree. But at the same time, I think it's more irritating
yes, that's what I meant, but maybe we should not use the internal macros here, but something more explicit like ERR_CRIT, ERR_FUNC, INF_CONFIG, INF_DATA, TRACE_... to make it more obvious what the message might be about.
Yes, sure. Care to file a ticket? :-)
that so many debug levels (mainly those that were mass-converted) are misplaced.
of course, but maybe having the level spelled out will help to identify the ones that are misplaced more easy?
Yes, it would be easier to read a word than a hexa number. We could even colorize the output when running interactively :-)
What we can also do easily and with relatively low effort is to select a couple of the most common usage patterns like: * login with the correct password, online and offline * login with wrong password * run sudo * change password * ....
And make sure they don't print any messages with debug_level <= 3.
On 09/29/2015 07:53 PM, Jakub Hrozek wrote:
On Tue, Sep 29, 2015 at 06:15:35PM +0200, Sumit Bose wrote:
On Tue, Sep 29, 2015 at 05:57:32PM +0200, Jakub Hrozek wrote:
On Mon, Sep 28, 2015 at 10:18:07AM +0200, Sumit Bose wrote:
On Mon, Jun 29, 2015 at 11:07:30PM -0400, Dan Lavu wrote:
I've been watching various logs for the past few minutes, FWIW, I think a more casual message will help people better understand what SSSD is doing. Look at debug level 4, the first instance of a user name look up (getent passwd dlavu) a common command we tell folks to test to see if SSSD is working
(Mon Jun 29 22:10:59 2015) [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (0x0200): Got request for [0x1001][1][name=dlavu]
Just imagine if you knew nothing about SSSD and how it worked, what can you gather from this line of text? Timestamp, process, domain, get_account_info, got_request and userid and the rest is sort of gibberish and what is the difference between be_get_account_info and got_request_for? I think it's confusing, now looking at some other logs messages.
What is missing in the list of components above is '(0x0200)' which is the debug_level. We recently had a number of questions about messages from a high debug level which in general have an information character, but since it not easy to identify the level of the message it was considered as an error message. Maybe it would be good to have a some translations here as well to make it easier to separate errors from infos.
Do you mean printing the level as string, so that instead of: [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (0x0200): Got request for [0x1001][1][name=dlavu] we would have: [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (SSSDBG_FUNC_DATA): Got request for [0x1001][1][name=dlavu]
?
If yes, then I agree. But at the same time, I think it's more irritating
yes, that's what I meant, but maybe we should not use the internal macros here, but something more explicit like ERR_CRIT, ERR_FUNC, INF_CONFIG, INF_DATA, TRACE_... to make it more obvious what the message might be about.
Yes, sure. Care to file a ticket? :-)
that so many debug levels (mainly those that were mass-converted) are misplaced.
of course, but maybe having the level spelled out will help to identify the ones that are misplaced more easy?
Yes, it would be easier to read a word than a hexa number. We could even colorize the output when running interactively :-)
Yes, we could - I have for quite some time wip patches (example of colored logs http://picpaste.com/unnamed-d2I1GzUk.png)
What we can also do easily and with relatively low effort is to select a couple of the most common usage patterns like: * login with the correct password, online and offline * login with wrong password * run sudo * change password * ....
And make sure they don't print any messages with debug_level <= 3.
+1
sssd-devel mailing list sssd-devel@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
On Tue, Sep 29, 2015 at 07:53:41PM +0200, Jakub Hrozek wrote:
On Tue, Sep 29, 2015 at 06:15:35PM +0200, Sumit Bose wrote:
On Tue, Sep 29, 2015 at 05:57:32PM +0200, Jakub Hrozek wrote:
On Mon, Sep 28, 2015 at 10:18:07AM +0200, Sumit Bose wrote:
On Mon, Jun 29, 2015 at 11:07:30PM -0400, Dan Lavu wrote:
I've been watching various logs for the past few minutes, FWIW, I think a more casual message will help people better understand what SSSD is doing. Look at debug level 4, the first instance of a user name look up (getent passwd dlavu) a common command we tell folks to test to see if SSSD is working
(Mon Jun 29 22:10:59 2015) [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (0x0200): Got request for [0x1001][1][name=dlavu]
Just imagine if you knew nothing about SSSD and how it worked, what can you gather from this line of text? Timestamp, process, domain, get_account_info, got_request and userid and the rest is sort of gibberish and what is the difference between be_get_account_info and got_request_for? I think it's confusing, now looking at some other logs messages.
What is missing in the list of components above is '(0x0200)' which is the debug_level. We recently had a number of questions about messages from a high debug level which in general have an information character, but since it not easy to identify the level of the message it was considered as an error message. Maybe it would be good to have a some translations here as well to make it easier to separate errors from infos.
Do you mean printing the level as string, so that instead of: [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (0x0200): Got request for [0x1001][1][name=dlavu] we would have: [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (SSSDBG_FUNC_DATA): Got request for [0x1001][1][name=dlavu]
?
If yes, then I agree. But at the same time, I think it's more irritating
yes, that's what I meant, but maybe we should not use the internal macros here, but something more explicit like ERR_CRIT, ERR_FUNC, INF_CONFIG, INF_DATA, TRACE_... to make it more obvious what the message might be about.
Yes, sure. Care to file a ticket? :-)
It's https://fedorahosted.org/sssd/ticket/2808 . Please add ideas and suggestions how those tags shall look like.
bye, Sumit
that so many debug levels (mainly those that were mass-converted) are misplaced.
of course, but maybe having the level spelled out will help to identify the ones that are misplaced more easy?
Yes, it would be easier to read a word than a hexa number. We could even colorize the output when running interactively :-)
What we can also do easily and with relatively low effort is to select a couple of the most common usage patterns like: * login with the correct password, online and offline * login with wrong password * run sudo * change password * ....
And make sure they don't print any messages with debug_level <= 3. _______________________________________________ sssd-devel mailing list sssd-devel@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
On Wed, Sep 30, 2015 at 09:53:24AM +0200, Sumit Bose wrote:
It's https://fedorahosted.org/sssd/ticket/2808 . Please add ideas and suggestions how those tags shall look like.
Thanks, I ressurected https://fedorahosted.org/sssd/ticket/1372 from Deferred as well.
On 09/30/2015 11:15 AM, Jakub Hrozek wrote:
On Wed, Sep 30, 2015 at 09:53:24AM +0200, Sumit Bose wrote:
It's https://fedorahosted.org/sssd/ticket/2808 . Please add ideas and suggestions how those tags shall look like.
Thanks, I ressurected https://fedorahosted.org/sssd/ticket/1372 from Deferred as well. _______________________________________________
This topic resonates with me. Text instead of hexadecimal numbers is better and it could make our logs more understandable. And usage patterns are very nice guides for orientation in logs.
I would like to work on this ticket.
Petr
On Wed, Sep 30, 2015 at 01:10:20PM +0200, Petr Cech wrote:
On 09/30/2015 11:15 AM, Jakub Hrozek wrote:
On Wed, Sep 30, 2015 at 09:53:24AM +0200, Sumit Bose wrote:
It's https://fedorahosted.org/sssd/ticket/2808 . Please add ideas and suggestions how those tags shall look like.
Thanks, I ressurected https://fedorahosted.org/sssd/ticket/1372 from Deferred as well. _______________________________________________
This topic resonates with me. Text instead of hexadecimal numbers is better and it could make our logs more understandable. And usage patterns are very nice guides for orientation in logs.
I would like to work on this ticket.
Sure, pick it up.
On 09/29/2015 07:53 PM, Jakub Hrozek wrote:
On Tue, Sep 29, 2015 at 06:15:35PM +0200, Sumit Bose wrote:
On Tue, Sep 29, 2015 at 05:57:32PM +0200, Jakub Hrozek wrote:
On Mon, Sep 28, 2015 at 10:18:07AM +0200, Sumit Bose wrote:
On Mon, Jun 29, 2015 at 11:07:30PM -0400, Dan Lavu wrote:
I've been watching various logs for the past few minutes, FWIW, I think a more casual message will help people better understand what SSSD is doing. Look at debug level 4, the first instance of a user name look up (getent passwd dlavu) a common command we tell folks to test to see if SSSD is working
(Mon Jun 29 22:10:59 2015) [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (0x0200): Got request for [0x1001][1][name=dlavu]
Just imagine if you knew nothing about SSSD and how it worked, what can you gather from this line of text? Timestamp, process, domain, get_account_info, got_request and userid and the rest is sort of gibberish and what is the difference between be_get_account_info and got_request_for? I think it's confusing, now looking at some other logs messages.
What is missing in the list of components above is '(0x0200)' which is the debug_level. We recently had a number of questions about messages from a high debug level which in general have an information character, but since it not easy to identify the level of the message it was considered as an error message. Maybe it would be good to have a some translations here as well to make it easier to separate errors from infos.
Do you mean printing the level as string, so that instead of: [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (0x0200): Got request for [0x1001][1][name=dlavu] we would have: [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (SSSDBG_FUNC_DATA): Got request for [0x1001][1][name=dlavu]
?
If yes, then I agree. But at the same time, I think it's more irritating
yes, that's what I meant, but maybe we should not use the internal macros here, but something more explicit like ERR_CRIT, ERR_FUNC, INF_CONFIG, INF_DATA, TRACE_... to make it more obvious what the message might be about.
I don't oppose, but I have to ask. Is there really any developer who reads debug levels when debugging? I personally only read messages and I'd prefer to see smaller lines.
Yes, sure. Care to file a ticket? :-)
that so many debug levels (mainly those that were mass-converted) are misplaced.
of course, but maybe having the level spelled out will help to identify the ones that are misplaced more easy?
Yes, it would be easier to read a word than a hexa number. We could even colorize the output when running interactively :-)
What we can also do easily and with relatively low effort is to select a couple of the most common usage patterns like: * login with the correct password, online and offline * login with wrong password * run sudo * change password * ....
And make sure they don't print any messages with debug_level <= 3. _______________________________________________ sssd-devel mailing list sssd-devel@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
On 10/01/2015 09:58 AM, Pavel Březina wrote:
On 09/29/2015 07:53 PM, Jakub Hrozek wrote:
On Tue, Sep 29, 2015 at 06:15:35PM +0200, Sumit Bose wrote:
On Tue, Sep 29, 2015 at 05:57:32PM +0200, Jakub Hrozek wrote:
On Mon, Sep 28, 2015 at 10:18:07AM +0200, Sumit Bose wrote:
On Mon, Jun 29, 2015 at 11:07:30PM -0400, Dan Lavu wrote:
I've been watching various logs for the past few minutes, FWIW, I think a more casual message will help people better understand what SSSD is doing. Look at debug level 4, the first instance of a user name look up (getent passwd dlavu) a common command we tell folks to test to see if SSSD is working
(Mon Jun 29 22:10:59 2015) [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (0x0200): Got request for [0x1001][1][name=dlavu]
Just imagine if you knew nothing about SSSD and how it worked, what can you gather from this line of text? Timestamp, process, domain, get_account_info, got_request and userid and the rest is sort of gibberish and what is the difference between be_get_account_info and got_request_for? I think it's confusing, now looking at some other logs messages.
What is missing in the list of components above is '(0x0200)' which is the debug_level. We recently had a number of questions about messages from a high debug level which in general have an information character, but since it not easy to identify the level of the message it was considered as an error message. Maybe it would be good to have a some translations here as well to make it easier to separate errors from infos.
Do you mean printing the level as string, so that instead of: [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (0x0200): Got request for [0x1001][1][name=dlavu] we would have: [sssd[be[lab.runlevelone.lan]]] [be_get_account_info] (SSSDBG_FUNC_DATA): Got request for [0x1001][1][name=dlavu]
?
If yes, then I agree. But at the same time, I think it's more irritating
yes, that's what I meant, but maybe we should not use the internal macros here, but something more explicit like ERR_CRIT, ERR_FUNC, INF_CONFIG, INF_DATA, TRACE_... to make it more obvious what the message might be about.
I don't oppose, but I have to ask. Is there really any developer who reads debug levels when debugging? I personally only read messages and I'd prefer to see smaller lines.
I think that this is not aimed for developers but for admins/users who when confronted with verbose debug file might be unnecessary scared from some debug messages. The idea is that if they see that the scary sounding message is just TRACE_ALL instead of 0x400 they might stop panicking.
Yes, sure. Care to file a ticket? :-)
that so many debug levels (mainly those that were mass-converted) are misplaced.
of course, but maybe having the level spelled out will help to identify the ones that are misplaced more easy?
Yes, it would be easier to read a word than a hexa number. We could even colorize the output when running interactively :-)
What we can also do easily and with relatively low effort is to select a couple of the most common usage patterns like: * login with the correct password, online and offline * login with wrong password * run sudo * change password * ....
And make sure they don't print any messages with debug_level <= 3. _______________________________________________ sssd-devel mailing list sssd-devel@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
sssd-devel mailing list sssd-devel@lists.fedorahosted.org https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
On Mon, Jun 29, 2015 at 06:13:20PM +0200, Jakub Hrozek wrote:
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.
Then the question is if the first part ([be_get_account_info]/[acctinfo_callback]) of those lines shouldn't match, for easy search'n'jump to the "matching bracket". Something like [account info >] ... and [account info <] would be even better, distinguishing the entry points (ha, nice, so the call at least got here) from the exits.
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.
It'd be great if the default option was to emit one error message per failure (per operation, where operation should be defined from user's point of view, not developer's point of view) and no message for success. The next level would be to have one error message per failure and one message per success, so that it's easy to observe what is going on without getting into too much detail.
- anything that causes SSSD to fail to start should also emit a syslog message. Admins don't really know about sssd debug logs.
We have a ticket https://fedorahosted.org/sssd/ticket/2687 filed for this one.
On Tue, Jun 30, 2015 at 10:30:16AM +0200, Jan Pazdziora wrote:
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.
It'd be great if the default option was to emit one error message per failure (per operation, where operation should be defined from user's point of view, not developer's point of view) and no message for success. The next level would be to have one error message per failure and one message per success, so that it's easy to observe what is going on without getting into too much detail.
What someone (sorry, I already forgot who :-/) also suggested during a discussion was to add a new log level for start and end of an operation.
On Tue, 2015-06-30 at 12:04 +0200, Jakub Hrozek wrote:
On Tue, Jun 30, 2015 at 10:30:16AM +0200, Jan Pazdziora wrote:
- 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.
It'd be great if the default option was to emit one error message per failure (per operation, where operation should be defined from user's point of view, not developer's point of view) and no message for success. The next level would be to have one error message per failure and one message per success, so that it's easy to observe what is going on without getting into too much detail.
What someone (sorry, I already forgot who :-/) also suggested during a discussion was to add a new log level for start and end of an operation.
The other thing we might want to be doing is looking at some of the more advanced journald logging capabilities. For example, if you look at the Cockpit and realmd projects, they have implemented a mechanism to use journald tagging to easily identify activities being performed by specific clients. We should do the same, so it's possible to limit our view of the journal to just the actions we're interested in (which will make life easier on a busy server)
On Tue, Jun 30, 2015 at 07:58:45AM -0400, Stephen Gallagher wrote:
On Tue, 2015-06-30 at 12:04 +0200, Jakub Hrozek wrote:
On Tue, Jun 30, 2015 at 10:30:16AM +0200, Jan Pazdziora wrote:
- 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.
It'd be great if the default option was to emit one error message per failure (per operation, where operation should be defined from user's point of view, not developer's point of view) and no message for success. The next level would be to have one error message per failure and one message per success, so that it's easy to observe what is going on without getting into too much detail.
What someone (sorry, I already forgot who :-/) also suggested during a discussion was to add a new log level for start and end of an operation.
The other thing we might want to be doing is looking at some of the more advanced journald logging capabilities. For example, if you look at the Cockpit and realmd projects, they have implemented a mechanism to use journald tagging to easily identify activities being performed by specific clients. We should do the same, so it's possible to limit our view of the journal to just the actions we're interested in (which will make life easier on a busy server)
Yes, I already looked at realmd and I really liked what I see. It would be indeed easy to add tagging for the top-level request, but because of the async nature of SSSD, we would have to pass the tag into the nested requests..
btw I was also thinking if this would be something useful to add to tevent, so each tevent request would have an ID, maybe something that would allow to identify the parents as well. Like: parent - 0x0000AA subreq1 - 0x00BBAA subreq2 - 0x00BCAA subsubreq - 0xDDBCAA
On (29/06/15 18:13), 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]
^^^^^^^^^^ The last part is single variable filter. I don't think we need to split it
[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.
This one is doable short term.
- same for authentication
the same as above
- 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.
the same as above
- 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.
This one is not doable in short term. Please consider AD provider and error causedb by "replacing" groups after tokengroups. But I agree that in long term we shoudl do it.
- anything that causes SSSD to fail to start should also emit a syslog
message. Admins don't really know about sssd debug logs.
We just need to enable logging to journald by default + change debug level. But it requires to fix previous point.
- our man pages are not structured well, especially the LDAP man page is
too big and contains too many options.
Do you have an idea how to split man pages?
We do not have one long man page. sssd(8), sssd.conf(5), sssd-ldap(5), sssd-krb5(5), sssd-simple(5), sssd-ipa(5), sssd-ad(5), sssd-sudo(5),sss_cache(8), sss_debuglevel(8), sss_groupadd(8), sss_groupdel(8), sss_groupshow(8), sss_groupmod(8), sss_useradd(8), sss_userdel(8), sss_usermod(8), sss_obfuscate(8), sss_seed(8), sssd_krb5_locator_plugin(8), sss_ssh_authorizedkeys(8), sss_ssh_knownhostsproxy(8),sssd-ifp(5),pam_sss(8). sss_rpcidmapd(5)
The main problem is that people needn't know about them and/or they needn't know where to start.
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.
The best way how to get familiar with sssd is to fix few bugs in different part of sssd :-)
LS
On Tue, Jun 30, 2015 at 11:28:39PM +0200, Lukas Slebodnik wrote:
- 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.
This one is not doable in short term. Please consider AD provider and error causedb by "replacing" groups after tokengroups. But I agree that in long term we shoudl do it.
Maybe not all, but we could do a lot here even in short term.
- anything that causes SSSD to fail to start should also emit a syslog
message. Admins don't really know about sssd debug logs.
We just need to enable logging to journald by default
- change debug level. But it requires to fix previous point.
- our man pages are not structured well, especially the LDAP man page is
too big and contains too many options.
Do you have an idea how to split man pages?
We do not have one long man page. sssd(8), sssd.conf(5), sssd-ldap(5), sssd-krb5(5), sssd-simple(5), sssd-ipa(5), sssd-ad(5), sssd-sudo(5),sss_cache(8), sss_debuglevel(8), sss_groupadd(8), sss_groupdel(8), sss_groupshow(8), sss_groupmod(8), sss_useradd(8), sss_userdel(8), sss_usermod(8), sss_obfuscate(8), sss_seed(8), sssd_krb5_locator_plugin(8), sss_ssh_authorizedkeys(8), sss_ssh_knownhostsproxy(8),sssd-ifp(5),pam_sss(8). sss_rpcidmapd(5)
The main problem is that people needn't know about them and/or they needn't know where to start.
I think most man pages are not that bad, I mostly have issue with sssd.conf(5) and sssd-ldap(5). Especially sssd-ldap would much more readable if we grouped the options. At least having a section for user attribute mappings, group attribute mappings, ... would be very helpful.
On (01/07/15 10:03), Jakub Hrozek wrote:
On Tue, Jun 30, 2015 at 11:28:39PM +0200, Lukas Slebodnik wrote:
- 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.
This one is not doable in short term. Please consider AD provider and error causedb by "replacing" groups after tokengroups. But I agree that in long term we shoudl do it.
Maybe not all, but we could do a lot here even in short term.
- anything that causes SSSD to fail to start should also emit a syslog
message. Admins don't really know about sssd debug logs.
We just need to enable logging to journald by default
- change debug level. But it requires to fix previous point.
- our man pages are not structured well, especially the LDAP man page is
too big and contains too many options.
Do you have an idea how to split man pages?
We do not have one long man page. sssd(8), sssd.conf(5), sssd-ldap(5), sssd-krb5(5), sssd-simple(5), sssd-ipa(5), sssd-ad(5), sssd-sudo(5),sss_cache(8), sss_debuglevel(8), sss_groupadd(8), sss_groupdel(8), sss_groupshow(8), sss_groupmod(8), sss_useradd(8), sss_userdel(8), sss_usermod(8), sss_obfuscate(8), sss_seed(8), sssd_krb5_locator_plugin(8), sss_ssh_authorizedkeys(8), sss_ssh_knownhostsproxy(8),sssd-ifp(5),pam_sss(8). sss_rpcidmapd(5)
The main problem is that people needn't know about them and/or they needn't know where to start.
I think most man pages are not that bad, I mostly have issue with sssd.conf(5) and sssd-ldap(5). Especially sssd-ldap would much more readable if we grouped the options. At least having a section for user attribute mappings, group attribute mappings, ... would be very helpful.
Sections are good idea.
Do we have a ticket?
LS
On Mon, Jul 13, 2015 at 09:31:35AM +0200, Lukas Slebodnik wrote:
I think most man pages are not that bad, I mostly have issue with sssd.conf(5) and sssd-ldap(5). Especially sssd-ldap would much more readable if we grouped the options. At least having a section for user attribute mappings, group attribute mappings, ... would be very helpful.
Sections are good idea.
Do we have a ticket?
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.
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.
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
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.
On (01/07/15 12:48), 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.
The other thing to be careful about is that admins are used to just set: debug_level=10
We needn't extend old debug levels just bit mask version and old debug level(0-9) can be a bitmask of more new debug_levels.
So if someone set debug_level 9 or 10 it will still enable all debug messages.
LS
On Mon, Jul 13, 2015 at 09:34:23AM +0200, Lukas Slebodnik wrote:
On (01/07/15 12:48), 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.
The other thing to be careful about is that admins are used to just set: debug_level=10
We needn't extend old debug levels just bit mask version and old debug level(0-9) can be a bitmask of more new debug_levels.
So if someone set debug_level 9 or 10 it will still enable all debug messages.
OK, that's a good idea.
sssd-devel@lists.fedorahosted.org
-
Dan Lavu -
Jakub Hrozek -
Jan Pazdziora -
Lukas Slebodnik -
Pavel Březina -
Pavel Reichl -
Petr Cech -
Simo Sorce -
Stephen Gallagher -
Sumit Bose