Rasterio: vsis3 cache not cleared after AWS credentials/region change

[glostis]

Expected behavior and actual behavior.

Sorry for the unclear title of the issue, it isn't easy to describe in a single sentence.

The situation I encounter is the following: in a given Python session, if I get a RasterioIOError while trying to open a file on S3 (due to a CPLE_AWSSignatureDoesNotMatchError error triggered by an incorrect region name for example), I will keep getting a RasterioIOError on any subsequent open on the same file in the same Python session, regardless of the fact that I have changed my region name to the correct one. The only way to fix the problem is to restart a new Python session.

It seems like rasterio/GDAL is not trying to perform the request on the second open, it spits out the error as if it had "cached" the fact that such a request had previously lead to an error.
I have tried to play with the VSI_CACHE config option, but to no avail.

Steps to reproduce the problem.

The most illustrative example of this issue is with a local OpenIO instance, that exposes an S3 API.
Running the following command exposes an S3 endpoint at http://172.17.0.2:6007, where the region name is goodregion (see the reference)

docker run -e REGION=goodregion -it openio/sds:19.10

We can then make a bucket and upload a file to it using awscli:

wget -q https://github.com/mapbox/rasterio/raw/master/tests/data/alpha.tif
aws --endpoint-url $ENDPOINT_URL s3 mb s3://bucket
aws --endpoint-url $ENDPOINT_URL s3 cp alpha.tif s3://bucket

Finally, the following python snippet shows the issue:

import os
import sys
import rasterio


def try_opening(path):
    try:
        with rasterio.open(path) as f:
            pass
    except rasterio.errors.RasterioIOError:
        return False
    else:
        return True


endpoint_url = os.environ["ENDPOINT_URL"].replace("http://", "")  # GDAL does not like http://
path = "s3://bucket/alpha.tif"
kwargs = dict(AWS_HTTPS=False, AWS_VIRTUAL_HOSTING=False, AWS_S3_ENDPOINT=endpoint_url)

for region in ["badregion", "goodregion"]:
    with rasterio.Env(AWS_DEFAULT_REGION=region, **kwargs):
        print(f"Opening file with region: {region}. Success: {try_opening(path)}")

as it will print

Opening file with region: badregion. Success: False
Opening file with region: goodregion. Success: False

whereas switching the order of the opens (for region in ["goodregion", "badregion"]) prints:

Opening file with region: goodregion. Success: True
Opening file with region: badregion. Success: True

Since several steps are required to reproduce the example, I've included a .zip in which the example can be reproduced by running docker-compose up.
This will run two Docker images: one with the OpenIO instance, and the other with a bash script that uploads an image to a bucket of the OpenIO instance, and then calls the python snippet above.
rasterio-cpleopenfailed.zip

Operating system

MacOS and Ubuntu (these are the two OS I have access to)

Rasterio version and provenance

This issue can be seen on the latest rasterio wheel (1.1.3), but I have already encountered that issue on several previous rasterio versions.

[sgillies]

@glostis like you, I think it's possible that vsi caching may be involved. I think you should turn on the verbose curl logs and see whether a cache hit can be seen. CPL_CURL_VERBOSE=YES python snippet.py. Does your fake S3 server have logs? Do you see multiple region requests there?

[glostis]

Following your advice, I have looked at the server-side logs, and at the GDAL CURL logs.
They both show the same information, which is:

1. When I first try to open the file with the bad region name, GDAL makes 2 GET requests:

GET /bucket/alpha.tif (Range: bytes=0-16383)
GET /bucket/?delimiter=%2F&max-keys=100&prefix=alpha.tif%2F HTTP/1.1

If I then try to open the same file within the same python session, no further HTTP calls are made, even if I change the region name to the good one (i.e. nothing is logged after the first open is made).

1. When I first try to open the file with the good region name, GDAL makes 2 GET requests:

GET /bucket/alpha.tif (Range: bytes=0-16383)
GET /bucket/alpha.tif (Range: bytes=98304-105792)

If I then try to open the same file within the same python session, no further HTTP calls are made, even if I change the region name to a bad one (i.e. nothing is logged after the first open is made).

Cases 1. and 2. are basically symmetrical: in both cases, GDAL only makes calls at the first file open and then doesn't do any calls for the other open of the same session.

[sgillies]

@glostis thanks for the report. Have you tried using the CPL_VSIL_CURL_NON_CACHED option mentioned in https://gdal.org/user/virtual_file_systems.html#vsicurl-http-https-ftp-files-random-access?

I've been thinking about calling https://gdal.org/api/cpl.html#_CPPv417VSICurlClearCachev when a rasterio Env is exited. This wouldn't help the code as you've written it but would give you the option to use new, clean environments within your loop. What would you think about that?

[glostis]

@sgillies I've just tried running my snippet with CPL_VSIL_CURL_NON_CACHED=/vsis3/bucket/alpha.tif, and it solves the problem!

However, it is quite cumbersome to use in "real life" because you need to specify the filenames of all the files that you want to access.

Calling VSICurlClearCache() at the exit of an Env context would seem a good solution to me. I think it would help my code as I've written it, because I do a rasterio.Env within my for loop, so a new Env is used at every iteration of the loop.

[glostis]

Now that I understand the issue a bit more clearly, I wonder if there is not something that could be fixed in the GDAL caching mechanism? When we change the region name, we essentially change the headers of the requests made to the server, so GDAL should not use the cached responses, it should "know" that the requests are different.

I don't know anything about GDAL's caching mechanism however and I'm sure it very complex, so maybe there's a good reason for this behavior to exist.

[ciaranevans]

@glostis you mentioned you'd tried VSI_CACHE, what values have you tried? Just curious :)

[glostis]

@ciaranevans I have tried to set VSI_CACHE=FALSE in order to solve the issue I was describing, but I've since seen in the GDAL source code that FALSE is the default value so that explains why it had no effect in my case :)

[ciaranevans]

@glostis interesting! We've got it as TRUE but I don't think we've had an issue when it's been FALSE. Not a useful message from me unfortunately, hope it gets worked out!

[sgillies]

@glostis it's possible that headers aren't considered when making hash keys. Are you looking into this in GDAL?

I have been thinking a little more about having the VSI and curl caches cleared on Env exit... what you think about a flag for this that defaults to False? We could even add a flag for flushing the raster cache https://gdal.org/doxygen/gdal_8h.html#ad19e351b5fc67513ea36bf6a60f1120d. The reason for making it default to False is that users who are content with the invisible implicit Env inside rasterio.open() probably want the caches to remain between calls to that function.

[glostis]

@sgillies I've looked around in the GDAL codebase to try and understand where the decision to serve a cached response is done, but I haven't managed to pinpoint it to a single function. I'll try to come up with a code snippet that uses python-gdal only to demonstrate the problem and open an issue there.

I completely agree that it is important to keep backward compatibility for rasterio users regarding the caching behavior, so a flag that defaults to False would make sense in my opinion.

[glostis]

I've managed to make a much simpler example of the issue that doesn't require setting up a fake local S3, and opened an issue upstream: https://github.com/OSGeo/gdal/issues/2294

[glostis]

@sgillies the issue has been fixed upstream in https://github.com/OSGeo/gdal/commit/5f22744da4d967c5a4f8699997dc0a697df5ee35

[sgillies]

@glostis thanks for figuring this one out! I'm going to close now that I've made a ticket to patch GDAL in the binary wheels.

[sgillies]

Related: I'm working on an API for clearing the VSI cache in #2011 .