Redis lock acquired prematurely leading to 500 internal server errors
- Dominant language
- Go
- Stars
- 4.8k
- Forks
- 542
- Avg merge
- 7d 21h
- Merged PRs (30d)
- 2
Description
**Describe the bug**
Background: we use Athens with Redis (as our `SingleFlightMode`) to manage concurrent write access to our storage (S3).
We have encountered an issue in our Athens setup where requests for certain modules and versions (e.g. `github.com/aws/aws-sdk-go/@v/v1.12.42.info`) has resulted in a 500 status code and a `"redislock: not obtained"` error in our logs.
**Error Message**
When users see 500 Internal Server Error. Our Athens log:
```sh
redislock: not obtained
```
When users see 404 Not Found. Our Athens log (expected):
```sh
github.com/aws/aws-sdk-go@v1.12.42: verifying go.mod: github.com/aws/aws-sdk-go@v1.12.42/go.mod: reading https://sum.golang.org/lookup/github.com/aws/aws-sdk-go@v1.12.42: 404 Not Found
server response:
not found: create zip: models/apis/sagemaker/2017-07-24/api-2.json: case-insensitive file name collision: "models/apis/SageMaker/2017-07-24/api-2.json" and "models/apis/sagemaker/2017-07-24/api-2.json"
models/apis/sagemaker/2017-07-24/docs-2.json: case-insensitive file name collision: "models/apis/SageMaker/2017-07-24/docs-2.json" and "models/apis/sagemaker/2017-07-24/docs-2.json"
```
**To Reproduce**
Steps to reproduce the behavior:
1. Clone this repository
2. Start a Redis locally: `docker run -d --name some-redis -p 6379:6379 redis`
3. Update [config.dev.toml](https://github.com/gomods/athens/blob/a1e728e5be3be4419fd0f8eec6729bfb4f3317ab/config.dev.toml#L315) to `SingleFlightType = "redis"`
4. Start Athens: `make run`
5. To reproduce, rapidly send few requests to `time curl http://localhost:3000/github.com/aws/aws-sdk-go/@v/v1.12.42.info`. This took me ~30s on average. Here, you should see `redislock: not obtained` getting logged
**Expected behavior**
The expected behavior here is for Athens to return a 404 status code as this module does not exist. However, Athens is returning a 500 status code (with a Redis lock error logged on the server-side).
**Environment**
- OS: macOS
- Go version: `go1.22.2 darwin/arm64`
- Proxy version : `v0.14.1`
- Storage (fs/mongodb/s3 etc.): S3
**Additional context**
1. Sending the same request to the public proxy https://proxy.golang.org/github.com/aws/aws-sdk-go/@v/v1.12.42.info yields immediate 404 (probably because it caches non-200 responses too)
2. `/github.com/aws/aws-sdk-go/@v/v1.12.42` is part of our transitive dependencies so there isn't a way to avoid it
3. `/github.com/aws/aws-sdk-go/@v/v1.12.42` is just an example, we've seen similar cases with other Go modules like: `/cloud.google.com/go/storage/@v/v1.35.0.info`, `/github.com/go-redis/redis/@v/v6.15.3+incompatible.info`, `/gopkg.in/go-playground/validator.v9/@v/v9.30.1.info` (... and more). Generally they seemed to be 'problematic' modules to run `go mod download -json` on
**Further investigation**
The root cause appears to be related to **Athens obtaining the Redis lock before fetching from the upstream source** ([code](https://github.com/gomods/athens/blob/a1e728e5be3be4419fd0f8eec6729bfb4f3317ab/pkg/stash/with_redis.go#L79-L82)) at `module.downloadModule`. In this specific case, fetching from the upstream took a significant amount of time, and obtaining the Redis lock prematurely has lead to lock contention and timeouts.
Upon further investigation, it was discovered that the bottleneck occurred within the `goGetFetcher.Fetch` function, which calls `module.downloadModule` ([reference](https://github.com/gomods/athens/blob/a1e728e5be3be4419fd0f8eec6729bfb4f3317ab/pkg/module/go_get_fetcher.go#L137))
The `module.downloadModule` function is responsible for executing the `go mod download -json github.com/aws/aws-sdk-go@v1.12.42`. Here, the `go mod download -json` command took on average about 30 seconds to complete
**Proposal**
- I propose that instead of obtaining the Redis lock before fetching from the upstream source, the lock should be acquired only **after** successfully fetching the module from upstream and before stashing it to the storage backend
- This approach ensures that the lock is held for a minimal duration (reduces the chances of lock contention and timeouts)
Contributor guide
Research direction
Start with pkg/stash/with_redis.go and pkg/module/go_get_fetcher.go, then reproduce with Redis running via Docker and the rapid curl request described in the issue. Trace how module.downloadModule and goGetFetcher.Fetch handle the upstream fetch and Redis lock. Done means the problematic module returns 404 rather than 500 without logging redislock: not obtained.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- docker, go, redis
- Domain
- backend, distributed-systems
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Clearly specified
- Newbie friendliness
- 42/100