Failure to open a file for writing that has just been created

[IdrisMiles]

Mountpoint for Amazon S3 version

mount-s3 1.15.0

AWS Region

eu-west-2

Describe the running environment

• EC2 spot instance of C/M/R families
• Rocky 8.9
• Mountpoint using EC2 instances IAM role for permissions to access bucket
• Mounting S3 bucket with mount-s3 to /rendercache which acts as a storage location for temporary data for Visual Effect rendering workloads, in particular as a location to write .ass and .ifd files from the Houdini application.

Mountpoint options

sudo mount-s3 \
        --allow-other --allow-delete --allow-overwrite \
        --gid $GROUP_ID --file-mode 0777 --dir-mode 0777 \
        $BUCKET /rendercache

What happened?

Running the hython application, that ships with SideFX Houdini, to export files to mount-s3 location errors when the hython process is given a frame range rather than a single frame to export.

hython \
    /deadline/DeadlineRepository10/custom/plugins/UtdHoudini/hrender_dl.py \
    -f 1052 1056 1 1152 -d /out/mantraClean "/jobs/foo_bar/054/ns/sh0005/h_sh0005/renders/generic/fxBlast/v169/.hip/4dba6dbc5177_sh0005_generic_fxBlast_v169.hip"

Receive the following error from the application:

Rendering frames 1052 to 1056
Error: Caught exception: ['  File "/software/installed/houdini/el8-x86-64/houdini-20.5.332/houdini/python3.10libs/hou.py", line 80783, in render\n    return _hou.RopNode_render(self, *args, **kwargs)\n', 'hou.OperationFailed: The attempted operation failed.\nError:       Failed to save output to file "/rendercache/foo_bar/2025_04_01//054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd".\n']

The output file is present but with 0 bytes

While strace-ing the application this seems to be where the error comes from:

