==> xrdlog <== 110202 17:36:37 001 XrdInet: Accepted connection from 22@rcas6202.rcf.bnl.gov 110202 17:36:37 26268 XrootdXeq: starlib.30669:22@rcas6202 login as starlib 110202 17:46:38 26268 XrootdXeq: starlib.30669:22@rcas6202 disc 0:10:01 ==> cmslog <== 110202 17:36:37 26297 Admin_Login received request: 'newfn /home/starlib/home/starreco/reco/EmcCheck/ReversedFullField/P08ie/2008/048/9048041/test2.root' 110202 17:36:37 26297 do_RmDud sending managers have online /home/starlib/home/starreco/reco/EmcCheck/ReversedFullField/P08ie/2008/048/9048041/test2.root 110202 17:36:37 26297 Inform rcas6140 have [rcas6202] ~/> xrdcp -f -d 3 /tmp/test1.root root://rcas6202.rcf.bnl.gov:40748//home/starlib/home/starreco/reco/EmcCheck/ReversedFullField/P08ie/2008/048/9048041/test2.root Set debug level 3 110202 17:36:37 001 Xrd: main: (C) 2004-2010 by the Xrootd group. $Revision: 1.100 $ - Xrootd version: 20100315-1007_dbg 110202 17:36:37 001 Xrd: Create: (C) 2004-2010 by the Xrootd group. XrdClient $Revision: 1.155 $ - Xrootd version: 20100315-1007_dbg 110202 17:36:37 001 Xrd: TakeUrl: parsing url: 110202 17:36:37 001 Xrd: XrdClientUrlSet: parsing: root://rcas6202.rcf.bnl.gov:40748//home/starlib/home/starreco/reco/EmcCheck/ReversedFullField/P08ie/2008/048/9048041/test2.root 110202 17:36:37 001 Xrd: XrdClientUrlSet: protocol: root 110202 17:36:37 001 Xrd: XrdClientUrlSet: file: /home/starlib/home/starreco/reco/EmcCheck/ReversedFullField/P08ie/2008/048/9048041/test2.root 110202 17:36:37 001 Xrd: XrdClientUrlSet: list of [host:port] : rcas6202.rcf.bnl.gov:40748 110202 17:36:37 001 Xrd: XrdClientUrlSet: Remote file to open is '/home/starlib/home/starreco/reco/EmcCheck/ReversedFullField/P08ie/2008/048/9048041/test2.root' 110202 17:36:37 001 Xrd: XrdClientUrlSet: parsing entity: rcas6202.rcf.bnl.gov:40748 110202 17:36:37 001 Xrd: TakeUrl: parsing url: rcas6202.rcf.bnl.gov:40748 110202 17:36:37 001 Xrd: TakeUrl: HostWPort: rcas6202.rcf.bnl.gov:40748 110202 17:36:37 001 Xrd: TakeUrl: File: / 110202 17:36:37 001 Xrd: TakeUrl: Host: rcas6202.rcf.bnl.gov 110202 17:36:37 001 Xrd: TakeUrl: Port: 40748 110202 17:36:37 001 Xrd: ConvertDNSAlias: resolving rcas6202.rcf.bnl.gov:40748 110202 17:36:37 001 Xrd: CheckPort: specified port (40748) potentially valid. 110202 17:36:37 001 Xrd: ConvertDNSAlias: found host rcas6202.rcf.bnl.gov with addr 130.199.183.205 110202 17:36:37 001 Xrd: ShowUrls: The converted URLs count is 1 110202 17:36:37 001 Xrd: ShowUrls: URL n.1: root://rcas6202.rcf.bnl.gov:40748//home/starlib/home/starreco/reco/EmcCheck/ReversedFullField/P08ie/2008/048/9048041/test2.root. 110202 17:36:37 001 Xrd: TakeUrl: parsing url: root://rcas6202.rcf.bnl.gov:40748//home/starlib/home/starreco/reco/EmcCheck/ReversedFullField/P08ie/2008/048/9048041/test2.root 110202 17:36:37 001 Xrd: TakeUrl: Proto: root 110202 17:36:37 001 Xrd: TakeUrl: HostWPort: rcas6202.rcf.bnl.gov:40748 110202 17:36:37 001 Xrd: TakeUrl: File: /home/starlib/home/starreco/reco/EmcCheck/ReversedFullField/P08ie/2008/048/9048041/test2.root 110202 17:36:37 001 Xrd: TakeUrl: Host: rcas6202.rcf.bnl.gov 110202 17:36:37 001 Xrd: TakeUrl: Port: 40748 110202 17:36:37 001 Xrd: CheckHostDomain: Resolved [rcas6202.rcf.bnl.gov]'s domain name into [rcf.bnl.gov] 110202 17:36:37 001 Xrd: DomainMatcher: search for 'rcf.bnl.gov' in '' 110202 17:36:37 001 Xrd: DomainMatcher: no domain matching 'rcf.bnl.gov' found in '' 110202 17:36:37 001 Xrd: DomainMatcher: search for 'rcf.bnl.gov' in '*' 110202 17:36:37 001 Xrd: DomainMatcher: checking domain: * 110202 17:36:37 001 Xrd: DomainMatcher: domain: * matches 'rcf.bnl.gov' (matching chars: 1) 110202 17:36:37 001 Xrd: CheckHostDomain: Access granted to the domain of [rcas6202.rcf.bnl.gov]. 110202 17:36:37 001 Xrd: Open: Trying to connect to rcas6202.rcf.bnl.gov:40748. Connect try 1 110202 17:36:37 001 Xrd: XrdClientConn: Trying to connect to 130.199.183.205:40748 110202 17:36:37 001 Xrd: Connect: Creating a logical connection... 110202 17:36:37 001 Xrd: Connect: Physical connection not found. Creating a new one... 110202 17:36:37 001 Xrd: Connect: Connecting to [rcas6202.rcf.bnl.gov:40748] 110202 17:36:37 001 Xrd: ClientSock::TryConnect_low: Trying to connect to rcas6202.rcf.bnl.gov(130.199.183.205):40748 Windowsize=0 Timeout=120 110202 17:36:37 001 Xrd: Connect: Connected to [rcas6202.rcf.bnl.gov:40748] 110202 17:36:37 001 Xrd: Connect: New physical connection to server rcas6202.rcf.bnl.gov:40748 succesfully created. 110202 17:36:37 001 Xrd: Connect: LogConn: size:1 count: 1PhyConn: size:1 110202 17:36:37 001 Xrd: Connect: Connect(rcas6202.rcf.bnl.gov, 40748) returned 0 110202 17:36:37 001 Xrd: Open: The logical connection id is 0. 110202 17:36:37 001 Xrd: Open: Working url is root://rcas6202.rcf.bnl.gov:40748//home/starlib/home/starreco/reco/EmcCheck/ReversedFullField/P08ie/2008/048/9048041/test2.root 110202 17:36:37 001 Xrd: DoHandShake: HandShake step 1: Sending 20 bytes. 110202 17:36:37 001 Xrd: WriteRaw: Writing to substreamid 0 110202 17:36:37 001 Xrd: DoHandShake: HandShake step 2: Reading 4 bytes. 110202 17:36:37 001 Xrd: ReadRaw: Reading from rcas6202.rcf.bnl.gov:40748 110202 17:36:37 001 Xrd: DoHandShake: HandShake step 3: Reading 12 bytes. 110202 17:36:37 001 Xrd: ReadRaw: Reading from rcas6202.rcf.bnl.gov:40748 110202 17:36:37 001 Xrd: DoHandShake: Server protocol: 657 type: 1 110202 17:36:37 001 Xrd: GetAccessToSrv: Ok, the server on [rcas6202.rcf.bnl.gov:40748] is an xrootd data server. 110202 17:36:37 001 Xrd: StartReader: Starting reader thread... 110202 17:36:37 30669 Xrd: SocketReaderThread: Reader Thread starting. 110202 17:36:37 30669 Xrd: XrdClientMessage::ReadRaw: Reading header (8 bytes). 110202 17:36:37 30669 Xrd: ReadRaw: Reading from rcas6202.rcf.bnl.gov:40748 110202 17:36:37 001 Xrd: DoLogin: Logging into the server [rcas6202.rcf.bnl.gov:40748]. pid=30669 uid=starlib 110202 17:36:37 001 Xrd: SendGenCommand: Sending command XrdClientConn::DoLogin ================= DUMPING CLIENT REQUEST HEADER ================= ClientHeader.streamid = 0x01 0x00 ClientHeader.requestid = kXR_login (3007) ClientHeader.login.pid = 30669 ClientHeader.login_body.username = starlib ClientHeader.login.reserved = 0 repeated 2 times ClientHeader.login.capver = 130 ClientHeader.login.role = 0 ClientHeader.header.dlen = 0 =================== END CLIENT HEADER DUMPING =================== 110202 17:36:37 001 Xrd: WriteRaw: Writing 24 bytes to physical connection 110202 17:36:37 001 Xrd: WriteRaw: Writing to substreamid 0 110202 17:36:37 001 Xrd: ReadPartialAnswer: Reading a XrdClientMessage from the server [rcas6202.rcf.bnl.gov:40748]... 110202 17:36:37 30669 Xrd: XrdClientMessage::ReadRaw: sid: 1, IsAttn: 0, substreamid: 0 110202 17:36:37 30669 Xrd: XrdClientMessage::ReadRaw: Reading data (23 bytes) from substream 0 110202 17:36:37 30669 Xrd: ReadRaw: Reading from rcas6202.rcf.bnl.gov:40748 110202 17:36:37 30669 Xrd: BuildMessage: posting id 1 ======== DUMPING SERVER RESPONSE HEADER ======== ServerHeader.streamid = 0x01 0x00 ServerHeader.status = kXR_ok (0) ServerHeader.dlen = 23 ========== END DUMPING SERVER HEADER =========== 110202 17:36:37 001 Xrd: DoLogin: Got session ID: 04000000ffffff9c6600001600000004000000 110202 17:36:37 001 Xrd: DoLogin: server requires authentication 110202 17:36:37 001 Xrd: DoAuthentication: host rcas6202.rcf.bnl.gov sent a list of 8 bytes 110202 17:36:37 30669 Xrd: XrdClientMessage::ReadRaw: Reading header (8 bytes). sec_Client: protocol request for host rcas6202.rcf.bnl.gov token='&P=unix' sec_PM: Loading unix protocol object from libXrdSecunix.so 110202 17:36:37 30669 Xrd: sec_PM: Using unix protocol, args='' ReadRaw: Reading from rcas6202.rcf.bnl.gov:40748 110202 17:36:37 001 Xrd: DoAuthentication: credentials size: 20 110202 17:36:37 001 Xrd: SendGenCommand: Sending command XrdClientConn::DoAuthentication ================= DUMPING CLIENT REQUEST HEADER ================= ClientHeader.streamid = 0x01 0x00 ClientHeader.requestid = kXR_auth (3000) ClientHeader.auth.reserved = 0 repeated 12 times ClientHeader.auth.credtype= 0x20 0xe7 0x48 0x5e ClientHeader.header.dlen = 20 =================== END CLIENT HEADER DUMPING =================== 110202 17:36:37 001 Xrd: WriteRaw: Writing 24 bytes to physical connection 110202 17:36:37 001 Xrd: WriteRaw: Writing to substreamid 0 110202 17:36:37 001 Xrd: WriteRaw: Writing 20 bytes to physical connection 110202 17:36:37 001 Xrd: WriteRaw: Writing to substreamid 0 110202 17:36:37 001 Xrd: ReadPartialAnswer: Reading a XrdClientMessage from the server [rcas6202.rcf.bnl.gov:40748]... 110202 17:36:37 30669 Xrd: XrdClientMessage::ReadRaw: sid: 1, IsAttn: 0, substreamid: 0 110202 17:36:37 30669 Xrd: BuildMessage: posting id 1 110202 17:36:37 30669 Xrd: XrdClientMessage::ReadRaw: Reading header (8 bytes). 110202 17:36:37 30669 Xrd: ReadRaw: Reading from rcas6202.rcf.bnl.gov:40748 ======== DUMPING SERVER RESPONSE HEADER ======== ServerHeader.streamid = 0x01 0x00 ServerHeader.status = kXR_ok (0) ServerHeader.dlen = 0 ========== END DUMPING SERVER HEADER =========== 110202 17:36:37 001 Xrd: DoAuthentication: server reply: status: 0 dlen: 0 110202 17:36:37 001 Xrd: DoLogin: No prev session info for 130.199.183.205:40748 110202 17:36:37 001 Xrd: Open: Access to server granted. 110202 17:36:37 001 Xrd: Open: Opening the remote file /home/starlib/home/starreco/reco/EmcCheck/ReversedFullField/P08ie/2008/048/9048041/test2.root 110202 17:36:37 001 Xrd: SendGenCommand: Sending command Open ================= DUMPING CLIENT REQUEST HEADER ================= ClientHeader.streamid = 0x01 0x00 ClientHeader.requestid = kXR_open (3010) ClientHeader.open.mode = 0xb4 0x01 ClientHeader.open.options = 0x62 0x05 ClientHeader.open.reserved = 0 repeated 12 times ClientHeader.header.dlen = 93 =================== END CLIENT HEADER DUMPING =================== 110202 17:36:37 001 Xrd: WriteRaw: Writing 24 bytes to physical connection 110202 17:36:37 001 Xrd: WriteRaw: Writing to substreamid 0 110202 17:36:37 001 Xrd: WriteRaw: Writing 93 bytes to physical connection 110202 17:36:37 001 Xrd: WriteRaw: Writing to substreamid 0 110202 17:36:37 001 Xrd: ReadPartialAnswer: Reading a XrdClientMessage from the server [rcas6202.rcf.bnl.gov:40748]... 110202 17:36:37 30669 Xrd: XrdClientMessage::ReadRaw: sid: 1, IsAttn: 0, substreamid: 0 110202 17:36:37 30669 Xrd: XrdClientMessage::ReadRaw: Reading data (43 bytes) from substream 0 110202 17:36:37 30669 Xrd: ReadRaw: Reading from rcas6202.rcf.bnl.gov:40748 110202 17:36:37 30669 Xrd: BuildMessage: posting id 1 110202 17:36:37 30669 Xrd: XrdClientMessage::ReadRaw: Reading header (8 bytes). 110202 17:36:37 30669 Xrd: ReadRaw: Reading from rcas6202.rcf.bnl.gov:40748 ======== DUMPING SERVER RESPONSE HEADER ======== ServerHeader.streamid = 0x01 0x00 ServerHeader.status = kXR_ok (0) ServerHeader.dlen = 43 ========== END DUMPING SERVER HEADER =========== 110202 17:36:37 001 Xrd: Open: Returned stats=75707388528657 0 48 1296686197 110202 17:36:37 001 Xrd: Open: File opened succesfully. 110202 17:36:37 001 Xrd: main: /tmp/test1.root --> root://rcas6202.rcf.bnl.gov:40748//home/starlib/home/starreco/reco/EmcCheck/ReversedFullField/P08ie/2008/048/9048041/test2.root 110202 17:36:37 30669 Xrd: ReaderThread_loc: Reader Thread starting. 110202 17:36:37 001 Xrd: Cache: Submitting 0->445986 to cache as pinned data. ================= DUMPING CLIENT REQUEST HEADER ================= ClientHeader.streamid = 0x02 0x00 ClientHeader.requestid = kXR_write (3019) ClientHeader.write.fhandle = 0x00 0x00 0x00 0x00 ClientHeader.write.offset = 0 ClientHeader.write.pathid = 0 ClientHeader.write.reserved = 0 repeated 3 times ClientHeader.header.dlen = 445987 =================== END CLIENT HEADER DUMPING =================== 110202 17:36:37 001 Xrd: WriteRaw: Writing 24 bytes to physical connection 110202 17:36:37 001 Xrd: WriteRaw: Writing to substreamid 0 110202 17:36:37 001 Xrd: WriteRaw: Writing 445987 bytes to physical connection 110202 17:36:37 001 Xrd: WriteRaw: Writing to substreamid 0 110202 17:37:07 30669 Xrd: DumpPhyConn: Phyconn entry, key='starlib@rcas6202.rcf.bnl.gov:40748', LogCnt=1 Valid 110202 17:37:37 30669 Xrd: DumpPhyConn: Phyconn entry, key='starlib@rcas6202.rcf.bnl.gov:40748', LogCnt=1 Valid 110202 17:38:07 30669 Xrd: DumpPhyConn: Phyconn entry, key='starlib@rcas6202.rcf.bnl.gov:40748', LogCnt=1 Valid 110202 17:38:37 30669 Xrd: DumpPhyConn: Phyconn entry, key='starlib@rcas6202.rcf.bnl.gov:40748', LogCnt=1 Valid 110202 17:39:07 30669 Xrd: DumpPhyConn: Phyconn entry, key='starlib@rcas6202.rcf.bnl.gov:40748', LogCnt=1 Valid 110202 17:39:37 30669 Xrd: DumpPhyConn: Phyconn entry, key='starlib@rcas6202.rcf.bnl.gov:40748', LogCnt=1 Valid 110202 17:40:07 30669 Xrd: DumpPhyConn: Phyconn entry, key='starlib@rcas6202.rcf.bnl.gov:40748', LogCnt=1 Valid 110202 17:40:37 30669 Xrd: DumpPhyConn: Phyconn entry, key='starlib@rcas6202.rcf.bnl.gov:40748', LogCnt=1 Valid 110202 17:41:07 30669 Xrd: DumpPhyConn: Phyconn entry, key='starlib@rcas6202.rcf.bnl.gov:40748', LogCnt=1 Valid 110202 17:41:37 30669 Xrd: DumpPhyConn: Phyconn entry, key='starlib@rcas6202.rcf.bnl.gov:40748', LogCnt=1 Valid 110202 17:41:37 30669 Xrd: ClientSock::RecvRaw: Request timed out 300seconds reading 8 bytes from server rcas6202.rcf.bnl.gov:40748 110202 17:41:37 30669 Xrd: XrdClientMessage::ReadRaw: sid: 0, IsAttn: 0, substreamid: 0 110202 17:41:37 30669 Xrd: BuildMessage: deleting id 0 110202 17:41:37 30669 Xrd: XrdClientMessage::ReadRaw: Reading header (8 bytes). 110202 17:41:37 30669 Xrd: ReadRaw: Reading from rcas6202.rcf.bnl.gov:40748 110202 17:41:38 001 Xrd: SendGenCommand: Sending command Write_checkpoint ================= DUMPING CLIENT REQUEST HEADER ================= ClientHeader.streamid = 0x01 0x00 ClientHeader.requestid = kXR_write (3019) ClientHeader.write.fhandle = 0x00 0x00 0x00 0x00 ClientHeader.write.offset = 0 ClientHeader.write.pathid = 0 ClientHeader.write.reserved = 0 repeated 3 times ClientHeader.header.dlen = 445987 =================== END CLIENT HEADER DUMPING =================== 110202 17:41:38 001 Xrd: WriteRaw: Writing 24 bytes to physical connection 110202 17:41:38 001 Xrd: WriteRaw: Writing to substreamid 0 110202 17:41:38 001 Xrd: WriteRaw: Writing 445987 bytes to physical connection 110202 17:41:38 001 Xrd: WriteRaw: Writing to substreamid 0 110202 17:41:38 001 Xrd: ReadPartialAnswer: Reading a XrdClientMessage from the server [rcas6202.rcf.bnl.gov:40748]... 110202 17:42:07 30669 Xrd: DumpPhyConn: Phyconn entry, key='starlib@rcas6202.rcf.bnl.gov:40748', LogCnt=1 Valid 110202 17:42:37 30669 Xrd: DumpPhyConn: Phyconn entry, key='starlib@rcas6202.rcf.bnl.gov:40748', LogCnt=1 Valid 110202 17:43:07 30669 Xrd: DumpPhyConn: Phyconn entry, key='starlib@rcas6202.rcf.bnl.gov:40748', LogCnt=1 Valid 110202 17:43:37 30669 Xrd: DumpPhyConn: Phyconn entry, key='starlib@rcas6202.rcf.bnl.gov:40748', LogCnt=1 Valid 110202 17:44:07 30669 Xrd: DumpPhyConn: Phyconn entry, key='starlib@rcas6202.rcf.bnl.gov:40748', LogCnt=1 Valid 110202 17:44:37 30669 Xrd: DumpPhyConn: Phyconn entry, key='starlib@rcas6202.rcf.bnl.gov:40748', LogCnt=1 Valid 110202 17:45:07 30669 Xrd: DumpPhyConn: Phyconn entry, key='starlib@rcas6202.rcf.bnl.gov:40748', LogCnt=1 Valid 110202 17:45:37 30669 Xrd: DumpPhyConn: Phyconn entry, key='starlib@rcas6202.rcf.bnl.gov:40748', LogCnt=1 Valid 110202 17:46:07 30669 Xrd: DumpPhyConn: Phyconn entry, key='starlib@rcas6202.rcf.bnl.gov:40748', LogCnt=1 Valid 110202 17:46:37 30669 Xrd: ClientSock::RecvRaw: Request timed out 300seconds reading 8 bytes from server rcas6202.rcf.bnl.gov:40748 110202 17:46:37 30669 Xrd: XrdClientMessage::ReadRaw: sid: 0, IsAttn: 0, substreamid: 0 110202 17:46:37 30669 Xrd: BuildMessage: deleting id 0 110202 17:46:37 30669 Xrd: XrdClientMessage::ReadRaw: Reading header (8 bytes). 110202 17:46:37 30669 Xrd: ReadRaw: Reading from rcas6202.rcf.bnl.gov:40748 110202 17:46:37 30669 Xrd: DumpPhyConn: Phyconn entry, key='starlib@rcas6202.rcf.bnl.gov:40748', LogCnt=1 Valid 110202 17:46:38 001 Xrd: ReadPartialAnswer: Failed to read msg from connmgr (server [rcas6202.rcf.bnl.gov:40748]). Retrying ... 110202 17:46:38 001 Xrd: Cache: Cache Status -------------------------- 110202 17:46:38 001 Xrd: Cache blk: 0Data block 0->445986 (pinned) 110202 17:46:38 001 Xrd: Cache: -------------------------------------- fTotalByteCount = 0 110202 17:46:38 001 Xrd: PhyConnection: Disconnecting socket... 110202 17:46:38 001 Xrd: DumpPhyConn: Phyconn entry, key='starlib@rcas6202.rcf.bnl.gov:40748', LogCnt=1 NotValid 110202 17:46:38 001 Xrd: PhyConnection: Disconnecting socket... 110202 17:46:38 001 Xrd: DumpPhyConn: Phyconn entry, key='Trashed connection', LogCnt=1 NotValid 110202 17:46:38 001 Xrd: Disconnect: LogConnID: 0 destroyed 110202 17:46:38 001 Xrd: HandleServerError: Redir count=1 110202 17:46:38 001 Xrd: SendGenCommand: Max time limit elapsed for request kXR_write. Aborting command. 110202 17:46:38 001 Xrd: SendGenCommand: Sending command Close ================= DUMPING CLIENT REQUEST HEADER ================= ClientHeader.streamid = 0x01 0x00 ClientHeader.requestid = kXR_close (3003) ClientHeader.close.fhandle = 0x00 0x00 0x00 0x00 ClientHeader.close.reserved = 0 repeated 4 times ClientHeader.header.dlen = 0 =================== END CLIENT HEADER DUMPING =================== 110202 17:46:38 001 Xrd: WriteToServer: Unknown logical conn 0 110202 17:46:38 001 Xrd: Cache: Cache Status -------------------------- 110202 17:46:38 001 Xrd: Cache blk: 0Data block 0->445986 110202 17:46:38 001 Xrd: Cache: -------------------------------------- fTotalByteCount = 445987 110202 17:46:38 001 Xrd: HandleServerError: Redir count=2 110202 17:46:38 001 Xrd: SendGenCommand: Max time limit elapsed for request kXR_close. Aborting command. 110202 17:46:38 001 Xrd: Cache: Cache Status -------------------------- 110202 17:46:38 001 Xrd: Cache blk: 0Data block 0->445986 110202 17:46:38 001 Xrd: Cache: -------------------------------------- fTotalByteCount = 445987 Low level caching info: StallsRate=0 StallsCount=0 ReadsCounter=0 BytesUsefulness=0 BytesSubmitted=0 BytesHit=0 XrdClient counters: ReadBytes: 0 WrittenBytes: 445987 WriteRequests: 1 ReadRequests: 0 ReadMisses: 0 ReadHits: 0 ReadMissRate: 0.000000 ReadVRequests: 0 ReadVSubRequests: 0 ReadVSubChunks: 0 ReadVBytes: 0 ReadVAsyncRequests: 0 ReadVAsyncSubRequests: 0 ReadVAsyncSubChunks: 0 ReadVAsyncBytes: 0 ReadAsyncRequests: 0 ReadAsyncBytes: 0