1551648 – goa-daemon produces high CPU usage

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 1551648 - goa-daemon produces high CPU usage

Summary: goa-daemon produces high CPU usage

Keywords:
Status:	CLOSED EOL
Alias:	None
Product:	Fedora
Classification:	Fedora
Component:	gnome-online-accounts
Sub Component:
Version:	30
Hardware:	Unspecified
OS:	Unspecified
Priority:	urgent
Severity:	urgent
Target Milestone:	---
Assignee:	Debarshi Ray
QA Contact:	Fedora Extras Quality Assurance
Docs Contact:
URL:
Whiteboard:
Duplicates (1):	1757057 (view as bug list)
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2018-03-05 15:57 UTC by Nathaniel McCallum
Modified:	2020-12-22 10:15 UTC (History)
CC List:	19 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2020-05-26 18:25:25 UTC
Type:	Bug
Embargoed:
Dependent Products:

Attachments	(Terms of Use)
strace log of goa-identity-service (750.94 KB, application/x-gzip) 2018-10-04 08:32 UTC, Tomas Popela	no flags	Details
pstacks of goa-identity-service (2.85 KB, application/x-gzip) 2018-10-04 10:31 UTC, Tomas Popela	no flags	Details
View All

Description Nathaniel McCallum 2018-03-05 15:57:23 UTC

I only have one GOA account: my Fedora kerberos account.

goa-daemon is using 13% CPU all the time; likewise, 25% in goa-identity-service.

It also produces:
 * 35% in sssd_kcm
 * 60% in sssd_secrets

Killing the goa processes (I think just goa-identity-service will do it) makes all of them drop to 0%.

Comment 1 Nathaniel McCallum 2018-03-05 15:58:23 UTC

Actually, GOA seems to register my SSSD configured Red Hat kerberos account too. So I have two kerberos accounts.

Comment 2 Nathaniel McCallum 2018-03-05 16:12:28 UTC

Also, this is a high priority because it appears that killing GOA just causes it to eventually get restarted. So I have no real way to stop the CPU eating.

Comment 3 Nathaniel McCallum 2018-03-05 16:30:25 UTC

Thread 5 (Thread 0x7f844a384700 (LWP 1859)):
#0  0x00007f845a4adbf9 in syscall () at /lib64/libc.so.6
#1  0x00007f845ad5d62a in g_cond_wait_until () at /lib64/libglib-2.0.so.0
#2  0x00007f845acec381 in g_async_queue_pop_intern_unlocked () at /lib64/libglib-2.0.so.0
#3  0x00007f845acec93c in g_async_queue_timeout_pop () at /lib64/libglib-2.0.so.0
#4  0x00007f845ad3ff2e in g_thread_pool_thread_proxy () at /lib64/libglib-2.0.so.0
#5  0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#6  0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#7  0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 4 (Thread 0x7f844ab85700 (LWP 1838)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f845ad17e99 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007f845ad18232 in g_main_loop_run () at /lib64/libglib-2.0.so.0
#3  0x00007f845b300b56 in gdbus_shared_thread_func () at /lib64/libgio-2.0.so.0
#4  0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#5  0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#6  0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 3 (Thread 0x7f844b386700 (LWP 1837)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f8459d78948 in __res_context_send () at /lib64/libresolv.so.2
#2  0x00007f8459d76221 in __res_context_query () at /lib64/libresolv.so.2
#3  0x00007f8459d76fdd in __res_context_search () at /lib64/libresolv.so.2
#4  0x00007f8459d775df in __res_search () at /lib64/libresolv.so.2
#5  0x00007f845dba1489 in krb5int_dns_init () at /lib64/libkrb5.so.3
#6  0x00007f845dba1b8b in k5_make_uri_query () at /lib64/libkrb5.so.3
#7  0x00007f845dba7c8e in locate_server () at /lib64/libkrb5.so.3
#8  0x00007f845dba8109 in k5_kdc_is_master () at /lib64/libkrb5.so.3
#9  0x00007f845dbab761 in krb5_sendto_kdc () at /lib64/libkrb5.so.3
#10 0x00007f845db77d5d in k5_init_creds_get () at /lib64/libkrb5.so.3
#11 0x00007f845db77ee4 in k5_get_init_creds () at /lib64/libkrb5.so.3
#12 0x00007f845db79fc3 in krb5_get_init_creds_password () at /lib64/libkrb5.so.3
#13 0x000055b603e192ad in goa_kerberos_identity_sign_in ()
#14 0x000055b603e1b1bf in on_job_scheduled ()
#15 0x00007f845b298df6 in io_job_thread () at /lib64/libgio-2.0.so.0
#16 0x00007f845b2bfe16 in g_task_thread_pool_thread () at /lib64/libgio-2.0.so.0
#17 0x00007f845ad3fe50 in g_thread_pool_thread_proxy () at /lib64/libglib-2.0.so.0
#18 0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#19 0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#20 0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 2 (Thread 0x7f844bb87700 (LWP 1836)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f845ad17e99 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007f845ad17fac in g_main_context_iteration () at /lib64/libglib-2.0.so.0
#3  0x00007f845ad17ff1 in glib_worker_main () at /lib64/libglib-2.0.so.0
#4  0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#5  0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#6  0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 1 (Thread 0x7f845e244f00 (LWP 1833)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f845ad17e99 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007f845ad18232 in g_main_loop_run () at /lib64/libglib-2.0.so.0
#3  0x000055b603e0d7cf in main ()