openat(AT_FDCWD, "/rendercache/foo_bar/2025_04_01//054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 24
close(24)                               = 0
stat("/rendercache/foo_bar/2025_04_01//054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169", {st_mode=S_IFDIR|0777, st_size=0, ...}) = 0
openat(AT_FDCWD, "/rendercache/foo_bar/2025_04_01//054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd", O_WRONLY|O_CREAT|O_TRUNC, 0666) = -1 EPERM (Operation not permitted)

An initial glance at the mount-s3 logs and the strace, my theory is that the issues revolves around the file being touched with 0 bytes and then immediately being re-opened for writing before the initial upload to S3, from first creation, has completed?

Full Logs:
mountpoint-s3-2025-04-01_houdini-strace-REDACTED.log
mountpoint-s3-2025-04-01T16-42-22Z.5x8mTa-REDACTED.log

Relevant log output

2025-04-01T16:45:19.330153Z DEBUG fuser::request: FUSE( 34) ino 0x0000000000000001 LOOKUP name "foo_bar"    
2025-04-01T16:45:19.330278Z DEBUG lookup{req=34 ino=1 name="foo_bar"}:head_object{id=4 bucket="company-s3-bucket" key="foo_bar"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-04-01T16:45:19.330360Z DEBUG lookup{req=34 ino=1 name="foo_bar"}:list_objects{id=5 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-04-01T16:45:19.349141Z DEBUG lookup{req=34 ino=1 name="foo_bar"}:head_object{id=4 bucket="company-s3-bucket" key="foo_bar"}: mountpoint_s3_client::s3_crt_client: S3 request failed request_type=HeadObject crt_error=Some(Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request")) http_status=404 range=None duration=18.74162ms ttfb=Some(15.520345ms) request_id=W3AR9ASMQ8H3FS9W
2025-04-01T16:45:19.349224Z DEBUG lookup{req=34 ino=1 name="foo_bar"}:head_object{id=4 bucket="company-s3-bucket" key="foo_bar"}: mountpoint_s3_client::s3_crt_client: duration=18.913884ms request_id=W3AR9ASMQ8H3FS9W error=ServiceError(NotFound) meta request failed
2025-04-01T16:45:19.349236Z DEBUG lookup{req=34 ino=1 name="foo_bar"}:head_object{id=4 bucket="company-s3-bucket" key="foo_bar"}: mountpoint_s3_client::s3_crt_client: meta request result: MetaRequestResult { response_status: 404, crt_error: Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request"), error_response_headers: Some(Headers { inner: 0x7fa88c017e50 }), error_response_body: None }
2025-04-01T16:45:19.359110Z DEBUG lookup{req=34 ino=1 name="foo_bar"}:list_objects{id=5 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=Default crt_error=None http_status=200 range=None duration=28.649928ms ttfb=Some(23.463356ms) request_id=W3ASQ4F11SEC8R9Y
2025-04-01T16:45:19.359147Z DEBUG lookup{req=34 ino=1 name="foo_bar"}:list_objects{id=5 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=28.777323ms
2025-04-01T16:45:19.359294Z DEBUG fuser::request: FUSE( 36) ino 0x000000000000000b LOOKUP name "2025_04_01"    
2025-04-01T16:45:19.359330Z DEBUG mountpoint_s3::fuse::session: starting fuse worker 2 (thread id 8163)
2025-04-01T16:45:19.359369Z DEBUG lookup{req=36 ino=11 name="2025_04_01"}:head_object{id=6 bucket="company-s3-bucket" key="foo_bar/2025_04_01"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-04-01T16:45:19.359425Z DEBUG lookup{req=36 ino=11 name="2025_04_01"}:list_objects{id=7 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-04-01T16:45:19.365943Z DEBUG lookup{req=36 ino=11 name="2025_04_01"}:head_object{id=6 bucket="company-s3-bucket" key="foo_bar/2025_04_01"}: mountpoint_s3_client::s3_crt_client: S3 request failed request_type=HeadObject crt_error=Some(Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request")) http_status=404 range=None duration=6.500753ms ttfb=Some(6.332119ms) request_id=W3AH0E1J5ANTCNBT
2025-04-01T16:45:19.365987Z DEBUG lookup{req=36 ino=11 name="2025_04_01"}:head_object{id=6 bucket="company-s3-bucket" key="foo_bar/2025_04_01"}: mountpoint_s3_client::s3_crt_client: duration=6.605916ms request_id=W3AH0E1J5ANTCNBT error=ServiceError(NotFound) meta request failed
2025-04-01T16:45:19.365996Z DEBUG lookup{req=36 ino=11 name="2025_04_01"}:head_object{id=6 bucket="company-s3-bucket" key="foo_bar/2025_04_01"}: mountpoint_s3_client::s3_crt_client: meta request result: MetaRequestResult { response_status: 404, crt_error: Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request"), error_response_headers: Some(Headers { inner: 0x7fa88001a0f0 }), error_response_body: None }
2025-04-01T16:45:19.391222Z DEBUG lookup{req=36 ino=11 name="2025_04_01"}:list_objects{id=7 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=Default crt_error=None http_status=200 range=None duration=31.711763ms ttfb=Some(27.088667ms) request_id=W3AV4S5KVF8RZ1CM
2025-04-01T16:45:19.391258Z DEBUG lookup{req=36 ino=11 name="2025_04_01"}:list_objects{id=7 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=31.82479ms
2025-04-01T16:45:19.391395Z DEBUG fuser::request: FUSE( 38) ino 0x000000000000000e LOOKUP name "054"    
2025-04-01T16:45:19.391454Z DEBUG lookup{req=38 ino=14 name="054"}:head_object{id=8 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-04-01T16:45:19.391528Z DEBUG lookup{req=38 ino=14 name="054"}:list_objects{id=9 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-04-01T16:45:19.402435Z DEBUG lookup{req=38 ino=14 name="054"}:head_object{id=8 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054"}: mountpoint_s3_client::s3_crt_client: S3 request failed request_type=HeadObject crt_error=Some(Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request")) http_status=404 range=None duration=10.894275ms ttfb=Some(10.744145ms) request_id=W3AK6ZWT56YZJP1G
2025-04-01T16:45:19.402477Z DEBUG lookup{req=38 ino=14 name="054"}:head_object{id=8 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054"}: mountpoint_s3_client::s3_crt_client: duration=11.013423ms request_id=W3AK6ZWT56YZJP1G error=ServiceError(NotFound) meta request failed
2025-04-01T16:45:19.402493Z DEBUG lookup{req=38 ino=14 name="054"}:head_object{id=8 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054"}: mountpoint_s3_client::s3_crt_client: meta request result: MetaRequestResult { response_status: 404, crt_error: Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request"), error_response_headers: Some(Headers { inner: 0x7fa8880187c0 }), error_response_body: None }
2025-04-01T16:45:19.424188Z DEBUG lookup{req=38 ino=14 name="054"}:list_objects{id=9 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=Default crt_error=None http_status=200 range=None duration=32.620163ms ttfb=Some(28.455687ms) request_id=W3AJ5YV0QQ28MYDA
2025-04-01T16:45:19.424220Z DEBUG lookup{req=38 ino=14 name="054"}:list_objects{id=9 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=32.684014ms
2025-04-01T16:45:19.424328Z DEBUG fuser::request: FUSE( 40) ino 0x000000000000000f LOOKUP name "ns"    
2025-04-01T16:45:19.424405Z DEBUG lookup{req=40 ino=15 name="ns"}:head_object{id=10 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-04-01T16:45:19.424472Z DEBUG lookup{req=40 ino=15 name="ns"}:list_objects{id=11 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-04-01T16:45:19.431609Z DEBUG lookup{req=40 ino=15 name="ns"}:head_object{id=10 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns"}: mountpoint_s3_client::s3_crt_client: S3 request failed request_type=HeadObject crt_error=Some(Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request")) http_status=404 range=None duration=7.125119ms ttfb=Some(6.948289ms) request_id=W3AJGY26DB0VPJHV
2025-04-01T16:45:19.431646Z DEBUG lookup{req=40 ino=15 name="ns"}:head_object{id=10 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns"}: mountpoint_s3_client::s3_crt_client: duration=7.230718ms request_id=W3AJGY26DB0VPJHV error=ServiceError(NotFound) meta request failed
2025-04-01T16:45:19.431653Z DEBUG lookup{req=40 ino=15 name="ns"}:head_object{id=10 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns"}: mountpoint_s3_client::s3_crt_client: meta request result: MetaRequestResult { response_status: 404, crt_error: Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request"), error_response_headers: Some(Headers { inner: 0x7fa88001c6f0 }), error_response_body: None }
2025-04-01T16:45:19.455078Z DEBUG lookup{req=40 ino=15 name="ns"}:list_objects{id=11 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=Default crt_error=None http_status=200 range=None duration=30.535403ms ttfb=Some(26.269774ms) request_id=W3AN6N61CF3QTJVA
2025-04-01T16:45:19.455117Z DEBUG lookup{req=40 ino=15 name="ns"}:list_objects{id=11 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=30.621803ms
2025-04-01T16:45:19.455234Z DEBUG fuser::request: FUSE( 42) ino 0x0000000000000010 LOOKUP name "sh0005"    
2025-04-01T16:45:19.455292Z DEBUG lookup{req=42 ino=16 name="sh0005"}:head_object{id=12 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-04-01T16:45:19.455350Z DEBUG lookup{req=42 ino=16 name="sh0005"}:list_objects{id=13 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-04-01T16:45:19.465200Z DEBUG lookup{req=42 ino=16 name="sh0005"}:head_object{id=12 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005"}: mountpoint_s3_client::s3_crt_client: S3 request failed request_type=HeadObject crt_error=Some(Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request")) http_status=404 range=None duration=9.836831ms ttfb=Some(9.678754ms) request_id=W3AN7QQJRZF7RXFP
2025-04-01T16:45:19.465239Z DEBUG lookup{req=42 ino=16 name="sh0005"}:head_object{id=12 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005"}: mountpoint_s3_client::s3_crt_client: duration=9.931923ms request_id=W3AN7QQJRZF7RXFP error=ServiceError(NotFound) meta request failed
2025-04-01T16:45:19.465245Z DEBUG lookup{req=42 ino=16 name="sh0005"}:head_object{id=12 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005"}: mountpoint_s3_client::s3_crt_client: meta request result: MetaRequestResult { response_status: 404, crt_error: Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request"), error_response_headers: Some(Headers { inner: 0x7fa88801a8b0 }), error_response_body: None }
2025-04-01T16:45:19.486379Z DEBUG lookup{req=42 ino=16 name="sh0005"}:list_objects{id=13 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=Default crt_error=None http_status=200 range=None duration=30.97829ms ttfb=Some(26.149442ms) request_id=W3APDPNQ9QQEJKWE
2025-04-01T16:45:19.486413Z DEBUG lookup{req=42 ino=16 name="sh0005"}:list_objects{id=13 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=31.055391ms
2025-04-01T16:45:19.486525Z DEBUG fuser::request: FUSE( 44) ino 0x0000000000000011 LOOKUP name "h_sh0005"    
2025-04-01T16:45:19.486574Z DEBUG lookup{req=44 ino=17 name="h_sh0005"}:head_object{id=14 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-04-01T16:45:19.486633Z DEBUG lookup{req=44 ino=17 name="h_sh0005"}:list_objects{id=15 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-04-01T16:45:19.496478Z DEBUG lookup{req=44 ino=17 name="h_sh0005"}:head_object{id=14 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005"}: mountpoint_s3_client::s3_crt_client: S3 request failed request_type=HeadObject crt_error=Some(Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request")) http_status=404 range=None duration=9.843967ms ttfb=Some(9.70392ms) request_id=W3AWSJEWHN2PV1ZN
2025-04-01T16:45:19.496522Z DEBUG lookup{req=44 ino=17 name="h_sh0005"}:head_object{id=14 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005"}: mountpoint_s3_client::s3_crt_client: duration=9.938752ms request_id=W3AWSJEWHN2PV1ZN error=ServiceError(NotFound) meta request failed
2025-04-01T16:45:19.496527Z DEBUG lookup{req=44 ino=17 name="h_sh0005"}:head_object{id=14 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005"}: mountpoint_s3_client::s3_crt_client: meta request result: MetaRequestResult { response_status: 404, crt_error: Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request"), error_response_headers: Some(Headers { inner: 0x7fa89001bd80 }), error_response_body: None }
2025-04-01T16:45:19.526263Z DEBUG lookup{req=44 ino=17 name="h_sh0005"}:list_objects{id=15 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=Default crt_error=None http_status=200 range=None duration=39.577654ms ttfb=Some(33.624304ms) request_id=W3ARANV7ZZGSSPV8
2025-04-01T16:45:19.526302Z DEBUG lookup{req=44 ino=17 name="h_sh0005"}:list_objects{id=15 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=39.660455ms
2025-04-01T16:45:19.526417Z DEBUG fuser::request: FUSE( 46) ino 0x0000000000000012 LOOKUP name "ifd"    
2025-04-01T16:45:19.526468Z DEBUG lookup{req=46 ino=18 name="ifd"}:head_object{id=16 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-04-01T16:45:19.526527Z DEBUG lookup{req=46 ino=18 name="ifd"}:list_objects{id=17 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-04-01T16:45:19.535888Z DEBUG lookup{req=46 ino=18 name="ifd"}:head_object{id=16 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd"}: mountpoint_s3_client::s3_crt_client: S3 request failed request_type=HeadObject crt_error=Some(Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request")) http_status=404 range=None duration=9.355692ms ttfb=Some(9.195972ms) request_id=W3APS90CPS5F2RP9
2025-04-01T16:45:19.535921Z DEBUG lookup{req=46 ino=18 name="ifd"}:head_object{id=16 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd"}: mountpoint_s3_client::s3_crt_client: duration=9.442554ms request_id=W3APS90CPS5F2RP9 error=ServiceError(NotFound) meta request failed
2025-04-01T16:45:19.535928Z DEBUG lookup{req=46 ino=18 name="ifd"}:head_object{id=16 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd"}: mountpoint_s3_client::s3_crt_client: meta request result: MetaRequestResult { response_status: 404, crt_error: Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request"), error_response_headers: Some(Headers { inner: 0x7fa87401c590 }), error_response_body: None }
2025-04-01T16:45:19.557584Z DEBUG lookup{req=46 ino=18 name="ifd"}:list_objects{id=17 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=Default crt_error=None http_status=200 range=None duration=31.006233ms ttfb=Some(27.162065ms) request_id=W3AMXYRWVP98Z1Z5
2025-04-01T16:45:19.557626Z DEBUG lookup{req=46 ino=18 name="ifd"}:list_objects{id=17 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=31.090642ms
2025-04-01T16:45:19.557773Z DEBUG fuser::request: FUSE( 48) ino 0x0000000000000013 LOOKUP name "generic"    
2025-04-01T16:45:19.557861Z DEBUG lookup{req=48 ino=19 name="generic"}:head_object{id=18 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-04-01T16:45:19.557929Z DEBUG lookup{req=48 ino=19 name="generic"}:list_objects{id=19 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-04-01T16:45:19.572195Z DEBUG lookup{req=48 ino=19 name="generic"}:head_object{id=18 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic"}: mountpoint_s3_client::s3_crt_client: S3 request failed request_type=HeadObject crt_error=Some(Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request")) http_status=404 range=None duration=14.243454ms ttfb=Some(14.012664ms) request_id=W3AMB7R1DMDGF156
2025-04-01T16:45:19.572255Z DEBUG lookup{req=48 ino=19 name="generic"}:head_object{id=18 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic"}: mountpoint_s3_client::s3_crt_client: duration=14.376141ms request_id=W3AMB7R1DMDGF156 error=ServiceError(NotFound) meta request failed
2025-04-01T16:45:19.572265Z DEBUG lookup{req=48 ino=19 name="generic"}:head_object{id=18 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic"}: mountpoint_s3_client::s3_crt_client: meta request result: MetaRequestResult { response_status: 404, crt_error: Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request"), error_response_headers: Some(Headers { inner: 0x7fa878043e70 }), error_response_body: None }
2025-04-01T16:45:19.591898Z DEBUG lookup{req=48 ino=19 name="generic"}:list_objects{id=19 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=Default crt_error=None http_status=200 range=None duration=33.918449ms ttfb=Some(29.295043ms) request_id=W3AKH0QEK7594JB0
2025-04-01T16:45:19.591953Z DEBUG lookup{req=48 ino=19 name="generic"}:list_objects{id=19 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=34.013443ms
2025-04-01T16:45:19.592101Z DEBUG fuser::request: FUSE( 50) ino 0x0000000000000014 LOOKUP name "fxBlast"    
2025-04-01T16:45:19.592180Z DEBUG lookup{req=50 ino=20 name="fxBlast"}:head_object{id=20 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-04-01T16:45:19.592248Z DEBUG lookup{req=50 ino=20 name="fxBlast"}:list_objects{id=21 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-04-01T16:45:19.604615Z DEBUG lookup{req=50 ino=20 name="fxBlast"}:head_object{id=20 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast"}: mountpoint_s3_client::s3_crt_client: S3 request failed request_type=HeadObject crt_error=Some(Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request")) http_status=404 range=None duration=12.368331ms ttfb=Some(12.216557ms) request_id=W3AJ6GYQY9J4TYFB
2025-04-01T16:45:19.604673Z DEBUG lookup{req=50 ino=20 name="fxBlast"}:head_object{id=20 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast"}: mountpoint_s3_client::s3_crt_client: duration=12.479601ms request_id=W3AJ6GYQY9J4TYFB error=ServiceError(NotFound) meta request failed
2025-04-01T16:45:19.604692Z DEBUG lookup{req=50 ino=20 name="fxBlast"}:head_object{id=20 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast"}: mountpoint_s3_client::s3_crt_client: meta request result: MetaRequestResult { response_status: 404, crt_error: Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request"), error_response_headers: Some(Headers { inner: 0x7fa8780186f0 }), error_response_body: None }
2025-04-01T16:45:19.619040Z DEBUG lookup{req=50 ino=20 name="fxBlast"}:list_objects{id=21 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=Default crt_error=None http_status=200 range=None duration=26.730613ms ttfb=Some(23.560253ms) request_id=W3AJES5175BCC97K
2025-04-01T16:45:19.619098Z DEBUG lookup{req=50 ino=20 name="fxBlast"}:list_objects{id=21 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=26.837559ms
2025-04-01T16:45:19.619255Z DEBUG fuser::request: FUSE( 52) ino 0x0000000000000015 LOOKUP name "v169"    
2025-04-01T16:45:19.619349Z DEBUG lookup{req=52 ino=21 name="v169"}:head_object{id=22 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-04-01T16:45:19.619416Z DEBUG lookup{req=52 ino=21 name="v169"}:list_objects{id=23 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-04-01T16:45:19.632922Z DEBUG lookup{req=52 ino=21 name="v169"}:head_object{id=22 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169"}: mountpoint_s3_client::s3_crt_client: S3 request failed request_type=HeadObject crt_error=Some(Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request")) http_status=404 range=None duration=13.495966ms ttfb=Some(13.306941ms) request_id=W3AXQSTJX53YD1DP
2025-04-01T16:45:19.632980Z DEBUG lookup{req=52 ino=21 name="v169"}:head_object{id=22 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169"}: mountpoint_s3_client::s3_crt_client: duration=13.617143ms request_id=W3AXQSTJX53YD1DP error=ServiceError(NotFound) meta request failed
2025-04-01T16:45:19.632992Z DEBUG lookup{req=52 ino=21 name="v169"}:head_object{id=22 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169"}: mountpoint_s3_client::s3_crt_client: meta request result: MetaRequestResult { response_status: 404, crt_error: Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request"), error_response_headers: Some(Headers { inner: 0x7fa874022680 }), error_response_body: None }
2025-04-01T16:45:19.649445Z DEBUG lookup{req=52 ino=21 name="v169"}:list_objects{id=23 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=Default crt_error=None http_status=200 range=None duration=29.985389ms ttfb=Some(25.999153ms) request_id=W3AQXHCX0EVPBR1E
2025-04-01T16:45:19.649516Z DEBUG lookup{req=52 ino=21 name="v169"}:list_objects{id=23 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=30.089723ms
2025-04-01T16:45:19.649721Z DEBUG fuser::request: FUSE( 54) ino 0x0000000000000016 LOOKUP name "mantraClean_v169.1052.ifd"    
2025-04-01T16:45:19.649809Z DEBUG lookup{req=54 ino=22 name="mantraClean_v169.1052.ifd"}:head_object{id=24 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-04-01T16:45:19.649871Z DEBUG lookup{req=54 ino=22 name="mantraClean_v169.1052.ifd"}:list_objects{id=25 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-04-01T16:45:19.668569Z DEBUG lookup{req=54 ino=22 name="mantraClean_v169.1052.ifd"}:head_object{id=24 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=HeadObject crt_error=None http_status=200 range=None duration=18.685156ms ttfb=Some(18.420981ms) request_id=W3ASHX75K249VQQZ
2025-04-01T16:45:19.668652Z DEBUG lookup{req=54 ino=22 name="mantraClean_v169.1052.ifd"}:head_object{id=24 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=18.830913ms
2025-04-01T16:45:19.680284Z DEBUG lookup{req=54 ino=22 name="mantraClean_v169.1052.ifd"}:list_objects{id=25 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd/"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=Default crt_error=None http_status=200 range=None duration=30.36389ms ttfb=Some(26.677924ms) request_id=W3AMYKPMEH3XG185
2025-04-01T16:45:19.680360Z DEBUG lookup{req=54 ino=22 name="mantraClean_v169.1052.ifd"}:list_objects{id=25 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=30.478723ms
2025-04-01T16:45:19.680513Z DEBUG fuser::request: FUSE( 56) ino 0x0000000000000017 OPEN flags 0x8201    
2025-04-01T16:45:19.680598Z DEBUG open{req=56 ino=23 pid=7992 name="mantraClean_v169.1052.ifd"}:head_object{id=26 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-04-01T16:45:19.680656Z DEBUG open{req=56 ino=23 pid=7992 name="mantraClean_v169.1052.ifd"}:list_objects{id=27 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-04-01T16:45:19.692316Z DEBUG open{req=56 ino=23 pid=7992 name="mantraClean_v169.1052.ifd"}:list_objects{id=27 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd/"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=Default crt_error=None http_status=200 range=None duration=11.610371ms ttfb=Some(10.646046ms) request_id=W3ASQX0HZ7S2JZP4
2025-04-01T16:45:19.692374Z DEBUG open{req=56 ino=23 pid=7992 name="mantraClean_v169.1052.ifd"}:list_objects{id=27 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=11.708397ms
2025-04-01T16:45:19.695088Z DEBUG open{req=56 ino=23 pid=7992 name="mantraClean_v169.1052.ifd"}:head_object{id=26 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=HeadObject crt_error=None http_status=200 range=None duration=14.432491ms ttfb=Some(14.255393ms) request_id=W3AQ94D29HN3V3AR
2025-04-01T16:45:19.695135Z DEBUG open{req=56 ino=23 pid=7992 name="mantraClean_v169.1052.ifd"}:head_object{id=26 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=14.524934ms
2025-04-01T16:45:19.695197Z DEBUG open{req=56 ino=23 pid=7992 name="mantraClean_v169.1052.ifd"}: mountpoint_s3::fs: new file handle created fh=4 ino=23
2025-04-01T16:45:19.695244Z DEBUG put_object{id=28 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd"}: mountpoint_s3_client::s3_crt_client::put_object: new request
2025-04-01T16:45:19.695247Z DEBUG fuser::request: FUSE( 58) ino 0x0000000000000017 GETXATTR name "security.capability", size GetSize(GetXAttrSize)    
2025-04-01T16:45:19.695275Z  WARN getxattr{req=58 ino=23 name="security.capability"}: mountpoint_s3::fuse: getxattr failed: operation not supported by Mountpoint
2025-04-01T16:45:19.695327Z DEBUG fuser::request: FUSE( 60) ino 0x0000000000000017 FLUSH fh FileHandle(4), lock owner LockOwner(11841727292529178569)    
2025-04-01T16:45:19.695348Z DEBUG flush{req=60 ino=23 fh=4 pid=7992 name="mantraClean_v169.1052.ifd"}: mountpoint_s3::fs::handles: not completing upload because nothing was written yet key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd"
2025-04-01T16:45:19.695370Z DEBUG fuser::request: FUSE( 62) ino 0x0000000000000017 RELEASE fh FileHandle(4), flags 0x8001, flush false, lock owner None    
2025-04-01T16:45:19.695510Z DEBUG fuser::request: FUSE( 64) ino 0x0000000000000017 GETATTR    
2025-04-01T16:45:19.695546Z DEBUG fuser::request: FUSE( 66) ino 0x0000000000000017 OPEN flags 0x8201    
2025-04-01T16:45:19.695619Z DEBUG open{req=66 ino=23 pid=7992 name="mantraClean_v169.1052.ifd"}:head_object{id=29 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-04-01T16:45:19.695681Z DEBUG open{req=66 ino=23 pid=7992 name="mantraClean_v169.1052.ifd"}:list_objects{id=30 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-04-01T16:45:19.703228Z DEBUG open{req=66 ino=23 pid=7992 name="mantraClean_v169.1052.ifd"}:head_object{id=29 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=HeadObject crt_error=None http_status=200 range=None duration=7.555594ms ttfb=Some(7.390931ms) request_id=W3AG9DKV4X63SRSN
2025-04-01T16:45:19.703277Z DEBUG open{req=66 ino=23 pid=7992 name="mantraClean_v169.1052.ifd"}:head_object{id=29 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=7.64654ms
2025-04-01T16:45:19.713725Z DEBUG put_object{id=28 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=CreateMultipartUpload crt_error=None http_status=200 range=None duration=18.316082ms ttfb=Some(17.257264ms) request_id=W3AT52HNS35FEGNV
2025-04-01T16:45:19.725847Z DEBUG open{req=66 ino=23 pid=7992 name="mantraClean_v169.1052.ifd"}:list_objects{id=30 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd/"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=Default crt_error=None http_status=200 range=None duration=30.117438ms ttfb=Some(25.203712ms) request_id=W3ARW01FSKPSB5CQ
2025-04-01T16:45:19.725898Z DEBUG open{req=66 ino=23 pid=7992 name="mantraClean_v169.1052.ifd"}:list_objects{id=30 bucket="company-s3-bucket" continued=false delimiter="/" max_keys="1" prefix="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=30.20578ms
2025-04-01T16:45:19.726001Z  WARN open{req=66 ino=23 pid=7992 name="mantraClean_v169.1052.ifd"}: mountpoint_s3::fuse: open failed with errno 1: inode error: inode 23 (full key "foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd") is already being written
2025-04-01T16:45:19.735087Z DEBUG put_object{id=28 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=UploadPart crt_error=None http_status=200 range=None duration=21.242708ms ttfb=Some(21.059964ms) request_id=W3AJ3KWX5E5W0RMB
2025-04-01T16:45:19.832550Z DEBUG put_object{id=28 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=CompleteMultipartUpload crt_error=None http_status=200 range=None duration=97.38623ms ttfb=Some(50.154002ms) request_id=W3ATJZ5D96HGNZJD
2025-04-01T16:45:19.832653Z DEBUG put_object{id=28 bucket="company-s3-bucket" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=137.301352ms
2025-04-01T16:45:19.832705Z DEBUG release{req=62 ino=23 fh=4 name="mantraClean_v169.1052.ifd"}: mountpoint_s3::fs::handles: put succeeded etag="\"59adb24ef3cdbe0297f05b395827453f-1\"" key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd" size=0
2025-04-01T16:45:19.832720Z DEBUG release{req=62 ino=23 fh=4 name="mantraClean_v169.1052.ifd"}: mountpoint_s3::fs: upload completed async after file was closed key="foo_bar/2025_04_01/054/ns/sh0005/h_sh0005/ifd/generic/fxBlast/v169/mantraClean_v169.1052.ifd"
2025-04-01T16:45:22.390748Z  INFO mountpoint_s3::metrics: fs.current_handles[type=write]: 0
2025-04-01T16:45:22.390762Z  INFO mountpoint_s3::metrics: fs.inode_kinds[kind=directory]: 22
2025-04-01T16:45:22.390764Z  INFO mountpoint_s3::metrics: fs.inode_kinds[kind=file]: 1
2025-04-01T16:45:22.390766Z  INFO mountpoint_s3::metrics: fs.inodes: 23

[dannycjones]

Hey @IdrisMiles. Thanks for opening the comprehensive bug report, sorry for the delay.

An initial glance at the mount-s3 logs and the strace, my theory is that the issues revolves around the file being touched with 0 bytes and then immediately being re-opened for writing before the initial upload to S3, from first creation, has completed?

I think this is a fair assessment. Unfortunately, this behavior is a side effect of the way we treat write file handles for compatibility, however in this case it is obviously causing issues.

For context: there are some applications which will open a file handle, duplicate it, transfer it to another process before writing, and immediately close the first file handle in the original process. Mountpoint cannot detect when this happens synchronously due to the shape of the FUSE file system protocol. To mitigate this issue, Mountpoint in this specific circumstance (no data written to file) does not block file closure on upload completion. Unfortunately in this instance, your application is able to try opening the file again before we detect that the file has really been closed and we should upload to S3.

We'll review this use case in more detail to understand what can be done here.

[IdrisMiles]

Hi @dannycjones all good!
Thanks for the context. For the time being I think we're able to work around the issue by writing locally and then moving the file to the mounted S3 bucket as a post process.
But if anything is able to be done here, e.g. adding a flag at mount time to enable blocking file close on s3 upload, that would be handy to make mountpoint-s3 slot into existing systems more seemlessly, at least in the world of visual effects.