Bug 811113 - Quiet down the startup of sssd
Quiet down the startup of sssd
Status: ASSIGNED
Product: Fedora
Classification: Fedora
Component: sssd (Show other bugs)
23
Unspecified Unspecified
unspecified Severity low
: ---
: ---
Assigned To: Jakub Hrozek
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2012-04-10 03:42 EDT by Stef Walter
Modified: 2016-07-20 11:40 EDT (History)
6 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed:
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


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

  None (edit)
Description Stef Walter 2012-04-10 03:42:05 EDT
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 05:18:28 EDT
Upstream ticket:
https://fedorahosted.org/sssd/ticket/1294
Comment 2 Jakub Hrozek 2012-04-10 05:22:32 EDT
(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 09:36:04 EDT
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 10:09:28 EDT
(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 14:58:40 EDT
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 15:44:24 EDT
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 16:57:14 EST
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 08:36:37 EST
Still an issue, planned for next upstream version.
Comment 9 Jan Kurik 2015-07-15 11:10:16 EDT
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

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