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

[GH-ISSUE #1685] Parallel Multipart Upload failed because of Content Length 0 #875

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

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

I've a simple copy job. The cp command reports an IO error for setting timestamps. The file content is correct.

When I follow the log entries, I see that setting the timestamps triggers a multipart upload. This upload fails. In doing so cp reports preserving times for "/s3mnt/3750M": Input/output error.

But at the end, the flush command also triggers a multipart upload and this second upload is successful.

The difference between the two multipart uploads is: the first upload uses the x-amz-copy-source-range header but does not provide any content (Content-Length: 0) and the second upload does not use x-amz-copy-source-range but the correct Content-Length:.

Additionally, I wonder why the final multipart upload does not set the correct times in the initial post request as shown in step 7?

Steps to reproduce:

  1. Start s3fs

    ./s3fs mybucket /s3mnt -o url=http://mys3service:8088,use_path_request_style,notsup_compat_dir,enable_noobj_cache,curldbg,dbglevel=debug -d -d -f -o tmpdir=/extradisk/tmp/

  2. Copy a larger file

    # cp -p /extradisk/3750M /s3mnt/
cp: overwrite "/s3mnt/3750M"? y
cp: preserving times for "/s3mnt/3750M": Input/output error

  3. Content is correct but the timestamp is wrong

    # ll /extradisk/3750M /s3mnt/3750M
-rw-r--r-- 1 root root 3929478700 Jun 16 14:57 /s3mnt/3750M
-rw-r--r-- 1 root root 3929478700 Mar  4 14:08 /extradisk/3750M

# md5sum /s3mnt/3750M /extradisk/3750M
23cff1bf6eabb1a7743a35d8d91699ed  /s3mnt/3750M
23cff1bf6eabb1a7743a35d8d91699ed  /extradisk/3750M

Detailed analysis:

  1. file has fully written to the temporary file

    419966 unique: 59966, opcode: WRITE (16), nodeid: 2, insize: 65616, pid: 6790
419967 write[2] 65536 bytes to 3929341952 flags: 0x8001
419968 2021-06-17T09:30:46.300Z (pid: 6774) [DBG] s3fs.cpp:s3fs_write(2343): [path=/3750M][size=65536][offset=3929341952][fd=2]
419969 2021-06-17T09:30:46.300Z (pid: 6774) [DBG] fdcache.cpp:GetExistFdEntity(593): [path=/3750M][existfd=2]
419970 2021-06-17T09:30:46.300Z (pid: 6774) [DBG] fdcache_entity.cpp:Write(1594): [path=/3750M][pseudo_fd=2][physical_fd=5][offset=3929341952][size=65536]
419971    write[2] 65536 bytes to 3929341952
419972    unique: 59966, success, outsize: 24
419973 unique: 59967, opcode: WRITE (16), nodeid: 2, insize: 65616, pid: 6790
419974 write[2] 65536 bytes to 3929407488 flags: 0x8001
419975 2021-06-17T09:30:46.300Z (pid: 6772) [DBG] s3fs.cpp:s3fs_write(2343): [path=/3750M][size=65536][offset=3929407488][fd=2]
419976 2021-06-17T09:30:46.300Z (pid: 6772) [DBG] fdcache.cpp:GetExistFdEntity(593): [path=/3750M][existfd=2]
419977 2021-06-17T09:30:46.300Z (pid: 6772) [DBG] fdcache_entity.cpp:Write(1594): [path=/3750M][pseudo_fd=2][physical_fd=5][offset=3929407488][size=65536]
419978    write[2] 65536 bytes to 3929407488
419979    unique: 59967, success, outsize: 24
419980 unique: 59968, opcode: WRITE (16), nodeid: 2, insize: 5756, pid: 6790
419981 write[2] 5676 bytes to 3929473024 flags: 0x8001
419982 2021-06-17T09:30:46.300Z (pid: 6774) [DBG] s3fs.cpp:s3fs_write(2343): [path=/3750M][size=5676][offset=3929473024][fd=2]
419983 2021-06-17T09:30:46.300Z (pid: 6774) [DBG] fdcache.cpp:GetExistFdEntity(593): [path=/3750M][existfd=2]
419984 2021-06-17T09:30:46.300Z (pid: 6774) [DBG] fdcache_entity.cpp:Write(1594): [path=/3750M][pseudo_fd=2][physical_fd=5][offset=3929473024][size=5676]
419985    write[2] 5676 bytes to 3929473024
419986    unique: 59968, success, outsize: 24

  2. timestamps will be set:

    419987 unique: 59969, opcode: SETATTR (4), nodeid: 2, insize: 128, pid: 6790
419988 utimens /3750M 1623848254.482895965 1614863324.017080564
419989 2021-06-17T09:30:46.301Z (pid: 6772) [INF] s3fs.cpp:s3fs_utimens(1982): [path=/3750M][mtime=1614863324][ctime/atime=1623848254]

  3. this triggers a multipart upload

    419990 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] s3fs.cpp:check_parent_object_access(639): [path=/3750M]
