adding external data on S3 fails

[shcheklein]

To keep track of the problem:

https://discordapp.com/channels/485586884165107732/485596304961962003/678284389230182430

the data set i'm trying to add is an LDC data set
in s3://BUCKET/LDC/LDC96T17/ there's only one directory
callhome_spanish_trans_970711
adding s3://BUCKET/LDC/LDC96T17/ fails
adding s3://BUCKET/LDC/LDC96T17/callhome_spanish_trans_970711/ work

more context here:

https://discordapp.com/channels/485586884165107732/485596304961962003/678261668723032075

ERROR: s3://<BUCKET>/dvc_cache/da/8ae919cf1e2400af35eae297eacd67 does not exist: An error occurred (404) when calling the HeadObject operation: Not Found

[efiop]

@shcheklein It is probably some kind of acl issue, I don't think the problem is on dvc side.

[efiop]

Closing for now, as we've suggested an alternative approach and there is not enough info to pinpoint the issue more than we've done already.

[efiop]

Missed some details, reopening.

[shcheklein]

Was able to reproduce the part with "Removing ...":

(.env) [ivan@ivan ~/Projects/test-ext-dep]$ aws s3 ls s3://dvc-temp/cache/
                           PRE b9/

then:

(.env) [ivan@ivan ~/Projects/test-ext-dep]$ dvc add -v s3://dvc-temp/ivan/configure.sh
2020-02-15 18:24:20,283 DEBUG: PRAGMA user_version;
2020-02-15 18:24:20,285 DEBUG: fetched: [(3,)]
2020-02-15 18:24:20,285 DEBUG: CREATE TABLE IF NOT EXISTS state (inode INTEGER PRIMARY KEY, mtime TEXT NOT NULL, size TEXT NOT NULL, md5 TEXT NOT NULL, timestamp TEXT NOT NULL)
2020-02-15 18:24:20,286 DEBUG: CREATE TABLE IF NOT EXISTS state_info (count INTEGER)
2020-02-15 18:24:20,286 DEBUG: CREATE TABLE IF NOT EXISTS link_state (path TEXT PRIMARY KEY, inode INTEGER NOT NULL, mtime TEXT NOT NULL)
2020-02-15 18:24:20,286 DEBUG: INSERT OR IGNORE INTO state_info (count) SELECT 0 WHERE NOT EXISTS (SELECT * FROM state_info)
2020-02-15 18:24:20,287 DEBUG: PRAGMA user_version = 3;
2020-02-15 18:24:20,361 DEBUG: Path .dvc/cache/27/5dc5b7c7d03ded4193f55a8836e316 inode 60745619
2020-02-15 18:24:20,361 DEBUG: SELECT mtime, size, md5, timestamp from state WHERE inode=?
2020-02-15 18:24:20,361 DEBUG: fetched: [('1578506993901407232', '3187', '275dc5b7c7d03ded4193f55a8836e316', '1581810849255110912')]
2020-02-15 18:24:20,362 DEBUG: UPDATE state SET timestamp = ? WHERE inode = ?
2020-02-15 18:24:20,362 DEBUG: cache '.dvc/cache/27/5dc5b7c7d03ded4193f55a8836e316' expected '275dc5b7c7d03ded4193f55a8836e316' actual '275dc5b7c7d03ded4193f55a8836e316'
2020-02-15 18:24:20,363 DEBUG: Path configure.sh inode 60752984
2020-02-15 18:24:20,363 DEBUG: SELECT mtime, size, md5, timestamp from state WHERE inode=?
2020-02-15 18:24:20,363 DEBUG: fetched: [('1578506993901407232', '3187', '275dc5b7c7d03ded4193f55a8836e316', '1581810849254287872')]
2020-02-15 18:24:20,364 DEBUG: UPDATE state SET timestamp = ? WHERE inode = ?
2020-02-15 18:24:21,253 DEBUG: {'s3://dvc-temp/ivan/configure.sh': 'modified'}
2020-02-15 18:24:21,362 DEBUG: Computed stage 'configure.sh.dvc' md5: 'b74bc306405e05917ac37442dfeeef4e'
2020-02-15 18:24:21,368 DEBUG: Saving 's3://dvc-temp/ivan/configure.sh' to 's3://dvc-temp/cache/27/5dc5b7c7d03ded4193f55a8836e316'.
2020-02-15 18:24:21,698 DEBUG: cache 's3://dvc-temp/cache/27/5dc5b7c7d03ded4193f55a8836e316' expected '275dc5b7c7d03ded4193f55a8836e316' actual 'None'
2020-02-15 18:24:21,891 DEBUG: Removing s3://dvc-temp/ivan/configure.sh
2020-02-15 18:24:22,379 DEBUG: Created 'copy': s3://dvc-temp/cache/27/5dc5b7c7d03ded4193f55a8836e316 -> s3://dvc-temp/ivan/configure.sh
2020-02-15 18:24:22,381 DEBUG: Saving information to 'configure.sh.dvc'.
100% Add|██████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████|1/1 [00:02,  2.10s/file]

