Opening file for write fails with EPERM when read handle was just closed

[mtcalvin]

Mountpoint for Amazon S3 version

mount-s3 1.14.0

AWS Region

us-west-2

Describe the running environment

Running in EC2 on AL2 with credentials provided via AWS_PROFILE in a shell session.

Linux <hostname> 5.10.234-206.910.amzn2int.x86_64 #1 SMP Sat Feb 22 01:31:51 UTC 2025 x86_64 x86_64 x86_64 GNU/Linux

Mountpoint options

mount-s3 -l ./log --allow-overwrite -f -d <bucket name> mnt

What happened?

I wrote a small Rust program to reproduce the bug:

use std::{fs::{self, File, OpenOptions}};
use std::io::Read;
use std::io::Write;

fn main() {
    let path = "mountpoint-test/mnt/test.txt";

    // Ensure file exists before running the test
    {
        let mut f = OpenOptions::new()
                .write(true)
                .create(true)
                .truncate(true)
                .open(&path)
                .expect("open for write");

        f.write_all(b"hello, world!\n").unwrap();
        f.sync_all().unwrap();
    }

    for i in 0..1000 {
        println!("attempt {}", i);
        let mut buf = Vec::new();
        {
            let mut f = File::open(&path).expect("open for read");
            f.read_to_end(&mut buf).expect("read_to_end");
            // file is closed here since f goes out of scope
        }

        let mut f = OpenOptions::new()
                .write(true)
                .create(true)
                .truncate(true)
                .open(&path)
                .expect("open for write");

        f.write_all(&buf).unwrap();
        f.sync_all().unwrap();
    }
}

I then ran this program under strace and observed that it successfully read the file, closed the file descriptor associated with the readable file, then attempted to open the file again for writing, which crashed:

openat(AT_FDCWD, "...mountpoint-test/mnt/test.txt", O_RDONLY|O_CLOEXEC) = 3
statx(3, "", AT_STATX_SYNC_AS_STAT|AT_EMPTY_PATH, STATX_ALL, {stx_mask=STATX_BASIC_STATS|0x1000, stx_attributes=0, stx_mode=S_IFREG|0644, stx_size=14, ...}) = 0
lseek(3, 0, SEEK_CUR)                   = 0
read(3, "hello, world!\n", 14)          = 14
read(3, "", 32)                         = 0
close(3)                                = 0

