race in authentication completion?

[Colin Walters]

I'm trying to track down why my application gets its connection closed
randomly.  Sometimes it works, sometimes it doesn't, so it does seem
like a race condition somewhere.

This is a direct connection between two apps speaking the D-BUS
protocol.  From examining the following strace, it looks to me like the
first read chunk of data after the authentication completes and the
server gets BEGIN<chunk> is being ignored, and the continuation chunk is
being parsed first.  My guess right now is that there are two watches on
the connection fd active, one for authentication and one for later
message parsing?  And it's the second watch which acts first sometimes?
Not sure, I'm hoping this will ring a bell for someone.  I'm going to
keep digging.

Here is the strace:

[pid  1653] write(2, "[0x50bb80] [handle_new_connection] imsep-loader.c:204 (21:20:04): got new connection 0x518390\n", 94) = 94
[pid  1653] write(2, "1653: Allocated slot 0 on allocator 0x3313c5e390 total 1 slots allocated 1 used\n", 80) = 80
[pid  1653] write(2, "1653: Adding a watch on fd 4 using newly-set add watch function\n", 64) = 64
[pid  1653] write(2, "1653: Adding a watch on fd 4 using newly-set add watch function\n", 64) = 64
[pid  1653] write(2, "1653: Setting watch fd 4 data to data = 0x518580 function = 0x3314305ae0 from data = (nil) function = (nil)\n", 108) = 108
[pid  1653] poll([{fd=4, events=POLLIN, revents=POLLIN}, {fd=3, events=POLLIN}], 2, -1) = 1
[pid  1653] recvmsg(4, {msg_name(0)=NULL, msg_iov(1)=[{"\0", 1}], msg_controllen=0, msg_flags=0}, 0) = 1[pid  1653] write(2, "1653: read credentials byte\n", 28) = 28
[pid  1653] getsockopt(4, SOL_SOCKET, SO_PEERCRED, "t\6\0\0\364\1\0\0\364\1\0\0", [545460846604]) = 0
[pid  1653] write(2, "1653: Credentials:  pid 1652  uid 500  gid 500\n", 47) = 47
[pid  1653] write(2, "1653:  server auth state: waiting for input\n", 44) = 44
[pid  1653] read(4, "AUTH EXTERNAL 353030\r\n", 2048) = 22
[pid  1653] write(2, "1653:  read 22 bytes in auth phase\n", 35) = 35
[pid  1653] write(2, "1653: server: got command \"AUTH EXTERNAL 353030\"\n", 49) = 49
[pid  1653] write(2, "1653: server: Trying mechanism EXTERNAL\n", 40) = 40
[pid  1653] write(2, "1653: server: data: \'500\'\n", 26) = 26
[pid  1653] write(2, "1653: server: going from state WaitingForAuth to state WaitingForBegin\n", 71) = 71
[pid  1653] write(2, "1653: server: authenticated client with UID 500 matching socket credentials UID 500\n", 84) = 84
[pid  1653] write(2, "1653:  server auth state: bytes to send\n", 40) = 40
[pid  1653] write(2, "1653: Toggling watch on fd 4 to 0\n", 34) = 34
[pid  1653] write(2, "1653: Setting watch fd 4 data to data = (nil) function = (nil) from data = 0x518580 function = 0x3314305ae0\n", 108) = 108
[pid  1653] write(2, "1653: Toggling watch on fd 4 to 1\n", 34) = 34
[pid  1653] write(2, "1653: Setting watch fd 4 data to data = 0x5187d0 function = 0x3314305ae0 from data = (nil) function = (nil)\n", 108) = 108
[pid  1653] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLOUT, revents=POLLOUT}], 2, -1) = 1
[pid  1653] write(2, "1653:  server auth state: bytes to send\n", 40) = 40
[pid  1653] write(4, "OK\r\n", 4)       = 4
[pid  1653] write(2, "1653: server: Sent 4 bytes of: OK\r\n\n", 36) = 36
[pid  1653] write(2, "1653:  server auth state: waiting for input\n", 44) = 44
[pid  1653] write(2, "1653: Toggling watch on fd 4 to 1\n", 34) = 34
[pid  1653] write(2, "1653: Setting watch fd 4 data to data = 0x518580 function = 0x3314305ae0 from data = (nil) function = (nil)\n", 108) = 108
[pid  1653] write(2, "1653: Toggling watch on fd 4 to 0\n", 34) = 34
[pid  1653] write(2, "1653: Setting watch fd 4 data to data = (nil) function = (nil) from data = 0x5187d0 function = 0x3314305ae0\n", 108) = 108
[pid  1653] write(2, "1653: Not authenticated, not writing anything\n", 46) = 46
[pid  1653] poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN, revents=POLLIN}], 2, -1) = 1
[pid  1653] write(2, "1653:  server auth state: waiting for input\n", 44) = 44
[pid  1653] read(4, "BEGIN\r\nl\1\0\0\220\0\0\0\277\313\2\0\1\0\0\0\1o\0\0\35\0\0\0/org/freedesktop/Imsep/Loader\0\6s\25\0\0\0org.freedesktop.Imsep\0\2s\34\0\0\0org.freedesktop.Imsep.Loader\0\3s\0\4\0\0\0Load\0\10s\0\2\0\0\0ay\0\0\0\0\0\0ay\0\0\267\313\2\0\377\330\377\340\0\20JFIF\0\1\1\0\0\1\0\1\0\0\377\333\0C\0\4\3\3\4\3\3\4\4\4\4\5\5\4\5\7\v"..., 2048) = 2048
[pid  1653] write(2, "1653:  read 2048 bytes in auth phase\n", 37) = 37
[pid  1653] write(2, "1653: server: got command \"BEGIN\"\n", 34) = 34
[pid  1653] write(2, "1653: server: going from state WaitingForBegin to state Authenticated\n", 70) = 70[pid  1653] getuid()                    = 500
[pid  1653] getgid()                    = 500
[pid  1653] write(2, "1653: Client authorized as UID 500 matching our UID 500\n", 56) = 56
[pid  1653] read(4, "\216*\235\370\201\342}3F\207\360\5\245\324-u{\177\r\254\227Wv\326s\254\252\306;\210\216v\377\0\211P\343p\31\24e\25\334\nO\260\236\37\366b\361\224\366\311\2754\350\265y!\370\204\321\244\276\214_4x\316DY\366\354N~Y\243l?\331\332k\337\302Q\342\243\177\r\256\260u\27\210\301ww\34QGj\2211`\312F\3416\365\3413\235\275\252\307u\370\177\246\337\376/M\370\246\237\210\336\35>\25}Tk\7R\223Q\vs\4a\303"..., 2048) = 2048
[pid  1653] write(2, "1653:  read 2048 bytes\n", 23) = 23
[pid  1653] write(2, "1653:  2041 unused bytes sent to message loader\n", 48) = 48
[pid  1653] write(2, "1653: Message has protocol version -8 ours is 0\n", 48) = 48
[pid  1653] write(2, "1653: Corrupted message stream, disconnecting\n", 46) = 46
[pid  1653] write(2, "1653: Removing watch on fd 4\n", 29) = 29

-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 189 bytes
Desc: This is a digitally signed message part
Url : http://freedesktop.org/pipermail/dbus/attachments/20041018/239d290d/attachment.pgp