caddyserver / caddyserver/cache-handler

Caddy crashes under load, with huge number of mutex locks in cache handler

Open
#114 2 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Dominant language
Go
Stars
393
Forks
28
Avg merge
32m
Merged PRs (30d)
1

Description

Under reasonably small load (~250 req/sec), when using the cache-handler (we're using the go-redis storage, but I saw this happen with the default one as well), we get a fatal error: concurrent map iteration and map write in Caddy, this happens reasonably frequently (maybe once a day), requiring a restart.

 fatal error: concurrent map iteration and map write
 
 goroutine 27695297 [running]:
 net/http.Header.Clone(...)
 	net/http/header.go:101
 net/http.(*response).WriteHeader(0xc920c73c00, 0x1f4)
 	net/http/server.go:1231 +0x1e7
 github.com/caddyserver/caddy/v2/modules/caddyhttp.(*responseRecorder).WriteHeader(0x1ef02e0?, 0x1a70889?)
 	github.com/caddyserver/caddy/v2@v2.8.4/modules/caddyhttp/responsewriter.go:167 +0xb6
 github.com/caddyserver/caddy/v2/modules/caddyhttp.(*Server).ServeHTTP(0xc00089a008, {0x1f00d70, 0xc920c73c00}, 0xcf30e57040)
 	github.com/caddyserver/caddy/v2@v2.8.4/modules/caddyhttp/server.go:415 +0x1535
 net/http.serverHandler.ServeHTTP({0xcfd3b14750?}, {0x1f00d70?, 0xc920c73c00?}, 0x6?)
 	net/http/server.go:3210 +0x8e
 net/http.(*conn).serve(0xcef56bf4d0, {0x1f04538, 0x1070ae8cba0})
 	net/http/server.go:2092 +0x5d0
 created by net/http.(*Server).Serve in goroutine 181
 	net/http/server.go:3360 +0x485

This is accompanied by about 1.9 million of these goroutine "Sync.lock.mutex" states, implying (I guess) that a huge number of goroutines are waiting on a mutex.

goroutine 21446179 [sync.Mutex.Lock, 92 minutes]:
sync.runtime_SemacquireMutex(0xc918f18cb0?, 0xb8?, 0xc001a52708?)
	runtime/sema.go:95 +0x25
sync.(*Mutex).lockSlow(0xc0008fc640)
	sync/mutex.go:173 +0x15d
sync.(*Mutex).Lock(...)
	sync/mutex.go:92
github.com/darkweak/souin/pkg/surrogate/providers.(*baseStorage).storeTag(0xc000a80360, {0x0, 0x0}, {0xc61aaf6ac0, 0x38}, 0xcb96172320)
	github.com/darkweak/souin@v1.7.5/pkg/surrogate/providers/common.go:168 +0xad
github.com/darkweak/souin/pkg/surrogate/providers.(*baseStorage).Store(0xc000a80360, 0xc918f18ec0?, {0xc428c81400?, 0x90?}, {0x19dce40?, 0xcc0cfff7
	github.com/darkweak/souin@v1.7.5/pkg/surrogate/providers/common.go:232 +0x27f
github.com/darkweak/souin/pkg/middleware.(*SouinBaseHandler).Store.func2({{0x0, 0x0}, 0x12d, {0x0, 0x0}, 0x0, 0x0, 0xca7ca1ea50, {0x1efafc8, 0xcd3d
	github.com/darkweak/souin@v1.7.5/pkg/middleware/middleware.go:376 +0xcd
created by github.com/darkweak/souin/pkg/middleware.(*SouinBaseHandler).Store in goroutine 21446047
	github.com/darkweak/souin@v1.7.5/pkg/middleware/middleware.go:375 +0x2891
2024-12-06T08:04:16.889267314Z status_proxy_caddy_caddy.0.t7ydd1vd5hya@statuspage-1    | 

My theory is that the crash happens when some pool is finally exhausted.

Attached a log file containing the first 1000 lines, the full thing is many gigabytes (but I can provide if interested, they're all different goroutines waiting at the same point in the code)

limited.txt

Build:

FROM caddy:2.8.4-builder AS builder

RUN xcaddy build \
    --with github.com/pberkel/caddy-storage-redis@v1.3.0 \
    --with github.com/caddyserver/cache-handler@v0.15.0 \
    --with github.com/darkweak/storages/go-redis/caddy \
    --with github.com/aksdb/caddy-cgi@v2.2.3

Caddyfile, some values redacted.

(ip_block) {
    @block {             
        remote_ip REDACTED 
    }
    respond @block "Access denied" 403
}

(host_block) {
    @host_block {
        host REDACTED
    }
    respond @host_block "Rate limited" 429
}

{
    on_demand_tls {
        ask https://REDACTED
    }

    storage redis {
        host           "{$REDIS_HOST}"
        username       "{$REDIS_USER}"
        password       "{$REDIS_PASSWORD}"
    }

    servers {
        metrics
    }

    cache {
        # how our cache shows in the response header; default is Souin.
        cache_name sc

        redis {
            configuration {
                Addrs "{$REDIS_CACHE_HOST}:6379"
                User "{$REDIS_CACHE_USER}"
                Password "{$REDIS_CACHE_PASSWORD}"
                DB 0
            }
        }
    }

    order cgi before respond
}

# Catch-all for any domain
:443 {
    log

    tls {
        # we do some funky certificate selection stuff with a local script, fallback to the default
        get_certificate http http://localhost:4434/cert
        on_demand
    }

    import ip_block
    import host_block

    cache {
        key {
            hide
            headers Accept-Language
        }
        # ignore any cache-control indicators from the client
        mode bypass_request
    }

    # Reverse proxy to server.betteruptime.com
    reverse_proxy https://REDACTED {
        header_up Host {upstream_hostport}
        header_up X-Real-IP {http.request.remote.host}
    }
}

http://:9190 {
    metrics /metrics
}

http://localhost:4434 {
    cache {
        stale 5m
        ttl 5m
    }
    cgi /cert /etc/caddy/get_fallback_cert.sh
}

Contributor guide

No contributing guide indexed for this repository

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start with the cache-handler integration and the stack-trace locations in github.com/darkweak/souin/pkg/surrogate/providers/common.go and pkg/middleware/middleware.go, then compare them with net/http/header.go and caddyhttp/responsewriter.go. Reproduce the load scenario using the provided Caddyfile and cache configuration. Done means the concurrent map crash and the large population of mutex-waiting goroutines no longer occur under load.

Written by the indexing model from the issue text.

Assessment

Tech stack
go, redis
Domain
backend, performance
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
25/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.