Comment 4 Nathaniel McCallum 2018-03-05 16:34:33 UTC

Forget that previous stack trace. CPU usage was low during it.

Comment 5 Nathaniel McCallum 2018-03-05 16:35:46 UTC

$ gstack $(pidof goa-identity-service)
Thread 5 (Thread 0x7f844a384700 (LWP 1859)):
#0  0x00007f845a4adbf9 in syscall () at /lib64/libc.so.6
#1  0x00007f845ad5d62a in g_cond_wait_until () at /lib64/libglib-2.0.so.0
#2  0x00007f845acec381 in g_async_queue_pop_intern_unlocked () at /lib64/libglib-2.0.so.0
#3  0x00007f845acec93c in g_async_queue_timeout_pop () at /lib64/libglib-2.0.so.0
#4  0x00007f845ad3ff2e in g_thread_pool_thread_proxy () at /lib64/libglib-2.0.so.0
#5  0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#6  0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#7  0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 4 (Thread 0x7f844ab85700 (LWP 1838)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f845ad17e99 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007f845ad18232 in g_main_loop_run () at /lib64/libglib-2.0.so.0
#3  0x00007f845b300b56 in gdbus_shared_thread_func () at /lib64/libgio-2.0.so.0
#4  0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#5  0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#6  0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 3 (Thread 0x7f844b386700 (LWP 1837)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f8459d78948 in __res_context_send () at /lib64/libresolv.so.2
#2  0x00007f8459d76221 in __res_context_query () at /lib64/libresolv.so.2
#3  0x00007f8459d76fdd in __res_context_search () at /lib64/libresolv.so.2
#4  0x00007f8459d775df in __res_search () at /lib64/libresolv.so.2
#5  0x00007f845dba1489 in krb5int_dns_init () at /lib64/libkrb5.so.3
#6  0x00007f845dba1b8b in k5_make_uri_query () at /lib64/libkrb5.so.3
#7  0x00007f845dba7c8e in locate_server () at /lib64/libkrb5.so.3
#8  0x00007f845dba8109 in k5_kdc_is_master () at /lib64/libkrb5.so.3
#9  0x00007f845dbab761 in krb5_sendto_kdc () at /lib64/libkrb5.so.3
#10 0x00007f845db77d5d in k5_init_creds_get () at /lib64/libkrb5.so.3
#11 0x00007f845db77ee4 in k5_get_init_creds () at /lib64/libkrb5.so.3
#12 0x00007f845db79fc3 in krb5_get_init_creds_password () at /lib64/libkrb5.so.3
#13 0x000055b603e192ad in goa_kerberos_identity_sign_in ()
#14 0x000055b603e1b1bf in on_job_scheduled ()
#15 0x00007f845b298df6 in io_job_thread () at /lib64/libgio-2.0.so.0
#16 0x00007f845b2bfe16 in g_task_thread_pool_thread () at /lib64/libgio-2.0.so.0
#17 0x00007f845ad3fe50 in g_thread_pool_thread_proxy () at /lib64/libglib-2.0.so.0
#18 0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#19 0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#20 0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 2 (Thread 0x7f844bb87700 (LWP 1836)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f845ad17e99 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007f845ad17fac in g_main_context_iteration () at /lib64/libglib-2.0.so.0
#3  0x00007f845ad17ff1 in glib_worker_main () at /lib64/libglib-2.0.so.0
#4  0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#5  0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#6  0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 1 (Thread 0x7f845e244f00 (LWP 1833)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f845ad17e99 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007f845ad18232 in g_main_loop_run () at /lib64/libglib-2.0.so.0
#3  0x000055b603e0d7cf in main ()



