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

Summary:	Nearly 1GB per day written to sssd_kcm.log
Product:	[Fedora] Fedora	Reporter:	Jonathan Wakely <jwakely>
Component:	sssd	Assignee:	Alexey Tikhonov <atikhono>
Status:	CLOSED ERRATA	QA Contact:	Fedora Extras Quality Assurance <extras-qa>
Severity:	unspecified	Docs Contact:
Priority:	unspecified
Version:	34	CC:	abokovoy, amigadave, atikhono, jhrozek, lslebodn, luk.claes, mzidek, pbrezina, sbose, ssorce, sssd-maintainers
Target Milestone:	---	Keywords:	Triaged
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:	sync-to-jira review
Fixed In Version:	sssd-2.5.1-2.fc34	Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2021-07-01 01:14:17 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

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.