Bug 811113 - Quiet down the startup of sssd
Summary: Quiet down the startup of sssd
Keywords:
Status: CLOSED UPSTREAM
Alias: None
Product: Fedora
Classification: Fedora
Component: sssd
Version: 26
Hardware: Unspecified
OS: Unspecified
unspecified
low
Target Milestone: ---
Assignee: Jakub Hrozek
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2012-04-10 07:42 UTC by Stef Walter
Modified: 2020-05-02 16:50 UTC (History)
7 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-04-11 15:49:15 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
Move some debug lines to new debug log levels (11.23 KB, patch)
2012-04-12 13:36 UTC, Stef Walter
no flags Details | Diff
Updated for Stephen's initial review (11.28 KB, patch)
2012-04-12 18:58 UTC, Stef Walter
no flags Details | Diff


Links
System ID Private Priority Status Summary Last Updated
Github SSSD sssd issues 2336 0 None None None 2020-05-02 16:50:53 UTC

Description Stef Walter 2012-04-10 07:42:05 UTC
When SSSD is started with a debug level that should show failures, lots of messages that have nothing to do with failure show up. This obscures the actual problems.

I'll submit some patches to reassign some of the messages to the correct locations.

Example:

[root@stef-desktop data]# /usr/sbin/sssd -d 0x00F0 -i
(Tue Apr 10 09:08:01:333969 2012) [sssd] [check_file] (0x0020): lstat for [/var/run/nscd/socket] failed: [2][No such file or directory].
(Tue Apr 10 09:08:01:335171 2012) [sssd] [confdb_get_domain_internal] (0x0020): No enumeration for [ad.thewalter.lan]!
(Tue Apr 10 09:08:01 2012) [sssd] [server_setup] (0x0080): CONFDB: /var/lib/sss/db/config.ldb
(Tue Apr 10 09:08:01 2012) [sssd] [sbus_new_server] (0x0080): D-BUS Server listening on unix:path=/var/lib/sss/pipes/private/sbus-monitor,guid=eab88a161d7b3ba30f5012f300001624
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [server_setup] (0x0080): CONFDB: /var/lib/sss/db/config.ldb
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [fo_context_init] (0x0080): Created new fail over context, retry timeout is 30
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [confdb_get_domain_internal] (0x0020): No enumeration for [ad.thewalter.lan]!
(Tue Apr 10 09:08:01 2012) [sssd] [monitor_service_init] (0x0080): Initializing D-BUS Service
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [sbus_new_server] (0x0080): D-BUS Server listening on unix:path=/var/lib/sss/pipes/private/sbus-dp_ad.thewalter.lan.12534,guid=62df5fee35e9244dbc19011900001624
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [sssm_ldap_id_init] (0x0020): Missing ldap_uri, will use service discovery
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [fo_new_service] (0x0080): Creating new service 'LDAP'
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [fo_add_srv_server] (0x0080): Adding new SRV server in domain 'unknown', to service 'LDAP' using tcp
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [sdap_gssapi_init] (0x0020): Missing krb5_server option, using service discovery!
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [fo_new_service] (0x0080): Creating new service 'KERBEROS'
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [fo_add_srv_server] (0x0080): Adding new SRV server in domain 'unknown', to service 'KERBEROS' using udp
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [fo_add_srv_server] (0x0080): Adding new SRV server in domain 'unknown', to service 'KERBEROS' using tcp
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [find_principal_in_keytab] (0x0080): No principal matching stef-desktop.thewalter.lan$@AD.THEWALTER.LAN found in keytab.
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [sssm_krb5_auth_init] (0x0020): Missing krb5_server option, using service discovery!
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [fo_add_srv_server] (0x0080): Adding new SRV server in domain 'unknown', to service 'KERBEROS' using udp
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [fo_add_srv_server] (0x0080): Adding new SRV server in domain 'unknown', to service 'KERBEROS' using tcp
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [fo_new_service] (0x0080): Creating new service 'KPASSWD'
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [fo_add_srv_server] (0x0080): Adding new SRV server in domain 'unknown', to service 'KPASSWD' using udp
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [fo_add_srv_server] (0x0080): Adding new SRV server in domain 'unknown', to service 'KPASSWD' using tcp
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [check_and_export_options] (0x0020): No KDC explicitly configured, using defaults.
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [check_and_export_options] (0x0020): No kpasswd server explicitly configured, using the KDC or defaults.
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [ldap_get_autofs_options] (0x0040): Error: no autofs search base set
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [load_backend_module] (0x0010): Error (2) in module (ldap) initialization (sssm_ldap_autofs_init)!
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [be_process_init] (0x0080): No autofs module provided for [ad.thewalter.lan] !!
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [be_process_init] (0x0020): No Session module provided for [ad.thewalter.lan] !!
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [be_process_init] (0x0020): No host info module provided for [ad.thewalter.lan] !!
(Tue Apr 10 09:08:01 2012) [sssd[be[ad.thewalter.lan]]] [main] (0x0020): Backend provider (ad.thewalter.lan) started!
(Tue Apr 10 09:08:01 2012) [sssd[nss]] [server_setup] (0x0080): (Tue Apr 10 09:08:01 2012) [sssd[pam]] [server_setup] (0x0080): CONFDB: /var/lib/sss/db/config.ldb
CONFDB: /var/lib/sss/db/config.ldb
(Tue Apr 10 09:08:01 2012) [sssd[pam]] [confdb_get_domain_internal] (0x0020): No enumeration for [ad.thewalter.lan]!
(Tue Apr 10 09:08:01 2012) [sssd[nss]] [confdb_get_domain_internal] (0x0020): No enumeration for [ad.thewalter.lan]!
(Tue Apr 10 09:08:01 2012) [sssd] [monitor_service_init] (0x0080): Initializing D-BUS Service
(Tue Apr 10 09:08:01 2012) [sssd[pam]] [sss_process_init] (0x0020): Responder Initialization complete
(Tue Apr 10 09:08:01 2012) [sssd] [monitor_service_init] (0x0080): Initializing D-BUS Service
(Tue Apr 10 09:08:01 2012) [sssd[nss]] [sss_process_init] (0x0020): Responder Initialization complete
(Tue Apr 10 09:08:01 2012) [sssd[nss]] [nss_process_init] (0x0020): NSS Initialization complete

