cache-handler icon indicating copy to clipboard operation
cache-handler copied to clipboard
verified publisher icon caddyserver

`otter` uses a huge amount of memory for large files

Open gucci-on-fleek opened this issue 4 months ago • 6 comments

When trying to use the otter storage to serve a 4GB file, Caddy uses 25GB+ of memory and returns an error instead of the file's contents. The file is served correctly if I disable the cache.

Demonstration 
$ caddy --version
v2.10.2 h1:g/gTYjGMD0dec+UgMw8SnfmJ3I9+M2TdvoRL/Ovu6U8=

$ caddy list-modules --versions --packages
admin.api.load v2.10.2 github.com/caddyserver/caddy/v2
admin.api.metrics v2.10.2 github.com/caddyserver/caddy/v2
admin.api.pki v2.10.2 github.com/caddyserver/caddy/v2
admin.api.reverse_proxy v2.10.2 github.com/caddyserver/caddy/v2
caddy.adapters.caddyfile v2.10.2 github.com/caddyserver/caddy/v2
caddy.config_loaders.http v2.10.2 github.com/caddyserver/caddy/v2
caddy.filesystems v2.10.2 github.com/caddyserver/caddy/v2
caddy.listeners.http_redirect v2.10.2 github.com/caddyserver/caddy/v2
caddy.listeners.proxy_protocol v2.10.2 github.com/caddyserver/caddy/v2
caddy.listeners.tls v2.10.2 github.com/caddyserver/caddy/v2
caddy.logging.cores.mock v2.10.2 github.com/caddyserver/caddy/v2
caddy.logging.encoders.append v2.10.2 github.com/caddyserver/caddy/v2
caddy.logging.encoders.console v2.10.2 github.com/caddyserver/caddy/v2
caddy.logging.encoders.filter v2.10.2 github.com/caddyserver/caddy/v2
caddy.logging.encoders.filter.cookie v2.10.2 github.com/caddyserver/caddy/v2
caddy.logging.encoders.filter.delete v2.10.2 github.com/caddyserver/caddy/v2
caddy.logging.encoders.filter.hash v2.10.2 github.com/caddyserver/caddy/v2
caddy.logging.encoders.filter.ip_mask v2.10.2 github.com/caddyserver/caddy/v2
caddy.logging.encoders.filter.query v2.10.2 github.com/caddyserver/caddy/v2
caddy.logging.encoders.filter.regexp v2.10.2 github.com/caddyserver/caddy/v2
caddy.logging.encoders.filter.rename v2.10.2 github.com/caddyserver/caddy/v2
caddy.logging.encoders.filter.replace v2.10.2 github.com/caddyserver/caddy/v2
caddy.logging.encoders.json v2.10.2 github.com/caddyserver/caddy/v2
caddy.logging.writers.discard v2.10.2 github.com/caddyserver/caddy/v2
caddy.logging.writers.file v2.10.2 github.com/caddyserver/caddy/v2
caddy.logging.writers.net v2.10.2 github.com/caddyserver/caddy/v2
caddy.logging.writers.stderr v2.10.2 github.com/caddyserver/caddy/v2
caddy.logging.writers.stdout v2.10.2 github.com/caddyserver/caddy/v2
caddy.network_proxy.none v2.10.2 github.com/caddyserver/caddy/v2
caddy.network_proxy.url v2.10.2 github.com/caddyserver/caddy/v2
caddy.storage.file_system v2.10.2 github.com/caddyserver/caddy/v2
events v2.10.2 github.com/caddyserver/caddy/v2
http v2.10.2 github.com/caddyserver/caddy/v2
http.authentication.hashes.bcrypt v2.10.2 github.com/caddyserver/caddy/v2
http.authentication.providers.http_basic v2.10.2 github.com/caddyserver/caddy/v2
http.encoders.gzip v2.10.2 github.com/caddyserver/caddy/v2
http.encoders.zstd v2.10.2 github.com/caddyserver/caddy/v2
http.handlers.acme_server v2.10.2 github.com/caddyserver/caddy/v2
http.handlers.authentication v2.10.2 github.com/caddyserver/caddy/v2
http.handlers.copy_response v2.10.2 github.com/caddyserver/caddy/v2
http.handlers.copy_response_headers v2.10.2 github.com/caddyserver/caddy/v2
http.handlers.encode v2.10.2 github.com/caddyserver/caddy/v2
http.handlers.error v2.10.2 github.com/caddyserver/caddy/v2
http.handlers.file_server v2.10.2 github.com/caddyserver/caddy/v2
http.handlers.headers v2.10.2 github.com/caddyserver/caddy/v2
http.handlers.intercept v2.10.2 github.com/caddyserver/caddy/v2
http.handlers.invoke v2.10.2 github.com/caddyserver/caddy/v2
http.handlers.log_append v2.10.2 github.com/caddyserver/caddy/v2
http.handlers.map v2.10.2 github.com/caddyserver/caddy/v2
http.handlers.metrics v2.10.2 github.com/caddyserver/caddy/v2
http.handlers.push v2.10.2 github.com/caddyserver/caddy/v2
http.handlers.request_body v2.10.2 github.com/caddyserver/caddy/v2
http.handlers.reverse_proxy v2.10.2 github.com/caddyserver/caddy/v2
http.handlers.rewrite v2.10.2 github.com/caddyserver/caddy/v2
http.handlers.static_response v2.10.2 github.com/caddyserver/caddy/v2
http.handlers.subroute v2.10.2 github.com/caddyserver/caddy/v2
http.handlers.templates v2.10.2 github.com/caddyserver/caddy/v2
http.handlers.tracing v2.10.2 github.com/caddyserver/caddy/v2
http.handlers.vars v2.10.2 github.com/caddyserver/caddy/v2
http.ip_sources.static v2.10.2 github.com/caddyserver/caddy/v2
http.matchers.client_ip v2.10.2 github.com/caddyserver/caddy/v2
http.matchers.expression v2.10.2 github.com/caddyserver/caddy/v2
http.matchers.file v2.10.2 github.com/caddyserver/caddy/v2
http.matchers.header v2.10.2 github.com/caddyserver/caddy/v2
http.matchers.header_regexp v2.10.2 github.com/caddyserver/caddy/v2
http.matchers.host v2.10.2 github.com/caddyserver/caddy/v2
http.matchers.method v2.10.2 github.com/caddyserver/caddy/v2
http.matchers.not v2.10.2 github.com/caddyserver/caddy/v2
http.matchers.path v2.10.2 github.com/caddyserver/caddy/v2
http.matchers.path_regexp v2.10.2 github.com/caddyserver/caddy/v2
http.matchers.protocol v2.10.2 github.com/caddyserver/caddy/v2
http.matchers.query v2.10.2 github.com/caddyserver/caddy/v2
http.matchers.remote_ip v2.10.2 github.com/caddyserver/caddy/v2
http.matchers.tls v2.10.2 github.com/caddyserver/caddy/v2
http.matchers.vars v2.10.2 github.com/caddyserver/caddy/v2
http.matchers.vars_regexp v2.10.2 github.com/caddyserver/caddy/v2
http.precompressed.br v2.10.2 github.com/caddyserver/caddy/v2
http.precompressed.gzip v2.10.2 github.com/caddyserver/caddy/v2
http.precompressed.zstd v2.10.2 github.com/caddyserver/caddy/v2
http.reverse_proxy.selection_policies.client_ip_hash v2.10.2 github.com/caddyserver/caddy/v2
http.reverse_proxy.selection_policies.cookie v2.10.2 github.com/caddyserver/caddy/v2
http.reverse_proxy.selection_policies.first v2.10.2 github.com/caddyserver/caddy/v2
http.reverse_proxy.selection_policies.header v2.10.2 github.com/caddyserver/caddy/v2
http.reverse_proxy.selection_policies.ip_hash v2.10.2 github.com/caddyserver/caddy/v2
http.reverse_proxy.selection_policies.least_conn v2.10.2 github.com/caddyserver/caddy/v2
http.reverse_proxy.selection_policies.query v2.10.2 github.com/caddyserver/caddy/v2
http.reverse_proxy.selection_policies.random v2.10.2 github.com/caddyserver/caddy/v2
http.reverse_proxy.selection_policies.random_choose v2.10.2 github.com/caddyserver/caddy/v2
http.reverse_proxy.selection_policies.round_robin v2.10.2 github.com/caddyserver/caddy/v2
http.reverse_proxy.selection_policies.uri_hash v2.10.2 github.com/caddyserver/caddy/v2
http.reverse_proxy.selection_policies.weighted_round_robin v2.10.2 github.com/caddyserver/caddy/v2
http.reverse_proxy.transport.fastcgi v2.10.2 github.com/caddyserver/caddy/v2
http.reverse_proxy.transport.http v2.10.2 github.com/caddyserver/caddy/v2
http.reverse_proxy.upstreams.a v2.10.2 github.com/caddyserver/caddy/v2
http.reverse_proxy.upstreams.multi v2.10.2 github.com/caddyserver/caddy/v2
http.reverse_proxy.upstreams.srv v2.10.2 github.com/caddyserver/caddy/v2
pki v2.10.2 github.com/caddyserver/caddy/v2
tls v2.10.2 github.com/caddyserver/caddy/v2
tls.ca_pool.source.file v2.10.2 github.com/caddyserver/caddy/v2
tls.ca_pool.source.http v2.10.2 github.com/caddyserver/caddy/v2
tls.ca_pool.source.inline v2.10.2 github.com/caddyserver/caddy/v2
tls.ca_pool.source.pki_intermediate v2.10.2 github.com/caddyserver/caddy/v2
tls.ca_pool.source.pki_root v2.10.2 github.com/caddyserver/caddy/v2
tls.ca_pool.source.storage v2.10.2 github.com/caddyserver/caddy/v2
tls.certificates.automate v2.10.2 github.com/caddyserver/caddy/v2
tls.certificates.load_files v2.10.2 github.com/caddyserver/caddy/v2
tls.certificates.load_folders v2.10.2 github.com/caddyserver/caddy/v2
tls.certificates.load_pem v2.10.2 github.com/caddyserver/caddy/v2
tls.certificates.load_storage v2.10.2 github.com/caddyserver/caddy/v2
tls.client_auth.verifier.leaf v2.10.2 github.com/caddyserver/caddy/v2
tls.ech.publishers.dns v2.10.2 github.com/caddyserver/caddy/v2
tls.get_certificate.http v2.10.2 github.com/caddyserver/caddy/v2
tls.get_certificate.tailscale v2.10.2 github.com/caddyserver/caddy/v2
tls.handshake_match.local_ip v2.10.2 github.com/caddyserver/caddy/v2
tls.handshake_match.remote_ip v2.10.2 github.com/caddyserver/caddy/v2
tls.handshake_match.sni v2.10.2 github.com/caddyserver/caddy/v2
tls.handshake_match.sni_regexp v2.10.2 github.com/caddyserver/caddy/v2
tls.issuance.acme v2.10.2 github.com/caddyserver/caddy/v2
tls.issuance.internal v2.10.2 github.com/caddyserver/caddy/v2
tls.issuance.zerossl v2.10.2 github.com/caddyserver/caddy/v2
tls.leaf_cert_loader.file v2.10.2 github.com/caddyserver/caddy/v2
tls.leaf_cert_loader.folder v2.10.2 github.com/caddyserver/caddy/v2
tls.leaf_cert_loader.pem v2.10.2 github.com/caddyserver/caddy/v2
tls.leaf_cert_loader.storage v2.10.2 github.com/caddyserver/caddy/v2
tls.permission.http v2.10.2 github.com/caddyserver/caddy/v2
tls.stek.distributed v2.10.2 github.com/caddyserver/caddy/v2
tls.stek.standard v2.10.2 github.com/caddyserver/caddy/v2

  Standard modules: 127

