210209 08:59:58 122 XrdXeq: Worker thread started 210209 08:59:58 121 XrdPfc_File: debug ProcessBlockResponse after failed prefetch on io 0x7f747009c580 disabling prefetching on this io. /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 121 XrdPfc_File: debug ProcessBlockResponse stopping prefetching after io 0x7f747009c580 marked as bad. /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 121 XrdPfc_File: error ProcessBlockResponse block 0x7f747c193da0, idx=0, off=0 error=-42 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 122 XrdSched: Now have 13 workers 210209 08:59:58 106 XrdSched: running inq=0 210209 08:59:58 121 XrdSched: Now have 13 workers 210209 08:59:58 121 XrdSched: running inq=0 210209 08:59:58 114 XrdPfc_File: error ProcessBlockResponse block 0x7f747c1b4d00, idx=6, off=6291456 error=-42 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 123 XrdXeq: Worker thread started 210209 08:59:58 122 XrdSched: running inq=0 210209 08:59:58 124 XrdXeq: Worker thread started 210209 08:59:58 120 XrdPfc_File: error ProcessBlockResponse block 0x7f747c1cdba0, idx=1, off=1048576 error=-42 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 119 XrdPfc_File: error ProcessBlockResponse block 0x7f747c000990, idx=7, off=7340032 error=-42 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 010 XrdPfc_File: error ProcessBlockResponse block 0x7f747c1e2bb0, idx=3, off=3145728 error=-42 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 010 XrdSched: running inq=0 210209 08:59:58 010 XrdPfc_File: error ProcessBlockResponse block 0x7f747000c210, idx=0, off=0 error=-42 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 118 XrdPfc_File: error ProcessBlockResponse block 0x7f747c1cea70, idx=4, off=4194304 error=-42 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 110 XrdPfc_File: error ProcessBlockResponse block 0x7f747c1cf090, idx=5, off=5242880 error=-42 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 106 XrdPfc_File: error ProcessBlockResponse block 0x7f747c1ce090, idx=2, off=2097152 error=-42 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 121 XrdPfc_File: error ProcessBlockResponse block 0x7f747c3dcb10, idx=9, off=9437184 error=-42 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 122 XrdPfc_File: error ProcessBlockResponse block 0x7f747c1b4950, idx=8, off=8388608 error=-42 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 108 XrdPfc_File: error Read() io 0x7f747009c580, block 0 finished with error 42 no message of desired type /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 108 XrdPfc_IO: warning Read() error in File::Read(), exit status=-42, error=no message of desired type https://u29@ccdcalitest10.in2p3.fr:2880//pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out? 210209 08:59:58 108 ofs_read: ulMusset.73:29@ccosvms0007.in2p3.fr Unable to read /https:/ccdcalitest10.in2p3.fr:2880/pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out; no message of desired type 210209 08:59:58 108 ulMusset.73:29@ccosvms0007.in2p3.fr XrootdResponse: 0000 sending err 3005: Unable to read /https:/ccdcalitest10.in2p3.fr:2880/pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out; no message of desired type 210209 08:59:58 108 sysXrdHttp: XrdHttpReq::Error 210209 08:59:58 108 ulMusset.73:29@ccosvms0007.in2p3.fr sysXrdHttp: PostProcessHTTPReq req: 2 reqstate: 2 210209 08:59:58 108 ulMusset.73:29@ccosvms0007.in2p3.fr sysXrdHttp: PostProcessHTTPReq mapping Xrd error [3005] to status code [500] 210209 08:59:58 108 ulMusset.73:29@ccosvms0007.in2p3.fr sysXrdHttp: Sending resp: 500 header len:78 210209 08:59:58 108 sysXrdHttp: Sending 78 bytes 210209 08:59:58 108 sysXrdHttp: Sending 160 bytes 210209 08:59:58 108 sysXrdHttp: XrdHttpReq request ended. 210209 08:59:58 108 sysXrdHttp: Cleanup 210209 08:59:58 108 sysXrdHttp: SSL_shutdown failed 210209 08:59:58 108 sysXrdHttp: Reset 210209 08:59:58 108 sysXrdHttp: XrdHttpReq request ended. 210209 08:59:58 108 XrootdXeq: ulMusset.73:29@ccosvms0007.in2p3.fr disc 0:00:01 (send failure) 210209 08:59:58 108 ulMusset.73:29@ccosvms0007.in2p3.fr XrootdFile: closing r /https:/ccdcalitest10.in2p3.fr:2880/pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 108 ulMusset.73:29@ccosvms0007.in2p3.fr ofs_close: use=1 fn=/https:/ccdcalitest10.in2p3.fr:2880/pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 108 XrdPfc_File: debug ioActive start for io 0x7f747009c580 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 108 XrdPfc_File: info ioActive for io 0x7f747009c580, active_prefetches 0, allow_prefetching False, ioactive_false_reported False, ios_in_detach 0 210209 08:59:58 108 XrdPfc_File: info io_map.size() 1, block_map.size() 0, file /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 108 XrdPfc_File: info ioActive for io 0x7f747009c580 returning False, file /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 108 XrdPfc_IO: info DetachFinalize() 0x7f747009c580 210209 08:59:58 108 XrdPfc_Cache: debug ReleaseFile /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out, io 0x7f747009c580 210209 08:59:58 108 XrdPfc_File: debug RemoveIO() io = 0x7f747009c580 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 108 XrdPfc_Cache: debug dec_ref_cnt /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out, cnt at entry = 1 210209 08:59:58 108 XrdPfc_File: debug FinalizeSyncBeforeExit requesting sync to write detach stats /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 108 XrdPfc_Cache: debug dec_ref_cnt /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out, scheduling final sync 210209 08:59:58 108 XrdPfc_IO: debug ~IOEntireFile() 0x7f747009c580 https://u29@ccdcalitest10.in2p3.fr:2880//pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out? 210209 08:59:58 123 XrdSched[2021-02-09 08:59:58.053760 +0000][Debug ][XrdClHttp ] Closing davix fd: 140138071995648 : running inq=0 210209 08:59:58 108 ulMusset.73:29@ccosvms0007.in2p3.fr XrdPoll: Poller 0 removing FD 29 210209 08:59:58 108 ulMusset.73:29@ccosvms0007.in2p3.fr XrdPoll: FD 29 detached from poller 0; num=0 210209 08:59:58 123 XrdPfc_Cache: debug dec_ref_cnt /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out, cnt at entry = 1 210209 08:59:58 123 XrdPfc_File: debug FinalizeSyncBeforeExit sync not required /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 123 XrdPfc_Cache: debug dec_ref_cnt /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out, cnt after sync_check and dec_ref_cnt = 0 210209 08:59:58 123 XrdPfc_File: debug ~File() close info /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 123 oss_Adjust: used=4028+212 path=/mnt/xcache/metadata/meta/ 210209 08:59:58 123 oss_Adjust: free=21430013896-212 path=/mnt/xcache/metadata/ 210209 08:59:58 123 XrdPfc_File: debug ~File() close output /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 08:59:58 123 XrdPfc_File: debug ~File() ended, prefetch score = 0 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:02:28 025 XrdPfc_Cache: info Purge() Started. 210209 09:02:28 025 XrdPfc_Cache: debug Purge() used disk space 67600384 bytes. 210209 09:02:28 025 XrdPfc_Cache: debug Purge() Precheck: 210209 09:02:28 025 XrdPfc_Cache: debug bytes_to_remove_disk = 0 B 210209 09:02:28 025 XrdPfc_Cache: debug bytes_to remove_files = 0 B (estimated) 210209 09:02:28 025 XrdPfc_Cache: debug bytes_to_remove = 0 B 210209 09:02:28 025 XrdPfc_Cache: debug enforce_age_based_purge = False 210209 09:02:28 025 XrdPfc_Cache: info Purge() Finished, removed 0 data files, total size 0, bytes to remove at end 0, purge duration 0 210209 09:05:27 124 XrdSched: running underused thread monitor inq=0 210209 09:05:27 124 XrdSched: 13 threads; 11 idle 210209 09:05:27 124 XrdSched: scheduling underused thread monitor in 780 seconds 210209 09:05:27 120 XrdSched: terminating thread; workers=12 210209 09:07:28 025 XrdPfc_Cache: info Purge() Started. 210209 09:07:28 025 XrdPfc_Cache: debug Purge() used disk space 67600384 bytes. 210209 09:07:28 025 XrdPfc_Cache: debug Purge() Precheck: 210209 09:07:28 025 XrdPfc_Cache: debug bytes_to_remove_disk = 0 B 210209 09:07:28 025 XrdPfc_Cache: debug bytes_to remove_files = 0 B (estimated) 210209 09:07:28 025 XrdPfc_Cache: debug bytes_to_remove = 0 B 210209 09:07:28 025 XrdPfc_Cache: debug enforce_age_based_purge = False 210209 09:07:28 025 XrdPfc_Cache: info Purge() Finished, removed 0 data files, total size 0, bytes to remove at end 0, purge duration 0 210209 09:12:28 025 XrdPfc_Cache: info Purge() Started. 210209 09:12:28 025 XrdPfc_Cache: debug Purge() used disk space 67600384 bytes. 210209 09:12:28 025 XrdPfc_Cache: debug Purge() Precheck: 210209 09:12:28 025 XrdPfc_Cache: debug bytes_to_remove_disk = 0 B 210209 09:12:28 025 XrdPfc_Cache: debug bytes_to remove_files = 0 B (estimated) 210209 09:12:28 025 XrdPfc_Cache: debug bytes_to_remove = 0 B 210209 09:12:28 025 XrdPfc_Cache: debug enforce_age_based_purge = False 210209 09:12:28 025 XrdPfc_Cache: info Purge() Finished, removed 0 data files, total size 0, bytes to remove at end 0, purge duration 0 210209 09:17:27 008 XrdBuffManager: Reshaper has 2049K; target 800860K 210209 09:17:28 025 XrdPfc_Cache: info Purge() Started. 210209 09:17:28 025 XrdPfc_Cache: debug Purge() used disk space 67600384 bytes. 210209 09:17:28 025 XrdPfc_Cache: debug Purge() Precheck: 210209 09:17:28 025 XrdPfc_Cache: debug bytes_to_remove_disk = 0 B 210209 09:17:28 025 XrdPfc_Cache: debug bytes_to remove_files = 0 B (estimated) 210209 09:17:28 025 XrdPfc_Cache: debug bytes_to_remove = 0 B 210209 09:17:28 025 XrdPfc_Cache: debug enforce_age_based_purge = False 210209 09:17:28 025 XrdPfc_Cache: info Purge() Finished, removed 0 data files, total size 0, bytes to remove at end 0, purge duration 0 210209 09:18:01 116 XrdInet: Accepted connection on port 1094 from 23@ccosvms0007.in2p3.fr 210209 09:18:01 119 XrdSched: running main accept inq=0 210209 09:18:01 116 anon.0:23@ccosvms0007.in2p3.fr sysXrdHttp: received dlen: 16 210209 09:18:01 116 anon.0:23@ccosvms0007.in2p3.fr sysXrdHttp: received dump: 22 03 01 00 -54 01 00 00 -58 03 03 76 11 16 83 00 210209 09:18:01 116 anon.0:23@ccosvms0007.in2p3.fr sysXrdHttp: This does not look like http at pos 0 210209 09:18:01 116 anon.0:23@ccosvms0007.in2p3.fr sysXrdHttp: This may look like https 210209 09:18:01 116 anon.0:23@ccosvms0007.in2p3.fr sysXrdHttp: Protocol matched. https: 1 210209 09:18:01 116 XrdProtLoad: matched port 1094 protocol http 210209 09:18:01 116 anon.0:23@ccosvms0007.in2p3.fr XrdPoll: FD 23 attached to poller 0; num=1 210209 09:18:01 116 anon.0:23@ccosvms0007.in2p3.fr sysXrdHttp: Process. lp:0x7f74a8005650 reqstate: 0 210209 09:18:01 116 anon.0:23@ccosvms0007.in2p3.fr sysXrdHttp: Setting host: [::ffff:134.158.239.7] 210209 09:18:01 116 anon.0:23@ccosvms0007.in2p3.fr sysXrdHttp: Entering SSL_accept... 210209 09:18:01 116 anon.0:23@ccosvms0007.in2p3.fr sysXrdHttp: SSL_accept returned :1 210209 09:18:01 116 cryptossl_X509::CertType: certificate has 3 extensions 210209 09:18:01 116 cryptossl_X509::CertType: certificate has 9 extensions 210209 09:18:01 116 cryptossl_X509::CertType: certificate has 7 extensions 210209 09:18:01 116 anon.0:23@ccosvms0007.in2p3.fr sysXrdHttp: Subject name is : '/O=GRID-FR/C=FR/O=CNRS/OU=CC-IN2P3/CN=Paul Musset' 210209 09:18:01 116 anon.0:23@ccosvms0007.in2p3.fr sysXrdHttp: Extracting auth info. http Protocol 'gsi' http Name 'ulMusset' http Host '[::ffff:134.158.239.7]' http Vorg 'escape' http Role 'NULL' http Grps '/escape' http Caps '' http Pidn '' http Crlen 0 http ueid 0 http uid 0 http gid 0 210209 09:18:01 116 sysXrdHttp: getDataOneShot BuffAvailable: 1048576 maxread: 1048576 210209 09:18:01 116 sysXrdHttp: getDataOneShot sslavail: 1048576 210209 09:18:01 116 sysXrdHttp: read 207 of 1048576 bytes 210209 09:18:01 116 sysXrdHttp: rc:133 got hdr line: GET //https://ccdcalitest10.in2p3.fr:2880/pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out HTTP/1.1 210209 09:18:01 116 sysXrdHttp: Parsing first line: GET //https://ccdcalitest10.in2p3.fr:2880/pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out HTTP/1.1 210209 09:18:01 116 sysXrdHttp: rc:25 got hdr line: User-Agent: curl/7.29.0 210209 09:18:01 116 sysXrdHttp: rc:34 got hdr line: Host: ccosfip00282.in2p3.fr:1094 210209 09:18:01 116 sysXrdHttp: rc:13 got hdr line: Accept: */* 210209 09:18:01 116 sysXrdHttp: rc:2 got hdr line: 210209 09:18:01 116 sysXrdHttp: rc:2 detected header end. 210209 09:18:01 116 XrootdBridge: ulMusset.74:23@ccosvms0007.in2p3.fr login as ulMusset 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr sysXrdHttp: Process. lp:0x7f74a8005650 reqstate: 0 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr XrootdProtocol: 0000 Bridge req=3017 dlen=119 blen=119 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr sysXrdHttp: Process is exiting rc:0 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr ofs_stat: fn=/https:/ccdcalitest10.in2p3.fr:2880/pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr Pss_Stat: url=https://p0@ccdcalitest10.in2p3.fr:2880//pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out? [2021-02-09 09:18:01.932873 +0000][Debug ][XrdClHttp ] HttpFileSystemPlugIn constructed with URL: https://p0@ccdcalitest10.in2p3.fr:2880//pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out. 210209 09:18:01 116 xrootd oss_Open_ufs: fd=524288 flags=0 mode=600 path=/mnt/xcache/ns/pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out.cinfo 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr XrootdProtocol: 0000 rc=0 stat /https:/ccdcalitest10.in2p3.fr:2880/pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr XrootdResponse: 0000 sending 83 data bytes 210209 09:18:01 116 sysXrdHttp: XrdHttpReq::Data! final=0 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr sysXrdHttp: PostProcessHTTPReq req: 2 reqstate: 0 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr sysXrdHttp: Stat for GET /https:/ccdcalitest10.in2p3.fr:2880/pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out stat=72058422966680608 805306368 48 1612861198 1612861198 1612861198 0600 xrootd xrootd 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr sysXrdHttp: Process. lp:0 reqstate: 0 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr XrootdProtocol: 0000 Bridge req=3010 dlen=119 blen=119 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr sysXrdHttp: Process is exiting rc:0 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr XrootdProtocol: 0000 open rt //https://ccdcalitest10.in2p3.fr:2880/pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr ofs_open: 0-600 fn=/https:/ccdcalitest10.in2p3.fr:2880/pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr Pss_Open: url=https://u23@ccdcalitest10.in2p3.fr:2880//pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out? 210209 09:18:01 116 XrdPfc_Cache: info Attach() https://u23@ccdcalitest10.in2p3.fr:2880//pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out? 210209 09:18:01 116 XrdPfc_Cache: debug GetFile /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out, io 0x7f74a81d3150 210209 09:18:01 116 xrootd oss_Open_ufs: fd=524288 flags=0 mode=600 path=/mnt/xcache/ns/pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out.cinfo 210209 09:18:01 116 XrdPfc_IO: info initCachedStat successfuly read size from info file = 805306368 https://u23@ccdcalitest10.in2p3.fr:2880//pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out? 210209 09:18:01 116 xrootd oss_Open_ufs: fd=524288 flags=2 mode=600 path=/mnt/xcache/ns/pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:01 116 xrootd oss_Open_ufs: fd=524289 flags=2 mode=600 path=/mnt/xcache/ns/pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out.cinfo 210209 09:18:01 116 XrdPfc_File: debug Open() Reading existing info file. (data_existed=True, data_size_stat=0, data_size_from_last_block=0) /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:01 116 XrdPfc_Cache: debug inc_ref_cnt /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out, cnt at exit = 1 210209 09:18:01 116 XrdPfc_File: debug AddIO() io = 0x7f74a81d3150 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:01 116 XrdPfc_Cache: debug Attach() https://u23@ccdcalitest10.in2p3.fr:2880//pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out? location: 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr ofs_fstat: fn=/https:/ccdcalitest10.in2p3.fr:2880/pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr XrootdResponse: 0000 sending 94 data bytes; status=0 210209 09:18:01 116 sysXrdHttp: XrdHttpReq::Data! final=1 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr sysXrdHttp: PostProcessHTTPReq req: 2 reqstate: 1 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr sysXrdHttp: fhandle:0:0:0:0 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr sysXrdHttp: Sending resp: 200 header len:70 210209 09:18:01 116 sysXrdHttp: Sending 70 bytes 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr sysXrdHttp: Process. lp:0 reqstate: 1 210209 09:18:01 116 sysXrdHttp: XrdBridge::SetSF(false) failed. 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr XrootdProtocol: 0000 Bridge req=3013 dlen=0 blen=0 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr sysXrdHttp: Process is exiting rc:0 210209 09:18:01 116 ulMusset.74:23@ccosvms0007.in2p3.fr XrootdProtocol: 0000 0 fh=0 read 1048576@0 [2021-02-09 09:18:01.934390 +0000][Debug ][XrdClHttp ] HttpFilePlugin constructed. [2021-02-09 09:18:01.934456 +0000][Debug ][XrdClHttp ] Open: URL: https://u23@ccdcalitest10.in2p3.fr:2880//pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out?, XRootD flags: 16, POSIX flags: 0 [2021-02-09 09:18:02.028282 +0000][Debug ][XrdClHttp ] Opened: https://u23@ccdcalitest10.in2p3.fr:2880//pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out? [2021-02-09 09:18:02.064020 +0000][Debug ][XrdClHttp ] Stat-ed URL: https://u23@ccdcalitest10.in2p3.fr:2880//pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out? 210209 09:18:02 023 XrdPfc_IO: info Update() https://u23@ccdcalitest10.in2p3.fr:2880//pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out? location: [2021-02-09 09:18:02.307847 +0000][Debug ][XrdClHttp ] Read 1048576 bytes, at offset 0, from URL: https://u23@ccdcalitest10.in2p3.fr:2880//pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out? 210209 09:18:02 114 XrdSched: running inq=6 210209 09:18:02 114 XrdPfc_File: debug ProcessBlockResponse after failed prefetch on io 0x7f74a81d3150 disabling prefetching on this io. /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:02 114 XrdPfc_File: debug ProcessBlockResponse stopping prefetching after io 0x7f74a81d3150 marked as bad. /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:02 114 XrdPfc_File: error ProcessBlockResponse block 0x7f747cce80d0, idx=1, off=1048576 error=-42 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:02 114 XrdSched: running inq=6 210209 09:18:02 114 XrdPfc_File: error ProcessBlockResponse block 0x7f747cce9250, idx=2, off=2097152 error=-42 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:02 114 XrdSched: running inq=5 210209 09:18:02 114 XrdPfc_File: error ProcessBlockResponse block 0x7f747c150420, idx=3, off=3145728 error=-42 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:02 114 XrdSched: running inq=4 210209 09:18:02 114 XrdPfc_File: error ProcessBlockResponse block 0x7f747c14d080, idx=4, off=4194304 error=-42 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:02 114 XrdSched: running inq=3 210209 09:18:02 114 XrdPfc_File: error ProcessBlockResponse block 0x7f747cce8db0, idx=5, off=5242880 error=-42 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:02 114 XrdSched: running inq=2 210209 09:18:02 114 XrdPfc_File: error ProcessBlockResponse block 0x7f747ccdbed0, idx=6, off=6291456 error=-42 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:02 114 XrdSched: running inq=1 210209 09:18:02 114 XrdPfc_File: error ProcessBlockResponse block 0x7f747c120c30, idx=7, off=7340032 error=-42 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:02 010 XrdSched: running inq=0 210209 09:18:02 010 XrdPfc_File: error ProcessBlockResponse block 0x7f747ccdc190, idx=8, off=8388608 error=-42 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:02 116 ulMusset.74:23@ccosvms0007.in2p3.fr XrootdResponse: 0000 sending 1048576 data bytes 210209 09:18:02 116 sysXrdHttp: XrdHttpReq::Data! final=1 210209 09:18:02 116 ulMusset.74:23@ccosvms0007.in2p3.fr sysXrdHttp: PostProcessHTTPReq req: 2 reqstate: 2 210209 09:18:02 116 ulMusset.74:23@ccosvms0007.in2p3.fr sysXrdHttp: Got data vectors to send:1 210209 09:18:02 116 sysXrdHttp: Sending 1048576 bytes 210209 09:18:02 116 ulMusset.74:23@ccosvms0007.in2p3.fr sysXrdHttp: Process. lp:0 reqstate: 2 210209 09:18:02 116 sysXrdHttp: XrdBridge::SetSF(false) failed. 210209 09:18:02 116 ulMusset.74:23@ccosvms0007.in2p3.fr XrootdProtocol: 0000 Bridge req=3013 dlen=0 blen=0 210209 09:18:02 116 ulMusset.74:23@ccosvms0007.in2p3.fr sysXrdHttp: Process is exiting rc:0 210209 09:18:02 116 ulMusset.74:23@ccosvms0007.in2p3.fr XrootdProtocol: 0000 0 fh=0 read 1048576@1048576 210209 09:18:02 123 XrdSched: running inq=0 210209 09:18:02 123 XrdPfc_File: error ProcessBlockResponse block 0x7f74a80f2360, idx=1, off=1048576 error=-42 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:02 116 XrdPfc_File: error Read() io 0x7f74a81d3150, block 1 finished with error 42 no message of desired type /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:02 116 XrdPfc_IO: warning Read() error in File::Read(), exit status=-42, error=no message of desired type https://u23@ccdcalitest10.in2p3.fr:2880//pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out? 210209 09:18:02 116 ofs_read: ulMusset.74:23@ccosvms0007.in2p3.fr Unable to read /https:/ccdcalitest10.in2p3.fr:2880/pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out; no message of desired type 210209 09:18:02 116 ulMusset.74:23@ccosvms0007.in2p3.fr XrootdResponse: 0000 sending err 3005: Unable to read /https:/ccdcalitest10.in2p3.fr:2880/pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out; no message of desired type 210209 09:18:02 116 sysXrdHttp: XrdHttpReq::Error 210209 09:18:02 116 ulMusset.74:23@ccosvms0007.in2p3.fr sysXrdHttp: PostProcessHTTPReq req: 2 reqstate: 3 210209 09:18:02 116 ulMusset.74:23@ccosvms0007.in2p3.fr sysXrdHttp: PostProcessHTTPReq mapping Xrd error [3005] to status code [500] 210209 09:18:02 116 ulMusset.74:23@ccosvms0007.in2p3.fr sysXrdHttp: Stopping request because more data is expected but no data has been read. 210209 09:18:02 116 sysXrdHttp: XrdHttpReq request ended. 210209 09:18:02 116 sysXrdHttp: Cleanup 210209 09:18:02 116 sysXrdHttp: SSL_shutdown failed 210209 09:18:02 116 sysXrdHttp: Reset 210209 09:18:02 116 sysXrdHttp: XrdHttpReq request ended. 210209 09:18:02 116 XrootdXeq: ulMusset.74:23@ccosvms0007.in2p3.fr disc 0:00:01 (send failure) 210209 09:18:02 116 ulMusset.74:23@ccosvms0007.in2p3.fr XrootdFile: closing r /https:/ccdcalitest10.in2p3.fr:2880/pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:02 116 ulMusset.74:23@ccosvms0007.in2p3.fr ofs_close: use=1 fn=/https:/ccdcalitest10.in2p3.fr:2880/pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:02 116 XrdPfc_File: debug ioActive start for io 0x7f74a81d3150 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:02 116 XrdPfc_File: info ioActive for io 0x7f74a81d3150, active_prefetches 0, allow_prefetching False, ioactive_false_reported False, ios_in_detach 0 210209 09:18:02 116 XrdPfc_File: info io_map.size() 1, block_map.size() 0, file /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:02 116 XrdPfc_File: info ioActive for io 0x7f74a81d3150 returning False, file /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:02 116 XrdPfc_IO: info DetachFinalize() 0x7f74a81d3150 210209 09:18:02 116 XrdPfc_Cache: debug ReleaseFile /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out, io 0x7f74a81d3150 210209 09:18:02 116 XrdPfc_File: debug RemoveIO() io = 0x7f74a81d3150 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:02 116 XrdPfc_Cache: debug dec_ref_cnt /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out, cnt at entry = 1 210209 09:18:02 116 XrdPfc_File: debug FinalizeSyncBeforeExit requesting sync to write detach stats /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:02 116 XrdPfc_Cache: debug dec_ref_cnt /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out, scheduling final sync 210209 09:18:02 116 XrdPfc_IO: debug ~IOEntireFile() 0x7f74a81d3150 https://u23@ccdcalitest10.in2p3.fr:2880//pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out? 210209 09:18:02 116 Posix_PrepIODisable: Disabling defered open https://u23@ccdcalitest10.in2p3.fr:2880//pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out? [2021-02-09 09:18:02.325906 +0000][Debug ][XrdClHttp ] Closing davix fd: 140138275199280 210209 09:18:02 124 XrdSched: running inq=0 210209 09:18:02 116 ulMusset.74:23@ccosvms0007.in2p3.fr XrdPoll: Poller 0 removing FD 23 210209 09:18:02 116 ulMusset.74:23@ccosvms0007.in2p3.fr XrdPoll: FD 23 detached from poller 0; num=0 210209 09:18:02 124 XrdPfc_Cache: debug dec_ref_cnt /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out, cnt at entry = 1 210209 09:18:02 124 XrdPfc_File: debug FinalizeSyncBeforeExit sync not required /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:02 124 XrdPfc_Cache: debug dec_ref_cnt /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out, cnt after sync_check and dec_ref_cnt = 0 210209 09:18:02 124 XrdPfc_File: debug ~File() close info /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:02 124 oss_Adjust: used=4240+56 path=/mnt/xcache/metadata/meta/ 210209 09:18:02 124 oss_Adjust: free=21430079488-56 path=/mnt/xcache/metadata/ 210209 09:18:02 124 XrdPfc_File: debug ~File() close output /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out 210209 09:18:02 124 oss_Adjust: used=4042260480+1048576 path=/mnt/xcache/storage/data0/data/ 210209 09:18:02 124 oss_Adjust: free=21430534144-1048576 path=/mnt/xcache/storage/data0/ 210209 09:18:02 124 XrdPfc_File: debug ~File() ended, prefetch score = 0.111111 /pnfs/in2p3.fr/data/escape/cc_in2p3_dcache/NESSIE/35/6b/test_iorandom_768MB_8.out