Note: This is a public test instance of Red Hat Bugzilla. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback at bugzilla.redhat.com.
Bug 1970923 - Nearly 1GB per day written to sssd_kcm.log
Summary: Nearly 1GB per day written to sssd_kcm.log
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: sssd
Version: 34
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Alexey Tikhonov
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard: sync-to-jira review
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2021-06-11 13:23 UTC by Jonathan Wakely
Modified: 2021-07-01 09:41 UTC (History)
11 users (show)

Fixed In Version: sssd-2.5.1-2.fc34
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2021-07-01 01:14:17 UTC
Type: Bug
Embargoed:

Attachments (Terms of Use)

Description Jonathan Wakely 2021-06-11 13:23:02 UTC 
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.
Comment 1 Jonathan Wakely 2021-06-11 13:44:33 UTC 
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.
Comment 2 Alexey Tikhonov 2021-06-14 09:00:48 UTC 
Thank you for the report. It will be fixed shortly.
Comment 3 Alexey Tikhonov 2021-06-15 13:56:14 UTC 
Upstream PR: https://github.com/SSSD/sssd/pull/5683
Comment 4 Alexey Tikhonov 2021-06-17 09:41:32 UTC 
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.
Comment 5 Fedora Update System 2021-06-24 11:16:50 UTC 
FEDORA-2021-77d6d22858 has been submitted as an update to Fedora 34. https://bodhi.fedoraproject.org/updates/FEDORA-2021-77d6d22858
Comment 6 Fedora Update System 2021-06-24 16:55:41 UTC 
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.
Comment 7 Fedora Update System 2021-07-01 01:14:17 UTC 
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.
Note You need to log in before you can comment on or make changes to this bug.