Slow load (5 seconds) only with png-images

Help
1

Hi.

1. Problem

I am running a caddy-reverse-proxy in a podman-container serving contents of a podman-apache-container. Loading a png-image (less than 100kB; either inside html and as raw file) results in loading and displaying 12% of the image as fast as expected. Then it hangs for about 5 to 6 seconds, then the rest of the file will be loaded as fast as expected.
The issue occurs with all browsers, I tested with chromium, firefox, curl and wget.

The issue occurs only with png, not with jpg, gif or html-content.
Once the image lies in cache, loading time is as expected.

I think it’s because of caddy as loading the png-image is
→ fast with development-apache-container (podman) directly connected
→ fast with production-apache-container (podman) directly connected to the port on server
→ slow as described with production-apache-container (podman) behind caddy-reverse-proxy running in a container (podman) on server

Somewhere I read about KeepAlive. I switched it off in apache and caddy: no success.

2. Error messages and/or full log output:

As there is no systemd in container, I cannot use journalctl for logging.
Here is the output of “podman pod logs”. You can see the delay of 6s between loading the image and the final loading of favicon.ico:

podman pod logs

> eae0b030cf95 10.0.2.100 - - [16/Nov/2023:00:19:09 +0000] "GET /storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png HTTP/1.1" 200 86772 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/117.0"
> eae0b030cf95 10.0.2.100 - - [16/Nov/2023:00:19:15 +0000] "GET /favicon.ico HTTP/1.1" 200 1250 "https://wikicardia.de/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png" "Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/117.0"

curl log

curl -vL wikicardia.de/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png > out.png

* processing: wikicardia.de/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1   
* Connected to wikicardia.de (90.187.109.81) port 80
> GET /storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png HTTP/1.1
> Host: wikicardia.de
> User-Agent: curl/8.2.1
> Accept: */*
> 
< HTTP/1.1 308 Permanent Redirect
< Connection: close
< Location: https://wikicardia.de/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png
< Server: Caddy
< Date: Thu, 16 Nov 2023 00:25:53 GMT
< Content-Length: 0
* Closing connection
* Clear auth, redirects to port from 80 to 443
* Issue another request to this URL: 'https://wikicardia.de/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png'
*   Trying 90.187.109.81:443...
* Connected to wikicardia.de (90.187.109.81) port 443
* ALPN: offers h2,http/1.1
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_128_GCM_SHA256
* ALPN: server accepted h2
* Server certificate:
*  subject: CN=wikicardia.de
*  start date: Oct 30 00:00:00 2023 GMT
*  expire date: Jan 28 23:59:59 2024 GMT
*  subjectAltName: host "wikicardia.de" matched cert's "wikicardia.de"
*  issuer: C=AT; O=ZeroSSL; CN=ZeroSSL ECC Domain Secure Site CA
*  SSL certificate verify ok.
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* using HTTP/2
* h2 [:method: GET]
* h2 [:scheme: https]
* h2 [:authority: wikicardia.de]
* h2 [:path: /storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png]
* h2 [user-agent: curl/8.2.1]
* h2 [accept: */*]
* Using Stream ID: 1
> GET /storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png HTTP/2
> Host: wikicardia.de
> User-Agent: curl/8.2.1
> Accept: */*
> 
{ [5 bytes data]
< HTTP/2 200 
< accept-ranges: bytes
< alt-svc: h3=":443"; ma=2592000
< content-type: image/png
< date: Thu, 16 Nov 2023 00:25:53 GMT
< etag: "1520b-607bb34a24eb2"
< last-modified: Sun, 15 Oct 2023 06:14:43 GMT
< server: Caddy
< server: Apache/2.4.54 (Debian)
< content-length: 86539
< 
{ [11203 bytes data]
100 86539  100 86539    0     0  16749      0  0:00:05  0:00:05 --:--:-- 13675
* Connection #1 to host wikicardia.de left intact

caddy debug log:

{"level":"debug","ts":1700321689.566036,"logger":"events","msg":"event","name":"tls_get_certificate","id":"8b2045c7-be4d-48d9-a338-fab458002e0d","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":"wikicardia.de","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],"Conn":{}}}}
{"level":"debug","ts":1700321689.56612,"logger":"tls.handshake","msg":"choosing certificate","identifier":"wikicardia.de","num_choices":1}
{"level":"debug","ts":1700321689.5661445,"logger":"tls.handshake","msg":"default certificate selection results","identifier":"wikicardia.de","subjects":["wikicardia.de"],"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"81c72b079e2dc74073c45ae2e0599f67332fdc913046b2b3e4eade153d8eb47c"}
{"level":"debug","ts":1700321689.5661566,"logger":"tls.handshake","msg":"matched certificate in cache","remote_ip":"10.0.2.100","remote_port":"34040","subjects":["wikicardia.de"],"managed":true,"expiration":1706486400,"hash":"81c72b079e2dc74073c45ae2e0599f67332fdc913046b2b3e4eade153d8eb47c"}
{"level":"debug","ts":1700321689.608357,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"fiducit-0-performance-server:18002","total_upstreams":1}
{"level":"debug","ts":1700321689.6137106,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"fiducit-0-performance-server:18002","duration":0.005303351,"request":{"remote_ip":"10.0.2.100","remote_port":"34040","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"User-Agent":["curl/8.2.1"],"Accept":["*/*"],"X-Forwarded-For":["10.0.2.100"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["wikicardia.de"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}},"headers":{"Accept-Ranges":["bytes"],"Content-Length":["86539"],"Content-Type":["image/png"],"Date":["Sat, 18 Nov 2023 15:34:49 GMT"],"Server":["Apache/2.4.54 (Debian)"],"Last-Modified":["Sun, 15 Oct 2023 06:14:43 GMT"],"Etag":["\"1520b-607bb34a24eb2\""]},"status":200}

