This is probably only interesting to Andy and Fabrizio. (You were
warned. Here be tedious dragons!)
I finally reproduced the error by turning off ALL tracing in ... the
redirector. At a certain point way below you see that the client timed
out its connections and tried unsuccessfully to reconnect. In the
section after the client debug, you will see the director debug - and
it definitely is not closing connections from the client, even though
the client is bravely making new ones. It even hits its thread limit.
My naive guess is to suspect that the client thinks the connection
failed, while the server does not. (Not much insight there, but I give
it to you free of charge.)
Something I would like to try:
Andy, can you please give me the file# and approximate line# for the
problem you mentioned yesterday about an "==" that should be a "!=". I
would like to fix that and see if it makes any substantive difference.
One extra data point - I am able to reproduce this bug with the
20041212 release, as well as the 20041214 release. So it isn't due to a
change between those two releases.
The way I generally trigger this problem is to have 5 or 6 clients beat
on a single director with a single server.
---- XRDCLIENT OUTPUT @ debug level 1 -----
This is the output of the client.
Fri Dec 17 14:31:42 2004
%src/bin/pdsTest-INFO: Will use
root://sol199:1094//cleo/test/mc_test_tiny.pds t
o read from
041217 14:31:42 001 Xrd: Create (C) 2004 SLAC INFN XrdClient 0.3
041217 14:31:42 001 Xrd: XrdClientUrlSet List of servers to connect to
is [sol19
9:1094]
041217 14:31:42 001 Xrd: ShowUrls The converted URLs count is 1
041217 14:31:42 001 Xrd: ShowUrls URL n.1:
sol199.lns.cornell.edu:1094//.
041217 14:31:42 001 Xrd: Create Access to server granted.
041217 14:31:42 001 Xrd: Create Opening the remote file
/cleo/test/mc_test_tiny.
pds
041217 14:33:42 001 Xrd: ReadPartialAnswer Error reading msg from
connmgr (serve
r [sol199.lns.cornell.edu:1094]).
041217 14:33:42 000 Xrd: ClientSock::RecvRaw Disconnection detected
reading 8 by
tes from socket 5 (server[sol199.lns.cornell.edu:1094]). Revents=32
041217 14:33:42 001 Xrd: HandleServerError Received redirection to
[sol199.lns.c
ornell.edu:1094]. Token=[].
041217 14:33:42 000 Xrd: XrdClientMessage::ReadRaw Error reading 8
bytes.
041217 14:35:42 001 Xrd: ReadPartialAnswer Error reading msg from
connmgr (serve
r [sol199.lns.cornell.edu:1094]).
041217 14:35:42 000 Xrd: ClientSock::RecvRaw Disconnection detected
reading 8 by
tes from socket 5 (server[sol199.lns.cornell.edu:1094]). Revents=32
041217 14:35:42 001 Xrd: HandleServerError Received redirection to
[sol199.lns.c
ornell.edu:1094]. Token=[].
041217 14:35:42 000 Xrd: XrdClientMessage::ReadRaw Error reading 8
bytes.
041217 14:37:42 001 Xrd: ReadPartialAnswer Error reading msg from
connmgr (serve
r [sol199.lns.cornell.edu:1094]).
041217 14:37:42 000 Xrd: ClientSock::RecvRaw Disconnection detected
reading 8 by
tes from socket 5 (server[sol199.lns.cornell.edu:1094]). Revents=32
041217 14:37:42 001 Xrd: HandleServerError Received redirection to
[sol199.lns.c
ornell.edu:1094]. Token=[].
041217 14:37:42 000 Xrd: XrdClientMessage::ReadRaw Error reading 8
bytes.
041217 14:39:42 001 Xrd: ReadPartialAnswer Error reading msg from
connmgr (serve
r [sol199.lns.cornell.edu:1094]).
041217 14:39:42 000 Xrd: ClientSock::RecvRaw Disconnection detected
reading 8 by
tes from socket 5 (server[sol199.lns.cornell.edu:1094]). Revents=32
041217 14:39:42 001 Xrd: HandleServerError Received redirection to
[sol199.lns.c
ornell.edu:1094]. Token=[].
041217 14:39:42 000 Xrd: XrdClientMessage::ReadRaw Error reading 8
bytes.
041217 14:41:44 001 Xrd: ReadPartialAnswer Error reading msg from
connmgr (serve
r [sol199.lns.cornell.edu:1094]).
041217 14:41:44 000 Xrd: ClientSock::RecvRaw Disconnection detected
reading 8 by
tes from socket 5 (server[sol199.lns.cornell.edu:1094]). Revents=32
041217 14:41:44 001 Xrd: HandleServerError Received redirection to
[sol199.lns.c
ornell.edu:1094]. Token=[].
041217 14:41:44 000 Xrd: XrdClientMessage::ReadRaw Error reading 8
bytes.
041217 14:43:43 000 Xrd: GarbageCollect Purging physical connection 0
041217 14:43:43 000 Xrd: GarbageCollect Purged physical connection 0
041217 14:43:44 001 Xrd: ReadPartialAnswer Error reading msg from
connmgr (serve
r [sol199.lns.cornell.edu:1094]).
041217 14:43:44 000 Xrd: ClientSock::RecvRaw Disconnection detected
reading 8 by
tes from socket 5 (server[sol199.lns.cornell.edu:1094]). Revents=32
041217 14:43:44 001 Xrd: HandleServerError Received redirection to
[sol199.lns.c
ornell.edu:1094]. Token=[].
041217 14:43:44 000 Xrd: XrdClientMessage::ReadRaw Error reading 8
bytes.
041217 14:45:43 000 Xrd: GarbageCollect Purging physical connection 1
041217 14:45:43 000 Xrd: GarbageCollect Purged physical connection 1
041217 14:45:44 001 Xrd: ReadPartialAnswer Error reading msg from
connmgr (serve
r [sol199.lns.cornell.edu:1094]).
041217 14:45:44 000 Xrd: ClientSock::RecvRaw Disconnection detected
reading 8 by
tes from socket 5 (server[sol199.lns.cornell.edu:1094]). Revents=32
041217 14:45:44 001 Xrd: HandleServerError Received redirection to
[sol199.lns.c
ornell.edu:1094]. Token=[].
041217 14:45:44 000 Xrd: XrdClientMessage::ReadRaw Error reading 8
bytes.
041217 14:47:43 000 Xrd: GarbageCollect Purging physical connection 2
041217 14:47:43 000 Xrd: GarbageCollect Purged physical connection 2
041217 14:47:44 001 Xrd: ReadPartialAnswer Error reading msg from
connmgr (serve
r [sol199.lns.cornell.edu:1094]).
041217 14:47:44 000 Xrd: ClientSock::RecvRaw Disconnection detected
reading 8 by
tes from socket 5 (server[sol199.lns.cornell.edu:1094]). Revents=32
041217 14:47:44 001 Xrd: HandleServerError Received redirection to
[sol199.lns.c
ornell.edu:1094]. Token=[].
041217 14:47:44 000 Xrd: XrdClientMessage::ReadRaw Error reading 8
bytes.
041217 14:49:43 000 Xrd: GarbageCollect Purging physical connection 3
041217 14:49:43 000 Xrd: GarbageCollect Purged physical connection 3
041217 14:49:44 001 Xrd: ReadPartialAnswer Error reading msg from
connmgr (serve
r [sol199.lns.cornell.edu:1094]).
041217 14:49:44 000 Xrd: ClientSock::RecvRaw Disconnection detected
reading 8 by
tes from socket 5 (server[sol199.lns.cornell.edu:1094]). Revents=32
041217 14:49:44 001 Xrd: HandleServerError Received redirection to
[sol199.lns.c
ornell.edu:1094]. Token=[].
041217 14:49:44 000 Xrd: XrdClientMessage::ReadRaw Error reading 8
bytes.
041217 14:50:45 001 Xrd: DoHandShake Error reading 4 bytes from server
[sol199.l
ns.cornell.edu:1094].
041217 14:50:45 001 Xrd: GetAccessToSrv HandShake failed with server
[sol199.lns
.cornell.edu:1094]
041217 14:50:45 000 Xrd: ClientSock::RecvRaw Disconnection detected
reading 8 by
tes from socket 5 (server[sol199.lns.cornell.edu:1094]). Revents=32
041217 14:50:45 001 Xrd: GoToAnotherServer Error handshaking to
[sol199.lns.corn
ell.edu:1094]
041217 14:50:45 000 Xrd: XrdClientMessage::ReadRaw Error reading 8
bytes.
041217 14:50:55 001 Xrd: HandleServerError Received redirection to
[sol199.lns.c
ornell.edu:1094]. Token=[].
041217 14:51:45 000 Xrd: GarbageCollect Purging physical connection 4
041217 14:51:45 000 Xrd: GarbageCollect Purged physical connection 4
041217 14:51:56 001 Xrd: DoHandShake Error reading 4 bytes from server
[sol199.l
ns.cornell.edu:1094].
041217 14:51:56 001 Xrd: GetAccessToSrv HandShake failed with server
[sol199.lns
.cornell.edu:1094]
041217 14:51:56 000 Xrd: ClientSock::RecvRaw Disconnection detected
reading 8 by
tes from socket 5 (server[sol199.lns.cornell.edu:1094]). Revents=32
041217 14:51:56 001 Xrd: GoToAnotherServer Error handshaking to
[sol199.lns.corn
ell.edu:1094]
041217 14:51:56 000 Xrd: XrdClientMessage::ReadRaw Error reading 8
bytes.
041217 14:52:06 001 Xrd: HandleServerError Received redirection to
[sol199.lns.c
ornell.edu:1094]. Token=[].
041217 14:53:07 001 Xrd: DoHandShake Error reading 4 bytes from server
[sol199.l
ns.cornell.edu:1094].
041217 14:53:07 001 Xrd: GetAccessToSrv HandShake failed with server
[sol199.lns
.cornell.edu:1094]
041217 14:53:07 000 Xrd: ClientSock::RecvRaw Disconnection detected
reading 8 by
tes from socket 5 (server[sol199.lns.cornell.edu:1094]). Revents=32
041217 14:53:07 001 Xrd: GoToAnotherServer Error handshaking to
[sol199.lns.corn
ell.edu:1094]
041217 14:53:07 000 Xrd: XrdClientMessage::ReadRaw Error reading 8
bytes.
041217 14:53:17 001 Xrd: HandleServerError Received redirection to
[sol199.lns.c
ornell.edu:1094]. Token=[].
041217 14:53:45 000 Xrd: GarbageCollect Purging physical connection 5
041217 14:53:45 000 Xrd: GarbageCollect Purged physical connection 5
041217 14:54:18 001 Xrd: DoHandShake Error reading 4 bytes from server
[sol199.l
ns.cornell.edu:1094].
041217 14:54:18 001 Xrd: GetAccessToSrv HandShake failed with server
[sol199.lns
.cornell.edu:1094]
041217 14:54:18 000 Xrd: ClientSock::RecvRaw Disconnection detected
reading 8 by
tes from socket 5 (server[sol199.lns.cornell.edu:1094]). Revents=32
041217 14:54:18 001 Xrd: GoToAnotherServer Error handshaking to
[sol199.lns.corn
ell.edu:1094]
041217 14:54:18 000 Xrd: XrdClientMessage::ReadRaw Error reading 8
bytes.
041217 14:54:28 001 Xrd: HandleServerError Received redirection to
[sol199.lns.c
ornell.edu:1094]. Token=[].
041217 14:55:29 001 Xrd: DoHandShake Error reading 4 bytes from server
[sol199.l
ns.cornell.edu:1094].
041217 14:55:29 001 Xrd: GetAccessToSrv HandShake failed with server
[sol199.lns
.cornell.edu:1094]
041217 14:55:29 000 Xrd: ClientSock::RecvRaw Disconnection detected
reading 8 by
tes from socket 5 (server[sol199.lns.cornell.edu:1094]). Revents=32
041217 14:55:29 001 Xrd: GoToAnotherServer Error handshaking to
[sol199.lns.corn
ell.edu:1094]
041217 14:55:29 000 Xrd: XrdClientMessage::ReadRaw Error reading 8
bytes.
041217 14:55:39 001 Xrd: HandleServerError Received redirection to
[sol199.lns.c
ornell.edu:1094]. Token=[].
041217 14:55:45 000 Xrd: GarbageCollect Purging physical connection 6
041217 14:55:45 000 Xrd: GarbageCollect Purged physical connection 6
041217 14:55:46 000 Xrd: GarbageCollect Purging physical connection 9
041217 14:55:46 000 Xrd: GarbageCollect Purged physical connection 9
041217 14:56:40 001 Xrd: DoHandShake Error reading 4 bytes from server
[sol199.l
ns.cornell.edu:1094].
041217 14:56:40 001 Xrd: GetAccessToSrv HandShake failed with server
[sol199.lns
.cornell.edu:1094]
041217 14:56:40 000 Xrd: ClientSock::RecvRaw Disconnection detected
reading 8 by
tes from socket 5 (server[sol199.lns.cornell.edu:1094]). Revents=32
041217 14:56:40 001 Xrd: GoToAnotherServer Error handshaking to
[sol199.lns.corn
ell.edu:1094]
041217 14:56:40 000 Xrd: XrdClientMessage::ReadRaw Error reading 8
bytes.
041217 14:56:50 001 Xrd: HandleServerError Received redirection to
[sol199.lns.c
ornell.edu:1094]. Token=[].
041217 14:56:57 000 Xrd: GarbageCollect Purging physical connection 10
041217 14:56:57 000 Xrd: GarbageCollect Purged physical connection 10
041217 14:57:45 000 Xrd: GarbageCollect Purging physical connection 7
041217 14:57:45 000 Xrd: GarbageCollect Purged physical connection 7
041217 14:57:51 001 Xrd: DoHandShake Error reading 4 bytes from server
[sol199.l
ns.cornell.edu:1094].
041217 14:57:51 001 Xrd: GetAccessToSrv HandShake failed with server
[sol199.lns
.cornell.edu:1094]
041217 14:57:51 000 Xrd: ClientSock::RecvRaw Disconnection detected
reading 8 by
tes from socket 5 (server[sol199.lns.cornell.edu:1094]). Revents=32
041217 14:57:51 001 Xrd: GoToAnotherServer Error handshaking to
[sol199.lns.corn
ell.edu:1094]
----- DIRECTOR XROOTD SVR LOG FILE ----- (no messages in the OLBD
director logfile)
041217 14:31:14 016 XrdLink: gregor.9186:17@lnx243 disconnected after
0:00:01 (l
ink read error)
041217 14:31:14 007 XrootdXeq: User logged in as gregor.26612:21@lnx6211
041217 14:31:14 015 XrootdXeq: User logged in as gregor.9191:17@lnx243
041217 14:31:21 016 XrdLink: gregor.26612:21@lnx6211 disconnected after
0:00:07
(link read error)
041217 14:31:21 007 XrootdXeq: User logged in as gregor.26617:20@lnx6211
041217 14:31:41 016 XrdLink: gregor.8740:18@sol184 disconnected after
0:04:32 (l
ink read error)
041217 14:31:42 017 XrootdXeq: User logged in as gregor.8748:21@sol184
041217 14:31:56 016 XrdLink: gregor.3065:19@sol199 disconnected after
0:03:33 (l
ink read error)
041217 14:33:21 016 XrootdXeq: User logged in as gregor.26617:18@lnx6211
041217 14:33:22 018 XrootdXeq: User logged in as gregor.9191:19@lnx243
041217 14:33:42 019 XrootdXeq: User logged in as gregor.8748:22@sol184
041217 14:35:21 020 XrootdXeq: User logged in as gregor.26617:23@lnx6211
041217 14:35:22 021 XrootdXeq: User logged in as gregor.9191:24@lnx243
041217 14:35:42 022 XrootdXeq: User logged in as gregor.8748:25@sol184
041217 14:37:21 023 XrootdXeq: User logged in as gregor.26617:26@lnx6211
041217 14:37:22 024 XrootdXeq: User logged in as gregor.9191:27@lnx243
041217 14:37:42 025 XrootdXeq: User logged in as gregor.8748:28@sol184
041217 14:39:21 026 XrootdXeq: User logged in as gregor.26617:29@lnx6211
041217 14:39:22 027 XrootdXeq: User logged in as gregor.9191:30@lnx243
041217 14:39:42 028 XrootdXeq: User logged in as gregor.8748:31@sol184
041217 14:41:11 029 XrootdXeq: User logged in as gregor.3086:32@sol199
041217 14:41:21 030 XrootdXeq: User logged in as gregor.26617:33@lnx6211
041217 14:41:22 031 XrootdXeq: User logged in as gregor.9191:34@lnx243
041217 14:41:44 032 XrootdXeq: User logged in as gregor.8748:35@sol184
041217 14:43:11 033 XrootdXeq: User logged in as gregor.3086:36@sol199
041217 14:43:21 034 XrootdXeq: User logged in as gregor.26617:37@lnx6211
041217 14:43:22 035 XrootdXeq: User logged in as gregor.9191:38@lnx243
041217 14:43:44 036 XrootdXeq: User logged in as gregor.8748:39@sol184
041217 14:45:11 037 XrootdXeq: User logged in as gregor.3086:40@sol199
041217 14:45:21 038 XrootdXeq: User logged in as gregor.26617:41@lnx6211
041217 14:45:22 038 XrootdXeq: User logged in as gregor.9191:42@lnx243
041217 14:45:44 038 XrootdXeq: User logged in as gregor.8748:43@sol184
041217 14:47:11 038 XrootdXeq: User logged in as gregor.3086:44@sol199
041217 14:47:21 038 XrootdXeq: User logged in as gregor.26617:45@lnx6211
041217 14:47:22 038 XrootdXeq: User logged in as gregor.9191:46@lnx243
041217 14:47:44 038 XrootdXeq: User logged in as gregor.8748:47@sol184
041217 14:49:11 038 XrdScheduler: Thread limit has been reached!
041217 14:49:11 038 XrootdXeq: User logged in as gregor.3086:48@sol199
--
Gregory J. Sharp email: [log in to unmask]
Wilson Synchrotron Laboratory url:
http://www.lepp.cornell.edu/~gregor
Dryden Rd ph: +1 607 255 4882
Ithaca, NY 14853 fax: +1 607 255 8062
|
