[Bug 1970923] New: Nearly 1GB per day written to sssd_kcm.log

https://bugzilla.redhat.com/show_bug.cgi?id=1970923

Bug ID: 1970923
           Summary: Nearly 1GB per day written to sssd_kcm.log
           Product: Fedora
           Version: 34
            Status: NEW
         Component: sssd
          Assignee: [e-mail]
          Reporter: [e-mail]
        QA Contact: [e-mail]
                CC: [e-mail], [e-mail],
                    [e-mail], [e-mail],
                    [e-mail], [e-mail],
                    [e-mail], [e-mail],
                    [e-mail],
                    [e-mail]
  Target Milestone: ---
    Classification: Fedora

Description of problem:

My disk filled up due to sssd log spam.

Version-Release number of selected component (if applicable):

sssd-kcm-2.5.0-2.fc34.x86_64
gnome-online-accounts-3.40.0-1.fc34.x86_64

Every 5 seconds I get the same 336 lines of debug dump written to
/var/log/sssd/sssd_kcm.log

Each entry looks like:
:

(2021-06-11 14:15:25): [kcm] [sec_get] (0x0040): Cannot retrieve the secret
[2]: No such file or directory
********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING
BACKTRACE:
   *  (2021-06-11 14:15:20): [kcm] [ccdb_secdb_list_send] (0x2000): Listing all
ccaches 
   *  (2021-06-11 14:15:20): [kcm] [sss_sec_map_path] (0x1000): Mapping prefix
/kcm/
   *  (2021-06-11 14:15:20): [kcm] [kcm_map_url_to_path] (0x1000):
User-specific KCM path is [/kcm/persistent/1000/ccache/]
[...]
   *  (2021-06-11 14:15:20): [kcm] [kcm_send] (0x2000): All data sent!
   *  (2021-06-11 14:15:20): [kcm] [kcm_recv] (0x4000): Client closed
connection.
   *  (2021-06-11 14:15:20): [kcm] [client_close_fn] (0x2000): Terminated
client [0x55c7aa910ba0][14]
   *  (2021-06-11 14:15:25): [kcm] [get_client_cred] (0x4000): Client
[0x55c7abd1eef0][14] creds: euid[1000] egid[1003] pid[3730]
cmd_line['/usr/libexec/goa-identity-service'].
   *  (2021-06-11 14:15:25): [kcm] [setup_client_idle_timer] (0x4000): Idle
timer re-set for client [0x55c7abd1eef0][14]
   *  (2021-06-11 14:15:25): [kcm] [accept_fd_handler] (0x0400): Client
[0x55c7abd1eef0][14] connected!
[...]
   *  (2021-06-11 14:15:25): [kcm] [secdb_dfl_url_req] (0x2000): Created
request for URL /kcm/persistent/1000/default
   *  (2021-06-11 14:15:25): [kcm] [sss_sec_get] (0x0400): Retrieving a secret
from [persistent/1000/default]
   *  (2021-06-11 14:15:25): [kcm] [sss_sec_get] (0x2000): Searching for
[(|(type=simple)(type=binary))] at [cn=default,cn=1000,cn=persistent,cn=kcm]
with scope=base
   *  (2021-06-11 14:15:25): [kcm] [sss_sec_get] (0x1000): No secret found
   *  (2021-06-11 14:15:25): [kcm] [sec_get] (0x0040): Cannot retrieve the
secret [2]: No such file or directory
********************** BACKTRACE DUMP ENDS HERE
*********************************

I have no idea what this is telling me, but I need it to stop filling my disk.

What is the point in this verbose logging being done AGAIN AND AGAIN every 5s
if nobody is looking at it? This can't be useful.

[Bug 1970923] Nearly 1GB per day written to sssd_kcm.log

https://bugzilla.redhat.com/show_bug.cgi?id=1970923

--- Comment #1 from Jonathan Wakely  ---
I've just done 'dnf erase gnome-online-accounts' and rebooted, and the spam has
stopped being logged every 5s.

