 |
 |
ciao Mario, i guess you are using the gfal2 transfer API in Rucio right ? ( the equivalent to gfal-copy) in gfal2, in the case of the transfer API for xrootd, we don't do much as we just use the xrootd client ( XrdCl::CopyProcess), so we don't touch file offsets. so we may want to investigate if there is a problem in XrdCl. Do you have the logs of the client? If you are using the gfal2 Posix API instead we need to investigate a possible bug there cheers Andrea > Hi Petr, Andy, > > once extra piece of information here: Rucio uses the python bindings to > the gfal library to upload these files, and de-facto always uses the > current stable gfal version that is published on ALRB. Rucio doesn't > implement any other upload by itself. > > Cheers, > Mario > > On 05/09/2019 04:21, Andrew Hanushevsky wrote: >> Hi Petr, >> >> So, look at this line: >> >> 190904 17:02:16 22915 atlasprd.2817:152@[2001:718:401:6e03::1:82] >> ofs_write: 1784104010@6506989258351653185 >> fn=/dpm/farm.particle.cz/home/atlas/atlasdatadisk/rucio/mc15_5TeV/90/9f/EVNT.18960107._035789.pool.root.1.rucio.upload >> Why did the application doing the write specify an offset of >> 5506989258351653185? So, that is the problem and, as you noted, it >> doesn’t matter whether POSC is on or not. Indeed, it’s the first write >> to the file and only the first write that suffers from this problem. So, >> there are two possibilities here: a) there is a bug in the uploader, or >> b) there was a network data corruption that managed to hit the offset >> (somewhat unlikely). >> >> Andy >> >> *From:* Petr Vokac <mailto:[log in to unmask]> >> *Sent:* Wednesday, September 04, 2019 12:19 PM >> *To:* Andrew Hanushevsky <mailto:[log in to unmask]> >> *Cc:* dpm-devel <mailto:[log in to unmask]> ; [log in to unmask] >> <mailto:[log in to unmask]> >> *Subject:* Re: Uploaded file 128TB on filesystem >> >> I configured our diskservers with "ofs.trace write" (I did not yet add >> in xrootd configuraton "ofs.persist hold 0") and today new file appeared >> on one of our storage servers: >> >> *[root@dpmpool1 ~]# grep atlasprd.2817:152 >> /var/log/xrootd/dpmdisk/xrootd.log* >> 190904 17:02:08 1894 XrootdXeq: atlasprd.2817:152@[2001:718:401:6e03::1:82] pub IP64 login as /DC=ch/DC=cern/OU=Organic Units/OU=Users/CN=atlpilo1/CN=614260/CN=Robot: ATLAS Pilot1 >> 190904 17:02:16 22915 atlasprd.2817:152@[2001:718:401:6e03::1:82] ofs_write: 1784104010@6506989258351653185 fn=/dpm/farm.particle.cz/home/atlas/atlasdatadisk/rucio/mc15_5TeV/90/9f/EVNT.18960107._035789.pool.root.1.rucio.upload >> 190904 17:02:16 22915 atlasprd.2817:152@[2001:718:401:6e03::1:82] ofs_write: 262144@262144 fn=/dpm/farm.particle.cz/home/atlas/atlasdatadisk/rucio/mc15_5TeV/90/9f/EVNT.18960107._035789.pool.root.1.rucio.upload >> 190904 17:02:17 22915 atlasprd.2817:152@[2001:718:401:6e03::1:82] ofs_write: 262144@524288 fn=/dpm/farm.particle.cz/home/atlas/atlasdatadisk/rucio/mc15_5TeV/90/9f/EVNT.18960107._035789.pool.root.1.rucio.upload >> 190904 17:02:17 22915 atlasprd.2817:152@[2001:718:401:6e03::1:82] ofs_write: 262144@786432 fn=/dpm/farm.particle.cz/home/atlas/atlasdatadisk/rucio/mc15_5TeV/90/9f/EVNT.18960107._035789.pool.root.1.rucio.upload >> 190904 17:02:17 22915 atlasprd.2817:152@[2001:718:401:6e03::1:82] ofs_write: 262144@1048576 fn=/dpm/farm.particle.cz/home/atlas/atlasdatadisk/rucio/mc15_5TeV/90/9f/EVNT.18960107._035789.pool.root.1.rucio.upload >> 190904 17:02:17 22915 atlasprd.2817:152@[2001:718:401:6e03::1:82] ofs_write: 262144@1310720 fn=/dpm/farm.particle.cz/home/atlas/atlasdatadisk/rucio/mc15_5TeV/90/9f/EVNT.18960107._035789.pool.root.1.rucio.upload >> 190904 17:02:17 22915 atlasprd.2817:152@[2001:718:401:6e03::1:82] ofs_write: 262144@1572864 fn=/dpm/farm.particle.cz/home/atlas/atlasdatadisk/rucio/mc15_5TeV/90/9f/EVNT.18960107._035789.pool.root.1.rucio.upload >> 190904 17:02:17 22915 atlasprd.2817:152@[2001:718:401:6e03::1:82] ofs_write: 262144@1835008 fn=/dpm/farm.particle.cz/home/atlas/atlasdatadisk/rucio/mc15_5TeV/90/9f/EVNT.18960107._035789.pool.root.1.rucio.upload >> 190904 17:02:17 22915 atlasprd.2817:152@[2001:718:401:6e03::1:82] ofs_write: 135000@2097152 fn=/dpm/farm.particle.cz/home/atlas/atlasdatadisk/rucio/mc15_5TeV/90/9f/EVNT.18960107._035789.pool.root.1.rucio.upload >> 190904 17:07:32 2163 XrootdXeq: atlasprd.2817:152@[2001:718:401:6e03::1:82] disc 0:05:24 >> >> *[root@dpmpool1 ~]# ls -la >> /mnt/fs2/atlas/2019-09-04/EVNT.18960107._035789.pool.root.1.rucio.upload.309650.1567609328* >> -rw-rw---- 1 dpmmgr dpmmgr 6506989258351919104 Sep 4 17:02 /mnt/fs2/atlas/2019-09-04/EVNT.18960107._035789.pool.root.1.rucio.upload.309650.1567609328 >> >> *[root@dpmpool1 ~]# du --block-size=1 >> /mnt/fs2/atlas/2019-09-04/EVNT.18960107._035789.pool.root.1.rucio.upload.309650.1567609328* >> 2236416 /mnt/fs2/atlas/2019-09-04/EVNT.18960107._035789.pool.root.1.rucio.upload.309650.1567609328 >> >> This file has first 256kb filled with 0x00 (adler32 up to original size >> 2232152 doesn't match) and this time there is no ofs_Posc in the >> xrootd.log file. >> >> Petr Vokac >> >> On 8/19/19 3:24 AM, Andrew Hanushevsky wrote: >>> Hi Petr, >>> >>> The issue here is that the python script (I believe it's python) is >>> disconnecting without closing the file and then reconnecting and >>> writing at a high offset. The log is pretty clear on that. You can >>> verify by adding "ofs.trace write" to see the write offsets (hough it >>> will produce a lot of output). You can also prohibit reconnection by >>> adding this to the persist directive. >>> >>> ofs.persist hold 0 >>> >>> which would delete the file the moment the client disconnects without >>> closing the file. >>> >>> Andy >>> >>> On Sat, 17 Aug 2019, Petr Vokac wrote: >>> >>>> Today new "65PB" file appeared on our storage and it was again >>>> transferred with xrootd protocol. I can see again same error in the log >>>> file: >>>> >>>> **[root@dpmpool21 ~]# ls -la >>>> /mnt/fs4/atlas/2019-08-17/EVNT.18893579._003197.pool.root.1.rucio.upload.234855.1566031522* >>>> >>>> *-rw-rw---- 1 dpmmgr dpmmgr 72340172838077281 Aug 17 10:48 >>>> /mnt/fs4/atlas/2019-08-17/EVNT.18893579._003197.pool.root.1.rucio.upload.234855.1566031522 >>>> ***[root@dpmpool21 ~]# grep atlasprd.2757 >>>> /var/log/xrootd/dpmdisk/xrootd.log* >>>> ... >>>> 190817 10:47:55 57803 XrootdXeq: >>>> atlasprd.2757:65@[2001:718:401:6e03::1:43] pub IP64 login as >>>> /DC=ch/DC=cern/OU=Organic >>>> Units/OU=Users/CN=atlpilo1/CN=614260/CN=Robot: ATLAS Pilot1 >>>> 190817 10:47:55 61859 XrootdXeq: >>>> atlasprd.2757:66@[2001:718:401:6e03::1:83] pub IP64 login as >>>> /DC=ch/DC=cern/OU=Organic >>>> Units/OU=Users/CN=atlpilo1/CN=614260/CN=Robot: ATLAS Pilot1 >>>> 190817 10:48:52 62233 XrootdXeq: >>>> atlasprd.2757:46@[2001:718:401:6e03::1:72] disc 0:00:58 >>>> 190817 10:48:52 62954 XrootdXeq: >>>> atlasprd.2757:25@[2001:718:401:6e03::1:72] disc 0:03:30 >>>> 190817 10:48:52 57804 XrootdXeq: >>>> atlasprd.2757:28@[2001:718:401:6e03::1:72] pub IP64 login as >>>> /DC=ch/DC=cern/OU=Organic >>>> Units/OU=Users/CN=atlpilo1/CN=614260/CN=Robot: ATLAS Pilot1 >>>> 190817 10:48:52 57804 ofs_Posc: Creator changed from >>>> atlasprd.2757:25@[2001:718:401:6e03::1:72] to >>>> atlasprd.2757:28@[2001:718:401:6e03::1:72] for >>>> /dpm/farm.particle.cz/home/atlas/atlasdatadisk/rucio/mc15_13TeV/8b/f3/EVNT.18893579._003197.pool.root.1.rucio.upload >>>> 190817 10:48:53 57803 XrootdXeq: >>>> atlasprd.2757:46@[2001:718:401:6017:20:0:14:44] pub IP64 login as >>>> /DC=ch/DC=cern/OU=Organic >>>> Units/OU=Users/CN=atlpilo1/CN=614260/CN=Robot: ATLAS Pilot1 >>>> 190817 10:49:01 57818 XrootdXeq: >>>> atlasprd.2757:70@[2001:718:401:6017:20:0:11:11] pub IP64 login as >>>> /DC=ch/DC=cern/OU=Organic >>>> Units/OU=Users/CN=atlpilo1/CN=614260/CN=Robot: ATLAS Pilot1 >>>> 190817 10:49:07 62954 XrootdXeq: >>>> atlasprd.2757:55@[2001:718:401:6e03::1:81] disc 0:10:17 >>>> ... >>>> >>>> Any suggestion how to trace what is causing this behavior? >>>> >>>> Petr >>>> >>>> >>>> On 7/20/19 7:48 AM, Petr Vokac wrote: >>>>> Hi, >>>>> >>>>> I ran the command you sent me >>>>> >>>>> grep "atlasprd.2757:" <logfile> | egrep >>>>> '2001:718:401:6e03::1:21|2001:718:401:6e03::1:32' > <excerpt> >>>>> >>>>> and because the output was not just few lines long I uploaded it to the >>>>> >>>>> https://vokac.web.cern.ch/vokac/tmp/dpmpool22.xrootd.log >>>>> https://vokac.web.cern.ch/vokac/tmp/dpmpool24.xrootd.log >>>>> >>>>> These machines on 2001:718:401:6e03::/64 subnet are in remote location >>>>> (but relatively close with RTT ~ 0.7ms). I can see several ofs_Posc >>>>> occurrences in the logs of our disknodes during "190717 17:xx:xx" time >>>>> period: >>>>> >>>>> http://vokac.web.cern.ch/vokac/tmp/POSC.txt >>>>> >>>>> Petr >>>>> >>>>> On 7/19/19 8:51 PM, Andrew Hanushevsky wrote: >>>>>> Hi Petr, >>>>>> >>>>>> Well, POSC says that the client reconnected for writing so not all >>>>>> went well. Can I get the log output for that occurrence as I >>>>>> previously described? >>>>>> >>>>>> Andy >>>>>> >>>>>> On Fri, 19 Jul 2019, Petr Vokac wrote: >>>>>> >>>>>>> We are using Rucio download client to transfer job outputs (it is >>>>>>> build >>>>>>> on top of gfal2 python interface). >>>>>>> >>>>>>> https://vokac.web.cern.ch/vokac/tmp/dpmpool22.xrootd.log >>>>>>> https://vokac.web.cern.ch/vokac/tmp/dpmpool24.xrootd.log >>>>>>> >>>>>>> this is the full job output unfortunately with minimal gfal2 logging >>>>>>> output. >>>>>>> >>>>>>> https://vokac.web.cern.ch/vokac/tmp/grid.2258136.4.out-from-2001:718:401:6e03::1:21-to-dpmpool22.txt >>>>>>> >>>>>>> >>>>>>> https://vokac.web.cern.ch/vokac/tmp/grid.2255921.7.out-from-2001:718:401:6e03::1:32-to-dpmpool24.txt >>>>>>> >>>>>>> >>>>>>> >>>>>>> It looks like according gfal2 transfer was OK >>>>>>> >>>>>>> 2019-07-17 15:09:17,782 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_xrootd.so loaded with >>>>>>> success >>>>>>> 2019-07-17 15:09:17,782 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_rfio.so loaded with success >>>>>>> 2019-07-17 15:09:17,783 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_gridftp.so loaded with >>>>>>> success >>>>>>> 2019-07-17 15:09:17,783 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_http.so loaded with success >>>>>>> 2019-07-17 15:09:17,783 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_lfc.so loaded with success >>>>>>> 2019-07-17 15:09:17,783 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_file.so loaded with success >>>>>>> 2019-07-17 15:09:17,784 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_sftp.so loaded with success >>>>>>> 2019-07-17 15:09:17,784 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_dcap.so loaded with success >>>>>>> 2019-07-17 15:09:17,784 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_srm.so loaded with success >>>>>>> 2019-07-17 15:09:17,793 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_xrootd.so loaded with >>>>>>> success >>>>>>> 2019-07-17 15:09:17,793 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_rfio.so loaded with success >>>>>>> 2019-07-17 15:09:17,793 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_gridftp.so loaded with >>>>>>> success >>>>>>> 2019-07-17 15:09:17,794 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_http.so loaded with success >>>>>>> 2019-07-17 15:09:17,794 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_lfc.so loaded with success >>>>>>> 2019-07-17 15:09:17,794 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_file.so loaded with success >>>>>>> 2019-07-17 15:09:17,794 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_sftp.so loaded with success >>>>>>> 2019-07-17 15:09:17,794 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_dcap.so loaded with success >>>>>>> 2019-07-17 15:09:17,794 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_srm.so loaded with success >>>>>>> 2019-07-17 15:09:17,795 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_xrootd.so loaded with >>>>>>> success >>>>>>> 2019-07-17 15:09:17,795 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_rfio.so loaded with success >>>>>>> 2019-07-17 15:09:17,795 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_gridftp.so loaded with >>>>>>> success >>>>>>> 2019-07-17 15:09:17,795 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_http.so loaded with success >>>>>>> 2019-07-17 15:09:17,796 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_lfc.so loaded with success >>>>>>> 2019-07-17 15:09:17,796 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_file.so loaded with success >>>>>>> 2019-07-17 15:09:17,796 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_sftp.so loaded with success >>>>>>> 2019-07-17 15:09:17,796 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_dcap.so loaded with success >>>>>>> 2019-07-17 15:09:17,796 | INFO | copytool_out | >>>>>>> gfal2 | connect | >>>>>>> [gfal_module_load] plugin >>>>>>> /usr/lib64/gfal2-plugins//libgfal_plugin_srm.so loaded with success >>>>>>> 2019-07-17 15:09:17,810 | INFO | copytool_out | >>>>>>> gfal2 | __gfal2_copy | Event >>>>>>> triggered: BOTH GFAL2:CORE:COPY LIST:ENTER >>>>>>> 2019-07-17 15:09:17,810 | INFO | copytool_out | >>>>>>> gfal2 | __gfal2_copy | Event >>>>>>> triggered: BOTH GFAL2:CORE:COPY LIST:ITEM >>>>>>> file:///scratch/condor/dir_24031/atlas_HudmF2he/PanDA_Pilot-4419868006/log.18636890._001059.job.log.tgz.1 >>>>>>> >>>>>>> => >>>>>>> root://golias100.farm.particle.cz:1094//dpm/farm.particle.cz/home/atlas/atlasdatadisk/rucio/mc15_13TeV/26/98/log.18636890._001059.job.log.tgz.1.rucio.upload >>>>>>> >>>>>>> 2019-07-17 15:09:17,810 | INFO | copytool_out | >>>>>>> gfal2 | __gfal2_copy | Event >>>>>>> triggered: BOTH GFAL2:CORE:COPY LIST:EXIT >>>>>>> 2019-07-17 15:09:17,811 | INFO | Dummy-2 | >>>>>>> gfal2 | (unknown function) | Event >>>>>>> triggered: BOTH xroot TRANSFER:ENTER >>>>>>> file://localhost///scratch/condor/dir_24031/atlas_HudmF2he/PanDA_Pilot-4419868006/log.18636890._001059.job.log.tgz.1?xrd.gsiusrpxy=/scratch/condor/dir_24031/job.9XONDm6yx7unnoBGSqYX2MjnABFKDmABFKDmSyhTDmEBFKDmqAGN3n.proxy&xrd.wantprot=gsi,unix >>>>>>> >>>>>>> => >>>>>>> root://golias100.farm.particle.cz:1094///dpm/farm.particle.cz/home/atlas/atlasdatadisk/rucio/mc15_13TeV/26/98/log.18636890._001059.job.log.tgz.1.rucio.upload?xrd.gsiusrpxy=/scratch/condor/dir_24031/job.9XONDm6yx7unnoBGSqYX2MjnABFKDmABFKDmSyhTDmEBFKDmqAGN3n.proxy&x >>>>>>> >>>>>>> 2019-07-17 15:09:17,811 | INFO | Dummy-2 | >>>>>>> gfal2 | (unknown function) | Event >>>>>>> triggered: BOTH xroot TRANSFER:TYPE streamed >>>>>>> 2019-07-17 15:11:23,914 | INFO | Dummy-2 | >>>>>>> gfal2 | (unknown function) | Event >>>>>>> triggered: BOTH xroot TRANSFER:EXIT Job finished, [SUCCESS] >>>>>>> >>>>>>> but probably rucio tries to verify checksum (gfal-sum via python >>>>>>> bindings) and it fails >>>>>>> >>>>>>> 2019-07-17 15:15:23,774 | INFO | copytool_out | >>>>>>> pilot.copytool.rucio | copy_out | >>>>>>> stderr = An unknown exception occurred. >>>>>>> Details: Checksum not validated >>>>>>> >>>>>>> because DPM is unable to calculate checksum for 128TB file within >>>>>>> timeout. >>>>>>> >>>>>>> Petr >>>>>>> >>>>>>> On 7/19/19 5:07 AM, Andrew Hanushevsky wrote: >>>>>>>> Hi Petr, >>>>>>>> >>>>>>>> Indeed, it looks like what was used to upload the files (xrdcp?) >>>>>>>> created a very large sparse file by writing with a very large >>>>>>>> offset. >>>>>>>> The clue here is that an anomaly occurred during the write and these >>>>>>>> two messages (lkely each corresponding to each file) tell us >>>>>>>> something.... >>>>>>>> >>>>>>>>> 190717 17:10:39 332092 ofs_Posc: Creator changed from >>>>>>>> atlasprd.2757:90@[2001:718:401:6e03::1:21] to >>>>>>>> atlasprd.2757:39@[2001:718:401:6e03::1:21] for >>>>>>>> >>>>>>>> /dpm/farm.particle.cz/home/atlas/atlasdatadisk/rucio/mc15_13TeV/26/98/ >>>>>>>> >>>>>>>> log.18636890._001059.job.log.tgz.1.rucio.upload >>>>>>>> >>>>>>>>> 190717 17:29:26 14204 ofs_Posc: Creator changed from >>>>>>>> atlasprd.2757:33@[2001:718:401:6e03::1:32] to >>>>>>>> atlasprd.2757:95@[2001:718:401:6e03::1:32] for >>>>>>>> >>>>>>>> /dpm/farm.particle.cz/home/atlas/atlasdatadisk/rucio/mc16_5TeV/09/bc/ >>>>>>>> >>>>>>>> AOD.18595963._000786.pool.root.1.rucio.upload >>>>>>>> >>>>>>>> What the POSC system is saying is that in each case the original >>>>>>>> creator of the file lost contact with the server. It then >>>>>>>> reconnected >>>>>>>> and resumed writing with a successful close. POSC allows this to >>>>>>>> avoid >>>>>>>> network glitches from deleting a file because a network glitch will >>>>>>>> cause the client to reconnect and resume where it left off. This is >>>>>>>> only allowed when the resuming client comes from the same IP >>>>>>>> address, >>>>>>>> has the same process ID, and the same logical name. In this case it >>>>>>>> was "atlasprd.2757". I find that rather odd because it's next to >>>>>>>> impossible for two processes on two different machines to have the >>>>>>>> same process number (i.e. 2757). So, this is why I am wondering if >>>>>>>> this was really an xrdcp or some other program. >>>>>>>> >>>>>>>> We should look to see what these client were actually doing during >>>>>>>> this period as they clearly did not do the right thing when they >>>>>>>> reconnected. So, could you grep out all interactions of these two >>>>>>>> client from the log. Something like: >>>>>>>> >>>>>>>> grep "atlasprd.2757:" <logfile> | egrep >>>>>>>> '2001:718:401:6e03::1:21|2001:718:401:6e03::1:32' > <excerpt> >>>>>>>> >>>>>>>> and send the excerpt to me? >>>>>>>> >>>>>>>> Andy >>>>>>>> >>>>>>>> >>>>>>>> On Thu, 18 Jul 2019, Petr Vokac wrote: >>>>>>>> >>>>>>>>> Hi, >>>>>>>>> >>>>>>>>> our DPM which is using native xrootd 4.9.1 yesterday created two >>>>>>>>> different 128TB files on two different diskservers that were >>>>>>>>> received as >>>>>>>>> a job output from two different worker nodes. The size of original >>>>>>>>> file >>>>>>>>> was few megabytes and when I check beginning of stored files up to >>>>>>>>> original size & checksum everything seems to be OK - except >>>>>>>>> these are >>>>>>>>> sparse files with size 128TB. Original transferred files from WN >>>>>>>>> looked >>>>>>>>> like: >>>>>>>>> >>>>>>>>> mc15_13TeV:log.18636890._001059.job.log.tgz.1 - original size >>>>>>>>> 3101899, adler32 742e1336 >>>>>>>>> mc16_5TeV:AOD.18595963._000786.pool.root.1 - original size >>>>>>>>> 737474514, >>>>>>>>> adler32 dc68cb21 >>>>>>>>> >>>>>>>>> but on our diskservers they were stored as >>>>>>>>> >>>>>>>>> [root@dpmpool22 ~]# ls -l >>>>>>>>> /mnt/fs1/atlas/2019-07-17/log.18636890._001059.job.log.tgz.1.rucio.upload.209928.1563376157 >>>>>>>>> >>>>>>>>> >>>>>>>>> -rw-rw---- 1 dpmmgr dpmmgr 140560257079236 Jul 17 17:11 >>>>>>>>> /mnt/fs1/atlas/2019-07-17/log.18636890._001059.job.log.tgz.1.rucio.upload.209928.1563376157 >>>>>>>>> >>>>>>>>> >>>>>>>>> [root@dpmpool22 ~]# du --block-size=1 >>>>>>>>> /mnt/fs1/atlas/2019-07-17/log.18636890._001059.job.log.tgz.1.rucio.upload.209928.1563376157 >>>>>>>>> >>>>>>>>> >>>>>>>>> 3108864 >>>>>>>>> /mnt/fs1/atlas/2019-07-17/log.18636890._001059.job.log.tgz.1.rucio.upload.209928.1563376157 >>>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>>>> [root@dpmpool24 ~]# ls -l >>>>>>>>> /mnt/fs2/atlas/2019-07-17/AOD.18595963._000786.pool.root.1.rucio.upload.210480.1563377083 >>>>>>>>> >>>>>>>>> >>>>>>>>> -rw-rw---- 1 dpmmgr dpmmgr 139734345056408 Jul 17 17:31 >>>>>>>>> /mnt/fs2/atlas/2019-07-17/AOD.18595963._000786.pool.root.1.rucio.upload.210480.1563377083 >>>>>>>>> >>>>>>>>> >>>>>>>>> [root@dpmpool24 tmp]# du --block-size=1 >>>>>>>>> /mnt/fs2/atlas/2019-07-17/AOD.18595963._000786.pool.root.1.rucio.upload.210480.1563377083 >>>>>>>>> >>>>>>>>> >>>>>>>>> 737480704 >>>>>>>>> /mnt/fs2/atlas/2019-07-17/AOD.18595963._000786.pool.root.1.rucio.upload.210480.1563377083 >>>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>>>> I was told that DPM is not really involved in transfering / storing >>>>>>>>> files with xrootd protocol, so I guess something bad must happened >>>>>>>>> inside XRootD libraries. Do you have any idea why these two >>>>>>>>> transfers >>>>>>>>> generated such extreme files? Unfortunately our xrootd logging is >>>>>>>>> pretty >>>>>>>>> low and I was able to find only info about file creation >>>>>>>>> >>>>>>>>> [root@dpmpool22 ~]# grep log.18636890._001059.job.log.tgz >>>>>>>>> /var/log/xrootd/dpmdisk/xrootd.log >>>>>>>>> 190717 17:10:39 332092 ofs_Posc: Creator changed from >>>>>>>> atlasprd.2757:90@[2001:718:401:6e03::1:21] to >>>>>>>> atlasprd.2757:39@[2001:718:401:6e03::1:21] for >>>>>>>> >>>>>>>> /dpm/farm.particle.cz/home/atlas/atlasdatadisk/rucio/mc15_13TeV/26/98/ >>>>>>>> >>>>>>>> log.18636890._001059.job.log.tgz.1.rucio.upload >>>>>>>>> [root@dpmpool24 tmp]# grep AOD.18595963._000786.pool.root >>>>>>>>> /var/log/xrootd/dpmdisk/xrootd.log >>>>>>>>> 190717 17:29:26 14204 ofs_Posc: Creator changed from >>>>>>>> atlasprd.2757:33@[2001:718:401:6e03::1:32] to >>>>>>>> atlasprd.2757:95@[2001:718:401:6e03::1:32] for >>>>>>>> >>>>>>>> /dpm/farm.particle.cz/home/atlas/atlasdatadisk/rucio/mc16_5TeV/09/bc/AOD.18595963. >>>>>>>> >>>>>>>> >>>>>>>> _000786.pool.root.1.rucio.upload >>>>>>>>> >>>>>>>>> Petr >>>>>>>>> >>>>>>>>> ######################################################################## >>>>>>>>> >>>>>>>>> >>>>>>>>> Use REPLY-ALL to reply to list >>>>>>>>> >>>>>>>>> To unsubscribe from the XROOTD-L list, click the following link: >>>>>>>>> https://listserv.slac.stanford.edu/cgi-bin/wa?SUBED1=XROOTD-L&A=1 >>>>>>>>> >>>>>>>> ######################################################################## >>>>>>>> >>>>>>>> >>>>>>>> Use REPLY-ALL to reply to list >>>>>>>> >>>>>>>> To unsubscribe from the XROOTD-L list, click the following link: >>>>>>>> https://listserv.slac.stanford.edu/cgi-bin/wa?SUBED1=XROOTD-L&A=1 >>>>>>> >>>>>> ######################################################################## >>>>>> >>>>>> Use REPLY-ALL to reply to list >>>>>> >>>>>> To unsubscribe from the XROOTD-L list, click the following link: >>>>>> https://listserv.slac.stanford.edu/cgi-bin/wa?SUBED1=XROOTD-L&A=1 >>>>> >>>>> ------------------------------------------------------------------------ >>>>> >>>>> >>>>> Use REPLY-ALL to reply to list >>>>> >>>>> To unsubscribe from the XROOTD-L list, click the following link: >>>>> https://listserv.slac.stanford.edu/cgi-bin/wa?SUBED1=XROOTD-L&A=1 >>>>> >>>> >> >> ------------------------------------------------------------------------ >> >> Use REPLY-ALL to reply to list >> >> To unsubscribe from the XROOTD-L list, click the following link: >> https://listserv.slac.stanford.edu/cgi-bin/wa?SUBED1=XROOTD-L&A=1 >> ######################################################################## Use REPLY-ALL to reply to list To unsubscribe from the XROOTD-L list, click the following link: https://listserv.slac.stanford.edu/cgi-bin/wa?SUBED1=XROOTD-L&A=1