Hello Andy
I restarted the olbds with -d option and run the test again.
> xrdcp -d2 dummy.root root://bbr-test-xfer1:2094////prod/s13/wk.root
The log files are:
# ---- olbdlog from redirector: (first time running xrdcp)
041217 13:06:25 010 Receive From bbr-test-xfer1.slac.stanford.edu: 0 select c /prod/s13/wk.root
041217 13:06:25 010 do_Select Lookup delay bbr-test-xfer1.slac.stanford.edu 5
041217 13:06:30 010 Receive From bbr-test-xfer1.slac.stanford.edu: 1 select r /prod/s13/wk.root
041217 13:06:30 010 do_Select No servers available to r /prod/s13/wk.root
# ---- olbdlog from oprserv04 (data server)
041217 13:06:25 001 Receive From bbr-test-xfer1.slac.stanford.edu: 7@0 state /prod/s13/wk.root
# ---- olbdlog from oprserv07 (data server)
041217 13:06:25 001 Receive From bbr-test-xfer1.slac.stanford.edu: 7@0 state /prod/s13/wk.root
running the command a second time:
> xrdcp -d2 dummy.root root://bbr-test-xfer1:2094////prod/s13/wk.root
# ---- olbdlog from redirector: (second time running xrdcp)
041217 13:11:20 010 Receive From bbr-test-xfer1.slac.stanford.edu: 2 select c /prod/s13/wk.root
041217 13:11:20 010 SelServer Server oprserv07.slac.stanford.edu:2094 bound to /prod/s13/wk.root
041217 13:11:20 010 do_Select Redirect bbr-test-xfer1.slac.stanford.edu ->
oprserv07.slac.stanford.edu:2094 for /prod/s13/wk.root
There are no entries in the olbdlog of the two data servers.
I also provided the entires in the xrdlog file (redirector) for the first
attempt to run xrdcp.
# ---- xrdlog redirector (first time running xrdcp)
041217 13:06:25 029 XrdInet: Accepted connection from noric13
041217 13:06:25 007 XrdSched: running 5@noric13 inq=0
041217 13:06:25 007 XrdProtocol: matched protocol xrootd
041217 13:06:25 007 ?:15@noric13 XrdPoll: FD 15 attached to poller 0; num=1
041217 13:06:25 007 ?:15@noric13 XrootdProtocol: 0000 req=3007 dlen=0
041217 13:06:25 007 wilko.18587:15@noric13 XrootdResponse: 0000 sending OK
041217 13:06:25 007 XrootdXeq: User logged in as wilko.18587:15@noric13
041217 13:06:25 007 wilko.18587:15@noric13 XrootdProtocol: 0000 req=3010 dlen=19
041217 13:06:25 007 wilko.18587:15@noric13 ofs_open: 100-1000000664 fn=/prod/s13/wk.root
041217 13:06:25 007 odc_Locate: user=wilko.18587:15@noric13 wait :5 by
bbr-test-xfer1 path=/prod/s13/wk.root
041217 13:06:25 007 wilko.18587:15@noric13 XrootdProtocol: 0000 stalling
client for 5 sec
041217 13:06:30 007 wilko.18587:15@noric13 XrootdProtocol: 0000 req=3010 dlen=19
041217 13:06:30 007 wilko.18587:15@noric13 ofs_open: 0-664 fn=/prod/s13/wk.root
041217 13:06:30 007 odc_Locate: user=wilko.18587:15@noric13 error: No
servers are available to read the file.:0 by bbr-test-xfer1 path=/prod/s13/wk.root
041217 13:06:30 007 wilko.18587:15@noric13 XrootdResponse: 0000 sending
err 3005: No servers are available to read the file.
041217 13:06:30 007 XrdLink: wilko.18587:15@noric13 disconnected after 0:00:05 (link read error)
041217 13:06:30 007 wilko.18587:15@noric13 XrdPoll: FD 15 detached from poller 0; num=0
I hope this helps
Cheers,
Wilko
On Fri, 17 Dec 2004, Andrew Hanushevsky wrote:
> Hi Wilko,
>
> Could you rerun the test with the olbd's started with the -d option and
> send me the log; thanks.
>
> Andy
>
> On Thu, 16 Dec 2004, Wilko Kroeger wrote:
>
> >
> >
> >
> > Hello Andy and Fabrizio
> >
> > I tried to copy a local file into xrootd using the latest xrootd release,
> > 20041216-0815. I am using one redirector (bbr-test-xfer1) and two data
> > servers (oprser04, oprserv07).
> > Running xrdcp against a data server works fine, but running it against
> > the redirector doesn't work the way it should.
> >
> > Running xrdcp the first time fails with the error:
> >
> > 041216 22:32:25 001 Xrd: SendGenCommand Server declared error 3005:No servers
> > are available to read the file.
> >
> > Running the same xrdcp command a second time the client is redirected to a
> > data server and the file is transfered.
> > Below is the output from the client and the relevant part from the redirector
> > or data server (if aplicable) log files. The output is quiet verbose
> > because in the xrootd.cf the 'trace: all' option was used for:
> > xrootd,xrd,olb,ofs,oss
> >
> > Any idea ?
> >
> > Thanks,
> > Wilko
> >
> >
> > #
> > # first attempt to copy a local file into xrootd
> > #
> >
> > > xrdcp -d2 dummy.root root://bbr-test-xfer1:2094////prod/s5/wk.root
> >
> > # ------------ xrdcp output
> >
> > 041216 22:32:20 001 Xrd: Create Access to server granted.
> > 041216 22:32:20 001 Xrd: Create Opening the remote file ///prod/s5/wk.root
> > 041216 22:32:20 001 Xrd: SendGenCommand Sending command Open
> > 041216 22:32:20 001 Xrd: ReadPartialAnswer Reading a XrdClientMessage from the server
> > [bbr-test-xfer1.slac.stanford.edu:2094]...
> > 041216 22:32:20 001 Xrd: ReadPartialAnswer Server [bbr-test-xfer1.slac.stanford.edu:2094]
> > did not answer OK. Resp status is [kXR_wait]
> > 041216 22:32:20 001 Xrd: SendGenCommand Server [bbr-test-xfer1.slac.stanford.edu:2094]
> > requested 5 seconds of wait
> > 041216 22:32:25 001 Xrd: SendGenCommand Sending command Open
> > 041216 22:32:25 001 Xrd: ReadPartialAnswer Reading a XrdClientMessage from the server
> > [bbr-test-xfer1.slac.stanford.edu:2094]...
> > 041216 22:32:25 001 Xrd: ReadPartialAnswer Server [bbr-test-xfer1.slac.stanford.edu:2094]
> > did not answer OK. Resp status is [kXR_error]
> > 041216 22:32:25 001 Xrd: Open Server [bbr-test-xfer1.slac.stanford.edu:2094] did not
> > return OK message for last request.
> > 041216 22:32:25 001 Xrd: SendGenCommand Server declared error 3005:No servers are available
> > to read the file.
> > 041216 22:32:25 001 Xrd: Create Error opening the file ///prod/s5/wk.root on host
> > bbr-test-xfer1:2094
> > 041216 22:32:25 001 Xrd: Close File not opened.
> > Caching info: MissRate=0 MissCount=0 ReadsCounter=0
> > Caching info: BytesUsefulness=0 BytesSubmitted=0 BytesHit=0
> > Error accessing path/file for root://bbr-test-xfer1:2094////prod/s5/wk.root
> >
> > # ----------------------- Redirector log file
> >
> > 041216 22:32:20 029 XrdInet: Accepted connection from noric06
> > 041216 22:32:20 008 XrdSched: running 6@noric06 inq=0
> > 041216 22:32:20 008 XrdProtocol: matched protocol xrootd
> > 041216 22:32:20 008 ?:16@noric06 XrdPoll: FD 16 attached to poller 0; num=1
> > 041216 22:32:20 008 ?:16@noric06 XrootdProtocol: 0000 req=3007 dlen=0
> > 041216 22:32:20 008 wilko.25211:16@noric06 XrootdResponse: 0000 sending OK
> > 041216 22:32:20 008 XrootdXeq: User logged in as wilko.25211:16@noric06
> > 041216 22:32:20 008 wilko.25211:16@noric06 XrootdProtocol: 0000 req=3010 dlen=18
> > 041216 22:32:20 008 wilko.25211:16@noric06 ofs_open: 100-1000000664 fn=/prod/s5/wk.root
> > 041216 22:32:20 008 odc_Locate: user=wilko.25211:16@noric06 wait :5 by bbr-test-xfer1
> > path=/prod/s5/wk.root
> > 041216 22:32:20 008 wilko.25211:16@noric06 XrootdProtocol: 0000 stalling client for 5 sec
> > 041216 22:32:25 008 wilko.25211:16@noric06 XrootdProtocol: 0000 request timeout;
> > read 0 of 24 bytes
> > 041216 22:32:25 023 XrdPoll: Poller 0 enable fd 16
> > 041216 22:32:25 009 XrdSched: running wilko.25211:16@noric06 inq=0
> > 041216 22:32:25 009 wilko.25211:16@noric06 XrootdProtocol: 0000 req=3010 dlen=18
> > 041216 22:32:25 009 wilko.25211:16@noric06 ofs_open: 0-664 fn=/prod/s5/wk.root
> > 041216 22:32:25 009 odc_Locate: user=wilko.25211:16@noric06 error: No servers are available to
> > read the file.:0 by bbr-test-xfer1 path=/prod/s5/wk.root
> > 041216 22:32:25 009 wilko.25211:16@noric06 XrootdResponse: 0000 sending err 3005:
> > No servers are available to read the file.
> > 041216 22:32:25 009 XrdLink: wilko.25211:16@noric06 disconnected after 0:00:05 (link read error)
> >
> >
> > #
> > # 2nd attempt
> > #
> >
> > > xrdcp -d2 dummy.root root://bbr-test-xfer1:2094////prod/s5/wk.root
> >
> > # ------------ xrdcp output
> >
> > 041216 22:36:08 001 Xrd: Create Access to server granted.
> > 041216 22:36:08 001 Xrd: Create Opening the remote file ///prod/s5/wk.root
> > 041216 22:36:08 001 Xrd: SendGenCommand Sending command Open
> > 041216 22:36:08 001 Xrd: ReadPartialAnswer Reading a XrdClientMessage from the server
> > [bbr-test-xfer1.slac.stanford.edu:2094]...
> > 041216 22:36:08 001 Xrd: ReadPartialAnswer Server [bbr-test-xfer1.slac.stanford.edu:2094]
> > did not answer OK. Resp status is [kXR_redirect]
> > 041216 22:36:08 001 Xrd: HandleServerError Redir count=1
> > 041216 22:36:08 001 Xrd: HandleServerError Received redirection to
> > [oprserv04.slac.stanford.edu:2094]. Token=[].
> > 041216 22:36:08 001 Xrd: GetDomainToMatch GetHostName(oprserv04.slac.stanford.edu) returned
> > name=oprserv04.slac.stanford.edu
> > 041216 22:36:08 001 Xrd: GetDomainToMatch GetDomain(oprserv04.slac.stanford.edu) -->
> > slac.stanford.edu
> > 041216 22:36:08 001 Xrd: CheckHostDomain Resolved [oprserv04.slac.stanford.edu]'s domain
> > name into [slac.stanford.edu]
> > 041216 22:36:08 001 Xrd: CheckHostDomain Access granted to the domain of
> > [oprserv04.slac.stanford.edu].
> > 041216 22:36:08 001 Xrd: Connect Creating a logical connection...
> > 041216 22:36:08 001 Xrd: Connect Physical connection not found. Creating a new one...
> > 041216 22:36:08 001 Xrd: Connect Connecting to [oprserv04.slac.stanford.edu:2094]
> > 041216 22:36:08 001 Xrd: ClientSock::TryConnect Trying to connect tooprserv04.slac.stanford.edu(
> > 134.79.85.44):2094 Timeout=60
> > 041216 22:36:08 001 Xrd: Connect Connected to [oprserv04.slac.stanford.edu:2094]
> > 041216 22:36:08 001 Xrd: Connect New physical connection to server
> > oprserv04.slac.stanford.edu:2094 succesfully created.
> > 041216 22:36:08 001 Xrd: Connect LogConn: size:2 count: 1PhyConn: size:2 count: 2
> > 041216 22:36:08 001 Xrd: Connect Connect(oprserv04.slac.stanford.edu, 2094) returned 1
> > 041216 22:36:08 001 Xrd: DoHandShake HandShake step 1: Sending 20 bytes to the server
> > [oprserv04.slac.stanford.edu:2094]
> > 041216 22:36:08 001 Xrd: DoHandShake HandShake step 2: Reading 4 bytes from server
> > [oprserv04.slac.stanford.edu:2094].
> > 041216 22:36:08 001 Xrd: DoHandShake HandShake step 3: Reading 12 bytes from server
> > [oprserv04.slac.stanford.edu:2094].
> > 041216 22:36:08 001 Xrd: StartReader Starting reader thread...
> > 041216 22:36:08 000 Xrd: SocketReaderThread Reader Thread starting.
> > 041216 22:36:08 001 Xrd: GetAccessToSrv Ok, the server on [oprserv04.slac.stanford.edu:2094]
> > is an xrootd data server.
> > 041216 22:36:08 001 Xrd: DoLogin Logging into the server [oprserv04.slac.stanford.edu:2094].
> > pid=25233 uid=wilko
> > 041216 22:36:08 001 Xrd: SendGenCommand Sending command XTNetconn::doLogin
> > 041216 22:36:08 001 Xrd: ReadPartialAnswer Reading a XrdClientMessage from the server
> > [oprserv04.slac.stanford.edu:2094]...
> > 041216 22:36:08 001 Xrd: SendGenCommand Communication error detected with
> > [oprserv04.slac.stanford.edu:2094
> > 041216 22:36:08 001 Xrd: SendGenCommand Sending command Open
> > 041216 22:36:08 001 Xrd: ReadPartialAnswer Reading a XrdClientMessage from the server
> > [oprserv04.slac.stanford.edu:2094]...
> > 041216 22:36:08 001 Xrd: Create File opened succesfully.
> > 041216 22:36:08 001 Xrd: main dummy.root --> root://bbr-test-xfer1:2094////prod/s5/wk.root
> > 041216 22:36:08 25233 Xrd: ReaderThread_loc Reader Thread starting.
> > 041216 22:36:08 001 Xrd: SendGenCommand Sending command Write
> > 041216 22:36:08 001 Xrd: ReadPartialAnswer Reading a XrdClientMessage from the server
> > [oprserv04.slac.stanford.edu:2094]...
> > 041216 22:36:08 001 Xrd: SendGenCommand Sending command Close
> > 041216 22:36:08 001 Xrd: ReadPartialAnswer Reading a XrdClientMessage from the server
> > [oprserv04.slac.stanford.edu:2094]...
> > Caching info: MissRate=0 MissCount=0 ReadsCounter=0
> > Caching info: BytesUsefulness=0 BytesSubmitted=0 BytesHit=0
> >
> >
> > # ------------------ Redirector bbr-test-xfer1 log file
> >
> >
> > 041216 22:36:08 029 XrdInet: Accepted connection from noric06
> > 041216 22:36:08 010 XrdSched: running 7@noric06 inq=0
> > 041216 22:36:08 010 XrdProtocol: matched protocol xrootd
> > 041216 22:36:08 010 ?:17@noric06 XrdPoll: FD 17 attached to poller 0; num=1
> > 041216 22:36:08 010 ?:17@noric06 XrootdProtocol: 0000 req=3007 dlen=0
> > 041216 22:36:08 010 wilko.25233:17@noric06 XrootdResponse: 0000 sending OK
> > 041216 22:36:08 010 XrootdXeq: User logged in as wilko.25233:17@noric06
> > 041216 22:36:08 010 wilko.25233:17@noric06 XrootdProtocol: 0000 req=3010 dlen=18
> > 041216 22:36:08 010 wilko.25233:17@noric06 ofs_open: 100-1000000664 fn=/prod/s5/wk.root
> > 041216 22:36:08 010 odc_Locate: user=wilko.25233:17@noric06 redirected to
> > oprserv04.slac.stanford.edu:2094 by bbr-test-xfer1 path=/prod/s5/wk.root
> > 041216 22:36:08 010 wilko.25233:17@noric06 XrootdProtocol: 0000 redirecting to
> > oprserv04.slac.stanford.edu:2094
> > 041216 22:36:08 010 XrdLink: wilko.25233:17@noric06 disconnected after 0:00:00 (link read error)
> >
> >
> > # ------------------ Data Server oprserv04 log file
> >
> > 041216 22:36:08 029 XrdInet: Accepted connection from noric06
> > 041216 22:36:08 007 XrdSched: running 5@noric06 inq=0
> > 041216 22:36:08 007 XrdProtocol: matched protocol xrootd
> > 041216 22:36:08 007 ?:15@noric06 XrdPoll: FD 15 attached to poller 0; num=1
> > 041216 22:36:08 007 ?:15@noric06 XrootdProtocol: 0100 req=3007 dlen=0
> > 041216 22:36:08 007 wilko.25233:15@noric06 XrootdResponse: 0100 sending OK
> > 041216 22:36:08 007 XrootdXeq: User logged in as wilko.25233:15@noric06
> > 041216 22:36:08 007 wilko.25233:15@noric06 XrootdProtocol: 0100 req=3010 dlen=18
> > 041216 22:36:08 007 wilko.25233:15@noric06 ofs_open: 100-1000000664 fn=/prod/s5/wk.root
> > 041216 22:36:08 007 oss_Alloc_Cache: public cache as /u1/kanga/cache0/%u1%kanga%prod%s5%wk.root
> > 041216 22:36:08 007 wilko.25233:15@noric06 oss_Open_ufs: fd=8192 flags=2 mode=1000000664
> > path=/u1/kanga/prod/s5/wk.root
> > 041216 22:36:08 007 wilko.25233:15@noric06 ofs_stat: pi=5 fn=/prod/s5/wk.root
> > 041216 22:36:08 007 wilko.25233:15@noric06 XrootdProtocol: 0100 open nmfa /prod/s5/wk.root fh=0
> > 041216 22:36:08 007 wilko.25233:15@noric06 XrootdResponse: 0100 sending 4 data bytes; rc=0
> > 041216 22:36:08 007 wilko.25233:15@noric06 XrootdProtocol: 0100 req=3019 dlen=29
> > 041216 22:36:08 007 wilko.25233:15@noric06 XrootdProtocol: 0100 fh=0 write 29@0
> > 041216 22:36:08 007 wilko.25233:15@noric06 ofs_write: 29@0 pi=5 fn=/prod/s5/wk.root
> > 041216 22:36:08 007 wilko.25233:15@noric06 XrootdResponse: 0100 sending OK
> > 041216 22:36:08 007 wilko.25233:15@noric06 XrootdProtocol: 0100 req=3003 dlen=0
> > 041216 22:36:08 007 wilko.25233:15@noric06 XrootdFile: closing w /prod/s5/wk.root
> > 041216 22:36:08 007 wilko.25233:15@noric06 ofs_close: lnks=1 pi=5 fn=/prod/s5/wk.root
> > 041216 22:36:08 007 ofs_Unopen: numfd=0 pi=5 fn=/prod/s5/wk.root
> > 041216 22:36:08 007 wilko.25233:15@noric06 XrootdProtocol: 0100 close fh=0
> > 041216 22:36:08 007 wilko.25233:15@noric06 XrootdResponse: 0100 sending OK
> > 041216 22:36:08 007 XrdLink: wilko.25233:15@noric06 disconnected after 0:00:00 (link read error)
> >
> >
>