admin.api.souin v0.16.0 github.com/caddyserver/cache-handler
cache v0.16.0 github.com/caddyserver/cache-handler
caddy.listeners.layer4 v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
caddy.logging.encoders.formatted v0.0.0-20250416233754-15eef9743261 github.com/caddyserver/transform-encoder
caddy.logging.encoders.transform v0.0.0-20250416233754-15eef9743261 github.com/caddyserver/transform-encoder
dns.providers.rfc2136 v1.0.0 github.com/caddy-dns/rfc2136
http.handlers.cache v0.16.0 github.com/caddyserver/cache-handler
http.handlers.rate_limit v0.1.0 github.com/mholt/caddy-ratelimit
http.handlers.replace_response v0.0.0-20250618171559-80962887e4c6 github.com/caddyserver/replace-response
http.matchers.maxmind_geolocation v1.0.1 github.com/porech/caddy-maxmind-geolocation
layer4 v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.handlers.echo v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.handlers.proxy v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.handlers.proxy_protocol v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.handlers.socks5 v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.handlers.subroute v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.handlers.tee v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.handlers.throttle v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.handlers.tls v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.matchers.clock v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.matchers.dns v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.matchers.http v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.matchers.local_ip v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.matchers.not v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.matchers.openvpn v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.matchers.postgres v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.matchers.proxy_protocol v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.matchers.quic v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.matchers.rdp v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.matchers.regexp v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.matchers.remote_ip v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.matchers.remote_ip_list v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.matchers.socks4 v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.matchers.socks5 v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.matchers.ssh v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.matchers.tls v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.matchers.winbox v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.matchers.wireguard v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.matchers.xmpp v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.proxy.selection_policies.first v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.proxy.selection_policies.ip_hash v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.proxy.selection_policies.least_conn v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.proxy.selection_policies.random v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.proxy.selection_policies.random_choose v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
layer4.proxy.selection_policies.round_robin v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4
storages.cache.otter v0.0.16 github.com/darkweak/storages/otter/caddy
tls.handshake_match.alpn v0.0.0-20251001194302-2e3e6cf60b25 github.com/mholt/caddy-l4

  Non-standard modules: 47

  Unknown modules: 0

