Bug 1005619 - goa-daemon consuming 100% CPU (Kerberos authentication in use)
goa-daemon consuming 100% CPU (Kerberos authentication in use)
Status: CLOSED ERRATA
Product: Fedora
Classification: Fedora
Component: gnome-online-accounts (Show other bugs)
19
All Linux
high Severity high
: ---
: ---
Assigned To: Debarshi Ray
Fedora Extras Quality Assurance
:
: 950078 1006267 1010529 (view as bug list)
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2013-09-08 22:01 EDT by Bojan Smojver
Modified: 2014-04-10 05:24 EDT (History)
45 users (show)

See Also:
Fixed In Version: gnome-online-accounts-3.8.3-3.fc19
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2013-09-29 20:37:13 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)


External Trackers
Tracker ID Priority Status Summary Last Updated
GNOME Desktop 705395 None None None Never

  None (edit)
Description Bojan Smojver 2013-09-08 22:01:24 EDT
Description of problem:
The goa-daemon is using 100% of the CPU. I have two machines that both use Kerberos authentication (one against Fedora MIT krb5, the other against AD - both via sssd) and they are experiencing the same problem. Different architectures too: x86_64 and i686.

Version-Release number of selected component (if applicable):
gnome-online-accounts-3.8.3-1.fc19.x86_64

How reproducible:
Always.

Steps to Reproduce:
1. Login to Gnome.
2. Run top.
3. goa-daemon using 100% of the CPU.

Actual results:
Keeps using all of one CPU.

Expected results:
Did not notice this problem ever before.

Additional info:
Quick strace gives this (endlessly):
----------------------------
[pid  1303] poll([{fd=4, events=POLLIN}, {fd=12, events=POLLIN}, {fd=13, events=POLLIN}, {fd=9, events=POLLIN}, {fd=19, events=POLLIN}, {fd=11, events=POLLIN}], 6, 0) = 1 ([{fd=4, revents=POLLIN}])
[pid  1303] read(4, "\4\0\0\0\0\0\0\0", 16) = 8
[pid  1303] write(4, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  1303] write(4, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  1303] write(4, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  1303] poll([{fd=11, events=POLLIN}], 1, 0) = 0 (Timeout)
[pid  1303] open("/etc/localtime", O_RDONLY) = 15
[pid  1303] fstat(15, {st_mode=S_IFREG|0644, st_size=2183, ...}) = 0
[pid  1303] mmap(NULL, 2183, PROT_READ, MAP_PRIVATE, 15, 0) = 0x7f307462f000
[pid  1303] close(15)                   = 0
[pid  1303] munmap(0x7f307462f000, 2183) = 0
[pid  1303] write(4, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  1303] poll([{fd=4, events=POLLIN}, {fd=12, events=POLLIN}, {fd=13, events=POLLIN}, {fd=9, events=POLLIN}, {fd=19, events=POLLIN}, {fd=11, events=POLLIN}], 6, 0) = 1 ([{fd=4, revents=POLLIN}])
[pid  1303] read(4, "\4\0\0\0\0\0\0\0", 16) = 8
[pid  1303] write(4, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  1303] write(4, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  1303] write(4, "\1\0\0\0\0\0\0\0", 8) = 8
[pid  1303] poll([{fd=11, events=POLLIN}], 1, 0) = 0 (Timeout)
[pid  1303] open("/etc/localtime", O_RDONLY) = 15
[pid  1303] fstat(15, {st_mode=S_IFREG|0644, st_size=2183, ...}) = 0
[pid  1303] mmap(NULL, 2183, PROT_READ, MAP_PRIVATE, 15, 0) = 0x7f307462f000
[pid  1303] close(15)                   = 0
[pid  1303] munmap(0x7f307462f000, 2183) = 0
[pid  1303] write(4, "\1\0\0\0\0\0\0\0", 8) = 8
----------------------------
Comment 1 Bojan Smojver 2013-09-08 22:33:05 EDT
Here is a random backtrace as well:
----------------------
(gdb) t a a bt

Thread 4 (Thread 0x7f2c125ff700 (LWP 2910)):
#0  0x0000003568aeb76d in poll () at ../sysdeps/unix/syscall-template.S:81
#1  0x000000356ae480f4 in g_main_context_poll (priority=2147483647, n_fds=1, 
    fds=0x7f2c040008c0, timeout=-1, context=0x846e00) at gmain.c:3995
#2  g_main_context_iterate (context=context@entry=0x846e00, 
    block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>)
    at gmain.c:3696
#3  0x000000356ae481fc in g_main_context_iteration (context=0x846e00, 
    may_block=may_block@entry=1) at gmain.c:3762
#4  0x000000356ae48249 in glib_worker_main (data=<optimized out>)
    at gmain.c:5427
#5  0x000000356ae6c185 in g_thread_proxy (data=0x847000) at gthread.c:798
#6  0x0000003568e07c53 in start_thread (arg=0x7f2c125ff700)
    at pthread_create.c:308
