dvc: dvc.api.open fails on pickle serialisation files absent from a dvc tracked directory

DEBUG: fetched: [(0,)]

This just means the id in the DVC’s state that the 1 item has been fetched.

With the target file missing from both desired location and local cache:

It means that it’s not in your workspace nor in the cache, but exists in the remote, right?

UnpicklingError: pickle data was truncated

This might be a bug in the DVC. It could happen if the network gets closed prematurely, or something similar happens. It could also happen if the pickled file is itself corrupted.

Could you try the following script? And, please modify the pickle file, so that it could be easily reproducible.

#! /bin/bash

set -e

# initialize
cd "$(mktemp -d)"
git init && dvc init

# install and run moto server locally
pip install moto[server]
moto_server s3 &> /dev/null &
trap "echo killing moto server && kill $!" EXIT  # cleanup

# create a bucket and add remote
export AWS_ACCESS_KEY_ID='testing' AWS_SECRET_ACCESS_KEY='testing'
python -c '
import boto3

session = boto3.session.Session()
s3 = session.client("s3", endpoint_url="http://localhost:5000")
s3.create_bucket(Bucket="dvc-temp")
'
dvc remote add -d moto s3://dvc-temp
dvc remote modify moto endpointurl http://localhost:5000

# create file
python -c '
import pickle
with open("model.pickle", mode="wb") as f:
    pickle.dump("hello world", f)
'

# track file
dvc add model.pickle
dvc push
git add -A && git commit -m "initial"

# clear from cache and workspace
rm model.pickle .dvc/cache/** -rf

# try to read
python -c '
import dvc.api, pickle

import logging
logger = logging.getLogger("dvc")
logger.setLevel(5)


with dvc.api.open("model.pickle", mode="rb") as f:
  msg = pickle.load(f)

print(msg)
'

Also, it’d be great if you could try out a few more things, and see if it works: 1)

import dvc.api, io, pickle

with dvc.api.open("model.pickle", mode="rb") as f:
  stream = io.BytesIO(f.read())

msg = pickle.load(stream)
print(msg)

and, 2)

import dvc.api, io, pickle

msg = pickle.load(io.BytesIO(dvc.api.read("model.pickle", mode="rb")))

Sorry that this is taking quite long to figure out, but we haven’t been able to figure out what’s wrong.

The above script should be as close to your environment with an s3 remote. Please try it out, and see if you could manage to reproduce.

@efiop issue is gone with dvc==2.0.3.

@pared the issue is not critical for me as using read is an acceptable workaround. However, as read breaks the streaming aspect, and requires loading the entire archive in RAM (as I understood from the doc, open behaves differently), there is an almost doubled peak memory consumption on model loading that might become a severe issue in the future (at least for me). Thus, I would not categories this issue as urgent but still, I think it should be fixed in a decent timeframe.

@hugo-ricateau-tiime, can confirm. Thanks for the repro.

I finally succeed to figure out what is the key aspect of the issue: the archive size; it looks like large archives are truncated when streamed from an s3 storage (maybe when the buffer gets full?).

The following diff on the suggested script:

30c30
<     pickle.dump("hello world"*1000, f)
---
>     pickle.dump("hello world", f)
39c39
< rm -rf model.pickle .dvc/cache/**
---
> rm model.pickle .dvc/cache/** -rf

results in

Initialized empty Git repository in .../.git/

You can now commit the changes to git.

+---------------------------------------------------------------------+
|                                                                     |
|        DVC has enabled anonymous aggregate usage analytics.         |
|     Read the analytics documentation (and how to opt-out) here:     |
|             <https://dvc.org/doc/user-guide/analytics>              |
|                                                                     |
+---------------------------------------------------------------------+

What's next?
------------
- Check out the documentation: <https://dvc.org/doc>
- Get help and share ideas: <https://dvc.org/chat>
- Star us on GitHub: <https://github.com/iterative/dvc>
Requirement already satisfied: [...]
Setting 'moto' as a default remote.
100% Add|██████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████|1/1 [00:00,  2.94file/s]

To track the changes with git, run:

	git add model.pickle.dvc .gitignore
1 file pushed
[master (root-commit) 501ad01] initial
 11 files changed, 525 insertions(+)
 create mode 100644 .dvc/.gitignore
 create mode 100644 .dvc/config
 create mode 100644 .dvc/plots/confusion.json
 create mode 100644 .dvc/plots/confusion_normalized.json
 create mode 100644 .dvc/plots/default.json
 create mode 100644 .dvc/plots/linear.json
 create mode 100644 .dvc/plots/scatter.json
 create mode 100644 .dvc/plots/smooth.json
 create mode 100644 .dvcignore
 create mode 100644 .gitignore
 create mode 100644 model.pickle.dvc
2020-12-09 09:31:04,689 TRACE: PRAGMA user_version;
2020-12-09 09:31:04,689 DEBUG: fetched: [(3,)]
2020-12-09 09:31:04,689 TRACE: 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-12-09 09:31:04,690 TRACE: CREATE TABLE IF NOT EXISTS state_info (count INTEGER)
2020-12-09 09:31:04,690 TRACE: CREATE TABLE IF NOT EXISTS link_state (path TEXT PRIMARY KEY, inode INTEGER NOT NULL, mtime TEXT NOT NULL)
2020-12-09 09:31:04,690 TRACE: INSERT OR IGNORE INTO state_info (count) SELECT 0 WHERE NOT EXISTS (SELECT * FROM state_info)
2020-12-09 09:31:04,690 TRACE: PRAGMA user_version = 3;
2020-12-09 09:31:04,695 DEBUG: cache '.../.dvc/cache/87/61b028bd29d9fa506a25513d0c10b9' expected 'HashInfo(name='md5', value='8761b028bd29d9fa506a25513d0c10b9', dir_info=None, size=11010, nfiles=None)' actual 'None'
2020-12-09 09:31:04,935 TRACE: SELECT count from state_info WHERE rowid=?
2020-12-09 09:31:04,935 DEBUG: fetched: [(2,)]
2020-12-09 09:31:04,935 TRACE: UPDATE state_info SET count = ? WHERE rowid = ?
Traceback (most recent call last):
  File "<string>", line 10, in <module>
_pickle.UnpicklingError: pickle data was truncated
killing moto server

Note that adding any of these diff to the previous one, workarounds the issue

43c43
< import dvc.api, io, pickle
---
> import dvc.api, pickle
51c51
<   msg = pickle.load(io.BytesIO(f.read()))
---
>   msg = pickle.load(f)

43c43
< import dvc.api, io, pickle
---
> import dvc.api, pickle
50c50,51
< msg = pickle.load(io.BytesIO(dvc.api.read("model.pickle", mode="rb")))
---
> with dvc.api.open("model.pickle", mode="rb") as f:
>   msg = pickle.load(f)

50c50,51
< msg = pickle.loads(dvc.api.read("model.pickle", mode="rb"))
---
> with dvc.api.open("model.pickle", mode="rb") as f:
>   msg = pickle.load(f)

Also note that there is no problem with a local storage (i.e. using this script with "hello world"*1000).