$ cat ./Caddyfile
{
        log {
                output stderr
                format console
                level DEBUG
        }
}

localhost {
        log {
                output stderr
                format console
        }

        cache {
                otter
        }

        file_server
}

$ truncate --size=4G big-empty-file

$ du --human-readable --apparent-size big-empty-file
4.0G    big-empty-file

$ /usr/bin/time --verbose caddy run --config=./Caddyfile
2025/10/06 07:49:24.619 INFO    maxprocs: Leaving GOMAXPROCS=16: CPU quota undefined
2025/10/06 07:49:24.620 INFO    GOMEMLIMIT is updated   {"package": "github.com/KimMachineGun/automemlimit/memlimit", "GOMEMLIMIT": 29652601651, "previous": 9223372036854775807}
2025/10/06 07:49:24.620 INFO    using config from file  {"file": "./Caddyfile"}
2025/10/06 07:49:24.621 INFO    adapted config to JSON  {"adapter": "caddyfile"}
2025/10/06 07:49:24.622 INFO    admin   admin endpoint started  {"address": "localhost:2019", "enforce_origin": false, "origins": ["//localhost:2019", "//[::1]:2019", "//127.0.0.1:2019"]}
2025/10/06 07:49:24.622 INFO    http.auto_https server is listening only on the HTTPS port but has no TLS connection policies; adding one to enable TLS      {"server_name": "srv0", "https_port": 443}
2025/10/06 07:49:24.622 INFO    http.auto_https enabling automatic HTTP->HTTPS redirects        {"server_name": "srv0"}
2025/10/06 07:49:24.622 INFO    tls.cache.maintenance   started background certificate maintenance      {"cache": "0xc000471080"}
2025/10/06 07:49:24.623 DEBUG   http.auto_https adjusted config {"tls": {"automation":{"policies":[{"subjects":["localhost"]},{}]}}, "http": {"servers":{"remaining_auto_https_redirects":{"listen":[":80"],"routes":[{},{}],"logs":{"logger_names":{"localhost":["log0"]}}},"srv0":{"listen":[":443"],"routes":[{"handle":[{"handler":"subroute","routes":[{"handle":[{"Configuration":{"API":{"basepath":"","debug":{"basepath":"","enable":false,"security":false},"prometheus":{"basepath":"","enable":false,"security":false},"security":{"basepath":"","enable":false,"secret":"","users":null},"souin":{"basepath":"","enable":false,"security":false}},"DefaultCache":{"allowed_additional_status_codes":null,"allowed_http_verbs":[],"badger":null,"cache_name":"","cdn":{},"default_cache_control":"","disable_coalescing":false,"distributed":false,"etcd":null,"headers":null,"key":{},"max_cacheable_body_bytes":0,"mode":"","nats":null,"nuts":null,"olric":null,"otter":{"Uuid":"","configuration":null,"found":true,"path":"","url":""},"redis":null,"regex":{"exclude":""},"simplefs":null,"stale":"0s","storers":null,"timeout":{"backend":"0s","cache":"0s"},"ttl":"0s"},"LogLevel":"","SurrogateKeyDisabled":false,"SurrogateKeys":null,"URLs":null,"cache_keys":{}},"badger":null,"etcd":null,"handler":"cache","key":{},"nats":null,"nuts":null,"olric":null,"otter":null,"redis":null,"simplefs":null,"stale":"0s","timeout":{"backend":"0s","cache":"0s"},"ttl":"0s"},{"handler":"file_server","hide":["./Caddyfile"]}]}]}],"terminal":true}],"tls_connection_policies":[{}],"automatic_https":{},"logs":{"logger_names":{"localhost":["log0"]}}}}}}
2025/10/06 07:49:24.623 INFO    storages.cache.otter    otter.storage.size 10000
2025/10/06 07:49:24.623 DEBUG   http.handlers.cache     You're running Souin with the following storages in this order OTTER
2025/10/06 07:49:24.623 DEBUG   http.handlers.cache     Storer initialized: []types.Storer{(*otter.Otter)(0xc000472da0)}.
2025/10/06 07:49:24.623 DEBUG   http.handlers.cache     Try to load the storer OTTER-0s as surrogate backend
2025/10/06 07:49:24.623 DEBUG   http.handlers.cache     Surrogate storage initialized.
2025/10/06 07:49:24.623 DEBUG   http.handlers.cache     Set Souin as Cache-Status name
2025/10/06 07:49:24.623 DEBUG   http.handlers.cache     Allow 2 method(s). [GET HEAD].
2025/10/06 07:49:24.623 DEBUG   http.handlers.cache     The cache logic will run as : &{Strict:true Bypass_request:false Bypass_response:false}
2025/10/06 07:49:24.623 INFO    http.handlers.cache     Set backend timeout to 10s
2025/10/06 07:49:24.623 INFO    http.handlers.cache     Set cache timeout to 10ms
2025/10/06 07:49:24.623 INFO    http.handlers.cache     Souin configuration is now loaded.
2025/10/06 07:49:24.623 DEBUG   http.handlers.cache     registering mapping eviction for storer OTTER
2025/10/06 07:49:24.623 INFO    pki.ca.local    root certificate is already trusted by system   {"path": "storage:pki/authorities/local/root.crt"}
2025/10/06 07:49:24.623 DEBUG   http.handlers.cache     run mapping eviction for storer OTTER
2025/10/06 07:49:24.623 DEBUG   http    starting server loop    {"address": "[::]:443", "tls": true, "http3": false}
2025/10/06 07:49:24.623 INFO    http    enabling HTTP/3 listener        {"addr": ":443"}
2025/10/06 07:49:24.623 INFO    failed to sufficiently increase receive buffer size (was: 208 kiB, wanted: 7168 kiB, got: 416 kiB). See https://github.com/quic-go/quic-go/wiki/UDP-Buffer-Sizes for details.
2025/10/06 07:49:24.623 INFO    http.log        server running  {"name": "srv0", "protocols": ["h1", "h2", "h3"]}
2025/10/06 07:49:24.623 DEBUG   http    starting server loop    {"address": "[::]:80", "tls": false, "http3": false}
2025/10/06 07:49:24.623 WARN    http    HTTP/2 skipped because it requires TLS  {"network": "tcp", "addr": ":80"}
2025/10/06 07:49:24.623 WARN    http    HTTP/3 skipped because it requires TLS  {"network": "tcp", "addr": ":80"}
2025/10/06 07:49:24.623 INFO    http.log        server running  {"name": "remaining_auto_https_redirects", "protocols": ["h1", "h2", "h3"]}
2025/10/06 07:49:24.623 INFO    http    enabling automatic TLS certificate management   {"domains": ["localhost"]}
2025/10/06 07:49:24.624 WARN    tls     stapling OCSP   {"identifiers": ["localhost"]}
2025/10/06 07:49:24.624 DEBUG   tls.cache       added certificate to cache      {"subjects": ["localhost"], "expiration": "2025/10/06 19:37:50.000", "managed": true, "issuer_key": "local", "hash": "1080b96f865d59469aa5e85cc40e39164a1b0aaaaafd6ccbbbc46cbb3839fef1", "cache_size": 1, "cache_capacity": 10000}
2025/10/06 07:49:24.624 DEBUG   events  event   {"name": "cached_managed_cert", "id": "7bc31211-e7e8-4f87-9806-5bd6ce020fad", "origin": "tls", "data": {"sans":["localhost"]}}
2025/10/06 07:49:24.624 DEBUG   events  event   {"name": "started", "id": "a798f3e4-67f7-42d8-8038-cd1f09a5e305", "origin": "", "data": null}
2025/10/06 07:49:24.624 INFO    autosaved config (load with --resume flag)      {"file": "/home/max/.config/caddy/autosave.json"}
2025/10/06 07:49:24.624 INFO    serving initial configuration
2025/10/06 07:49:24.630 INFO    tls     storage cleaning happened too recently; skipping for now        {"storage": "FileStorage:/home/max/.local/share/caddy", "instance": "d8cf091d-5eb6-4e73-892e-f97970c6d66b", "try_again": "2025/10/07 07:49:24.630", "try_again_in": 86399.999997626}
2025/10/06 07:49:24.630 INFO    tls     finished cleaning storage units
2025/10/06 07:49:30.446 DEBUG   events  event   {"name": "tls_get_certificate", "id": "3a79207f-a54d-4791-9854-5dbc6f00cd46", "origin": "tls", "data": {"client_hello":{"CipherSuites":[4866,4867,4865,4868,49196,49200,52393,52392,49325,49195,49199,49324,49187,49191,49162,49172,49161,49171,157,49309,156,49308,61,60,53,47,159,52394,49311,158,49310,107,103,57,51,255],"ServerName":"localhost","SupportedCurves":[29,23,30,25,24,256,257,258,259,260],"SupportedPoints":"AAEC","SignatureSchemes":[1027,1283,1539,2055,2056,2057,2058,2059,2052,2053,2054,1025,1281,1537,771,769],"SupportedProtos":["h2","http/1.1"],"SupportedVersions":[772,771],"RemoteAddr":{"IP":"::1","Port":50562,"Zone":""},"LocalAddr":{"IP":"::1","Port":443,"Zone":""}}}}
2025/10/06 07:49:30.446 DEBUG   tls.handshake   choosing certificate    {"identifier": "localhost", "num_choices": 1}
2025/10/06 07:49:30.446 DEBUG   tls.handshake   default certificate selection results   {"identifier": "localhost", "subjects": ["localhost"], "managed": true, "issuer_key": "local", "hash": "1080b96f865d59469aa5e85cc40e39164a1b0aaaaafd6ccbbbc46cbb3839fef1"}
2025/10/06 07:49:30.446 DEBUG   tls.handshake   matched certificate in cache    {"remote_ip": "::1", "remote_port": "50562", "subjects": ["localhost"], "managed": true, "expiration": "2025/10/06 19:37:50.000", "hash": "1080b96f865d59469aa5e85cc40e39164a1b0aaaaafd6ccbbbc46cbb3839fef1"}
2025/10/06 07:49:30.454 DEBUG   http.handlers.cache     Incomming request &{Method:GET URL:/big-empty-file Proto:HTTP/2.0 ProtoMajor:2 ProtoMinor:0 Header:map[Accept:[*/*] User-Agent:[curl/8.11.1]] Body:0xc0002d8570 GetBody:<nil> ContentLength:0 TransferEncoding:[] Close:false Host:localhost Form:map[] PostForm:map[] MultipartForm:<nil> Trailer:map[] RemoteAddr:[::1]:50562 RequestURI:/big-empty-file TLS:0xc00065e0c0 Cancel:<nil> Response:<nil> Pattern: ctx:0xc000416690 pat:<nil> matches:[] otherValues:map[]}
2025/10/06 07:49:30.454 DEBUG   http.handlers.cache     Request cache-control &{MaxAge:-1 MaxStale:-1 MaxStaleSet:false MinFresh:-1 NoCache:false NoStore:false NoTransform:false OnlyIfCached:false StaleIfError:0 Extensions:[]}
2025/10/06 07:49:30.454 DEBUG   storages.cache.otter    Impossible to get the mapping key IDX_GET-https-localhost-/big-empty-file in Otter
2025/10/06 07:49:30.454 DEBUG   http.handlers.cache     Request the upstream server
2025/10/06 07:49:30.455 DEBUG   http.handlers.file_server       sanitized path join     {"site_root": ".", "fs": "", "request_path": "/big-empty-file", "result": "big-empty-file"}
2025/10/06 07:49:30.455 DEBUG   http.handlers.file_server       opening file    {"filename": "big-empty-file"}
2025/10/06 07:49:37.461 DEBUG   http.handlers.cache     Response cache-control &{MustRevalidate:false NoCache:map[] NoCachePresent:false NoStore:false NoTransform:false Public:false Private:map[] PrivatePresent:false ProxyRevalidate:false MaxAge:-1 SMaxAge:-1 Immutable:false StaleIfError:-1 StaleWhileRevalidate:-1 Extensions:[]}
2025/10/06 07:49:40.455 INFO    http.handlers.cache     Internal server error on endpoint /big-empty-file: [0xc000472da0]
2025/10/06 07:49:40.455 ERROR   http.log.error.log0     context deadline exceeded       {"request": {"remote_ip": "::1", "remote_port": "50562", "client_ip": "::1", "proto": "HTTP/2.0", "method": "GET", "host": "localhost", "uri": "/big-empty-file", "headers": {"User-Agent": ["curl/8.11.1"], "Accept": ["*/*"]}, "tls": {"resumed": false, "version": 772, "cipher_suite": 4865, "proto": "h2", "server_name": "localhost"}}, "duration": 10.001342644, "error": "context deadline exceeded"}
2025/10/06 07:49:40.456 ERROR   http.log.access.log0    handled request {"request": {"remote_ip": "::1", "remote_port": "50562", "client_ip": "::1", "proto": "HTTP/2.0", "method": "GET", "host": "localhost", "uri": "/big-empty-file", "headers": {"User-Agent": ["curl/8.11.1"], "Accept": ["*/*"]}, "tls": {"resumed": false, "version": 772, "cipher_suite": 4865, "proto": "h2", "server_name": "localhost"}}, "bytes_read": 0, "user_id": "", "duration": 10.001342644, "size": 21, "status": 504, "resp_headers": {"Accept-Ranges": ["bytes"], "Content-Length": ["4294967296"], "X-Souin-Stored-Ttl": ["2m0s"], "Vary": ["Accept-Encoding"], "Content-Type": [], "Last-Modified": ["Mon, 06 Oct 2025 07:49:16 GMT"], "Cache-Control": [""], "Cache-Status": ["Souin; fwd=bypass; detail=DEADLINE-EXCEEDED"], "Server": ["Caddy"], "Alt-Svc": ["h3=\":443\"; ma=2592000"], "Etag": ["\"ddb2otemkgur1z141z4\""]}}
2025/10/06 07:50:03.359 DEBUG   http.handlers.cache     Store the response for GET-https-localhost-/big-empty-file{-VARY-}Accept-Encoding: with duration 1m52.538771525s
2025/10/06 07:50:03.359 INFO    http.handlers.cache     recovered due to closed errorCacheCh chan, the request context has finished prematurely /big-empty-file
2025/10/06 07:50:24.624 DEBUG   http.handlers.cache     run mapping eviction for storer OTTER
^C2025/10/06 07:50:49.910       INFO    shutting down   {"signal": "SIGINT"}
2025/10/06 07:50:49.919 WARN    exiting; byeee!! 👋     {"signal": "SIGINT"}
2025/10/06 07:50:49.919 DEBUG   events  event   {"name": "stopping", "id": "58567fd5-8023-453d-8258-aa462ebaebcf", "origin": "", "data": null}
2025/10/06 07:50:49.919 INFO    http    servers shutting down with eternal grace period
2025/10/06 07:50:49.921 DEBUG   http.handlers.cache     Cleanup...
2025/10/06 07:50:49.921 INFO    admin   stopped previous server {"address": "localhost:2019"}
2025/10/06 07:50:49.921 INFO    shutdown complete       {"signal": "SIGINT", "exit_code": 0}
        Command being timed: "caddy run --config=./Caddyfile"
        User time (seconds): 10.00
        System time (seconds): 38.38
        Percent of CPU this job got: 55%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 1:27.00
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 25086852
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 431
        Minor (reclaiming a frame) page faults: 8929070
        Voluntary context switches: 111227
        Involuntary context switches: 1776
        Swaps: 0
        File system inputs: 6376
        File system outputs: 304
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 4096
        Exit status: 0

$ curl -vv https://localhost/big-empty-file  # (In a separate window while the above is running)
01:49:30.444032 [0-0] * Host localhost:443 was resolved.
01:49:30.444134 [0-0] * IPv6: ::1
01:49:30.444186 [0-0] * IPv4: 127.0.0.1
01:49:30.444255 [0-0] * [HTTPS-CONNECT] added
01:49:30.444323 [0-0] * [HTTPS-CONNECT] connect, init
01:49:30.444382 [0-0] * [HTTPS-CONNECT] connect, check h21
01:49:30.444489 [0-0] *   Trying [::1]:443...
01:49:30.444757 [0-0] * [HTTPS-CONNECT] connect -> 0, done=0
01:49:30.444797 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
01:49:30.444850 [0-0] * [HTTPS-CONNECT] connect, check h21
01:49:30.446214 [0-0] * ALPN: curl offers h2,http/1.1
01:49:30.446357 [0-0] * TLSv1.3 (OUT), TLS handshake, Client hello (1):
01:49:30.451578 [0-0] *  CAfile: /etc/pki/ca-trust/extracted/pem/tls-ca-bundle.pem
01:49:30.451616 [0-0] *  CApath: none
01:49:30.451660 [0-0] * [HTTPS-CONNECT] connect -> 0, done=0
01:49:30.451698 [0-0] * [HTTPS-CONNECT] adjust_pollset -> 1 socks
01:49:30.451746 [0-0] * [HTTPS-CONNECT] connect, check h21
01:49:30.451796 [0-0] * TLSv1.3 (IN), TLS handshake, Server hello (2):
01:49:30.452014 [0-0] * TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
01:49:30.452062 [0-0] * TLSv1.3 (IN), TLS handshake, Certificate (11):
01:49:30.452464 [0-0] * TLSv1.3 (IN), TLS handshake, CERT verify (15):
01:49:30.452582 [0-0] * TLSv1.3 (IN), TLS handshake, Finished (20):
01:49:30.452650 [0-0] * TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
01:49:30.452717 [0-0] * TLSv1.3 (OUT), TLS handshake, Finished (20):
01:49:30.452879 [0-0] * SSL connection using TLSv1.3 / TLS_AES_128_GCM_SHA256 / x25519 / id-ecPublicKey
01:49:30.452919 [0-0] * ALPN: server accepted h2
01:49:30.452966 [0-0] * Server certificate:
01:49:30.453007 [0-0] *  subject: 
01:49:30.453046 [0-0] *  start date: Oct  6 07:37:49 2025 GMT
01:49:30.453080 [0-0] *  expire date: Oct  6 19:37:49 2025 GMT
01:49:30.453120 [0-0] *  subjectAltName: host "localhost" matched cert's "localhost"
01:49:30.453159 [0-0] *  issuer: CN=Caddy Local Authority - ECC Intermediate
01:49:30.453204 [0-0] *  SSL certificate verify ok.
01:49:30.453245 [0-0] *   Certificate level 0: Public key type EC/prime256v1 (256/128 Bits/secBits), signed using ecdsa-with-SHA256
01:49:30.453284 [0-0] *   Certificate level 1: Public key type EC/prime256v1 (256/128 Bits/secBits), signed using ecdsa-with-SHA256
01:49:30.453320 [0-0] *   Certificate level 2: Public key type EC/prime256v1 (256/128 Bits/secBits), signed using ecdsa-with-SHA256
01:49:30.453359 [0-0] * [HTTPS-CONNECT] connect+handshake h21: 8ms, 1st data: 7ms
01:49:30.453422 [0-0] * [HTTP/2] [0] created h2 session
01:49:30.453464 [0-0] * [HTTP/2] [0] -> FRAME[SETTINGS, len=18]
01:49:30.453496 [0-0] * [HTTP/2] [0] -> FRAME[WINDOW_UPDATE, incr=1048510465]
01:49:30.453531 [0-0] * [HTTP/2] cf_connect() -> 0, 1, 
01:49:30.453567 [0-0] * [HTTPS-CONNECT] connect -> 0, done=1
01:49:30.453624 [0-0] * Connected to localhost (::1) port 443
01:49:30.453665 [0-0] * using HTTP/2
01:49:30.453764 [0-0] * [HTTP/2] [1] OPENED stream for https://localhost/big-empty-file
01:49:30.453801 [0-0] * [HTTP/2] [1] [:method: GET]
01:49:30.453844 [0-0] * [HTTP/2] [1] [:scheme: https]
01:49:30.453889 [0-0] * [HTTP/2] [1] [:authority: localhost]
01:49:30.453938 [0-0] * [HTTP/2] [1] [:path: /big-empty-file]
01:49:30.453985 [0-0] * [HTTP/2] [1] [user-agent: curl/8.11.1]
01:49:30.454032 [0-0] * [HTTP/2] [1] [accept: */*]
01:49:30.454072 [0-0] * [HTTP/2] [1] submit -> 85, 0
01:49:30.454121 [0-0] * [HTTP/2] [1] -> FRAME[HEADERS, len=38, hend=1, eos=1]
01:49:30.454201 [0-0] * [HTTP/2] [0] egress: wrote 111 bytes
01:49:30.454249 [0-0] * [HTTP/2] [1] cf_send(len=85) -> 85, 0, eos=1, h2 windows 65535-65535 (stream-conn), buffers 0-0 (stream-conn)
01:49:30.454289 [0-0] > GET /big-empty-file HTTP/2
01:49:30.454289 [0-0] > Host: localhost
01:49:30.454289 [0-0] > User-Agent: curl/8.11.1
01:49:30.454289 [0-0] > Accept: */*
01:49:30.454289 [0-0] > 
01:49:30.454563 [0-0] * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
01:49:30.454643 [0-0] * [HTTP/2] [0] ingress: read 39 bytes
01:49:30.454687 [0-0] * [HTTP/2] [0] <- FRAME[SETTINGS, len=30]
01:49:30.454733 [0-0] * [HTTP/2] [0] MAX_CONCURRENT_STREAMS: 250
01:49:30.454772 [0-0] * [HTTP/2] [0] ENABLE_PUSH: TRUE
01:49:30.454822 [0-0] * [HTTP/2] [0] notify MAX_CONCURRENT_STREAMS: 250
01:49:30.454866 [0-0] * [HTTP/2] [1] DRAIN select_bits=1
01:49:30.454911 [0-0] * [HTTP/2] [0] progress ingress: inbufg=0
01:49:30.454963 [0-0] * [HTTP/2] [0] ingress: read 13 bytes
01:49:30.454997 [0-0] * [HTTP/2] [0] <- FRAME[WINDOW_UPDATE, incr=983041]
01:49:30.455035 [0-0] * [HTTP/2] [0] progress ingress: inbufg=0
01:49:30.455115 [0-0] * [HTTP/2] [0] ingress: read 9 bytes
01:49:30.455154 [0-0] * [HTTP/2] [0] <- FRAME[SETTINGS, ack=1]
01:49:30.455192 [0-0] * [HTTP/2] [0] progress ingress: inbufg=0
01:49:30.455228 [0-0] * [HTTP/2] [0] progress ingress: done
01:49:30.455282 [0-0] * [HTTP/2] [0] -> FRAME[SETTINGS, ack=1]
01:49:30.455343 [0-0] * [HTTP/2] [0] egress: wrote 9 bytes
01:49:30.455387 [0-0] * [HTTP/2] [1] cf_recv(len=102400) -> -1 81, window=0/65536, connection 1048576000/1048576000
01:49:30.455427 [0-0] * Request completely sent off
01:49:30.455469 [0-0] * [HTTP/2] [0] progress ingress: done
01:49:30.455518 [0-0] * [HTTP/2] [1] cf_recv(len=102400) -> -1 81, window=0/65536, connection 1048576000/1048576000
01:49:30.455566 [0-0] * [HTTP/2] [0] progress ingress: done
01:49:30.455615 [0-0] * [HTTP/2] [1] cf_recv(len=102400) -> -1 81, window=0/65536, connection 1048576000/1048576000
01:49:30.644925 [0-0] * [HTTP/2] [0] progress ingress: done
01:49:30.644984 [0-0] * [HTTP/2] [1] cf_recv(len=102400) -> -1 81, window=0/65536, connection 1048576000/1048576000
01:49:31.645802 [0-0] * [HTTP/2] [0] progress ingress: done
01:49:31.645866 [0-0] * [HTTP/2] [1] cf_recv(len=102400) -> -1 81, window=0/65536, connection 1048576000/1048576000
01:49:32.647002 [0-0] * [HTTP/2] [0] progress ingress: done
01:49:32.647076 [0-0] * [HTTP/2] [1] cf_recv(len=102400) -> -1 81, window=0/65536, connection 1048576000/1048576000
01:49:33.648205 [0-0] * [HTTP/2] [0] progress ingress: done
01:49:33.648302 [0-0] * [HTTP/2] [1] cf_recv(len=102400) -> -1 81, window=0/65536, connection 1048576000/1048576000
01:49:34.648779 [0-0] * [HTTP/2] [0] progress ingress: done
01:49:34.648853 [0-0] * [HTTP/2] [1] cf_recv(len=102400) -> -1 81, window=0/65536, connection 1048576000/1048576000
01:49:35.649966 [0-0] * [HTTP/2] [0] progress ingress: done
01:49:35.650038 [0-0] * [HTTP/2] [1] cf_recv(len=102400) -> -1 81, window=0/65536, connection 1048576000/1048576000
01:49:36.651183 [0-0] * [HTTP/2] [0] progress ingress: done
01:49:36.651253 [0-0] * [HTTP/2] [1] cf_recv(len=102400) -> -1 81, window=0/65536, connection 1048576000/1048576000
01:49:37.652408 [0-0] * [HTTP/2] [0] progress ingress: done
01:49:37.652501 [0-0] * [HTTP/2] [1] cf_recv(len=102400) -> -1 81, window=0/65536, connection 1048576000/1048576000
01:49:38.652777 [0-0] * [HTTP/2] [0] progress ingress: done
01:49:38.652865 [0-0] * [HTTP/2] [1] cf_recv(len=102400) -> -1 81, window=0/65536, connection 1048576000/1048576000
01:49:39.653983 [0-0] * [HTTP/2] [0] progress ingress: done
01:49:39.654053 [0-0] * [HTTP/2] [1] cf_recv(len=102400) -> -1 81, window=0/65536, connection 1048576000/1048576000
01:49:40.456379 [0-0] * [HTTP/2] [0] ingress: read 206 bytes
01:49:40.456431 [0-0] < HTTP/2 504 
01:49:40.456484 [0-0] * [HTTP/2] [1] local window update by 10420224
01:49:40.456528 [0-0] * [HTTP/2] [1] status: HTTP/2 504
01:49:40.456579 [0-0] < accept-ranges: bytes
01:49:40.456626 [0-0] * [HTTP/2] [1] header: accept-ranges: bytes
01:49:40.456681 [0-0] < alt-svc: h3=":443"; ma=2592000
01:49:40.456734 [0-0] * [HTTP/2] [1] header: alt-svc: h3=":443"; ma=2592000
01:49:40.456777 [0-0] < cache-control: 
01:49:40.456818 [0-0] * [HTTP/2] [1] header: cache-control: 
01:49:40.456866 [0-0] < cache-status: Souin; fwd=bypass; detail=DEADLINE-EXCEEDED
01:49:40.456906 [0-0] * [HTTP/2] [1] header: cache-status: Souin; fwd=bypass; detail=DEADLINE-EXCEEDED
01:49:40.456950 [0-0] < etag: "ddb2otemkgur1z141z4"
01:49:40.457011 [0-0] * [HTTP/2] [1] header: etag: "ddb2otemkgur1z141z4"
01:49:40.457056 [0-0] < last-modified: Mon, 06 Oct 2025 07:49:16 GMT
01:49:40.457095 [0-0] * [HTTP/2] [1] header: last-modified: Mon, 06 Oct 2025 07:49:16 GMT
01:49:40.457134 [0-0] < server: Caddy
01:49:40.457173 [0-0] * [HTTP/2] [1] header: server: Caddy
01:49:40.457221 [0-0] < vary: Accept-Encoding
01:49:40.457257 [0-0] * [HTTP/2] [1] header: vary: Accept-Encoding
01:49:40.457292 [0-0] < x-souin-stored-ttl: 2m0s
01:49:40.457327 [0-0] * [HTTP/2] [1] header: x-souin-stored-ttl: 2m0s
01:49:40.457362 [0-0] < content-length: 4294967296
01:49:40.457394 [0-0] * [HTTP/2] [1] header: content-length: 4294967296
01:49:40.457443 [0-0] < date: Mon, 06 Oct 2025 07:49:40 GMT
01:49:40.457491 [0-0] * [HTTP/2] [1] header: date: Mon, 06 Oct 2025 07:49:40 GMT
01:49:40.457541 [0-0] * [HTTP/2] [1] <- FRAME[HEADERS, len=197, hend=1, eos=0]
01:49:40.457573 [0-0] < 
01:49:40.457607 [0-0] * [HTTP/2] [1] DRAIN select_bits=1
01:49:40.457659 [0-0] * [HTTP/2] [0] progress ingress: inbufg=0
01:49:40.457731 [0-0] * [HTTP/2] [0] ingress: read 30 bytes
01:49:40.457770 [0-0] * [HTTP/2] [0] progress ingress: inbufg=0
01:49:40.457812 [0-0] * [HTTP/2] [0] progress ingress: done
01:49:40.457851 [0-0] * [HTTP/2] [1] -> FRAME[RST_STREAM, len=4, flags=0, error=1]
01:49:40.457888 [0-0] * [HTTP/2] [1] RESET: PROTOCOL_ERROR (err 1)
01:49:40.457933 [0-0] * [HTTP/2] [1] DRAIN select_bits=1
01:49:40.458005 [0-0] * [HTTP/2] [0] egress: wrote 13 bytes
01:49:40.458033 [0-0] * [HTTP/2] [1] cf_recv(len=102400) -> -1 81, window=-1/-1, connection 1048575979/1048576000
01:49:40.458096 [0-0] * [HTTP/2] [1] returning CLOSE
01:49:40.458131 [0-0] * HTTP/2 stream 1 was not closed cleanly: PROTOCOL_ERROR (err 1)
01:49:40.458165 [0-0] * [HTTP/2] [1] stream_recv(len=102400) -> -1, 92
01:49:40.458199 [0-0] * [HTTP/2] [1] cf_recv(len=102400) -> -1 92, window=-1/-1, connection 1048575979/1048576000
01:49:40.458243 [0-0] * Connection #0 to host localhost left intact
curl: (92) HTTP/2 stream 1 was not closed cleanly: PROTOCOL_ERROR (err 1)
Internal server error

gucci-on-fleek avatar Oct 06 '25 08:10 gucci-on-fleek

Why are you caching file_server? There's very little benefit to that, you're likely increasing latency if anything. The OS kernel has its own file caching, files will get served very fast.

francislavoie avatar Oct 06 '25 09:10 francislavoie

@francislavoie

Why are you caching file_server? There's very little benefit to that, you're likely increasing latency if anything. The OS kernel has its own file caching, files will get served very fast.

I'm caching everything, since that was the easiest/laziest option to implement. But now that you point that out, that probably isn't the optimal solution.

gucci-on-fleek avatar Oct 06 '25 10:10 gucci-on-fleek

Yeah, caching is for dynamic content that's (relatively) slow to produce. The benefit for static content is very low (unless it's static content behind a proxy that's a network layer away and not on the same machine).

francislavoie avatar Oct 06 '25 10:10 francislavoie

@gucci-on-fleek you should not cache the file_server. But you can limit the response size to cache using max_cacheable_body_bytes directive.

darkweak avatar Oct 06 '25 16:10 darkweak

@darkweak

But you can limit the response size to cache using max_cacheable_body_bytes directive.

Ok, I'll change that setting, thanks! But I'd still argue that the default settings shouldn't ever cause Caddy to use 25GB of memory, since that could probably be used as a DoS in some cases.

gucci-on-fleek avatar Oct 06 '25 22:10 gucci-on-fleek

By default the cache-handler uses an in memory storage that's why the memory is growing, you should another one (redis, nats, etcd, ...).

darkweak avatar Oct 07 '25 05:10 darkweak