Caddy version:
v2.7.5

4. How I installed and ran Caddy:

docker image via podman:
Client: Podman Engine
Version: 4.3.1
API Version: 4.3.1
Go Version: go1.19.8
Built: Thu Jan 1 01:00:00 1970
OS/Arch: linux/amd64

#podman ps

cd9d004c848e  docker.io/library/caddy:latest  caddy run --confi...  7 minutes ago  Up 7 minutes ago  0.0.0.0:14001->443/tcp, 0.0.0.0:18001->80/tcp  reverse-proxy_caddy
docker.io/library/caddy:latest

a. System environment

uname -r

6.1.0-13-amd64

neofetch

app_001_infra_reverse-proxy@fiducit-0-performance-server 
OS: Debian GNU/Linux 12 (bookworm) x86_64 
Kernel: 6.1.0-13-amd64 
Uptime: 4 days, 18 hours, 23 mins 
Packages: 906 (dpkg) 
Shell: bash 5.2.15 
Terminal: /dev/pts/0 
CPU: AMD Ryzen Threadripper 2990WX (64) @ 3.000GHz 
GPU: NVIDIA GeForce GT 1030 
Memory: 1760MiB / 31990MiB

b. Command:

/usr/bin/podman container run \
        --cidfile=%t/%n.ctr-id \
        --cgroups=no-conmon \
        --rm \
        --pod-id-file %t/pod-reverse-proxy.pod-id \
        --sdnotify=conmon \
        -d \
        --replace \
        --name reverse-proxy_caddy \
        -v /data/apps/001_infra_reverse-proxy/data/caddy/Caddyfiles/:/etc/caddy/ \
        -v /data/apps/001_infra_reverse-proxy/data/caddy/config/:/config/ \
        -v /data/apps/001_infra_reverse-proxy/data/caddy/data/:/data/ \
        caddy:latest

c. Service/unit/compose file:

# container-reverse-proxy_caddy.service
# autogenerated by Podman 4.3.1
# Mon Oct 30 01:22:01 CET 2023

[Unit]
Description=Podman container-reverse-proxy_caddy.service
Documentation=man:podman-generate-systemd(1)
Wants=network-online.target
After=network-online.target
RequiresMountsFor=%t/containers
BindsTo=pod-reverse-proxy.service
After=pod-reverse-proxy.service

[Service]
Environment=PODMAN_SYSTEMD_UNIT=%n
Restart=on-failure
TimeoutStopSec=70
ExecStartPre=/bin/rm \
        -f %t/%n.ctr-id
