`error decoding response body` after upgrade to object store 0.10

[ion-elgreco]

Describe the bug
We bumped the object store to 0.10 in delta-rs, and now we already seeing a couple reports on the following error error decoding response body. Happens on Azure and S3.

See delta-io/delta-rs#2595 and delta-io/delta-rs#2592

To Reproduce
Seems to occur when reading tables or doing operations on them.

Expected behavior
Don't have an issue decoding the response body

Additional context

@thomasfrederikhoeck @k-ye

[tustvold]

I think we would need a reproducer to action this, the linked issues aren't even clearly implicating object_store

[Xuanwo]

Please also print the source of the error via Debug print. Usually, it should be caused by connection reset or similar network related errors.

[ion-elgreco]

@thomasfrederikhoeck @k-ye can you guys provide additional details please

[thomasfrederikhoeck]

@Xuanwo I would love to be of more help but I don't now how to do this in delta-rs (an in turn object_store). I didn't help setting the timeout to 300s.

@ion-elgreco Can you point me in the direction of how I can provide better logs?

[Xuanwo]

@Xuanwo I would love to be of more help but I don't now how to do this in delta-rs (an in turn object_store). I didn't help setting the timeout to 300s.

Hi, if you can consistently reproduce this issue, please change the following places:

https://github.com/delta-io/delta-rs/blob/d17ed97b5bda0cadbc0df959f8fb38e275570c87/python/src/error.rs#L41-L51

fn object_store_to_py(err: ObjectStoreError) -> PyErr {
    match err {
        ObjectStoreError::NotFound { .. } => PyFileNotFoundError::new_err(err.to_string()),
        ObjectStoreError::Generic { source, .. }
            if source.to_string().contains("AWS_S3_ALLOW_UNSAFE_RENAME") =>
        {
            DeltaProtocolError::new_err(source.to_string())
        }
        _ => PyIOError::new_err(err.to_string()),
    }
}

Don't use err.to_string(), print it's debug message instead.

[thomasfrederikhoeck]

@Xuanwo Ah thanks!! I get the following consistently :

Generic {
    store: "MicrosoftAzure",
    source: reqwest::Error {
        kind: Decode,
        source: reqwest::Error {
            kind: Body,
            source: TimedOut,
        },
    },
}

I also tried bumping the timeout to 600s. I still get _internal.DeltaError: Failed to parse parquet: Parquet error: Z-order failed while scanning data: ArrowError(ExternalError(General("ParquetObjectReader::get_byte_ranges error: Generic MicrosoftAzure error: error decoding response body")), None) but I never hit the debug print in this case. I am however seeing a lot of

[2024-06-24T21:09:33Z INFO  object_store::client::retry] Encountered transport error backing off for 0.1 seconds, retry 1 of 10: error sending request for url (REDACTED)
[2024-06-24T21:13:00Z DEBUG hyper_util::client::legacy::client] client connection error: error shutting down connection

[Xuanwo]

[2024-06-24T21:09:33Z INFO object_store::client::retry] Encountered transport error backing off for 0.1 seconds, retry 1 of 10: error sending request for url (REDACTED)

I suspect there's an issue with the network connection between your environment and Azure.

Could you provide more details about your setup?

• Where are you conducting the tests?
• Which Azure region or zone are you using, or are you just using Azurite?
• What is the average latency and bandwidth between your location and Azure?
• Can you try using azcopy to read/write large file?

[thomasfrederikhoeck]

@Xuanwo I might be network related but I have some feeling that is related to how object_store or delta-rs handles if there is a lower throughput than within a Azure data center (some connections going stale while waiting for somthing else).

• Running from local laptop in Europe
• Azure region is Westeurope
• I just benchmarked with azcopy bench "https://ACCOUNT.blob.core.windows.net/CONTAINER?SAS" --file-count 20 --size-per-file 10000M. So 20 files of 10 Gb and here I get a throughput of 145 Mb/s. It runs through with no failures.

The benchmark took 1+ hours with no failure while the delta-rs call fails within a few minutes.

[ion-elgreco]

@Xuanwo @tustvold I can concur this also happens to us in v0.18.1/2, I can see logs in LakeFS which says "context canceled".

Somewhere in object store the connection is getting dropped constantly with large files. Can you guys give suggestions on how to debug.

For me I am connecting within a VNET in EU amsterdam

[tustvold]

Are you mixing IO with CPU bound work, I wonder if you are stalling out the tokio runtime

[ion-elgreco]

Hmm I am not sure, I started working on delta-rs a year ago and most of this FileSystem handling code was already there.

We essentially create a DeltaFileSystemHandler which we expose to Python. In python we create a DeltaStorageHandler which inherits the pyarrow FileSystemHandler methods, which we implement to call the Rust DeltaFileSystemHandler.

I think Pyarrow just calls read on an ObjectInputFile, which in rust calls get_range on the underlying object-store (https://github.com/delta-io/delta-rs/blob/c446b1287dedba122b941d8d1d4ae6290aa86d5c/python/src/filesystem.rs#L467-L495)

    fn read<'py>(&mut self, nbytes: Option<i64>, py: Python<'py>) -> PyResult<Bound<'py, PyBytes>> {
        self.check_closed()?;
        let range = match nbytes {
            Some(len) => {
                let end = i64::min(self.pos + len, self.content_length) as usize;
                std::ops::Range {
                    start: self.pos as usize,
                    end,
                }
            }
            _ => std::ops::Range {
                start: self.pos as usize,
                end: self.content_length as usize,
            },
        };
        let nbytes = (range.end - range.start) as i64;
        self.pos += nbytes;
        let data = if nbytes > 0 {
            py.allow_threads(|| {
                rt().block_on(self.store.get_range(&self.path, range))
                    .map_err(PythonError::from)
            })?
        } else {
            "".into()
        };
        // TODO: PyBytes copies the buffer. If we move away from the limited CPython
        // API (the stable C API), we could implement the buffer protocol for
        // bytes::Bytes and return this zero-copy.
        Ok(PyBytes::new_bound(py, data.as_ref()))

Here rt() just creates a runtime if it doesn't exist yet. So I don't see where here CPU bound related stuff is happening, unless I have to consider the cpu bound work in python which is done by PyArrow itself?