419991 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] s3fs.cpp:check_object_access(533): [path=/]
419992 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] s3fs.cpp:get_object_attribute(364): [path=/]
419993 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] s3fs.cpp:check_object_access(533): [path=/3750M]
419994 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M]
419995 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=566048.219264420][hit count=3]
419996 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M]
419997 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=566048.219264420][hit count=4]
419998 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] fdcache.cpp:OpenExistFdEntiy(610): [path=/3750M][flags=0x0]
419999 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] fdcache.cpp:Open(508): [path=/3750M][size=-1][time=-1][flags=0x0]
420000 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] fdcache_entity.cpp:Open(413): [path=/3750M][physical_fd=5][size=-1][time=-1][flags=0x0]
420001 2021-06-17T09:30:46.301Z (pid: 6772) [INF]       fdcache_entity.cpp:SetMCtime(780): [path=/3750M][physical_fd=5][mtime=1614863324][ctime=1623848254]
420002 2021-06-17T09:30:46.301Z (pid: 6772) [INF]       fdcache_entity.cpp:SetAtime(764): [path=/3750M][physical_fd=5][time=1623848254]
420003 2021-06-17T09:30:46.301Z (pid: 6772) [INF] s3fs.cpp:s3fs_utimens(2052): meta is not pending, but need to keep current mtime.
420004 2021-06-17T09:30:46.301Z (pid: 6772) [INF]     s3fs.cpp:put_headers(745): [path=/3750M]
420005 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M]
420006 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=566048.219264420][hit count=5]
420007 2021-06-17T09:30:46.301Z (pid: 6772) [INF]       curl.cpp:MultipartHeadRequest(3921): [tpath=/3750M]
420008 2021-06-17T09:30:46.301Z (pid: 6772) [INF]       curl.cpp:PreMultipartPostRequest(3458): [tpath=/3750M]
420009 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] curl_handlerpool.cpp:GetHandler(81): Get handler from pool: rest = 30
420010 2021-06-17T09:30:46.301Z (pid: 6772) [INF]       curl_util.cpp:prepare_url(254): URL is http://mys3service:8088/mybucket/3750M?uploads
420011 2021-06-17T09:30:46.301Z (pid: 6772) [INF]       curl_util.cpp:prepare_url(287): URL changed is http://mys3service:8088/mybucket/3750M?uploads
420012 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] curl.cpp:RequestPerform(2274): connecting to URL http://mys3service:8088/mybucket/3750M?uploads
420013 2021-06-17T09:30:46.301Z (pid: 6772) [INF]       curl.cpp:insertV4Headers(2666): computing signature [POST] [/3750M] [uploads] []
420014 2021-06-17T09:30:46.301Z (pid: 6772) [INF]       curl_util.cpp:url_to_host(331): url is http://mys3service:8088
420015 2021-06-17T09:30:46.301Z (pid: 6772) [CURL DBG]* Found bundle for host mys3service: 0x7f0320018ba0
420016 2021-06-17T09:30:46.301Z (pid: 6772) [CURL DBG]* Re-using existing connection! (#0) with host mys3service
420017 2021-06-17T09:30:46.301Z (pid: 6772) [CURL DBG]* Connected to mys3service (172.20.10.152) port 8088 (#0)
420018 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> POST /mybucket/3750M?uploads HTTP/1.1
420019 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> User-Agent: s3fs/1.89 (commit hash c2c56d0; OpenSSL)
420020 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> Authorization: AWS4-HMAC-SHA256 Credential=NHTL282ERGST9B40156H/20210617/us-east-1/s3/aws4_request, SignedHeaders=content-type;host;x-amz-content-sha256;x-amz-date;x-amz-meta-atime;x-amz-meta-ctime;x-amz-meta-gid;x-amz-meta-mode;x-amz-meta-mtime;x-amz-meta-uid;x-amz-metadata-directive, Signature=703c0dadfd6af342d6883b3f50bea1b72cb91d2b6906a253a7f2543a28391114
420021 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> Content-Type: application/octet-stream
420022 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> host: mys3service:8088
420023 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
420024 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> x-amz-date: 20210617T093046Z
420025 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> x-amz-meta-atime: 1623848254.482895965
420026 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> x-amz-meta-ctime: 1623848254.482895965
420027 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> x-amz-meta-gid: 0
420028 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> x-amz-meta-mode: 33188
420029 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> x-amz-meta-mtime: 1614863324.017080564
420030 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> x-amz-meta-uid: 0
420031 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> x-amz-metadata-directive: REPLACE
420032 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]>
420033 2021-06-17T09:30:46.307Z (pid: 6772) [CURL DBG]< HTTP/1.1 200 OK
420034 2021-06-17T09:30:46.307Z (pid: 6772) [CURL DBG]< Date: Thu, 17 Jun 2021 09:30:46 GMT
420035 2021-06-17T09:30:46.307Z (pid: 6772) [CURL DBG]< Connection: KEEP-ALIVE
420036 2021-06-17T09:30:46.307Z (pid: 6772) [CURL DBG]< Server: StorageGRID/11.4.0.4
420037 2021-06-17T09:30:46.307Z (pid: 6772) [CURL DBG]< x-amz-request-id: 1623922217136394
420038 2021-06-17T09:30:46.307Z (pid: 6772) [CURL DBG]< x-amz-id-2: 12293711
420039 2021-06-17T09:30:46.307Z (pid: 6772) [CURL DBG]< Content-Length: 311
420040 2021-06-17T09:30:46.307Z (pid: 6772) [CURL DBG]< Content-Type: application/xml
420041 2021-06-17T09:30:46.307Z (pid: 6772) [CURL DBG]<
420042 2021-06-17T09:30:46.307Z (pid: 6772) [CURL DBG]* Connection #0 to host mys3service left intact

  4. Uploading part 1 is failing because of Content-Length: 0

    420078 2021-06-17T09:30:46.308Z (pid: 6806) [DBG] curl_handlerpool.cpp:GetHandler(81): Get handler from pool: rest = 30
420079 2021-06-17T09:30:46.308Z (pid: 6806) [DBG] curl.cpp:RequestPerform(2274): connecting to URL http://mys3service:8088/mybucket/3750M?partNumber=1&uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4bjkWiZ9XXOkpYq6roSxAyA
420080 2021-06-17T09:30:46.308Z (pid: 6806) [INF]       curl.cpp:insertV4Headers(2666): computing signature [PUT] [/3750M] [partNumber=1&uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4bjkWiZ9XXOkpYq6roSxAyA] []
420081 2021-06-17T09:30:46.308Z (pid: 6806) [INF]       curl_util.cpp:url_to_host(331): url is http://mys3service:8088
420089 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]* Found bundle for host mys3service: 0x7f0320018ba0
420091 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]* Re-using existing connection! (#0) with host mys3service
420092 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]* Connected to mys3service (172.20.10.152) port 8088 (#0)
420101 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> PUT /mybucket/3750M?partNumber=1&uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4bjkWiZ9XXOkpYq6roSxAyA HTTP/1.1
420102 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> User-Agent: s3fs/1.89 (commit hash c2c56d0; OpenSSL)
420105 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> Accept: */*
420106 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> Authorization: AWS4-HMAC-SHA256 Credential=NHTL282ERGST9B40156H/20210617/us-east-1/s3/aws4_request, SignedHeaders=content-type;host;x-amz-content-sha256;x-amz-copy-source;x-amz-copy-source-range;x-amz-date, Signature=c9938f1e27e7c6f1f9e634492ef39ea5b032cf2b31ed96c925936741ad2a5aec
420107 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> Content-Type: application/octet-stream
420108 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> host: mys3service:8088
420109 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
420110 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> x-amz-copy-source: /mybucket/3750M
420111 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> x-amz-copy-source-range: bytes=0-536870911
420112 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> x-amz-date: 20210617T093046Z
420113 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> Content-Length: 0
420114 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> Expect: 100-continue
420115 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]>
420178 2021-06-17T09:30:46.310Z (pid: 6806) [CURL DBG]< HTTP/1.1 100 Continue
420179 2021-06-17T09:30:46.313Z (pid: 6806) [CURL DBG]< HTTP/1.1 416 Requested Range Not Satisfiable
420180 2021-06-17T09:30:46.313Z (pid: 6806) [CURL DBG]< Date: Thu, 17 Jun 2021 09:30:46 GMT
420181 2021-06-17T09:30:46.313Z (pid: 6806) [CURL DBG]< Connection: CLOSE
420182 2021-06-17T09:30:46.313Z (pid: 6806) [CURL DBG]< Server: StorageGRID/11.4.0.4
420183 2021-06-17T09:30:46.313Z (pid: 6806) [CURL DBG]< x-amz-request-id: 1623922217136394
420184 2021-06-17T09:30:46.313Z (pid: 6806) [CURL DBG]< x-amz-id-2: 12293711
420185 2021-06-17T09:30:46.313Z (pid: 6806) [CURL DBG]< Content-Length: 328
420186 2021-06-17T09:30:46.313Z (pid: 6806) [CURL DBG]< Content-Type: application/xml
420187 2021-06-17T09:30:46.313Z (pid: 6806) [CURL DBG]<
420188 2021-06-17T09:30:46.313Z (pid: 6806) [CURL DBG]* Closing connection 0
420189 2021-06-17T09:30:46.313Z (pid: 6806) [INF]       curl.cpp:RequestPerform(2362): HTTP response code 416 was returned, returning EIO
420190 2021-06-17T09:30:46.314Z (pid: 6806) [DBG] curl_handlerpool.cpp:ReturnHandler(103): Return handler to pool

  5. This repeats for part 1 to 8 serveral times till the upload will be cleaned upload

    421905 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiPerform(169): thread terminated with a non-zero return code: -5
421906 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiPerform(169): thread terminated with a non-zero return code: -5
421907 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiPerform(169): thread terminated with a non-zero return code: -5
421908 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiPerform(169): thread terminated with a non-zero return code: -5
421909 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiPerform(169): thread terminated with a non-zero return code: -5
421910 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiRead(221): failed a request(416: http://mys3service:8088/mybucket/3750M?partNumber=1&uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4b
jkWiZ9XXOkpYq6roSxAyA)
421911 2021-06-17T09:30:46.442Z (pid: 6772) [ERR] curl.cpp:CopyMultipartPostRetryCallback(1218): Over retry count(5) limit(/3750M:1).
421912 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiRead(221): failed a request(416: http://mys3service:8088/mybucket/3750M?partNumber=2&uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4b
jkWiZ9XXOkpYq6roSxAyA)
421913 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiRead(221): failed a request(416: http://mys3service:8088/mybucket/3750M?partNumber=3&uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4b
jkWiZ9XXOkpYq6roSxAyA)
421914 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiRead(221): failed a request(416: http://mys3service:8088/mybucket/3750M?partNumber=4&uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4b
jkWiZ9XXOkpYq6roSxAyA)
421915 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiRead(221): failed a request(416: http://mys3service:8088/mybucket/3750M?partNumber=5&uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4b
jkWiZ9XXOkpYq6roSxAyA)
421916 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiRead(221): failed a request(416: http://mys3service:8088/mybucket/3750M?partNumber=6&uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4b
jkWiZ9XXOkpYq6roSxAyA)
421917 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiRead(221): failed a request(416: http://mys3service:8088/mybucket/3750M?partNumber=7&uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4b
jkWiZ9XXOkpYq6roSxAyA)
421918 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiRead(221): failed a request(416: http://mys3service:8088/mybucket/3750M?partNumber=8&uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4bjkWiZ9XXOkpYq6roSxAyA)
421919 2021-06-17T09:30:46.442Z (pid: 6772) [ERR] curl.cpp:MultipartHeadRequest(3963): error occurred in multi request(errno=-5).
421920 2021-06-17T09:30:46.442Z (pid: 6772) [INF]       curl.cpp:AbortMultipartUpload(3675): [tpath=/3750M]
421921 2021-06-17T09:30:46.442Z (pid: 6772) [DBG] curl_handlerpool.cpp:GetHandler(81): Get handler from pool: rest = 30
421922 2021-06-17T09:30:46.442Z (pid: 6772) [INF]       curl_util.cpp:prepare_url(254): URL is http://mys3service:8088/mybucket/3750M?uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4bjkWiZ9XXOkpYq6roSxAyA
421923 2021-06-17T09:30:46.442Z (pid: 6772) [INF]       curl_util.cpp:prepare_url(287): URL changed is http://mys3service:8088/mybucket/3750M?uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4bjkWiZ9XXOkpYq6roSxAyA
421924 2021-06-17T09:30:46.442Z (pid: 6772) [DBG] curl.cpp:RequestPerform(2274): connecting to URL http://mys3service:8088/mybucket/3750M?uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4bjkWiZ9XXOkpYq6roSxAyA
421925 2021-06-17T09:30:46.442Z (pid: 6772) [INF]       curl.cpp:insertV4Headers(2666): computing signature [DELETE] [/3750M] [uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4bjkWiZ9XXOkpYq6roSxAyA] []
421926 2021-06-17T09:30:46.442Z (pid: 6772) [INF]       curl_util.cpp:url_to_host(331): url is http://mys3service:8088
421927 2021-06-17T09:30:46.442Z (pid: 6772) [CURL DBG]* About to connect() to mys3service port 8088 (#48)
421928 2021-06-17T09:30:46.442Z (pid: 6772) [CURL DBG]*   Trying 172.20.10.152...
421929 2021-06-17T09:30:46.443Z (pid: 6772) [CURL DBG]* Connected to mys3service (172.20.10.152) port 8088 (#48)
421930 2021-06-17T09:30:46.443Z (pid: 6772) [CURL DBG]> DELETE /mybucket/3750M?uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4bjkWiZ9XXOkpYq6roSxAyA HTTP/1.1
421931 2021-06-17T09:30:46.443Z (pid: 6772) [CURL DBG]> User-Agent: s3fs/1.89 (commit hash c2c56d0; OpenSSL)
421932 2021-06-17T09:30:46.443Z (pid: 6772) [CURL DBG]> Accept: */*
421933 2021-06-17T09:30:46.443Z (pid: 6772) [CURL DBG]> Authorization: AWS4-HMAC-SHA256 Credential=NHTL282ERGST9B40156H/20210617/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=1c51b02cc02436c8
cc8dca0e9da0765f9fc08a33844aeb1dd6f0ec02480712d8
421934 2021-06-17T09:30:46.443Z (pid: 6772) [CURL DBG]> host: mys3service:8088
421935 2021-06-17T09:30:46.443Z (pid: 6772) [CURL DBG]> x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
421936 2021-06-17T09:30:46.443Z (pid: 6772) [CURL DBG]> x-amz-date: 20210617T093046Z
421937 2021-06-17T09:30:46.443Z (pid: 6772) [CURL DBG]>
421938 2021-06-17T09:30:46.452Z (pid: 6772) [CURL DBG]< HTTP/1.1 204 No Content
421939 2021-06-17T09:30:46.452Z (pid: 6772) [CURL DBG]< Date: Thu, 17 Jun 2021 09:30:46 GMT
421940 2021-06-17T09:30:46.452Z (pid: 6772) [CURL DBG]< Connection: KEEP-ALIVE
421941 2021-06-17T09:30:46.452Z (pid: 6772) [CURL DBG]< Server: StorageGRID/11.4.0.4
421942 2021-06-17T09:30:46.452Z (pid: 6772) [CURL DBG]< x-amz-request-id: 1623922246448222
421943 2021-06-17T09:30:46.452Z (pid: 6772) [CURL DBG]< x-amz-id-2: 12293711
421944 2021-06-17T09:30:46.452Z (pid: 6772) [CURL DBG]< Content-Length: 0
421945 2021-06-17T09:30:46.452Z (pid: 6772) [CURL DBG]<
421946 2021-06-17T09:30:46.452Z (pid: 6772) [CURL DBG]* Connection #48 to host mys3service left intact

  6. the timestamp operation from step 2 finally fails

    421947 2021-06-17T09:30:46.452Z (pid: 6772) [INF]       curl.cpp:RequestPerform(2307): HTTP response code 204
421948 2021-06-17T09:30:46.452Z (pid: 6772) [DBG] curl_handlerpool.cpp:ReturnHandler(103): Return handler to pool
421949 2021-06-17T09:30:46.452Z (pid: 6772) [DBG] fdcache.cpp:Close(662): [ent->file=/3750M][pseudo_fd=3]
421950 2021-06-17T09:30:46.452Z (pid: 6772) [DBG] fdcache_entity.cpp:Close(209): [path=/3750M][pseudo_fd=3][physical_fd=5]
421951    unique: 59969, error: -5 (Input/output error), outsize: 16

  7. finally the temporary file will be flushed successfully, the Content-Length header is set correctly

    421952 unique: 59970, opcode: FLUSH (25), nodeid: 2, insize: 64, pid: 6790
421953 flush[2]
421954 2021-06-17T09:30:46.452Z (pid: 6774) [INF] s3fs.cpp:s3fs_flush(2389): [path=/3750M][fd=2]
421955 2021-06-17T09:30:46.452Z (pid: 6774) [DBG] s3fs.cpp:check_parent_object_access(639): [path=/3750M]
421956 2021-06-17T09:30:46.452Z (pid: 6774) [DBG] s3fs.cpp:check_object_access(533): [path=/]
421957 2021-06-17T09:30:46.452Z (pid: 6774) [DBG] s3fs.cpp:get_object_attribute(364): [path=/]
421958 2021-06-17T09:30:46.452Z (pid: 6774) [DBG] s3fs.cpp:check_object_access(533): [path=/3750M]
421959 2021-06-17T09:30:46.452Z (pid: 6774) [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M]
421960 2021-06-17T09:30:46.452Z (pid: 6774) [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=566048.219264420][hit count=6]
421961 2021-06-17T09:30:46.452Z (pid: 6774) [DBG] fdcache.cpp:GetExistFdEntity(593): [path=/3750M][existfd=2]
421962 2021-06-17T09:30:46.452Z (pid: 6774) [INF]       fdcache_entity.cpp:RowFlush(1319): [tpath=][path=/3750M][pseudo_fd=2][physical_fd=5]
421963 2021-06-17T09:30:46.453Z (pid: 6774) [INF]       curl.cpp:ParallelMixMultipartUploadRequest(1381): [tpath=/3750M][fd=5]
421964 2021-06-17T09:30:46.453Z (pid: 6774) [INF]       curl.cpp:PreMultipartPostRequest(3458): [tpath=/3750M]
421965 2021-06-17T09:30:46.453Z (pid: 6774) [DBG] curl_handlerpool.cpp:GetHandler(81): Get handler from pool: rest = 30
421966 2021-06-17T09:30:46.453Z (pid: 6774) [INF]       curl_util.cpp:prepare_url(254): URL is http://mys3service:8088/mybucket/3750M?uploads
421967 2021-06-17T09:30:46.453Z (pid: 6774) [INF]       curl_util.cpp:prepare_url(287): URL changed is http://mys3service:8088/mybucket/3750M?uploads
421968 2021-06-17T09:30:46.453Z (pid: 6774) [DBG] curl.cpp:RequestPerform(2274): connecting to URL http://mys3service:8088/mybucket/3750M?uploads
421969 2021-06-17T09:30:46.453Z (pid: 6774) [INF]       curl.cpp:insertV4Headers(2666): computing signature [POST] [/3750M] [uploads] []
421970 2021-06-17T09:30:46.453Z (pid: 6774) [INF]       curl_util.cpp:url_to_host(331): url is http://mys3service:8088
421971 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]* Found bundle for host mys3service: 0x7f0320019b10
421972 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]* Re-using existing connection! (#48) with host mys3service
421973 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]* Connected to mys3service (172.20.10.152) port 8088 (#48)
421974 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> POST /mybucket/3750M?uploads HTTP/1.1
421975 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> User-Agent: s3fs/1.89 (commit hash c2c56d0; OpenSSL)
421976 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> Authorization: AWS4-HMAC-SHA256 Credential=NHTL282ERGST9B40156H/20210617/us-east-1/s3/aws4_request, SignedHeaders=content-type;host;x-amz-content-sha256;x-amz-date;x-amz-meta-ati
me;x-amz-meta-ctime;x-amz-meta-gid;x-amz-meta-mode;x-amz-meta-mtime;x-amz-meta-uid;x-amz-metadata-directive, Signature=aa9704eefb886af925020e80ef663036cd5de236b9dc9216cec08f0bcc80869a
421977 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> Content-Type: application/octet-stream
421978 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> host: mys3service:8088
421979 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
421980 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> x-amz-date: 20210617T093046Z
421981 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> x-amz-meta-atime: 1623848254.482895965
421982 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> x-amz-meta-ctime: 1623922246
421983 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> x-amz-meta-gid: 0
421984 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> x-amz-meta-mode: 33188
421985 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> x-amz-meta-mtime: 1623848254
421986 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> x-amz-meta-uid: 0
421987 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> x-amz-metadata-directive: REPLACE
421988 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]>
421989 2021-06-17T09:30:46.456Z (pid: 6774) [CURL DBG]< HTTP/1.1 200 OK
421990 2021-06-17T09:30:46.456Z (pid: 6774) [CURL DBG]< Date: Thu, 17 Jun 2021 09:30:46 GMT
421991 2021-06-17T09:30:46.456Z (pid: 6774) [CURL DBG]< Connection: KEEP-ALIVE
421992 2021-06-17T09:30:46.456Z (pid: 6774) [CURL DBG]< Server: StorageGRID/11.4.0.4
421993 2021-06-17T09:30:46.456Z (pid: 6774) [CURL DBG]< x-amz-request-id: 1623922246448222
421994 2021-06-17T09:30:46.456Z (pid: 6774) [CURL DBG]< x-amz-id-2: 12293711
421995 2021-06-17T09:30:46.456Z (pid: 6774) [CURL DBG]< Content-Length: 311
421996 2021-06-17T09:30:46.456Z (pid: 6774) [CURL DBG]< Content-Type: application/xml
421997 2021-06-17T09:30:46.456Z (pid: 6774) [CURL DBG]<
421998 2021-06-17T09:30:46.456Z (pid: 6774) [CURL DBG]* Connection #48 to host mys3service left intact

    423502 2021-06-17T09:30:47.133Z (pid: 6855) [DBG] curl_handlerpool.cpp:GetHandler(81): Get handler from pool: rest = 28
