[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.1567609328This 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.
[log in to unmask] type="cite">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 fromatlasprd.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 fromatlasprd.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,atlasprd.2757:90@[2001:718:401:6e03::1:21] to
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: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
atlasprd.2757:33@[2001:718:401:6e03::1:32] to
[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: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