Good morning,
Regarding the problem above, it seems that it doesn’t happen so much after upgrading the client to version 5.2.22. Although, we had a similar case at the occasion of the unwanted reboot of an FST. The fusex client doesn’t correctly recover is this situation. Could it be because they are running a user mount ?
I have another interesting case of an unwanted behaviour when writing files with fusex (big files it seems it that case, above 20GB) which causes an increase of the load average of the FSTs, so kind of worrying situation.
The files fails to be finalised, and the eosxd clients sends some additional requests every minute for ever (can be days, which tends to cause the FST to read the whole file (which is big) every time.
The files is in status fuse::missingcommits (sys.fusex.state="|>⚌U±U±U±U±U±U±U±U±U±U±U±UUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUU+3483s|c|"), although it seems to be correctly finished (i.e readable).
The output of the eos fs status of the FS containing the file can give very high stat.wopen.hotfiles numbers And the fs has a high read rate onthe disk (causing high load average on the FST)
stat.disk.load := 0.807891
stat.disk.readratemb := 206.006678
stat.wopen.hotfiles := 54:a902f2e6
Here are the logs of the eosx client :
240420 01:48:53 t=1713570533.265490 f=DumpStatistic l=WARN tid=00007fdab47ff700 s=eosfuse:2389 IO unblock on ino=0x80000000a902f2e6 for op=write since 1180.00 ms { /eos/jeodpp/data/projects/path/to/2008_v10_ERA5LP.nc [root://AAAAAIEM@fst-026.cidsn.jrc.it:1095//fusex-open?cap.msg=qPFuqcArwW0OMB5N8IJ7+ycmP1zAR9lwdftRAgsvTeCRHDyDXDWjj3kQywjSj5sxY2Sbrm82jcG5TRkbFZkf+oTKElogmfEd/ogPvP6t9Beg9Oc9WSsFGL8EdH0heI+2RJ5AqUM/CyxAeDdo7lvoCgfHCX9ksbUhkz642xqsqNqalN6qG8IMwZuoUshHV1AaqaEKCQcl6H9+ifRHWuWjDJR5p7EBuWy2Q/BTHaZjj0Us2letZBgg0jFPbCwYTjVXs0FA5ueFsJVFGqKPLObyRlgzzhL43902riPhfI/UvPaUJ4L9hk8TF6h4TJ+mMnpftPt9DfgsBQ6HfNxCeX1EzPUU0/ph0q+XH1RQ8qYVEQ5HCJA0mMCf9STxbJesjbB2QxE3LqKOffny3UTtVJdnBHa0cTGtCs5VeBMbRmm2/i8q6bUD2BE1CUK0SlU69AV+MJ6bfNppC713vMgGbmHmTFRG79zNT3TSNX0MnxBLK2YpP5s+IqY/7buxaIOE0IWRRHU11VoEbyWNYx9XtHK0TR7CYHhivhKtsMqOaB5DEmy0HI2dS2HM3KHjFp40gohMkUdH5WdL/q6PyEX3VhLjuYTDC93b9msE0qe8KlggNV5sKrGAmEpsjcB7wuhTVJj5&cap.sym=nq9z3fi7CoSgkW2BJuOkw28sFZo=&eos.app=fuse::jhub&eos.bookingsize=0&eos.clientinfo=zbase64:MDAwMDAwNjh4nBXIbQqAIAyA4at0gcSkDxJ2mNKNFqEyF9Hty3/P++aCyYuCM8vYcfb7A5yoqYYDI9hGfQvCfhOhYGyjCGeISNt9aet/s2BQoKq9dbMJHGsypwTD6ge7Th923yQb&eos.lfn=ino:80000000a902f2e6&fuse.exe=python3.10&fuse.gid=35637&fuse.pid=20235&fuse.uid=35637&fuse.ver=5.1.21&mgm.fusex=1&mgm.id=a902f2e6&mgm.logid=dd77d7ee-fea4-11ee-bd0f-48df374dec7c&mgm.mtime=0&mgm.replicahead=0&mgm.replicaindex=0&xrd.k5ccname=/tmp/krb5cc_35637&xrd.wantprot=krb5,unix&xrdcl.requuid=cc6f2d89-685d-4fa6-b10f-71c0bd04df62&xrdcl.secgid=35637&xrdcl.secuid=35637 ] }
240420 01:50:14 t=1713570614.981235 f=HandleResponse l=CRIT tid=00007fdaa7ff3700 s=xrdclproxy:741 1818c210 current status = 4 - setting CLOSEFAILED - msg=[ERROR] Operation expired url=root://AAAAAIEM@eos-jeodpp:1094//fusex-open?eos.app=fuse::jhub&eos.bookingsize=0&eos.lfn=ino:80000000a902f2e6&fuse.exe=python3.10&fuse.gid=35637&fuse.pid=20235&fuse.uid=35637&fuse.ver=5.1.21&mgm.fusex=1&mgm.mtime=0&xrd.k5ccname=/tmp/krb5cc_35637&xrd.wantprot=krb5,unix&xrdcl.secgid=35637&xrdcl.secuid=35637
240420 01:50:15 t=1713570615.003882 f=ioflush l=WARN tid=00007fdab83f3700 s=data:3323 re-issuing OpenAsync request after timeout - ino:80000000a902f2e6 err-code:206
240420 01:51:16 t=1713570676.152088 f=HandleResponse l=CRIT tid=00007fdaaa7f8700 s=xrdclproxy:741 8e4da010 current status = 4 - setting CLOSEFAILED - msg=[ERROR] Operation expired url=root://AAAAAIEM@eos-jeodpp:1094//fusex-open?eos.app=fuse::jhub&eos.bookingsize=0&eos.lfn=ino:80000000a902f2e6&fuse.exe=python3.10&fuse.gid=35637&fuse.pid=20235&fuse.uid=35637&fuse.ver=5.1.21&mgm.fusex=1&mgm.mtime=0&xrd.k5ccname=/tmp/krb5cc_35637&xrd.wantprot=krb5,unix&xrdcl.secgid=35637&xrdcl.secuid=35637
240420 01:51:16 t=1713570676.153217 f=ioflush l=WARN tid=00007fdab83f3700 s=data:3323 re-issuing OpenAsync request after timeout - ino:80000000a902f2e6 err-code:206
...
240426 11:29:26 t=1714123766.885375 f=HandleResponse l=CRIT tid=00007fdaa7ff3700 s=xrdclproxy:741 4e4f2410 current status = 4 - setting CLOSEFAILED - msg=[ERROR] Operation expired url=root://AAAAAIEM@eos-jeodpp:1094//fusex-open?eos.app=fuse::jhub&eos.bookingsize=0&eos.lfn=ino:80000000a902f2e6&fuse.exe=python3.10&fuse.gid=35637&fuse.pid=20235&fuse.uid=35637&fuse.ver=5.1.21&mgm.fusex=1&mgm.mtime=0&xrd.k5ccname=/tmp/krb5cc_35637&xrd.wantprot=krb5,unix&xrdcl.secgid=35637&xrdcl.secuid=35637
240426 11:29:26 t=1714123766.910598 f=ioflush l=WARN tid=00007fdab83f3700 s=data:3323 re-issuing OpenAsync request after timeout - ino:80000000a902f2e6 err-code:206
On the FST side, the logs are these ones :
240426 11:47:00 time=1714124820.001776 func=Close level=ERROR logid=3d5dd8dc-03a7-11ef-ad48-48df374dec7c unit=fst@fst-026.cidsn.jrc.it:1095 tid=00007f6127ffa700 source=ReplicaParLayout:473 tident=AAAAAIEM.1248:163@gpu-004 sec=unix uid=0 gid=0 name=root geo="" msg="failed to close replica 1" url="root://fst-024.cidsn.jrc.it:1095///fusex-open?&cap.msg=qPFuqcArwW0OMB5N8IJ7+ycmP1zAR9lwdftRAgsvTeCRHDyDXDWjj3kQywjSj5sxY2Sbrm82jcG5TRkbFZkf+oTKElogmfEd/ogPvP6t9Beg9Oc9WSsFGL8EdH0heI+2RJ5AqUM/CyxAeDdo7lvoCgfHCX9ksbUhkz642xqsqNqalN6qG8IMwZuoUshHV1AaqaEKCQcl6H9+ifRHWuWjDJR5p7EBuWy2Q/BTHaZjj0Us2letZBgg0jFPbCwYTjVXs0FA5ueFsJVFGqKPLObyRlgzzhL43902riPhfI/UvPaUJ4L9hk8TF6h4TJ+mMnpftPt9DfgsBQ6HfNxCeX1EzPUU0/ph0q+XH1RQ8qYVEQ5HCJA0mMCf9STxbJesjbB2QxE3LqKOffny3UTtVJdnBHa0cTGtCs5VeBMbRmm2/i8q6bUD2BE1CUK0SlU69AV+MJ6bfNppC713vMgGbmHmTFRG79zNT3TSNX0MnxBLK2YpP5s+IqY/7buxaIOE0IWRRHU11VoEbyWNYx9XtHK0TR7CYHhivhKtsMqOaB5DEmy0HI2dS2HM3KHjFp40gohMkUdH5WdL/q6PyEX3VhLjuYTDC93b9msE0qe8KlggNV4778cbPkdIcbqHah36Q6qE&cap.sym=nq9z3fi7CoSgkW2BJuOkw28sFZo=&eos.app=fuse::jhub&eos.bookingsize=0&eos.clientinfo=zbase64:MDAwMDAwNjh4nBXIYQqAIAxA4at0gcSEBIUdpnSjRajMRXT78t/3Xm1Yoig448PENe4PcKGhng7MYAf1bQj7TYSCeYwmXCEjbfelo//NgkmBus7WeZM492JOSYY1LjasH3hSJB8=&eos.lfn=ino:80000000a902f2e6&fuse.exe=python3.10&fuse.gid=35637&fuse.pid=20235&fuse.uid=35637&fuse.ver=5.1.21&mgm.fusex=1&mgm.id=a902f2e6&mgm.logid=3d5dd8dc-03a7-11ef-ad48-48df374dec7c&mgm.mtime=0&mgm.replicahead=0&mgm.replicaindex=1&xrd.k5ccname=/tmp/krb5cc_35637&xrd.wantprot=krb5,unix&mgm.path=/fusex-open"
240426 11:47:00 time=1714124820.002064 func=_close level=INFO logid=static.............................. unit=fst@fst-026.cidsn.jrc.it:1095 tid=00007f6127ffa700 source=XrdFstOfsFile:2025 tident= sec=(null) uid=99 gid=99 name=- geo="" msg="log=3d5dd8dc-03a7-11ef-ad48-48df374dec7c&path=/eos/jeodpp/data/projects/path/to/2008_v10_ERA5LP.nc&fstpath=/data57/000453a2/a902f2e6&ruid=35637&rgid=50007&td=AAAAAIEM.1248:163@gpu-004&host=fst-026.cidsn.jrc.it&lid=1048850&fid=2835542758&fsid=3483&ots=1714123705&otms=696&cts=1714124820&ctms=1&nrc=81426&nwc=0&rb=0&rb_min=0&rb_max=0&rb_sigma=0.00&rv_op=0&rvb_min=0&rvb_max=0&rvb_sum=0&rvb_sigma=0.00&rs_op=0&rsb_min=0&rsb_max=0&rsb_sum=0&rsb_sigma=0.00&rc_min=0&rc_max=0&rc_sum=0&rc_sigma=0.00&wb=0&wb_min=0&wb_max=0&wb_sigma=0.00&sfwdb=3476088186470400&sbwdb=0&sxlfwdb=3476088186470400&sxlbwdb=0&nfwds=81425&nbwds=0&nxlfwds=81425&nxlbwds=0&usage=33.29&iot=1114305.750&idt=743334.625&lrt=0.000&lrvt=0.000&lwt=0.000&ot=3.346&ct=370967.807&rt=243054.84&rvt=0.00&wt=0.00&osize=85380611281&csize=85380611281&delete_on_close=0&prio_c=2&prio_l=4&prio_d=1&forced_bw=0&ms_sleep=0&ior_err=0&iow_err=0&sec.prot=krb5&sec.name=userproc&sec.host=gpu-004.cidsn.jrc.it&sec.vorg=&sec.grps=&sec.role=&sec.info=&sec.app=fuse::jhub"
240426 11:48:00 time=1714124880.001942 func=MgmSyncer level=INFO logid=static.............................. unit=fst@fst-026.cidsn.jrc.it:1095 tid=00007f6116bff700 source=MgmSyncer:94 tident= sec=(null) uid=99 gid=99 name=- geo="" fxid=a902f2e6 mtime=1713571196
And on the MGM :
40426 11:49:27 time=1714124967.237765 func=open level=INFO logid=453baa10-03b2-11ef-b891-48df374dec7c unit=mgm@s-jrciprjeop214p.cidsn.jrc.it:1094 tid=00007ef8993fb700 source=XrdMgmOfsFile:549 tident=AAAAAIEM.1248:747@gpu-004 sec=krb5 uid=35637 gid=50007 name=userproc geo="JRC::DC1" op=write trunc=0 path=ino:80000000a902f2e6 info=eos.app=fuse::jhub&eos.bookingsize=0&eos.lfn=ino:80000000a902f2e6&fuse.exe=python3.10&fuse.gid=35637&fuse.pid=20235&fuse.uid=35637&fuse.ver=5.1.21&mgm.fusex=1&mgm.mtime=0&xrd.k5ccname=/tmp/krb5cc_35637&xrd.wantprot=krb5,unix
240426 11:49:27 time=1714124967.238007 func=open level=INFO logid=453baa10-03b2-11ef-b891-48df374dec7c unit=mgm@s-jrciprjeop214p.cidsn.jrc.it:1094 tid=00007ef8993fb700 source=XrdMgmOfsFile:590 tident=AAAAAIEM.1248:747@gpu-004 sec=krb5 uid=35637 gid=50007 name=userproc geo="JRC::DC1" msg="access by inode" ino=ino:80000000a902f2e6 path=/eos/jeodpp/data/projects/path/to/2008_v10_ERA5LP.nc
240426 11:49:27 time=1714124967.239539 func=open level=INFO logid=453baa10-03b2-11ef-b891-48df374dec7c unit=mgm@s-jrciprjeop214p.cidsn.jrc.it:1094 tid=00007ef8993fb700 source=XrdMgmOfsFile:3201 tident=AAAAAIEM.1248:747@gpu-004 sec=krb5 uid=35637 gid=50007 name=userproc geo="JRC::DC1" op=write path=/eos/jeodpp/data/projects/path/to/2008_v10_ERA5LP.nc info=eos.app=fuse::jhub&eos.bookingsize=0&eos.lfn=ino:80000000a902f2e6&fuse.exe=python3.10&fuse.gid=35637&fuse.pid=20235&fuse.uid=35637&fuse.ver=5.1.21&mgm.fusex=1&mgm.mtime=0&xrd.k5ccname=/tmp/krb5cc_35637&xrd.wantprot=krb5,unix target[0]=(fst-026.cidsn.jrc.it,3483) target[1]=(fst-024.cidsn.jrc.it,3363) redirection=fst-026.cidsn.jrc.it?&cap.sym=<...>&cap.msg=<...>&mgm.logid=453baa10-03b2-11ef-b891-48df374dec7c&mgm.replicaindex=0&mgm.replicahead=0&mgm.id=a902f2e6&mgm.mtime=0 xrd_port=1095 http_port=8001
240426 11:50:27 time=1714125027.341407 func=open level=INFO logid=690ec134-03b2-11ef-8acf-48df374dec7c unit=mgm@s-jrciprjeop214p.cidsn.jrc.it:1094 tid=00007f4b4dffa700 source=XrdMgmOfsFile:549 tident=AAAAAIEM.1248:747@gpu-004 sec=krb5 uid=35637 gid=50007 name=userproc geo="JRC::DC1" op=write trunc=0 path=ino:80000000a902f2e6 info=eos.app=fuse::jhub&eos.bookingsize=0&eos.lfn=ino:80000000a902f2e6&fuse.exe=python3.10&fuse.gid=35637&fuse.pid=20235&fuse.uid=35637&fuse.ver=5.1.21&mgm.fusex=1&mgm.mtime=0&xrd.k5ccname=/tmp/krb5cc_35637&xrd.wantprot=krb5,unix
240426 11:50:27 time=1714125027.341616 func=open level=INFO logid=690ec134-03b2-11ef-8acf-48df374dec7c unit=mgm@s-jrciprjeop214p.cidsn.jrc.it:1094 tid=00007f4b4dffa700 source=XrdMgmOfsFile:590 tident=AAAAAIEM.1248:747@gpu-004 sec=krb5 uid=35637 gid=50007 name=userproc geo="JRC::DC1" msg="access by inode" ino=ino:80000000a902f2e6 path=/eos/jeodpp/data/projects/path/to/2008_v10_ERA5LP.nc
240426 11:50:27 time=1714125027.343065 func=open level=INFO logid=690ec134-03b2-11ef-8acf-48df374dec7c unit=mgm@s-jrciprjeop214p.cidsn.jrc.it:1094 tid=00007f4b4dffa700 source=XrdMgmOfsFile:3201 tident=AAAAAIEM.1248:747@gpu-004 sec=krb5 uid=35637 gid=50007 name=userproc geo="JRC::DC1" op=write path=/eos/jeodpp/data/projects/path/to/2008_v10_ERA5LP.nc info=eos.app=fuse::jhub&eos.bookingsize=0&eos.lfn=ino:80000000a902f2e6&fuse.exe=python3.10&fuse.gid=35637&fuse.pid=20235&fuse.uid=35637&fuse.ver=5.1.21&mgm.fusex=1&mgm.mtime=0&xrd.k5ccname=/tmp/krb5cc_35637&xrd.wantprot=krb5,unix target[0]=(fst-026.cidsn.jrc.it,3483) target[1]=(fst-024.cidsn.jrc.it,3363) redirection=fst-026.cidsn.jrc.it?&cap.sym=<...>&cap.msg=<...>&mgm.logid=690ec134-03b2-11ef-8acf-48df374dec7c&mgm.replicaindex=0&mgm.replicahead=0&mgm.id=a902f2e6&mgm.mtime=0 xrd_port=1095 http_port=8001
On some files, the process doesn’t go forever, they end up in failure, like the ones mentioned in the first comment here
240416 10:25:51 t=1713255951.501290 f=ioflush l=WARN tid=00007fdab83f3700 s=data:3323 re-issuing OpenAsync request after timeout - ino:80000000a8d1fd7a err-code:206
240416 10:26:57 t=1713256017.621539 f=HandleResponse l=CRIT tid=00007fdaabffb700 s=xrdclproxy:741 3853eb10 current status = 4 - setting CLOSEFAILED - msg=[ERROR] Operation expired url=root://AAAAAIBA@eos-jeodpp:1094//fusex-open?eos.app=fuse::jhub&eos.bookingsize=0&eos.lfn=ino:80000000a8d1fd7a&fuse.exe=/usr/bin/mv&fuse.gid=35637&fuse.pid=28747&fuse.uid=35637&fuse.ver=5.1.21&mgm.fusex=1&mgm.mtime=0&xrd.k5ccname=/tmp/krb5cc_35637&xrd.wantprot=krb5,unix&xrdcl.secgid=35637&xrdcl.secuid=35637
240416 10:26:57 t=1713256017.644417 f=ioflush l=WARN tid=00007fdab83f3700 s=data:3323 re-issuing OpenAsync request after timeout - ino:80000000a8d1fd7a err-code:206
240416 10:26:57 t=1713256017.772780 f=ioflush l=WARN tid=00007fdab83f3700 s=data:3334 OpenAsync failed - trying recovery - ino:80000000a8d1fd7a err-code:400
240416 10:26:57 t=1713256017.772798 f=ioflush l=WARN tid=00007fdab83f3700 s=data:3360 giving up OpenAsync request - ino:80000000a8d1fd7a err-code:400
240416 10:26:57 t=1713256017.772988 f=ioflush l=CRIT tid=00007fdab83f3700 s=data:3389 ino:80000000a8d1fd7a msg=file open failed file-recovery=<none> journal-recovery=/var/cache/eos/fusex/cache/jeodpp/00A/80000000A8D1FD7A.jc.recover
# -[ 000 ] 240416 10:10:13 t=1713255013.517340 f=flush_nolock l= ino:80000000a8d1fd7a s=data:371 status='[ERROR] Error response: no such device' hint='will TryRecovery'
# -[ 001 ] 240416 10:10:13 t=1713255013.517656 f=recover_write l= ino:80000000a8d1fd7a s=data:1671 hint='recover write'
# -[ 002 ] 240416 10:10:13 t=1713255013.517662 f=recover_write l= ino:80000000a8d1fd7a s=data:1728 hint='recover from remote file'
# -[ 003 ] 240416 10:10:13 t=1713255013.517710 f=try_ropen l= ino:80000000a8d1fd7a s=data:1325 hint='try read-open'
# -[ 004 ] 240416 10:13:39 t=1713255219.456446 f=recover_write l= ino:80000000a8d1fd7a s=data:1859 hint='failed to write to local stage file'
# -[ 005 ] 240416 10:13:39 t=1713255219.456469 f=flush_nolock l= ino:80000000a8d1fd7a s=data:404 errno='121' hint='failed TryRecovery'
# -[ 006 ] 240416 10:13:44 t=1713255224.223889 f=recover_write l= ino:80000000a8d1fd7a s=data:1671 hint='recover write'
# -[ 007 ] 240416 10:13:44 t=1713255224.223895 f=recover_write l= ino:80000000a8d1fd7a s=data:1728 hint='recover from remote file'
# -[ 008 ] 240416 10:13:44 t=1713255224.223955 f=try_ropen l= ino:80000000a8d1fd7a s=data:1325 hint='try read-open'
# -[ 009 ] 240416 10:16:50 t=1713255410.631339 f=recover_write l= ino:80000000a8d1fd7a s=data:1859 hint='failed to write to local stage file'
The situation is kind of worrying because many such files are written from one client, and the only way to stop it would be to restart the client.
This client is running 5.1.22, but the same is observed on another one running 5.2.22 but creates less big files.