423503 2021-06-17T09:30:47.134Z (pid: 6855) [DBG] curl.cpp:RequestPerform(2274): connecting to URL http://mys3service:8088/mybucket/3750M?partNumber=1&uploadId=p-x_pr6wSP3JAJ8sTRXojUawtF1DM1HMVvMfAv5kW_c1qV_-BNoswuuQ-g
423509 2021-06-17T09:30:47.191Z (pid: 6855) [INF]       curl.cpp:insertV4Headers(2666): computing signature [PUT] [/3750M] [partNumber=1&uploadId=p-x_pr6wSP3JAJ8sTRXojUawtF1DM1HMVvMfAv5kW_c1qV_-BNoswuuQ-g] [5daceb6dc085d16c14a47a16eb298222241e3ac3e02227dfc6c3580f13e90338]
423511 2021-06-17T09:30:47.191Z (pid: 6855) [INF]       curl_util.cpp:url_to_host(331): url is http://mys3service:8088
423513 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]* About to connect() to mys3service port 8088 (#50)
423515 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]*   Trying 172.20.10.152...
423520 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]* Connected to mys3service (172.20.10.152) port 8088 (#50)
423521 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]> PUT /mybucket/3750M?partNumber=1&uploadId=p-x_pr6wSP3JAJ8sTRXojUawtF1DM1HMVvMfAv5kW_c1qV_-BNoswuuQ-g HTTP/1.1
423522 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]> User-Agent: s3fs/1.89 (commit hash c2c56d0; OpenSSL)
423523 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]> Authorization: AWS4-HMAC-SHA256 Credential=NHTL282ERGST9B40156H/20210617/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=75ac1fb0729c0b243b15bd84b33b43d98f1366eabe84346b01d5eeaec1c1a77f
423524 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]> host: mys3service:8088
423525 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]> x-amz-content-sha256: 5daceb6dc085d16c14a47a16eb298222241e3ac3e02227dfc6c3580f13e90338
423526 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]> x-amz-date: 20210617T093047Z
423527 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]> Content-Length: 10485760
423528 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]> Expect: 100-continue
423529 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]>
423579 2021-06-17T09:30:47.197Z (pid: 6855) [CURL DBG]< HTTP/1.1 100 Continue
423614 2021-06-17T09:30:47.368Z (pid: 6855) [CURL DBG]* We are completely uploaded and fine
423644 2021-06-17T09:30:47.382Z (pid: 6855) [CURL DBG]< HTTP/1.1 200 OK
423645 2021-06-17T09:30:47.382Z (pid: 6855) [CURL DBG]< Date: Thu, 17 Jun 2021 09:30:47 GMT
423646 2021-06-17T09:30:47.382Z (pid: 6855) [CURL DBG]< Connection: KEEP-ALIVE
423647 2021-06-17T09:30:47.382Z (pid: 6855) [CURL DBG]< Server: StorageGRID/11.4.0.4
423648 2021-06-17T09:30:47.382Z (pid: 6855) [CURL DBG]< x-amz-request-id: 1623922247195972
423649 2021-06-17T09:30:47.382Z (pid: 6855) [CURL DBG]< x-amz-id-2: 12616688
423650 2021-06-17T09:30:47.382Z (pid: 6855) [CURL DBG]< Content-Length: 0
423651 2021-06-17T09:30:47.382Z (pid: 6855) [CURL DBG]< ETag: "548bc15132a172f92312729eaa28ed06"
423652 2021-06-17T09:30:47.382Z (pid: 6855) [CURL DBG]<
423653 2021-06-17T09:30:47.382Z (pid: 6855) [CURL DBG]* Connection #50 to host mys3service left intact
423654 2021-06-17T09:30:47.382Z (pid: 6855) [INF]       curl.cpp:RequestPerform(2307): HTTP response code 200
423655 2021-06-17T09:30:47.382Z (pid: 6855) [DBG] curl_handlerpool.cpp:ReturnHandler(103): Return handler to pool

    434728 2021-06-17T09:30:59.314Z (pid: 6774) [CURL DBG]> POST /mybucket/3750M?uploadId=p-x_pr6wSP3JAJ8sTRXojUawtF1DM1HMVvMfAv5kW_c1qV_-BNoswuuQ-g HTTP/1.1