#7  0x0000003568af5d3d in clone ()
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 3 (Thread 0x7f2c11dfe700 (LWP 2911)):
#0  pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1  0x000000356ae874c7 in g_cond_wait (cond=cond@entry=0x85fe68, 
    mutex=mutex@entry=0x85fe60) at gthread-posix.c:750
---Type <return> to continue, or q <return> to quit---
#2  0x000000356ae1eb0b in g_async_queue_pop_intern_unlocked (
    queue=queue@entry=0x85fe60, wait=wait@entry=1, end_time=end_time@entry=-1)
    at gasyncqueue.c:421
#3  0x000000356ae1ef07 in g_async_queue_pop (queue=queue@entry=0x85fe60)
    at gasyncqueue.c:455
#4  0x00000000004117e8 in on_job_scheduled (job=0x84bb00, 
    cancellable=0x7f2c0c0022a0, self=<optimized out>)
    at goakerberosidentitymanager.c:968
#5  0x000000356c259806 in io_job_thread (task=<optimized out>, 
    source_object=<optimized out>, task_data=0x84bb00, 
    cancellable=<optimized out>) at gioscheduler.c:89
#6  0x000000356c2780a5 in g_task_thread_pool_thread (thread_data=0x84eaa0, 
    pool_data=<optimized out>) at gtask.c:1242
#7  0x000000356ae6cb46 in g_thread_pool_thread_proxy (data=<optimized out>)
    at gthreadpool.c:309
#8  0x000000356ae6c185 in g_thread_proxy (data=0x847190) at gthread.c:798
#9  0x0000003568e07c53 in start_thread (arg=0x7f2c11dfe700)
    at pthread_create.c:308
#10 0x0000003568af5d3d in clone ()
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 2 (Thread 0x7f2c115fd700 (LWP 2912)):
#0  0x0000003568aeb76d in poll () at ../sysdeps/unix/syscall-template.S:81
---Type <return> to continue, or q <return> to quit---
#1  0x000000356ae480f4 in g_main_context_poll (priority=2147483647, n_fds=3, 
    fds=0x7f2c080010c0, timeout=-1, context=0x7f2c0c00d9a0) at gmain.c:3995
#2  g_main_context_iterate (context=0x7f2c0c00d9a0, block=block@entry=1, 
    dispatch=dispatch@entry=1, self=<optimized out>) at gmain.c:3696
#3  0x000000356ae4855a in g_main_loop_run (loop=0x7f2c0c00d930) at gmain.c:3895
#4  0x000000356c2c6d66 in gdbus_shared_thread_func (user_data=0x7f2c0c00d970)
    at gdbusprivate.c:278
#5  0x000000356ae6c185 in g_thread_proxy (data=0x7f2c0c004b70) at gthread.c:798
#6  0x0000003568e07c53 in start_thread (arg=0x7f2c115fd700)
    at pthread_create.c:308
#7  0x0000003568af5d3d in clone ()
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 1 (Thread 0x7f2c12600a40 (LWP 2909)):
#0  0x0000003568a7d6a7 in _int_malloc (av=0x3568dba780 <main_arena>, bytes=208)
    at malloc.c:3325
#1  0x0000003568a8005c in __GI___libc_malloc (bytes=208) at malloc.c:2863
#2  0x0000003568a2b80f in __gconv_lookup_cache (
    toset=toset@entry=0x7fff07e67720 "UTF-8//", 
    fromset=fromset@entry=0x7fff07e67700 "ANSI_X3.4-1968//", 
    handle=handle@entry=0x7fff07e67690, nsteps=nsteps@entry=0x7fff07e676a0, 
    flags=flags@entry=0) at gconv_cache.c:371
#3  0x0000003568a23e6e in __gconv_find_transform (
---Type <return> to continue, or q <return> to quit---
    toset=toset@entry=0x7fff07e67720 "UTF-8//", 
    fromset=fromset@entry=0x7fff07e67700 "ANSI_X3.4-1968//", 
    handle=handle@entry=0x7fff07e67690, nsteps=nsteps@entry=0x7fff07e676a0, 
    flags=flags@entry=0) at gconv_db.c:721
#4  0x0000003568a228af in __gconv_open (
    toset=toset@entry=0x7fff07e67720 "UTF-8//", 
    fromset=fromset@entry=0x7fff07e67700 "ANSI_X3.4-1968//", 
    handle=handle@entry=0x7fff07e67740, flags=flags@entry=0)
    at gconv_open.c:173
#5  0x0000003568a22442 in iconv_open (tocode=0x7fff07e67720 "UTF-8//", 
    tocode@entry=0x356aeb5437 "UTF-8", 
    fromcode=0x7fff07e67700 "ANSI_X3.4-1968//", 
    fromcode@entry=0x845e70 "ANSI_X3.4-1968") at iconv_open.c:71
