Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Mountpoint operations hang indefinitely #706

Closed
SamStudio8 opened this issue Jan 19, 2024 · 12 comments
Closed

Mountpoint operations hang indefinitely #706

SamStudio8 opened this issue Jan 19, 2024 · 12 comments
Labels
bug Something isn't working

Comments

@SamStudio8
Copy link

Mountpoint for Amazon S3 version

mount-s3 1.3.2

AWS Region

eu-west-1

Describe the running environment

Mountpoint installed to EC2 instances and a single client is started to share a bucket mount with ECS tasks.

2024-01-18T19:19:04.080064Z DEBUG mountpoint_s3_client::instance_info: got instance info from IMDS identity_document=IdentityDocument { instance_type: "m5.12xlarge", region: "eu-west-1" }
2024-01-18T19:19:04.080323Z  INFO mount_s3: target network throughput 12 Gbps
2024-01-18T19:19:04.080338Z DEBUG mount_s3: using instance region eu-west-1

Mountpoint options

mount-s3 --debug -l /home/ec2-user/mnt-log --allow-other --uid 1000 --gid 1000 --part-size 33554432 --cache /home/ec2-user/mnt-cache --metadata-ttl 15 <bucket> /home/ec2-user/mnt

What happened?

Occasionally, mount-s3 enters what appears to be a deadlock and will hang indefinitely. Any process attempting to access the mount will be stuck in an uninterruptible sleep. I don't have a lot to go on but attach the relevant logs in the hope that somebody who knows the internals of mount-s3 might be able to see what might be going on. I've no idea if useful but I've also backtraced the main client-s3 thread and one of the workers.

As our ECS tasks are stuck I can access the machine to read logs and run commands. The instance is otherwise usable: EBS volume is responsive and the mount-s3 client continues to log (the same lines repeatedly). I do not have a repro but I am happy to collect additional data with any further debugging suggestions, as I am able to unreliably reproduce the issue.

Relevant log output