$ gstack $(pidof goa-identity-service)
Thread 5 (Thread 0x7f844a384700 (LWP 1859)):
#0  0x00007f845a4adbf9 in syscall () at /lib64/libc.so.6
#1  0x00007f845ad5d62a in g_cond_wait_until () at /lib64/libglib-2.0.so.0
#2  0x00007f845acec381 in g_async_queue_pop_intern_unlocked () at /lib64/libglib-2.0.so.0
#3  0x00007f845ad3fe24 in g_thread_pool_thread_proxy () at /lib64/libglib-2.0.so.0
#4  0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#5  0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#6  0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 4 (Thread 0x7f844ab85700 (LWP 1838)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f845ad17e99 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007f845ad18232 in g_main_loop_run () at /lib64/libglib-2.0.so.0
#3  0x00007f845b300b56 in gdbus_shared_thread_func () at /lib64/libgio-2.0.so.0
#4  0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#5  0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#6  0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 3 (Thread 0x7f844b386700 (LWP 1837)):
#0  0x00007f845a790678 in read () at /lib64/libpthread.so.0
#1  0x00007f845dba8345 in krb5_net_read () at /lib64/libkrb5.so.3
#2  0x00007f845db5d08b in kcmio_call () at /lib64/libkrb5.so.3
#3  0x00007f845db5d703 in cache_call.isra () at /lib64/libkrb5.so.3
#4  0x00007f845db5d8b7 in kcm_start_seq_get () at /lib64/libkrb5.so.3
#5  0x000055b603e1830d in goa_kerberos_identity_initable_init ()
#6  0x000055b603e199c7 in goa_kerberos_identity_new ()
#7  0x000055b603e1b601 in on_job_scheduled ()
#8  0x00007f845b298df6 in io_job_thread () at /lib64/libgio-2.0.so.0
#9  0x00007f845b2bfe16 in g_task_thread_pool_thread () at /lib64/libgio-2.0.so.0
#10 0x00007f845ad3fe50 in g_thread_pool_thread_proxy () at /lib64/libglib-2.0.so.0
#11 0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#12 0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#13 0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 2 (Thread 0x7f844bb87700 (LWP 1836)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f845ad17e99 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007f845ad17fac in g_main_context_iteration () at /lib64/libglib-2.0.so.0
#3  0x00007f845ad17ff1 in glib_worker_main () at /lib64/libglib-2.0.so.0
#4  0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#5  0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#6  0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 1 (Thread 0x7f845e244f00 (LWP 1833)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f845ad17e99 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007f845ad18232 in g_main_loop_run () at /lib64/libglib-2.0.so.0
#3  0x000055b603e0d7cf in main ()



