starred/s3fs-fuse
1
0
Fork 0
mirror of https://github.com/s3fs-fuse/s3fs-fuse.git synced 2026-04-25 21:35:58 +03:00
Code Issues 305 Projects Releases 5 Packages Wiki Activity

[GH-ISSUE #1676] Deadlock in current development version #872

New issue
Closed
opened 2026-03-04 01:49:33 +03:00 by kerem · 4 comments
kerem commented 2026-03-04 01:49:33 +03:00
Owner
Copy link

Originally created by @CarstenGrohmann on GitHub (Jun 9, 2021).
Original GitHub issue: https://github.com/s3fs-fuse/s3fs-fuse/issues/1676

Dear S3FS Developer,

Running the current master to copy a file and do a parallel ls causes a deadlock.

After I started a copy job, I repeatedly displayed the contents of the mount. After a few repetitions, s3fs hung at fdcache.cpp:Open(468).

strace shows a futex(0x7ffe383480b0, FUTEX_WAIT_PRIVATE, 0, NULL in this state. After waiting a few minutes I terminated s3fs with kill -9 (SIGKILL). I simple kill doesn't terminate the process.

I can reproduce this issue only with the current master f5701fa. I'm not able to reproduce this issue with the older commit 9bf525e.

More details:

# ps -ef | grep s3
root     28283 28213 22 12:44 pts/4    00:00:33 ./s3fs mybucket /s3 -o url=http://mys3service:8088,use_path_request_style,notsup_compat_dir,enable_noobj_cache,curldbg,dbglevel=debug -d -d -f

# strace -p 28283
strace: Process 28283 attached
futex(0x7ffe383480b0, FUTEX_WAIT_PRIVATE, 0, NULL^Cstrace: Process 28283 detached
 <detached ...>

# gdb -p 28283
GNU gdb (GDB) Red Hat Enterprise Linux 7.6.1-114.el7
Copyright (C) 2013 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
[...]
(gdb) bt full
#0  0x00007f95b9d7cadb in futex_abstimed_wait (cancel=true, private=<optimized out>, abstime=0x0, expected=0, futex=0x7ffe383480b0) at ../nptl/sysdeps/unix/sysv/linux/sem_waitcommon.c:43
        __to = 0x0
        __status = <optimized out>
        _val = 0
        err = <optimized out>
        oldtype = 0
#1  do_futex_wait (sem=sem@entry=0x7ffe383480b0, abstime=0x0) at ../nptl/sysdeps/unix/sysv/linux/sem_waitcommon.c:223
        err = <optimized out>
#2  0x00007f95b9d7cb6f in __new_sem_wait_slow (sem=0x7ffe383480b0, abstime=0x0) at ../nptl/sysdeps/unix/sysv/linux/sem_waitcommon.c:292
        _buffer = {__routine = 0x7f95b9d7caa0 <__sem_wait_cleanup>, __arg = 0x7ffe383480b0, __canceltype = 25338624, __prev = 0x0}
        err = <optimized out>
        d = 0
#3  0x00007f95b9d7cc0b in __new_sem_wait (sem=<optimized out>) at ../nptl/sysdeps/unix/sysv/linux/sem_wait.c:28
No locals.
#4  0x00007f95bb1f25c8 in fuse_session_loop_mt () from /lib64/libfuse.so.2
No symbol table info available.
#5  0x00007f95bb1f7ce7 in fuse_loop_mt () from /lib64/libfuse.so.2
No symbol table info available.
#6  0x00007f95bb1fa875 in fuse_main_common () from /lib64/libfuse.so.2
No symbol table info available.
#7  0x0000000000429514 in main (argc=<optimized out>, argv=<optimized out>) at s3fs.cpp:5246
        option_index = 0
        long_opts = {{name = 0x48c178 "help", has_arg = 0, flag = 0x0, val = 104}, {name = 0x48c079 "version", has_arg = 0, flag = 0x0, val = 0}, {name = 0x48bcfc "debug", has_arg = 0, flag = 0x0, val = 100}, {
            name = 0x48c17d "incomplete-mpu-list", has_arg = 0, flag = 0x0, val = 117}, {name = 0x48c191 "incomplete-mpu-abort", has_arg = 2, flag = 0x0, val = 97}, {name = 0x0, has_arg = 0, flag = 0x0, val = 0}}
        found = <optimized out>
        fuse_res = <optimized out>
        __func__ = "main"
        ch = <optimized out>
        s3fs_oper = {getattr = 0x411ba7 <s3fs_getattr(char const*, stat*)>, readlink = 0x415690 <s3fs_readlink(char const*, char*, size_t)>, getdir = 0x0, mknod = 0x41b00e <s3fs_mknod(char const*, mode_t, dev_t)>,
          mkdir = 0x418ff5 <s3fs_mkdir(char const*, mode_t)>, unlink = 0x40fe91 <s3fs_unlink(char const*)>, rmdir = 0x415e34 <s3fs_rmdir(char const*)>, symlink = 0x41fb7a <s3fs_symlink(char const*, char const*)>,
          rename = 0x41d271 <s3fs_rename(char const*, char const*)>, link = 0x4065ab <s3fs_link(char const*, char const*)>, chmod = 0x422118 <s3fs_chmod(char const*, mode_t)>,
          chown = 0x419264 <s3fs_chown(char const*, uid_t, gid_t)>, truncate = 0x42119c <s3fs_truncate(char const*, off_t)>, utime = 0x0, open = 0x41445d <s3fs_open(char const*, fuse_file_info*)>,
          read = 0x4086b6 <s3fs_read(char const*, char*, size_t, off_t, fuse_file_info*)>, write = 0x407de6 <s3fs_write(char const*, char const*, size_t, off_t, fuse_file_info*)>,
          statfs = 0x406060 <s3fs_statfs(char const*, statvfs*)>, flush = 0x4118e9 <s3fs_flush(char const*, fuse_file_info*)>, release = 0x407718 <s3fs_release(char const*, fuse_file_info*)>,
          fsync = 0x40696e <s3fs_fsync(char const*, int, fuse_file_info*)>, setxattr = 0x0, getxattr = 0x0, listxattr = 0x0, removexattr = 0x0, opendir = 0x4116ca <s3fs_opendir(char const*, fuse_file_info*)>,
          readdir = 0x410328 <s3fs_readdir(char const*, void*, fuse_fill_dir_t, off_t, fuse_file_info*)>, releasedir = 0x0, fsyncdir = 0x0, init = 0x4124a5 <s3fs_init(fuse_conn_info*)>, destroy = 0x406bd8 <s3fs_destroy(void*)>,
          access = 0x4100de <s3fs_access(char const*, int)>, create = 0x41b392 <s3fs_create(char const*, mode_t, fuse_file_info*)>, ftruncate = 0x0, fgetattr = 0x0, lock = 0x0,
          utimens = 0x41ed1f <s3fs_utimens(char const*, timespec const*)>, bmap = 0x0, flag_nullpath_ok = 0, flag_nopath = 0, flag_utime_omit_ok = 0, flag_reserved = 0, ioctl = 0x0, poll = 0x0, write_buf = 0x0, read_buf = 0x0,
          flock = 0x0, fallocate = 0x0}
        incomp_abort_time = 86400
        singletonLog = {static NEST_MAX = 4, static nest_spaces = {0x48c078 "", 0x498542 "  ", 0x498540 "    ", 0x49853e "      "}, static LOGFILEENV = 0x4985f2 <S3fsLog::LOGFILEENV> "S3FS_LOGFILE",
          static MSGTIMESTAMP = <same as static member of an already seen type>, static pSingleton = 0x7ffe383481bb, static debug_level = S3fsLog::LEVEL_DBG, static logfp = 0x0, static plogfile = 0x0, static time_stamp = true}
        custom_args = {argc = 5, argv = 0x17fdc80, allocated = 1}

Steps to reproduce:

  1. Start s3fs
  2. Copy a larger file (e.g. 3750M) 
    # cp -p 3750M /s3/
  3. Wait till s3fs starts flushing
  4. Do an ll to the mount 
    # ll /s3/
  5. Repeat the ll command on success till it blocks

Additionally I found this unexpected warning:

[WAN] string_util.cpp:cvt_strtoofft(96): something error is occurred in convert std::string(017080564) to off_t, thus return 0 as default.

s3fs debug log:

unique: 59997, opcode: WRITE (16), nodeid: 3, insize: 65616, pid: 28412
write[5] 65536 bytes to 3929145344 flags: 0x8001
2021-06-09T10:46:27.508Z [DBG] s3fs.cpp:s3fs_write(2346): [path=/3750M][size=65536][offset=3929145344][fd=5]
2021-06-09T10:46:27.508Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=5][ignore_existfd=false]
2021-06-09T10:46:27.508Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1]
2021-06-09T10:46:27.508Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=2]
2021-06-09T10:46:27.508Z [DBG] fdcache_entity.cpp:Open(336): [path=/3750M][fd=5][size=-1][time=-1]
2021-06-09T10:46:27.508Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=3]
2021-06-09T10:46:27.508Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=2]
2021-06-09T10:46:27.508Z [DBG] fdcache_entity.cpp:Write(1472): [path=/3750M][fd=5][offset=3929145344][size=65536]
2021-06-09T10:46:27.508Z [DBG] fdcache.cpp:Close(618): [ent->file=/3750M][ent->fd=5]
2021-06-09T10:46:27.508Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=1]
   write[5] 65536 bytes to 3929145344
   unique: 59997, success, outsize: 24
unique: 59998, opcode: WRITE (16), nodeid: 3, insize: 65616, pid: 28412
write[5] 65536 bytes to 3929210880 flags: 0x8001
2021-06-09T10:46:27.508Z [DBG] s3fs.cpp:s3fs_write(2346): [path=/3750M][size=65536][offset=3929210880][fd=5]
2021-06-09T10:46:27.508Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=5][ignore_existfd=false]
2021-06-09T10:46:27.508Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1]
2021-06-09T10:46:27.508Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=2]
2021-06-09T10:46:27.508Z [DBG] fdcache_entity.cpp:Open(336): [path=/3750M][fd=5][size=-1][time=-1]
2021-06-09T10:46:27.508Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=3]
2021-06-09T10:46:27.508Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=2]
2021-06-09T10:46:27.508Z [DBG] fdcache_entity.cpp:Write(1472): [path=/3750M][fd=5][offset=3929210880][size=65536]
2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:Close(618): [ent->file=/3750M][ent->fd=5]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=1]
   write[5] 65536 bytes to 3929210880
   unique: 59998, success, outsize: 24