## Tail of mountpoint-s3 log
2024-01-18T19:19:04.076711Z  INFO mount_s3: mount-s3 1.3.2
[...]
2024-01-18T19:35:28.265228Z DEBUG fuser::request: FUSE(721680) ino 0x0000000000000941 WRITE fh FileHandle(26906), offset 16384, size 4096, write flags 0x0
2024-01-18T19:35:28.265244Z DEBUG fuser::request: FUSE(721681) ino 0x0000000000000925 WRITE fh FileHandle(26881), offset 184320, size 4096, write flags 0x0
2024-01-18T19:35:28.265259Z DEBUG fuser::request: FUSE(721682) ino 0x0000000000000923 WRITE fh FileHandle(26879), offset 188416, size 4096, write flags 0x0
2024-01-18T19:35:28.265275Z DEBUG fuser::request: FUSE(721683) ino 0x0000000000000930 WRITE fh FileHandle(26889), offset 122880, size 4096, write flags 0x0
2024-01-18T19:35:28.265301Z DEBUG fuser::request: FUSE(721684) ino 0x0000000000000939 WRITE fh FileHandle(26898), offset 61440, size 4096, write flags 0x0
2024-01-18T19:35:28.265318Z DEBUG fuser::request: FUSE(721685) ino 0x0000000000000944 IOCTL fh FileHandle(26909), cmd 21505, data size 0, flags 0x0
2024-01-18T19:35:28.265324Z  WARN ioctl{req=721685 ino=2372 fh=26909 cmd=21505}: mountpoint_s3::fuse: ioctl failed: operation not supported by Mountpoint
2024-01-18T19:35:28.265354Z DEBUG fuser::request: FUSE(721686) ino 0x00000000000008f3 LOOKUP name "<name>"
2024-01-18T19:35:28.265743Z DEBUG open{req=719433 ino=2334 pid=26137 name="<name>" }:put_object{id=19985 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client: CRT request finished request_type=UploadPart crt_error=None http_status=200 range=None duration=61.379263ms ttfb=Some(60.479686ms) request_id=F3420JWE17M3G2TV
2024-01-18T19:35:28.265818Z DEBUG lookup{req=721664 ino=2338 name="<name>" }:list_objects{id=20389 bucket="<bucket>" continued=false delimiter="/" max_keys="1" prefix="<prefix>" }: mountpoint_s3_client::s3_crt_client::list_objects: new request
2024-01-18T19:35:28.266141Z DEBUG lookup{req=721674 ino=2267 name="<name>" }:head_object{id=20390 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client::head_object: new request
2024-01-18T19:35:28.266757Z DEBUG open{req=719210 ino=2333 pid=26117 name="<name>" }:put_object{id=19950 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client: CRT request finished request_type=CompleteMultipartUpload crt_error=None http_status=200 range=None duration=68.952613ms ttfb=Some(35.221913ms) request_id=F341MAXP3S6DVS
C5
2024-01-18T19:35:28.266804Z DEBUG open{req=719210 ino=2333 pid=26117 name="<name>" }:put_object{id=19950 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client: meta request finished duration=652.416645ms
2024-01-18T19:35:28.266833Z DEBUG flush{req=721025 ino=2333 fh=26875 pid=26117 name="<name>" }: mountpoint_s3::fs: put succeeded key="<key>"  size=214453
2024-01-18T19:35:28.266868Z DEBUG fuser::request: FUSE(721687) ino 0x000000000000093a WRITE fh FileHandle(26899), offset 53248, size 4096, write flags 0x0
2024-01-18T19:35:28.266900Z DEBUG fuser::request: FUSE(721688) ino 0x0000000000000924 WRITE fh FileHandle(26880), offset 176128, size 4096, write flags 0x0
2024-01-18T19:35:28.266924Z DEBUG fuser::request: FUSE(721689) ino 0x000000000000093d WRITE fh FileHandle(26902), offset 36864, size 4096, write flags 0x0
2024-01-18T19:35:28.266941Z DEBUG fuser::request: FUSE(721690) ino 0x0000000000000933 WRITE fh FileHandle(26892), offset 114688, size 4096, write flags 0x0
2024-01-18T19:35:28.266963Z DEBUG fuser::request: FUSE(721691) ino 0x0000000000000891 READ fh FileHandle(26784), offset 18379419648, size 131072
2024-01-18T19:35:28.267291Z DEBUG mknod{req=721632 parent=2265 name="<name>" }:head_object{id=20378 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client: CRT request failed request_type=Default 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=8.929413ms ttfb=Some(6.646909ms) request_id=F340R3B69WDJTEF2
2024-01-18T19:35:28.267335Z DEBUG fuser::request: FUSE(721692) ino 0x000000000000093b WRITE fh FileHandle(26900), offset 57344, size 4096, write flags 0x0
2024-01-18T19:35:28.267354Z DEBUG mknod{req=721632 parent=2265 name="<name>" }:head_object{id=20378 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client: meta request failed duration=9.076201ms error=ServiceError(NotFound)
2024-01-18T19:35:28.267360Z DEBUG fuser::request: FUSE(721693) ino 0x000000000000092d WRITE fh FileHandle(26887), offset 143360, size 4096, write flags 0x0
2024-01-18T19:35:28.267361Z DEBUG mknod{req=721632 parent=2265 name="<name>" }:head_object{id=20378 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client: failed 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: 0x7f58780dcef0 }), error_response_body: None }
2024-01-18T19:35:28.267377Z DEBUG fuser::request: FUSE(721694) ino 0x0000000000000891 READ fh FileHandle(26784), offset 18379550720, size 131072
2024-01-18T19:35:28.267531Z DEBUG fuser::request: FUSE(721695) ino 0x0000000000000936 WRITE fh FileHandle(26895), offset 102400, size 4096, write flags 0x0
2024-01-18T19:35:28.267553Z DEBUG fuser::request: FUSE(721696) ino 0x00000000000008ea MKNOD name "<name>", mode 0o100644, rdev 0
2024-01-18T19:35:28.267734Z DEBUG lookup{req=721686 ino=2291 name="<name>" }:head_object{id=20391 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client::head_object: new request
2024-01-18T19:35:28.268354Z DEBUG lookup{req=721674 ino=2267 name="<name>" }:list_objects{id=20392 bucket="<bucket>" continued=false delimiter="/" max_keys="1" prefix="<prefix>" }: mountpoint_s3_client::s3_crt_client::list_objects: new request
2024-01-18T19:35:28.269634Z DEBUG open{req=721553 ino=2371 pid=26233 name="<name>" }:put_object{id=20363 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client: CRT request finished request_type=CreateMultipartUpload crt_error=None http_status=200 range=None duration=21.425882ms ttfb=Some(20.458712ms) request_id=F34C6MRFAQWDAG2R
2024-01-18T19:35:28.269715Z DEBUG fuser::request: FUSE(721697) ino 0x0000000000000937 WRITE fh FileHandle(26896), offset 81920, size 4096, write flags 0x0
2024-01-18T19:35:28.269750Z DEBUG fuser::request: FUSE(721698) ino 0x000000000000093c WRITE fh FileHandle(26901), offset 49152, size 4096, write flags 0x0
2024-01-18T19:35:28.269762Z DEBUG mknod{req=721696 parent=2282 name="<name>" }:head_object{id=20393 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client::head_object: new request
2024-01-18T19:35:28.269769Z DEBUG fuser::request: FUSE(721699) ino 0x0000000000000920 WRITE fh FileHandle(26878), offset 225280, size 4096, write flags 0x0
2024-01-18T19:35:28.269796Z DEBUG fuser::request: FUSE(721700) ino 0x000000000000092e WRITE fh FileHandle(26888), offset 143360, size 4096, write flags 0x0
2024-01-18T19:35:28.269814Z DEBUG fuser::request: FUSE(721701) ino 0x0000000000000891 READ fh FileHandle(26783), offset 71941730304, size 131072
2024-01-18T19:35:28.270537Z DEBUG fuser::request: FUSE(721702) ino 0x000000000000092b WRITE fh FileHandle(26885), offset 147456, size 4096, write flags 0x0
2024-01-18T19:35:28.270564Z DEBUG fuser::request: FUSE(721703) ino 0x0000000000000931 WRITE fh FileHandle(26890), offset 122880, size 4096, write flags 0x0
2024-01-18T19:35:28.270581Z DEBUG fuser::request: FUSE(721704) ino 0x0000000000000946 OPEN flags 0x8001
2024-01-18T19:35:28.270595Z DEBUG open{req=721704 ino=2374 pid=26291 name="<name>" }:put_object{id=20394 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client::put_object: new request
2024-01-18T19:35:28.270649Z DEBUG lookup{req=721584 ino=2135 name="<name>" }:list_objects{id=20374 bucket="<bucket>" continued=false delimiter="/" max_keys="1" prefix="<prefix>" }: mountpoint_s3_client::s3_crt_client: CRT request finished request_type=Default crt_error=None http_status=200 range=None duration=16.281271ms ttfb=Some(14.9163ms) request_id
=F34550ZZ65YEMC4D
2024-01-18T19:35:28.271161Z DEBUG lookup{req=721686 ino=2291 name="<name>" }:list_objects{id=20395 bucket="<bucket>" continued=false delimiter="/" max_keys="1" prefix="<prefix>" }: mountpoint_s3_client::s3_crt_client::list_objects: new request
2024-01-18T19:35:28.271158Z DEBUG lookup{req=721655 ino=2290 name="<name>" }:head_object{id=20386 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client: CRT request failed request_type=Default crt_error=Some(Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request")) http_status=404 r
ange=None duration=8.375727ms ttfb=Some(6.560267ms) request_id=F34BREKN66C7AYG7
2024-01-18T19:35:28.271962Z DEBUG mknod{req=721696 parent=2282 name="<name>" }:list_objects{id=20396 bucket="<bucket>" continued=false delimiter="/" max_keys="1" prefix="<prefix>" }: mountpoint_s3_client::s3_crt_client::list_objects: new request
2024-01-18T19:35:28.272634Z DEBUG open{req=721704 ino=2374 pid=26291 name="<name>" }: mountpoint_s3::fs: new file handle created fh=26911 ino=2374
2024-01-18T19:35:28.272659Z DEBUG fuser::request: FUSE(721705) ino 0x000000000000092f GETATTR
2024-01-18T19:35:28.272683Z DEBUG fuser::request: FUSE(721706) ino 0x0000000000000942 WRITE fh FileHandle(26907), offset 16384, size 4096, write flags 0x0
2024-01-18T19:35:28.272704Z DEBUG fuser::request: FUSE(721707) ino 0x0000000000000891 READ fh FileHandle(26783), offset 71941861376, size 131072
2024-01-18T19:35:28.272868Z DEBUG fuser::request: FUSE(721708) ino 0x000000000000093f WRITE fh FileHandle(26904), offset 20480, size 4096, write flags 0x0
2024-01-18T19:35:28.272893Z DEBUG fuser::request: FUSE(721709) ino 0x0000000000000935 WRITE fh FileHandle(26894), offset 110592, size 4096, write flags 0x0
2024-01-18T19:35:28.272910Z DEBUG fuser::request: FUSE(721710) ino 0x0000000000000891 READ fh FileHandle(26781), offset 119753666560, size 131072
2024-01-18T19:35:28.273410Z DEBUG lookup{req=721590 ino=2294 name="<name>" }:list_objects{id=20376 bucket="<bucket>" continued=false delimiter="/" max_keys="1" prefix="<prefix>" }: mountpoint_s3_client::s3_crt_client: CRT request finished request_type=Default crt_error=None http_status=200 range=None duration=16.953093ms ttfb=Some(12.693253ms)
request_id=F347593YS67TF0AD
2024-01-18T19:35:28.275100Z DEBUG fuser::request: FUSE(721711) ino 0x0000000000000938 WRITE fh FileHandle(26897), offset 81920, size 4096, write flags 0x0
2024-01-18T19:35:28.275133Z DEBUG fuser::request: FUSE(721712) ino 0x0000000000000928 WRITE fh FileHandle(26883), offset 167936, size 4096, write flags 0x0
2024-01-18T19:35:28.275151Z DEBUG fuser::request: FUSE(721713) ino 0x0000000000000891 READ fh FileHandle(26781), offset 119753797632, size 131072
2024-01-18T19:35:28.275184Z DEBUG mknod{req=721644 parent=2345 name="<name>" }:list_objects{id=20384 bucket="<bucket>" continued=false delimiter="/" max_keys="1" prefix="<prefix>" }: mountpoint_s3_client::s3_crt_client: CRT request finished request_type=Default crt_error=None http_status=200 range=None duration=13.65011ms ttfb=Some(11.708416ms)
 request_id=F34D1FJMVAWGEV7S
2024-01-18T19:35:28.275268Z DEBUG mknod{req=721632 parent=2265 name="<name>" }:list_objects{id=20382 bucket="<bucket>" continued=false delimiter="/" max_keys="1" prefix="<prefix>" }: mountpoint_s3_client::s3_crt_client: CRT request finished request_type=Default crt_error=None http_status=200 range=None duration=14.770739ms ttfb=Some(12.082877
ms) request_id=F340RPCNG7MFS8CQ
2024-01-18T19:35:28.275323Z DEBUG fuser::request: FUSE(721714) ino 0x000000000000093e WRITE fh FileHandle(26903), offset 24576, size 4096, write flags 0x0
2024-01-18T19:35:28.275348Z DEBUG fuser::request: FUSE(721715) ino 0x0000000000000945 IOCTL fh FileHandle(26910), cmd 21505, data size 0, flags 0x0
2024-01-18T19:35:28.275355Z  WARN ioctl{req=721715 ino=2373 fh=26910 cmd=21505}: mountpoint_s3::fuse: ioctl failed: operation not supported by Mountpoint
2024-01-18T19:35:28.275368Z DEBUG fuser::request: FUSE(721716) ino 0x0000000000000947 OPEN flags 0x8001
2024-01-18T19:35:28.275360Z DEBUG lookup{req=721664 ino=2338 name="<name>" }:head_object{id=20387 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client: CRT request failed request_type=Default crt_error=Some(Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request")) http_status=404 ran
ge=None duration=11.763297ms ttfb=Some(9.5269ms) request_id=F342VPX8X8C4TJYG
2024-01-18T19:35:28.275381Z DEBUG open{req=721716 ino=2375 pid=26338 name="<name>" }:put_object{id=20397 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client::put_object: new request
2024-01-18T19:35:28.275664Z DEBUG lookup{req=721597 ino=2337 name="<name>" }:head_object{id=20377 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client: CRT request failed request_type=Default crt_error=Some(Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request")) http_status=404 ran
ge=None duration=18.699695ms ttfb=Some(15.775978ms) request_id=F348V1RVXQRP61ZG
2024-01-18T19:35:28.276753Z DEBUG lookup{req=721597 ino=2337 name="<name>" }:list_objects{id=20380 bucket="<bucket>" continued=false delimiter="/" max_keys="1" prefix="<prefix>" }: mountpoint_s3_client::s3_crt_client: CRT request finished request_type=Default crt_error=None http_status=200 range=None duration=17.598859ms ttfb=Some(15.200644ms)
request_id=F34AWBQCMY53FNGY
2024-01-18T19:35:28.277365Z DEBUG open{req=721716 ino=2375 pid=26338 name="<name>" }: mountpoint_s3::fs: new file handle created fh=26912 ino=2375
2024-01-18T19:35:28.277392Z DEBUG fuser::request: FUSE(721717) ino 0x000000000000092c WRITE fh FileHandle(26886), offset 147456, size 4096, write flags 0x0
2024-01-18T19:35:28.277418Z DEBUG fuser::request: FUSE(721718) ino 0x0000000000000934 WRITE fh FileHandle(26893), offset 110592, size 4096, write flags 0x0
2024-01-18T19:35:28.277436Z DEBUG fuser::request: FUSE(721719) ino 0x000000000000092a WRITE fh FileHandle(26884), offset 155648, size 4096, write flags 0x0
2024-01-18T19:35:28.277478Z DEBUG fuser::request: FUSE(721720) ino 0x0000000000000926 WRITE fh FileHandle(26882), offset 172032, size 4096, write flags 0x0
2024-01-18T19:35:28.277499Z DEBUG fuser::request: FUSE(721721) ino 0x0000000000000940 WRITE fh FileHandle(26905), offset 16384, size 4096, write flags 0x0
2024-01-18T19:35:28.277523Z DEBUG fuser::request: FUSE(721722) ino 0x0000000000000941 WRITE fh FileHandle(26906), offset 20480, size 4096, write flags 0x0
2024-01-18T19:35:28.277539Z DEBUG fuser::request: FUSE(721723) ino 0x0000000000000925 WRITE fh FileHandle(26881), offset 188416, size 4096, write flags 0x0
2024-01-18T19:35:28.277557Z DEBUG fuser::request: FUSE(721724) ino 0x0000000000000923 WRITE fh FileHandle(26879), offset 192512, size 4096, write flags 0x0
2024-01-18T19:35:28.277573Z DEBUG fuser::request: FUSE(721725) ino 0x0000000000000939 WRITE fh FileHandle(26898), offset 65536, size 4096, write flags 0x0
2024-01-18T19:35:28.277590Z DEBUG fuser::request: FUSE(721726) ino 0x0000000000000930 WRITE fh FileHandle(26889), offset 126976, size 4096, write flags 0x0
2024-01-18T19:35:28.277605Z DEBUG fuser::request: FUSE(721727) ino 0x0000000000000944 WRITE fh FileHandle(26909), offset 0, size 4096, write flags 0x0
2024-01-18T19:35:28.278162Z DEBUG lookup{req=721686 ino=2291 name="<name>" }:head_object{id=20391 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client: CRT request failed request_type=Default crt_error=Some(Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request")) http_status=404 r
ange=None duration=10.318992ms ttfb=Some(8.439632ms) request_id=F34A07W22J6S0EA7
2024-01-18T19:35:28.281312Z DEBUG lookup{req=721655 ino=2290 name="<name>" }:list_objects{id=20388 bucket="<bucket>" continued=false delimiter="/" max_keys="1" prefix="<prefix>" }: mountpoint_s3_client::s3_crt_client: CRT request finished request_type=Default crt_error=None http_status=200 range=None duration=16.31502ms ttfb=Some(13.419538ms)
 request_id=F344NA2JBTA03CW2
2024-01-18T19:35:28.281590Z DEBUG open{req=719204 ino=2332 pid=26135 name="<name>" }:put_object{id=19946 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client: CRT request finished request_type=CompleteMultipartUpload crt_error=None http_status=200 range=None duration=77.493614ms ttfb=Some(44.229555ms) request_id=F34E7Y99PXAC7J
6Z
2024-01-18T19:35:28.281867Z DEBUG lookup{req=721559 ino=2343 name="<name>" }:list_objects{id=20371 bucket="<bucket>" continued=false delimiter="/" max_keys="1" prefix="<prefix>" }: mountpoint_s3_client::s3_crt_client: CRT request finished request_type=Default crt_error=None http_status=200 range=None duration=28.716197ms ttfb=Some(27.774847ms)
request_id=F340XZTEFVB2YC1J
2024-01-18T19:35:28.283492Z DEBUG lookup{req=721629 ino=2285 name="<name>" }:head_object{id=20379 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client: CRT request failed request_type=Default crt_error=Some(Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request")) http_status=404 ran
ge=None duration=24.96529ms ttfb=Some(22.580245ms) request_id=F3459YX4H6SNZ3HF
2024-01-18T19:35:28.286166Z DEBUG mknod{req=721644 parent=2345 name="<name>" }:head_object{id=20381 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client: CRT request failed request_type=Default crt_error=Some(Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request")) http_status=404 r
ange=None duration=26.778536ms ttfb=Some(24.876791ms) request_id=F341H73XA98AWMY9
2024-01-18T19:35:28.287840Z DEBUG lookup{req=721674 ino=2267 name="<name>" }:head_object{id=20390 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client: CRT request failed request_type=Default crt_error=Some(Error(14343, "aws-c-s3: AWS_ERROR_S3_INVALID_RESPONSE_STATUS, Invalid response status from request")) http_status=404 ran
ge=None duration=20.948545ms ttfb=Some(18.647582ms) request_id=F346301GES0WDNNB
2024-01-18T19:35:28.288675Z DEBUG lookup{req=721674 ino=2267 name="<name>" }:list_objects{id=20392 bucket="<bucket>" continued=false delimiter="/" max_keys="1" prefix="<prefix>" }: mountpoint_s3_client::s3_crt_client: CRT request finished request_type=Default crt_error=None http_status=200 range=None duration=20.24768ms ttfb=Some(17.287806ms) r
equest_id=F34DJWJ50YHEYMNH
2024-01-18T19:35:28.291032Z DEBUG open{req=721623 ino=2372 pid=26212 name="<name>" }:put_object{id=20375 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client: CRT request finished request_type=CreateMultipartUpload crt_error=None http_status=200 range=None duration=33.086008ms ttfb=Some(29.772593ms) request_id=F34D34SAB1SPYCPY
2024-01-18T19:35:28.293995Z DEBUG lookup{req=721629 ino=2285 name="<name>" }:list_objects{id=20383 bucket="<bucket>" continued=false delimiter="/" max_keys="1" prefix="<prefix>" }: mountpoint_s3_client::s3_crt_client: CRT request finished request_type=Default crt_error=None http_status=200 range=None duration=32.658243ms ttfb=Some(30.605397ms) request_id=F34512VVSFJWKGNY
2024-01-18T19:35:28.295719Z DEBUG open{req=721673 ino=2373 pid=26335 name="<name>" }:put_object{id=20385 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client: CRT request finished request_type=CreateMultipartUpload crt_error=None http_status=200 range=None duration=31.52631ms ttfb=Some(28.519792ms) request_id=F349R9GEP7NTWTYR
2024-01-18T19:35:28.296161Z DEBUG lookup{req=721664 ino=2338 name="<name>" }:list_objects{id=20389 bucket="<bucket>" continued=false delimiter="/" max_keys="1" prefix="<prefix>" }: mountpoint_s3_client::s3_crt_client: CRT request finished request_type=Default crt_error=None http_status=200 range=None duration=29.958345ms ttfb=Some(27.096718ms) request_id=F34EYNZM3QF3SH4W
2024-01-18T19:35:28.308727Z DEBUG open{req=719448 ino=2335 pid=26085 name="<name>" }:put_object{id=19986 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client: CRT request finished request_type=UploadPart crt_error=None http_status=200 range=None duration=72.812413ms ttfb=Some(70.492493ms) request_id=F34BWTXY90J48YKV
2024-01-18T19:35:28.363808Z DEBUG open{req=719433 ino=2334 pid=26137 name="<name>" }:put_object{id=19985 bucket="<bucket>" key="<key>" }: mountpoint_s3_client::s3_crt_client: CRT request finished request_type=CompleteMultipartUpload crt_error=None http_status=200 range=None duration=97.706598ms ttfb=Some(61.986059ms) request_id=F342K3DF369BJQ5X
2024-01-18T19:35:29.388442Z  INFO mountpoint_s3::metrics: disk_data_cache.block_hit: 1
2024-01-18T19:35:29.388463Z  INFO mountpoint_s3::metrics: disk_data_cache.eviction_duration_us: n=4180: min=4 p10=4 p50=5 avg=6.26 p90=8 p99=30 p99.9=70 max=98
2024-01-18T19:35:29.388465Z  INFO mountpoint_s3::metrics: disk_data_cache.read_duration_us: n=1: min=278 p10=279 p50=279 avg=279.00 p90=279 p99=279 p99.9=279 max=279
2024-01-18T19:35:29.388467Z  INFO mountpoint_s3::metrics: disk_data_cache.total_bytes[type=read]: 487655
2024-01-18T19:35:29.388469Z  INFO mountpoint_s3::metrics: disk_data_cache.total_bytes[type=write]: 4385144832 (n=4182)
2024-01-18T19:35:29.388471Z  INFO mountpoint_s3::metrics: disk_data_cache.write_duration_us: n=4182: min=366 p10=441 p50=509 avg=550.80 p90=719 p99=983 p99.9=1215 max=2543
2024-01-18T19:35:29.388474Z  INFO mountpoint_s3::metrics: fs.current_handles[type=read]: 15
2024-01-18T19:35:29.388475Z  INFO mountpoint_s3::metrics: fs.current_handles[type=write]: 38
2024-01-18T19:35:29.388477Z  INFO mountpoint_s3::metrics: fuse.io_size[type=read]: n=10306: min=94208 p10=132095 p50=132095 avg=131580.40 p90=132095 p99=132095 p99.9=132095 max=132095
2024-01-18T19:35:29.388479Z  INFO mountpoint_s3::metrics: fuse.io_size[type=write]: n=2936: min=126 p10=4127 p50=4127 avg=4038.34 p90=4127 p99=4127 p99.9=4127 max=4127
2024-01-18T19:35:29.388481Z  INFO mountpoint_s3::metrics: fuse.op_failures[op=ioctl]: 118 (n=118)
2024-01-18T19:35:29.388482Z  INFO mountpoint_s3::metrics: fuse.op_failures[op=lookup]: 475 (n=475)
2024-01-18T19:35:29.388484Z  INFO mountpoint_s3::metrics: fuse.op_latency_us[op=flush]: n=155: min=6 p10=9 p50=17 avg=74431.81 p90=171007 p99=532479 p99.9=724991 max=724991
2024-01-18T19:35:29.388486Z  INFO mountpoint_s3::metrics: fuse.op_latency_us[op=getattr]: n=244: min=6 p10=7 p50=12 avg=26370.76 p90=44 p99=704511 p99.9=1499135 max=1499135
2024-01-18T19:35:29.388488Z  INFO mountpoint_s3::metrics: fuse.op_latency_us[op=ioctl]: n=118: min=7 p10=10 p50=12 avg=14.35 p90=21 p99=32 p99.9=59 max=59
2024-01-18T19:35:29.388490Z  INFO mountpoint_s3::metrics: fuse.op_latency_us[op=lookup]: n=498: min=14976 p10=18559 p50=30975 avg=66094.39 p90=135167 p99=1040383 p99.9=1392639 max=1392639
2024-01-18T19:35:29.388491Z  INFO mountpoint_s3::metrics: fuse.op_latency_us[op=mkdir]: n=17: min=14592 p10=19199 p50=28799 avg=33786.35 p90=60415 p99=91647 p99.9=91647 max=91647
2024-01-18T19:35:29.388493Z  INFO mountpoint_s3::metrics: fuse.op_latency_us[op=mknod]: n=120: min=14720 p10=17535 p50=28671 avg=49970.93 p90=90111 p99=350207 p99.9=454655 max=454655
2024-01-18T19:35:29.388495Z  INFO mountpoint_s3::metrics: fuse.op_latency_us[op=open]: n=84: min=134144 p10=151551 p50=311295 avg=391582.48 p90=655359 p99=1048575 p99.9=1048575 max=1048575
2024-01-18T19:35:29.388497Z  INFO mountpoint_s3::metrics: fuse.op_latency_us[op=read]: n=10279: min=86 p10=113 p50=153 avg=1334.73 p90=359 p99=679 p99.9=3311 max=4030463
2024-01-18T19:35:29.388499Z  INFO mountpoint_s3::metrics: fuse.op_latency_us[op=release]: n=109: min=6 p10=9 p50=14 avg=33691.61 p90=167935 p99=362495 p99.9=610303 max=610303
2024-01-18T19:35:29.388501Z  INFO mountpoint_s3::metrics: fuse.op_latency_us[op=write]: n=2936: min=7 p10=8 p50=11 avg=1089.52 p90=19 p99=22015 p99.9=250879 max=493567
2024-01-18T19:35:29.388502Z  INFO mountpoint_s3::metrics: fuse.op_unimplemented[op=ioctl]: 118 (n=118)
2024-01-18T19:35:29.388504Z  INFO mountpoint_s3::metrics: fuse.total_bytes[type=read]: 1351053543 (n=10308)
2024-01-18T19:35:29.388506Z  INFO mountpoint_s3::metrics: fuse.total_bytes[type=write]: 11810556 (n=2936)
2024-01-18T19:35:29.388508Z  INFO mountpoint_s3::metrics: metadata_cache.cache_hit: 0 (n=642)
2024-01-18T19:35:29.388509Z  INFO mountpoint_s3::metrics: prefetch.blocks_served_from_cache: 1
2024-01-18T19:35:29.388511Z  INFO mountpoint_s3::metrics: prefetch.cache_update_duration_us: n=4183: min=376 p10=451 p50=523 avg=570.26 p90=739 p99=1015 p99.9=1447 max=19711
2024-01-18T19:35:29.388521Z  INFO mountpoint_s3::metrics: prefetch.contiguous_read_len: n=27: min=334 p10=335 p50=14207 avg=9477170.33 p90=6586367 p99=128974847 p99.9=128974847 max=128974847
2024-01-18T19:35:29.388523Z  INFO mountpoint_s3::metrics: prefetch.out_of_order: 1
2024-01-18T19:35:29.388524Z  INFO mountpoint_s3::metrics: prefetch.part_queue_starved_us: n=1: min=400 p10=401 p50=401 avg=401.00 p90=401 p99=401 p99.9=401 max=401
2024-01-18T19:35:29.388526Z  INFO mountpoint_s3::metrics: s3.client.num_auto_default_network_io: 9
2024-01-18T19:35:29.388528Z  INFO mountpoint_s3::metrics: s3.client.num_auto_ranged_copy_network_io: 0
2024-01-18T19:35:29.388530Z  INFO mountpoint_s3::metrics: s3.client.num_auto_ranged_get_network_io: 0
2024-01-18T19:35:29.388531Z  INFO mountpoint_s3::metrics: s3.client.num_auto_ranged_put_network_io: 5
2024-01-18T19:35:29.388533Z  INFO mountpoint_s3::metrics: s3.client.num_requests_being_prepared: 30
2024-01-18T19:35:29.388535Z  INFO mountpoint_s3::metrics: s3.client.num_requests_being_processed: 44
2024-01-18T19:35:29.388537Z  INFO mountpoint_s3::metrics: s3.client.num_requests_stream_queued_waiting: 0
2024-01-18T19:35:29.388539Z  INFO mountpoint_s3::metrics: s3.client.num_requests_streaming_response: 0
2024-01-18T19:35:29.388540Z  INFO mountpoint_s3::metrics: s3.client.num_total_network_io: 14
2024-01-18T19:35:29.388542Z  INFO mountpoint_s3::metrics: s3.client.request_queue_size: 0
2024-01-18T19:35:29.388544Z  INFO mountpoint_s3::metrics: s3.meta_requests.failures[op=head_object,status=404]: 637 (n=637)
2024-01-18T19:35:29.388546Z  INFO mountpoint_s3::metrics: s3.meta_requests.first_byte_latency_us[op=head_object]: n=659: min=5824 p10=8447 p50=16767 avg=43905.41 p90=107519 p99=364543 p99.9=1343487 max=1343487
2024-01-18T19:35:29.388547Z  INFO mountpoint_s3::metrics: s3.meta_requests.first_byte_latency_us[op=list_objects]: n=666: min=9216 p10=12863 p50=23679 avg=52217.47 p90=114687 p99=610303 p99.9=1499135 max=1499135
2024-01-18T19:35:29.388549Z  INFO mountpoint_s3::metrics: s3.meta_requests.first_byte_latency_us[op=put_object]: n=84: min=131072 p10=149503 p50=309247 avg=389241.90 p90=655359 p99=1048575 p99.9=1048575 max=1048575
2024-01-18T19:35:29.388551Z  INFO mountpoint_s3::metrics: s3.meta_requests.throughput_mibs[op=get_object,size=>16MiB]: n=3: min=512 p10=515 p50=527 avg=540.67 p90=583 p99=583 p99.9=583 max=583
2024-01-18T19:35:29.388553Z  INFO mountpoint_s3::metrics: s3.meta_requests.throughput_mibs[op=put_object,size=<1MiB]: n=84: min=0 p10=0 p50=0 avg=0.01 p90=0 p99=1 p99.9=1 max=1
2024-01-18T19:35:29.388555Z  INFO mountpoint_s3::metrics: s3.meta_requests.total_latency_us[op=get_object]: n=3: min=3506176 p10=3522559 p50=3915775 avg=3803818.67 p90=3997695 p99=3997695 p99.9=3997695 max=3997695
2024-01-18T19:35:29.388557Z  INFO mountpoint_s3::metrics: s3.meta_requests.total_latency_us[op=head_object]: n=659: min=5824 p10=8447 p50=16767 avg=43905.41 p90=107519 p99=364543 p99.9=1343487 max=1343487
2024-01-18T19:35:29.388559Z  INFO mountpoint_s3::metrics: s3.meta_requests.total_latency_us[op=list_objects]: n=656: min=9280 p10=12863 p50=23935 avg=52811.32 p90=115199 p99=610303 p99.9=1499135 max=1499135
2024-01-18T19:35:29.388560Z  INFO mountpoint_s3::metrics: s3.meta_requests.total_latency_us[op=put_object]: n=84: min=131072 p10=149503 p50=309247 avg=389241.90 p90=655359 p99=1048575 p99.9=1048575 max=1048575
2024-01-18T19:35:29.388562Z  INFO mountpoint_s3::metrics: s3.meta_requests[op=get_object]: 3 (n=3)
2024-01-18T19:35:29.388564Z  INFO mountpoint_s3::metrics: s3.meta_requests[op=head_object]: 659 (n=659)
2024-01-18T19:35:29.388566Z  INFO mountpoint_s3::metrics: s3.meta_requests[op=list_objects]: 656 (n=656)
2024-01-18T19:35:29.388568Z  INFO mountpoint_s3::metrics: s3.meta_requests[op=put_object]: 84 (n=84)
2024-01-18T19:35:29.388569Z  INFO mountpoint_s3::metrics: s3.requests.failures[op=head_object,type=Default,status=404]: 644 (n=644)
2024-01-18T19:35:29.388571Z  INFO mountpoint_s3::metrics: s3.requests.first_byte_latency_us[op=get_object,type=GetObject]: n=123: min=13888 p10=18303 p50=68095 avg=67177.37 p90=118783 p99=182271 p99.9=238591 max=238591
2024-01-18T19:35:29.388575Z  INFO mountpoint_s3::metrics: s3.requests.first_byte_latency_us[op=head_object,type=Default]: n=666: min=0 p10=7359 p50=9791 avg=12848.14 p90=22015 p99=35839 p99.9=187391 max=187391
2024-01-18T19:35:29.388577Z  INFO mountpoint_s3::metrics: s3.requests.first_byte_latency_us[op=list_objects,type=Default]: n=666: min=8032 p10=10623 p50=14079 avg=17410.43 p90=28287 p99=43263 p99.9=243711 max=243711
2024-01-18T19:35:29.388579Z  INFO mountpoint_s3::metrics: s3.requests.first_byte_latency_us[op=put_object,type=CompleteMultipartUpload]: n=86: min=32640 p10=36351 p50=42495 avg=45013.58 p90=57087 p99=76799 p99.9=76799 max=76799
2024-01-18T19:35:29.388581Z  INFO mountpoint_s3::metrics: s3.requests.first_byte_latency_us[op=put_object,type=CreateMultipartUpload]: n=118: min=13696 p10=15359 p50=22783 avg=25602.17 p90=38655 p99=68095 p99.9=76799 max=76799
2024-01-18T19:35:29.388583Z  INFO mountpoint_s3::metrics: s3.requests.first_byte_latency_us[op=put_object,type=UploadPart]: n=87: min=16384 p10=21887 p50=41727 avg=46095.45 p90=75775 p99=154623 p99.9=154623 max=154623
2024-01-18T19:35:29.388584Z  INFO mountpoint_s3::metrics: s3.requests.total_latency_us[op=get_object,type=GetObject]: n=123: min=438272 p10=655359 p50=1269759 avg=1325247.48 p90=1982463 p99=2047999 p99.9=2064383 max=2064383
2024-01-18T19:35:29.388586Z  INFO mountpoint_s3::metrics: s3.requests.total_latency_us[op=head_object,type=Default]: n=666: min=5696 p10=8255 p50=15679 avg=36007.04 p90=96255 p99=299007 p99.9=452607 max=452607
2024-01-18T19:35:29.388588Z  INFO mountpoint_s3::metrics: s3.requests.total_latency_us[op=list_objects,type=Default]: n=666: min=9088 p10=12799 p50=23423 avg=44397.65 p90=103935 p99=313343 p99.9=1032191 max=1032191
2024-01-18T19:35:29.388590Z  INFO mountpoint_s3::metrics: s3.requests.total_latency_us[op=put_object,type=CompleteMultipartUpload]: n=86: min=63488 p10=69119 p50=85503 avg=97096.93 p90=126975 p99=307199 p99.9=307199 max=307199
2024-01-18T19:35:29.388592Z  INFO mountpoint_s3::metrics: s3.requests.total_latency_us[op=put_object,type=CreateMultipartUpload]: n=118: min=14848 p10=17919 p50=29567 avg=41212.75 p90=62719 p99=315391 p99.9=491519 max=491519
2024-01-18T19:35:29.388593Z  INFO mountpoint_s3::metrics: s3.requests.total_latency_us[op=put_object,type=UploadPart]: n=87: min=17920 p10=25599 p50=54527 avg=70742.07 p90=87039 p99=471039 p99.9=471039 max=471039
2024-01-18T19:35:29.388595Z  INFO mountpoint_s3::metrics: s3.requests[op=get_object,type=GetObject]: 123 (n=123)
2024-01-18T19:35:29.388597Z  INFO mountpoint_s3::metrics: s3.requests[op=head_object,type=Default]: 666 (n=666)
2024-01-18T19:35:29.388599Z  INFO mountpoint_s3::metrics: s3.requests[op=list_objects,type=Default]: 666 (n=666)
2024-01-18T19:35:29.388601Z  INFO mountpoint_s3::metrics: s3.requests[op=put_object,type=CompleteMultipartUpload]: 86 (n=86)
2024-01-18T19:35:29.388602Z  INFO mountpoint_s3::metrics: s3.requests[op=put_object,type=CreateMultipartUpload]: 118 (n=118)
2024-01-18T19:35:29.388604Z  INFO mountpoint_s3::metrics: s3.requests[op=put_object,type=UploadPart]: 87 (n=87)
2024-01-18T19:35:34.388839Z  INFO mountpoint_s3::metrics: fs.current_handles[type=read]: 15
2024-01-18T19:35:34.388874Z  INFO mountpoint_s3::metrics: fs.current_handles[type=write]: 38
[...]
2024-01-18T19:35:39.389112Z  INFO mountpoint_s3::metrics: fs.current_handles[type=read]: 15
2024-01-18T19:35:39.389133Z  INFO mountpoint_s3::metrics: fs.current_handles[type=write]: 38
2024-01-18T19:35:44.389373Z  INFO mountpoint_s3::metrics: fs.current_handles[type=read]: 15
2024-01-18T19:35:44.389406Z  INFO mountpoint_s3::metrics: fs.current_handles[type=write]: 38
[...] # message repeats continuously
2024-01-18T22:27:04.946483Z  INFO mountpoint_s3::metrics: fs.current_handles[type=read]: 15
2024-01-18T22:27:04.946529Z  INFO mountpoint_s3::metrics: fs.current_handles[type=write]: 38


## strace
$ sudo strace -p 5964
strace: Process 5964 attached
futex(0x563c09d3d998, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_AN



## Backtrace of main mount-s3 process
(gdb) bt
#0  0x00007f58925152a9 in syscall () from /lib64/libc.so.6
#1  0x0000563c08a13955 in std::sys::unix::futex::futex_wait () at library/std/src/sys/unix/futex.rs:62
#2  std::sys_common::thread_parking::futex::Parker::park () at library/std/src/sys_common/thread_parking/futex.rs:52
#3  std::thread::park () at library/std/src/thread/mod.rs:988
#4  0x0000563c08504d02 in wait_until () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/std/src/sync/mpmc/context.rs:139
#5  {closure#1}<()> () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/std/src/sync/mpmc/list.rs:444
#6  {closure#0}<std::sync::mpmc::list::{impl#3}::recv::{closure_env#1}<()>, ()> () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/std/src/sync/mpmc/context.rs:50
#7  0x0000563c08503d5d in {closure#1}<std::sync::mpmc::list::{impl#3}::recv::{closure_env#1}<mountpoint_s3::fuse::session::Message>, ()> () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/std/src/sync/mpmc/context.rs:58
#8  try_with<core::cell::Cell<core::option::Option<std::sync::mpmc::context::Context>>, std::sync::mpmc::context::{impl#0}::with::{closure_env#1}<std::sync::mpmc::list::{impl#3}::recv::{closure_env#1}<mountpoint_s3::fuse::session::Message>, ()>, ()> () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/std/src/thread/local.rs:270
#9  with<std::sync::mpmc::list::{impl#3}::recv::{closure_env#1}<mountpoint_s3::fuse::session::Message>, ()> () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/std/src/sync/mpmc/context.rs:53
#10 recv<mountpoint_s3::fuse::session::Message> () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/std/src/sync/mpmc/list.rs:434
#11 0x0000563c08512e12 in recv<mountpoint_s3::fuse::session::Message> () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/std/src/sync/mpmc/mod.rs:307
#12 recv<mountpoint_s3::fuse::session::Message> () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/std/src/sync/mpsc/mod.rs:860
#13 join () at mountpoint-s3/src/fuse/session.rs:92
#14 0x0000563c0844f9e2 in main () at mountpoint-s3/src/main.rs:416
#15 0x0000563c08497db3 in call_once<fn() -> core::result::Result<(), anyhow::Error>, ()> () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/core/src/ops/function.rs:250
#16 __rust_begin_short_backtrace<fn() -> core::result::Result<(), anyhow::Error>, core::result::Result<(), anyhow::Error>> () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/std/src/sys_common/backtrace.rs:135
#17 0x0000563c0849946d in {closure#0}<core::result::Result<(), anyhow::Error>> () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/std/src/rt.rs:166
#18 0x0000563c08a133bb in core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once () at library/core/src/ops/function.rs:284
#19 std::panicking::try::do_call () at library/std/src/panicking.rs:500
#20 std::panicking::try () at library/std/src/panicking.rs:464
#21 std::panic::catch_unwind () at library/std/src/panic.rs:142
#22 std::rt::lang_start_internal::{{closure}} () at library/std/src/rt.rs:148
#23 std::panicking::try::do_call () at library/std/src/panicking.rs:500
#24 std::panicking::try () at library/std/src/panicking.rs:464
#25 std::panic::catch_unwind () at library/std/src/panic.rs:142
#26 std::rt::lang_start_internal () at library/std/src/rt.rs:148
#27 0x0000563c08463aec in main () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/alloc/src/boxed.rs:2021



## Backtrace of mount-s3 worker(?) process
(gdb) bt
#0  0x00007f58925152a9 in syscall () from /lib64/libc.so.6
#1  0x0000563c08a13955 in std::sys::unix::futex::futex_wait () at library/std/src/sys/unix/futex.rs:62
#2  std::sys_common::thread_parking::futex::Parker::park () at library/std/src/sys_common/thread_parking/futex.rs:52
#3  std::thread::park () at library/std/src/thread/mod.rs:988
#4  0x0000563c0847b7dc in {closure#0}<core::result::Result<mountpoint_s3::fs::Entry, mountpoint_s3::fs::error::Error>, futures_executor::local_pool::block_on::{closure_env#0}<tracing::instrument::Instrumented<mountpoint_s3::fs::{impl#8}::mknod::{async_fn_env#0}<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>>>> () at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/futures-executor-0.3.29/src/local_pool.rs:99
#5  try_with<alloc::sync::Arc<futures_executor::local_pool::ThreadNotify>, futures_executor::local_pool::run_executor::{closure_env#0}<core::result::Result<mountpoint_s3::fs::Entry, mountpoint_s3::fs::error::Error>, futures_executor::local_pool::block_on::{closure_env#0}<tracing::instrument::Instrumented<mountpoint_s3::fs::{impl#8}::mknod::{async_fn_env#0}<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>>>>, core::result::Result<mountpoint_s3::fs::Entry, mountpoint_s3::fs::error::Error>> () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/std/src/thread/local.rs:270
#6  with<alloc::sync::Arc<futures_executor::local_pool::ThreadNotify>, futures_executor::local_pool::run_executor::{closure_env#0}<core::result::Result<mountpoint_s3::fs::Entry, mountpoint_s3::fs::error::Error>, futures_executor::local_pool::block_on::{closure_env#0}<tracing::instrument::Instrumented<mountpoint_s3::fs::{impl#8}::mknod::{async_fn_env#0}<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>>>>, core::result::Result<mountpoint_s3::fs::Entry, mountpoint_s3::fs::error::Error>> () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/std/src/thread/local.rs:246
#7  run_executor<core::result::Result<mountpoint_s3::fs::Entry, mountpoint_s3::fs::error::Error>, futures_executor::local_pool::block_on::{closure_env#0}<tracing::instrument::Instrumented<mountpoint_s3::fs::{impl#8}::mknod::{async_fn_env#0}<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>>>> () at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/futures-executor-0.3.29/src/local_pool.rs:86
#8  block_on<tracing::instrument::Instrumented<mountpoint_s3::fs::{impl#8}::mknod::{async_fn_env#0}<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>>> ()
    at /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/futures-executor-0.3.29/src/local_pool.rs:317
#9  0x0000563c08426508 in mknod<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>> () at mountpoint-s3/src/fuse.rs:281
#10 0x0000563c084ae3e4 in dispatch_req<mountpoint_s3::fuse::S3FuseFilesystem<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>> () at vendor/fuser/src/request.rs:238
#11 0x0000563c084af8c5 in dispatch<mountpoint_s3::fuse::S3FuseFilesystem<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>> () at vendor/fuser/src/request.rs:58
#12 0x0000563c08480d5d in run_with_callbacks<mountpoint_s3::fuse::S3FuseFilesystem<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>, mountpoint_s3::fuse::session::{impl#3}::run::{closure_env#1}<mountpoint_s3::fuse::S3FuseFilesystem<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>, mountpoint_s3::fuse::session::{impl#1}::run::{closure_env#0}<fuser::session::Session<mountpoint_s3::fuse::S3FuseFilesystem<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>>>, mountpoint_s3::fuse::session::{impl#1}::run::{closure_env#1}<fuser::session::Session<mountpoint_s3::fuse::S3FuseFilesystem<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>>>>, mountpoint_s3::fuse::session::{impl#3}::run::{closure_env#0}<mountpoint_s3::fuse::S3FuseFilesystem<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>, mountpoint_s3::fuse::session::{impl#1}::run::{closure_env#0}<fuser::session::Session<mountpoint_s3::fuse::S3FuseFilesystem<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>>>, mountpoint_s3::fuse::session::{impl#1}::run::{closure_env#1}<fuser::session::Session<mountpoint_s3::fuse::S3FuseFilesystem<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>>>>> () at vendor/fuser/src/session.rs:148
#13 run<mountpoint_s3::fuse::S3FuseFilesystem<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>, mountpoint_s3::fuse::session::{impl#1}::run::{closure_env#0}<fuser::session::Session<mountpoint_s3::fuse::S3FuseFilesystem<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>>>, mountpoint_s3::fuse::session::{impl#1}::run::{closure_env#1}<fuser::session::Session<mountpoint_s3::fuse::S3FuseFilesystem<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>>>> () at mountpoint-s3/src/fuse/session.rs:223
#14 0x0000563c084a4be0 in run<fuser::session::Session<mountpoint_s3::fuse::S3FuseFilesystem<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>>> () at mountpoint-s3/src/fuse/session.rs:185
#15 0x0000563c08497fc0 in {closure#1}<fuser::session::Session<mountpoint_s3::fuse::S3FuseFilesystem<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>>> () at mountpoint-s3/src/fuse/session.rs:176
#16 __rust_begin_short_backtrace<mountpoint_s3::fuse::session::{impl#1}::try_add_worker::{closure_env#1}<fuser::session::Session<mountpoint_s3::fuse::S3FuseFilesystem<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>>>, core::result::Result<(), std::io::error::Error>> () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/std/src/sys_common/backtrace.rs:135
#17 0x0000563c0848710c in {closure#0}<mountpoint_s3::fuse::session::{impl#1}::try_add_worker::{closure_env#1}<fuser::session::Session<mountpoint_s3::fuse::S3FuseFilesystem<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>>>, core::result::Result<(), std::io::error::Error>> () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/std/src/thread/mod.rs:529
#18 call_once<core::result::Result<(), std::io::error::Error>, std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure_env#0}<mountpoint_s3::fuse::session::{impl#1}::try_add_worker::{closure_env#1}<fuser::session::Session<mountpoint_s3::fuse::S3FuseFilesystem<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>>>, core::result::Result<(), std::io::error::Error>>> () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/core/src/panic/unwind_safe.rs:271
#19 do_call<core::panic::unwind_safe::AssertUnwindSafe<std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure_env#0}<mountpoint_s3::fuse::session::{impl#1}::try_add_worker::{closure_env#1}<fuser::session::Session<mountpoint_s3::fuse::S3FuseFilesystem<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>>>, core::result::Result<(), std::io::error::Error>>>, core::result::Result<(), std::io::error::Error>> () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/std/src/panicking.rs:500
#20 try<core::result::Result<(), std::io::error::Error>, core::panic::unwind_safe::AssertUnwindSafe<std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure_env#0}<mountpoint_s3::fuse::session::{impl#1}::try_add_worker::{closure_env#1}<fuser::session::Session<mountpoint_s3::fuse::S3FuseFilesystem<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>>>, core::result::Result<(), std::io::error::Error>>>> () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/std/src/panicking.rs:464
#21 catch_unwind<core::panic::unwind_safe::AssertUnwindSafe<std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure_env#0}<mountpoint_s3::fuse::session::{impl#1}::try_add_worker::{closure_env#1}<fuser::session::Session<mountpoint_s3::fuse::S3FuseFilesystem<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>>>, core::result::Result<(), std::io::error::Error>>>, core::result::Result<(), std::io::error::Error>> () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/std/src/panic.rs:142
#22 {closure#1}<mountpoint_s3::fuse::session::{impl#1}::try_add_worker::{closure_env#1}<fuser::session::Session<mountpoint_s3::fuse::S3FuseFilesystem<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>>>, core::result::Result<(), std::io::error::Error>> () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/std/src/thread/mod.rs:528
#23 call_once<std::thread::{impl#0}::spawn_unchecked_::{closure_env#1}<mountpoint_s3::fuse::session::{impl#1}::try_add_worker::{closure_env#1}<fuser::session::Session<mountpoint_s3::fuse::S3FuseFilesystem<mountpoint_s3_client::s3_crt_client::S3CrtClient, mountpoint_s3::prefetch::Prefetcher<mountpoint_s3::prefetch::caching_stream::CachingPartStream<mountpoint_s3::data_cache::disk_data_cache::DiskDataCache, mountpoint_s3_crt::io::event_loop::EventLoopGroup>>>>>, core::result::Result<(), std::io::error::Error>>, ()> () at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/core/src/ops/function.rs:250
#24 0x0000563c08a23585 in <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once () at library/alloc/src/boxed.rs:1993
#25 <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once () at library/alloc/src/boxed.rs:1993
#26 std::sys::unix::thread::Thread::new::thread_start () at library/std/src/sys/unix/thread.rs:108
#27 0x00007f5892d2344b in start_thread () from /lib64/libpthread.so.0
#28 0x00007f589251a52f in clone () from /lib64/libc.so.6
@SamStudio8 SamStudio8 added the bug Something isn't working label Jan 19, 2024
@SamStudio8 SamStudio8 changed the title Mountpoint hangs indefinitely Mountpoint operations hang indefinitely Jan 19, 2024
@monthonk
Copy link
Contributor

monthonk commented Jan 22, 2024 •
edited
Loading

Hi @SamStudio8, thanks for reporting the issue. From your backtrace, mountpoint seems to be stuck at mknod operation. We looked into the code and found that there is a possibility of deadlock if mknod and forget are called on files under the same directory. This is something we should fix but we're still not sure weather it is the root cause for your problem or not.

The backtrace you provided is very helpful but it's only for 1 worker thread. Would it be possible for you to get backtrace from all workers in mountpoint, so we can confirm the root cause?

@monthonk
Copy link
Contributor

Another thing we're interested in is a way to reproduce the issue. Could you share more about your access pattern that causing the hang so we have better idea how to reproduce it?

@SamStudio8
Copy link
Author

SamStudio8 commented Jan 22, 2024 •
edited
Loading

@monthonk Thanks for taking a look! I am glad the backtraces were helpful. The machine that I produced these backtraces from has been terminated, but I will capture a backtrace of all workers the next time I see this manifest and update here. With regards to the access pattern, it is hard to characterise specifics that would be helpful for a repro but there are several things going on:

  • consistent access to ranges of a very large file (which should be cached)
  • consistent access to several small files
  • heavy write load copying from EBS volumes to S3 mount to create new files (and directories)

Sorry that isn't much to go on!

@SamStudio8
Copy link
Author

@monthonk Backtrace of all threads from a new hang attached.
backtraces.txt

@monthonk
Copy link
Contributor

@SamStudio8 thanks again for providing more details on your access pattern! I will take a look at the full backtrace and let you know once we have any updates.

@monthonk monthonk mentioned this issue Jan 24, 2024
Merged
@monthonk
Copy link
Contributor

I have looked at the full backtraces you sent but didn't see any forget calls among other file operations. So, there might be another problem with the lock somewhere and still need further investigation.

Anyway, we have just released v1.4.0 which includes a bug fix for the problem with mknod and forget. It might help reduce the possibility of deadlock for you as well since mknod now handle the lock properly. I think it's worth trying the new version!

@SamStudio8
Copy link
Author

Thanks @monthonk, way ahead of you on that front! Took 1.4.0 for a spin this morning but we're getting some intermittent "bad file descriptor" errors (we haven't changed anything workload related between 1.3.2 and 1.4.0). I am trying to isolate the cause to see what we're doing wrong.

@SamStudio8
Copy link
Author

Just FYI I think I have associated the "bad file descriptor" error to an entry in the mount-s3 log that indicates that we're reading from a closed file handle. I am not sure how this is the case, but I will investigate further and then hopefully we'll be able to reap the benefits of 1.4.0!

@ahmarsuhail
Copy link
Contributor

Hey @SamStudio8, wondering if you were able to try again with v1.4.0 and are still facing this issue?

@SamStudio8
Copy link
Author

Hi @ahmarsuhail, thanks for checking in. I was able to circumvent the "bad file descriptor" described above by just copying the file in question to change its access pattern to just read from EBS. I haven't seen this hanging issue in 1.4.0 so I am happy if you want to close this issue for now. We can reopen it if I am able to reproduce it again.

@ahmarsuhail
Copy link
Contributor

Sounds good, thank you! closing for now.

@dannycjones dannycjones mentioned this issue Feb 13, 2024
Closed
@dannycjones
Copy link
Contributor

I was able to circumvent the "bad file descriptor" described above by just copying the file in question to change its access pattern to just read from EBS. I haven't seen this hanging issue in 1.4.0 so I am happy if you want to close this issue for now. We can reopen it if I am able to reproduce it again.

@SamStudio8 It may be worth subscribing to #749 since it looks like the same issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@SamStudio8 @dannycjones @ahmarsuhail @monthonk