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

Open IdrisMiles opened this issue 1 year ago • 2 comments

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

Apr 02 '25 11:04 IdrisMiles

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.

Apr 22 '25 06:04 dannycjones

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.

Apr 25 '25 08:04 IdrisMiles

Hi, as requested in the referenced issue https://github.com/awslabs/mountpoint-s3-csi-driver/issues/647#issuecomment-3597743940 I activated the debug option. This is the outcome:

2025-12-04T09:25:26.722564Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fs.current_handles[type=write]: 0
2025-12-04T09:25:26.722583Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fs.inode_kinds[kind=file]: 18
2025-12-04T09:25:26.722586Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fs.inodes: 25
2025-12-04T09:25:26.722587Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.idle_threads: n=52: min=2 p10=3 p50=3 avg=3.46 p90=4 p99=4 p99.9=4 max=4
2025-12-04T09:25:26.722589Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.io_size(B)[fuse_request=write]: n=8: min=1 p10=1 p50=72 avg=88.38 p90=185 p99=185 p99.9=185 max=185
2025-12-04T09:25:26.722591Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_errors[fuse_request=lookup]: 4 (n=4)
2025-12-04T09:25:26.722593Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_latency(μs)[fuse_request=flush]: n=2: min=130560 p10=131071 p50=131071 avg=133248.00 p90=136191 p99=136191 p99.9=136191 max=136191
2025-12-04T09:25:26.722595Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_latency(μs)[fuse_request=forget]: n=1: min=11 p10=11 p50=11 avg=11.00 p90=11 p99=11 p99.9=11 max=11
2025-12-04T09:25:26.722597Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_latency(μs)[fuse_request=getattr]: n=3: min=21 p10=21 p50=22 avg=16526.33 p90=49663 p99=49663 p99.9=49663 max=49663
2025-12-04T09:25:26.722599Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_latency(μs)[fuse_request=lookup]: n=5: min=15552 p10=15615 p50=47615 avg=43462.40 p90=57599 p99=57599 p99.9=57599 max=57599
2025-12-04T09:25:26.722601Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_latency(μs)[fuse_request=mknod]: n=2: min=46848 p10=47103 p50=47103 avg=50176.00 p90=53503 p99=53503 p99.9=53503 max=53503
2025-12-04T09:25:26.722603Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_latency(μs)[fuse_request=open]: n=2: min=45824 p10=46079 p50=46079 avg=47616.00 p90=49407 p99=49407 p99.9=49407 max=49407
2025-12-04T09:25:26.722605Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_latency(μs)[fuse_request=release]: n=2: min=23 p10=23 p50=23 avg=24.00 p90=25 p99=25 p99.9=25 max=25
2025-12-04T09:25:26.722608Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_latency(μs)[fuse_request=statfs]: n=1: min=14 p10=14 p50=14 avg=14.00 p90=14 p99=14 p99.9=14 max=14
2025-12-04T09:25:26.722609Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_latency(μs)[fuse_request=unlink]: n=1: min=31872 p10=31999 p50=31999 avg=31936.00 p90=31999 p99=31999 p99.9=31999 max=31999
2025-12-04T09:25:26.722612Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_latency(μs)[fuse_request=write]: n=8: min=11 p10=11 p50=24 avg=10319.00 p90=44287 p99=44287 p99.9=44287 max=44287
2025-12-04T09:25:26.722614Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.total_bytes[type=write]: 707 (n=8)
2025-12-04T09:25:26.722615Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: metadata_cache.inode_forgotten_before_expiry: 1
2025-12-04T09:25:26.722616Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: pool.allocated_pages[size=8388608]: 1
2025-12-04T09:25:26.722618Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: pool.empty_pages[size=8388608]: 1
2025-12-04T09:25:26.722619Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: pool.reserved_bytes[kind=put_object]: 0
2025-12-04T09:25:26.722621Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: pool.reserved_bytes[type=primary,kind=put_object]: n=2: min=8388608 p10=8454143 p50=8454143 avg=8421376.00 p90=8454143 p99=8454143 p99.9=8454143 max=8454143
2025-12-04T09:25:26.722623Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: pool.slack_bytes[size=8388608,kind=put_object]: n=2: min=0 p10=0 p50=0 avg=0.00 p90=0 p99=0 p99.9=0 max=0
2025-12-04T09:25:26.722625Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: pool.trim_pages[size=8388608]: n=1: min=1 p10=1 p50=1 avg=1.00 p90=1 p99=1 p99.9=1 max=1
2025-12-04T09:25:26.722626Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: process.memory_usage(B): 21295104
2025-12-04T09:25:26.722628Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.client.host_count[host=myapp-f8af1bd6.s3.eu-central-1.amazonaws.com]: 48
2025-12-04T09:25:26.722632Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.client.num_auto_default_network_io: 0
2025-12-04T09:25:26.722633Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.client.num_auto_ranged_copy_network_io: 0
2025-12-04T09:25:26.722635Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.client.num_auto_ranged_get_network_io: 0
2025-12-04T09:25:26.722636Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.client.num_auto_ranged_put_network_io: 0
2025-12-04T09:25:26.722638Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.client.num_requests_being_prepared: 0
2025-12-04T09:25:26.722639Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.client.num_requests_being_processed: 0
2025-12-04T09:25:26.722641Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.client.num_requests_stream_queued_waiting: 0
2025-12-04T09:25:26.722643Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.client.num_requests_streaming_response: 0
2025-12-04T09:25:26.722644Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.client.num_total_network_io: 0
2025-12-04T09:25:26.722646Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.client.request_queue_size: 0
2025-12-04T09:25:26.722648Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.endpoint_resolution_us: n=25: min=14 p10=19 p50=66 avg=51.80 p90=83 p99=91 p99.9=91 max=91
2025-12-04T09:25:26.722650Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests.canceled[op=head_object]: 1
2025-12-04T09:25:26.722652Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests.failures[op=head_object,status=404]: 8 (n=8)
2025-12-04T09:25:26.722654Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests.first_byte_latency_us[op=delete_object]: n=1: min=17152 p10=17279 p50=17279 avg=17216.00 p90=17279 p99=17279 p99.9=17279 max=17279
2025-12-04T09:25:26.722657Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests.first_byte_latency_us[op=head_object]: n=11: min=9792 p10=11711 p50=15103 avg=21038.55 p90=49407 p99=57343 p99.9=57343 max=57343
2025-12-04T09:25:26.722660Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests.first_byte_latency_us[op=list_objects]: n=11: min=13568 p10=14143 p50=46591 avg=38914.91 p90=50175 p99=52991 p99.9=52991 max=52991
2025-12-04T09:25:26.722663Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests.first_byte_latency_us[op=put_object]: n=2: min=168960 p10=169983 p50=169983 avg=175104.00 p90=181247 p99=181247 p99.9=181247 max=181247
2025-12-04T09:25:26.722666Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests.throughput_mibs[op=put_object,size=<1MiB]: n=2: min=0 p10=0 p50=0 avg=0.00 p90=0 p99=0 p99.9=0 max=0
2025-12-04T09:25:26.722669Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests.total_latency_us[op=delete_object]: n=1: min=17152 p10=17279 p50=17279 avg=17216.00 p90=17279 p99=17279 p99.9=17279 max=17279
2025-12-04T09:25:26.722672Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests.total_latency_us[op=head_object]: n=11: min=9792 p10=11711 p50=15103 avg=21038.55 p90=49407 p99=57343 p99.9=57343 max=57343
2025-12-04T09:25:26.722676Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests.total_latency_us[op=list_objects]: n=11: min=13632 p10=14207 p50=46591 avg=38955.64 p90=50175 p99=52991 p99.9=52991 max=52991
2025-12-04T09:25:26.722679Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests.total_latency_us[op=put_object]: n=2: min=168960 p10=169983 p50=169983 avg=175104.00 p90=181247 p99=181247 p99.9=181247 max=181247
2025-12-04T09:25:26.722683Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests[op=delete_object]: 1
2025-12-04T09:25:26.722686Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests[op=head_object]: 11 (n=11)
2025-12-04T09:25:26.722688Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests[op=list_objects]: 11 (n=11)
2025-12-04T09:25:26.722691Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests[op=put_object]: 2 (n=2)
2025-12-04T09:25:26.722694Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_canceled[s3_request=HeadObject]: 1
2025-12-04T09:25:26.722697Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_count[s3_request=CompleteMultipartUpload]: 2 (n=2)
2025-12-04T09:25:26.722700Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_count[s3_request=CreateMultipartUpload]: 2 (n=2)
2025-12-04T09:25:26.722702Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_count[s3_request=DeleteObject]: 1
2025-12-04T09:25:26.722704Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_count[s3_request=HeadObject]: 11 (n=11)
2025-12-04T09:25:26.722706Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_count[s3_request=ListObjectsV2]: 11 (n=11)
2025-12-04T09:25:26.722708Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_count[s3_request=UploadPart]: 2 (n=2)
2025-12-04T09:25:26.722710Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_errors[s3_request=HeadObject,http_status=404]: 8 (n=8)
2025-12-04T09:25:26.722712Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_first_byte_latency(μs)[s3_request=CompleteMultipartUpload]: n=2: min=48896 p10=49151 p50=49151 avg=49280.00 p90=49663 p99=49663 p99.9=49663 max=49663
2025-12-04T09:25:26.722722Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_first_byte_latency(μs)[s3_request=CreateMultipartUpload]: n=2: min=36608 p10=36863 p50=36863 avg=39680.00 p90=42751 p99=42751 p99.9=42751 max=42751
2025-12-04T09:25:26.722726Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_first_byte_latency(μs)[s3_request=DeleteObject]: n=1: min=16768 p10=16895 p50=16895 avg=16832.00 p90=16895 p99=16895 p99.9=16895 max=16895
2025-12-04T09:25:26.722729Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_first_byte_latency(μs)[s3_request=HeadObject]: n=10: min=9152 p10=9215 p50=13695 avg=17116.80 p90=16191 p99=51711 p99.9=51711 max=51711
2025-12-04T09:25:26.722733Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_first_byte_latency(μs)[s3_request=ListObjectsV2]: n=11: min=12544 p10=12671 p50=40703 avg=33899.64 p90=43519 p99=45567 p99.9=45567 max=45567
2025-12-04T09:25:26.722736Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_first_byte_latency(μs)[s3_request=UploadPart]: n=2: min=36096 p10=36351 p50=36351 avg=38016.00 p90=39935 p99=39935 p99.9=39935 max=39935
2025-12-04T09:25:26.722740Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_total_latency(μs)[s3_request=CompleteMultipartUpload]: n=2: min=93696 p10=94207 p50=94207 avg=94464.00 p90=95231 p99=95231 p99.9=95231 max=95231
2025-12-04T09:25:26.722744Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_total_latency(μs)[s3_request=CreateMultipartUpload]: n=2: min=37632 p10=37887 p50=37887 avg=40704.00 p90=43775 p99=43775 p99.9=43775 max=43775
2025-12-04T09:25:26.722748Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_total_latency(μs)[s3_request=DeleteObject]: n=1: min=17024 p10=17151 p50=17151 avg=17088.00 p90=17151 p99=17151 p99.9=17151 max=17151
2025-12-04T09:25:26.722751Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_total_latency(μs)[s3_request=HeadObject]: n=11: min=9344 p10=11391 p50=14911 avg=20750.55 p90=49151 p99=57087 p99.9=57087 max=57087
2025-12-04T09:25:26.722779Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_total_latency(μs)[s3_request=ListObjectsV2]: n=11: min=13504 p10=14079 p50=46335 avg=38827.64 p90=50175 p99=52991 p99.9=52991 max=52991
2025-12-04T09:25:26.722784Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_total_latency(μs)[s3_request=UploadPart]: n=2: min=36352 p10=36607 p50=36607 avg=38272.00 p90=40191 p99=40191 p99.9=40191 max=40191
2025-12-04T09:25:26.722788Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: system.available_memory: 12587982848
2025-12-04T09:25:27.523660Z DEBUG ThreadId(10) fuser::request: FUSE(2892) ino 0x0000000000000007 GETATTR
2025-12-04T09:25:27.523832Z DEBUG ThreadId(10) getattr{req=2892 ino=7 name="ffdc"}:head_object{id=250 bucket="myapp-f8af1bd6" key="online/logs/ffdc"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-12-04T09:25:27.524015Z DEBUG ThreadId(10) getattr{req=2892 ino=7 name="ffdc"}:list_objects{id=251 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-12-04T09:25:27.548009Z DEBUG ThreadId(11) getattr{req=2892 ino=7 name="ffdc"}:list_objects{id=251 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/"}: mountpoint_s3_client::s3_crt_client: S3 request finished operation_name="ListObjectsV2" crt_error=None http_status=200 range=None duration=23.789528ms ttfb=Some(17.588697ms) request_id=ZNKSNQCQ5BAHY5H7
2025-12-04T09:25:27.548088Z DEBUG ThreadId(06) getattr{req=2892 ino=7 name="ffdc"}:list_objects{id=251 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=24.032655ms
2025-12-04T09:25:27.548362Z DEBUG ThreadId(11) getattr{req=2892 ino=7 name="ffdc"}:head_object{id=250 bucket="myapp-f8af1bd6" key="online/logs/ffdc"}: mountpoint_s3_client::s3_crt_client: S3 request canceled operation_name="HeadObject" crt_error=Some(Error(14347, "aws-c-s3: AWS_ERROR_S3_CANCELED, Request successfully cancelled")) range=None duration=24.314796ms ttfb=None request_id=<unknown>
2025-12-04T09:25:27.548401Z DEBUG ThreadId(06) getattr{req=2892 ino=7 name="ffdc"}:head_object{id=250 bucket="myapp-f8af1bd6" key="online/logs/ffdc"}: mountpoint_s3_client::s3_crt_client: duration=24.542104ms request_id=<unknown> error=ClientError(RequestCanceled) meta request canceled
2025-12-04T09:25:27.548412Z DEBUG ThreadId(06) getattr{req=2892 ino=7 name="ffdc"}:head_object{id=250 bucket="myapp-f8af1bd6" key="online/logs/ffdc"}: mountpoint_s3_client::s3_crt_client: meta request result: MetaRequestResult { response_status: 0, crt_error: Error(14347, "aws-c-s3: AWS_ERROR_S3_CANCELED, Request successfully cancelled"), error_response_headers: None, error_response_body: None }
2025-12-04T09:25:27.564035Z DEBUG ThreadId(15) fuser::request: FUSE(2894) ino 0x0000000000000007 LOOKUP name "ffdc_25.12.04_09.25.27.0.log"
2025-12-04T09:25:27.564199Z DEBUG ThreadId(15) lookup{req=2894 ino=7 name="ffdc_25.12.04_09.25.27.0.log"}:head_object{id=252 bucket="myapp-f8af1bd6" key="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-12-04T09:25:27.564289Z DEBUG ThreadId(15) lookup{req=2894 ino=7 name="ffdc_25.12.04_09.25.27.0.log"}:list_objects{id=253 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-12-04T09:25:27.579067Z DEBUG ThreadId(11) lookup{req=2894 ino=7 name="ffdc_25.12.04_09.25.27.0.log"}:list_objects{id=253 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client: S3 request finished operation_name="ListObjectsV2" crt_error=None http_status=200 range=None duration=14.514585ms ttfb=Some(13.377845ms) request_id=ZNKT1SE21GT8K30F
2025-12-04T09:25:27.579154Z DEBUG ThreadId(06) lookup{req=2894 ino=7 name="ffdc_25.12.04_09.25.27.0.log"}:list_objects{id=253 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=14.850398ms
2025-12-04T09:25:27.610318Z DEBUG ThreadId(11) lookup{req=2894 ino=7 name="ffdc_25.12.04_09.25.27.0.log"}:head_object{id=252 bucket="myapp-f8af1bd6" key="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: S3 request failed operation_name="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=45.645338ms ttfb=Some(42.306951ms) request_id=ZNKWGP2SVQZETQ9C
2025-12-04T09:25:27.610401Z DEBUG ThreadId(06) lookup{req=2894 ino=7 name="ffdc_25.12.04_09.25.27.0.log"}:head_object{id=252 bucket="myapp-f8af1bd6" key="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: duration=46.171687ms request_id=ZNKWGP2SVQZETQ9C error=ServiceError(NotFound) meta request failed
2025-12-04T09:25:27.610423Z DEBUG ThreadId(06) lookup{req=2894 ino=7 name="ffdc_25.12.04_09.25.27.0.log"}:head_object{id=252 bucket="myapp-f8af1bd6" key="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log"}: 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: 0x7f968803cdd0 }), error_response_body: None }
2025-12-04T09:25:27.610507Z DEBUG ThreadId(15) lookup{req=2894 ino=7 name="ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_fs::fuse: lookup failed with errno 2: file does not exist: file "ffdc_25.12.04_09.25.27.0.log" does not exist in parent inode 7 (partial key "logs/ffdc/")
2025-12-04T09:25:27.620825Z DEBUG ThreadId(08) fuser::request: FUSE(2896) ino 0x0000000000000007 MKNOD name "ffdc_25.12.04_09.25.27.0.log", mode 0o100640, rdev 0
2025-12-04T09:25:27.621074Z DEBUG ThreadId(08) mknod{req=2896 parent=7 name="ffdc_25.12.04_09.25.27.0.log"}:head_object{id=254 bucket="myapp-f8af1bd6" key="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-12-04T09:25:27.621152Z DEBUG ThreadId(08) mknod{req=2896 parent=7 name="ffdc_25.12.04_09.25.27.0.log"}:list_objects{id=255 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-12-04T09:25:27.631127Z DEBUG ThreadId(11) mknod{req=2896 parent=7 name="ffdc_25.12.04_09.25.27.0.log"}:head_object{id=254 bucket="myapp-f8af1bd6" key="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: S3 request failed operation_name="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.830036ms ttfb=Some(9.462077ms) request_id=ZNKYAMWWGMR4WMBQ
2025-12-04T09:25:27.631190Z DEBUG ThreadId(06) mknod{req=2896 parent=7 name="ffdc_25.12.04_09.25.27.0.log"}:head_object{id=254 bucket="myapp-f8af1bd6" key="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: duration=10.094762ms request_id=ZNKYAMWWGMR4WMBQ error=ServiceError(NotFound) meta request failed
2025-12-04T09:25:27.631200Z DEBUG ThreadId(06) mknod{req=2896 parent=7 name="ffdc_25.12.04_09.25.27.0.log"}:head_object{id=254 bucket="myapp-f8af1bd6" key="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log"}: 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: 0x7f968001f380 }), error_response_body: None }
2025-12-04T09:25:27.669645Z DEBUG ThreadId(12) mknod{req=2896 parent=7 name="ffdc_25.12.04_09.25.27.0.log"}:list_objects{id=255 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client: S3 request finished operation_name="ListObjectsV2" crt_error=None http_status=200 range=None duration=48.339534ms ttfb=Some(42.199128ms) request_id=ZNKWR6KR1W2FRCAM
2025-12-04T09:25:27.669737Z DEBUG ThreadId(06) mknod{req=2896 parent=7 name="ffdc_25.12.04_09.25.27.0.log"}:list_objects{id=255 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=48.565546ms
2025-12-04T09:25:27.669907Z DEBUG ThreadId(08) mknod{req=2896 parent=7 name="ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_fs::fs: new inode created ino=26
2025-12-04T09:25:27.670019Z DEBUG ThreadId(16) fuser::request: FUSE(2898) ino 0x000000000000001a OPEN flags 0x8002
2025-12-04T09:25:27.670239Z DEBUG ThreadId(16) open{req=2898 ino=26 pid=110262 name="ffdc_25.12.04_09.25.27.0.log"}:head_object{id=256 bucket="myapp-f8af1bd6" key="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-12-04T09:25:27.670329Z DEBUG ThreadId(16) open{req=2898 ino=26 pid=110262 name="ffdc_25.12.04_09.25.27.0.log"}:list_objects{id=257 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-12-04T09:25:27.684467Z DEBUG ThreadId(11) open{req=2898 ino=26 pid=110262 name="ffdc_25.12.04_09.25.27.0.log"}:head_object{id=256 bucket="myapp-f8af1bd6" key="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: S3 request failed operation_name="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.101713ms ttfb=Some(13.787114ms) request_id=ZNKYHVK6P74R40DJ
2025-12-04T09:25:27.684558Z DEBUG ThreadId(06) open{req=2898 ino=26 pid=110262 name="ffdc_25.12.04_09.25.27.0.log"}:head_object{id=256 bucket="myapp-f8af1bd6" key="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: duration=14.276624ms request_id=ZNKYHVK6P74R40DJ error=ServiceError(NotFound) meta request failed
2025-12-04T09:25:27.684574Z DEBUG ThreadId(06) open{req=2898 ino=26 pid=110262 name="ffdc_25.12.04_09.25.27.0.log"}:head_object{id=256 bucket="myapp-f8af1bd6" key="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log"}: 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: 0x7f9688025a80 }), error_response_body: None }
2025-12-04T09:25:27.709510Z DEBUG ThreadId(11) open{req=2898 ino=26 pid=110262 name="ffdc_25.12.04_09.25.27.0.log"}:list_objects{id=257 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client: S3 request finished operation_name="ListObjectsV2" crt_error=None http_status=200 range=None duration=39.083438ms ttfb=Some(34.917256ms) request_id=ZNKTCS0PJHFAGKF8
2025-12-04T09:25:27.709577Z DEBUG ThreadId(06) open{req=2898 ino=26 pid=110262 name="ffdc_25.12.04_09.25.27.0.log"}:list_objects{id=257 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=39.236048ms
2025-12-04T09:25:27.709705Z DEBUG ThreadId(16) open{req=2898 ino=26 pid=110262 name="ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_fs::fs: fs:open choosing write handle for O_RDWR
2025-12-04T09:25:27.709732Z DEBUG ThreadId(16) open{req=2898 ino=26 pid=110262 name="ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_fs::fs: new file handle created fh=19 ino=26
2025-12-04T09:25:27.709803Z DEBUG ThreadId(10) fuser::request: FUSE(2900) ino 0x000000000000001a FLUSH fh FileHandle(19), lock owner LockOwner(2232806188869093241)
2025-12-04T09:25:27.709838Z DEBUG ThreadId(10) flush{req=2900 ino=26 fh=19 pid=110262 name="ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_fs::fs::handles: not completing upload because nothing was written yet key=online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log (bucket: myapp-f8af1bd6)
2025-12-04T09:25:27.710077Z DEBUG ThreadId(18) put_object{id=258 bucket="myapp-f8af1bd6" key="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client::put_object: new request
2025-12-04T09:25:27.720829Z DEBUG ThreadId(15) fuser::request: FUSE(2902) ino 0x000000000000001a RELEASE fh FileHandle(19), flags 0x8002, flush false, lock owner None
2025-12-04T09:25:27.721966Z DEBUG ThreadId(08) fuser::request: FUSE(2904) ino 0x0000000000000007 GETATTR
2025-12-04T09:25:27.722073Z DEBUG ThreadId(16) fuser::request: FUSE(2906) ino 0x000000000000001a OPEN flags 0x8201
2025-12-04T09:25:27.722198Z DEBUG ThreadId(16) open{req=2906 ino=26 pid=110262 name="ffdc_25.12.04_09.25.27.0.log"}:head_object{id=259 bucket="myapp-f8af1bd6" key="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-12-04T09:25:27.722324Z DEBUG ThreadId(16) open{req=2906 ino=26 pid=110262 name="ffdc_25.12.04_09.25.27.0.log"}:list_objects{id=260 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-12-04T09:25:27.755393Z DEBUG ThreadId(05) put_object{id=258 bucket="myapp-f8af1bd6" key="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: S3 request finished operation_name="CreateMultipartUpload" crt_error=None http_status=200 range=None duration=44.962204ms ttfb=Some(43.721261ms) request_id=ZNKZT7KT60E27TZV
2025-12-04T09:25:27.765346Z DEBUG ThreadId(05) open{req=2906 ino=26 pid=110262 name="ffdc_25.12.04_09.25.27.0.log"}:head_object{id=259 bucket="myapp-f8af1bd6" key="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: S3 request failed operation_name="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=42.974958ms ttfb=Some(39.162074ms) request_id=ZNKHZS3XJ9KTH10M
2025-12-04T09:25:27.765463Z DEBUG ThreadId(06) open{req=2906 ino=26 pid=110262 name="ffdc_25.12.04_09.25.27.0.log"}:head_object{id=259 bucket="myapp-f8af1bd6" key="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: duration=43.198856ms request_id=ZNKHZS3XJ9KTH10M error=ServiceError(NotFound) meta request failed
2025-12-04T09:25:27.765485Z DEBUG ThreadId(06) open{req=2906 ino=26 pid=110262 name="ffdc_25.12.04_09.25.27.0.log"}:head_object{id=259 bucket="myapp-f8af1bd6" key="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log"}: 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: 0x7f967404b280 }), error_response_body: None }
2025-12-04T09:25:27.774567Z DEBUG ThreadId(05) open{req=2906 ino=26 pid=110262 name="ffdc_25.12.04_09.25.27.0.log"}:list_objects{id=260 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client: S3 request finished operation_name="ListObjectsV2" crt_error=None http_status=200 range=None duration=52.118624ms ttfb=Some(42.659524ms) request_id=ZNKK6PRN2Y9WHQ2Q
2025-12-04T09:25:27.774632Z DEBUG ThreadId(06) open{req=2906 ino=26 pid=110262 name="ffdc_25.12.04_09.25.27.0.log"}:list_objects{id=260 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=52.25644ms
2025-12-04T09:25:27.774801Z  WARN ThreadId(16) open{req=2906 ino=26 pid=110262 name="ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_fs::fuse: open failed with errno 1: inode error: inode 26 (partial key "logs/ffdc/ffdc_25.12.04_09.25.27.0.log") is already being written
2025-12-04T09:25:27.775483Z DEBUG ThreadId(10) fuser::request: FUSE(2908) ino 0x0000000000000007 LOOKUP name "exception_summary_25.12.04_09.25.27.0.log"
2025-12-04T09:25:27.775615Z DEBUG ThreadId(10) lookup{req=2908 ino=7 name="exception_summary_25.12.04_09.25.27.0.log"}:head_object{id=261 bucket="myapp-f8af1bd6" key="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-12-04T09:25:27.775683Z DEBUG ThreadId(10) lookup{req=2908 ino=7 name="exception_summary_25.12.04_09.25.27.0.log"}:list_objects{id=262 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-12-04T09:25:27.790450Z DEBUG ThreadId(11) lookup{req=2908 ino=7 name="exception_summary_25.12.04_09.25.27.0.log"}:head_object{id=261 bucket="myapp-f8af1bd6" key="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: S3 request failed operation_name="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.701812ms ttfb=Some(14.441593ms) request_id=ZNKTTDKE0GFAAKAS
2025-12-04T09:25:27.790566Z DEBUG ThreadId(06) lookup{req=2908 ino=7 name="exception_summary_25.12.04_09.25.27.0.log"}:head_object{id=261 bucket="myapp-f8af1bd6" key="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: duration=14.931724ms request_id=ZNKTTDKE0GFAAKAS error=ServiceError(NotFound) meta request failed
2025-12-04T09:25:27.790581Z DEBUG ThreadId(06) lookup{req=2908 ino=7 name="exception_summary_25.12.04_09.25.27.0.log"}:head_object{id=261 bucket="myapp-f8af1bd6" key="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log"}: 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: 0x7f967402a3d0 }), error_response_body: None }
2025-12-04T09:25:27.791202Z DEBUG ThreadId(05) put_object{id=258 bucket="myapp-f8af1bd6" key="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: S3 request finished operation_name="UploadPart" crt_error=None http_status=200 range=None duration=35.361402ms ttfb=Some(35.082314ms) request_id=ZNKPT6E0DHB2DX5Q
2025-12-04T09:25:27.824474Z DEBUG ThreadId(11) lookup{req=2908 ino=7 name="exception_summary_25.12.04_09.25.27.0.log"}:list_objects{id=262 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client: S3 request finished operation_name="ListObjectsV2" crt_error=None http_status=200 range=None duration=48.634721ms ttfb=Some(41.606294ms) request_id=ZNKRT44FFTCYJABB
2025-12-04T09:25:27.824545Z DEBUG ThreadId(06) lookup{req=2908 ino=7 name="exception_summary_25.12.04_09.25.27.0.log"}:list_objects{id=262 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=48.843695ms
2025-12-04T09:25:27.824673Z DEBUG ThreadId(10) lookup{req=2908 ino=7 name="exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_fs::fuse: lookup failed with errno 2: file does not exist: file "exception_summary_25.12.04_09.25.27.0.log" does not exist in parent inode 7 (partial key "logs/ffdc/")
2025-12-04T09:25:27.824742Z DEBUG ThreadId(08) fuser::request: FUSE(2910) ino 0x0000000000000007 MKNOD name "exception_summary_25.12.04_09.25.27.0.log", mode 0o100640, rdev 0
2025-12-04T09:25:27.824893Z DEBUG ThreadId(08) mknod{req=2910 parent=7 name="exception_summary_25.12.04_09.25.27.0.log"}:head_object{id=263 bucket="myapp-f8af1bd6" key="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-12-04T09:25:27.824968Z DEBUG ThreadId(08) mknod{req=2910 parent=7 name="exception_summary_25.12.04_09.25.27.0.log"}:list_objects{id=264 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-12-04T09:25:27.840224Z DEBUG ThreadId(11) mknod{req=2910 parent=7 name="exception_summary_25.12.04_09.25.27.0.log"}:head_object{id=263 bucket="myapp-f8af1bd6" key="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: S3 request failed operation_name="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=15.025752ms ttfb=Some(14.782815ms) request_id=ZNKY3NQ1HTKNHKXA
2025-12-04T09:25:27.840310Z DEBUG ThreadId(06) mknod{req=2910 parent=7 name="exception_summary_25.12.04_09.25.27.0.log"}:head_object{id=263 bucket="myapp-f8af1bd6" key="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: duration=15.391422ms request_id=ZNKY3NQ1HTKNHKXA error=ServiceError(NotFound) meta request failed
2025-12-04T09:25:27.840328Z DEBUG ThreadId(06) mknod{req=2910 parent=7 name="exception_summary_25.12.04_09.25.27.0.log"}:head_object{id=263 bucket="myapp-f8af1bd6" key="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log"}: 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: 0x7f9688018150 }), error_response_body: None }
2025-12-04T09:25:27.871147Z DEBUG ThreadId(05) mknod{req=2910 parent=7 name="exception_summary_25.12.04_09.25.27.0.log"}:list_objects{id=264 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client: S3 request finished operation_name="ListObjectsV2" crt_error=None http_status=200 range=None duration=46.090318ms ttfb=Some(42.112432ms) request_id=ZNKVBQ8R575WJZH1
2025-12-04T09:25:27.871347Z DEBUG ThreadId(06) mknod{req=2910 parent=7 name="exception_summary_25.12.04_09.25.27.0.log"}:list_objects{id=264 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=46.332794ms
2025-12-04T09:25:27.871506Z DEBUG ThreadId(08) mknod{req=2910 parent=7 name="exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_fs::fs: new inode created ino=27
2025-12-04T09:25:27.871633Z DEBUG ThreadId(16) fuser::request: FUSE(2912) ino 0x000000000000001b OPEN flags 0x8002
2025-12-04T09:25:27.871771Z DEBUG ThreadId(16) open{req=2912 ino=27 pid=110262 name="exception_summary_25.12.04_09.25.27.0.log"}:head_object{id=265 bucket="myapp-f8af1bd6" key="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-12-04T09:25:27.871837Z DEBUG ThreadId(16) open{req=2912 ino=27 pid=110262 name="exception_summary_25.12.04_09.25.27.0.log"}:list_objects{id=266 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-12-04T09:25:27.884109Z DEBUG ThreadId(05) open{req=2912 ino=27 pid=110262 name="exception_summary_25.12.04_09.25.27.0.log"}:head_object{id=265 bucket="myapp-f8af1bd6" key="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: S3 request failed operation_name="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.24131ms ttfb=Some(11.728742ms) request_id=ZNKGFAMXGSHY364Z
2025-12-04T09:25:27.884171Z DEBUG ThreadId(06) open{req=2912 ino=27 pid=110262 name="exception_summary_25.12.04_09.25.27.0.log"}:head_object{id=265 bucket="myapp-f8af1bd6" key="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: duration=12.383115ms request_id=ZNKGFAMXGSHY364Z error=ServiceError(NotFound) meta request failed
2025-12-04T09:25:27.884178Z DEBUG ThreadId(06) open{req=2912 ino=27 pid=110262 name="exception_summary_25.12.04_09.25.27.0.log"}:head_object{id=265 bucket="myapp-f8af1bd6" key="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log"}: 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: 0x7f9680025710 }), error_response_body: None }
2025-12-04T09:25:27.940265Z DEBUG ThreadId(05) open{req=2912 ino=27 pid=110262 name="exception_summary_25.12.04_09.25.27.0.log"}:list_objects{id=266 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client: S3 request finished operation_name="ListObjectsV2" crt_error=None http_status=200 range=None duration=68.30052ms ttfb=Some(61.754512ms) request_id=ZNKR2CD8DQRJYCAY
2025-12-04T09:25:27.940335Z DEBUG ThreadId(06) open{req=2912 ino=27 pid=110262 name="exception_summary_25.12.04_09.25.27.0.log"}:list_objects{id=266 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=68.481787ms
2025-12-04T09:25:27.940437Z DEBUG ThreadId(16) open{req=2912 ino=27 pid=110262 name="exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_fs::fs: fs:open choosing write handle for O_RDWR
2025-12-04T09:25:27.940467Z DEBUG ThreadId(16) open{req=2912 ino=27 pid=110262 name="exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_fs::fs: new file handle created fh=20 ino=27
2025-12-04T09:25:27.940559Z DEBUG ThreadId(10) fuser::request: FUSE(2914) ino 0x000000000000001b FLUSH fh FileHandle(20), lock owner LockOwner(2232806188869093241)
2025-12-04T09:25:27.940597Z DEBUG ThreadId(10) flush{req=2914 ino=27 fh=20 pid=110262 name="exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_fs::fs::handles: not completing upload because nothing was written yet key=online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log (bucket: myapp-f8af1bd6)
2025-12-04T09:25:27.940607Z DEBUG ThreadId(14) put_object{id=267 bucket="myapp-f8af1bd6" key="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client::put_object: new request
2025-12-04T09:25:27.940650Z DEBUG ThreadId(08) fuser::request: FUSE(2916) ino 0x000000000000001b RELEASE fh FileHandle(20), flags 0x8002, flush false, lock owner None
2025-12-04T09:25:27.940741Z DEBUG ThreadId(16) fuser::request: FUSE(2918) ino 0x0000000000000007 GETATTR
2025-12-04T09:25:27.940890Z DEBUG ThreadId(10) fuser::request: FUSE(2920) ino 0x000000000000001b OPEN flags 0x8201
2025-12-04T09:25:27.941013Z DEBUG ThreadId(10) open{req=2920 ino=27 pid=110262 name="exception_summary_25.12.04_09.25.27.0.log"}:head_object{id=268 bucket="myapp-f8af1bd6" key="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-12-04T09:25:27.941078Z DEBUG ThreadId(10) open{req=2920 ino=27 pid=110262 name="exception_summary_25.12.04_09.25.27.0.log"}:list_objects{id=269 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-12-04T09:25:27.988801Z DEBUG ThreadId(05) put_object{id=267 bucket="myapp-f8af1bd6" key="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: S3 request finished operation_name="CreateMultipartUpload" crt_error=None http_status=200 range=None duration=47.76217ms ttfb=Some(46.640515ms) request_id=ZNKZGP2K16MPTV2C
2025-12-04T09:25:27.989795Z DEBUG ThreadId(05) open{req=2920 ino=27 pid=110262 name="exception_summary_25.12.04_09.25.27.0.log"}:head_object{id=268 bucket="myapp-f8af1bd6" key="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: S3 request failed operation_name="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=48.63812ms ttfb=Some(44.812382ms) request_id=ZNKTNJMMKDSV18G4
2025-12-04T09:25:27.989939Z DEBUG ThreadId(06) open{req=2920 ino=27 pid=110262 name="exception_summary_25.12.04_09.25.27.0.log"}:head_object{id=268 bucket="myapp-f8af1bd6" key="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: duration=48.904109ms request_id=ZNKTNJMMKDSV18G4 error=ServiceError(NotFound) meta request failed
2025-12-04T09:25:27.989962Z DEBUG ThreadId(06) open{req=2920 ino=27 pid=110262 name="exception_summary_25.12.04_09.25.27.0.log"}:head_object{id=268 bucket="myapp-f8af1bd6" key="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log"}: 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: 0x7f967c06e970 }), error_response_body: None }
2025-12-04T09:25:28.013480Z DEBUG ThreadId(05) open{req=2920 ino=27 pid=110262 name="exception_summary_25.12.04_09.25.27.0.log"}:list_objects{id=269 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client: S3 request finished operation_name="ListObjectsV2" crt_error=None http_status=200 range=None duration=72.288795ms ttfb=Some(66.474461ms) request_id=ZNKKPY4FR2N16ZNE
2025-12-04T09:25:28.013730Z DEBUG ThreadId(06) open{req=2920 ino=27 pid=110262 name="exception_summary_25.12.04_09.25.27.0.log"}:list_objects{id=269 bucket="myapp-f8af1bd6" continued=false delimiter="/" max_keys="1" prefix="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=72.631506ms
2025-12-04T09:25:28.013900Z  WARN ThreadId(10) open{req=2920 ino=27 pid=110262 name="exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_fs::fuse: open failed with errno 1: inode error: inode 27 (partial key "logs/ffdc/exception_summary_25.12.04_09.25.27.0.log") is already being written
2025-12-04T09:25:28.025674Z DEBUG ThreadId(05) put_object{id=267 bucket="myapp-f8af1bd6" key="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: S3 request finished operation_name="UploadPart" crt_error=None http_status=200 range=None duration=36.468289ms ttfb=Some(36.174387ms) request_id=ZNKJEJF8D23VYJHJ
2025-12-04T09:25:28.119049Z DEBUG ThreadId(05) put_object{id=267 bucket="myapp-f8af1bd6" key="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: S3 request finished operation_name="CompleteMultipartUpload" crt_error=None http_status=200 range=None duration=93.267121ms ttfb=Some(47.550452ms) request_id=2MK36ASZV2TA677T
2025-12-04T09:25:28.119120Z DEBUG ThreadId(06) put_object{id=267 bucket="myapp-f8af1bd6" key="online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=178.388967ms
2025-12-04T09:25:28.119252Z DEBUG ThreadId(08) release{req=2916 ino=27 fh=20 name="exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_fs::fs::handles: put succeeded etag="\"0d09eabd0d4e9df587ba685829e20863-1\"" key=online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log (bucket: myapp-f8af1bd6) size=0
2025-12-04T09:25:28.119281Z DEBUG ThreadId(08) release{req=2916 ino=27 fh=20 name="exception_summary_25.12.04_09.25.27.0.log"}: mountpoint_s3_fs::fs: upload completed async after file was closed key=online/logs/ffdc/exception_summary_25.12.04_09.25.27.0.log (bucket: myapp-f8af1bd6)
2025-12-04T09:25:28.153053Z DEBUG ThreadId(05) put_object{id=258 bucket="myapp-f8af1bd6" key="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: S3 request finished operation_name="CompleteMultipartUpload" crt_error=None http_status=200 range=None duration=361.74326ms ttfb=Some(116.315304ms) request_id=ZNKVZTGYRRPVYRP4
2025-12-04T09:25:28.153138Z DEBUG ThreadId(06) put_object{id=258 bucket="myapp-f8af1bd6" key="online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=442.934255ms
2025-12-04T09:25:28.153239Z DEBUG ThreadId(15) release{req=2902 ino=26 fh=19 name="ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_fs::fs::handles: put succeeded etag="\"14be856d734231bee1676da5000204b1-1\"" key=online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log (bucket: myapp-f8af1bd6) size=0
2025-12-04T09:25:28.153270Z DEBUG ThreadId(15) release{req=2902 ino=26 fh=19 name="ffdc_25.12.04_09.25.27.0.log"}: mountpoint_s3_fs::fs: upload completed async after file was closed key=online/logs/ffdc/ffdc_25.12.04_09.25.27.0.log (bucket: myapp-f8af1bd6)
2025-12-04T09:25:31.723334Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fs.current_handles[type=write]: 0
2025-12-04T09:25:31.723349Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fs.inode_kinds[kind=file]: 20
2025-12-04T09:25:31.723351Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fs.inodes: 27
2025-12-04T09:25:31.723353Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.idle_threads: n=30: min=1 p10=1 p50=3 avg=2.70 p90=4 p99=4 p99.9=4 max=4
2025-12-04T09:25:31.723354Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_errors[fuse_request=lookup]: 2 (n=2)
2025-12-04T09:25:31.723355Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_errors[fuse_request=open]: 2 (n=2)
2025-12-04T09:25:31.723356Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_latency(μs)[fuse_request=flush]: n=2: min=31 p10=31 p50=31 avg=32.00 p90=33 p99=33 p99.9=33 max=33
2025-12-04T09:25:31.723357Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_latency(μs)[fuse_request=getattr]: n=3: min=17 p10=17 p50=25 avg=8270.00 p90=24831 p99=24831 p99.9=24831 max=24831
2025-12-04T09:25:31.723359Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_latency(μs)[fuse_request=lookup]: n=2: min=46336 p10=46591 p50=46591 avg=47872.00 p90=49407 p99=49407 p99.9=49407 max=49407
2025-12-04T09:25:31.723360Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_latency(μs)[fuse_request=mknod]: n=2: min=46592 p10=46847 p50=46847 avg=47872.00 p90=49151 p99=49151 p99.9=49151 max=49151
2025-12-04T09:25:31.723362Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_latency(μs)[fuse_request=open]: n=4: min=39424 p10=39679 p50=52991 avg=58560.00 p90=73215 p99=73215 p99.9=73215 max=73215
2025-12-04T09:25:31.723363Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_latency(μs)[fuse_request=release]: n=2: min=178176 p10=179199 p50=179199 avg=305920.00 p90=434175 p99=434175 p99.9=434175 max=434175
2025-12-04T09:25:31.723365Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: pool.allocated_pages[size=8388608]: 0
2025-12-04T09:25:31.723366Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: pool.empty_pages[size=8388608]: 0
2025-12-04T09:25:31.723367Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: pool.reserved_bytes[kind=put_object]: 0
2025-12-04T09:25:31.723368Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: pool.reserved_bytes[type=primary,kind=put_object]: n=2: min=8388608 p10=8454143 p50=8454143 avg=8421376.00 p90=8454143 p99=8454143 p99.9=8454143 max=8454143
2025-12-04T09:25:31.723370Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: pool.slack_bytes[size=8388608,kind=put_object]: n=2: min=0 p10=0 p50=0 avg=0.00 p90=0 p99=0 p99.9=0 max=0
2025-12-04T09:25:31.723371Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: pool.trim_pages[size=8388608]: n=1: min=1 p10=1 p50=1 avg=1.00 p90=1 p99=1 p99.9=1 max=1
2025-12-04T09:25:31.723372Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: process.memory_usage(B): 21331968
2025-12-04T09:25:31.723373Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.client.host_count[host=myapp-f8af1bd6.s3.eu-central-1.amazonaws.com]: 48
2025-12-04T09:25:31.723374Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.client.num_auto_default_network_io: 0
2025-12-04T09:25:31.723375Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.client.num_auto_ranged_copy_network_io: 0
2025-12-04T09:25:31.723376Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.client.num_auto_ranged_get_network_io: 0
2025-12-04T09:25:31.723377Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.client.num_auto_ranged_put_network_io: 2
2025-12-04T09:25:31.723378Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.client.num_requests_being_prepared: 1
2025-12-04T09:25:31.723379Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.client.num_requests_being_processed: 3
2025-12-04T09:25:31.723380Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.client.num_requests_stream_queued_waiting: 0
2025-12-04T09:25:31.723381Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.client.num_requests_streaming_response: 0
2025-12-04T09:25:31.723382Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.client.num_total_network_io: 2
2025-12-04T09:25:31.723386Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.client.request_queue_size: 0
2025-12-04T09:25:31.723392Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.endpoint_resolution_us: n=20: min=19 p10=19 p50=68 avg=53.80 p90=81 p99=88 p99.9=88 max=88
2025-12-04T09:25:31.723393Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests.canceled[op=head_object]: 1
2025-12-04T09:25:31.723394Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests.failures[op=head_object,status=404]: 8 (n=8)
2025-12-04T09:25:31.723395Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests.first_byte_latency_us[op=head_object]: n=9: min=10048 p10=10111 p50=15423 avg=25553.78 p90=49151 p99=49151 p99.9=49151 max=49151
2025-12-04T09:25:31.723397Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests.first_byte_latency_us[op=list_objects]: n=9: min=14720 p10=14783 p50=48639 avg=46019.56 p90=72703 p99=72703 p99.9=72703 max=72703
2025-12-04T09:25:31.723398Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests.first_byte_latency_us[op=put_object]: n=2: min=178176 p10=179199 p50=179199 avg=311040.00 p90=444415 p99=444415 p99.9=444415 max=444415
2025-12-04T09:25:31.723400Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests.throughput_mibs[op=put_object,size=<1MiB]: n=2: min=0 p10=0 p50=0 avg=0.00 p90=0 p99=0 p99.9=0 max=0
2025-12-04T09:25:31.723402Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests.total_latency_us[op=head_object]: n=9: min=10048 p10=10111 p50=15423 avg=25553.78 p90=49151 p99=49151 p99.9=49151 max=49151
2025-12-04T09:25:31.723403Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests.total_latency_us[op=list_objects]: n=9: min=14848 p10=14911 p50=48639 avg=46090.67 p90=72703 p99=72703 p99.9=72703 max=72703
2025-12-04T09:25:31.723405Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests.total_latency_us[op=put_object]: n=2: min=178176 p10=179199 p50=179199 avg=311040.00 p90=444415 p99=444415 p99.9=444415 max=444415
2025-12-04T09:25:31.723407Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests[op=head_object]: 9 (n=9)
2025-12-04T09:25:31.723408Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests[op=list_objects]: 9 (n=9)
2025-12-04T09:25:31.723409Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.meta_requests[op=put_object]: 2 (n=2)
2025-12-04T09:25:31.723410Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_canceled[s3_request=HeadObject]: 1
2025-12-04T09:25:31.723411Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_count[s3_request=CompleteMultipartUpload]: 2 (n=2)
2025-12-04T09:25:31.723413Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_count[s3_request=CreateMultipartUpload]: 2 (n=2)
2025-12-04T09:25:31.723414Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_count[s3_request=HeadObject]: 9 (n=9)
2025-12-04T09:25:31.723415Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_count[s3_request=ListObjectsV2]: 9 (n=9)
2025-12-04T09:25:31.723416Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_count[s3_request=UploadPart]: 2 (n=2)
2025-12-04T09:25:31.723417Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_errors[s3_request=HeadObject,http_status=404]: 8 (n=8)
2025-12-04T09:25:31.723419Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_first_byte_latency(μs)[s3_request=CompleteMultipartUpload]: n=2: min=47360 p10=47615 p50=47615 avg=81984.00 p90=116735 p99=116735 p99.9=116735 max=116735
2025-12-04T09:25:31.723421Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_first_byte_latency(μs)[s3_request=CreateMultipartUpload]: n=2: min=43520 p10=43775 p50=43775 avg=45184.00 p90=46847 p99=46847 p99.9=46847 max=46847
2025-12-04T09:25:31.723423Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_first_byte_latency(μs)[s3_request=HeadObject]: n=8: min=9408 p10=9471 p50=14463 avg=23812.00 p90=45055 p99=45055 p99.9=45055 max=45055
2025-12-04T09:25:31.723425Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_first_byte_latency(μs)[s3_request=ListObjectsV2]: n=9: min=13376 p10=13439 p50=42239 avg=40280.89 p90=66559 p99=66559 p99.9=66559 max=66559
2025-12-04T09:25:31.723427Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_first_byte_latency(μs)[s3_request=UploadPart]: n=2: min=35072 p10=35327 p50=35327 avg=35712.00 p90=36351 p99=36351 p99.9=36351 max=36351
2025-12-04T09:25:31.723428Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_total_latency(μs)[s3_request=CompleteMultipartUpload]: n=2: min=93184 p10=93695 p50=93695 avg=227456.00 p90=362495 p99=362495 p99.9=362495 max=362495
2025-12-04T09:25:31.723430Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_total_latency(μs)[s3_request=CreateMultipartUpload]: n=2: min=44800 p10=45055 p50=45055 avg=46336.00 p90=47871 p99=47871 p99.9=47871 max=47871
2025-12-04T09:25:31.723431Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_total_latency(μs)[s3_request=HeadObject]: n=9: min=9792 p10=9855 p50=15039 avg=25248.00 p90=48639 p99=48639 p99.9=48639 max=48639
2025-12-04T09:25:31.723433Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_total_latency(μs)[s3_request=ListObjectsV2]: n=9: min=14464 p10=14527 p50=48383 avg=45905.78 p90=72703 p99=72703 p99.9=72703 max=72703
2025-12-04T09:25:31.723435Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: s3.request_total_latency(μs)[s3_request=UploadPart]: n=2: min=35328 p10=35583 p50=35583 avg=35968.00 p90=36607 p99=36607 p99.9=36607 max=36607
2025-12-04T09:25:31.723436Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: system.available_memory: 12606910464
2025-12-04T09:25:35.014743Z DEBUG ThreadId(16) fuser::request: FUSE(2922) ino 0x0000000000000001 STATFS
2025-12-04T09:25:36.723747Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.idle_threads: n=2: min=3 p10=3 p50=3 avg=3.50 p90=4 p99=4 p99.9=4 max=4
2025-12-04T09:25:36.723764Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_latency(μs)[fuse_request=statfs]: n=1: min=14 p10=14 p50=14 avg=14.00 p90=14 p99=14 p99.9=14 max=14
2025-12-04T09:25:40.566960Z DEBUG ThreadId(10) fuser::request: FUSE(2924) ino 0x0000000000000001 STATFS
2025-12-04T09:25:41.724053Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.idle_threads: n=2: min=3 p10=3 p50=3 avg=3.50 p90=4 p99=4 p99.9=4 max=4
2025-12-04T09:25:41.724068Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_latency(μs)[fuse_request=statfs]: n=1: min=14 p10=14 p50=14 avg=14.00 p90=14 p99=14 p99.9=14 max=14
2025-12-04T09:25:50.016173Z DEBUG ThreadId(08) fuser::request: FUSE(2926) ino 0x0000000000000001 STATFS
2025-12-04T09:25:51.724695Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.idle_threads: n=2: min=3 p10=3 p50=3 avg=3.50 p90=4 p99=4 p99.9=4 max=4
2025-12-04T09:25:51.724711Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_latency(μs)[fuse_request=statfs]: n=1: min=15 p10=15 p50=15 avg=15.00 p90=15 p99=15 p99.9=15 max=15
2025-12-04T09:25:55.568553Z DEBUG ThreadId(15) fuser::request: FUSE(2928) ino 0x0000000000000001 STATFS
2025-12-04T09:25:56.725014Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.idle_threads: n=2: min=3 p10=3 p50=3 avg=3.50 p90=4 p99=4 p99.9=4 max=4
2025-12-04T09:25:56.725031Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: fuse.request_latency(μs)[fuse_request=statfs]: n=1: min=16 p10=16 p50=16 avg=16.00 p90=16 p99=16 p99.9=16 max=16
2025-12-04T09:25:56.725033Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: process.memory_usage(B): 21340160
2025-12-04T09:25:56.725034Z  INFO ThreadId(03) mountpoint_s3_fs::metrics: system.available_memory: 12591779840
2025-12-04T09:26:05.015106Z DEBUG ThreadId(16) fuser::request: FUSE(2930) ino 0x0000000000000001 STATFS

Dec 04 '25 15:12 elcaos