$ gstack $(pidof goa-identity-service)
Thread 5 (Thread 0x7f844a384700 (LWP 1859)):
#0  0x00007f845a4adbf9 in syscall () at /lib64/libc.so.6
#1  0x00007f845ad5d62a in g_cond_wait_until () at /lib64/libglib-2.0.so.0
#2  0x00007f845acec381 in g_async_queue_pop_intern_unlocked () at /lib64/libglib-2.0.so.0
#3  0x00007f845ad3fe24 in g_thread_pool_thread_proxy () at /lib64/libglib-2.0.so.0
#4  0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#5  0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#6  0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 4 (Thread 0x7f844ab85700 (LWP 1838)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f845ad17e99 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007f845ad18232 in g_main_loop_run () at /lib64/libglib-2.0.so.0
#3  0x00007f845b300b56 in gdbus_shared_thread_func () at /lib64/libgio-2.0.so.0
#4  0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#5  0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#6  0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 3 (Thread 0x7f844b386700 (LWP 1837)):
#0  0x00007f845a790678 in read () at /lib64/libpthread.so.0
#1  0x00007f845dba8345 in krb5_net_read () at /lib64/libkrb5.so.3
#2  0x00007f845db5d08b in kcmio_call () at /lib64/libkrb5.so.3
#3  0x00007f845db5d703 in cache_call.isra () at /lib64/libkrb5.so.3
#4  0x00007f845db5db69 in kcm_get_princ () at /lib64/libkrb5.so.3
#5  0x000055b603e18135 in goa_kerberos_identity_initable_init ()
#6  0x000055b603e199c7 in goa_kerberos_identity_new ()
#7  0x000055b603e1b601 in on_job_scheduled ()
#8  0x00007f845b298df6 in io_job_thread () at /lib64/libgio-2.0.so.0
#9  0x00007f845b2bfe16 in g_task_thread_pool_thread () at /lib64/libgio-2.0.so.0
#10 0x00007f845ad3fe50 in g_thread_pool_thread_proxy () at /lib64/libglib-2.0.so.0
#11 0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#12 0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#13 0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 2 (Thread 0x7f844bb87700 (LWP 1836)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f845ad17e99 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007f845ad17fac in g_main_context_iteration () at /lib64/libglib-2.0.so.0
#3  0x00007f845ad17ff1 in glib_worker_main () at /lib64/libglib-2.0.so.0
#4  0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#5  0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#6  0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 1 (Thread 0x7f845e244f00 (LWP 1833)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f845ad17e99 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007f845ad18232 in g_main_loop_run () at /lib64/libglib-2.0.so.0
#3  0x000055b603e0d7cf in main ()



$ gstack $(pidof goa-identity-service)
Thread 5 (Thread 0x7f844a384700 (LWP 1859)):
#0  0x00007f845a4adbf9 in syscall () at /lib64/libc.so.6
#1  0x00007f845ad5d62a in g_cond_wait_until () at /lib64/libglib-2.0.so.0
#2  0x00007f845acec381 in g_async_queue_pop_intern_unlocked () at /lib64/libglib-2.0.so.0
#3  0x00007f845ad3fe24 in g_thread_pool_thread_proxy () at /lib64/libglib-2.0.so.0
#4  0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#5  0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#6  0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 4 (Thread 0x7f844ab85700 (LWP 1838)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f845ad17e99 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007f845ad18232 in g_main_loop_run () at /lib64/libglib-2.0.so.0
#3  0x00007f845b300b56 in gdbus_shared_thread_func () at /lib64/libgio-2.0.so.0
#4  0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#5  0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#6  0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 3 (Thread 0x7f844b386700 (LWP 1837)):
#0  0x00007f845a790678 in read () at /lib64/libpthread.so.0
#1  0x00007f845dba8345 in krb5_net_read () at /lib64/libkrb5.so.3
#2  0x00007f845db5d08b in kcmio_call () at /lib64/libkrb5.so.3
#3  0x00007f845db5d703 in cache_call.isra () at /lib64/libkrb5.so.3
#4  0x00007f845db5d853 in kcm_start_seq_get () at /lib64/libkrb5.so.3
#5  0x000055b603e1830d in goa_kerberos_identity_initable_init ()
#6  0x000055b603e199c7 in goa_kerberos_identity_new ()
#7  0x000055b603e1b601 in on_job_scheduled ()
#8  0x00007f845b298df6 in io_job_thread () at /lib64/libgio-2.0.so.0
#9  0x00007f845b2bfe16 in g_task_thread_pool_thread () at /lib64/libgio-2.0.so.0
#10 0x00007f845ad3fe50 in g_thread_pool_thread_proxy () at /lib64/libglib-2.0.so.0
#11 0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#12 0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#13 0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 2 (Thread 0x7f844bb87700 (LWP 1836)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f845ad17e99 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007f845ad17fac in g_main_context_iteration () at /lib64/libglib-2.0.so.0
#3  0x00007f845ad17ff1 in glib_worker_main () at /lib64/libglib-2.0.so.0
#4  0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#5  0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#6  0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 1 (Thread 0x7f845e244f00 (LWP 1833)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f845ad17e99 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007f845ad18232 in g_main_loop_run () at /lib64/libglib-2.0.so.0
#3  0x000055b603e0d7cf in main ()

Comment 6 Nathaniel McCallum 2018-03-05 16:37:09 UTC