#6  0x000000356ae2bab9 in try_conversion (
    to_codeset=to_codeset@entry=0x356aeb5437 "UTF-8", 
    from_codeset=from_codeset@entry=0x845e70 "ANSI_X3.4-1968", 
    cd=cd@entry=0x7fff07e677a8) at gconvert.c:204
#7  0x000000356ae2c04f in g_iconv_open (
    to_codeset=to_codeset@entry=0x356aeb5437 "UTF-8", 
    from_codeset=from_codeset@entry=0x845e70 "ANSI_X3.4-1968")
    at gconvert.c:256
#8  0x000000356ae2c0e6 in open_converter (to_codeset=0x356aeb5437 "UTF-8", 
    from_codeset=0x845e70 "ANSI_X3.4-1968", error=0x0) at gconvert.c:633
---Type <return> to continue, or q <return> to quit---
#9  0x000000356ae2c4f8 in g_convert (
    str=str@entry=0x3568b7e020 "Resource temporarily unavailable", 
    len=len@entry=-1, to_codeset=to_codeset@entry=0x356aeb5437 "UTF-8", 
    from_codeset=<optimized out>, bytes_read=bytes_read@entry=0x0, 
    bytes_written=bytes_written@entry=0x0, error=error@entry=0x0)
    at gconvert.c:872
#10 0x000000356ae2cbaa in g_locale_to_utf8 (
    opsysstring=opsysstring@entry=0x3568b7e020 "Resource temporarily unavailable", len=len@entry=-1, bytes_read=bytes_read@entry=0x0, 
    bytes_written=bytes_written@entry=0x0, error=error@entry=0x0)
    at gconvert.c:1216
#11 0x000000356ae651b6 in g_strerror (errnum=errnum@entry=11)
    at gstrfuncs.c:1246
#12 0x000000356c2649c2 in g_pollable_input_stream_default_read_nonblocking (
    stream=0x7f2c0c011c50, buffer=0x7fff07e67958, count=8, error=0x0)
    at gpollableinputstream.c:152
#13 0x0000000000413bdf in on_timer_source_ready (stream=0x7f2c0c011c50, 
    self=0x88ef40) at goaalarm.c:379
#14 0x000000356ae47e06 in g_main_dispatch (context=0x845e90) at gmain.c:3054
#15 g_main_context_dispatch (context=context@entry=0x845e90) at gmain.c:3630
#16 0x000000356ae48158 in g_main_context_iterate (context=0x845e90, 
    block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>)
    at gmain.c:3701
---Type <return> to continue, or q <return> to quit---
#17 0x000000356ae4855a in g_main_loop_run (loop=0x8464e0) at gmain.c:3895
#18 0x00000000004086e2 in main (argc=1, argv=0x7fff07e67bc8) at main.c:135
----------------------
Comment 2 Bojan Smojver 2013-09-08 22:34:59 EDT
And one more:
-------------------
Program received signal SIGINT, Interrupt.
0x0000003568e0e06d in write () at ../sysdeps/unix/syscall-template.S:81
81	T_PSEUDO (SYSCALL_SYMBOL, SYSCALL_NAME, SYSCALL_NARGS)
(gdb) t a a bt

Thread 4 (Thread 0x7f2c125ff700 (LWP 2910)):
#0  0x0000003568aeb76d in poll () at ../sysdeps/unix/syscall-template.S:81
#1  0x000000356ae480f4 in g_main_context_poll (priority=2147483647, n_fds=1, 
    fds=0x7f2c040008c0, timeout=-1, context=0x846e00) at gmain.c:3995
#2  g_main_context_iterate (context=context@entry=0x846e00, 
    block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>)
    at gmain.c:3696
#3  0x000000356ae481fc in g_main_context_iteration (context=0x846e00, 
    may_block=may_block@entry=1) at gmain.c:3762
#4  0x000000356ae48249 in glib_worker_main (data=<optimized out>)
    at gmain.c:5427
#5  0x000000356ae6c185 in g_thread_proxy (data=0x847000) at gthread.c:798
#6  0x0000003568e07c53 in start_thread (arg=0x7f2c125ff700)
    at pthread_create.c:308
#7  0x0000003568af5d3d in clone ()
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 3 (Thread 0x7f2c11dfe700 (LWP 2911)):
#0  pthread_cond_wait@@GLIBC_2.3.2 ()
    at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1  0x000000356ae874c7 in g_cond_wait (cond=cond@entry=0x85fe68, 
    mutex=mutex@entry=0x85fe60) at gthread-posix.c:750
---Type <return> to continue, or q <return> to quit---
#2  0x000000356ae1eb0b in g_async_queue_pop_intern_unlocked (
    queue=queue@entry=0x85fe60, wait=wait@entry=1, end_time=end_time@entry=-1)
    at gasyncqueue.c:421
#3  0x000000356ae1ef07 in g_async_queue_pop (queue=queue@entry=0x85fe60)
    at gasyncqueue.c:455
#4  0x00000000004117e8 in on_job_scheduled (job=0x84bb00, 
    cancellable=0x7f2c0c0022a0, self=<optimized out>)
    at goakerberosidentitymanager.c:968
