I've been poking at this for a few hours and I haven't got very far.

So far, I've narrowed it down to an issue with threading (either in GIO or due to Vala's ‘yield’ keyword); most likely a race condition between unrefs of a GLocalFileInputStream.

However, gdb's not being very helpful (the output from `break close` is useless) and I'm out of ideas for the moment.

Here's an except of `strace -f -F -e trace=open,close,read,write` on the EDS add-persona test, which also reproduces the problem for me:

[pid 12762] write(2, "folks-Message: avatar-cache.vala"..., 222folks-Message: avatar-cache.vala:125: Storing avatar 'eds:local\://test:pas-id-4E6FB2B000000000' in file 'file:///tmp/tmp.gTeqrHL1h4/.cache/folks/avatars/eds%253Alocal%255C%253A%252F%252Ftest%253Apas-id-4E6FB2B000000000'.
) = 222
[pid 12762] open("/etc/localtime", O_RDONLY) = 16
[pid 12762] close(16)                   = 0
[pid 12783] open("/tmp/tmp.gTeqrHL1h4/.cache/folks/avatars/eds%3Alocal%5C%3A%2F%2Ftest%3Apas-id-4E6FB2B000000000", O_WRONLY|O_CREAT|O_EXCL, 0600) = 16
[pid 12783] write(8, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 12762] read(8, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 12783] write(16, "\377\330\377\340\0\20JFIF\0\1\1\1\0H\0H\0\0\377\333\0C\0\5\3\4\4\4\3\5"..., 1157) = 1157
[pid 12783] close(16)                   = 0
[pid 12783] write(8, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 12762] read(8, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 12783] open("/opt/gnome2/source/folks/tests/data/avatar-01.jpg", O_RDONLY) = 16
[pid 12762] close(16)                   = 0
[pid 12783] read(16, 0xe76000, 2048)    = -1 EBADF (Bad file descriptor)
[pid 12783] write(8, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 12762] read(8, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 12762] write(2, "\n** WARNING **: test-utils.vala:"..., 126
** WARNING **: test-utils.vala:87: Failed to read loadable icon for comparison: Error reading from file: Bad file descriptor
) = 126

If I'm correct, PID 12762 is the main thread and PID 12783 is GIO's worker thread. The main thread's closing FD 16 (avatar-01.jpg) before the worker thread tries to read it.

If I remove all the ‘yield’ statements from test-utils.vala's loadable_icons_content_equal() and make it use sync methods for everything, everything works fine. However, examining the generated C code for that method doesn't reveal any obvious refcounting issues, and manually adding lots of extra refs to the input streams doesn't fix anything.

I had a similar problem, but the other way around. When not using yield, I used to get many failures with bad file descriptor errors when running tests/eds/add-persona.

So with commit 05eb5224 I replaced the:

  loadable_icons_content_equal.begin (a, b, -1, (obj, result) => {}

dance with yield loadable_icons_content_equal.

And haven't seen the problem ever since.

Created attachment 196810 [details] [review]
Work around bug #659324 when storing avatars in the cache

https://www.gitorious.org/folks/folks/commits/658531-store-avatar-workaround

After more poking around, it turns out the problem is that GIO wasn't marking streams as closed under certain circumstances, which could result in them being closed several times (in this case, meaning we called close(15) twice and killed an innocent bystander FD). I've filed bug #659324 against GIO about this, with a patch.

However, we can also work around broken versions of GIO in folks with the patch attached here, which simply changes AvatarCache.store_avatar() to not use OutputStreamSpliceFlags.CLOSE_TARGET.

(There's also a secret other commit in the patch which prevents us opening /etc/localtime many, many times; which I noticed while looking at strace output. It's otherwise unrelated to fixing this bug, but I couldn't be bothered to push a trivia branch.)

Review of attachment 196810 [details] [review]:

From a visual inspection, this looks good.

Comment on attachment 196810 [details] [review]
Work around bug #659324 when storing avatars in the cache

Committed with a change to NEWS too.

commit e8a7b128464d03c8357e32ef6dcc842023e139d7
Author: Philip Withnall <philip@tecnocode.co.uk>
Date:   Sat Sep 17 17:24:30 2011 +0100

    Bug 658531 — Sometimes avatar caching doesn't work
    
    Work around bug #659324 (in GIO) to ensure that we never close the same FD
    more than once when storing avatars to the cache.
    
    Closes: bgo#658531

 NEWS                    |    1 +
 folks/avatar-cache.vala |   20 ++++++++++++++------
 2 files changed, 15 insertions(+), 6 deletions(-)

commit 3150a055e00a9fccea4811dc672960cd1fad8e95
Author: Philip Withnall <philip@tecnocode.co.uk>
Date:   Sat Sep 17 17:23:19 2011 +0100

    eds: Re-use a GTimeZone instance for converting birthday timezones
    
    Every time a GTimeZone is created, /etc/localtime is opened. Reduce this
    overhead by sharing a single GTimeZone instance between all Edsf.Personas
    for all time.
    
    This makes our strace a little tidier.

 backends/eds/lib/edsf-persona.vala |   12 +++++++++---
 1 files changed, 9 insertions(+), 3 deletions(-)