$ gstack $(pidof goa-identity-service)
Thread 4 (Thread 0x7f844ab85700 (LWP 1838)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f845ad17e99 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007f845ad18232 in g_main_loop_run () at /lib64/libglib-2.0.so.0
#3  0x00007f845b300b56 in gdbus_shared_thread_func () at /lib64/libgio-2.0.so.0
#4  0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#5  0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#6  0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 3 (Thread 0x7f844b386700 (LWP 1837)):
#0  0x00007f845a790678 in read () at /lib64/libpthread.so.0
#1  0x00007f845dba8345 in krb5_net_read () at /lib64/libkrb5.so.3
#2  0x00007f845db5d08b in kcmio_call () at /lib64/libkrb5.so.3
#3  0x00007f845db5e29e in kcm_ptcursor_next () at /lib64/libkrb5.so.3
#4  0x00007f845db562fe in krb5_cccol_cursor_next () at /lib64/libkrb5.so.3
#5  0x000055b603e1b5dc in on_job_scheduled ()
#6  0x00007f845b298df6 in io_job_thread () at /lib64/libgio-2.0.so.0
#7  0x00007f845b2bfe16 in g_task_thread_pool_thread () at /lib64/libgio-2.0.so.0
#8  0x00007f845ad3fe50 in g_thread_pool_thread_proxy () at /lib64/libglib-2.0.so.0
#9  0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#10 0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#11 0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 2 (Thread 0x7f844bb87700 (LWP 1836)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f845ad17e99 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007f845ad17fac in g_main_context_iteration () at /lib64/libglib-2.0.so.0
#3  0x00007f845ad17ff1 in glib_worker_main () at /lib64/libglib-2.0.so.0
#4  0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#5  0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#6  0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 1 (Thread 0x7f845e244f00 (LWP 1833)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f845ad17e99 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007f845ad18232 in g_main_loop_run () at /lib64/libglib-2.0.so.0
#3  0x000055b603e0d7cf in main ()



$ gstack $(pidof goa-identity-service)
Thread 4 (Thread 0x7f844ab85700 (LWP 1838)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f845ad17e99 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007f845ad18232 in g_main_loop_run () at /lib64/libglib-2.0.so.0
#3  0x00007f845b300b56 in gdbus_shared_thread_func () at /lib64/libgio-2.0.so.0
#4  0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#5  0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#6  0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 3 (Thread 0x7f844b386700 (LWP 1837)):
#0  0x00007f845a790678 in read () at /lib64/libpthread.so.0
#1  0x00007f845dba8345 in krb5_net_read () at /lib64/libkrb5.so.3
#2  0x00007f845db5d08b in kcmio_call () at /lib64/libkrb5.so.3
#3  0x00007f845db5e29e in kcm_ptcursor_next () at /lib64/libkrb5.so.3
#4  0x00007f845db562fe in krb5_cccol_cursor_next () at /lib64/libkrb5.so.3
#5  0x000055b603e1b5dc in on_job_scheduled ()
#6  0x00007f845b298df6 in io_job_thread () at /lib64/libgio-2.0.so.0
#7  0x00007f845b2bfe16 in g_task_thread_pool_thread () at /lib64/libgio-2.0.so.0
#8  0x00007f845ad3fe50 in g_thread_pool_thread_proxy () at /lib64/libglib-2.0.so.0
#9  0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#10 0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#11 0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 2 (Thread 0x7f844bb87700 (LWP 1836)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f845ad17e99 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007f845ad17fac in g_main_context_iteration () at /lib64/libglib-2.0.so.0
#3  0x00007f845ad17ff1 in glib_worker_main () at /lib64/libglib-2.0.so.0
#4  0x00007f845ad3f486 in g_thread_proxy () at /lib64/libglib-2.0.so.0
#5  0x00007f845a78661b in start_thread () at /lib64/libpthread.so.0
#6  0x00007f845a4b398f in clone () at /lib64/libc.so.6
Thread 1 (Thread 0x7f845e244f00 (LWP 1833)):
#0  0x00007f845a4a73db in poll () at /lib64/libc.so.6
#1  0x00007f845ad17e99 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#2  0x00007f845ad18232 in g_main_loop_run () at /lib64/libglib-2.0.so.0
#3  0x000055b603e0d7cf in main ()

Comment 7 Nathaniel McCallum 2018-03-05 16:37:40 UTC

The easiest way to trigger it appears to be to go offline.

Comment 8 Robbie Harwood 2018-03-05 16:42:27 UTC

Does it occur when KCM is not in use?

Comment 9 Nathaniel McCallum 2018-03-05 16:54:00 UTC

No. This seems to be KCM only.

Comment 10 Nathaniel McCallum 2018-03-05 16:54:46 UTC

Note that KCM is the default configuration. Also, this is on a clean install. So I expect other users to hit this.

Comment 11 Robbie Harwood 2018-03-05 17:13:36 UTC

KCM folks, could you take a look?

Comment 12 Fabiano Fidêncio 2018-03-05 17:26:05 UTC

Just for the record (it's from the top of my head and I didn't do any investigation on this bug report **yet**) ... this issue may be related to:
- https://pagure.io/SSSD/sssd/issue/3568
- https://bugzilla.redhat.com/show_bug.cgi?id=1511945

Comment 13 Debarshi Ray 2018-03-05 17:58:13 UTC

(In reply to Fabiano Fidêncio from comment #12)
> Just for the record (it's from the top of my head and I didn't do any
> investigation on this bug report **yet**) ... this issue may be related to:
> - https://pagure.io/SSSD/sssd/issue/3568
> - https://bugzilla.redhat.com/show_bug.cgi?id=1511945

While it would be nice to have a notification mechanism for KCM caches, it shouldn't cause any noticeable CPU load. It might lead to higher power consumption, though, because in the absence of notification, GOA polls the credentials cache at 5s intervals.

Such polling was already happening with KEYRING caches.

Comment 14 Nathaniel McCallum 2018-03-12 15:03:41 UTC

Fabiano, any status update? This affects our default installation config and is, IMHO, a high priority.

Comment 15 Fabiano Fidêncio 2018-03-12 15:07:58 UTC

(In reply to Nathaniel McCallum from comment #14)
> Fabiano, any status update? This affects our default installation config and
> is, IMHO, a high priority.

No updates, Nathaniel. I still didn't have any time to work on this yet.

I'll try to take a look later Today/Tomorrow, sorry for the delay.

Comment 16 Fabiano Fidêncio 2018-03-12 20:00:24 UTC

Nathaniel,

May I ask you to provide sssd_secrets.log and sssd_kcm.log files?
In order to get those (with some useful info), please do:
- In case you don't have a /etc/sssd/sssd.conf file, create one. The file must be owned by root:root and has to have permissions as 0600;
- Add to the file:
```
[kcm]
debug_level = 10

[secrets]
debug_level = 10
```
- Restart SSSD, kill both sssd_kcm and sssd_secrets processes.

Comment 18 Nathaniel McCallum 2018-03-14 18:54:03 UTC

From what I can see, the logs just show a deluge of incoming requests that are handled correctly by sssd-kcm. The logs for sssd-secrets shows the same thing. I think the problem is in goa.

Comment 19 Fabiano Fidêncio 2018-03-14 18:58:59 UTC

Okay, Rishi, may you give us some help here?

Comment 20 Debarshi Ray 2018-03-16 14:31:55 UTC

Sadly, KCM just doesn't work for me on Fedora 27 (probably bug 1494843). :/

I have now freed up some time to debug that. Once I figure out how to get a stable KCM set up I can debug this.

Comment 21 Debarshi Ray 2018-03-19 17:20:45 UTC

(In reply to Debarshi Ray from comment #20)
> Sadly, KCM just doesn't work for me on Fedora 27 (probably bug 1494843). :/

For the sake of background, krb5_cc_default was not working for me on Fedora 27. libkrb5 would write to sssd_kcm over the socket, but throw a KRB5_FCC_INTERNAL due to an unexpected response from the other side.

> I have now freed up some time to debug that. Once I figure out how to get a
> stable KCM set up I can debug this.

I debugged SSSD this with Fabiano today.

Stopping and starting the sssd, sssd-kcm and sssd-secrets systemd sockets somehow got things running for me. We observed that things were working if the processes were spawned without socket activation, but broke when we relied on the sockets. I have no idea how the sockets could have been broken like that, or how that breakage managed to survive multiple reboots over many months.

But seems like I have a working KCM setup on my laptop now!

Comment 22 Debarshi Ray 2018-03-20 17:58:44 UTC

Anyway, back to the original bug reported by Nathaniel here.

I wonder if "GOA seems to register my SSSD configured Red Hat kerberos account" (comment 1) is significant here. I assume that it means Nathaniel is logged in through GDM via Kerberos?

I tried toggling my network off/on while being logged in through a local user, with two Kerberos accounts set up through GOA. I saw goa-daemon and goa-identity-service rise through the ratings in top(1) right after the network was restored, but they eventually dropped off after a few seconds.

Comment 23 Nathaniel McCallum 2018-03-20 21:24:55 UTC

I upgraded to F28 yesterday, and the problem seems to be gone. But it is still disconcerting that I saw it on a fresh F27 install.

Comment 24 Nathaniel McCallum 2018-03-26 16:07:17 UTC

Nevermind, the issue is definitely here on F28.

Comment 25 Nathaniel McCallum 2018-04-10 14:47:23 UTC

I'm moving this to GOA since sssd seems to be responding correctly to *many* requests from GOA.

Comment 26 Till Maas 2018-09-28 11:42:01 UTC

Nathaniel, did you maybe find a better workaround than just killing the process repeatedly? It is very annoying having it increase the fan to full speed again and again...

Comment 27 Jakub Hrozek 2018-10-01 10:31:27 UTC

I was pointed to another instance of this issue by tpopela

Looking at the sssd_kcm.log, there is almost 70.000 requests to sssd-kcm in less than 2 minutes. The requests seem to be "klist-like" in the sense that the requests are more or less all read-only (get-principal for ccache, get ccache UUID list, get cred UUID).

But I'm stumped about why doees goa need all these data so often? What is exactly the thing that goa is trying to do? Does it shell out to klist or does it call some libkrb5 functions on its own?

Comment 28 Debarshi Ray 2018-10-03 17:01:20 UTC

(In reply to Jakub Hrozek from comment #27)
> Looking at the sssd_kcm.log, there is almost 70.000 requests to sssd-kcm in
> less than 2 minutes. The requests seem to be "klist-like" in the sense that
> the requests are more or less all read-only (get-principal for ccache, get
> ccache UUID list, get cred UUID).
> 
> But I'm stumped about why doees goa need all these data so often? What is
> exactly the thing that goa is trying to do? Does it shell out to klist or
> does it call some libkrb5 functions on its own?

If the credentials cache doesn't support any notification mechanism, goa-identity-service polls the credentials cache every 5 seconds using libkrb5 API to stay in sync with any changes done using the krb5 CLI (ie., kinit, kdestroy, etc.).

With DIR caches, we could use inotify to track changes to the credentials cache, but with KEYRING and KCM we are out luck. See these feature requests:
  https://pagure.io/SSSD/sssd/issue/3568
  https://bugzilla.redhat.com/show_bug.cgi?id=1511945

Anyway, 70K requests in 2 minutes is still too much. That's close to 600 requests per second. I believe that this is a symptom of either standalone KCM bugs or bugs triggered by GOA's (incorrect?) use of the libkrb5 API.

Generally speaking, the KCM caches have been generally buggy - there are various bug reports scattered across bugzilla about that. Also, see some of my previous comments here. Unbreaking the sockets (comment 21) got me past the initial hurdle, but various problems remained.

Some examples off the top of my head:
(a) The list of principals in klist would grow over time
(b) A kdestroy-ed principal would keep coming back

It's been a while, so I might be misremembering some details.

I believe Fabiano made some headway, but I don't think we managed to address everything.

Since then, it had gotten to a point where I just couldn't use Kerberos anymore, and debugging across libkrb5 and SSSD without knowing their internals inside out turned out to be too much of a time sink. :( So I switched back to KEYRING caches and things have been back to normal since then.

As far as the GOA code goes, it has a very small amount of cache-specific code. It's limited to:
(a) https://gitlab.gnome.org/GNOME/gnome-online-accounts/blob/master/src/goaidentity/goakerberosidentitymanager.c#L761 : Checks if the cache can handle multiple identies
(b) https://gitlab.gnome.org/GNOME/gnome-online-accounts/blob/master/src/goaidentity/goakerberosidentitymanager.c#L1363 : Checks if the cache has a notification mechanism or needs to be polled

So, from just reading the code, I expect KCM caches to use the same code paths as KEYRING caches. Except, it runs into weird issues like this one.

I could try re-enabling KCM and see what happens, but I am afraid it won't be much help if I can't get some basic functionality out of it. I wish somebody with an overall understanding of libkrb5 and SSSD would pick up where Fabiano left, and help debug it.

Comment 29 Debarshi Ray 2018-10-03 17:11:05 UTC

By the way, this might be of some help:
https://wiki.gnome.org/Projects/GnomeOnlineAccounts/Debugging

Comment 30 Ray Strode [halfline] 2018-10-03 17:12:20 UTC

can someone seeing this problem post an strace of goa-identity-service ?

Comment 31 Tomas Popela 2018-10-04 08:32:21 UTC

Created attachment 1490408 [details]
strace log of goa-identity-service

This is a strace log of goa-identity-service, when I left the strace attached for ~2 minutes.

Comment 32 Jakub Hrozek 2018-10-04 09:32:52 UTC

Any chance you could do a bunch of pstacks as well?

Comment 33 Tomas Popela 2018-10-04 10:31:51 UTC

Created attachment 1490454 [details]
pstacks of goa-identity-service

Comment 34 Alberto Ruiz 2018-11-02 16:48:52 UTC

I've filed this bug to solve the performance problem until the sssd folks implement kcm cache changes notification https://bugzilla.redhat.com/show_bug.cgi?id=1645624

Comment 35 Simo Sorce 2018-11-02 20:30:52 UTC

Debarshi what happen if sign_in_identiy fails in odd ways ?
Is it possible GOA goes into a loop in the kerberos case trying to sign you in a gazillion times ?
I ask because I see goa uses the krb5_cc_new_unique() call which we are seeing an issue with under openssh as well when used in certain ways.

We think it is a bug in libkrb5, but errors can always ahppen, so if GOA ends up pounding on ccaches in case of error it would be something to fix also in GOA.

Comment 36 Debarshi Ray 2018-11-06 13:48:43 UTC

GOA uses the same code paths for KCM and KEYRING caches, but I won't be surprised if GOA's use of libkrb5 isn't 100% accurate which manifests as weird misbehaviour with KCM caches.

Thanks for the hint about sign_in_identity!

I learnt from Fabiano that KCM has gotten a lot better over time, so I will give it a shot again and see what I can come up with.

Comment 37 Gwyn Ciesla 2018-11-07 17:57:47 UTC

I'm hitting this on my laptop. I use krb5/sssd for auth but local accounts for identity. I'm on f29. Let me know if I can provide more info.

Comment 38 Ben Cotton 2019-05-02 19:17:37 UTC

This message is a reminder that Fedora 28 is nearing its end of life.
On 2019-May-28 Fedora will stop maintaining and issuing updates for
Fedora 28. It is Fedora's policy to close all bug reports from releases
that are no longer maintained. At that time this bug will be closed as
EOL if it remains open with a Fedora 'version' of '28'.

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 28 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 39 Ben Cotton 2019-05-02 20:21:38 UTC

This message is a reminder that Fedora 28 is nearing its end of life.
On 2019-May-28 Fedora will stop maintaining and issuing updates for
Fedora 28. It is Fedora's policy to close all bug reports from releases
that are no longer maintained. At that time this bug will be closed as
EOL if it remains open with a Fedora 'version' of '28'.

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 28 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 40 Debarshi Ray 2019-12-04 19:31:59 UTC

*** Bug 1757057 has been marked as a duplicate of this bug. ***

Comment 41 Ben Cotton 2020-04-30 20:22:07 UTC

This message is a reminder that Fedora 30 is nearing its end of life.
Fedora will stop maintaining and issuing updates for Fedora 30 on 2020-05-26.
It is Fedora's policy to close all bug reports from releases that are no longer
maintained. At that time this bug will be closed as EOL if it remains open with a
Fedora 'version' of '30'.

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 30 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 42 Ben Cotton 2020-05-26 18:25:25 UTC

Fedora 30 changed to end-of-life (EOL) status on 2020-05-26. Fedora 30 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.

Comment 43 Arjen Heidinga 2020-12-22 10:15:53 UTC

This still is an issue on Fedora33, fresh install..

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