#5  0x000000356c259806 in io_job_thread (task=<optimized out>, 
    source_object=<optimized out>, task_data=0x84bb00, 
    cancellable=<optimized out>) at gioscheduler.c:89
#6  0x000000356c2780a5 in g_task_thread_pool_thread (thread_data=0x84eaa0, 
    pool_data=<optimized out>) at gtask.c:1242
#7  0x000000356ae6cb46 in g_thread_pool_thread_proxy (data=<optimized out>)
    at gthreadpool.c:309
#8  0x000000356ae6c185 in g_thread_proxy (data=0x847190) at gthread.c:798
#9  0x0000003568e07c53 in start_thread (arg=0x7f2c11dfe700)
    at pthread_create.c:308
#10 0x0000003568af5d3d in clone ()
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 2 (Thread 0x7f2c115fd700 (LWP 2912)):
#0  0x0000003568aeb76d in poll () at ../sysdeps/unix/syscall-template.S:81
---Type <return> to continue, or q <return> to quit---
#1  0x000000356ae480f4 in g_main_context_poll (priority=2147483647, n_fds=3, 
    fds=0x7f2c080010c0, timeout=-1, context=0x7f2c0c00d9a0) at gmain.c:3995
#2  g_main_context_iterate (context=0x7f2c0c00d9a0, block=block@entry=1, 
    dispatch=dispatch@entry=1, self=<optimized out>) at gmain.c:3696
#3  0x000000356ae4855a in g_main_loop_run (loop=0x7f2c0c00d930) at gmain.c:3895
#4  0x000000356c2c6d66 in gdbus_shared_thread_func (user_data=0x7f2c0c00d970)
    at gdbusprivate.c:278
#5  0x000000356ae6c185 in g_thread_proxy (data=0x7f2c0c004b70) at gthread.c:798
#6  0x0000003568e07c53 in start_thread (arg=0x7f2c115fd700)
    at pthread_create.c:308
#7  0x0000003568af5d3d in clone ()
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 1 (Thread 0x7f2c12600a40 (LWP 2909)):
#0  0x0000003568e0e06d in write () at ../sysdeps/unix/syscall-template.S:81
#1  0x000000356ae865af in g_wakeup_signal (wakeup=0x841330) at gwakeup.c:238
#2  0x000000356ae44d0e in g_main_context_add_poll_unlocked (
    context=<optimized out>, priority=<optimized out>, fd=<optimized out>)
    at gmain.c:4122
#3  0x000000356ae44d90 in unblock_source (source=source@entry=0x7f2c0c01fbd0)
    at gmain.c:2975
#4  0x000000356ae47f88 in g_main_dispatch (context=0x845e90) at gmain.c:3070
#5  g_main_context_dispatch (context=context@entry=0x845e90) at gmain.c:3630
---Type <return> to continue, or q <return> to quit---
#6  0x000000356ae48158 in g_main_context_iterate (context=0x845e90, 
    block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>)
    at gmain.c:3701
#7  0x000000356ae4855a in g_main_loop_run (loop=0x8464e0) at gmain.c:3895
#8  0x00000000004086e2 in main (argc=1, argv=0x7fff07e67bc8) at main.c:135
-------------------
Comment 3 Kurt Seifried 2013-09-09 12:31:49 EDT
I can confirm this: 

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND     
 3807 kseifrie  20   0 1509772 211164  36464 S 104.0  5.2   9:03.83 gnome-shell 
 3792 kseifrie  20   0  715392   9636   5656 R  99.7  0.2   3:11.48 goa-daemon  

I've tried to various tricks mentioned like logging out and back in, switching to a text console and back, nothing helps. This is highly annoying behaviour by the goa-demon.
Comment 4 David Sommerseth 2013-09-10 06:01:21 EDT
I've just noticed the same today.  It seems to mostly work find, but this morning it suddenly consumed about 95-100% of one CPU core.

As I only have kerberos registered, I killed the process and it came back up again and seems to behave better again.  I didn't think of doing a backtrace of it though, but the strace looked very much alike whats seen in comment #0.
Comment 5 Miranda Shutt 2013-09-10 15:02:33 EDT
I also see this on my Fedora 19 laptop.  Unfortunately, this process spinning at 100% on a laptop also has the unfortunate side effect of draining the battery in short order.

I am also using kerberos.

-r
Comment 6 Brian J. Murrell 2013-09-11 08:04:24 EDT
And ditto here.  Here's a backtrace from mine:

Thread 5 (Thread 0x7f2af776c700 (LWP 2416)):
#0  0x00000039a22eb76d in poll () from /lib64/libc.so.6
No symbol table info available.
#1  0x00000039a46480f4 in g_main_context_poll (priority=2147483647, n_fds=1, fds=0x7f2af00008e0, timeout=-1, context=0x15a0200) at gmain.c:3995
        poll_func = 0x39a4656d50 <g_poll>