ExecStart=/usr/bin/podman container run \
        --cidfile=%t/%n.ctr-id \
        --cgroups=no-conmon \
        --rm \
        --pod-id-file %t/pod-reverse-proxy.pod-id \
        --sdnotify=conmon \
        -d \
        --replace \
        --name reverse-proxy_caddy \
        -v /data/apps/001_infra_reverse-proxy/data/caddy/Caddyfiles/:/etc/caddy/ \
        -v /data/apps/001_infra_reverse-proxy/data/caddy/config/:/config/ \
        -v /data/apps/001_infra_reverse-proxy/data/caddy/data/:/data/ \
        caddy:latest

d. My complete Caddy config:

{
        debug
        email   kontakt@fiducit.de
        cert_issuer zerossl APIID
}

import etc_conf.d/*.caddy
import 0-performance_conf.d/*.caddy
import 1-storage_conf.d/*.caddy

cat 0-performance_conf.d/002_egbert.jacobs_wikicardia.caddy

wikicardia.de {
        reverse_proxy fiducit-0-performance-server:18002
}

www.wikicardia.de {
        redir https://wikicardia.de{uri}
}

5. Links to relevant resources:

none

2

Thanks for your debug logs, that’s a good start.

From opening that PNG in a browser, I notice that the image half loads and then pauses, then completes a few seconds later.

This shows that the proxy roundtrip was fast (5 milliseconds) so the problem doesn’t seem to be with your upstream. So this is certainly strange.

Please also add the log directive to your site block, to enable access logs. I’m curious to see what the request duration shows there.

If access logs also show that it’s fast, then the problem is probably at the networking layer for whatever reason.

I’m not an expert at low level TCP networking settings, but there might be something funky going on at that layer. :thinking:

3

Thanks for your reply and the time you spent.

Below the log lines (systemd of hosting the caddy-container) while request.
There is the 5-seconds-leap between the last two lines.

The second to last line comes from
logger: http.handlers.reverse_proxy

The last line comes from
logger: http.log.access.wikicardia-logger
The duration of the request in this line shows nearly exactly 5 seconds everytime I try:
duration: 5.000923963
duration: 5.001239373
duration: 5.000024392
duration: 5.000670855
duration: 5.000489334

Somewhere there seems to be a configured (?) delay of 5 seconds.

Nov 18 19:13:34 fiducit-0-performance-server reverse-proxy_caddy[848792]: {"level":"debug","ts":1700331214.4199002,"logger":"tls.handshake","msg":"choosing certificate","identifier":"wikicardia.de","num_choices":1}
Nov 18 19:13:34 fiducit-0-performance-server reverse-proxy_caddy[848792]: {"level":"debug","ts":1700331214.419927,"logger":"tls.handshake","msg":"default certificate selection results","identifier":"wikicardia.de","subjects":["wikicardia.de"],"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"81c72b079e2dc74073c45ae2e0599f67332fdc913046b2b3e4eade153d8eb47c"}
Nov 18 19:13:34 fiducit-0-performance-server reverse-proxy_caddy[848792]: {"level":"debug","ts":1700331214.41994,"logger":"tls.handshake","msg":"matched certificate in cache","remote_ip":"10.0.2.100","remote_port":"34826","subjects":["wikicardia.de"],"managed":true,"expiration":1706486400,"hash":"81c72b079e2dc74073c45ae2e0599f67332fdc913046b2b3e4eade153d8eb47c"}
Nov 18 19:13:34 fiducit-0-performance-server reverse-proxy_caddy[848792]: {"level":"debug","ts":1700331214.4450545,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"fiducit-0-performance-server:18002","total_upstreams":1}
Nov 18 19:13:34 fiducit-0-performance-server reverse-proxy_caddy[848792]: {"level":"debug","ts":1700331214.449749,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"fiducit-0-performance-server:18002","duration":0.004583204,"request":{"remote_ip":"10.0.2.100","remote_port":"34826","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"X-Forwarded-For":["10.0.2.100"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["wikicardia.de"],"Accept":["*/*"],"User-Agent":["curl/8.2.1"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}},"headers":{"Content-Length":["86539"],"Content-Type":["image/png"],"Date":["Sat, 18 Nov 2023 18:13:34 GMT"],"Server":["Apache/2.4.54 (Debian)"],"Last-Modified":["Sun, 15 Oct 2023 06:14:43 GMT"],"Etag":["\"1520b-607bb34a24eb2\""],"Accept-Ranges":["bytes"]},"status":200}
Nov 18 19:13:39 fiducit-0-performance-server reverse-proxy_caddy[848792]: {"level":"info","ts":1700331219.445193,"logger":"http.log.access.wikicardia-logger","msg":"handled request","request":{"remote_ip":"10.0.2.100","remote_port":"34826","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"User-Agent":["curl/8.2.1"],"Accept":["*/*"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}},"bytes_read":0,"user_id":"","duration":5.000199546,"size":86539,"status":200,"resp_headers":{"Accept-Ranges":["bytes"],"Content-Length":["86539"],"Content-Type":["image/png"],"Server":["Caddy","Apache/2.4.54 (Debian)"],"Alt-Svc":["h3=\":443\"; ma=2592000"],"Date":["Sat, 18 Nov 2023 18:13:34 GMT"],"Last-Modified":["Sun, 15 Oct 2023 06:14:43 GMT"],"Etag":["\"1520b-607bb34a24eb2\""]}}
1 Like
4

One more thing to try. Enable verbose_logs in your proxy (new feature added in v2.7.5 to spit out lots of logs in the proxy).

wikicardia.de {
	reverse_proxy fiducit-0-performance-server:18002 {
		verbose_logs
	}
}

This might show more info about timing for response body copying/streaming.

5

Here is the output with
directive verbose_logs and directive log:

Nov 18 22:52:38 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344358.1278777,"logger":"events","msg":"event","name":"tls_get_certificate","id":"5364d413-a8f9-4398-8ec5-011cca84e975","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":"wikicardia.de","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],"Conn":{}}}}
Nov 18 22:52:38 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344358.1279802,"logger":"tls.handshake","msg":"choosing certificate","identifier":"wikicardia.de","num_choices":1}
Nov 18 22:52:38 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344358.1280065,"logger":"tls.handshake","msg":"default certificate selection results","identifier":"wikicardia.de","subjects":["wikicardia.de"],"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"81c72b079e2dc74073c45ae2e0599f67332fdc913046b2b3e4eade153d8eb47c"}
Nov 18 22:52:38 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344358.1280189,"logger":"tls.handshake","msg":"matched certificate in cache","remote_ip":"10.0.2.100","remote_port":"54232","subjects":["wikicardia.de"],"managed":true,"expiration":1706486400,"hash":"81c72b079e2dc74073c45ae2e0599f67332fdc913046b2b3e4eade153d8eb47c"}
Nov 18 22:52:38 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344358.1720827,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"fiducit-0-performance-server:18002","total_upstreams":1}
Nov 18 22:52:38 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344358.1782415,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"fiducit-0-performance-server:18002","duration":0.006043263,"request":{"remote_ip":"10.0.2.100","remote_port":"54232","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"User-Agent":["curl/8.2.1"],"Accept":["*/*"],"X-Forwarded-For":["10.0.2.100"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["wikicardia.de"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}},"headers":{"Server":["Apache/2.4.54 (Debian)"],"Last-Modified":["Sun, 15 Oct 2023 06:14:43 GMT"],"Etag":["\"1520b-607bb34a24eb2\""],"Accept-Ranges":["bytes"],"Content-Length":["86539"],"Content-Type":["image/png"],"Date":["Sat, 18 Nov 2023 21:52:38 GMT"]},"status":200}
Nov 18 22:52:38 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344358.1782818,"logger":"http.handlers.reverse_proxy","msg":"wrote header","upstream":"fiducit-0-performance-server:18002","duration":0.006043263,"request":{"remote_ip":"10.0.2.100","remote_port":"54232","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"User-Agent":["curl/8.2.1"],"Accept":["*/*"],"X-Forwarded-For":["10.0.2.100"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["wikicardia.de"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}}}
Nov 18 22:52:38 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344358.1782975,"logger":"http.handlers.reverse_proxy","msg":"waiting to read from upstream","upstream":"fiducit-0-performance-server:18002","duration":0.006043263,"request":{"remote_ip":"10.0.2.100","remote_port":"54232","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"User-Agent":["curl/8.2.1"],"Accept":["*/*"],"X-Forwarded-For":["10.0.2.100"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["wikicardia.de"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}}}
Nov 18 22:52:38 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344358.1783104,"logger":"http.handlers.reverse_proxy","msg":"read from upstream","upstream":"fiducit-0-performance-server:18002","duration":0.006043263,"request":{"remote_ip":"10.0.2.100","remote_port":"54232","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"User-Agent":["curl/8.2.1"],"Accept":["*/*"],"X-Forwarded-For":["10.0.2.100"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["wikicardia.de"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}},"read":3863}
Nov 18 22:52:38 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344358.1783214,"logger":"http.handlers.reverse_proxy","msg":"writing to downstream","upstream":"fiducit-0-performance-server:18002","duration":0.006043263,"request":{"remote_ip":"10.0.2.100","remote_port":"54232","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"User-Agent":["curl/8.2.1"],"Accept":["*/*"],"X-Forwarded-For":["10.0.2.100"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["wikicardia.de"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}},"read":3863}
Nov 18 22:52:38 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344358.1783307,"logger":"http.handlers.reverse_proxy","msg":"wrote to downstream","upstream":"fiducit-0-performance-server:18002","duration":0.006043263,"request":{"remote_ip":"10.0.2.100","remote_port":"54232","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"User-Agent":["curl/8.2.1"],"Accept":["*/*"],"X-Forwarded-For":["10.0.2.100"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["wikicardia.de"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}},"read":3863,"written":3863,"written_total":3863}
Nov 18 22:52:38 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344358.178338,"logger":"http.handlers.reverse_proxy","msg":"waiting to read from upstream","upstream":"fiducit-0-performance-server:18002","duration":0.006043263,"request":{"remote_ip":"10.0.2.100","remote_port":"54232","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"User-Agent":["curl/8.2.1"],"Accept":["*/*"],"X-Forwarded-For":["10.0.2.100"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["wikicardia.de"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}}}
Nov 18 22:52:38 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344358.178359,"logger":"http.handlers.reverse_proxy","msg":"read from upstream","upstream":"fiducit-0-performance-server:18002","duration":0.006043263,"request":{"remote_ip":"10.0.2.100","remote_port":"54232","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"User-Agent":["curl/8.2.1"],"Accept":["*/*"],"X-Forwarded-For":["10.0.2.100"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["wikicardia.de"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}},"read":28672}
Nov 18 22:52:38 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344358.1783688,"logger":"http.handlers.reverse_proxy","msg":"writing to downstream","upstream":"fiducit-0-performance-server:18002","duration":0.006043263,"request":{"remote_ip":"10.0.2.100","remote_port":"54232","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"User-Agent":["curl/8.2.1"],"Accept":["*/*"],"X-Forwarded-For":["10.0.2.100"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["wikicardia.de"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}},"read":28672}
Nov 18 22:52:38 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344358.1787384,"logger":"http.handlers.reverse_proxy","msg":"wrote to downstream","upstream":"fiducit-0-performance-server:18002","duration":0.006043263,"request":{"remote_ip":"10.0.2.100","remote_port":"54232","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"User-Agent":["curl/8.2.1"],"Accept":["*/*"],"X-Forwarded-For":["10.0.2.100"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["wikicardia.de"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}},"read":28672,"written":28672,"written_total":32535}
Nov 18 22:52:38 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344358.1787746,"logger":"http.handlers.reverse_proxy","msg":"waiting to read from upstream","upstream":"fiducit-0-performance-server:18002","duration":0.006043263,"request":{"remote_ip":"10.0.2.100","remote_port":"54232","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"User-Agent":["curl/8.2.1"],"Accept":["*/*"],"X-Forwarded-For":["10.0.2.100"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["wikicardia.de"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}}}
Nov 18 22:52:43 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344363.278182,"logger":"http.handlers.reverse_proxy","msg":"read from upstream","upstream":"fiducit-0-performance-server:18002","duration":0.006043263,"request":{"remote_ip":"10.0.2.100","remote_port":"54232","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"User-Agent":["curl/8.2.1"],"Accept":["*/*"],"X-Forwarded-For":["10.0.2.100"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["wikicardia.de"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}},"read":32712}
Nov 18 22:52:43 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344363.2782152,"logger":"http.handlers.reverse_proxy","msg":"writing to downstream","upstream":"fiducit-0-performance-server:18002","duration":0.006043263,"request":{"remote_ip":"10.0.2.100","remote_port":"54232","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"User-Agent":["curl/8.2.1"],"Accept":["*/*"],"X-Forwarded-For":["10.0.2.100"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["wikicardia.de"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}},"read":32712}
Nov 18 22:52:43 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344363.2784207,"logger":"http.handlers.reverse_proxy","msg":"wrote to downstream","upstream":"fiducit-0-performance-server:18002","duration":0.006043263,"request":{"remote_ip":"10.0.2.100","remote_port":"54232","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"User-Agent":["curl/8.2.1"],"Accept":["*/*"],"X-Forwarded-For":["10.0.2.100"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["wikicardia.de"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}},"read":32712,"written":32712,"written_total":65247}
Nov 18 22:52:43 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344363.2784505,"logger":"http.handlers.reverse_proxy","msg":"waiting to read from upstream","upstream":"fiducit-0-performance-server:18002","duration":0.006043263,"request":{"remote_ip":"10.0.2.100","remote_port":"54232","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"User-Agent":["curl/8.2.1"],"Accept":["*/*"],"X-Forwarded-For":["10.0.2.100"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["wikicardia.de"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}}}
Nov 18 22:52:43 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344363.2785528,"logger":"http.handlers.reverse_proxy","msg":"read from upstream","upstream":"fiducit-0-performance-server:18002","duration":0.006043263,"request":{"remote_ip":"10.0.2.100","remote_port":"54232","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"User-Agent":["curl/8.2.1"],"Accept":["*/*"],"X-Forwarded-For":["10.0.2.100"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["wikicardia.de"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}},"read":21292,"error":"EOF"}
Nov 18 22:52:43 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344363.2785842,"logger":"http.handlers.reverse_proxy","msg":"writing to downstream","upstream":"fiducit-0-performance-server:18002","duration":0.006043263,"request":{"remote_ip":"10.0.2.100","remote_port":"54232","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"User-Agent":["curl/8.2.1"],"Accept":["*/*"],"X-Forwarded-For":["10.0.2.100"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["wikicardia.de"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}},"read":21292}
Nov 18 22:52:43 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344363.2787623,"logger":"http.handlers.reverse_proxy","msg":"wrote to downstream","upstream":"fiducit-0-performance-server:18002","duration":0.006043263,"request":{"remote_ip":"10.0.2.100","remote_port":"54232","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"User-Agent":["curl/8.2.1"],"Accept":["*/*"],"X-Forwarded-For":["10.0.2.100"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["wikicardia.de"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}},"read":21292,"written":21292,"written_total":86539}
Nov 18 22:52:43 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"debug","ts":1700344363.2787778,"logger":"http.handlers.reverse_proxy","msg":"closed response body from upstream","upstream":"fiducit-0-performance-server:18002","duration":0.006043263,"request":{"remote_ip":"10.0.2.100","remote_port":"54232","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"User-Agent":["curl/8.2.1"],"Accept":["*/*"],"X-Forwarded-For":["10.0.2.100"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["wikicardia.de"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}}}
Nov 18 22:52:43 fiducit-0-performance-server reverse-proxy_caddy[871925]: {"level":"info","ts":1700344363.2788196,"logger":"http.log.access.wikicardia-logger","msg":"handled request","request":{"remote_ip":"10.0.2.100","remote_port":"54232","client_ip":"10.0.2.100","proto":"HTTP/2.0","method":"GET","host":"wikicardia.de","uri":"/storage/base/titlelogo/3d6266fed52d0a99b6cebc1a209d1c33.png","headers":{"Accept":["*/*"],"User-Agent":["curl/8.2.1"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"wikicardia.de"}},"bytes_read":0,"user_id":"","duration":5.106797965,"size":86539,"status":200,"resp_headers":{"Content-Type":["image/png"],"Date":["Sat, 18 Nov 2023 21:52:38 GMT"],"Last-Modified":["Sun, 15 Oct 2023 06:14:43 GMT"],"Etag":["\"1520b-607bb34a24eb2\""],"Server":["Caddy","Apache/2.4.54 (Debian)"],"Alt-Svc":["h3=\":443\"; ma=2592000"],"Accept-Ranges":["bytes"],"Content-Length":["86539"]}}

By the way: Now I have converted every png-image to webp. There is no delay anymore. So at least there is a simple workaround.
Nevertheless it would be interesting to get into the cause of the problem.

Egbert

1 Like
6

This is where the 5-second latency is:

This is the location in the code:

This points towards it not being an issue with Caddy. However, I have a hunch. Do you know if your upstream sets the Content-Length header in its response off PNG files?

After you validate the fact about Content-Length from your upstream app, can you try adding flush_interval -1 inside the reverse_proxy block? Read about it here:

7

Thanks for your hints.

apache upstream sets the Content-Length header in its response:
Content-Length: 86539. That’s a correct value.

Adding flush_interval -1 inside the reverse_proxy block has no effect on the latency.

8

I’m very confused. I’m leaning towards it being a network issue and perhaps specific to Podman, but I’m not familiar much with Podman. To narrow it down to Podman, any chance you can try Docker?

9

Thank you very much for your hints.
I will try to narrow it down. It will take time. I’ll be back then.

Egbert

1 Like
10

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.

12

Hi!

The issue had nothing to do with the image-format PNG.
EVERY file with a minimum size of about 100kB leads to the describe issue, caused by a bug in the network handler slirp4netns used as default in rootless podman.

Explanation:
Podman runs caddy in a rootless container, so it has no root rights on host. This is why podman translates unprivileged ports like 14001 from outside to 443 inside the pod. Caddy only listens on this port and has no possibility to reach other ports outside the container. This is a security feature of podman.

This is the scheme of mapping and translating in the old configuration (with issue)

 incoming  firewall    pod caddy   caddy-reverse-proxy    pod app    app-container
 443       443:14001   14001:443   443     ->    18002    18002:80   80

The podman default program to realize translation from pod to (14001:443) for unprivileged network namespaces is named slirp4netns:
podman manual slirp4netns
slirp4netns on github
Unfortunately the manual of slirp4netns lists (only) one bug. This bug is the cause of 5s-issue:

Kernel 4.20 bumped up the default value of /proc/sys/net/ipv4/tcp_rmem from
87380 to 131072. This is known to slow down slirp4netns port forwarding:
bug report. As a workaround, you can adjust the value of /proc/sys/net/ipv4/tcp_rmem
inside the namespace.

Following the workaround avoids the 5s-leap, but leads to notably decreased
transfer rates.

The podman documentation mentions pasta as an alternative to slirp4netns. I couldn’t try it out because my podman version 4.3.1 contains no pasta and there is no stable debian with higher podman version.

Finally the solution is to get rid of slirp4netns and just completely pass through the host network interface. By this way caddy listens on the WHOLE network device and not only one specific port:

old configuration scheme
incoming  firewall    pod caddy   caddy-reverse-proxy    pod app    app-container
443       443:14001   14001:443   443     ->    18002    18002:80   80

new configuration scheme
incoming  firewall    pod caddy   caddy-reverse-proxy    pod app    app-container
443       443:14001   -------->   14001   ->    18002    18002:80   80

So I have to accept that the security standard decreases a little.

The podman options with podman-create:

old configuration with issue
podman create [...] --network=slirp4netns [...]

new configuration without issue
podman create [...] --network=host [...]

caddyfile

{
        email   USER@MAIL
        cert_issuer zerossl APPID
        http_port 18001
        https_port 14001
}

import DIR1/*.caddy

Thanks very much for your hints and time!

4 Likes
13

Excellent detective work. Thanks for the thorough answer to help future searchers!

1 Like
14

This same issue happens in Docker (caddy-reverse-proxy: loading png-images hangs for 5 seconds · Issue #5936 · caddyserver/caddy · GitHub) - it’s not just podman. Switching to host networking is not really a good solution; that defeats much of the purpose of using containers.

If this is a Docker/Podman bug, and not an issue with Caddy as well, why does the issue not happen under nginx and Apache?

I’d love to see this fixed with Caddy.

15

If that’s the case it could be lower in the network stack.

Are you experiencing the same delay as Mohammed identified here?

If so, all we’re doing is calling Read() which goes almost directly into the network stack. There might be a thin layer of standard library Go code in between.

16

It sounds like your issue isn’t the same, so you should open a new topic and fill out the help topic template to get help.

17

Posted to Slow reverse proxy compared to apache - turns out this is not actually Docker related.

18

This topic was automatically closed after 11 days. New replies are no longer allowed.