434729 2021-06-17T09:30:59.314Z (pid: 6774) [CURL DBG]> User-Agent: s3fs/1.89 (commit hash c2c56d0; OpenSSL)
434730 2021-06-17T09:30:59.314Z (pid: 6774) [CURL DBG]> Authorization: AWS4-HMAC-SHA256 Credential=NHTL282ERGST9B40156H/20210617/us-east-1/s3/aws4_request, SignedHeaders=content-type;host;x-amz-content-sha256;x-amz-date, Signature=c1c
dc39ae53e027fe826e233cf713948d1c352244a97d869e33d6efeaf16ffcc
434731 2021-06-17T09:30:59.314Z (pid: 6774) [CURL DBG]> Content-Type: application/xml
434732 2021-06-17T09:30:59.314Z (pid: 6774) [CURL DBG]> host: mys3service:8088
434733 2021-06-17T09:30:59.314Z (pid: 6774) [CURL DBG]> x-amz-content-sha256: 70231fecadb446a0cd72be4fbf45a53b73a3ab38a96ef08f7fa80601652c8db9
434734 2021-06-17T09:30:59.314Z (pid: 6774) [CURL DBG]> x-amz-date: 20210617T093059Z
434735 2021-06-17T09:30:59.314Z (pid: 6774) [CURL DBG]> Content-Length: 35849
434736 2021-06-17T09:30:59.314Z (pid: 6774) [CURL DBG]> Expect: 100-continue
434737 2021-06-17T09:30:59.314Z (pid: 6774) [CURL DBG]>
434738 2021-06-17T09:30:59.316Z (pid: 6774) [CURL DBG]< HTTP/1.1 100 Continue
434739 2021-06-17T09:30:59.333Z (pid: 6774) [CURL DBG]< HTTP/1.1 200 OK
434740 2021-06-17T09:30:59.333Z (pid: 6774) [CURL DBG]< Date: Thu, 17 Jun 2021 09:30:59 GMT
434741 2021-06-17T09:30:59.333Z (pid: 6774) [CURL DBG]< Connection: CLOSE
434742 2021-06-17T09:30:59.333Z (pid: 6774) [CURL DBG]< Server: StorageGRID/11.4.0.4
434743 2021-06-17T09:30:59.333Z (pid: 6774) [CURL DBG]< x-amz-request-id: 1623922247195972
434744 2021-06-17T09:30:59.333Z (pid: 6774) [CURL DBG]< x-amz-id-2: 12616688
434745 2021-06-17T09:30:59.333Z (pid: 6774) [CURL DBG]< Content-Type: application/xml
434746 2021-06-17T09:30:59.333Z (pid: 6774) [CURL DBG]<
434747 2021-06-17T09:31:03.051Z (pid: 6774) [CURL DBG]* Closing connection 50
434748 2021-06-17T09:31:03.051Z (pid: 6774) [INF]       curl.cpp:RequestPerform(2307): HTTP response code 200
434749 2021-06-17T09:31:03.051Z (pid: 6774) [DBG] curl_handlerpool.cpp:ReturnHandler(103): Return handler to pool
434750 2021-06-17T09:31:03.051Z (pid: 6774) [INF]       cache.cpp:DelStat(620): delete stat cache entry[path=/3750M]
434751    unique: 59970, success, outsize: 16
Originally created by @CarstenGrohmann on GitHub (Jun 18, 2021). Original GitHub issue: https://github.com/s3fs-fuse/s3fs-fuse/issues/1685 I've a simple copy job. The `cp` command reports an IO error for setting timestamps. The file content is correct. When I follow the log entries, I see that setting the timestamps triggers a multipart upload. This upload fails. In doing so `cp` reports `preserving times for "/s3mnt/3750M": Input/output error`. But at the end, the flush command also triggers a multipart upload and this second upload is successful. The difference between the two multipart uploads is: the first upload uses the `x-amz-copy-source-range` header but does not provide any content (`Content-Length: 0`) and the second upload does not use `x-amz-copy-source-range` but the correct `Content-Length:`. Additionally, I wonder why the final multipart upload does not set the correct times in the initial post request as shown in `step 7`? **Steps to reproduce:** 1. Start s3fs ``` ./s3fs mybucket /s3mnt -o url=http://mys3service:8088,use_path_request_style,notsup_compat_dir,enable_noobj_cache,curldbg,dbglevel=debug -d -d -f -o tmpdir=/extradisk/tmp/ ``` 2. Copy a larger file ``` # cp -p /extradisk/3750M /s3mnt/ cp: overwrite "/s3mnt/3750M"? y cp: preserving times for "/s3mnt/3750M": Input/output error ``` 3. Content is correct but the timestamp is wrong ``` # ll /extradisk/3750M /s3mnt/3750M -rw-r--r-- 1 root root 3929478700 Jun 16 14:57 /s3mnt/3750M -rw-r--r-- 1 root root 3929478700 Mar 4 14:08 /extradisk/3750M # md5sum /s3mnt/3750M /extradisk/3750M 23cff1bf6eabb1a7743a35d8d91699ed /s3mnt/3750M 23cff1bf6eabb1a7743a35d8d91699ed /extradisk/3750M ``` **Detailed analysis:** 1. file has fully written to the temporary file ``` 419966 unique: 59966, opcode: WRITE (16), nodeid: 2, insize: 65616, pid: 6790 419967 write[2] 65536 bytes to 3929341952 flags: 0x8001 419968 2021-06-17T09:30:46.300Z (pid: 6774) [DBG] s3fs.cpp:s3fs_write(2343): [path=/3750M][size=65536][offset=3929341952][fd=2] 419969 2021-06-17T09:30:46.300Z (pid: 6774) [DBG] fdcache.cpp:GetExistFdEntity(593): [path=/3750M][existfd=2] 419970 2021-06-17T09:30:46.300Z (pid: 6774) [DBG] fdcache_entity.cpp:Write(1594): [path=/3750M][pseudo_fd=2][physical_fd=5][offset=3929341952][size=65536] 419971 write[2] 65536 bytes to 3929341952 419972 unique: 59966, success, outsize: 24 419973 unique: 59967, opcode: WRITE (16), nodeid: 2, insize: 65616, pid: 6790 419974 write[2] 65536 bytes to 3929407488 flags: 0x8001 419975 2021-06-17T09:30:46.300Z (pid: 6772) [DBG] s3fs.cpp:s3fs_write(2343): [path=/3750M][size=65536][offset=3929407488][fd=2] 419976 2021-06-17T09:30:46.300Z (pid: 6772) [DBG] fdcache.cpp:GetExistFdEntity(593): [path=/3750M][existfd=2] 419977 2021-06-17T09:30:46.300Z (pid: 6772) [DBG] fdcache_entity.cpp:Write(1594): [path=/3750M][pseudo_fd=2][physical_fd=5][offset=3929407488][size=65536] 419978 write[2] 65536 bytes to 3929407488 419979 unique: 59967, success, outsize: 24 419980 unique: 59968, opcode: WRITE (16), nodeid: 2, insize: 5756, pid: 6790 419981 write[2] 5676 bytes to 3929473024 flags: 0x8001 419982 2021-06-17T09:30:46.300Z (pid: 6774) [DBG] s3fs.cpp:s3fs_write(2343): [path=/3750M][size=5676][offset=3929473024][fd=2] 419983 2021-06-17T09:30:46.300Z (pid: 6774) [DBG] fdcache.cpp:GetExistFdEntity(593): [path=/3750M][existfd=2] 419984 2021-06-17T09:30:46.300Z (pid: 6774) [DBG] fdcache_entity.cpp:Write(1594): [path=/3750M][pseudo_fd=2][physical_fd=5][offset=3929473024][size=5676] 419985 write[2] 5676 bytes to 3929473024 419986 unique: 59968, success, outsize: 24 ``` 2. timestamps will be set: ``` 419987 unique: 59969, opcode: SETATTR (4), nodeid: 2, insize: 128, pid: 6790 419988 utimens /3750M 1623848254.482895965 1614863324.017080564 419989 2021-06-17T09:30:46.301Z (pid: 6772) [INF] s3fs.cpp:s3fs_utimens(1982): [path=/3750M][mtime=1614863324][ctime/atime=1623848254] ``` 3. this triggers a multipart upload ``` 419990 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] s3fs.cpp:check_parent_object_access(639): [path=/3750M] 419991 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] s3fs.cpp:check_object_access(533): [path=/] 419992 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] s3fs.cpp:get_object_attribute(364): [path=/] 419993 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] s3fs.cpp:check_object_access(533): [path=/3750M] 419994 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M] 419995 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=566048.219264420][hit count=3] 419996 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M] 419997 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=566048.219264420][hit count=4] 419998 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] fdcache.cpp:OpenExistFdEntiy(610): [path=/3750M][flags=0x0] 419999 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] fdcache.cpp:Open(508): [path=/3750M][size=-1][time=-1][flags=0x0] 420000 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] fdcache_entity.cpp:Open(413): [path=/3750M][physical_fd=5][size=-1][time=-1][flags=0x0] 420001 2021-06-17T09:30:46.301Z (pid: 6772) [INF] fdcache_entity.cpp:SetMCtime(780): [path=/3750M][physical_fd=5][mtime=1614863324][ctime=1623848254] 420002 2021-06-17T09:30:46.301Z (pid: 6772) [INF] fdcache_entity.cpp:SetAtime(764): [path=/3750M][physical_fd=5][time=1623848254] 420003 2021-06-17T09:30:46.301Z (pid: 6772) [INF] s3fs.cpp:s3fs_utimens(2052): meta is not pending, but need to keep current mtime. 420004 2021-06-17T09:30:46.301Z (pid: 6772) [INF] s3fs.cpp:put_headers(745): [path=/3750M] 420005 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M] 420006 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=566048.219264420][hit count=5] 420007 2021-06-17T09:30:46.301Z (pid: 6772) [INF] curl.cpp:MultipartHeadRequest(3921): [tpath=/3750M] 420008 2021-06-17T09:30:46.301Z (pid: 6772) [INF] curl.cpp:PreMultipartPostRequest(3458): [tpath=/3750M] 420009 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] curl_handlerpool.cpp:GetHandler(81): Get handler from pool: rest = 30 420010 2021-06-17T09:30:46.301Z (pid: 6772) [INF] curl_util.cpp:prepare_url(254): URL is http://mys3service:8088/mybucket/3750M?uploads 420011 2021-06-17T09:30:46.301Z (pid: 6772) [INF] curl_util.cpp:prepare_url(287): URL changed is http://mys3service:8088/mybucket/3750M?uploads 420012 2021-06-17T09:30:46.301Z (pid: 6772) [DBG] curl.cpp:RequestPerform(2274): connecting to URL http://mys3service:8088/mybucket/3750M?uploads 420013 2021-06-17T09:30:46.301Z (pid: 6772) [INF] curl.cpp:insertV4Headers(2666): computing signature [POST] [/3750M] [uploads] [] 420014 2021-06-17T09:30:46.301Z (pid: 6772) [INF] curl_util.cpp:url_to_host(331): url is http://mys3service:8088 420015 2021-06-17T09:30:46.301Z (pid: 6772) [CURL DBG]* Found bundle for host mys3service: 0x7f0320018ba0 420016 2021-06-17T09:30:46.301Z (pid: 6772) [CURL DBG]* Re-using existing connection! (#0) with host mys3service 420017 2021-06-17T09:30:46.301Z (pid: 6772) [CURL DBG]* Connected to mys3service (172.20.10.152) port 8088 (#0) 420018 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> POST /mybucket/3750M?uploads HTTP/1.1 420019 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> User-Agent: s3fs/1.89 (commit hash c2c56d0; OpenSSL) 420020 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> Authorization: AWS4-HMAC-SHA256 Credential=NHTL282ERGST9B40156H/20210617/us-east-1/s3/aws4_request, SignedHeaders=content-type;host;x-amz-content-sha256;x-amz-date;x-amz-meta-atime;x-amz-meta-ctime;x-amz-meta-gid;x-amz-meta-mode;x-amz-meta-mtime;x-amz-meta-uid;x-amz-metadata-directive, Signature=703c0dadfd6af342d6883b3f50bea1b72cb91d2b6906a253a7f2543a28391114 420021 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> Content-Type: application/octet-stream 420022 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> host: mys3service:8088 420023 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 420024 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> x-amz-date: 20210617T093046Z 420025 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> x-amz-meta-atime: 1623848254.482895965 420026 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> x-amz-meta-ctime: 1623848254.482895965 420027 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> x-amz-meta-gid: 0 420028 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> x-amz-meta-mode: 33188 420029 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> x-amz-meta-mtime: 1614863324.017080564 420030 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> x-amz-meta-uid: 0 420031 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> x-amz-metadata-directive: REPLACE 420032 2021-06-17T09:30:46.302Z (pid: 6772) [CURL DBG]> 420033 2021-06-17T09:30:46.307Z (pid: 6772) [CURL DBG]< HTTP/1.1 200 OK 420034 2021-06-17T09:30:46.307Z (pid: 6772) [CURL DBG]< Date: Thu, 17 Jun 2021 09:30:46 GMT 420035 2021-06-17T09:30:46.307Z (pid: 6772) [CURL DBG]< Connection: KEEP-ALIVE 420036 2021-06-17T09:30:46.307Z (pid: 6772) [CURL DBG]< Server: StorageGRID/11.4.0.4 420037 2021-06-17T09:30:46.307Z (pid: 6772) [CURL DBG]< x-amz-request-id: 1623922217136394 420038 2021-06-17T09:30:46.307Z (pid: 6772) [CURL DBG]< x-amz-id-2: 12293711 420039 2021-06-17T09:30:46.307Z (pid: 6772) [CURL DBG]< Content-Length: 311 420040 2021-06-17T09:30:46.307Z (pid: 6772) [CURL DBG]< Content-Type: application/xml 420041 2021-06-17T09:30:46.307Z (pid: 6772) [CURL DBG]< 420042 2021-06-17T09:30:46.307Z (pid: 6772) [CURL DBG]* Connection #0 to host mys3service left intact ``` 4. Uploading part 1 is failing because of `Content-Length: 0` ``` 420078 2021-06-17T09:30:46.308Z (pid: 6806) [DBG] curl_handlerpool.cpp:GetHandler(81): Get handler from pool: rest = 30 420079 2021-06-17T09:30:46.308Z (pid: 6806) [DBG] curl.cpp:RequestPerform(2274): connecting to URL http://mys3service:8088/mybucket/3750M?partNumber=1&uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4bjkWiZ9XXOkpYq6roSxAyA 420080 2021-06-17T09:30:46.308Z (pid: 6806) [INF] curl.cpp:insertV4Headers(2666): computing signature [PUT] [/3750M] [partNumber=1&uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4bjkWiZ9XXOkpYq6roSxAyA] [] 420081 2021-06-17T09:30:46.308Z (pid: 6806) [INF] curl_util.cpp:url_to_host(331): url is http://mys3service:8088 420089 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]* Found bundle for host mys3service: 0x7f0320018ba0 420091 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]* Re-using existing connection! (#0) with host mys3service 420092 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]* Connected to mys3service (172.20.10.152) port 8088 (#0) 420101 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> PUT /mybucket/3750M?partNumber=1&uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4bjkWiZ9XXOkpYq6roSxAyA HTTP/1.1 420102 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> User-Agent: s3fs/1.89 (commit hash c2c56d0; OpenSSL) 420105 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> Accept: */* 420106 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> Authorization: AWS4-HMAC-SHA256 Credential=NHTL282ERGST9B40156H/20210617/us-east-1/s3/aws4_request, SignedHeaders=content-type;host;x-amz-content-sha256;x-amz-copy-source;x-amz-copy-source-range;x-amz-date, Signature=c9938f1e27e7c6f1f9e634492ef39ea5b032cf2b31ed96c925936741ad2a5aec 420107 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> Content-Type: application/octet-stream 420108 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> host: mys3service:8088 420109 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 420110 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> x-amz-copy-source: /mybucket/3750M 420111 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> x-amz-copy-source-range: bytes=0-536870911 420112 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> x-amz-date: 20210617T093046Z 420113 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> Content-Length: 0 420114 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> Expect: 100-continue 420115 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> 420178 2021-06-17T09:30:46.310Z (pid: 6806) [CURL DBG]< HTTP/1.1 100 Continue 420179 2021-06-17T09:30:46.313Z (pid: 6806) [CURL DBG]< HTTP/1.1 416 Requested Range Not Satisfiable 420180 2021-06-17T09:30:46.313Z (pid: 6806) [CURL DBG]< Date: Thu, 17 Jun 2021 09:30:46 GMT 420181 2021-06-17T09:30:46.313Z (pid: 6806) [CURL DBG]< Connection: CLOSE 420182 2021-06-17T09:30:46.313Z (pid: 6806) [CURL DBG]< Server: StorageGRID/11.4.0.4 420183 2021-06-17T09:30:46.313Z (pid: 6806) [CURL DBG]< x-amz-request-id: 1623922217136394 420184 2021-06-17T09:30:46.313Z (pid: 6806) [CURL DBG]< x-amz-id-2: 12293711 420185 2021-06-17T09:30:46.313Z (pid: 6806) [CURL DBG]< Content-Length: 328 420186 2021-06-17T09:30:46.313Z (pid: 6806) [CURL DBG]< Content-Type: application/xml 420187 2021-06-17T09:30:46.313Z (pid: 6806) [CURL DBG]< 420188 2021-06-17T09:30:46.313Z (pid: 6806) [CURL DBG]* Closing connection 0 420189 2021-06-17T09:30:46.313Z (pid: 6806) [INF] curl.cpp:RequestPerform(2362): HTTP response code 416 was returned, returning EIO 420190 2021-06-17T09:30:46.314Z (pid: 6806) [DBG] curl_handlerpool.cpp:ReturnHandler(103): Return handler to pool ``` 5. This repeats for part 1 to 8 serveral times till the upload will be cleaned upload ``` 421905 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiPerform(169): thread terminated with a non-zero return code: -5 421906 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiPerform(169): thread terminated with a non-zero return code: -5 421907 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiPerform(169): thread terminated with a non-zero return code: -5 421908 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiPerform(169): thread terminated with a non-zero return code: -5 421909 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiPerform(169): thread terminated with a non-zero return code: -5 421910 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiRead(221): failed a request(416: http://mys3service:8088/mybucket/3750M?partNumber=1&uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4b jkWiZ9XXOkpYq6roSxAyA) 421911 2021-06-17T09:30:46.442Z (pid: 6772) [ERR] curl.cpp:CopyMultipartPostRetryCallback(1218): Over retry count(5) limit(/3750M:1). 421912 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiRead(221): failed a request(416: http://mys3service:8088/mybucket/3750M?partNumber=2&uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4b jkWiZ9XXOkpYq6roSxAyA) 421913 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiRead(221): failed a request(416: http://mys3service:8088/mybucket/3750M?partNumber=3&uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4b jkWiZ9XXOkpYq6roSxAyA) 421914 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiRead(221): failed a request(416: http://mys3service:8088/mybucket/3750M?partNumber=4&uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4b jkWiZ9XXOkpYq6roSxAyA) 421915 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiRead(221): failed a request(416: http://mys3service:8088/mybucket/3750M?partNumber=5&uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4b jkWiZ9XXOkpYq6roSxAyA) 421916 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiRead(221): failed a request(416: http://mys3service:8088/mybucket/3750M?partNumber=6&uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4b jkWiZ9XXOkpYq6roSxAyA) 421917 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiRead(221): failed a request(416: http://mys3service:8088/mybucket/3750M?partNumber=7&uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4b jkWiZ9XXOkpYq6roSxAyA) 421918 2021-06-17T09:30:46.442Z (pid: 6772) [WAN] curl_multi.cpp:MultiRead(221): failed a request(416: http://mys3service:8088/mybucket/3750M?partNumber=8&uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4bjkWiZ9XXOkpYq6roSxAyA) 421919 2021-06-17T09:30:46.442Z (pid: 6772) [ERR] curl.cpp:MultipartHeadRequest(3963): error occurred in multi request(errno=-5). 421920 2021-06-17T09:30:46.442Z (pid: 6772) [INF] curl.cpp:AbortMultipartUpload(3675): [tpath=/3750M] 421921 2021-06-17T09:30:46.442Z (pid: 6772) [DBG] curl_handlerpool.cpp:GetHandler(81): Get handler from pool: rest = 30 421922 2021-06-17T09:30:46.442Z (pid: 6772) [INF] curl_util.cpp:prepare_url(254): URL is http://mys3service:8088/mybucket/3750M?uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4bjkWiZ9XXOkpYq6roSxAyA 421923 2021-06-17T09:30:46.442Z (pid: 6772) [INF] curl_util.cpp:prepare_url(287): URL changed is http://mys3service:8088/mybucket/3750M?uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4bjkWiZ9XXOkpYq6roSxAyA 421924 2021-06-17T09:30:46.442Z (pid: 6772) [DBG] curl.cpp:RequestPerform(2274): connecting to URL http://mys3service:8088/mybucket/3750M?uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4bjkWiZ9XXOkpYq6roSxAyA 421925 2021-06-17T09:30:46.442Z (pid: 6772) [INF] curl.cpp:insertV4Headers(2666): computing signature [DELETE] [/3750M] [uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4bjkWiZ9XXOkpYq6roSxAyA] [] 421926 2021-06-17T09:30:46.442Z (pid: 6772) [INF] curl_util.cpp:url_to_host(331): url is http://mys3service:8088 421927 2021-06-17T09:30:46.442Z (pid: 6772) [CURL DBG]* About to connect() to mys3service port 8088 (#48) 421928 2021-06-17T09:30:46.442Z (pid: 6772) [CURL DBG]* Trying 172.20.10.152... 421929 2021-06-17T09:30:46.443Z (pid: 6772) [CURL DBG]* Connected to mys3service (172.20.10.152) port 8088 (#48) 421930 2021-06-17T09:30:46.443Z (pid: 6772) [CURL DBG]> DELETE /mybucket/3750M?uploadId=UqLxIDL9RG3zetHUDv3vwX92zsaHnaTZmXv4bjkWiZ9XXOkpYq6roSxAyA HTTP/1.1 421931 2021-06-17T09:30:46.443Z (pid: 6772) [CURL DBG]> User-Agent: s3fs/1.89 (commit hash c2c56d0; OpenSSL) 421932 2021-06-17T09:30:46.443Z (pid: 6772) [CURL DBG]> Accept: */* 421933 2021-06-17T09:30:46.443Z (pid: 6772) [CURL DBG]> Authorization: AWS4-HMAC-SHA256 Credential=NHTL282ERGST9B40156H/20210617/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=1c51b02cc02436c8 cc8dca0e9da0765f9fc08a33844aeb1dd6f0ec02480712d8 421934 2021-06-17T09:30:46.443Z (pid: 6772) [CURL DBG]> host: mys3service:8088 421935 2021-06-17T09:30:46.443Z (pid: 6772) [CURL DBG]> x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 421936 2021-06-17T09:30:46.443Z (pid: 6772) [CURL DBG]> x-amz-date: 20210617T093046Z 421937 2021-06-17T09:30:46.443Z (pid: 6772) [CURL DBG]> 421938 2021-06-17T09:30:46.452Z (pid: 6772) [CURL DBG]< HTTP/1.1 204 No Content 421939 2021-06-17T09:30:46.452Z (pid: 6772) [CURL DBG]< Date: Thu, 17 Jun 2021 09:30:46 GMT 421940 2021-06-17T09:30:46.452Z (pid: 6772) [CURL DBG]< Connection: KEEP-ALIVE 421941 2021-06-17T09:30:46.452Z (pid: 6772) [CURL DBG]< Server: StorageGRID/11.4.0.4 421942 2021-06-17T09:30:46.452Z (pid: 6772) [CURL DBG]< x-amz-request-id: 1623922246448222 421943 2021-06-17T09:30:46.452Z (pid: 6772) [CURL DBG]< x-amz-id-2: 12293711 421944 2021-06-17T09:30:46.452Z (pid: 6772) [CURL DBG]< Content-Length: 0 421945 2021-06-17T09:30:46.452Z (pid: 6772) [CURL DBG]< 421946 2021-06-17T09:30:46.452Z (pid: 6772) [CURL DBG]* Connection #48 to host mys3service left intact ``` 6. the timestamp operation from step 2 finally fails ``` 421947 2021-06-17T09:30:46.452Z (pid: 6772) [INF] curl.cpp:RequestPerform(2307): HTTP response code 204 421948 2021-06-17T09:30:46.452Z (pid: 6772) [DBG] curl_handlerpool.cpp:ReturnHandler(103): Return handler to pool 421949 2021-06-17T09:30:46.452Z (pid: 6772) [DBG] fdcache.cpp:Close(662): [ent->file=/3750M][pseudo_fd=3] 421950 2021-06-17T09:30:46.452Z (pid: 6772) [DBG] fdcache_entity.cpp:Close(209): [path=/3750M][pseudo_fd=3][physical_fd=5] 421951 unique: 59969, error: -5 (Input/output error), outsize: 16 ``` 7. finally the temporary file will be flushed successfully, the `Content-Length` header is set correctly ``` 421952 unique: 59970, opcode: FLUSH (25), nodeid: 2, insize: 64, pid: 6790 421953 flush[2] 421954 2021-06-17T09:30:46.452Z (pid: 6774) [INF] s3fs.cpp:s3fs_flush(2389): [path=/3750M][fd=2] 421955 2021-06-17T09:30:46.452Z (pid: 6774) [DBG] s3fs.cpp:check_parent_object_access(639): [path=/3750M] 421956 2021-06-17T09:30:46.452Z (pid: 6774) [DBG] s3fs.cpp:check_object_access(533): [path=/] 421957 2021-06-17T09:30:46.452Z (pid: 6774) [DBG] s3fs.cpp:get_object_attribute(364): [path=/] 421958 2021-06-17T09:30:46.452Z (pid: 6774) [DBG] s3fs.cpp:check_object_access(533): [path=/3750M] 421959 2021-06-17T09:30:46.452Z (pid: 6774) [DBG] s3fs.cpp:get_object_attribute(364): [path=/3750M] 421960 2021-06-17T09:30:46.452Z (pid: 6774) [DBG] cache.cpp:GetStat(295): stat cache hit [path=/3750M][time=566048.219264420][hit count=6] 421961 2021-06-17T09:30:46.452Z (pid: 6774) [DBG] fdcache.cpp:GetExistFdEntity(593): [path=/3750M][existfd=2] 421962 2021-06-17T09:30:46.452Z (pid: 6774) [INF] fdcache_entity.cpp:RowFlush(1319): [tpath=][path=/3750M][pseudo_fd=2][physical_fd=5] 421963 2021-06-17T09:30:46.453Z (pid: 6774) [INF] curl.cpp:ParallelMixMultipartUploadRequest(1381): [tpath=/3750M][fd=5] 421964 2021-06-17T09:30:46.453Z (pid: 6774) [INF] curl.cpp:PreMultipartPostRequest(3458): [tpath=/3750M] 421965 2021-06-17T09:30:46.453Z (pid: 6774) [DBG] curl_handlerpool.cpp:GetHandler(81): Get handler from pool: rest = 30 421966 2021-06-17T09:30:46.453Z (pid: 6774) [INF] curl_util.cpp:prepare_url(254): URL is http://mys3service:8088/mybucket/3750M?uploads 421967 2021-06-17T09:30:46.453Z (pid: 6774) [INF] curl_util.cpp:prepare_url(287): URL changed is http://mys3service:8088/mybucket/3750M?uploads 421968 2021-06-17T09:30:46.453Z (pid: 6774) [DBG] curl.cpp:RequestPerform(2274): connecting to URL http://mys3service:8088/mybucket/3750M?uploads 421969 2021-06-17T09:30:46.453Z (pid: 6774) [INF] curl.cpp:insertV4Headers(2666): computing signature [POST] [/3750M] [uploads] [] 421970 2021-06-17T09:30:46.453Z (pid: 6774) [INF] curl_util.cpp:url_to_host(331): url is http://mys3service:8088 421971 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]* Found bundle for host mys3service: 0x7f0320019b10 421972 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]* Re-using existing connection! (#48) with host mys3service 421973 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]* Connected to mys3service (172.20.10.152) port 8088 (#48) 421974 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> POST /mybucket/3750M?uploads HTTP/1.1 421975 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> User-Agent: s3fs/1.89 (commit hash c2c56d0; OpenSSL) 421976 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> Authorization: AWS4-HMAC-SHA256 Credential=NHTL282ERGST9B40156H/20210617/us-east-1/s3/aws4_request, SignedHeaders=content-type;host;x-amz-content-sha256;x-amz-date;x-amz-meta-ati me;x-amz-meta-ctime;x-amz-meta-gid;x-amz-meta-mode;x-amz-meta-mtime;x-amz-meta-uid;x-amz-metadata-directive, Signature=aa9704eefb886af925020e80ef663036cd5de236b9dc9216cec08f0bcc80869a 421977 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> Content-Type: application/octet-stream 421978 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> host: mys3service:8088 421979 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> x-amz-content-sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 421980 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> x-amz-date: 20210617T093046Z 421981 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> x-amz-meta-atime: 1623848254.482895965 421982 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> x-amz-meta-ctime: 1623922246 421983 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> x-amz-meta-gid: 0 421984 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> x-amz-meta-mode: 33188 421985 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> x-amz-meta-mtime: 1623848254 421986 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> x-amz-meta-uid: 0 421987 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> x-amz-metadata-directive: REPLACE 421988 2021-06-17T09:30:46.453Z (pid: 6774) [CURL DBG]> 421989 2021-06-17T09:30:46.456Z (pid: 6774) [CURL DBG]< HTTP/1.1 200 OK 421990 2021-06-17T09:30:46.456Z (pid: 6774) [CURL DBG]< Date: Thu, 17 Jun 2021 09:30:46 GMT 421991 2021-06-17T09:30:46.456Z (pid: 6774) [CURL DBG]< Connection: KEEP-ALIVE 421992 2021-06-17T09:30:46.456Z (pid: 6774) [CURL DBG]< Server: StorageGRID/11.4.0.4 421993 2021-06-17T09:30:46.456Z (pid: 6774) [CURL DBG]< x-amz-request-id: 1623922246448222 421994 2021-06-17T09:30:46.456Z (pid: 6774) [CURL DBG]< x-amz-id-2: 12293711 421995 2021-06-17T09:30:46.456Z (pid: 6774) [CURL DBG]< Content-Length: 311 421996 2021-06-17T09:30:46.456Z (pid: 6774) [CURL DBG]< Content-Type: application/xml 421997 2021-06-17T09:30:46.456Z (pid: 6774) [CURL DBG]< 421998 2021-06-17T09:30:46.456Z (pid: 6774) [CURL DBG]* Connection #48 to host mys3service left intact ``` ``` 423502 2021-06-17T09:30:47.133Z (pid: 6855) [DBG] curl_handlerpool.cpp:GetHandler(81): Get handler from pool: rest = 28 423503 2021-06-17T09:30:47.134Z (pid: 6855) [DBG] curl.cpp:RequestPerform(2274): connecting to URL http://mys3service:8088/mybucket/3750M?partNumber=1&uploadId=p-x_pr6wSP3JAJ8sTRXojUawtF1DM1HMVvMfAv5kW_c1qV_-BNoswuuQ-g 423509 2021-06-17T09:30:47.191Z (pid: 6855) [INF] curl.cpp:insertV4Headers(2666): computing signature [PUT] [/3750M] [partNumber=1&uploadId=p-x_pr6wSP3JAJ8sTRXojUawtF1DM1HMVvMfAv5kW_c1qV_-BNoswuuQ-g] [5daceb6dc085d16c14a47a16eb298222241e3ac3e02227dfc6c3580f13e90338] 423511 2021-06-17T09:30:47.191Z (pid: 6855) [INF] curl_util.cpp:url_to_host(331): url is http://mys3service:8088 423513 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]* About to connect() to mys3service port 8088 (#50) 423515 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]* Trying 172.20.10.152... 423520 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]* Connected to mys3service (172.20.10.152) port 8088 (#50) 423521 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]> PUT /mybucket/3750M?partNumber=1&uploadId=p-x_pr6wSP3JAJ8sTRXojUawtF1DM1HMVvMfAv5kW_c1qV_-BNoswuuQ-g HTTP/1.1 423522 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]> User-Agent: s3fs/1.89 (commit hash c2c56d0; OpenSSL) 423523 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]> Authorization: AWS4-HMAC-SHA256 Credential=NHTL282ERGST9B40156H/20210617/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=75ac1fb0729c0b243b15bd84b33b43d98f1366eabe84346b01d5eeaec1c1a77f 423524 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]> host: mys3service:8088 423525 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]> x-amz-content-sha256: 5daceb6dc085d16c14a47a16eb298222241e3ac3e02227dfc6c3580f13e90338 423526 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]> x-amz-date: 20210617T093047Z 423527 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]> Content-Length: 10485760 423528 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]> Expect: 100-continue 423529 2021-06-17T09:30:47.191Z (pid: 6855) [CURL DBG]> 423579 2021-06-17T09:30:47.197Z (pid: 6855) [CURL DBG]< HTTP/1.1 100 Continue 423614 2021-06-17T09:30:47.368Z (pid: 6855) [CURL DBG]* We are completely uploaded and fine 423644 2021-06-17T09:30:47.382Z (pid: 6855) [CURL DBG]< HTTP/1.1 200 OK 423645 2021-06-17T09:30:47.382Z (pid: 6855) [CURL DBG]< Date: Thu, 17 Jun 2021 09:30:47 GMT 423646 2021-06-17T09:30:47.382Z (pid: 6855) [CURL DBG]< Connection: KEEP-ALIVE 423647 2021-06-17T09:30:47.382Z (pid: 6855) [CURL DBG]< Server: StorageGRID/11.4.0.4 423648 2021-06-17T09:30:47.382Z (pid: 6855) [CURL DBG]< x-amz-request-id: 1623922247195972 423649 2021-06-17T09:30:47.382Z (pid: 6855) [CURL DBG]< x-amz-id-2: 12616688 423650 2021-06-17T09:30:47.382Z (pid: 6855) [CURL DBG]< Content-Length: 0 423651 2021-06-17T09:30:47.382Z (pid: 6855) [CURL DBG]< ETag: "548bc15132a172f92312729eaa28ed06" 423652 2021-06-17T09:30:47.382Z (pid: 6855) [CURL DBG]< 423653 2021-06-17T09:30:47.382Z (pid: 6855) [CURL DBG]* Connection #50 to host mys3service left intact 423654 2021-06-17T09:30:47.382Z (pid: 6855) [INF] curl.cpp:RequestPerform(2307): HTTP response code 200 423655 2021-06-17T09:30:47.382Z (pid: 6855) [DBG] curl_handlerpool.cpp:ReturnHandler(103): Return handler to pool ``` ``` 434728 2021-06-17T09:30:59.314Z (pid: 6774) [CURL DBG]> POST /mybucket/3750M?uploadId=p-x_pr6wSP3JAJ8sTRXojUawtF1DM1HMVvMfAv5kW_c1qV_-BNoswuuQ-g HTTP/1.1 434729 2021-06-17T09:30:59.314Z (pid: 6774) [CURL DBG]> User-Agent: s3fs/1.89 (commit hash c2c56d0; OpenSSL) 434730 2021-06-17T09:30:59.314Z (pid: 6774) [CURL DBG]> Authorization: AWS4-HMAC-SHA256 Credential=NHTL282ERGST9B40156H/20210617/us-east-1/s3/aws4_request, SignedHeaders=content-type;host;x-amz-content-sha256;x-amz-date, Signature=c1c dc39ae53e027fe826e233cf713948d1c352244a97d869e33d6efeaf16ffcc 434731 2021-06-17T09:30:59.314Z (pid: 6774) [CURL DBG]> Content-Type: application/xml 434732 2021-06-17T09:30:59.314Z (pid: 6774) [CURL DBG]> host: mys3service:8088 434733 2021-06-17T09:30:59.314Z (pid: 6774) [CURL DBG]> x-amz-content-sha256: 70231fecadb446a0cd72be4fbf45a53b73a3ab38a96ef08f7fa80601652c8db9 434734 2021-06-17T09:30:59.314Z (pid: 6774) [CURL DBG]> x-amz-date: 20210617T093059Z 434735 2021-06-17T09:30:59.314Z (pid: 6774) [CURL DBG]> Content-Length: 35849 434736 2021-06-17T09:30:59.314Z (pid: 6774) [CURL DBG]> Expect: 100-continue 434737 2021-06-17T09:30:59.314Z (pid: 6774) [CURL DBG]> 434738 2021-06-17T09:30:59.316Z (pid: 6774) [CURL DBG]< HTTP/1.1 100 Continue 434739 2021-06-17T09:30:59.333Z (pid: 6774) [CURL DBG]< HTTP/1.1 200 OK 434740 2021-06-17T09:30:59.333Z (pid: 6774) [CURL DBG]< Date: Thu, 17 Jun 2021 09:30:59 GMT 434741 2021-06-17T09:30:59.333Z (pid: 6774) [CURL DBG]< Connection: CLOSE 434742 2021-06-17T09:30:59.333Z (pid: 6774) [CURL DBG]< Server: StorageGRID/11.4.0.4 434743 2021-06-17T09:30:59.333Z (pid: 6774) [CURL DBG]< x-amz-request-id: 1623922247195972 434744 2021-06-17T09:30:59.333Z (pid: 6774) [CURL DBG]< x-amz-id-2: 12616688 434745 2021-06-17T09:30:59.333Z (pid: 6774) [CURL DBG]< Content-Type: application/xml 434746 2021-06-17T09:30:59.333Z (pid: 6774) [CURL DBG]< 434747 2021-06-17T09:31:03.051Z (pid: 6774) [CURL DBG]* Closing connection 50 434748 2021-06-17T09:31:03.051Z (pid: 6774) [INF] curl.cpp:RequestPerform(2307): HTTP response code 200 434749 2021-06-17T09:31:03.051Z (pid: 6774) [DBG] curl_handlerpool.cpp:ReturnHandler(103): Return handler to pool 434750 2021-06-17T09:31:03.051Z (pid: 6774) [INF] cache.cpp:DelStat(620): delete stat cache entry[path=/3750M] 434751 unique: 59970, success, outsize: 16 ```
kerem closed this issue 2026-03-04 01:49:35 +03:00
kerem commented 2026-03-04 01:49:36 +03:00
Author
Owner
Copy link

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