openat(AT_FDCWD, "...mountpoint-test/mnt/test.txt", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = -1 EPERM (Operation not permitted)

I observed that in the mount-s3 debug logs, S3 mountpoint still believes the file is opened for reading despite that the file descriptor was closed prior to the call to open the file for writing.

Relevant log output

2025-03-19T17:14:02.457579Z DEBUG fuser::request: FUSE( 38) ino 0x0000000000000002 READ fh FileHandle(2), offset 0, size 4096    
2025-03-19T17:14:02.457684Z DEBUG fuser::request: FUSE( 40) ino 0x0000000000000002 FLUSH fh FileHandle(2), lock owner LockOwner(16635141689843330169)    
2025-03-19T17:14:02.457753Z DEBUG fuser::request: FUSE( 42) ino 0x0000000000000002 RELEASE fh FileHandle(2), flags 0x8000, flush false, lock owner None    
2025-03-19T17:14:02.457833Z DEBUG fuser::request: FUSE( 44) ino 0x0000000000000002 OPEN flags 0x8201    
2025-03-19T17:14:02.457937Z DEBUG open{req=44 ino=2 pid=29350 name="test.txt" name="test.txt"}:head_object{id=17 bucket="<bucket>" key="test.txt"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-03-19T17:14:02.458032Z DEBUG open{req=44 ino=2 pid=29350 name="test.txt" name="test.txt"}:list_objects{id=18 bucket="<bucket>" continued=false delimiter="/" max_keys="1" prefix="test.txt/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-03-19T17:14:02.465996Z DEBUG open{req=44 ino=2 pid=29350 name="test.txt" name="test.txt"}:head_object{id=17 bucket="<bucket>" key="test.txt"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=HeadObject crt_error=None http_status=200 range=None duration=7.969722ms ttfb=Some(7.712284ms) request_id=1YA9522261HK0B5J
2025-03-19T17:14:02.466110Z DEBUG open{req=44 ino=2 pid=29350 name="test.txt" name="test.txt"}:head_object{id=17 bucket="<bucket>" key="test.txt"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=8.142814ms
2025-03-19T17:14:02.468921Z DEBUG open{req=44 ino=2 pid=29350 name="test.txt" name="test.txt"}:list_objects{id=18 bucket="<bucket>" continued=false delimiter="/" max_keys="1" prefix="test.txt/"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=Default crt_error=None http_status=200 range=None duration=10.792946ms ttfb=Some(9.797485ms) request_id=1YA27CJFMAYNAD96
2025-03-19T17:14:02.469007Z DEBUG open{req=44 ino=2 pid=29350 name="test.txt" name="test.txt"}:list_objects{id=18 bucket="<bucket>" continued=false delimiter="/" max_keys="1" prefix="test.txt/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=10.950925ms
2025-03-19T17:14:02.469113Z  WARN open{req=44 ino=2 pid=29350 name="test.txt" name="test.txt"}: mountpoint_s3::fuse: open failed with errno 1: inode error: inode 2 (full key "test.txt") is not writable while being read

[mtcalvin]

mountpoint-s3-2025-03-19T17-11-42Z.bGOvzR.log

[c-hagem]

Hi, from the logs it seems as if there is another PID that is trying to access the file just written to (PID 29402), while the test seems to have PID 29350. From what I can see from the logs, the second PID opens the file for reading before the write happens. Could it be that there is some other software on the host, that might be scanning for new files?

[mtcalvin]

Thanks for pointing it out, it turns out the development environment I was running the reproducer on had some security scanners running in the background.

I was able to reproduce the issue in a clean environment that matches the production environment where we observed the problem originally.

Updated mount command:

mount-s3 -f -l ./logs -d --allow-overwrite --cache /tmp/cache <bucket> /tmp/testmount

With this setup, I was able to reproduce the problem and confirm from the logs that only one unique PID is printed (the PID of the test program).

$ cat mountpoint-scrubbed.log | grep -o 'pid=[0-9]\+' | uniq
pid=1195417

If I remove --cache /tmp/cache then I no longer observe the problem. Is there something about the local filesystem cache that could trigger this behavior?

[mtcalvin]

mountpoint-scrubbed.log

[adpeace]

This is reproducible even without local cache. The problem appears to be co-ordination between release calls and open calls in the filesystem crate. In release, we eventually decrement a reader count, which is checked on open and if non-zero causes the error you observe. However, those two operation appear to be able to run in parallel on separate threads, and adding a pause to the release method causes the issue to reproduce immediately. Similarly, starting mountpoint with --max-threads 1 makes the problem go away (1000 iterations complete successfully, at least).

[adpeace]

Trace log: here I added a 100ms pause in the release method, and the log message "finished handle" immediately after calling handle.finish on the read handle, which is where the reference-count is decremented:

2025-05-07T21:40:09.511369Z DEBUG fuser::request: FUSE( 30) ino 0x0000000000000002 OPEN flags 0x8201    
2025-05-07T21:40:09.511445Z DEBUG fuser::request: FUSE( 28) ino 0x0000000000000002 RELEASE fh FileHandle(2), flags 0x8000, flush false, lock owner None    
2025-05-07T21:40:09.511453Z TRACE open{req=30 ino=2 pid=53106}: mountpoint_s3_fs::fs: fs:open with ino 2 flags O_WRONLY | O_TRUNC | 0x8000 pid 53106
2025-05-07T21:40:09.511490Z DEBUG mountpoint_s3_fs::fuse::session: starting fuse worker 3 (thread id 53108)
2025-05-07T21:40:09.511527Z TRACE release{req=28 ino=2 fh=2}: mountpoint_s3_fs::fs: fs:release with ino 2 fh 2
2025-05-07T21:40:09.511704Z TRACE open{req=30 ino=2 pid=53106 name="test.txt" name="test.txt"}: mountpoint_s3_client::s3_crt_client: resolved endpoint uri=Uri("https://adpeace-mountpoint-perf-test.s3.us-east-1.amazonaws.com")
2025-05-07T21:40:09.511792Z TRACE open{req=30 ino=2 pid=53106 name="test.txt" name="test.txt"}: mountpoint_s3_client::s3_crt_client: resolved auth scheme auth_scheme=AuthScheme { disable_double_encoding: true, scheme_name: SigV4, signing_name: "s3", signing_region: "us-east-1" }
2025-05-07T21:40:09.511888Z DEBUG open{req=30 ino=2 pid=53106 name="test.txt" name="test.txt"}:head_object{id=11 bucket="adpeace-mountpoint-perf-test" key="test.txt"}: mountpoint_s3_client::s3_crt_client::head_object: new request
2025-05-07T21:40:09.512187Z TRACE open{req=30 ino=2 pid=53106 name="test.txt" name="test.txt"}: mountpoint_s3_client::s3_crt_client: resolved endpoint uri=Uri("https://adpeace-mountpoint-perf-test.s3.us-east-1.amazonaws.com")
2025-05-07T21:40:09.512262Z TRACE open{req=30 ino=2 pid=53106 name="test.txt" name="test.txt"}: mountpoint_s3_client::s3_crt_client: resolved auth scheme auth_scheme=AuthScheme { disable_double_encoding: true, scheme_name: SigV4, signing_name: "s3", signing_region: "us-east-1" }
2025-05-07T21:40:09.512363Z DEBUG open{req=30 ino=2 pid=53106 name="test.txt" name="test.txt"}:list_objects{id=12 bucket="adpeace-mountpoint-perf-test" continued=false delimiter="/" max_keys="1" prefix="test.txt/"}: mountpoint_s3_client::s3_crt_client::list_objects: new request
2025-05-07T21:40:09.522201Z DEBUG open{req=30 ino=2 pid=53106 name="test.txt" name="test.txt"}:head_object{id=11 bucket="adpeace-mountpoint-perf-test" key="test.txt"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=HeadObject crt_error=None http_status=200 range=None duration=10.00263ms ttfb=Some(9.28575ms) request_id=G8KXFSX81QN4ECFZ
2025-05-07T21:40:09.522320Z TRACE open{req=30 ino=2 pid=53106 name="test.txt" name="test.txt"}:head_object{id=11 bucket="adpeace-mountpoint-perf-test" key="test.txt"}: mountpoint_s3_client::s3_crt_client: S3 request completed detailed_metrics=RequestMetrics { request_id: Some("G8KXFSX81QN4ECFZ"), start_timestamp_ns: 40805176219121, end_timestamp_ns: 40805186221751, send_start_timestamp_ns: Some(40805176603758), send_end_timestamp_ns: Some(40805176761421), receive_start_timestamp_ns: Some(40805186047171), receive_end_timestamp_ns: Some(40805186116166), response_status_code: Some(200), response_headers: Some(Headers { inner: 0x7fb758056030 }), request_path_query: Some("/test.txt"), host_address: Some("adpeace-mountpoint-perf-test.s3.us-east-1.amazonaws.com"), ip_address: Some("16.15.176.208"), connection_id: Some(140425432343136), thread_id: Some(ThreadId(140426082244160)), request_stream_id: Some(17), request_type: HeadObject, error_code: Error(0, "aws-c-common: AWS_ERROR_SUCCESS, Success.") }
2025-05-07T21:40:09.522338Z TRACE open{req=30 ino=2 pid=53106 name="test.txt" name="test.txt"}:list_objects{id=12 bucket="adpeace-mountpoint-perf-test" continued=false delimiter="/" max_keys="1" prefix="test.txt/"}: mountpoint_s3_client::s3_crt_client: body part received start=0 length=289
2025-05-07T21:40:09.522469Z DEBUG open{req=30 ino=2 pid=53106 name="test.txt" name="test.txt"}:list_objects{id=12 bucket="adpeace-mountpoint-perf-test" continued=false delimiter="/" max_keys="1" prefix="test.txt/"}: mountpoint_s3_client::s3_crt_client: S3 request finished request_type=Default crt_error=None http_status=200 range=None duration=9.791822ms ttfb=Some(8.214587ms) request_id=G8KMYM4GPQNDM8ZC
2025-05-07T21:40:09.522546Z TRACE open{req=30 ino=2 pid=53106 name="test.txt" name="test.txt"}:list_objects{id=12 bucket="adpeace-mountpoint-perf-test" continued=false delimiter="/" max_keys="1" prefix="test.txt/"}: mountpoint_s3_client::s3_crt_client: S3 request completed detailed_metrics=RequestMetrics { request_id: Some("G8KMYM4GPQNDM8ZC"), start_timestamp_ns: 40805176759607, end_timestamp_ns: 40805186551429, send_start_timestamp_ns: Some(40805177083952), send_end_timestamp_ns: Some(40805177191808), receive_start_timestamp_ns: Some(40805185406395), receive_end_timestamp_ns: Some(40805186297094), response_status_code: Some(200), response_headers: Some(Headers { inner: 0x7fb758032ae0 }), request_path_query: Some("/?list-type=2&delimiter=%2F&max-keys=1&prefix=test.txt%2F"), host_address: Some("adpeace-mountpoint-perf-test.s3.us-east-1.amazonaws.com"), ip_address: Some("52.216.44.130"), connection_id: Some(140425432241696), thread_id: Some(ThreadId(140426082244160)), request_stream_id: Some(11), request_type: Unknown, error_code: Error(0, "aws-c-common: AWS_ERROR_SUCCESS, Success.") }
2025-05-07T21:40:09.522602Z DEBUG open{req=30 ino=2 pid=53106 name="test.txt" name="test.txt"}:head_object{id=11 bucket="adpeace-mountpoint-perf-test" key="test.txt"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=10.57995ms
2025-05-07T21:40:09.522724Z DEBUG open{req=30 ino=2 pid=53106 name="test.txt" name="test.txt"}:list_objects{id=12 bucket="adpeace-mountpoint-perf-test" continued=false delimiter="/" max_keys="1" prefix="test.txt/"}: mountpoint_s3_client::s3_crt_client: meta request finished duration=10.276098ms
2025-05-07T21:40:09.523047Z TRACE open{req=30 ino=2 pid=53106 name="test.txt" name="test.txt"}: mountpoint_s3_fs::superblock: found a regular file in S3 parent=1 name="test.txt" etag=Some("\"1093755b3c526deae5805edb1f317d5e-1\"")
2025-05-07T21:40:09.523126Z TRACE open{req=30 ino=2 pid=53106 name="test.txt" name="test.txt"}: mountpoint_s3_fs::superblock: updating inode in place parent=1 name="test.txt" ino=2
2025-05-07T21:40:09.523182Z TRACE open{req=30 ino=2 pid=53106 name="test.txt" name="test.txt"}: mountpoint_s3_fs::superblock: write ino=2
2025-05-07T21:40:09.523272Z  WARN open{req=30 ino=2 pid=53106 name="test.txt" name="test.txt"}: mountpoint_s3_fs::fuse: open failed with errno 1: inode error: inode 2 (key "test.txt") is not writable while being read
2025-05-07T21:40:09.611822Z TRACE release{req=28 ino=2 fh=2 name="test.txt" name="test.txt"}: mountpoint_s3_fs::fs: finished handle