search

Azure / azure-storage-azcopy

The new Azure Storage data transfer utility - AzCopy v10
MIT License
613 stars 222 forks source link

Alwasy receving "File modified since transfer scheduled" even when files havnt been modified #381

Closed sfc-gh-lrobles closed 3 years ago

sfc-gh-lrobles commented 5 years ago

Which version of the AzCopy was used?

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

AzCopy 10.1.1

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

Linux, centos

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.

sync /repos/repos/base https://some_storage_account.blob.core.windows.net/repos/repos/base?si=some_permission&sig=REDACTED&sr=c&sv=2018-03-28 --delete-destination true

What problem was encountered?

trying to sync our yum repositoriers to blob storage, all the files in $repo/repodata/* fail to transfer and we receive the error "File modified since transfer scheduled"

we have confirmed the files are NOT being modified. ls -lt shows modified time as 3 days in the past

How can we reproduce the problem in the simplest way?

Have you found a mitigation/solution?

if I cd into the repodata directory and ONE BY ONE run a azcopy copy $file /remote/path/with/sas_token

command seems to fail when trying to loop through the files in the dir with a 

for file in $(ls directory); do azcopy .........
JohnRusk commented 5 years ago

Thanks @ds89snsadbf.

When you loop through the files in the directory with 

for file in $(ls directory); do azcopy .........

you mentioned that the command seems to fail. Can you share some details on that?

Also, I'm not sure I understand your comment, that contains the delete call. What should I be looking at in that comment?

sfc-gh-lrobles commented 5 years ago

My mistake on uploading the snippit with the delete call

as for the looping, it will fail on sending a file with the same "Source modified during transfer"

for file in $(ls); do /usr/local/bin/azcopy copy $file "https://some_account.blob.core.windows.net/repos/repos/treasuredata/repodata/$file?sv=2018-03-28&si=some_permisisons&sr=c&sig=xyz"; done


2019/05/14 19:36:06 OS-Environment  linux
2019/05/14 19:36:06 OS-Architecture  amd64
2019/05/14 19:36:06 Job-Command copy 40e25b406271e3ba30b9cf5890babb1ccb07b595525f1d53963cb978e5202200-other.xml.gz https://some_account.blob.core.windows.net/repos/repos/treasuredata/repodata/40e25b406271e3ba30b9cf5890babb1ccb07b595525f1d53963cb978e5202200-other.xml.gz?si=some_permissions&sig=REDACTED&sr=c&sv=2018-03-28
2019/05/14 19:36:06 Number of CPUs: 4
2019/05/14 19:36:06 Max file buffer RAM 2.000 GB
2019/05/14 19:36:06 Max open files when downloading: 3562
2019/05/14 19:36:06 Max concurrent transfer initiation routines: 64
2019/05/14 19:36:06 JobID=459c01cb-ec7b-074e-553d-3bedd02de83e, credential type: Anonymous
2019/05/14 19:36:06 scheduling JobID=459c01cb-ec7b-074e-553d-3bedd02de83e, Part#=0, Transfer#=0, priority=0
2019/05/14 19:36:06 INFO: [P#0-T#0] has worker 25 which is processing TRANSFER
2019/05/14 19:36:06 INFO: [P#0-T#0] Starting transfer: Source "40e25b406271e3ba30b9cf5890babb1ccb07b595525f1d53963cb978e5202200-other.xml.gz" Destination "https://some_account.blob.core.windows.net/repos/repos/treasuredata/repodata/40e25b406271e3ba30b9cf5890babb1ccb07b595525f1d53963cb978e5202200-other.xml.gz?si=some_permissions&sig=REDACTED&sr=c&sv=2018-03-28". Specified chunk size 8388608
2019/05/14 19:36:06 PERF: primary performance constraint is Unknown. States: R:  0, D:  0, W:  0, F:  0, B:  0, T:  0
2019/05/14 19:36:06 ==> OUTGOING REQUEST (Try=1)
   PUT https://some_account.blob.core.windows.net/repos/repos/treasuredata/repodata/40e25b406271e3ba30b9cf5890babb1ccb07b595525f1d53963cb978e5202200-other.xml.gz?si=some_permissions&sig=REDACTED&sr=c&sv=2018-03-28&timeout=901
   Content-Length: [601]
   User-Agent: [AzCopy/10.1.1 Azure-Storage/0.6 (go1.10.3; linux)]
   X-Ms-Blob-Cache-Control: []
   X-Ms-Blob-Content-Disposition: []
   X-Ms-Blob-Content-Encoding: []
   X-Ms-Blob-Content-Language: []
   X-Ms-Blob-Content-Md5: []
   X-Ms-Blob-Content-Type: [application/x-gzip]
   X-Ms-Blob-Type: [BlockBlob]
   X-Ms-Client-Request-Id: [3a177647-cae8-451f-6659-061df94e1693]
   X-Ms-Version: [2018-03-28]

2019/05/14 19:36:06 ==> REQUEST/RESPONSE (Try=1/369.618541ms, OpTime=369.842276ms) -- RESPONSE SUCCESSFULLY RECEIVED
   PUT https://some_account.blob.core.windows.net/repos/repos/treasuredata/repodata/40e25b406271e3ba30b9cf5890babb1ccb07b595525f1d53963cb978e5202200-other.xml.gz?si=some_permissions&sig=REDACTED&sr=c&sv=2018-03-28&timeout=901
   Content-Length: [601]
   User-Agent: [AzCopy/10.1.1 Azure-Storage/0.6 (go1.10.3; linux)]
   X-Ms-Blob-Cache-Control: []
   X-Ms-Blob-Content-Disposition: []
   X-Ms-Blob-Content-Encoding: []
   X-Ms-Blob-Content-Language: []
   X-Ms-Blob-Content-Md5: []
   X-Ms-Blob-Content-Type: [application/x-gzip]
   X-Ms-Blob-Type: [BlockBlob]
   X-Ms-Client-Request-Id: [3a177647-cae8-451f-6659-061df94e1693]
   X-Ms-Version: [2018-03-28]
   --------------------------------------------------------------------------------
   RESPONSE Status: 201 Created
   Content-Length: [0]
   Content-Md5: [/n4Tl63uSDL3x71A/xxbFA==]
   Date: [Tue, 14 May 2019 19:36:06 GMT]
   Etag: ["0x8D6D8A368D47180"]
   Last-Modified: [Tue, 14 May 2019 19:36:06 GMT]
   Server: [Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0]
   X-Ms-Request-Id: [654457ab-b01e-00b3-468c-0a4c91000000]
   X-Ms-Request-Server-Encrypted: [true]
   X-Ms-Version: [2018-03-28]

2019/05/14 19:36:06 ERR: [P#0-T#0] UPLOADFAILED: 40e25b406271e3ba30b9cf5890babb1ccb07b595525f1d53963cb978e5202200-other.xml.gz : 000 : source modified during transfer. When epilogueWithCleanupSendToRemote. X-Ms-Request-Id:

   Dst: https://some_account.blob.core.windows.net/repos/repos/treasuredata/repodata/40e25b406271e3ba30b9cf5890babb1ccb07b595525f1d53963cb978e5202200-other.xml.gz?si=some_permissions&sig=REDACTED&sr=c&sv=2018-03-28
2019/05/14 19:36:06 ==> OUTGOING REQUEST (Try=1)
   DELETE https://some_account.blob.core.windows.net/repos/repos/treasuredata/repodata/40e25b406271e3ba30b9cf5890babb1ccb07b595525f1d53963cb978e5202200-other.xml.gz?si=some_permissions&sig=REDACTED&sr=c&sv=2018-03-28&timeout=30
   User-Agent: [AzCopy/10.1.1 Azure-Storage/0.6 (go1.10.3; linux)]
   X-Ms-Client-Request-Id: [a2cdbf2e-47ae-4acd-7d93-ca2ea3c1a721]
   X-Ms-Version: [2018-11-09]

2019/05/14 19:36:07 ==> REQUEST/RESPONSE (Try=1/83.270747ms, OpTime=83.379468ms) -- RESPONSE SUCCESSFULLY RECEIVED
   DELETE https://some_account.blob.core.windows.net/repos/repos/treasuredata/repodata/40e25b406271e3ba30b9cf5890babb1ccb07b595525f1d53963cb978e5202200-other.xml.gz?si=some_permissions&sig=REDACTED&sr=c&sv=2018-03-28&timeout=30
   User-Agent: [AzCopy/10.1.1 Azure-Storage/0.6 (go1.10.3; linux)]
   X-Ms-Client-Request-Id: [a2cdbf2e-47ae-4acd-7d93-ca2ea3c1a721]
   X-Ms-Version: [2018-11-09]
   --------------------------------------------------------------------------------
   RESPONSE Status: 202 Accepted
   Content-Length: [0]
   Date: [Tue, 14 May 2019 19:36:06 GMT]
   Server: [Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0]
   X-Ms-Delete-Type-Permanent: [true]
   X-Ms-Request-Id: [654457da-b01e-00b3-708c-0a4c91000000]
   X-Ms-Version: [2018-11-09]

2019/05/14 19:36:07 JobID=459c01cb-ec7b-074e-553d-3bedd02de83e, Part#=0, TransfersDone=1 of 1
2019/05/14 19:36:07 all parts of Job 459c01cb-ec7b-074e-553d-3bedd02de83e successfully completed, cancelled or paused
2019/05/14 19:36:08 PERF: primary performance constraint is Unknown. States: R:  0, D:  0, W:  0, F:  0, B:  0, T:  0```
JohnRusk commented 5 years ago

That is super-informative, thank you. Could you do me a favour please, could you run stat on one of the affected files, e.g.

stat 40e25b406271e3ba30b9cf5890babb1ccb07b595525f1d53963cb978e5202200-other.xml.gz

Could you reply here with the output of that (or, if you prefer, email it to me)?

sfc-gh-lrobles commented 5 years ago 
stat 40e25b406271e3ba30b9cf5890babb1ccb07b595525f1d53963cb978e5202200-other.xml.gz
  File: `40e25b406271e3ba30b9cf5890babb1ccb07b595525f1d53963cb978e5202200-other.xml.gz'
  Size: 601         Blocks: 2          IO Block: 131072 regular file
Device: 11h/17d Inode: 11331299528704836854  Links: 1
Access: (0644/-rw-r--r--)  Uid: (  505/ yumrepo)   Gid: (  506/ yumrepo)
Access: 2019-05-14 20:19:37.666769320 +0000
Modify: 2019-05-14 20:19:38.666741242 +0000
Change: 2019-05-14 20:19:39.174726944 +0000
JohnRusk commented 5 years ago

Interesting. Those dates look like they may be after you last ran AzCopy, but some minutes before you ran stat. Have I got that right? And is that what you expected? I.e. the files are changing, or at least being reported as changed, in the fairly recent past. I'm not sure this explains the behavior you're seeing in AzCopy, but maybe its a lead.

sfc-gh-lrobles commented 5 years ago

they seem to be reported as modifiedj/accessed as soon as i run an azcopy, ie, when i do the looping method, and ls all files in the directory, im wondering if thats triggering the change

JohnRusk commented 5 years ago

You mean the results of stat actually change after running your looping method? If so, does that still happen if you remove the call to azcopy and just do the ls?

xuanruiqi commented 5 years ago

I'm having this problem too. However, for me, the results of stat did not change, it's just azcopy complaining. I noted that that all the problematic files are symlinks, all other files are OK.

JohnRusk commented 5 years ago

@xuanruiqi Can you confirm exactly which version number you are using, and which OS?

xuanruiqi commented 5 years ago

Arch Linux, azcopy v10.2.1.

xuanruiqi commented 5 years ago

My issue is probably a different issue; a new issue might be more appropriate. But I can stay here too.

JohnRusk commented 5 years ago

OK. Can you log a new issue please, if you have not done so already.

JohnRusk commented 5 years ago

@ds89snsadbf How's this issue for you now? Any answer to the question I asked on May 15? Or shall we just close the issue?

JohnRusk commented 5 years ago

For the record, @xuanruiqi 's separate issue is here: #488

fhl13 commented 5 years ago

I have this same issue. I am copying veeam backup files from a Buffalo Terastation to azure blob using azcopy 10.2.1.

Some files fail immediately every time with the error "File modified since transfer scheduled". The file has not actually been modified.

fhl13 commented 5 years ago

I am using azcopy on server 2016.

Running "azcopy sync" command.

JohnRusk commented 4 years ago

We don't have an reproduction of this at this stage. We are planning a small tweak to the change detection logic in version 10.4. That might help with the issue reported here, so I'll mark this with the 10.4 milestone.

amsword commented 4 years ago

i have also seen this issue a lot. Luckily, azcopy v8 works.

adreed-msft commented 4 years ago

Hi there, would you mind testing again, now that 10.4 has been released?

JohnRusk commented 4 years ago

The small tweak mentioned above, had to be deferred to 10.5

zezha-msft commented 3 years ago

Closing due to inactivity.

vlizanae commented 1 year ago

I'm having this same issue in azcopy 10.11.0 running on Docker (CentOS 7 image). I have a directory structure and files over 74 mb fail complaining source modified during transfer. I run the stat and it doesn't seem the data has been modified in the last days, access to the file should not matter. If I increase the block size so it's larger than the largest file size it fails with the same error, but also transfers the file to the storage and it seems ok.

JohnRusk commented 1 year ago

@vlizanae Because this issue is closed, I recommend you make a new one for your instance of the problem.