Maybe this is a logical bug in github.com/s3fs-fuse/s3fs-fuse@1e0e2752bf/src/s3fs.cpp (L1971)

Starting this line as reported in the debug log:

420003 2021-06-17T09:30:46.301Z (pid: 6772) [INF] s3fs.cpp:s3fs_utimens(2052): meta is not pending, but need to keep current mtime.

github.com/s3fs-fuse/s3fs-fuse@1e0e2752bf/src/s3fs.cpp (L2051-L2061)

The source looks like that the metadata will be updated on a non-existing object with put_headers(is_copy=true):

github.com/s3fs-fuse/s3fs-fuse@1e0e2752bf/src/s3fs.cpp (L2062-L2069)

This probably causes the copy requests with Content-Length: 0 as shown in step 4:

420110 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> x-amz-copy-source: /mybucket/3750M
420111 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> x-amz-copy-source-range: bytes=0-536870911
420112 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> x-amz-date: 20210617T093046Z
420113 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> Content-Length: 0
<!-- gh-comment-id:863897338 --> @CarstenGrohmann commented on GitHub (Jun 18, 2021): Maybe this is a logical bug in https://github.com/s3fs-fuse/s3fs-fuse/blob/1e0e2752bf50c7f0d3180630818bb42f39c3926b/src/s3fs.cpp#L1971 Starting this line as reported in the debug log: ``` 420003 2021-06-17T09:30:46.301Z (pid: 6772) [INF] s3fs.cpp:s3fs_utimens(2052): meta is not pending, but need to keep current mtime. ``` https://github.com/s3fs-fuse/s3fs-fuse/blob/1e0e2752bf50c7f0d3180630818bb42f39c3926b/src/s3fs.cpp#L2051-L2061 The source looks like that the metadata will be updated on a non-existing object with `put_headers(is_copy=true)`: https://github.com/s3fs-fuse/s3fs-fuse/blob/1e0e2752bf50c7f0d3180630818bb42f39c3926b/src/s3fs.cpp#L2062-L2069 This probably causes the copy requests with `Content-Length: 0` as shown in step 4: ``` 420110 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> x-amz-copy-source: /mybucket/3750M 420111 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> x-amz-copy-source-range: bytes=0-536870911 420112 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> x-amz-date: 20210617T093046Z 420113 2021-06-17T09:30:46.309Z (pid: 6806) [CURL DBG]> Content-Length: 0 ```
kerem commented 2026-03-04 01:49:36 +03:00
Author
Owner
Copy link

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