I still get dozens of lines of errors when I run 'klist' or 'kinit'.

It seems like this _might_ be something worth logging:
(2021-06-11 14:38:05): [kcm] [sec_get] (0x0040): Cannot retrieve the secret
[2]: No such file or directory

But it doesn't tell me what file it was actually looking for so is not
actionable, even if it is an error I could do something about.

And the backtrace dump that follows it is useless to me, and causes real issues
by filling my disk.

Please think more carefully about whether dumping all this garbage onto a
user's disk by default is actually useful to the end user.

[Bug 1970923] Nearly 1GB per day written to sssd_kcm.log

https://bugzilla.redhat.com/show_bug.cgi?id=1970923

Alexey Tikhonov  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
           Keywords|                            |Triaged
           Assignee|[e-mail] |[e-mail]
                   |raproject.org               |

--- Comment #2 from Alexey Tikhonov  ---
Thank you for the report. It will be fixed shortly.

[Bug 1970923] Nearly 1GB per day written to sssd_kcm.log

https://bugzilla.redhat.com/show_bug.cgi?id=1970923

Alexey Tikhonov  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |ASSIGNED
         Whiteboard|                            |sync-to-jira review

--- Comment #3 from Alexey Tikhonov  ---
Upstream PR: https://github.com/SSSD/sssd/pull/5683

[Bug 1970923] Nearly 1GB per day written to sssd_kcm.log

https://bugzilla.redhat.com/show_bug.cgi?id=1970923

Alexey Tikhonov  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|ASSIGNED                    |POST

--- Comment #4 from Alexey Tikhonov  ---
Pushed PR: https://github.com/SSSD/sssd/pull/5683

* `master`
    * 5ead448c859860a4eb57a529a5b85eca1815e73a - KCM: reduce log severity in
sec_get() in case entry not found
    * 32a1fbfb262ea9657fa268f7ce09ef6e942b0829 - KCM: use SSSDBG_MINOR_FAILURE
for ERR_KCM_OP_NOT_IMPLEMENTED
    * 9cfcbe6edc451d7187e0a89a6a5bd7125a10f1c8 - secrets: reduce log severity
in local_db_create() in case entry already exists since this is expected during
normal oprations.
    * 75a5e1c7a80eaa921cb0b0531d685c9c7ed12127 - krb5_child: reduce log
severity in sss_send_pac() in case PAC responder isn't running.

[Bug 1970923] Nearly 1GB per day written to sssd_kcm.log

https://bugzilla.redhat.com/show_bug.cgi?id=1970923

Fedora Update System  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|POST                        |MODIFIED

--- Comment #5 from Fedora Update System  ---
FEDORA-2021-77d6d22858 has been submitted as an update to Fedora 34.
https://bodhi.fedoraproject.org/updates/FEDORA-2021-77d6d22858

[Bug 1970923] Nearly 1GB per day written to sssd_kcm.log

https://bugzilla.redhat.com/show_bug.cgi?id=1970923

Fedora Update System  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|MODIFIED                    |ON_QA

--- Comment #6 from Fedora Update System  ---
FEDORA-2021-77d6d22858 has been pushed to the Fedora 34 testing repository.
Soon you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing
--advisory=FEDORA-2021-77d6d22858`
You can provide feedback for this update here:
https://bodhi.fedoraproject.org/updates/FEDORA-2021-77d6d22858

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information
on how to test updates.

[Bug 1970923] Nearly 1GB per day written to sssd_kcm.log

https://bugzilla.redhat.com/show_bug.cgi?id=1970923

Fedora Update System  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|ON_QA                       |CLOSED
   Fixed In Version|                            |sssd-2.5.1-2.fc34
         Resolution|---                         |ERRATA
        Last Closed|                            |2021-07-01 01:14:17

--- Comment #7 from Fedora Update System  ---
FEDORA-2021-77d6d22858 has been pushed to the Fedora 34 stable repository.
If problem still persists, please make note of it in this bug report.