unique: 59999, opcode: WRITE (16), nodeid: 3, insize: 65616, pid: 28412
write[5] 65536 bytes to 3929276416 flags: 0x8001
2021-06-09T10:46:27.509Z [DBG] s3fs.cpp:s3fs_write(2346): [path=/3750M][size=65536][offset=3929276416][fd=5]
2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=5][ignore_existfd=false]
2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=2]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Open(336): [path=/3750M][fd=5][size=-1][time=-1]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=3]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=2]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Write(1472): [path=/3750M][fd=5][offset=3929276416][size=65536]
2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:Close(618): [ent->file=/3750M][ent->fd=5]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=1]
   write[5] 65536 bytes to 3929276416
   unique: 59999, success, outsize: 24
unique: 60000, opcode: WRITE (16), nodeid: 3, insize: 65616, pid: 28412
write[5] 65536 bytes to 3929341952 flags: 0x8001
2021-06-09T10:46:27.509Z [DBG] s3fs.cpp:s3fs_write(2346): [path=/3750M][size=65536][offset=3929341952][fd=5]
2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=5][ignore_existfd=false]
2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=2]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Open(336): [path=/3750M][fd=5][size=-1][time=-1]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=3]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=2]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Write(1472): [path=/3750M][fd=5][offset=3929341952][size=65536]
2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:Close(618): [ent->file=/3750M][ent->fd=5]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=1]
   write[5] 65536 bytes to 3929341952
   unique: 60000, success, outsize: 24
unique: 60001, opcode: WRITE (16), nodeid: 3, insize: 65616, pid: 28412
write[5] 65536 bytes to 3929407488 flags: 0x8001
2021-06-09T10:46:27.509Z [DBG] s3fs.cpp:s3fs_write(2346): [path=/3750M][size=65536][offset=3929407488][fd=5]
2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=5][ignore_existfd=false]
2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=2]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Open(336): [path=/3750M][fd=5][size=-1][time=-1]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=3]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=2]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Write(1472): [path=/3750M][fd=5][offset=3929407488][size=65536]
2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:Close(618): [ent->file=/3750M][ent->fd=5]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=1]
   write[5] 65536 bytes to 3929407488
   unique: 60001, success, outsize: 24
unique: 60002, opcode: WRITE (16), nodeid: 3, insize: 5756, pid: 28412
write[5] 5676 bytes to 3929473024 flags: 0x8001
2021-06-09T10:46:27.509Z [DBG] s3fs.cpp:s3fs_write(2346): [path=/3750M][size=5676][offset=3929473024][fd=5]
2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=5][ignore_existfd=false]
2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=2]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Open(336): [path=/3750M][fd=5][size=-1][time=-1]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=3]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=2]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Write(1472): [path=/3750M][fd=5][offset=3929473024][size=5676]
2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:Close(618): [ent->file=/3750M][ent->fd=5]
2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=1]
   write[5] 5676 bytes to 3929473024
   unique: 60002, success, outsize: 24
unique: 60003, opcode: SETATTR (4), nodeid: 3, insize: 128, pid: 28412
utimens /3750M 1623232438.035669217 1614863324.017080564
2021-06-09T10:46:27.510Z [INF] s3fs.cpp:s3fs_utimens(1977): [path=/3750M][mtime=1614863324][ctime/atime=1623232438]
2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_parent_object_access(639): [path=/3750M]
2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_object_access(533): [path=/]
2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/]
2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_object_access(533): [path=/3750M]
2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M]
2021-06-09T10:46:27.510Z [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=12621366.633215470][hit count=1]
2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M]
2021-06-09T10:46:27.510Z [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=12621366.633215470][hit count=2]
2021-06-09T10:46:27.510Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=-1][ignore_existfd=true]
2021-06-09T10:46:27.510Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1]
2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=2]
2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Open(336): [path=/3750M][fd=5][size=-1][time=-1]
2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=3]
2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=2]
2021-06-09T10:46:27.510Z [WAN] string_util.cpp:cvt_strtoofft(96): something error is occurred in convert std::string(017080564) to off_t, thus return 0 as default.
2021-06-09T10:46:27.510Z [WAN] string_util.cpp:cvt_strtoofft(96): something error is occurred in convert std::string(035669217) to off_t, thus return 0 as default.
2021-06-09T10:46:27.510Z [WAN] string_util.cpp:cvt_strtoofft(96): something error is occurred in convert std::string(035669217) to off_t, thus return 0 as default.
2021-06-09T10:46:27.510Z [INF]       fdcache_entity.cpp:SetMCtime(705): [path=/3750M][fd=5][mtime=1614863324][ctime=1623232438]
2021-06-09T10:46:27.510Z [INF]       fdcache_entity.cpp:SetAtime(689): [path=/3750M][fd=5][time=1623232438]
2021-06-09T10:46:27.510Z [INF] s3fs.cpp:s3fs_utimens(2039): meta pending until upload is complete
2021-06-09T10:46:27.510Z [INF]       cache.cpp:UpdateMetaStats(449): update stat cache entry[path=/3750M]
2021-06-09T10:46:27.510Z [DBG] fdcache.cpp:Close(618): [ent->file=/3750M][ent->fd=5]
2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=1]
getattr /3750M
2021-06-09T10:46:27.510Z [INF] s3fs.cpp:s3fs_getattr(769): [path=/3750M]
2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_parent_object_access(639): [path=/3750M]
2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_object_access(533): [path=/]
2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/]
2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_object_access(533): [path=/3750M]
2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M]
2021-06-09T10:46:27.510Z [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=12621450.629794699][hit count=3]
2021-06-09T10:46:27.510Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=-1][ignore_existfd=false]
2021-06-09T10:46:27.510Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1]
2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=2]
2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Open(336): [path=/3750M][fd=5][size=-1][time=-1]
2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=3]
2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=2]
2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:s3fs_getattr(792): [path=/3750M] uid=0, gid=0, mode=100600
2021-06-09T10:46:27.510Z [DBG] fdcache.cpp:Close(618): [ent->file=/3750M][ent->fd=5]
2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=1]
   unique: 60003, success, outsize: 120
unique: 60004, opcode: REMOVEXATTR (24), nodeid: 3, insize: 53, pid: 28412
   unique: 60004, error: -38 (Function not implemented), outsize: 16
unique: 60005, opcode: SETXATTR (21), nodeid: 3, insize: 100, pid: 28412
   unique: 60005, error: -38 (Function not implemented), outsize: 16
unique: 60006, opcode: SETATTR (4), nodeid: 3, insize: 128, pid: 28412
2021-06-09T10:46:27.510Z [INF] s3fs.cpp:s3fs_chmod(1621): [path=/3750M][mode=100644]
2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_parent_object_access(639): [path=/3750M]
2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_object_access(533): [path=/]
2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/]
2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_object_owner(607): [path=/3750M]
2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M]
2021-06-09T10:46:27.510Z [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=12621450.629794699][hit count=4]
2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M]
2021-06-09T10:46:27.510Z [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=12621450.629794699][hit count=5]
2021-06-09T10:46:27.510Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=-1][ignore_existfd=true]
2021-06-09T10:46:27.510Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1]
2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=2]
2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Open(336): [path=/3750M][fd=5][size=-1][time=-1]
2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=3]
2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=2]
2021-06-09T10:46:27.510Z [INF]       fdcache_entity.cpp:SetMCtime(705): [path=/3750M][fd=5][mtime=1614863324][ctime=1623235587]
2021-06-09T10:46:27.510Z [INF]       fdcache_entity.cpp:SetAtime(689): [path=/3750M][fd=5][time=1623232438]
2021-06-09T10:46:27.510Z [INF] s3fs.cpp:s3fs_chmod(1680): meta pending until upload is complete
2021-06-09T10:46:27.510Z [INF]       cache.cpp:UpdateMetaStats(449): update stat cache entry[path=/3750M]
2021-06-09T10:46:27.510Z [DBG] fdcache.cpp:Close(618): [ent->file=/3750M][ent->fd=5]
2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=1]
getattr /3750M
2021-06-09T10:46:27.510Z [INF] s3fs.cpp:s3fs_getattr(769): [path=/3750M]
2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_parent_object_access(639): [path=/3750M]
2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_object_access(533): [path=/]
2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/]
2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_object_access(533): [path=/3750M]
2021-06-09T10:46:27.511Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M]
2021-06-09T10:46:27.511Z [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=12621450.630794706][hit count=6]
2021-06-09T10:46:27.511Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=-1][ignore_existfd=false]
2021-06-09T10:46:27.511Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1]
2021-06-09T10:46:27.511Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=2]
2021-06-09T10:46:27.511Z [DBG] fdcache_entity.cpp:Open(336): [path=/3750M][fd=5][size=-1][time=-1]
2021-06-09T10:46:27.511Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=3]
2021-06-09T10:46:27.511Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=2]
2021-06-09T10:46:27.511Z [DBG] s3fs.cpp:s3fs_getattr(792): [path=/3750M] uid=0, gid=0, mode=100600
2021-06-09T10:46:27.511Z [DBG] fdcache.cpp:Close(618): [ent->file=/3750M][ent->fd=5]
2021-06-09T10:46:27.511Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=1]
   unique: 60006, success, outsize: 120
