[prev in list] [next in list] [prev in thread] [next in thread]
List: freedesktop-dbus
Subject: race in authentication completion?
From: Colin Walters <walters () verbum ! org>
Date: 2004-10-19 1:44:10
Message-ID: 1098150250.1120.9.camel () x-infinity ! verbum ! private
[Download RAW message or body]
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\2 \
16v\377\0\211P\343p\31\24e\25\334\nO\260\236\37\366b\361\224\366\311\2754\350\265y!\37 \
0\204\321\244\276\214_4x\316DY\366\354N~Y\243l?\331\332k\337\302Q\342\243\177\r\256\26 \
0u\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
["signature.asc" (application/pgp-signature)]
[prev in list] [next in list] [prev in thread] [next in thread]
Configure |
About |
News |
Add a list |
Sponsored by KoreLogic