Comment 1 Jakub Hrozek 2012-04-10 09:18:28 UTC
Upstream ticket:
https://fedorahosted.org/sssd/ticket/1294

Comment 2 Jakub Hrozek 2012-04-10 09:22:32 UTC
(In reply to comment #0)
> When SSSD is started with a debug level that should show failures, lots of
> messages that have nothing to do with failure show up. This obscures the actual
> problems.
> 

Many of the DEBUG statements, especially in code that hasn't been touched for some time, still use the old numeric levels. Changing them to the new debug levels (SSSDBG_*) would certainly be welcome. 

> I'll submit some patches to reassign some of the messages to the correct
> locations.
> 

Thank you. See https://fedorahosted.org/pipermail/sssd-devel/2011-June/006420.html for a short explanation of the different log levels.

Comment 3 Stef Walter 2012-04-12 13:36:04 UTC
Created attachment 577074 [details]
Move some debug lines to new debug log levels

* These are common lines of debug output when starting
   up sssd

Comments on some of the changes:

This isn't an error, legitimate configuration:
+        DEBUG(SSSDBG_TRACE_FUNC, ("No enumeration for [%s]!\n", domain->name));

Not errors, using service discovery is 'best' practice:
+        DEBUG(SSSDBG_TRACE_FUNC, ("No KDC explicitly configured, using defaults.\n"));
+        DEBUG(SSSDBG_TRACE_FUNC, ("No kpasswd server explicitly configured, "
+                                  "using the KDC or defaults.\n"));
+        DEBUG(SSSDBG_TRACE_FUNC, ("Missing krb5_server option, using service discovery!\n
+        DEBUG(SSSDBG_TRACE_FUNC, ("Missing krb5_server option, using service discovery!\n
+        DEBUG(SSSDBG_TRACE_FUNC, ("Missing ldap_uri, will use service discovery\n"));

Describe where the pid file failed to be created:
+            DEBUG(0, ("Error creating pidfile: %s/%s! (%d [%s])\n",
+                      PID_PATH, name, ret, strerror(ret)));

In cases where this is an error, caller prints out a relevant message:
-        DEBUG(SSSDBG_MINOR_FAILURE,
+        DEBUG(SSSDBG_TRACE_FUNC,
               ("No principal matching %s@%s found in keytab.\n",
                pattern_primary, pattern_realm));

This is expected to fail in many cases. In cases where this is an error
caller prints out a relevant message:
-        DEBUG(1, ("lstat for [%s] failed: [%d][%s].\n", filename, errno,
-                                                        strerror(errno)));
+        DEBUG(SSSDBG_TRACE_FUNC, ("lstat for [%s] failed: [%d][%s].\n", filename, errno,
+                                                                        strerror(errno)))

Comment 4 Stephen Gallagher 2012-04-12 14:09:28 UTC
(In reply to comment #3)
> Created attachment 577074 [details]
> Move some debug lines to new debug log levels
> 
> * These are common lines of debug output when starting
>    up sssd
> 
> Comments on some of the changes:
> 
> This isn't an error, legitimate configuration:
> +        DEBUG(SSSDBG_TRACE_FUNC, ("No enumeration for [%s]!\n",
> domain->name));
> 
> Not errors, using service discovery is 'best' practice:
> +        DEBUG(SSSDBG_TRACE_FUNC, ("No KDC explicitly configured, using
> defaults.\n"));
> +        DEBUG(SSSDBG_TRACE_FUNC, ("No kpasswd server explicitly configured, "
> +                                  "using the KDC or defaults.\n"));
> +        DEBUG(SSSDBG_TRACE_FUNC, ("Missing krb5_server option, using service
> discovery!\n
> +        DEBUG(SSSDBG_TRACE_FUNC, ("Missing krb5_server option, using service
> discovery!\n
> +        DEBUG(SSSDBG_TRACE_FUNC, ("Missing ldap_uri, will use service
> discovery\n"));
> 


All of the above should be SSSDBG_CONF_SETTINGS, not SSSDBG_TRACE_FUNC

> Describe where the pid file failed to be created:
> +            DEBUG(0, ("Error creating pidfile: %s/%s! (%d [%s])\n",
> +                      PID_PATH, name, ret, strerror(ret)));
> 

Please do not add numeric debug levels. In this case it should be SSSDBG_FATAL_FAILURE because this error prevents the entire system from working.


> In cases where this is an error, caller prints out a relevant message:
> -        DEBUG(SSSDBG_MINOR_FAILURE,
> +        DEBUG(SSSDBG_TRACE_FUNC,
>                ("No principal matching %s@%s found in keytab.\n",
>                 pattern_primary, pattern_realm));
> 

Looks right.

> This is expected to fail in many cases. In cases where this is an error
> caller prints out a relevant message:
> -        DEBUG(1, ("lstat for [%s] failed: [%d][%s].\n", filename, errno,
> -                                                        strerror(errno)));
> +        DEBUG(SSSDBG_TRACE_FUNC, ("lstat for [%s] failed: [%d][%s].\n",
> filename, errno,
> +                                                                       
> strerror(errno)))

Looks right.


I haven't reviewed the rest of the patch yet.

Comment 5 Stef Walter 2012-04-12 18:58:40 UTC
Created attachment 577155 [details]
Updated for Stephen's initial review

Move some debug lines to new debug log levels

 * These are common lines of debug output when starting
   up sssd

Comment 6 Fedora End Of Life 2013-04-03 19:44:24 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 19 development cycle.
Changing version to '19'.

(As we did not run this process for some time, it could affect also pre-Fedora 19 development
cycle bugs. We are very sorry. It will help us with cleanup during Fedora 19 End Of Life. Thank you.)

More information and reason for this action is here:
https://fedoraproject.org/wiki/BugZappers/HouseKeeping/Fedora19

Comment 7 Fedora End Of Life 2015-01-09 21:57:14 UTC
This message is a notice that Fedora 19 is now at end of life. Fedora 
has stopped maintaining and issuing updates for Fedora 19. It is 
Fedora's policy to close all bug reports from releases that are no 
longer maintained. Approximately 4 (four) weeks from now this bug will
be closed as EOL if it remains open with a Fedora 'version' of '19'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 19 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 8 Jakub Hrozek 2015-01-10 13:36:37 UTC
Still an issue, planned for next upstream version.

Comment 9 Jan Kurik 2015-07-15 15:10:16 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 23 development cycle.
Changing version to '23'.

(As we did not run this process for some time, it could affect also pre-Fedora 23 development
cycle bugs. We are very sorry. It will help us with cleanup during Fedora 23 End Of Life. Thank you.)

More information and reason for this action is here:
https://fedoraproject.org/wiki/BugZappers/HouseKeeping/Fedora23

Comment 10 Fedora End Of Life 2016-11-24 10:38:29 UTC
This message is a reminder that Fedora 23 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 23. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora  'version'
of '23'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 23 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 11 Fedora End Of Life 2017-02-28 09:30:39 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 26 development cycle.
Changing version to '26'.

Comment 12 Fabiano Fidêncio 2018-04-11 15:49:15 UTC
As this is an RFE that we've been already tracking in our pagure I'm closing this bug as "UPSTREAM".

For more details, please, feel free to follow: https://pagure.io/SSSD/sssd/issue/1294

If, for some reason, there's the need to re-open this bug, feel free to do so.


Note You need to log in before you can comment on or make changes to this bug.