unique: 60007, opcode: FLUSH (25), nodeid: 3, insize: 64, pid: 28412
flush[5]
2021-06-09T10:46:27.511Z [INF] s3fs.cpp:s3fs_flush(2394): [path=/3750M][fd=5]
2021-06-09T10:46:27.511Z [DBG] s3fs.cpp:check_parent_object_access(639): [path=/3750M]
2021-06-09T10:46:27.511Z [DBG] s3fs.cpp:check_object_access(533): [path=/]
2021-06-09T10:46:27.511Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/]
2021-06-09T10:46:27.511Z [DBG] s3fs.cpp:check_object_access(533): [path=/3750M]
2021-06-09T10:46:27.511Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M]
2021-06-09T10:46:27.511Z [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=12621450.630794706][hit count=7]
2021-06-09T10:46:27.511Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=5][ignore_existfd=false]
2021-06-09T10:46:27.511Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1]
2021-06-09T10:46:27.511Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=2]
2021-06-09T10:46:27.511Z [DBG] fdcache_entity.cpp:Open(336): [path=/3750M][fd=5][size=-1][time=-1]
2021-06-09T10:46:27.511Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=3]
2021-06-09T10:46:27.511Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=2]
2021-06-09T10:46:27.511Z [INF]       fdcache_entity.cpp:RowFlush(1216): [tpath=][path=/3750M][fd=5]
2021-06-09T10:46:27.511Z [INF]       curl.cpp:MultipartUploadRequest(4050): [upload_id=DutCg2tkhG_6i4hcWtJqIpA1IEM1jPsfpijrPCPzK4gv8lfUhaGrEqxNqw][tpath=/3750M][fd=5][offset=3928752128][size=726572]
2021-06-09T10:46:27.511Z [INF]       curl.cpp:UploadMultipartPostRequest(3786): [tpath=/3750M][start=3928752128][size=726572][part=376]
2021-06-09T10:46:27.511Z [INF]       curl.cpp:UploadMultipartPostSetup(3727): [tpath=/3750M][start=3928752128][size=726572][part=376]
2021-06-09T10:46:27.511Z [INF]       curl_util.cpp:prepare_url(254): URL is http://mys3service:8088/mybucket/3750M?partNumber=376&uploadId=DutCg2tkhG_6i4hcWtJqIpA1IEM1jPsfpijrPCPzK4gv8lfUhaGrEqxNqw
2021-06-09T10:46:27.511Z [INF]       curl_util.cpp:prepare_url(287): URL changed is http://mys3service:8088/mybucket/3750M?partNumber=376&uploadId=DutCg2tkhG_6i4hcWtJqIpA1IEM1jPsfpijrPCPzK4gv8lfUhaGrEqxNqw
2021-06-09T10:46:27.511Z [DBG] curl_handlerpool.cpp:GetHandler(81): Get handler from pool: rest = 30
2021-06-09T10:46:27.511Z [DBG] curl.cpp:RequestPerform(2281): connecting to URL http://mys3service:8088/mybucket/3750M?partNumber=376&uploadId=DutCg2tkhG_6i4hcWtJqIpA1IEM1jPsfpijrPCPzK4gv8lfUhaGrEqxNqw
2021-06-09T10:46:27.514Z [INF]       curl.cpp:insertV4Headers(2673): computing signature [PUT] [/3750M] [partNumber=376&uploadId=DutCg2tkhG_6i4hcWtJqIpA1IEM1jPsfpijrPCPzK4gv8lfUhaGrEqxNqw] [1a282c6abc7bb6c2567e2a8027bf5325cd1eef9e65eb218dab1d58cfdde6bd83]
2021-06-09T10:46:27.514Z [INF]       curl_util.cpp:url_to_host(331): url is http://mys3service:8088
2021-06-09T10:46:27.515Z [CURL DBG] * Found bundle for host mys3service: 0x7f95ac018ba0
2021-06-09T10:46:27.515Z [CURL DBG] * Re-using existing connection! (#0) with host mys3service
2021-06-09T10:46:27.515Z [CURL DBG] * Connected to mys3service (172.20.10.152) port 8088 (#0)
2021-06-09T10:46:27.515Z [CURL DBG] > PUT /mybucket/3750M?partNumber=376&uploadId=DutCg2tkhG_6i4hcWtJqIpA1IEM1jPsfpijrPCPzK4gv8lfUhaGrEqxNqw HTTP/1.1
2021-06-09T10:46:27.515Z [CURL DBG] > User-Agent: s3fs/1.89 (commit hash 8c58ba8; OpenSSL)
2021-06-09T10:46:27.515Z [CURL DBG] > Authorization: AWS4-HMAC-SHA256 Credential=NHTL282ERGST9B40156H/20210609/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=3b5115c339a450de850bd0b010caa524dbeca01af768c2e5b144cf6eb8077c37
2021-06-09T10:46:27.515Z [CURL DBG] > host: mys3service:8088
2021-06-09T10:46:27.515Z [CURL DBG] > x-amz-content-sha256: 1a282c6abc7bb6c2567e2a8027bf5325cd1eef9e65eb218dab1d58cfdde6bd83
2021-06-09T10:46:27.515Z [CURL DBG] > x-amz-date: 20210609T104627Z
2021-06-09T10:46:27.515Z [CURL DBG] > Content-Length: 726572
2021-06-09T10:46:27.515Z [CURL DBG] > Expect: 100-continue
2021-06-09T10:46:27.515Z [CURL DBG] >
2021-06-09T10:46:27.516Z [CURL DBG] < HTTP/1.1 100 Continue
2021-06-09T10:46:27.517Z [CURL DBG] * We are completely uploaded and fine
2021-06-09T10:46:27.529Z [CURL DBG] < HTTP/1.1 200 OK
2021-06-09T10:46:27.529Z [CURL DBG] < Date: Wed, 09 Jun 2021 10:46:27 GMT
2021-06-09T10:46:27.529Z [CURL DBG] < Connection: KEEP-ALIVE
2021-06-09T10:46:27.529Z [CURL DBG] < Server: StorageGRID/11.4.0.4
2021-06-09T10:46:27.529Z [CURL DBG] < x-amz-request-id: 1623235468181679
2021-06-09T10:46:27.529Z [CURL DBG] < x-amz-id-2: 12616688
2021-06-09T10:46:27.529Z [CURL DBG] < Content-Length: 0
2021-06-09T10:46:27.529Z [CURL DBG] < ETag: "a330ae562039ce296666415469ff641b"
2021-06-09T10:46:27.529Z [CURL DBG] <
2021-06-09T10:46:27.529Z [CURL DBG] * Connection #0 to host mys3service left intact
2021-06-09T10:46:27.529Z [INF]       curl.cpp:RequestPerform(2314): HTTP response code 200
2021-06-09T10:46:27.529Z [DBG] curl_handlerpool.cpp:ReturnHandler(103): Return handler to pool
2021-06-09T10:46:27.529Z [INF]       curl.cpp:CompleteMultipartPostRequest(3565): [tpath=/3750M][parts=376]
2021-06-09T10:46:27.530Z [DBG] curl_handlerpool.cpp:GetHandler(81): Get handler from pool: rest = 30
2021-06-09T10:46:27.530Z [INF]       curl_util.cpp:prepare_url(254): URL is http://mys3service:8088/mybucket/3750M?uploadId=DutCg2tkhG_6i4hcWtJqIpA1IEM1jPsfpijrPCPzK4gv8lfUhaGrEqxNqw
2021-06-09T10:46:27.530Z [INF]       curl_util.cpp:prepare_url(287): URL changed is http://mys3service:8088/mybucket/3750M?uploadId=DutCg2tkhG_6i4hcWtJqIpA1IEM1jPsfpijrPCPzK4gv8lfUhaGrEqxNqw
2021-06-09T10:46:27.530Z [DBG] curl.cpp:RequestPerform(2281): connecting to URL http://mys3service:8088/mybucket/3750M?uploadId=DutCg2tkhG_6i4hcWtJqIpA1IEM1jPsfpijrPCPzK4gv8lfUhaGrEqxNqw
2021-06-09T10:46:27.530Z [INF]       curl.cpp:insertV4Headers(2673): computing signature [POST] [/3750M] [uploadId=DutCg2tkhG_6i4hcWtJqIpA1IEM1jPsfpijrPCPzK4gv8lfUhaGrEqxNqw] [3f6ad2a1569a5efe986bd88c849194fe6bee8f0162bb41ad232adce4522349c6]
2021-06-09T10:46:27.530Z [INF]       curl_util.cpp:url_to_host(331): url is http://mys3service:8088
2021-06-09T10:46:27.530Z [CURL DBG] * Found bundle for host mys3service: 0x7f95ac018ba0
2021-06-09T10:46:27.530Z [CURL DBG] * Re-using existing connection! (#0) with host mys3service
2021-06-09T10:46:27.530Z [CURL DBG] * Connected to mys3service (172.20.10.152) port 8088 (#0)
2021-06-09T10:46:27.530Z [CURL DBG] > POST /mybucket/3750M?uploadId=DutCg2tkhG_6i4hcWtJqIpA1IEM1jPsfpijrPCPzK4gv8lfUhaGrEqxNqw HTTP/1.1
2021-06-09T10:46:27.530Z [CURL DBG] > User-Agent: s3fs/1.89 (commit hash 8c58ba8; OpenSSL)
2021-06-09T10:46:27.530Z [CURL DBG] > Authorization: AWS4-HMAC-SHA256 Credential=NHTL282ERGST9B40156H/20210609/us-east-1/s3/aws4_request, SignedHeaders=content-type;host;x-amz-content-sha256;x-amz-date, Signature=22a76ebc6d5d8037fe9e66543b0f1ebaa2b5505268f6fdbc29e06d74dcf69e4a
2021-06-09T10:46:27.530Z [CURL DBG] > Content-Type: application/xml
2021-06-09T10:46:27.530Z [CURL DBG] > host: mys3service:8088
2021-06-09T10:46:27.530Z [CURL DBG] > x-amz-content-sha256: 3f6ad2a1569a5efe986bd88c849194fe6bee8f0162bb41ad232adce4522349c6
2021-06-09T10:46:27.530Z [CURL DBG] > x-amz-date: 20210609T104627Z
2021-06-09T10:46:27.530Z [CURL DBG] > Content-Length: 36041
2021-06-09T10:46:27.530Z [CURL DBG] > Expect: 100-continue
2021-06-09T10:46:27.530Z [CURL DBG] >
2021-06-09T10:46:27.531Z [CURL DBG] < HTTP/1.1 100 Continue
2021-06-09T10:46:27.545Z [CURL DBG] < HTTP/1.1 200 OK
2021-06-09T10:46:27.546Z [CURL DBG] < Date: Wed, 09 Jun 2021 10:46:27 GMT
2021-06-09T10:46:27.546Z [CURL DBG] < Connection: CLOSE
2021-06-09T10:46:27.546Z [CURL DBG] < Server: StorageGRID/11.4.0.4
2021-06-09T10:46:27.546Z [CURL DBG] < x-amz-request-id: 1623235468181679
2021-06-09T10:46:27.546Z [CURL DBG] < x-amz-id-2: 12616688
2021-06-09T10:46:27.546Z [CURL DBG] < Content-Type: application/xml
2021-06-09T10:46:27.546Z [CURL DBG] <
2021-06-09T10:46:31.208Z [CURL DBG] * Closing connection 0
2021-06-09T10:46:31.208Z [INF]       curl.cpp:RequestPerform(2314): HTTP response code 200
2021-06-09T10:46:31.208Z [DBG] curl_handlerpool.cpp:ReturnHandler(103): Return handler to pool
unique: 60008, opcode: GETATTR (3), nodeid: 1, insize: 56, pid: 28495
getattr /
2021-06-09T10:46:37.497Z [INF] s3fs.cpp:s3fs_getattr(769): [path=/]
2021-06-09T10:46:37.497Z [DBG] s3fs.cpp:check_parent_object_access(639): [path=/]
2021-06-09T10:46:37.497Z [DBG] s3fs.cpp:check_object_access(533): [path=/]
2021-06-09T10:46:37.497Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/]
2021-06-09T10:46:37.497Z [DBG] fdcache.cpp:ExistOpen(551): [path=/][fd=-1][ignore_existfd=false]
2021-06-09T10:46:37.497Z [DBG] fdcache.cpp:Open(468): [path=/][size=-1][time=-1]
2021-06-09T10:46:37.497Z [DBG] s3fs.cpp:s3fs_getattr(792): [path=/] uid=0, gid=0, mode=40700
   unique: 60008, success, outsize: 120
unique: 60009, opcode: OPENDIR (27), nodeid: 1, insize: 48, pid: 28495
opendir flags: 0x18800 /
2021-06-09T10:46:37.497Z [INF] s3fs.cpp:s3fs_opendir(2507): [path=/][flags=0x18800]
2021-06-09T10:46:37.497Z [DBG] s3fs.cpp:check_object_access(533): [path=/]
2021-06-09T10:46:37.497Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/]
2021-06-09T10:46:37.497Z [DBG] s3fs.cpp:check_parent_object_access(639): [path=/]
   opendir[0] flags: 0x18800 /
   unique: 60009, success, outsize: 32
unique: 60010, opcode: READDIR (28), nodeid: 1, insize: 80, pid: 28495
readdir[0] from 0
2021-06-09T10:46:37.498Z [INF] s3fs.cpp:s3fs_readdir(2656): [path=/]
2021-06-09T10:46:37.498Z [DBG] s3fs.cpp:check_object_access(533): [path=/]
2021-06-09T10:46:37.498Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/]
2021-06-09T10:46:37.498Z [INF]   s3fs.cpp:list_bucket(2700): [path=/]
2021-06-09T10:46:37.498Z [INF]       curl.cpp:ListBucketRequest(3416): [tpath=/]
2021-06-09T10:46:37.498Z [DBG] curl_handlerpool.cpp:GetHandler(81): Get handler from pool: rest = 30
2021-06-09T10:46:37.498Z [INF]       curl_util.cpp:prepare_url(254): URL is http://mys3service:8088/mybucket?delimiter=/&max-keys=1000&prefix=
2021-06-09T10:46:37.498Z [INF]       curl_util.cpp:prepare_url(287): URL changed is http://mys3service:8088/mybucket/?delimiter=/&max-keys=1000&prefix=
2021-06-09T10:46:37.498Z [DBG] curl.cpp:RequestPerform(2281): connecting to URL http://mys3service:8088/mybucket/?delimiter=/&max-keys=1000&prefix=
2021-06-09T10:46:37.498Z [INF]       curl.cpp:insertV4Headers(2673): computing signature [GET] [/] [delimiter=/&max-keys=1000&prefix=] []
2021-06-09T10:46:37.498Z [INF]       curl_util.cpp:url_to_host(331): url is http://mys3service:8088
2021-06-09T10:46:37.498Z [CURL DBG] * About to connect() to mys3service port 8088 (#2)
2021-06-09T10:46:37.498Z [CURL DBG] *   Trying 172.20.10.152...
2021-06-09T10:46:37.499Z [CURL DBG] * Connected to mys3service (172.20.10.152) port 8088 (#2)
2021-06-09T10:46:37.499Z [CURL DBG] > GET /mybucket/?delimiter=/&max-keys=1000&prefix= HTTP/1.1
2021-06-09T10:46:37.499Z [CURL DBG] > User-Agent: s3fs/1.89 (commit hash 8c58ba8; OpenSSL)
2021-06-09T10:46:37.499Z [CURL DBG] > Accept: */*
2021-06-09T10:46:37.499Z [CURL DBG] > Authorization: AWS4-HMAC-SHA256 Credential=NHTL282ERGST9B40156H/20210609/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=cb2dcd404a2e11a70e1fd1de22b54f32306627f6f15f9be06390f585c0f5d6ec
2021-06-09T10:46:37.499Z [CURL DBG] > host: mys3service:8088
2021-06-09T10:46:37.499Z [CURL DBG] > x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
2021-06-09T10:46:37.499Z [CURL DBG] > x-amz-date: 20210609T104637Z
2021-06-09T10:46:37.499Z [CURL DBG] >
2021-06-09T10:46:38.610Z [CURL DBG] < HTTP/1.1 200 OK
2021-06-09T10:46:38.610Z [CURL DBG] < Date: Wed, 09 Jun 2021 10:46:38 GMT
2021-06-09T10:46:38.610Z [CURL DBG] < Connection: KEEP-ALIVE
2021-06-09T10:46:38.610Z [CURL DBG] < Server: StorageGRID/11.4.0.4
2021-06-09T10:46:38.610Z [CURL DBG] < x-amz-request-id: 1623235597503520
2021-06-09T10:46:38.610Z [CURL DBG] < x-amz-id-2: 12700546
2021-06-09T10:46:38.610Z [CURL DBG] < Content-Length: 587
2021-06-09T10:46:38.610Z [CURL DBG] < Content-Type: application/xml
2021-06-09T10:46:38.610Z [CURL DBG] <
2021-06-09T10:46:38.610Z [CURL DBG] * Connection #2 to host mys3service left intact
2021-06-09T10:46:38.611Z [INF]       curl.cpp:RequestPerform(2314): HTTP response code 200
2021-06-09T10:46:38.611Z [DBG] s3fs_xml.cpp:append_objects_from_xml_ex(331): contents_xp->nodesetval is empty.
2021-06-09T10:46:38.611Z [DBG] curl_handlerpool.cpp:ReturnHandler(103): Return handler to pool
2021-06-09T10:46:38.611Z [INF]   s3fs.cpp:readdir_multi_head(2572): [path=/][list=0]
2021-06-09T10:46:38.611Z [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=12621450.630794706][hit count=8]
2021-06-09T10:46:38.611Z [INF]       curl_multi.cpp:Request(297): [count=0]
2021-06-09T10:46:38.611Z [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=12621450.630794706][hit count=9]
   unique: 60010, success, outsize: 112
unique: 60011, opcode: LOOKUP (1), nodeid: 1, insize: 46, pid: 28495
LOOKUP /3750M
getattr /3750M
2021-06-09T10:46:38.611Z [INF] s3fs.cpp:s3fs_getattr(769): [path=/3750M]
2021-06-09T10:46:38.611Z [DBG] s3fs.cpp:check_parent_object_access(639): [path=/3750M]
2021-06-09T10:46:38.611Z [DBG] s3fs.cpp:check_object_access(533): [path=/]
2021-06-09T10:46:38.611Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/]
2021-06-09T10:46:38.611Z [DBG] s3fs.cpp:check_object_access(533): [path=/3750M]
2021-06-09T10:46:38.611Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M]
2021-06-09T10:46:38.611Z [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=12621450.630794706][hit count=10]
2021-06-09T10:46:38.611Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=-1][ignore_existfd=false]
2021-06-09T10:46:38.611Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1]
Originally created by @CarstenGrohmann on GitHub (Jun 9, 2021). Original GitHub issue: https://github.com/s3fs-fuse/s3fs-fuse/issues/1676 Dear S3FS Developer, Running the current master to copy a file and do a parallel `ls` causes a deadlock. After I started a copy job, I repeatedly displayed the contents of the mount. After a few repetitions, s3fs hung at `fdcache.cpp:Open(468)`. strace shows a `futex(0x7ffe383480b0, FUTEX_WAIT_PRIVATE, 0, NULL` in this state. After waiting a few minutes I terminated `s3fs` with `kill -9` (SIGKILL). I simple `kill` doesn't terminate the process. I can reproduce this issue only with the current master f5701fa. I'm not able to reproduce this issue with the older commit 9bf525e. **More details:** ``` # ps -ef | grep s3 root 28283 28213 22 12:44 pts/4 00:00:33 ./s3fs mybucket /s3 -o url=http://mys3service:8088,use_path_request_style,notsup_compat_dir,enable_noobj_cache,curldbg,dbglevel=debug -d -d -f # strace -p 28283 strace: Process 28283 attached futex(0x7ffe383480b0, FUTEX_WAIT_PRIVATE, 0, NULL^Cstrace: Process 28283 detached <detached ...> # gdb -p 28283 GNU gdb (GDB) Red Hat Enterprise Linux 7.6.1-114.el7 Copyright (C) 2013 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "x86_64-redhat-linux-gnu". For bug reporting instructions, please see: [...] (gdb) bt full #0 0x00007f95b9d7cadb in futex_abstimed_wait (cancel=true, private=<optimized out>, abstime=0x0, expected=0, futex=0x7ffe383480b0) at ../nptl/sysdeps/unix/sysv/linux/sem_waitcommon.c:43 __to = 0x0 __status = <optimized out> _val = 0 err = <optimized out> oldtype = 0 #1 do_futex_wait (sem=sem@entry=0x7ffe383480b0, abstime=0x0) at ../nptl/sysdeps/unix/sysv/linux/sem_waitcommon.c:223 err = <optimized out> #2 0x00007f95b9d7cb6f in __new_sem_wait_slow (sem=0x7ffe383480b0, abstime=0x0) at ../nptl/sysdeps/unix/sysv/linux/sem_waitcommon.c:292 _buffer = {__routine = 0x7f95b9d7caa0 <__sem_wait_cleanup>, __arg = 0x7ffe383480b0, __canceltype = 25338624, __prev = 0x0} err = <optimized out> d = 0 #3 0x00007f95b9d7cc0b in __new_sem_wait (sem=<optimized out>) at ../nptl/sysdeps/unix/sysv/linux/sem_wait.c:28 No locals. #4 0x00007f95bb1f25c8 in fuse_session_loop_mt () from /lib64/libfuse.so.2 No symbol table info available. #5 0x00007f95bb1f7ce7 in fuse_loop_mt () from /lib64/libfuse.so.2 No symbol table info available. #6 0x00007f95bb1fa875 in fuse_main_common () from /lib64/libfuse.so.2 No symbol table info available. #7 0x0000000000429514 in main (argc=<optimized out>, argv=<optimized out>) at s3fs.cpp:5246 option_index = 0 long_opts = {{name = 0x48c178 "help", has_arg = 0, flag = 0x0, val = 104}, {name = 0x48c079 "version", has_arg = 0, flag = 0x0, val = 0}, {name = 0x48bcfc "debug", has_arg = 0, flag = 0x0, val = 100}, { name = 0x48c17d "incomplete-mpu-list", has_arg = 0, flag = 0x0, val = 117}, {name = 0x48c191 "incomplete-mpu-abort", has_arg = 2, flag = 0x0, val = 97}, {name = 0x0, has_arg = 0, flag = 0x0, val = 0}} found = <optimized out> fuse_res = <optimized out> __func__ = "main" ch = <optimized out> s3fs_oper = {getattr = 0x411ba7 <s3fs_getattr(char const*, stat*)>, readlink = 0x415690 <s3fs_readlink(char const*, char*, size_t)>, getdir = 0x0, mknod = 0x41b00e <s3fs_mknod(char const*, mode_t, dev_t)>, mkdir = 0x418ff5 <s3fs_mkdir(char const*, mode_t)>, unlink = 0x40fe91 <s3fs_unlink(char const*)>, rmdir = 0x415e34 <s3fs_rmdir(char const*)>, symlink = 0x41fb7a <s3fs_symlink(char const*, char const*)>, rename = 0x41d271 <s3fs_rename(char const*, char const*)>, link = 0x4065ab <s3fs_link(char const*, char const*)>, chmod = 0x422118 <s3fs_chmod(char const*, mode_t)>, chown = 0x419264 <s3fs_chown(char const*, uid_t, gid_t)>, truncate = 0x42119c <s3fs_truncate(char const*, off_t)>, utime = 0x0, open = 0x41445d <s3fs_open(char const*, fuse_file_info*)>, read = 0x4086b6 <s3fs_read(char const*, char*, size_t, off_t, fuse_file_info*)>, write = 0x407de6 <s3fs_write(char const*, char const*, size_t, off_t, fuse_file_info*)>, statfs = 0x406060 <s3fs_statfs(char const*, statvfs*)>, flush = 0x4118e9 <s3fs_flush(char const*, fuse_file_info*)>, release = 0x407718 <s3fs_release(char const*, fuse_file_info*)>, fsync = 0x40696e <s3fs_fsync(char const*, int, fuse_file_info*)>, setxattr = 0x0, getxattr = 0x0, listxattr = 0x0, removexattr = 0x0, opendir = 0x4116ca <s3fs_opendir(char const*, fuse_file_info*)>, readdir = 0x410328 <s3fs_readdir(char const*, void*, fuse_fill_dir_t, off_t, fuse_file_info*)>, releasedir = 0x0, fsyncdir = 0x0, init = 0x4124a5 <s3fs_init(fuse_conn_info*)>, destroy = 0x406bd8 <s3fs_destroy(void*)>, access = 0x4100de <s3fs_access(char const*, int)>, create = 0x41b392 <s3fs_create(char const*, mode_t, fuse_file_info*)>, ftruncate = 0x0, fgetattr = 0x0, lock = 0x0, utimens = 0x41ed1f <s3fs_utimens(char const*, timespec const*)>, bmap = 0x0, flag_nullpath_ok = 0, flag_nopath = 0, flag_utime_omit_ok = 0, flag_reserved = 0, ioctl = 0x0, poll = 0x0, write_buf = 0x0, read_buf = 0x0, flock = 0x0, fallocate = 0x0} incomp_abort_time = 86400 singletonLog = {static NEST_MAX = 4, static nest_spaces = {0x48c078 "", 0x498542 " ", 0x498540 " ", 0x49853e " "}, static LOGFILEENV = 0x4985f2 <S3fsLog::LOGFILEENV> "S3FS_LOGFILE", static MSGTIMESTAMP = <same as static member of an already seen type>, static pSingleton = 0x7ffe383481bb, static debug_level = S3fsLog::LEVEL_DBG, static logfp = 0x0, static plogfile = 0x0, static time_stamp = true} custom_args = {argc = 5, argv = 0x17fdc80, allocated = 1} ``` **Steps to reproduce:** 1. Start s3fs 1. Copy a larger file (e.g. 3750M) ``` # cp -p 3750M /s3/ ``` 1. Wait till s3fs starts flushing 1. Do an `ll` to the mount ``` # ll /s3/ ``` 1. Repeat the `ll` command on success till it blocks Additionally I found this unexpected warning: ``` [WAN] string_util.cpp:cvt_strtoofft(96): something error is occurred in convert std::string(017080564) to off_t, thus return 0 as default. ``` **s3fs debug log:** ``` unique: 59997, opcode: WRITE (16), nodeid: 3, insize: 65616, pid: 28412 write[5] 65536 bytes to 3929145344 flags: 0x8001 2021-06-09T10:46:27.508Z [DBG] s3fs.cpp:s3fs_write(2346): [path=/3750M][size=65536][offset=3929145344][fd=5] 2021-06-09T10:46:27.508Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=5][ignore_existfd=false] 2021-06-09T10:46:27.508Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1] 2021-06-09T10:46:27.508Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=2] 2021-06-09T10:46:27.508Z [DBG] fdcache_entity.cpp:Open(336): [path=/3750M][fd=5][size=-1][time=-1] 2021-06-09T10:46:27.508Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=3] 2021-06-09T10:46:27.508Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=2] 2021-06-09T10:46:27.508Z [DBG] fdcache_entity.cpp:Write(1472): [path=/3750M][fd=5][offset=3929145344][size=65536] 2021-06-09T10:46:27.508Z [DBG] fdcache.cpp:Close(618): [ent->file=/3750M][ent->fd=5] 2021-06-09T10:46:27.508Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=1] write[5] 65536 bytes to 3929145344 unique: 59997, success, outsize: 24 unique: 59998, opcode: WRITE (16), nodeid: 3, insize: 65616, pid: 28412 write[5] 65536 bytes to 3929210880 flags: 0x8001 2021-06-09T10:46:27.508Z [DBG] s3fs.cpp:s3fs_write(2346): [path=/3750M][size=65536][offset=3929210880][fd=5] 2021-06-09T10:46:27.508Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=5][ignore_existfd=false] 2021-06-09T10:46:27.508Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1] 2021-06-09T10:46:27.508Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=2] 2021-06-09T10:46:27.508Z [DBG] fdcache_entity.cpp:Open(336): [path=/3750M][fd=5][size=-1][time=-1] 2021-06-09T10:46:27.508Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=3] 2021-06-09T10:46:27.508Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=2] 2021-06-09T10:46:27.508Z [DBG] fdcache_entity.cpp:Write(1472): [path=/3750M][fd=5][offset=3929210880][size=65536] 2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:Close(618): [ent->file=/3750M][ent->fd=5] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=1] write[5] 65536 bytes to 3929210880 unique: 59998, success, outsize: 24 unique: 59999, opcode: WRITE (16), nodeid: 3, insize: 65616, pid: 28412 write[5] 65536 bytes to 3929276416 flags: 0x8001 2021-06-09T10:46:27.509Z [DBG] s3fs.cpp:s3fs_write(2346): [path=/3750M][size=65536][offset=3929276416][fd=5] 2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=5][ignore_existfd=false] 2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=2] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Open(336): [path=/3750M][fd=5][size=-1][time=-1] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=3] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=2] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Write(1472): [path=/3750M][fd=5][offset=3929276416][size=65536] 2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:Close(618): [ent->file=/3750M][ent->fd=5] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=1] write[5] 65536 bytes to 3929276416 unique: 59999, success, outsize: 24 unique: 60000, opcode: WRITE (16), nodeid: 3, insize: 65616, pid: 28412 write[5] 65536 bytes to 3929341952 flags: 0x8001 2021-06-09T10:46:27.509Z [DBG] s3fs.cpp:s3fs_write(2346): [path=/3750M][size=65536][offset=3929341952][fd=5] 2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=5][ignore_existfd=false] 2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=2] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Open(336): [path=/3750M][fd=5][size=-1][time=-1] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=3] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=2] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Write(1472): [path=/3750M][fd=5][offset=3929341952][size=65536] 2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:Close(618): [ent->file=/3750M][ent->fd=5] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=1] write[5] 65536 bytes to 3929341952 unique: 60000, success, outsize: 24 unique: 60001, opcode: WRITE (16), nodeid: 3, insize: 65616, pid: 28412 write[5] 65536 bytes to 3929407488 flags: 0x8001 2021-06-09T10:46:27.509Z [DBG] s3fs.cpp:s3fs_write(2346): [path=/3750M][size=65536][offset=3929407488][fd=5] 2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=5][ignore_existfd=false] 2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=2] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Open(336): [path=/3750M][fd=5][size=-1][time=-1] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=3] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=2] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Write(1472): [path=/3750M][fd=5][offset=3929407488][size=65536] 2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:Close(618): [ent->file=/3750M][ent->fd=5] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=1] write[5] 65536 bytes to 3929407488 unique: 60001, success, outsize: 24 unique: 60002, opcode: WRITE (16), nodeid: 3, insize: 5756, pid: 28412 write[5] 5676 bytes to 3929473024 flags: 0x8001 2021-06-09T10:46:27.509Z [DBG] s3fs.cpp:s3fs_write(2346): [path=/3750M][size=5676][offset=3929473024][fd=5] 2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=5][ignore_existfd=false] 2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=2] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Open(336): [path=/3750M][fd=5][size=-1][time=-1] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=3] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=2] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Write(1472): [path=/3750M][fd=5][offset=3929473024][size=5676] 2021-06-09T10:46:27.509Z [DBG] fdcache.cpp:Close(618): [ent->file=/3750M][ent->fd=5] 2021-06-09T10:46:27.509Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=1] write[5] 5676 bytes to 3929473024 unique: 60002, success, outsize: 24 unique: 60003, opcode: SETATTR (4), nodeid: 3, insize: 128, pid: 28412 utimens /3750M 1623232438.035669217 1614863324.017080564 2021-06-09T10:46:27.510Z [INF] s3fs.cpp:s3fs_utimens(1977): [path=/3750M][mtime=1614863324][ctime/atime=1623232438] 2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_parent_object_access(639): [path=/3750M] 2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_object_access(533): [path=/] 2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/] 2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_object_access(533): [path=/3750M] 2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M] 2021-06-09T10:46:27.510Z [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=12621366.633215470][hit count=1] 2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M] 2021-06-09T10:46:27.510Z [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=12621366.633215470][hit count=2] 2021-06-09T10:46:27.510Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=-1][ignore_existfd=true] 2021-06-09T10:46:27.510Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1] 2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=2] 2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Open(336): [path=/3750M][fd=5][size=-1][time=-1] 2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=3] 2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=2] 2021-06-09T10:46:27.510Z [WAN] string_util.cpp:cvt_strtoofft(96): something error is occurred in convert std::string(017080564) to off_t, thus return 0 as default. 2021-06-09T10:46:27.510Z [WAN] string_util.cpp:cvt_strtoofft(96): something error is occurred in convert std::string(035669217) to off_t, thus return 0 as default. 2021-06-09T10:46:27.510Z [WAN] string_util.cpp:cvt_strtoofft(96): something error is occurred in convert std::string(035669217) to off_t, thus return 0 as default. 2021-06-09T10:46:27.510Z [INF] fdcache_entity.cpp:SetMCtime(705): [path=/3750M][fd=5][mtime=1614863324][ctime=1623232438] 2021-06-09T10:46:27.510Z [INF] fdcache_entity.cpp:SetAtime(689): [path=/3750M][fd=5][time=1623232438] 2021-06-09T10:46:27.510Z [INF] s3fs.cpp:s3fs_utimens(2039): meta pending until upload is complete 2021-06-09T10:46:27.510Z [INF] cache.cpp:UpdateMetaStats(449): update stat cache entry[path=/3750M] 2021-06-09T10:46:27.510Z [DBG] fdcache.cpp:Close(618): [ent->file=/3750M][ent->fd=5] 2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=1] getattr /3750M 2021-06-09T10:46:27.510Z [INF] s3fs.cpp:s3fs_getattr(769): [path=/3750M] 2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_parent_object_access(639): [path=/3750M] 2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_object_access(533): [path=/] 2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/] 2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_object_access(533): [path=/3750M] 2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M] 2021-06-09T10:46:27.510Z [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=12621450.629794699][hit count=3] 2021-06-09T10:46:27.510Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=-1][ignore_existfd=false] 2021-06-09T10:46:27.510Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1] 2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=2] 2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Open(336): [path=/3750M][fd=5][size=-1][time=-1] 2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=3] 2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=2] 2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:s3fs_getattr(792): [path=/3750M] uid=0, gid=0, mode=100600 2021-06-09T10:46:27.510Z [DBG] fdcache.cpp:Close(618): [ent->file=/3750M][ent->fd=5] 2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=1] unique: 60003, success, outsize: 120 unique: 60004, opcode: REMOVEXATTR (24), nodeid: 3, insize: 53, pid: 28412 unique: 60004, error: -38 (Function not implemented), outsize: 16 unique: 60005, opcode: SETXATTR (21), nodeid: 3, insize: 100, pid: 28412 unique: 60005, error: -38 (Function not implemented), outsize: 16 unique: 60006, opcode: SETATTR (4), nodeid: 3, insize: 128, pid: 28412 2021-06-09T10:46:27.510Z [INF] s3fs.cpp:s3fs_chmod(1621): [path=/3750M][mode=100644] 2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_parent_object_access(639): [path=/3750M] 2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_object_access(533): [path=/] 2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/] 2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_object_owner(607): [path=/3750M] 2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M] 2021-06-09T10:46:27.510Z [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=12621450.629794699][hit count=4] 2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M] 2021-06-09T10:46:27.510Z [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=12621450.629794699][hit count=5] 2021-06-09T10:46:27.510Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=-1][ignore_existfd=true] 2021-06-09T10:46:27.510Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1] 2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=2] 2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Open(336): [path=/3750M][fd=5][size=-1][time=-1] 2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=3] 2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=2] 2021-06-09T10:46:27.510Z [INF] fdcache_entity.cpp:SetMCtime(705): [path=/3750M][fd=5][mtime=1614863324][ctime=1623235587] 2021-06-09T10:46:27.510Z [INF] fdcache_entity.cpp:SetAtime(689): [path=/3750M][fd=5][time=1623232438] 2021-06-09T10:46:27.510Z [INF] s3fs.cpp:s3fs_chmod(1680): meta pending until upload is complete 2021-06-09T10:46:27.510Z [INF] cache.cpp:UpdateMetaStats(449): update stat cache entry[path=/3750M] 2021-06-09T10:46:27.510Z [DBG] fdcache.cpp:Close(618): [ent->file=/3750M][ent->fd=5] 2021-06-09T10:46:27.510Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=1] getattr /3750M 2021-06-09T10:46:27.510Z [INF] s3fs.cpp:s3fs_getattr(769): [path=/3750M] 2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_parent_object_access(639): [path=/3750M] 2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_object_access(533): [path=/] 2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/] 2021-06-09T10:46:27.510Z [DBG] s3fs.cpp:check_object_access(533): [path=/3750M] 2021-06-09T10:46:27.511Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M] 2021-06-09T10:46:27.511Z [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=12621450.630794706][hit count=6] 2021-06-09T10:46:27.511Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=-1][ignore_existfd=false] 2021-06-09T10:46:27.511Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1] 2021-06-09T10:46:27.511Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=2] 2021-06-09T10:46:27.511Z [DBG] fdcache_entity.cpp:Open(336): [path=/3750M][fd=5][size=-1][time=-1] 2021-06-09T10:46:27.511Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=3] 2021-06-09T10:46:27.511Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=2] 2021-06-09T10:46:27.511Z [DBG] s3fs.cpp:s3fs_getattr(792): [path=/3750M] uid=0, gid=0, mode=100600 2021-06-09T10:46:27.511Z [DBG] fdcache.cpp:Close(618): [ent->file=/3750M][ent->fd=5] 2021-06-09T10:46:27.511Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=1] unique: 60006, success, outsize: 120 unique: 60007, opcode: FLUSH (25), nodeid: 3, insize: 64, pid: 28412 flush[5] 2021-06-09T10:46:27.511Z [INF] s3fs.cpp:s3fs_flush(2394): [path=/3750M][fd=5] 2021-06-09T10:46:27.511Z [DBG] s3fs.cpp:check_parent_object_access(639): [path=/3750M] 2021-06-09T10:46:27.511Z [DBG] s3fs.cpp:check_object_access(533): [path=/] 2021-06-09T10:46:27.511Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/] 2021-06-09T10:46:27.511Z [DBG] s3fs.cpp:check_object_access(533): [path=/3750M] 2021-06-09T10:46:27.511Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M] 2021-06-09T10:46:27.511Z [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=12621450.630794706][hit count=7] 2021-06-09T10:46:27.511Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=5][ignore_existfd=false] 2021-06-09T10:46:27.511Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1] 2021-06-09T10:46:27.511Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=2] 2021-06-09T10:46:27.511Z [DBG] fdcache_entity.cpp:Open(336): [path=/3750M][fd=5][size=-1][time=-1] 2021-06-09T10:46:27.511Z [DBG] fdcache_entity.cpp:Dup(267): [path=/3750M][fd=5][refcnt=3] 2021-06-09T10:46:27.511Z [DBG] fdcache_entity.cpp:Close(221): [path=/3750M][fd=5][refcnt=2] 2021-06-09T10:46:27.511Z [INF] fdcache_entity.cpp:RowFlush(1216): [tpath=][path=/3750M][fd=5] 2021-06-09T10:46:27.511Z [INF] curl.cpp:MultipartUploadRequest(4050): [upload_id=DutCg2tkhG_6i4hcWtJqIpA1IEM1jPsfpijrPCPzK4gv8lfUhaGrEqxNqw][tpath=/3750M][fd=5][offset=3928752128][size=726572] 2021-06-09T10:46:27.511Z [INF] curl.cpp:UploadMultipartPostRequest(3786): [tpath=/3750M][start=3928752128][size=726572][part=376] 2021-06-09T10:46:27.511Z [INF] curl.cpp:UploadMultipartPostSetup(3727): [tpath=/3750M][start=3928752128][size=726572][part=376] 2021-06-09T10:46:27.511Z [INF] curl_util.cpp:prepare_url(254): URL is http://mys3service:8088/mybucket/3750M?partNumber=376&uploadId=DutCg2tkhG_6i4hcWtJqIpA1IEM1jPsfpijrPCPzK4gv8lfUhaGrEqxNqw 2021-06-09T10:46:27.511Z [INF] curl_util.cpp:prepare_url(287): URL changed is http://mys3service:8088/mybucket/3750M?partNumber=376&uploadId=DutCg2tkhG_6i4hcWtJqIpA1IEM1jPsfpijrPCPzK4gv8lfUhaGrEqxNqw 2021-06-09T10:46:27.511Z [DBG] curl_handlerpool.cpp:GetHandler(81): Get handler from pool: rest = 30 2021-06-09T10:46:27.511Z [DBG] curl.cpp:RequestPerform(2281): connecting to URL http://mys3service:8088/mybucket/3750M?partNumber=376&uploadId=DutCg2tkhG_6i4hcWtJqIpA1IEM1jPsfpijrPCPzK4gv8lfUhaGrEqxNqw 2021-06-09T10:46:27.514Z [INF] curl.cpp:insertV4Headers(2673): computing signature [PUT] [/3750M] [partNumber=376&uploadId=DutCg2tkhG_6i4hcWtJqIpA1IEM1jPsfpijrPCPzK4gv8lfUhaGrEqxNqw] [1a282c6abc7bb6c2567e2a8027bf5325cd1eef9e65eb218dab1d58cfdde6bd83] 2021-06-09T10:46:27.514Z [INF] curl_util.cpp:url_to_host(331): url is http://mys3service:8088 2021-06-09T10:46:27.515Z [CURL DBG] * Found bundle for host mys3service: 0x7f95ac018ba0 2021-06-09T10:46:27.515Z [CURL DBG] * Re-using existing connection! (#0) with host mys3service 2021-06-09T10:46:27.515Z [CURL DBG] * Connected to mys3service (172.20.10.152) port 8088 (#0) 2021-06-09T10:46:27.515Z [CURL DBG] > PUT /mybucket/3750M?partNumber=376&uploadId=DutCg2tkhG_6i4hcWtJqIpA1IEM1jPsfpijrPCPzK4gv8lfUhaGrEqxNqw HTTP/1.1 2021-06-09T10:46:27.515Z [CURL DBG] > User-Agent: s3fs/1.89 (commit hash 8c58ba8; OpenSSL) 2021-06-09T10:46:27.515Z [CURL DBG] > Authorization: AWS4-HMAC-SHA256 Credential=NHTL282ERGST9B40156H/20210609/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=3b5115c339a450de850bd0b010caa524dbeca01af768c2e5b144cf6eb8077c37 2021-06-09T10:46:27.515Z [CURL DBG] > host: mys3service:8088 2021-06-09T10:46:27.515Z [CURL DBG] > x-amz-content-sha256: 1a282c6abc7bb6c2567e2a8027bf5325cd1eef9e65eb218dab1d58cfdde6bd83 2021-06-09T10:46:27.515Z [CURL DBG] > x-amz-date: 20210609T104627Z 2021-06-09T10:46:27.515Z [CURL DBG] > Content-Length: 726572 2021-06-09T10:46:27.515Z [CURL DBG] > Expect: 100-continue 2021-06-09T10:46:27.515Z [CURL DBG] > 2021-06-09T10:46:27.516Z [CURL DBG] < HTTP/1.1 100 Continue 2021-06-09T10:46:27.517Z [CURL DBG] * We are completely uploaded and fine 2021-06-09T10:46:27.529Z [CURL DBG] < HTTP/1.1 200 OK 2021-06-09T10:46:27.529Z [CURL DBG] < Date: Wed, 09 Jun 2021 10:46:27 GMT 2021-06-09T10:46:27.529Z [CURL DBG] < Connection: KEEP-ALIVE 2021-06-09T10:46:27.529Z [CURL DBG] < Server: StorageGRID/11.4.0.4 2021-06-09T10:46:27.529Z [CURL DBG] < x-amz-request-id: 1623235468181679 2021-06-09T10:46:27.529Z [CURL DBG] < x-amz-id-2: 12616688 2021-06-09T10:46:27.529Z [CURL DBG] < Content-Length: 0 2021-06-09T10:46:27.529Z [CURL DBG] < ETag: "a330ae562039ce296666415469ff641b" 2021-06-09T10:46:27.529Z [CURL DBG] < 2021-06-09T10:46:27.529Z [CURL DBG] * Connection #0 to host mys3service left intact 2021-06-09T10:46:27.529Z [INF] curl.cpp:RequestPerform(2314): HTTP response code 200 2021-06-09T10:46:27.529Z [DBG] curl_handlerpool.cpp:ReturnHandler(103): Return handler to pool 2021-06-09T10:46:27.529Z [INF] curl.cpp:CompleteMultipartPostRequest(3565): [tpath=/3750M][parts=376] 2021-06-09T10:46:27.530Z [DBG] curl_handlerpool.cpp:GetHandler(81): Get handler from pool: rest = 30 2021-06-09T10:46:27.530Z [INF] curl_util.cpp:prepare_url(254): URL is http://mys3service:8088/mybucket/3750M?uploadId=DutCg2tkhG_6i4hcWtJqIpA1IEM1jPsfpijrPCPzK4gv8lfUhaGrEqxNqw 2021-06-09T10:46:27.530Z [INF] curl_util.cpp:prepare_url(287): URL changed is http://mys3service:8088/mybucket/3750M?uploadId=DutCg2tkhG_6i4hcWtJqIpA1IEM1jPsfpijrPCPzK4gv8lfUhaGrEqxNqw 2021-06-09T10:46:27.530Z [DBG] curl.cpp:RequestPerform(2281): connecting to URL http://mys3service:8088/mybucket/3750M?uploadId=DutCg2tkhG_6i4hcWtJqIpA1IEM1jPsfpijrPCPzK4gv8lfUhaGrEqxNqw 2021-06-09T10:46:27.530Z [INF] curl.cpp:insertV4Headers(2673): computing signature [POST] [/3750M] [uploadId=DutCg2tkhG_6i4hcWtJqIpA1IEM1jPsfpijrPCPzK4gv8lfUhaGrEqxNqw] [3f6ad2a1569a5efe986bd88c849194fe6bee8f0162bb41ad232adce4522349c6] 2021-06-09T10:46:27.530Z [INF] curl_util.cpp:url_to_host(331): url is http://mys3service:8088 2021-06-09T10:46:27.530Z [CURL DBG] * Found bundle for host mys3service: 0x7f95ac018ba0 2021-06-09T10:46:27.530Z [CURL DBG] * Re-using existing connection! (#0) with host mys3service 2021-06-09T10:46:27.530Z [CURL DBG] * Connected to mys3service (172.20.10.152) port 8088 (#0) 2021-06-09T10:46:27.530Z [CURL DBG] > POST /mybucket/3750M?uploadId=DutCg2tkhG_6i4hcWtJqIpA1IEM1jPsfpijrPCPzK4gv8lfUhaGrEqxNqw HTTP/1.1 2021-06-09T10:46:27.530Z [CURL DBG] > User-Agent: s3fs/1.89 (commit hash 8c58ba8; OpenSSL) 2021-06-09T10:46:27.530Z [CURL DBG] > Authorization: AWS4-HMAC-SHA256 Credential=NHTL282ERGST9B40156H/20210609/us-east-1/s3/aws4_request, SignedHeaders=content-type;host;x-amz-content-sha256;x-amz-date, Signature=22a76ebc6d5d8037fe9e66543b0f1ebaa2b5505268f6fdbc29e06d74dcf69e4a 2021-06-09T10:46:27.530Z [CURL DBG] > Content-Type: application/xml 2021-06-09T10:46:27.530Z [CURL DBG] > host: mys3service:8088 2021-06-09T10:46:27.530Z [CURL DBG] > x-amz-content-sha256: 3f6ad2a1569a5efe986bd88c849194fe6bee8f0162bb41ad232adce4522349c6 2021-06-09T10:46:27.530Z [CURL DBG] > x-amz-date: 20210609T104627Z 2021-06-09T10:46:27.530Z [CURL DBG] > Content-Length: 36041 2021-06-09T10:46:27.530Z [CURL DBG] > Expect: 100-continue 2021-06-09T10:46:27.530Z [CURL DBG] > 2021-06-09T10:46:27.531Z [CURL DBG] < HTTP/1.1 100 Continue 2021-06-09T10:46:27.545Z [CURL DBG] < HTTP/1.1 200 OK 2021-06-09T10:46:27.546Z [CURL DBG] < Date: Wed, 09 Jun 2021 10:46:27 GMT 2021-06-09T10:46:27.546Z [CURL DBG] < Connection: CLOSE 2021-06-09T10:46:27.546Z [CURL DBG] < Server: StorageGRID/11.4.0.4 2021-06-09T10:46:27.546Z [CURL DBG] < x-amz-request-id: 1623235468181679 2021-06-09T10:46:27.546Z [CURL DBG] < x-amz-id-2: 12616688 2021-06-09T10:46:27.546Z [CURL DBG] < Content-Type: application/xml 2021-06-09T10:46:27.546Z [CURL DBG] < 2021-06-09T10:46:31.208Z [CURL DBG] * Closing connection 0 2021-06-09T10:46:31.208Z [INF] curl.cpp:RequestPerform(2314): HTTP response code 200 2021-06-09T10:46:31.208Z [DBG] curl_handlerpool.cpp:ReturnHandler(103): Return handler to pool unique: 60008, opcode: GETATTR (3), nodeid: 1, insize: 56, pid: 28495 getattr / 2021-06-09T10:46:37.497Z [INF] s3fs.cpp:s3fs_getattr(769): [path=/] 2021-06-09T10:46:37.497Z [DBG] s3fs.cpp:check_parent_object_access(639): [path=/] 2021-06-09T10:46:37.497Z [DBG] s3fs.cpp:check_object_access(533): [path=/] 2021-06-09T10:46:37.497Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/] 2021-06-09T10:46:37.497Z [DBG] fdcache.cpp:ExistOpen(551): [path=/][fd=-1][ignore_existfd=false] 2021-06-09T10:46:37.497Z [DBG] fdcache.cpp:Open(468): [path=/][size=-1][time=-1] 2021-06-09T10:46:37.497Z [DBG] s3fs.cpp:s3fs_getattr(792): [path=/] uid=0, gid=0, mode=40700 unique: 60008, success, outsize: 120 unique: 60009, opcode: OPENDIR (27), nodeid: 1, insize: 48, pid: 28495 opendir flags: 0x18800 / 2021-06-09T10:46:37.497Z [INF] s3fs.cpp:s3fs_opendir(2507): [path=/][flags=0x18800] 2021-06-09T10:46:37.497Z [DBG] s3fs.cpp:check_object_access(533): [path=/] 2021-06-09T10:46:37.497Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/] 2021-06-09T10:46:37.497Z [DBG] s3fs.cpp:check_parent_object_access(639): [path=/] opendir[0] flags: 0x18800 / unique: 60009, success, outsize: 32 unique: 60010, opcode: READDIR (28), nodeid: 1, insize: 80, pid: 28495 readdir[0] from 0 2021-06-09T10:46:37.498Z [INF] s3fs.cpp:s3fs_readdir(2656): [path=/] 2021-06-09T10:46:37.498Z [DBG] s3fs.cpp:check_object_access(533): [path=/] 2021-06-09T10:46:37.498Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/] 2021-06-09T10:46:37.498Z [INF] s3fs.cpp:list_bucket(2700): [path=/] 2021-06-09T10:46:37.498Z [INF] curl.cpp:ListBucketRequest(3416): [tpath=/] 2021-06-09T10:46:37.498Z [DBG] curl_handlerpool.cpp:GetHandler(81): Get handler from pool: rest = 30 2021-06-09T10:46:37.498Z [INF] curl_util.cpp:prepare_url(254): URL is http://mys3service:8088/mybucket?delimiter=/&max-keys=1000&prefix= 2021-06-09T10:46:37.498Z [INF] curl_util.cpp:prepare_url(287): URL changed is http://mys3service:8088/mybucket/?delimiter=/&max-keys=1000&prefix= 2021-06-09T10:46:37.498Z [DBG] curl.cpp:RequestPerform(2281): connecting to URL http://mys3service:8088/mybucket/?delimiter=/&max-keys=1000&prefix= 2021-06-09T10:46:37.498Z [INF] curl.cpp:insertV4Headers(2673): computing signature [GET] [/] [delimiter=/&max-keys=1000&prefix=] [] 2021-06-09T10:46:37.498Z [INF] curl_util.cpp:url_to_host(331): url is http://mys3service:8088 2021-06-09T10:46:37.498Z [CURL DBG] * About to connect() to mys3service port 8088 (#2) 2021-06-09T10:46:37.498Z [CURL DBG] * Trying 172.20.10.152... 2021-06-09T10:46:37.499Z [CURL DBG] * Connected to mys3service (172.20.10.152) port 8088 (#2) 2021-06-09T10:46:37.499Z [CURL DBG] > GET /mybucket/?delimiter=/&max-keys=1000&prefix= HTTP/1.1 2021-06-09T10:46:37.499Z [CURL DBG] > User-Agent: s3fs/1.89 (commit hash 8c58ba8; OpenSSL) 2021-06-09T10:46:37.499Z [CURL DBG] > Accept: */* 2021-06-09T10:46:37.499Z [CURL DBG] > Authorization: AWS4-HMAC-SHA256 Credential=NHTL282ERGST9B40156H/20210609/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=cb2dcd404a2e11a70e1fd1de22b54f32306627f6f15f9be06390f585c0f5d6ec 2021-06-09T10:46:37.499Z [CURL DBG] > host: mys3service:8088 2021-06-09T10:46:37.499Z [CURL DBG] > x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 2021-06-09T10:46:37.499Z [CURL DBG] > x-amz-date: 20210609T104637Z 2021-06-09T10:46:37.499Z [CURL DBG] > 2021-06-09T10:46:38.610Z [CURL DBG] < HTTP/1.1 200 OK 2021-06-09T10:46:38.610Z [CURL DBG] < Date: Wed, 09 Jun 2021 10:46:38 GMT 2021-06-09T10:46:38.610Z [CURL DBG] < Connection: KEEP-ALIVE 2021-06-09T10:46:38.610Z [CURL DBG] < Server: StorageGRID/11.4.0.4 2021-06-09T10:46:38.610Z [CURL DBG] < x-amz-request-id: 1623235597503520 2021-06-09T10:46:38.610Z [CURL DBG] < x-amz-id-2: 12700546 2021-06-09T10:46:38.610Z [CURL DBG] < Content-Length: 587 2021-06-09T10:46:38.610Z [CURL DBG] < Content-Type: application/xml 2021-06-09T10:46:38.610Z [CURL DBG] < 2021-06-09T10:46:38.610Z [CURL DBG] * Connection #2 to host mys3service left intact 2021-06-09T10:46:38.611Z [INF] curl.cpp:RequestPerform(2314): HTTP response code 200 2021-06-09T10:46:38.611Z [DBG] s3fs_xml.cpp:append_objects_from_xml_ex(331): contents_xp->nodesetval is empty. 2021-06-09T10:46:38.611Z [DBG] curl_handlerpool.cpp:ReturnHandler(103): Return handler to pool 2021-06-09T10:46:38.611Z [INF] s3fs.cpp:readdir_multi_head(2572): [path=/][list=0] 2021-06-09T10:46:38.611Z [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=12621450.630794706][hit count=8] 2021-06-09T10:46:38.611Z [INF] curl_multi.cpp:Request(297): [count=0] 2021-06-09T10:46:38.611Z [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=12621450.630794706][hit count=9] unique: 60010, success, outsize: 112 unique: 60011, opcode: LOOKUP (1), nodeid: 1, insize: 46, pid: 28495 LOOKUP /3750M getattr /3750M 2021-06-09T10:46:38.611Z [INF] s3fs.cpp:s3fs_getattr(769): [path=/3750M] 2021-06-09T10:46:38.611Z [DBG] s3fs.cpp:check_parent_object_access(639): [path=/3750M] 2021-06-09T10:46:38.611Z [DBG] s3fs.cpp:check_object_access(533): [path=/] 2021-06-09T10:46:38.611Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/] 2021-06-09T10:46:38.611Z [DBG] s3fs.cpp:check_object_access(533): [path=/3750M] 2021-06-09T10:46:38.611Z [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M] 2021-06-09T10:46:38.611Z [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=12621450.630794706][hit count=10] 2021-06-09T10:46:38.611Z [DBG] fdcache.cpp:ExistOpen(551): [path=/3750M][fd=-1][ignore_existfd=false] 2021-06-09T10:46:38.611Z [DBG] fdcache.cpp:Open(468): [path=/3750M][size=-1][time=-1] ```
kerem closed this issue 2026-03-04 01:49:33 +03:00
kerem commented 2026-03-04 01:49:34 +03:00
Author
Owner
Copy link

@gaul commented on GitHub (Jun 13, 2021):

When you say deadlock do you mean that one of the requests never makes progress or it makes progress after the other operation completes? If it is the former, you make want to build s3fs using ThreadSanitizer which gives rich error information about these situations:

./configure CXX=clang++ CXXFLAGS="$COMMON_FLAGS -fsanitize=thread"
make
TSAN_OPTIONS='halt_on_error=1' s3fs ...

You can also try to git bisect to find the offending commit although I strongly suspect that 84174c560d caused this regression.

<!-- gh-comment-id:860213254 --> @gaul commented on GitHub (Jun 13, 2021): When you say deadlock do you mean that one of the requests never makes progress or it makes progress after the other operation completes? If it is the former, you make want to build s3fs using ThreadSanitizer which gives rich error information about these situations: ``` ./configure CXX=clang++ CXXFLAGS="$COMMON_FLAGS -fsanitize=thread" make TSAN_OPTIONS='halt_on_error=1' s3fs ... ``` You can also try to `git bisect` to find the offending commit although I strongly suspect that 84174c560d7542436067dfbfe1f697368ad7d4a1 caused this regression.
kerem commented 2026-03-04 01:49:34 +03:00
Author
Owner
Copy link

@CarstenGrohmann commented on GitHub (Jun 15, 2021):

Both requests bring no progress. Finally, I stopped s3fs with SIGKILL because I could not terminate either process (cp & ls).

Today I could not reproduce the problem manually or by script. So I'll close this ticket for now and reopen it when I have more useful information such as the ThreadSanitizer output.

<!-- gh-comment-id:861765517 --> @CarstenGrohmann commented on GitHub (Jun 15, 2021): Both requests bring no progress. Finally, I stopped s3fs with SIGKILL because I could not terminate either process (cp & ls). Today I could not reproduce the problem manually or by script. So I'll close this ticket for now and reopen it when I have more useful information such as the ThreadSanitizer output.
kerem commented 2026-03-04 01:49:34 +03:00
Author
Owner
Copy link

@gaul commented on GitHub (Jun 16, 2021):

I merged 4d39ea887e which fixed a locking regression although this should not manifest as deadlock. One of the most effective tools for diagnosing threading issues is ThreadSanitizer. You can see how to compile with it in run_tests_using_sanitizers.sh. This script is only as effective as the tests we have so manual testing could uncover other racy code paths.

<!-- gh-comment-id:862208961 --> @gaul commented on GitHub (Jun 16, 2021): I merged 4d39ea887e779fe23799d048aa423dc9bc29867b which fixed a locking regression although this should not manifest as deadlock. One of the most effective tools for diagnosing threading issues is ThreadSanitizer. You can see how to compile with it in [run_tests_using_sanitizers.sh](https://github.com/s3fs-fuse/s3fs-fuse/blob/master/test/run_tests_using_sanitizers.sh). This script is only as effective as the tests we have so manual testing could uncover other racy code paths.
kerem commented 2026-03-04 01:49:34 +03:00
Author
Owner
Copy link

@ggtakec commented on GitHub (Jun 16, 2021):

@CarstenGrohmann Thank you for your kindness, sorry for the reply was late.
The most recent code change may have been the impact of #1666 for this issue.
If you find a similar Deadlock in the future, please reopen this.

<!-- gh-comment-id:862408730 --> @ggtakec commented on GitHub (Jun 16, 2021): @CarstenGrohmann Thank you for your kindness, sorry for the reply was late. The most recent code change may have been the impact of #1666 for this issue. If you find a similar Deadlock in the future, please reopen this.
Sign in to join this conversation.
No Branch/Tag specified
Branches Tags
master
v1.97
v1.96
v1.95
v1.94
v1.93
v1.92
v1.91
v1.90
v1.89
v1.88
v1.87
v1.86
v1.85
v1.84
v1.83
v1.82
v1.81
v1.80
v1.79
v1.78
Pre-v1.78
v1.77
v1.76
v1.75
v1.74
Labels
Clear labels   
bug

   
bug

   
dataloss

   
duplicate

   
enhancement

   
feature request

   
help wanted

   
invalid

   
need info

   
performance

   
pull-request

Mirrored from GitHub Pull Request

  
question

   
question

   
testing
No labels
bug
bug
dataloss
duplicate
enhancement
feature request
help wanted
invalid
need info
performance
pull-request
question
question
testing
Milestone
Clear milestone
No items
No milestone
Projects
Clear projects
No items
No project
Assignees
Clear assignees
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference
starred/s3fs-fuse#872
No description provided.