To track the changes with git, run:

	git add configure.sh.dvc
2020-02-15 18:24:22,389 DEBUG: SELECT count from state_info WHERE rowid=?
2020-02-15 18:24:22,389 DEBUG: fetched: [(7,)]
2020-02-15 18:24:22,389 DEBUG: UPDATE state_info SET count = ? WHERE rowid = ?

cache after that:

(.env) [ivan@ivan ~/Projects/test-ext-dep]$ aws s3 ls s3://dvc-temp/cache/
                           PRE 27/
                           PRE b9/

When you run it second time:

2020-02-15 18:28:16,533 DEBUG: PRAGMA user_version;
2020-02-15 18:28:16,535 DEBUG: fetched: [(3,)]
2020-02-15 18:28:16,535 DEBUG: CREATE TABLE IF NOT EXISTS state (inode INTEGER PRIMARY KEY, mtime TEXT NOT NULL, size TEXT NOT NULL, md5 TEXT NOT NULL, timestamp TEXT NOT NULL)
2020-02-15 18:28:16,537 DEBUG: CREATE TABLE IF NOT EXISTS state_info (count INTEGER)
2020-02-15 18:28:16,537 DEBUG: CREATE TABLE IF NOT EXISTS link_state (path TEXT PRIMARY KEY, inode INTEGER NOT NULL, mtime TEXT NOT NULL)
2020-02-15 18:28:16,537 DEBUG: INSERT OR IGNORE INTO state_info (count) SELECT 0 WHERE NOT EXISTS (SELECT * FROM state_info)
2020-02-15 18:28:16,538 DEBUG: PRAGMA user_version = 3;
2020-02-15 18:28:16,994 DEBUG: cache 's3://dvc-temp/cache/27/5dc5b7c7d03ded4193f55a8836e316' expected '275dc5b7c7d03ded4193f55a8836e316' actual '275dc5b7c7d03ded4193f55a8836e316'
2020-02-15 18:28:17,349 DEBUG: Saving 's3://dvc-temp/ivan/configure.sh' to 's3://dvc-temp/cache/27/5dc5b7c7d03ded4193f55a8836e316'.
2020-02-15 18:28:17,575 DEBUG: cache 's3://dvc-temp/cache/27/5dc5b7c7d03ded4193f55a8836e316' expected '275dc5b7c7d03ded4193f55a8836e316' actual '275dc5b7c7d03ded4193f55a8836e316'
2020-02-15 18:28:17,575 DEBUG: Removing s3://dvc-temp/ivan/configure.sh
2020-02-15 18:28:17,995 DEBUG: Created 'copy': s3://dvc-temp/cache/27/5dc5b7c7d03ded4193f55a8836e316 -> s3://dvc-temp/ivan/configure.sh
Stage is cached, skipping.
  0% Add|                                                                                                                                                                          |0/0 [00:01,     ?file/s]
2020-02-15 18:28:18,357 DEBUG: SELECT count from state_info WHERE rowid=?
2020-02-15 18:28:18,358 DEBUG: fetched: [(7,)]
2020-02-15 18:28:18,358 DEBUG: UPDATE state_info SET count = ? WHERE rowid = ?

We need to check why Removing s3://dvc-temp/ivan/configure.sh is in the logs - both times. We need to be sure that we don't create a copy two times.

[shcheklein]

Don't see a reasonable explanation for these problems so far, would need way more info about config

An error occurred (404) when calling the HeadObject operation: Not Found (considering that aws ls works and considering that it happens on some object in cache and it data)

and

2020-02-15 16:57:52,715 DEBUG: cache 's3://<BUCKET>/dvc-cache/c9/863800000b3f4f2d52e5f964d3cd09' expected 'c9863800000b3f4f2d52e5f964d3cd09' actual 'None'                                                                                                                                                                   
2020-02-15 16:57:53,532 DEBUG: Removing s3://<BUCKET>/DATA_PATH/transcrp/devtest/sp_1930.txt                                                                                                                                                                                                
2020-02-15 16:57:55,275 DEBUG: Cache type 'copy' is not supported: s3://<BUCKET>/DATA_PATH/transcrp/devtest/sp_1930.txt does not exist                                                                                                                                                      
Adding...          

[skshetry]

@shcheklein, @efiop, Do we have more information regarding the original issue?