@CarstenGrohmann I fixed the code and post PR about it.
If you are not sorry to trouble you, please check it.

<!-- gh-comment-id:864508441 --> @ggtakec commented on GitHub (Jun 20, 2021): @CarstenGrohmann I fixed the code and post PR about it. If you are not sorry to trouble you, please check it.
kerem commented 2026-03-04 01:49:36 +03:00
Author
Owner
Copy link

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

@ggtakec Thank you for the fast fix. I'll test the change as well as testcase tomorrow and share the feedback.

<!-- gh-comment-id:864549323 --> @CarstenGrohmann commented on GitHub (Jun 20, 2021): @ggtakec Thank you for the fast fix. I'll test the change as well as testcase tomorrow and share the feedback.
kerem commented 2026-03-04 01:49:36 +03:00
Author
Owner
Copy link

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

@CarstenGrohmann Thanks for your feedback( https://github.com/s3fs-fuse/s3fs-fuse/pull/1689#issuecomment-864745558 )
This Issue has been resolved and will be closed.

<!-- gh-comment-id:864967869 --> @ggtakec commented on GitHub (Jun 21, 2021): @CarstenGrohmann Thanks for your feedback( https://github.com/s3fs-fuse/s3fs-fuse/pull/1689#issuecomment-864745558 ) This Issue has been resolved and will be closed.
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#875
No description provided.