#2  g_main_context_iterate (context=context@entry=0x15a0200, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at gmain.c:3696
        max_priority = 2147483647
        timeout = -1
        some_ready = <optimized out>
        nfds = 1
        allocated_nfds = 1
        fds = 0x7f2af00008e0
#3  0x00000039a46481fc in g_main_context_iteration (context=0x15a0200, may_block=may_block@entry=1) at gmain.c:3762
        retval = <optimized out>
#4  0x00000039a4648249 in glib_worker_main (data=<optimized out>) at gmain.c:5427
No locals.
#5  0x00000039a466c185 in g_thread_proxy (data=0x15a0400) at gthread.c:798
        thread = 0x15a0400
#6  0x00000039a2a07c53 in start_thread (arg=0x7f2af776c700) at pthread_create.c:308
        __res = <optimized out>
        pd = 0x7f2af776c700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {139822517110528, 5686760777101875899, 0, 139822517111232, 139822517110528, 0, -5710986396332188997, 5663324415772990139}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
#7  0x00000039a22f5d3d in clone () from /lib64/libc.so.6
No symbol table info available.

Thread 4 (Thread 0x7f2af6f6b700 (LWP 2417)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
No locals.
#1  0x00000039a46874c7 in g_cond_wait (cond=cond@entry=0x15d3678, mutex=mutex@entry=0x15d3670) at gthread-posix.c:750
        _g_boolean_var_ = <optimized out>
        status = <optimized out>
#2  0x00000039a461eb0b in g_async_queue_pop_intern_unlocked (queue=queue@entry=0x15d3670, wait=wait@entry=1, end_time=end_time@entry=-1) at gasyncqueue.c:421
        retval = <optimized out>
        __PRETTY_FUNCTION__ = "g_async_queue_pop_intern_unlocked"
#3  0x00000039a461ef07 in g_async_queue_pop (queue=0x15d3670) at gasyncqueue.c:455
        retval = <optimized out>
        __PRETTY_FUNCTION__ = "g_async_queue_pop"
#4  0x00000000004117e8 in on_job_scheduled ()
No symbol table info available.
#5  0x00000039a5a59806 in io_job_thread (task=<optimized out>, source_object=<optimized out>, task_data=0x15d14c0, cancellable=<optimized out>) at gioscheduler.c:89
        job = 0x15d14c0
        result = <optimized out>
#6  0x00000039a5a780a5 in g_task_thread_pool_thread (thread_data=0x15a82a0, pool_data=<optimized out>) at gtask.c:1242
        task = 0x15a82a0
#7  0x00000039a466cb46 in g_thread_pool_thread_proxy (data=<optimized out>) at gthreadpool.c:309
        task = 0x15a82a0
        pool = 0x15a5bb0
#8  0x00000039a466c185 in g_thread_proxy (data=0x15a0590) at gthread.c:798
        thread = 0x15a0590
#9  0x00000039a2a07c53 in start_thread (arg=0x7f2af6f6b700) at pthread_create.c:308
        __res = <optimized out>
        pd = 0x7f2af6f6b700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {139822508717824, 5686760777101875899, 0, 139822508718528, 139822508717824, 22698928, -5710983098334176581, 5663324415772990139}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
#10 0x00000039a22f5d3d in clone () from /lib64/libc.so.6
No symbol table info available.

Thread 3 (Thread 0x7f2af676a700 (LWP 2418)):
#0  0x00000039a22eb76d in poll () from /lib64/libc.so.6
No symbol table info available.
#1  0x00000039a46480f4 in g_main_context_poll (priority=2147483647, n_fds=3, fds=0x7f2aec0010c0, timeout=-1, context=0x7f2ae800d9a0) at gmain.c:3995
        poll_func = 0x39a4656d50 <g_poll>
#2  g_main_context_iterate (context=0x7f2ae800d9a0, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at gmain.c:3696
        max_priority = 2147483647
        timeout = -1
        some_ready = <optimized out>
        nfds = 3
        allocated_nfds = 3
        fds = 0x7f2aec0010c0
#3  0x00000039a464855a in g_main_loop_run (loop=0x7f2ae800d930) at gmain.c:3895
        __PRETTY_FUNCTION__ = "g_main_loop_run"
#4  0x00000039a5ac6d66 in gdbus_shared_thread_func (user_data=0x7f2ae800d970) at gdbusprivate.c:278
        data = 0x7f2ae800d970
#5  0x00000039a466c185 in g_thread_proxy (data=0x7f2ae8004b70) at gthread.c:798
        thread = 0x7f2ae8004b70
#6  0x00000039a2a07c53 in start_thread (arg=0x7f2af676a700) at pthread_create.c:308
        __res = <optimized out>
        pd = 0x7f2af676a700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {139822500325120, 5686760777101875899, 0, 139822500325824, 139822500325120, 139822257723760, -5710984198382675269, 5663324415772990139}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
#7  0x00000039a22f5d3d in clone () from /lib64/libc.so.6
No symbol table info available.

Thread 2 (Thread 0x7f2af52ee700 (LWP 2654)):
#0  0x00000039a22eb76d in poll () from /lib64/libc.so.6
No symbol table info available.
#1  0x00000039a46480f4 in g_main_context_poll (priority=2147483647, n_fds=1, fds=0x7f2ae40010c0, timeout=-1, context=0x7f2ae0400af0) at gmain.c:3995
        poll_func = 0x39a4656d50 <g_poll>
#2  g_main_context_iterate (context=context@entry=0x7f2ae0400af0, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at gmain.c:3696
        max_priority = 2147483647
        timeout = -1
        some_ready = <optimized out>
        nfds = 1
        allocated_nfds = 1
        fds = 0x7f2ae40010c0
#3  0x00000039a46481fc in g_main_context_iteration (context=context@entry=0x7f2ae0400af0, may_block=may_block@entry=1) at gmain.c:3762
        retval = <optimized out>
#4  0x00007f2af40659cd in dconf_gdbus_worker_thread (user_data=0x7f2ae0400af0) at dconf-gdbus-thread.c:81
        context = 0x7f2ae0400af0
#5  0x00000039a466c185 in g_thread_proxy (data=0x7f2ae0092b20) at gthread.c:798
        thread = 0x7f2ae0092b20
#6  0x00000039a2a07c53 in start_thread (arg=0x7f2af52ee700) at pthread_create.c:308
        __res = <optimized out>
        pd = 0x7f2af52ee700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {139822478845696, 5686760777101875899, 0, 139822478846400, 139822478845696, 23, -5710981516175598917, 5663324415772990139}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
#7  0x00000039a22f5d3d in clone () from /lib64/libc.so.6
No symbol table info available.

Thread 1 (Thread 0x7f2af776fa40 (LWP 2409)):
#0  0x00000039a22e6f34 in _fxstat () from /lib64/libc.so.6
No symbol table info available.
#1  0x00000039a464943e in fstat (__statbuf=0x7fff458cf190, __fd=494) at /usr/include/sys/stat.h:470
No locals.
#2  mapped_file_new_from_fd (fd=fd@entry=494, writable=writable@entry=0, filename=filename@entry=0x16b08c0 "/etc/localtime", error=error@entry=0x0) at gmappedfile.c:122
        file = 0x1880b60
        st = {st_dev = 64769, st_ino = 392352, st_nlink = 2, st_mode = 33188, st_uid = 0, st_gid = 0, __pad0 = 0, st_rdev = 0, st_size = 3477, st_blksize = 4096, st_blocks = 8, st_atim = {tv_sec = 1372967972, tv_nsec = 0}, st_mtim = {tv_sec = 1372967972, tv_nsec = 0}, st_ctim = {tv_sec = 1373828906, tv_nsec = 99670831}, __unused = {0, 0, 0}}
#3  0x00000039a4649740 in g_mapped_file_new (filename=filename@entry=0x16b08c0 "/etc/localtime", writable=writable@entry=0, error=error@entry=0x0) at gmappedfile.c:269
        file = <optimized out>
        fd = 494
        __PRETTY_FUNCTION__ = "g_mapped_file_new"
#4  0x00000039a466ebac in zone_info_unix (identifier=<optimized out>) at gtimezone.c:432
        filename = 0x16b08c0 "/etc/localtime"
        file = 0x0
        zoneinfo = 0x0
#5  g_time_zone_new (identifier=<optimized out>) at gtimezone.c:1411
        tz = 0x1884b00
        rules = 0x0
        identifier = <optimized out>
        tz = <optimized out>
#6  0x00000039a4631c1b in g_date_time_new_now_local () at gdatetime.c:731
        datetime = <optimized out>
        local = <optimized out>
#7  0x00000000004136d2 in fire_or_rearm_alarm ()
No symbol table info available.
#8  0x0000000000413bf2 in on_timer_source_ready ()
No symbol table info available.
#9  0x00000039a4647e06 in g_main_dispatch (context=0x159f840) at gmain.c:3054
        dispatch = 0x39a5a65060 <pollable_source_dispatch>
        was_in_call = 0
        user_data = 0x15d4c30
        callback = 0x413af0 <on_timer_source_ready>
        cb_funcs = 0x39a492a900 <g_source_callback_funcs>
        cb_data = 0x7f2ae80cc960
        need_destroy = <optimized out>
        current_source_link = {data = 0x7f2ae8073c90, next = 0x0}
        source = 0x7f2ae8073c90
        current = 0x159a670
        i = 185
#10 g_main_context_dispatch (context=context@entry=0x159f840) at gmain.c:3630
No locals.
#11 0x00000039a4648158 in g_main_context_iterate (context=0x159f840, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at gmain.c:3701
        max_priority = 0
        timeout = 0
        some_ready = 1
        nfds = <optimized out>
        allocated_nfds = 328
        fds = 0x16c1a60
#12 0x00000039a464855a in g_main_loop_run (loop=0x159ef50) at gmain.c:3895
        __PRETTY_FUNCTION__ = "g_main_loop_run"
#13 0x00000000004086e2 in main ()
No symbol table info available.
#0  0x00000039a22e6f34 in _fxstat () from /lib64/libc.so.6
#1  0x00000039a464943e in fstat (__statbuf=0x7fff458cf190, __fd=494) at /usr/include/sys/stat.h:470
#2  mapped_file_new_from_fd (fd=fd@entry=494, writable=writable@entry=0, filename=filename@entry=0x16b08c0 "/etc/localtime", error=error@entry=0x0) at gmappedfile.c:122
#3  0x00000039a4649740 in g_mapped_file_new (filename=filename@entry=0x16b08c0 "/etc/localtime", writable=writable@entry=0, error=error@entry=0x0) at gmappedfile.c:269
#4  0x00000039a466ebac in zone_info_unix (identifier=<optimized out>) at gtimezone.c:432
#5  g_time_zone_new (identifier=<optimized out>) at gtimezone.c:1411
#6  0x00000039a4631c1b in g_date_time_new_now_local () at gdatetime.c:731
#7  0x00000000004136d2 in fire_or_rearm_alarm ()
#8  0x0000000000413bf2 in on_timer_source_ready ()
#9  0x00000039a4647e06 in g_main_dispatch (context=0x159f840) at gmain.c:3054
#10 g_main_context_dispatch (context=context@entry=0x159f840) at gmain.c:3630
#11 0x00000039a4648158 in g_main_context_iterate (context=0x159f840, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at gmain.c:3701
#12 0x00000039a464855a in g_main_loop_run (loop=0x159ef50) at gmain.c:3895
#13 0x00000000004086e2 in main ()
Detaching from program: /usr/libexec/goa-daemon, process 2409
Comment 7 Jeff Layton 2013-09-11 08:16:45 EDT
*** Bug 1006267 has been marked as a duplicate of this bug. ***
Comment 8 Jeff Layton 2013-09-11 08:25:29 EDT
I have my machine set up to use sssd. When I first log in, I can't reach the KDC yet and goa-daemon runs at a reasonable pace. When I connect to the VPN though, sssd gets a TGT for me, and at that point goa-daemon takes off running. It also tends to drain my laptop battery in short order.

My workaround for the moment is to just kill goa-daemon when I log in. I haven't noticed any ill effects from that so far.
Comment 9 Lionel Landwerlin 2013-09-11 08:27:15 EDT
It looks a lot like a problem seen on telepathy-idle ( https://bugs.freedesktop.org/show_bug.cgi?id=64923 ), fixed in GLib by : https://bugzilla.gnome.org/show_bug.cgi?id=707097
Not backported to stable GLib yet.
Comment 10 Jeff Layton 2013-09-11 08:37:40 EDT
Looks like this bug is also a dup of bug 1004144.
Comment 11 Jeff Layton 2013-09-11 08:38:48 EDT
fwiw, downgrading to 3.8.2 seems to have fixed the problem so this is a fairly recent regression.
Comment 12 Dan Winship 2013-09-11 09:20:52 EDT
(In reply to Lionel Landwerlin from comment #9)
> It looks a lot like a problem seen on telepathy-idle (
> https://bugs.freedesktop.org/show_bug.cgi?id=64923 ), fixed in GLib by :
> https://bugzilla.gnome.org/show_bug.cgi?id=707097
> Not backported to stable GLib yet.

If this is the same problem that telepathy-idle had, then it doesn't need a GLib fix; just cancel all pending async ops on a socket/stream before closing it.

(Probably we should change the semantics of gio sockets and streams to not require this though. But note that that's not what the patch in bgo 707097 does; it just removes the infinite loop, while still leaving a race condition where some other thread could end up reusing the file descriptor that used to belong to the socket.)
Comment 13 David Sommerseth 2013-09-13 06:45:25 EDT
Happened again.  Did a gdb backtrace of all threads.  Basically the same result as can be found in comment #1.  Same function call chain.

The only thing I have configured in g-o-a is Kerberos, but without SSSD (at least not configured).  Otherwise, I'm experiencing pretty much the same as jlayton in comment #8.
Comment 14 David Woodhouse 2013-09-13 10:37:26 EDT
[Fri13-14:57] <halfline> nils, dwmw2_gone, danw: I think that bug is probably fallout from a bad patch that went in to fix https://bugzilla.gnome.org/show_bug.cgi?id=705395 initially
[Fri13-14:58] <halfline> if any of you are feeling adventurous, i'd appreciate if someone tried reverting that commit to see if the problem goes away.  It's on my todo list of things to investigate, but it's going to be a few days

Scratch build at http://koji.fedoraproject.org/koji/taskinfo?taskID=5931383 which reverts
https://git.gnome.org/browse/gnome-online-accounts/commit/?h=f4c04ad4

I haven't been 100% sure how to reproduce it (other than dropping off the VPN and it happens some time later), but will try.
Comment 15 Christophe Fergeau 2013-09-16 05:56:16 EDT
(In reply to David Woodhouse from comment #14)
> Scratch build at http://koji.fedoraproject.org/koji/taskinfo?taskID=5931383
> which reverts
> https://git.gnome.org/browse/gnome-online-accounts/commit/?h=f4c04ad4
> 
> I haven't been 100% sure how to reproduce it (other than dropping off the
> VPN and it happens some time later), but will try.

I installed that package and haven't hit the issue so far while without it I had it every time I got on the VPN and ran kinit.
Comment 16 David Woodhouse 2013-09-17 16:55:59 EDT
(In reply to Christophe Fergeau from comment #15)
> I installed that package and haven't hit the issue so far while without it I
> had it every time I got on the VPN and ran kinit.

Other users of my package also seem to concur with this. But just reverting the 'offending' commit isn't sufficient, is it? That was a fix for a potential deadlock, which does need to be fixed some other way.

I note the 'offending' commit says that it was based on a commit in Evolution... do we have a similar latent issue there? (adding mbarnes to cc)
Comment 17 Dave Allan 2013-09-17 21:03:04 EDT
(Not entirely in reply to David Woodhouse from comment #16)
> Other users of my package also seem to concur with this. But just reverting
> the 'offending' commit isn't sufficient, is it? That was a fix for a
> potential deadlock, which does need to be fixed some other way.

Totally agreed that a revert is not a complete fix.  FWIW, my vote is for reverting without waiting for the complete fix though since I never experienced the deadlock, and I remember to kill goa-deamon every morning when I burn my finger on the VGA port.
Comment 18 David Sommerseth 2013-09-18 07:14:36 EDT
I installed the scratch build yesterday.  I found that this issue hit me every morning, but with this build installed the issue is seems gone.  So it's most likely the correct commit causing this issue.
Comment 19 Stanislav Graf 2013-09-21 07:39:56 EDT
(In reply to David Sommerseth from comment #18)

+1, works for me
Comment 20 Paul W. Frields 2013-09-23 10:38:35 EDT
*** Bug 1010529 has been marked as a duplicate of this bug. ***
Comment 21 Kai Engert (:kaie) 2013-09-25 14:17:56 EDT
I've also experienced the 100% goa-daemon problem multiple times. Are you going to produce a real update build?

Regarding "how to reproduce". If your home NAT router gets a random IP address each time you reboot it, then try do reboot it while connected to a VPN.

(My ISP does a forced disconnect with a forced IP address change one a day.)
Comment 22 Lalatendu Mohanty 2013-09-26 04:34:32 EDT
I am also seeing this issue.
Comment 24 Fedora Update System 2013-09-27 14:53:18 EDT
gnome-online-accounts-3.8.3-2.fc19 has been submitted as an update for Fedora 19.
https://admin.fedoraproject.org/updates/gnome-online-accounts-3.8.3-2.fc19
Comment 25 Michael Cronenworth 2013-09-27 14:57:18 EDT
Just tested the update but 100% CPU usage still occurs after using something that requires authenticating.
Comment 26 Ray Strode [halfline] 2013-09-27 17:33:41 EDT
Dave Allan and I weren't too far away from each other so we met up and debugged the issue together.  I have a better idea what's going on now.  The problem is we change out the cancellable object when setting the timer.  If the timer source associated with the previous timer fires after this changeout, then we don't correctly notice an operation has cancelled (since we're checking the wrong object).

We got a proof of concept patch written.  I'll finish it up and post it upstream and in a new gnome-online-accounts package.
Comment 27 Fedora Update System 2013-09-27 21:31:56 EDT
gnome-online-accounts-3.8.3-3.fc19 has been submitted as an update for Fedora 19.
https://admin.fedoraproject.org/updates/gnome-online-accounts-3.8.3-3.fc19
Comment 28 Fedora Update System 2013-09-28 21:44:11 EDT
Package gnome-online-accounts-3.8.3-3.fc19:
* should fix your issue,
* was pushed to the Fedora 19 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing gnome-online-accounts-3.8.3-3.fc19'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2013-17920/gnome-online-accounts-3.8.3-3.fc19
then log in and leave karma (feedback).
Comment 29 Fedora Update System 2013-09-29 20:37:13 EDT
gnome-online-accounts-3.8.3-3.fc19 has been pushed to the Fedora 19 stable repository.  If problems still persist, please make note of it in this bug report.
Comment 30 Pavel Studeník 2013-10-02 09:45:17 EDT
I used new package on Fedora 19. And I have still problem that goa-daemon is consuming 100% CPU. 

package: gnome-online-accounts-3.8.3-3.fc19.x86_64
Comment 31 Dave Allan 2013-10-02 12:10:02 EDT
Did you log out & back in?  I'd been experiencing this 100% of the time, and it's fixed for me.
Comment 32 Debarshi Ray 2014-04-10 05:24:32 EDT
*** Bug 950078 has been marked as a duplicate of this bug. ***

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