#2561 Too much logging
Closed: Fixed None Opened 9 years ago by tarvin.

On a RHEL 7 system integrated with an AD domain: Whenever someone successfully logs in via SSH, it generates eight lines of syslog messages with no meaningful content (it looks like debug messages which someone forgot to mark as debug messages):

2015-01-20T22:40:02.319073+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 1
2015-01-20T22:40:02.319252+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 1
2015-01-20T22:40:02.322042+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 1
2015-01-20T22:40:02.322714+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 2
2015-01-20T22:40:02.371036+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 1
2015-01-20T22:40:02.371211+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 1
2015-01-20T22:40:02.375077+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 1
2015-01-20T22:40:02.375716+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 2

Fields changed

description: On a RHEL 7 system integrated with an AD domain: Whenever someone successfully logs in via SSH, it generates eight lines of syslog messages with no meaningful content (it looks like debug messages which someone forgot to mark as debug messages):

2015-01-20T22:40:02.319073+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 1
2015-01-20T22:40:02.319252+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 1
2015-01-20T22:40:02.322042+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 1
2015-01-20T22:40:02.322714+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 2
2015-01-20T22:40:02.371036+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 1
2015-01-20T22:40:02.371211+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 1
2015-01-20T22:40:02.375077+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 1
2015-01-20T22:40:02.375716+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 2 => On a RHEL 7 system integrated with an AD domain: Whenever someone successfully logs in via SSH, it generates eight lines of syslog messages with no meaningful content (it looks like debug messages which someone forgot to mark as debug messages):
{{{
2015-01-20T22:40:02.319073+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 1
2015-01-20T22:40:02.319252+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 1
2015-01-20T22:40:02.322042+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 1
2015-01-20T22:40:02.322714+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 2
2015-01-20T22:40:02.371036+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 1
2015-01-20T22:40:02.371211+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 1
2015-01-20T22:40:02.375077+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 1
2015-01-20T22:40:02.375716+01:00 somehost 127.0.0.1 sssd_be: GSSAPI client step 2
}}}
feature_milestone: => Fix formatting in description

Fields changed

feature_milestone: Fix formatting in description =>

Fields changed

owner: somebody => preichl

I found out that the logging comes from Cyrus-SASL library.
I tried to create a callback for logging:

+int ad_sasl_log(void *context, int level, const char *message)
+{
+    return SASL_OK;
+}
+
 typedef int (*sss_sasl_gen_cb_fn)(void);

 static const sasl_callback_t ad_sasl_callbacks[] = {
     { SASL_CB_GETOPT, (sss_sasl_gen_cb_fn)ad_sasl_getopt, NULL },
+    { SASL_CB_LOG, (sss_sasl_gen_cb_fn)ad_sasl_log, NULL },
     { SASL_CB_LIST_END, NULL, NULL }
 };

but SASL: ignores it as it calls loging with NULL context, so no callbacks are searched

params->utils->log(NULL, SASL_LOG_DEBUG, "GSSAPI client step %d", text->state);

It seems that other users have encountered same issues:
http://www.spinics.net/lists/cyrus-sasl/msg01831.html

Thanks!

Can you ask Simo? He knows cyrus-sasl well..

I see this in other projects too.
I guess we need to open a bug against cyrus-sasl and get it fixed ?

Simo do you mean we should open a bug about "Too much logging" or about failing to utilize the log callback?

Thanks!

I posted a message about both of these issues to cyrus-sasl mailing list.

There's an ongoing discussion on http://lists.andrew.cmu.edu/pipermail/cyrus-sasl/2015-January/ (subject: to much syslogging by default).

It's now my understanding that we can't do anything about this - there should be 2 ways how to suppress logging but both seems to be broken. This is fragment from the discussion:

>1) setting debug_level has no effect
>2) there's no way how to use our own log callback
>
>Am I right?

I suspect you are right, as your analysis indicates.

I personally think that SASL develepers are not too eager to fix this any time soon...

We cannot do anything about this issue. I filled bug against Fedora's component cyrus-sasl
https://bugzilla.redhat.com/show_bug.cgi?id=1187097

resolution: => cantfix
status: new => closed

Just a quick update - our cyrus-sasl maintainers have a fix, that should enable us to register logging callbacks. Using these callbacks we should be able to ignore too verbose debug messages.

Fixed package cyrus-sasl-2.1.26-23.fc22 has been pushed to the Fedora 22 stable repository. So this ticket should be now doable.

sensitive: => 0

Fields changed

resolution: cantfix =>
status: closed => reopened

Please move to a later milestone if this turns out to be a non-trivial task

milestone: NEEDS_TRIAGE => SSSD 1.13.2

Fields changed

rhbz: => todo

Fields changed

patch: 0 => 1

milestone: SSSD 1.13.2 => SSSD 1.13.1
resolution: => fixed
status: reopened => closed

Metadata Update from @tarvin:
- Issue assigned to preichl
- Issue set to the milestone: SSSD 1.13.1

7 years ago

SSSD is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in SSSD's github repository.

This issue has been cloned to Github and is available here:
- https://github.com/SSSD/sssd/issues/3603

If you want to receive further updates on the issue, please navigate to the github issue
and click on subscribe button.

Thank you for understanding. We apologize for all inconvenience.

Login to comment on this ticket.

Metadata