Hi Friends,
I am looking at getting rid of eosd in our CTA setup. It’s currently only used to mkdir, and write a .tar.gz file. All other traffic goes through the nginx proxy.
I am testing eoxd in our dev environment. I have found that the whole workflow works perfectly, until we try and write a .tar.gz file into a directory that is configured to send files to tape.
I am not sure if this is a CTA issue, or an EOS issue. Please tell me if this is not the right place to report this, or if this is possibly not even supported. This process works just fine with eosd, but not eosxd.
cp ~/blah.tar.gz /eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/anotherone.tar.gz
# No error reported back
MGM/WFE logs:
220722 03:15:26 INFO [00048/00048] root ::HandleMD ino=0000000000000000 operation=SET type=file name=anotherone.tar.gz pino=00000000000000bb cid= cuuid=82b5c4e2-08ab-11ed-9331-fa163e6c0b71
220722 03:15:26 INFO [00048/00048] root ::open msg="access by inode" ino=ino:80000000000004a6 path=/eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/anotherone.tar.gz
220722 03:15:26 INFO [00048/00048] root ::open op=write path=/eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/anotherone.tar.gz info=eos.app=fuse&eos.bookingsize=0&eos.lfn=ino:80000000000004a6&fuse.exe=/usr/bin/cp&fuse.gid=0&fuse.pid=10366&fuse.uid=0&fuse.ver=5.0.26&mgm.fusex=1&mgm.mtime=0&xrd.wantprot=unix target[0]=(6d8ca6e9-d20e-4322-b-0.fst.cta.svc.cluster.archive,7) redirection=6d8ca6e9-d20e-4322-b-0.fst.cta.svc.cluster.archive?&cap.sym=<...>&cap.msg=<...>&mgm.logid=87fd2b5e-096c-11ed-8814-b23298608cfd&mgm.replicaindex=0&mgm.replicahead=0&mgm.id=000004a6&mgm.mtime=0&mgm.event=sync::closew&mgm.workflow=default&mgm.instance=cta&mgm.owner_uid=48&mgm.owner_gid=48&mgm.requestor=apache&mgm.requestorgroup=apache&mgm.attributes=c3lzLmFyY2hpdmUuc3RvcmFnZV9jbGFzcz1zaW5nbGUtY29weS1iYWNrdXA= xrd_port=1095 http_port=8001
220722 03:15:26 INFO [00048/00048] root ::open path=/eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/anotherone.tar.gz rt=2.29
220722 03:15:26 INFO [00048/00048] root ::HandleMD ino=80000000000004a6 operation=SET type=file name=anotherone.tar.gz pino=00000000000000bb cid= cuuid=82b5c4e2-08ab-11ed-9331-fa163e6c0b71
220722 03:15:27 INFO WFE:1619 default SYNC::ARCHIVE_FAILED /eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/anotherone.tar.gz ctafrontend.cta.svc.cluster.archive:10955 fxid=000004a6 mgm.reqid=""
220722 03:15:27 INFO [00002/00002] daemon ::Event subcmd=event event=sync::closew path=/eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/anotherone.tar.gz fid=000004a6
220722 03:15:27 ERROR [00000/00000] ::Emsg Unable to trigger workflow - no workflow defined for <workflow>.<event> [EINVAL] &tapeenabled=1&mgm.access=update&mgm.ruid=48&mgm.rgid=48&mgm.uid=99&mgm.gid=99&mgm.path=/eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/anotherone.tar.gz&mgm.manager=eos-mgm-0.mgm.cta.svc.cluster.archive:1094&mgm.fid=000004a6&mgm.cid=187&mgm.sec=unix|root|[::ffff:10.54.1.1]||root|||fuse&mgm.lid=1048594&mgm.bookingsize=0&mgm.fsid=7&mgm.url0=root://6d8ca6e9-d20e-4322-b-0.fst.cta.svc.cluster.archive:1095//&mgm.fsid0=7&cap.valid=1658463326&mgm.pcmd=event&mgm.event=sync::closew&mgm.logid=87fd2b5e-096c-11ed-8814-b23298608cfd&mgm.ruid=48&mgm.rgid=48&mgm.sec=unix|root|[::ffff:10.54.1.1]||root|||fuse&mgm.workflow=default; Invalid argument
220722 03:15:27 time=1658459727.318394 func=NotifyProtoWfEndPointClosew level=ERROR logid=static.............................. unit=fst@6d8ca6e9-d20e-4322-b-0.fst.cta.svc.cluster.archive:1095 tid=00007f490effe700 source=XrdFstOfsFile:3798 tident= sec=(null) uid=99 gid=99 name=- geo="" RSP_ERR_PROTOBUF for file /eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/anotherone.tar.gz. Reason: processCLOSEW: Failed to find the extended attribute named sys.archive.file_id
220722 03:15:27 time=1658459727.324472 func=CallManager level=ERROR logid=static.............................. unit=fst@6d8ca6e9-d20e-4322-b-0.fst.cta.svc.cluster.archive:1095 tid=00007f490effe700 source=XrdFstOfs:1056 tident= sec=(null) uid=99 gid=99 name=- geo="" msg="MGM query failed" opaque="/?&tapeenabled=1&mgm.access=update&mgm.ruid=48&mgm.rgid=48&mgm.uid=99&mgm.gid=99&mgm.path=/eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/anotherone.tar.gz&mgm.manager=eos-mgm-0.mgm.cta.svc.cluster.archive:1094&mgm.fid=000004a6&mgm.cid=187&mgm.sec=unix|root|[::ffff:10.54.1.1]||root|||fuse&mgm.lid=1048594&mgm.bookingsize=0&mgm.fsid=7&mgm.url0=root://6d8ca6e9-d20e-4322-b-0.fst.cta.svc.cluster.archive:1095//&mgm.fsid0=7&cap.valid=1658463326&mgm.pcmd=event&mgm.event=sync::closew&mgm.logid=87fd2b5e-096c-11ed-8814-b23298608cfd&mgm.ruid=48&mgm.rgid=48&mgm.sec=unix|root|[::ffff:10.54.1.1]||root|||fuse&mgm.workflow=default"
CTA Frontend logs:
Jul 22 03:15:27.318122 ctafrontend-0 cta-frontend: LVL="INFO" PID="1" TID="8143" MSG="In RequestMessage::process(): processing SSI event" user="cta@ctafrontend-0" eventType="CLOSEW" eosInstance="cta" diskFilePath="/eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/anotherone.tar.gz" diskFileId="1190"
Jul 22 03:15:27.320388 ctafrontend-0 cta-frontend: LVL="INFO" PID="1" TID="8143" MSG="In RequestMessage::processCLOSEW(): sys.archive.file_id is not present in extended attributes" user="cta@ctafrontend-0" requesterInstance="6d8ca6e9-d20e-4322-b-0.fst.cta.svc.cluster.archive:fst"
Jul 22 03:15:27.320546 ctafrontend-0 cta-frontend: LVL="ERROR" PID="1" TID="8143" MSG="In RequestProc::ExecuteAction(): RSP_ERR_PROTOBUF: processCLOSEW: Failed to find the extended attribute named sys.archive.file_id
It looks to me like the CREATE workflow is never properly triggered. Instead CLOSEW is triggered, and it expected an archive file id to already exist (which does not because no CREATE was ever triggered).
When this is done via eosd, the logs are like this:
MGM / WFE:
220722 03:19:18 INFO [00048/00048] root ::open op=write trunc=512 path=/eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/cta_pre_upgrade.sql info=eos.app=fuse&eos.bookingsize=0&eos.encodepath=1&fst.valid=1658460017
220722 03:19:18 INFO WFE:1619 default SYNC::CREATE /eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/cta_pre_upgrade.sql ctafrontend.cta.svc.cluster.archive:10955 fxid=000004a8 mgm.reqid=""
220722 03:19:18 INFO WFE:2524 protoWFEndPoint="ctafrontend.cta.svc.cluster.archive:10955" protoWFResource="/ctafrontend" fullPath="/eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/cta_pre_upgrade.sql" event="sync::create" timeSpentMs=10 msg="Sent SSI protocol buffer request"
220722 03:19:18 INFO [00048/00048] root ::open op=write path=/eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/cta_pre_upgrade.sql info=eos.app=fuse&eos.bookingsize=0&eos.encodepath=1&fst.valid=1658460017 target[0]=(0168d081-28c5-4edd-9-0.fst.cta.svc.cluster.archive,1) redirection=0168d081-28c5-4edd-9-0.fst.cta.svc.cluster.archive?&cap.sym=<...>&cap.msg=<...>&mgm.logid=12c04c30-096d-11ed-9892-b23298608cfd&mgm.replicaindex=0&mgm.replicahead=0&mgm.id=000004a8&mgm.mtime=0&mgm.event=sync::closew&mgm.workflow=default&mgm.instance=cta&mgm.owner_uid=48&mgm.owner_gid=48&mgm.requestor=apache&mgm.requestorgroup=apache&mgm.attributes=c3lzLmFyY2hpdmUuZmlsZV9pZD0xMjU5Ozs7c3lzLmFyY2hpdmUuc3RvcmFnZV9jbGFzcz1zaW5nbGUtY29weS1iYWNrdXA= xrd_port=1095 http_port=8001
220722 03:19:18 INFO [00048/00048] root ::open path=/eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/cta_pre_upgrade.sql rt=15.44
220722 03:19:19 INFO [00048/00048] root ::_utimes calling utimes for path=/eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/cta_pre_upgrade.sql, uid=48, gid=48
220722 03:19:19 INFO [00002/00002] daemon ::log_info subcmd=commit path=/eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/cta_pre_upgrade.sql size=87097 fxid=000004a8 fsid=1 dropfsid= checksum=48eadc8a mtime=0 mtime.nsec=0 oc-chunk=0 oc-n=0 oc-max=0 oc-uuid=
220722 03:19:19 INFO [00002/00002] daemon ::Commit commitsize=1 n1=cta_pre_upgrade.sql n2=cta_pre_upgrade.sql occhunk=0 ocdone=0
220722 03:19:19 INFO [00002/00002] daemon ::Event subcmd=event event=sync::closew path=/eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/cta_pre_upgrade.sql fid=000004a8
220722 03:19:19 INFO WFE:1619 default SYNC::CLOSEW /eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/cta_pre_upgrade.sql ctafrontend.cta.svc.cluster.archive:10955 fxid=000004a8 mgm.reqid=""
220722 03:19:30 INFO [00002/00002] daemon ::open msg="access by inode" ino=fxid:4a8 path=/eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/cta_pre_upgrade.sql
220722 03:19:30 INFO [00002/00002] daemon ::open op=read path=/eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/cta_pre_upgrade.sql info=eos.lfn=fxid:4a8 target[0]=(0168d081-28c5-4edd-9-0.fst.cta.svc.cluster.archive,1) redirection=0168d081-28c5-4edd-9-0.fst.cta.svc.cluster.archive?&cap.sym=<...>&cap.msg=<...>&mgm.logid=198b7102-096d-11ed-8d09-b23298608cfd&mgm.blockchecksum=ignore&mgm.replicaindex=0&mgm.replicahead=0&mgm.id=000004a8&mgm.mtime=1658459959 xrd_port=1095 http_port=8001
220722 03:19:30 INFO [00002/00002] daemon ::open path=/eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/cta_pre_upgrade.sql rt=1.85
220722 03:19:31 INFO WFE:1619 default SYNC::ARCHIVED /eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/cta_pre_upgrade.sql ctafrontend.cta.svc.cluster.archive:10955 fxid=000004a8 mgm.reqid=""
CTA Frontend:
Jul 22 03:19:18.909523 ctafrontend-0 cta-frontend: LVL="INFO" PID="1" TID="1366" MSG="In RequestMessage::process(): processing SSI event" user="cta@ctafrontend-0" eventType="CREATE" eosInstance="cta" diskFilePath="/eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/cta_pre_upgrade.sql" diskFileId="1192"
Jul 22 03:19:18.916815 ctafrontend-0 cta-frontend: LVL="INFO" PID="1" TID="1366" MSG="Checked request and got next archive file ID" user="cta@ctafrontend-0" instanceName="cta" username="apache" usergroup="apache" storageClass="single-copy-backup" fileId="1259" catalogueTime="0.007086" schedulerDbTime="0.007086"
Jul 22 03:19:18.916955 ctafrontend-0 cta-frontend: LVL="INFO" PID="1" TID="1366" MSG="In RequestMessage::processCREATE(): assigning new archive file ID." user="cta@ctafrontend-0" diskFileId="1192" diskFilePath="/eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/cta_pre_upgrade.sql" fileId="1259" schedulerTime="0.00728
1"
Jul 22 03:19:19.200067 ctafrontend-0 cta-frontend: LVL="INFO" PID="1" TID="134" MSG="In RequestMessage::process(): processing SSI event" user="cta@ctafrontend-0" eventType="CLOSEW" eosInstance="cta" diskFilePath="/eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/cta_pre_upgrade.sql" diskFileId="1192"
Jul 22 03:19:19.234366 ctafrontend-0 cta-frontend: LVL="INFO" PID="1" TID="134" MSG="In OStoreDB::queueArchive(): recorded request for queueing (enqueueing posted to thread pool)." user="cta@ctafrontend-0" requesterInstance="0168d081-28c5-4edd-9-0.fst.cta.svc.cluster.archive:fst" fileId="1259" jobObject="ArchiveRequest-Frontend-ctafrontend
-0-1-20220622-14:36:33-0-14" diskInstance="cta" diskFilePath="/eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/cta_pre_upgrade.sql" diskFileId="1192" agentReferencingTime="0.024444" insertionTime="0.007357" taskPostingTime="0.000159" taskQueueSize="1" totalTime="0.031960"
Jul 22 03:19:19.234819 ctafrontend-0 cta-frontend: LVL="INFO" PID="1" TID="134" MSG="Queued archive request" user="cta@ctafrontend-0" requesterInstance="0168d081-28c5-4edd-9-0.fst.cta.svc.cluster.archive:fst" instanceName="cta" storageClass="single-copy-backup" diskFileID="1192" fileSize="87097" fileId="1259" tapePool1="crlt-piranha-tapes" policyName="default-mp" policyArchiveMinAge="1" policyArchivePriority="2" diskFilePath="/eos/cta/cta/aarnet.edu.au/denis.lujanski@aarnet.edu.au/metadata-backups/cta_pre_upgrade.sql" diskFileOwnerUid="48" diskFileGid="48" archiveReportURL="eosQuery://eos-[...]gid=0&cta_archive_file_id=1259" archiveErrorReportURL="eosQuery://eos-[...]chive_file_id=1259&mgm.errmsg=" creationHost="ctafrontend-0" creationTime="1658459959" creationUser="cta" requesterName="apache" requesterGroup="apache" srcURL="root://eos-mgm-[...]e_upgrade.sql?eos.lfn=fxid:4a8" catalogueTime="0.000097" schedulerDbTime="0.032217" checksumType="ADLER32" checksumValue="48eadc8a"
Jul 22 03:19:19.235203 ctafrontend-0 cta-frontend: LVL="INFO" PID="1" TID="134" MSG="In RequestMessage::processCLOSEW(): queued file for archive." user="cta@ctafrontend-0" requesterInstance="0168d081-28c5-4edd-9-0.fst.cta.svc.cluster.archive:fst" schedulerTime="0.032893" archiveRequestId="ArchiveRequest-Frontend-ctafrontend-0-1-20220622-14:36:33-0-14"
Any ideas?
Thank you,
Denis