Rasterio: Occasional "not recognized as a supported file format" errors when reading from S3

[dionhaefner]

Lately, we have encountered a strange bug in Terracotta. It basically always leads to errors like these:

(from https://github.com/DHI-GRAS/terracotta/issues/139)

Traceback (most recent call last):
  File "rasterio/_base.pyx", line 213, in rasterio._base.DatasetBase.__init__
  File "rasterio/_shim.pyx", line 64, in rasterio._shim.open_dataset
  File "rasterio/_err.pyx", line 205, in rasterio._err.exc_wrap_pointer
rasterio._err.CPLE_OpenFailedError: '/vsis3/italy-composite/rasters/italy_2018_red.tif' not recognized as a supported file format.

or

(from https://github.com/DHI-GRAS/terracotta/issues/10#issuecomment-489826885)

Traceback (most recent call last):
  File "rasterio/_io.pyx", line 698, in rasterio._io.DatasetReaderBase._read
  File "rasterio/shim_rasterioex.pxi", line 133, in rasterio._shim.io_multi_band
  File "rasterio/_err.pyx", line 182, in rasterio._err.exc_wrap_int
rasterio._err.CPLE_AppDefinedError: IReadBlock failed at X offset 0, Y offset 0: '/vsis3/bucket/prefix/tile330.tif' does not exist in the file system, and is not recognized as a supported dataset name.

The errors occur on different versions of rasterio, although anecdotally it wasn't a problem pre-1.0.15. It also seems to occur both during rasterio.open, and when actually reading tiles via WarpedVRT.read.

The problem is that we have only observed it with huge raster files, and we haven't been able to reproduce this reliably, or in a way where I could share it with you.

I am opening this issue to see if you have some intuition why the problem might occur. If you think it just adds noise, please feel free to close it.

[sgillies]

@dionhaefner will you bring this up on the rasterio discussion group https://rasterio.groups.io/g/main ? It's sort of ringing a bell, and I think it's likely to be something you can address using the right GDAL config options that someone else will point out.

[sgillies]

@dionhaefner after releasing rasterio 1.0.24 I scanned the terracotta source looking for places where you might be accidentally sharing GDAL dataset handles between threads. I found this one which seems to be executed by a thread pool executor https://github.com/DHI-GRAS/terracotta/blob/master/terracotta/drivers/raster_base.py#L465. Unless you pass sharing=False here, you'll be reusing shared dataset handles (see "shared mode" under https://gdal.org/api/raster_c_api.html#_CPPv410GDALOpenExPKcjPPCKcPPCKcPPCKc for details).

I suggest making that change and upgrading to 1.0.24.

[dionhaefner]

Thanks for reporting back (and going through the Terracotta sources)!

I don't think our multithreading is behind this particular issue, since we only use multithreading to retrieve RGB bands in parallel, which are usually stored in different raster files. This should only matter when operating on the same raster in parallel, right?

However, nothing in Terracotta forbids users to re-use the same raster for several RGB channels, so we should definitely use sharing mode if we can.

[j08lue]

I suggest making that change and upgrading to 1.0.24.

Unfortunately, the issue is still the same with rasterio 1.0.24.

Unless you pass sharing=False here, you'll be reusing shared dataset handles

Same issue with sharing=False.

[j08lue]

Upstream discussion now in https://rasterio.groups.io/g/main/topic/31734579

[dionhaefner]

We have made some progress debugging this.

The error is still present in recent rasterio and GDAL versions. We can now reproduce it, and it seems like the critical flag is GDAL_DISABLE_READDIR_ON_OPEN (so it might be related to https://github.com/mapbox/rasterio/issues/1706). We tried the following combinations serving rasters from an S3 bucket with 17000 images:

• GDAL_DISABLE_READDIR_ON_OPEN=EMPTY_DIR: many failing tiles
• GDAL_DISABLE_READDIR_ON_OPEN=TRUE: many failing tiles
• GDAL_DISABLE_READDIR_ON_OPEN=FALSE: all good

So this may or may not be due to the flag obscuring the real error (as in #1706), or just a buggy implementation.

[Kirill888]

@dionhaefner and @j08lue I think I'm facing a similar issue.

I'm using rasterio with dask to read COGs from s3 bucket on AWS in us-west-2 and when I push number of threads per Dask worker high enough (32 is what I use on a 16 core instance) I consistently see errors. Each thread is reading a separate file and I do use sharing=False also.

RasterioIOError: Read or write failed. /vsis3/<**path**>.tif, band 1: IReadBlock failed at X offset 4, Y offset 4: TIFFReadEncodedTile() failed.

Re-running same task with fewer threads succeeds just fine, so I'm certain it's not data related. I have also confirmed it's not related to S3 throttling of any kind. I'm using GDAL_HTTP_MAX_RETRY='10' and GDAL_HTTP_RETRY_DELAY='0.5', but I could not see a single 50X response in libcurl log.

For me changing GDAL_DISABLE_READDIR_ON_OPEN had no meaningful difference, failures still happen and total processing time is not that different (our folder structure is deep with only few files per "directory", so maybe that makes list dir fast enough to not interfere with race condition).

When I configure Dask to have a single thread per worker I can run 32 workers with single-thread each just fine without problems, so I strongly suspect this is threading related and changing readdir behaviour just masks the real problem.

[sgillies]

@Kirill888 to confirm: you call rasterio.open() within each new thread?

Would you be willing to try to see if this bug manifests with a local file using 32 Dask workers? Then we could know whether to focus more on Rasterio or more on GDAL's VSI system.

[Kirill888]

@sgillies correct. I open new file within each thread and read the entire lot with a single read, or at least that's what I think is happening. I'm certainly not sharing open handles across threads, and unless Dask does speculative concurrent execution each file is processed exactly once by exactly one thread.

I'm hoping to make a reproducible failing test that calls directly to rasterio without all our stuff in the way. I will then try it with file and s3 based resources. We just a bit busy right now with some looming deadlines, and I have a working work-around (don't use threads), so it might have to wait till November. I strongly suspect that this is inside gdal though, and probably curl specific.

[kylebarron]

Just FYI for someone in the future confused by hitting these errors, I've been hitting these same errors _without_ threading when I'm reading a COG from a requester pays bucket.

It turns out that you get these errors when you assign AWS_REQUEST_PAYER using os.environ from within Python, after having failed once to read from a requester pays bucket. This fails consistently for me:

from rio_tiler.io.cogeo import tile as tiler
import os

t, m = tiler('s3://naip-analytic/az/2017/60cm/rgbir_cog/36111/m_3611149_se_12_h_20170619.tif', 3098, 6427, 14)
# access denied

os.environ['AWS_REQUEST_PAYER'] = 'requester'

t, m = tiler('s3://naip-analytic/az/2017/60cm/rgbir_cog/36111/m_3611149_se_12_h_20170619.tif', 3098, 6427, 14)
# '/vsis3/naip-analytic/az/2017/60cm/rgbir_cog/36111/m_3611149_se_12_h_20170619.tif'
# does not exist in the file system, and is not recognized as a supported dataset name.

[sgillies]

@kylebarron I think you're seeing an unintended effect of the VSI subsystem cache. If you forget to specify requester pays for a particular dataset, your cache is going to block access to that dataset until you've made enough requests to other datasets to have evicted the problematic dataset.

[glostis]

@kylebarron the issue you point out looks similar to something I reported in GDAL a few months ago, and that was fixed and included in GDAL 3.1:
https://github.com/OSGeo/gdal/issues/2294

[kylebarron]

Thanks, that's good to know. I'm still on GDAL 2.4 because I found that GDAL 3.1 was much slower for my main use case (dynamic image tiling from Lambda) (see: https://github.com/developmentseed/cogeo-mosaic-tiler/issues/4#issuecomment-604120617, https://github.com/lambgeo/docker-lambda/issues/2)

[bw4sz]

I am also experiencing this error reading from dask workers. I believe if separate workers access the same file you will get this error.

>>> rasterio.__version__
'1.1.5'

(base) [b.weinstein@dev1 DeepTreeAttention]$ gdalinfo --version
GDAL 3.0.4, released 2020/01/28

Still searching for a lock mechanism to keep workers from interrupting, or waiting until file has been closed.

[sgillies]

@bw4sz if you have been building your own rasterio module (good for you!) you won't have the fix for this. The fix is in GDAL 3.1.x (3.1.3 or 3.1.4 specifically). I have patched the GDAL 2.4.4 library included in the rasterio wheels on PyPI, so that's another way to get it.

[bw4sz]

Thanks. I'll have a look. Right now I just reduced the number of workers,
but I haven't confirmed this works. I'll update requirements and see if I
can get GDAL > 3.1. Conda can be picky with geopandas and the rest of the
stack.

On Tue, Oct 27, 2020 at 2:31 PM Sean Gillies [e-mail]
wrote:

@bw4sz https://github.com/bw4sz if you have been building your own
rasterio module (good for you!) you won't have the fix for this. The fix is
in GDAL 3.1.x (3.1.3 or 3.1.4 specifically). I have patched the GDAL 2.4.4
library included in the rasterio wheels on PyPI, so that's another way to
get it.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/mapbox/rasterio/issues/1686#issuecomment-717552170,
or unsubscribe
https://github.com/notifications/unsubscribe-auth/AAJHBLF7E63GUIIPIMA5KPLSM4327ANCNFSM4HMH3EMA
.

--
Ben Weinstein, Ph.D.
Postdoctoral Fellow
University of Florida
http://benweinstein.weebly.com/

[SalasSanchez]

I have been running into the same issue, using rasterstats==0.15.0. I upgraded rasterio in my deploy to rasterio==1.1.8.

I am still getting the "'/vsis3/xxxx.tif' not recognized as a supported file format" error message, even with a single request, and with the latest rasterio. It does not recover until I redeploy.

@sgillies, under what conditions was your fix going to help?

I am still struggling to consistently reproduce the issue. I hit the same endpoint, backed by the same lambda, with a single request, sometimes it works and sometimes it does not.

Reducing the number of workers did make it so that the issue became less frequent under load.

The tif file is rather large, though, that's for sure, it is a world-wide digital elevation model and 27GB in its compressed format, 75GB uncompressed. It is cog-ified.

All I am trying to do is this:

average = zonal_stats(vectors=aoi_geometry, raster=f's3://{dem_bucket}/{dem_identifier}', stats=['mean'])

[SalasSanchez]

@bw4sz Did you confirm the reduced number of workers fixed it? I did the same, but I still see the issue pop up now and then.

[bw4sz]

Nope, i just checked back to this thread in case anyone else had. I am also
using rasterstats.

rasterio==1.1.5
rasterstats==0.15.0
gdal 3.0.4

I'll try updating gdal now.

On Wed, Nov 4, 2020 at 10:19 AM Salas Sanchez-Bennasar <
[email protected]> wrote:

@bw4sz https://github.com/bw4sz Did you confirm the reduced number of
workers fixed it? I did the same, but I still see the issue pop up now and
then.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/mapbox/rasterio/issues/1686#issuecomment-721895009,
or unsubscribe
https://github.com/notifications/unsubscribe-auth/AAJHBLECEPNPQMD6PMKQ7NDSOGLMRANCNFSM4HMH3EMA
.

--
Ben Weinstein, Ph.D.
Postdoctoral Fellow
University of Florida
http://benweinstein.weebly.com/

[bw4sz]

Just leaving an update since I said I would. It _currently_ looks that this errors only occurs when working on dask workers. Outside of dask I cannot (yet) recreate it. Very hard to create a reproducible example in these circumstances. pip install rasterio == 1.1.8 did not change any behavior. I am meticulously rebuilding a gdal == 3.2.0 environment, since conda was being very particular. My sense right now is that this a gdal error and upstream of rasterio. Its a very large run and since i can't do it in parallel, it will take atleast a day to confirm.

[dionhaefner]

I lost overview over what configurations people are using, but our experience was this:

• Serial execution: ✔️
• Multi-threaded execution: ❌
• Multi-processing: ✔️

So we just ditched multithreading and use a process pool instead, haven't seen the error since.