Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

The --preserve-posix-properties only works copying to BLOB stroage #2497

Closed
edwardsp opened this issue Dec 12, 2023 · 4 comments · Fixed by #2533
Closed

The --preserve-posix-properties only works copying to BLOB stroage #2497

edwardsp opened this issue Dec 12, 2023 · 4 comments · Fixed by #2533
Assignees
@gapra-msft
Labels
bug fixed-in-dev

Comments

@edwardsp
Copy link

Which version of the AzCopy was used?

Note: The version is visible when running AzCopy without any argument

AzCopy 10.22.0

Which platform are you using? (ex: Windows, Mac, Linux)

Linux

What command did you run?

Note: Please remove the SAS to avoid exposing your credentials. If you cannot remember the exact command, please retrieve it from the beginning of the log file.
# copy file to storage (this works - properties show in metadata)
azcopy cp --preserve-posix-properties testfile https://${account}.blob.core.windows.net/${container}

# copy back from storage (properties are not set on the local file)
azcopy cp --preserve-posix-properties https://${account}.blob.core.windows.net/${container}/testfile .

What problem was encountered?

The --preserve-posix-properties flag only works copying to BLOB stroage

How can we reproduce the problem in the simplest way?

See above

Have you found a mitigation/solution?

No
@gapra-msft
Copy link
Member

@edwardsp Could you please share debug level logs for the AzCopy command when you are trying to download?

@gapra-msft gapra-msft self-assigned this Dec 12, 2023
@edwardsp
Copy link
Author

@gapra-msft Here is the log:

2023/12/13 14:40:33 AzcopyVersion  10.22.0
2023/12/13 14:40:33 OS-Environment  linux
2023/12/13 14:40:33 OS-Architecture  amd64
2023/12/13 14:40:33 Log times are in UTC. Local time is 13 Dec 2023 14:40:33
2023/12/13 14:40:33 ISO 8601 START TIME: to copy files that changed before or after this job started, use the parameter --include-before=2023-12-13T14:40:28Z or --include-after=2023-12-13T14:40:28Z
2023/12/13 14:40:33 Any empty folders will not be processed, because --recursive was not specified
2023/12/13 14:40:33 Job-Command --log-level DEBUG cp --preserve-posix-properties https://ACCOUNTNAME.blob.core.windows.net/test/testfile?SASKEY . 
2023/12/13 14:40:33 Number of CPUs: 8
2023/12/13 14:40:33 Max file buffer RAM 4.000 GB
2023/12/13 14:40:33 Max concurrent network operations: 128 (Based on number of CPUs. Set AZCOPY_CONCURRENCY_VALUE environment variable to override)
2023/12/13 14:40:33 Check CPU usage when dynamically tuning concurrency: true (Based on hard-coded default. Set AZCOPY_TUNE_TO_CPU environment variable to true or false override)
2023/12/13 14:40:33 Max concurrent transfer initiation routines: 64 (Based on hard-coded default. Set AZCOPY_CONCURRENT_FILES environment variable to override)
2023/12/13 14:40:33 Max enumeration routines: 16 (Based on hard-coded default. Set AZCOPY_CONCURRENT_SCAN environment variable to override)
2023/12/13 14:40:33 Parallelize getting file properties (file.Stat): false (Based on AZCOPY_PARALLEL_STAT_FILES environment variable)
2023/12/13 14:40:33 Max open files when downloading: 1048047 (auto-computed)
2023/12/13 14:40:33 Final job part has been created
2023/12/13 14:40:33 scheduling JobID=4c1e280f-e215-e646-64a6-3f28089aa129, Part#=0, Transfer#=0, priority=0
2023/12/13 14:40:33 Final job part has been scheduled
2023/12/13 14:40:33 DBG: [P#0-T#0] has worker 63 which is processing TRANSFER 0
2023/12/13 14:40:33 DBG: [P#0-T#0] https://ACCOUNTNAME.blob.core.windows.net/test/testfile destination modified flag is set to true Dst: /home/paul/testfile
2023/12/13 14:40:34 ==> OUTGOING REQUEST (Try=1)
   GET https://ACCOUNTNAME.blob.core.windows.net/test/testfile?SASKEY
   Accept: application/xml
   If-Unmodified-Since: Wed, 13 Dec 2023 14:33:56 GMT
   User-Agent: AzCopy/10.22.0 azsdk-go-service.Client/v1.2.0 (go1.19.12; linux)
   X-Ms-Client-Request-Id: 0fdc96f7-1f39-410e-4284-b80b2f7828d6
   x-ms-range: bytes=0-8388607
   x-ms-version: 2023-08-03

2023/12/13 14:40:34 ==> OUTGOING REQUEST (Try=1)
   GET https://ACCOUNTNAME.blob.core.windows.net/test/testfile?SASKEY
   Accept: application/xml
   If-Unmodified-Since: Wed, 13 Dec 2023 14:33:56 GMT
   User-Agent: AzCopy/10.22.0 azsdk-go-service.Client/v1.2.0 (go1.19.12; linux)
   X-Ms-Client-Request-Id: 342b8af1-e309-42b9-56c9-6fb4a4b40633
   x-ms-range: bytes=25165824-27040669
   x-ms-version: 2023-08-03

2023/12/13 14:40:34 ==> OUTGOING REQUEST (Try=1)
   GET https://ACCOUNTNAME.blob.core.windows.net/test/testfile?SASKEY
   Accept: application/xml
   If-Unmodified-Since: Wed, 13 Dec 2023 14:33:56 GMT
   User-Agent: AzCopy/10.22.0 azsdk-go-service.Client/v1.2.0 (go1.19.12; linux)
   X-Ms-Client-Request-Id: 99828620-077b-4d68-40bd-e023aa9d779a
   x-ms-range: bytes=8388608-16777215
   x-ms-version: 2023-08-03

2023/12/13 14:40:34 ==> OUTGOING REQUEST (Try=1)
   GET https://ACCOUNTNAME.blob.core.windows.net/test/testfile?SASKEY
   Accept: application/xml
   If-Unmodified-Since: Wed, 13 Dec 2023 14:33:56 GMT
   User-Agent: AzCopy/10.22.0 azsdk-go-service.Client/v1.2.0 (go1.19.12; linux)
   X-Ms-Client-Request-Id: 5f50f1ce-edb8-4192-4f99-30726225a58e
   x-ms-range: bytes=16777216-25165823
   x-ms-version: 2023-08-03

2023/12/13 14:40:34 ==> REQUEST/RESPONSE (Try=1/57.005718ms, OpTime=66.961006ms) -- RESPONSE SUCCESSFULLY RECEIVED
   GET https://ACCOUNTNAME.blob.core.windows.net/test/testfile?SASKEY
   Accept: application/xml
   If-Unmodified-Since: Wed, 13 Dec 2023 14:33:56 GMT
   User-Agent: AzCopy/10.22.0 azsdk-go-service.Client/v1.2.0 (go1.19.12; linux)
   X-Ms-Client-Request-Id: 342b8af1-e309-42b9-56c9-6fb4a4b40633
   x-ms-range: bytes=25165824-27040669
   x-ms-version: 2023-08-03
   --------------------------------------------------------------------------------
   RESPONSE Status: 206 Partial Content
   Accept-Ranges: bytes
   Content-Length: 1874846
   Content-Range: bytes 25165824-27040669/27040670
   Content-Type: application/x-gzip
   Date: Wed, 13 Dec 2023 14:40:33 GMT
   Etag: "0x8DBFBE889BF91D1"
   Last-Modified: Wed, 13 Dec 2023 14:33:56 GMT
   Server: Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
   X-Ms-Blob-Type: BlockBlob
   X-Ms-Client-Request-Id: 342b8af1-e309-42b9-56c9-6fb4a4b40633
   X-Ms-Creation-Time: Wed, 13 Dec 2023 14:33:56 GMT
   X-Ms-Group: $superuser
   X-Ms-Lease-State: available
   X-Ms-Lease-Status: unlocked
   X-Ms-Meta-Linux_attribute: 0
   X-Ms-Meta-Linux_attribute_mask: 3160180
   X-Ms-Meta-Linux_btime: 1702376209077248285
   X-Ms-Meta-Linux_statx_mask: 8191
   X-Ms-Meta-Modtime: 1702376209109248073
   X-Ms-Meta-Permissions: 33257
   X-Ms-Meta-Posix_atime: 1702478036104313337
   X-Ms-Meta-Posix_ctime: 1702376216773153924
   X-Ms-Meta-Posix_dev: 2049
   X-Ms-Meta-Posix_group: 1000
   X-Ms-Meta-Posix_ino: 258058
   X-Ms-Meta-Posix_nlink: 1
   X-Ms-Meta-Posix_owner: 1000
   X-Ms-Owner: $superuser
   X-Ms-Permissions: rw-r-----
   X-Ms-Request-Id: 195f8edc-201e-0035-3ad2-2dae37000000
   X-Ms-Resource-Type: file
   X-Ms-Server-Encrypted: true
   X-Ms-Version: 2023-08-03

2023/12/13 14:40:34 ==> REQUEST/RESPONSE (Try=1/72.795665ms, OpTime=84.761973ms) -- RESPONSE SUCCESSFULLY RECEIVED
   GET https://ACCOUNTNAME.blob.core.windows.net/test/testfile?SASKEY
   Accept: application/xml
   If-Unmodified-Since: Wed, 13 Dec 2023 14:33:56 GMT
   User-Agent: AzCopy/10.22.0 azsdk-go-service.Client/v1.2.0 (go1.19.12; linux)
   X-Ms-Client-Request-Id: 0fdc96f7-1f39-410e-4284-b80b2f7828d6
   x-ms-range: bytes=0-8388607
   x-ms-version: 2023-08-03
   --------------------------------------------------------------------------------
   RESPONSE Status: 206 Partial Content
   Accept-Ranges: bytes
   Content-Length: 8388608
   Content-Range: bytes 0-8388607/27040670
   Content-Type: application/x-gzip
   Date: Wed, 13 Dec 2023 14:40:33 GMT
   Etag: "0x8DBFBE889BF91D1"
   Last-Modified: Wed, 13 Dec 2023 14:33:56 GMT
   Server: Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
   X-Ms-Blob-Type: BlockBlob
   X-Ms-Client-Request-Id: 0fdc96f7-1f39-410e-4284-b80b2f7828d6
   X-Ms-Creation-Time: Wed, 13 Dec 2023 14:33:56 GMT
   X-Ms-Group: $superuser
   X-Ms-Lease-State: available
   X-Ms-Lease-Status: unlocked
   X-Ms-Meta-Linux_attribute: 0
   X-Ms-Meta-Linux_attribute_mask: 3160180
   X-Ms-Meta-Linux_btime: 1702376209077248285
   X-Ms-Meta-Linux_statx_mask: 8191
   X-Ms-Meta-Modtime: 1702376209109248073
   X-Ms-Meta-Permissions: 33257
   X-Ms-Meta-Posix_atime: 1702478036104313337
   X-Ms-Meta-Posix_ctime: 1702376216773153924
   X-Ms-Meta-Posix_dev: 2049
   X-Ms-Meta-Posix_group: 1000
   X-Ms-Meta-Posix_ino: 258058
   X-Ms-Meta-Posix_nlink: 1
   X-Ms-Meta-Posix_owner: 1000
   X-Ms-Owner: $superuser
   X-Ms-Permissions: rw-r-----
   X-Ms-Request-Id: 5f7111a1-301e-0074-7fd2-2df6d3000000
   X-Ms-Resource-Type: file
   X-Ms-Server-Encrypted: true
   X-Ms-Version: 2023-08-03

2023/12/13 14:40:34 ==> REQUEST/RESPONSE (Try=1/74.403525ms, OpTime=86.266456ms) -- RESPONSE SUCCESSFULLY RECEIVED
   GET https://ACCOUNTNAME.blob.core.windows.net/test/testfile?SASKEY
   Accept: application/xml
   If-Unmodified-Since: Wed, 13 Dec 2023 14:33:56 GMT
   User-Agent: AzCopy/10.22.0 azsdk-go-service.Client/v1.2.0 (go1.19.12; linux)
   X-Ms-Client-Request-Id: 5f50f1ce-edb8-4192-4f99-30726225a58e
   x-ms-range: bytes=16777216-25165823
   x-ms-version: 2023-08-03
   --------------------------------------------------------------------------------
   RESPONSE Status: 206 Partial Content
   Accept-Ranges: bytes
   Content-Length: 8388608
   Content-Range: bytes 16777216-25165823/27040670
   Content-Type: application/x-gzip
   Date: Wed, 13 Dec 2023 14:40:34 GMT
   Etag: "0x8DBFBE889BF91D1"
   Last-Modified: Wed, 13 Dec 2023 14:33:56 GMT
   Server: Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
   X-Ms-Blob-Type: BlockBlob
   X-Ms-Client-Request-Id: 5f50f1ce-edb8-4192-4f99-30726225a58e
   X-Ms-Creation-Time: Wed, 13 Dec 2023 14:33:56 GMT
   X-Ms-Group: $superuser
   X-Ms-Lease-State: available
   X-Ms-Lease-Status: unlocked
   X-Ms-Meta-Linux_attribute: 0
   X-Ms-Meta-Linux_attribute_mask: 3160180
   X-Ms-Meta-Linux_btime: 1702376209077248285
   X-Ms-Meta-Linux_statx_mask: 8191
   X-Ms-Meta-Modtime: 1702376209109248073
   X-Ms-Meta-Permissions: 33257
   X-Ms-Meta-Posix_atime: 1702478036104313337
   X-Ms-Meta-Posix_ctime: 1702376216773153924
   X-Ms-Meta-Posix_dev: 2049
   X-Ms-Meta-Posix_group: 1000
   X-Ms-Meta-Posix_ino: 258058
   X-Ms-Meta-Posix_nlink: 1
   X-Ms-Meta-Posix_owner: 1000
   X-Ms-Owner: $superuser
   X-Ms-Permissions: rw-r-----
   X-Ms-Request-Id: 6503b28b-c01e-004f-74d2-2db377000000
   X-Ms-Resource-Type: file
   X-Ms-Server-Encrypted: true
   X-Ms-Version: 2023-08-03

2023/12/13 14:40:34 ==> REQUEST/RESPONSE (Try=1/78.878111ms, OpTime=91.757538ms) -- RESPONSE SUCCESSFULLY RECEIVED
   GET https://ACCOUNTNAME.blob.core.windows.net/test/testfile?SASKEY
   Accept: application/xml
   If-Unmodified-Since: Wed, 13 Dec 2023 14:33:56 GMT
   User-Agent: AzCopy/10.22.0 azsdk-go-service.Client/v1.2.0 (go1.19.12; linux)
   X-Ms-Client-Request-Id: 99828620-077b-4d68-40bd-e023aa9d779a
   x-ms-range: bytes=8388608-16777215
   x-ms-version: 2023-08-03
   --------------------------------------------------------------------------------
   RESPONSE Status: 206 Partial Content
   Accept-Ranges: bytes
   Content-Length: 8388608
   Content-Range: bytes 8388608-16777215/27040670
   Content-Type: application/x-gzip
   Date: Wed, 13 Dec 2023 14:40:33 GMT
   Etag: "0x8DBFBE889BF91D1"
   Last-Modified: Wed, 13 Dec 2023 14:33:56 GMT
   Server: Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0
   X-Ms-Blob-Type: BlockBlob
   X-Ms-Client-Request-Id: 99828620-077b-4d68-40bd-e023aa9d779a
   X-Ms-Creation-Time: Wed, 13 Dec 2023 14:33:56 GMT
   X-Ms-Group: $superuser
   X-Ms-Lease-State: available
   X-Ms-Lease-Status: unlocked
   X-Ms-Meta-Linux_attribute: 0
   X-Ms-Meta-Linux_attribute_mask: 3160180
   X-Ms-Meta-Linux_btime: 1702376209077248285
   X-Ms-Meta-Linux_statx_mask: 8191
   X-Ms-Meta-Modtime: 1702376209109248073
   X-Ms-Meta-Permissions: 33257
   X-Ms-Meta-Posix_atime: 1702478036104313337
   X-Ms-Meta-Posix_ctime: 1702376216773153924
   X-Ms-Meta-Posix_dev: 2049
   X-Ms-Meta-Posix_group: 1000
   X-Ms-Meta-Posix_ino: 258058
   X-Ms-Meta-Posix_nlink: 1
   X-Ms-Meta-Posix_owner: 1000
   X-Ms-Owner: $superuser
   X-Ms-Permissions: rw-r-----
   X-Ms-Request-Id: 23599ad1-301e-0039-38d2-2d393f000000
   X-Ms-Resource-Type: file
   X-Ms-Server-Encrypted: true
   X-Ms-Version: 2023-08-03

2023/12/13 14:40:34 WARN: [P#0-T#0] https://ACCOUNTNAME.blob.core.windows.net/test/testfile no MD5 was stored in the Blob/File service against this file. So the downloaded data cannot be MD5-validated. Dst: /home/paul/testfile
2023/12/13 14:40:34 INFO: [P#0-T#0] DOWNLOADSUCCESSFUL: /home/paul/testfile
2023/12/13 14:40:34 DBG: [P#0-T#0] Finalizing Transfer
2023/12/13 14:40:34 JobID=4c1e280f-e215-e646-64a6-3f28089aa129, Part#=0, TransfersDone=1 of 1
2023/12/13 14:40:34 all parts of entire Job 4c1e280f-e215-e646-64a6-3f28089aa129 successfully completed, cancelled or paused
2023/12/13 14:40:34 is part of Job which 1 total number of parts done 
2023/12/13 14:40:35 PERF: primary performance constraint is Unknown. States: C:  0, R:  0, W:  0, F:  0, H:  0, B:  0, S:  0, P:  0, Q:  0, D:  0, E:  0, T:  0, GRs: 128
2023/12/13 14:40:35 100.0 %, 1 Done, 0 Failed, 0 Pending, 0 Skipped, 1 Total, 2-sec Throughput (Mb/s): 108.0933
2023/12/13 14:40:35 

Diagnostic stats:
IOPS: 0
End-to-end ms per request: 0
Network Errors: 0.00%
Server Busy: 0.00%


Job 4c1e280f-e215-e646-64a6-3f28089aa129 summary
Elapsed Time (Minutes): 0.0334
Number of File Transfers: 1
Number of Folder Property Transfers: 0
Number of Symlink Transfers: 0
Total Number of Transfers: 1
Number of File Transfers Completed: 1
Number of Folder Transfers Completed: 0
Number of File Transfers Failed: 0
Number of Folder Transfers Failed: 0
Number of File Transfers Skipped: 0
Number of Folder Transfers Skipped: 0
TotalBytesTransferred: 27040670
Final Job Status: Completed

2023/12/13 14:40:35 Closing Log

@gapra-msft
Copy link
Member

@edwardsp Thanks for sharing the log, I think I have an idea as to what is going on here. We will work on getting a reproduction and fix as soon as we can.

Future dev notes: common.unixStatAdapter.ReadStatFromMetadata does not take into account that the metadata could be returned with an initial capital letter, and I believe that is where the issue is for this bug.

@gapra-msft gapra-msft added the bug label Dec 13, 2023
@gapra-msft gapra-msft linked a pull request Jan 9, 2024 that will close this issue
Standardize metadata handling to deal with capitalization #2533
Merged
@gapra-msft gapra-msft mentioned this issue Jan 9, 2024
Merged
@gapra-msft
Copy link
Member

Closing this issue as a PR was merged that will be released as part of 10.23.0 which will resolve this issue.

@BrewTestBot BrewTestBot mentioned this issue Jan 29, 2024
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@gapra-msft gapra-msft

Labels
bug fixed-in-dev
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Standardize metadata handling to deal with capitalization Azure/azure-storage-azcopy
2 participants
@edwardsp @gapra-msft