How to debug reverse proxy with multiple upstreams?

Help
1

I run caddy reverse proxy with multiple upstreams and have this problem: when 1 upstream fails, sometime caddy fails to response to incoming requests, despite the other upstreams are still healthy. How can I debug and find out the cause? The config was included below. It was simplified, the real config has multiple services instead of abc, but they are all similar and differ only in the abc part.

{
  log default {
    level DEBUG
    format json
    output file /var/log/caddy/default.log
  }
}
(lb_settings) {
    header_up Host {upstream_hostport}
    lb_policy round_robin
    ## passive health check:
    fail_duration 120m        # if an upstream fails, it's taken from the pool for this duration
    unhealthy_latency 20s     # max duration to complete a request
    ## active health check:
    health_uri /health-check  # /health-check must be configured on upstream servers
    health_status 200         # default is 200
    health_interval 30s       # default is 30s
    health_timeout 5s         # default is 5s
}
abc.example.net {
  log {
    output file /var/log/caddy/abc.log
  }
  reverse_proxy {
    to https://abc1.example.com
    to https://abc2.example.com
    to https://abc3.example.com
    to https://abc4.example.com
    to https://abc5.example.com
    import lb_settings
  }
}
2

Enable the debug global option. What’s in your logs when failures happen?

You might want to enable retries so Caddy can try another upstream if the connection fails.

3

after enabling debug I could see some entries with msg “no upstreams available” (attached below). However the preceding entries didn’t reveal anything unusual.

how can I find the reason why there is no upstream available?

{
  "level": "debug",
  "ts": 1710725124.1058261,
  "logger": "http.handlers.reverse_proxy",
  "msg": "selected upstream",
  "dial": "swf4.example.com:443",
  "total_upstreams": 4
}
.
.
{
  "level": "error",
  "ts": 1710734491.341056,
  "logger": "http.log.error.log7",
  "msg": "no upstreams available",
  "request": {
    "remote_ip": "1.2.3.4",
    "remote_port": "10947",
    "proto": "HTTP/2.0",
    "method": "GET",
    "host": "swf.example.com",
    "uri": "/split_workflow_opecon.php",
    "headers": {
      "User-Agent": [
        "Mozilla/5.0 (X11; Linux x86_64; rv:122.0) Gecko/20100101 Firefox/122.0"
      ],
      "Accept-Language": [
        "en-US,en;q=0.5"
      ],
      "Cookie": [],
      "Sec-Fetch-Dest": [
        "document"
      ],
      "Te": [
        "trailers"
      ],
      "Accept": [
        "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8"
      ],
      "Accept-Encoding": [
        "gzip, deflate, br"
      ],
      "Referer": [
        "https://swf.example.com/"
      ],
      "Upgrade-Insecure-Requests": [
        "1"
      ],
      "Sec-Fetch-Mode": [
        "navigate"
      ],
      "Sec-Fetch-Site": [
        "same-origin"
      ],
      "Sec-Fetch-User": [
        "?1"
      ]
    },
    "tls": {
      "resumed": true,
      "version": 772,
      "cipher_suite": 4865,
      "proto": "h2",
      "server_name": "swf.example.com"
    }
  },
  "duration": 0.000118616,
  "status": 503,
  "err_id": "ns06xyp9a",
  "err_trace": "reverseproxy.(*Handler).proxyLoopIteration (reverseproxy.go:547)"
}
4

the config I posted here is a bit simplified. The real config has nearly 20 sites, but they are all similar to this:

abc.example.net {
  log {
    output file /var/log/caddy/abc.log
  }
  reverse_proxy {
    to https://abc1.example.com
    to https://abc2.example.com
    to https://abc3.example.com
    to https://abc4.example.com
    to https://abc5.example.com
    import lb_settings
  }
}

I feel that I am doing something wrong here, because way many health checks are being done, but in reality I have only 5 upstream servers.

5

This is a super long time. 120 minutes. Are you sure that’s what you meant? That’s probably the reason.

Usually fail duration should be in seconds, like 5s or 30s, that kind of thing.

Basically this means “if a single connection failure happens, ignore this upstream for two hours”, wouldn’t be surprising that it would totally stop responding quite quickly.

6

the reverse proxy is a server at DigitalOcean. All the upstream servers are located on a site with unreliable connections. When a link fails, it is usually down for a few hours. So I thought 2 hours is a reasonable value for fail_duration?

7

That means Caddy will remember a single request failure for 2 hours and never recognize it as healthy again until it forgets about that failure. That’s definitely way, way too long. If the upstream comes back online within a minute, then it would still wait 2 hours before it realizes it. You want a short enough time so that Caddy will allow trying to connect again within short order. You might also want to enable retries to smooth it over so if connecting to one fails, it’ll try another with the same request (so the user doesn’t see an error).

8

thanks for the hint. I added lb_retries 3 and reduced fail_duration to 5m.

However I cannot reproduce the problems consistently, so I have to wait for sometime and see if things improve.

9

the situation has slightly improved after your suggestion, thank you. However it’s not completely resolved; sometime I get errors “no upstream available” when only 1 upstream fails.

Isn’t it better to disable active health check in my case? It seems that passive health check should be sufficient?

10

A 5 minute fail timeout is still very long. Are you sure that all 3 didn’t go down for a single health check within 5 minutes of eachother?

Please share your config as it is now, and share debug logs from around the time you have the problem.

11

Please find the Caddyfile below.

{
  debug
  log default {
    level DEBUG
    format json
    output file /var/log/caddy/default.log
  }
}
(lb_settings) {
    header_up Host {upstream_hostport}
    lb_policy round_robin
    ## passive health check:
    fail_duration 5m          # if an upstream fails, it's taken from the pool for this duration
    unhealthy_latency 20s     # max duration to complete a request
    ## active health check:
    health_uri /health-check  # /health-check must be configured on upstream servers
    health_status 200         # default is 200
    health_interval 30s       # default is 30s
    health_timeout 5s         # default is 5s
    lb_retries 3              # defaullt is 0
}
helpdesk.river-valley.com {
  log {
    output file /var/log/caddy/helpdesk.river-valley.com.log
  }
  basicauth / {
   user deleted-password
  }
  root * /srv/caddy/helpdesk.river-valley.com
  file_server
}
helpdesk-primo.river-valley.com {
  log {
    output file /var/log/caddy/helpdesk-primo.river-valley.com.log
  }
  basicauth / {
   user deleted-password
  }
  root * /srv/caddy/helpdesk-primo.river-valley.com
  file_server
}
tf.stmdocs.com {
  log {
    output file /var/log/caddy/tf.log
  }
  reverse_proxy {
    to https://texfolio1.river-valley.com
    to https://texfolio2.river-valley.com
    #to https://texfolio3.river-valley.com
    to https://texfolio4.river-valley.com
    to https://texfolio5.river-valley.com
    import lb_settings
  }
}
https://tf.stmdocs.com:8443 {
  log {
    output file /var/log/caddy/tf-8443.log
  }
  reverse_proxy {
    to https://texfolio1.river-valley.com:8443
    to https://texfolio2.river-valley.com:8443
    #to https://texfolio3.river-valley.com:8443
    to https://texfolio4.river-valley.com:8443
    to https://texfolio5.river-valley.com:8443
    import lb_settings
  }
}
tf-wiki.stmdocs.com {
  log {
    output file /var/log/caddy/tf-wiki.log
  }
  reverse_proxy {
    #to https://tf-wiki1.river-valley.com
    to https://tf-wiki2.river-valley.com
    to https://tf-wiki3.river-valley.com
    to https://tf-wiki4.river-valley.com
    to https://tf-wiki5.river-valley.com
    import lb_settings
  }
}
kimai.stmdocs.com {
  log {
    output file /var/log/caddy/kimai.log
  }
  reverse_proxy {
    to https://kimai1.river-valley.com
    to https://kimai2.river-valley.com
    #to https://kimai3.river-valley.com
    to https://kimai4.river-valley.com
    to https://kimai5.river-valley.com
    import lb_settings
  }
}
https://kimai.stmdocs.com:1880 {
  log {
    output file /var/log/caddy/kimai-1880.log
  }
  reverse_proxy {
    to https://kimai1.river-valley.com:1880
    to https://kimai2.river-valley.com:1880
    #to https://kimai3.river-valley.com:1880
    to https://kimai4.river-valley.com:1880
    to https://kimai5.river-valley.com:1880
    import lb_settings
  }
}
swf.stmdocs.com {
  log {
    level DEBUG
    output file /var/log/caddy/swf.log
  }
  reverse_proxy {
    to https://swf1.river-valley.com
    to https://swf2.river-valley.com
    #to https://swf3.river-valley.com
    to https://swf4.river-valley.com
    to https://swf5.river-valley.com
    import lb_settings
  }
}
https://swf.stmdocs.com:1880 {
  log {
    output file /var/log/caddy/swf-1880.log
  }
  reverse_proxy {
    to https://swf1.river-valley.com:1880
    to https://swf2.river-valley.com:1880
    #to https://swf3.river-valley.com:1880
    to https://swf4.river-valley.com:1880
    to https://swf5.river-valley.com:1880
    import lb_settings
  }
}
stmdocs.in, 
www.stmdocs.in, 
stmdocs.com, 
www.stmdocs.com {
  log {
    output file /var/log/caddy/stmdocs.log
  }
  reverse_proxy {
    to https://stmdocs1.river-valley.com
    to https://stmdocs2.river-valley.com
    #to https://stmdocs3.river-valley.com
    to https://stmdocs4.river-valley.com
    to https://stmdocs5.river-valley.com
    import lb_settings
  }
}
support.stmdocs.in,
els-support.stmdocs.com,
support.stmdocs.com {
  log {
    output file /var/log/caddy/support.log
  }
  reverse_proxy {
    #to https://els-support1.river-valley.com
    to https://els-support2.river-valley.com
    to https://els-support3.river-valley.com
    to https://els-support4.river-valley.com
    to https://els-support5.river-valley.com
    import lb_settings
  }
}
forum-stm-support.stmdocs.com {
  log {
    output file /var/log/caddy/forum-stm-support.log
  }
  reverse_proxy {
    #to https://forum-stm-support1.river-valley.com
    to https://forum-stm-support2.river-valley.com
    to https://forum-stm-support3.river-valley.com
    to https://forum-stm-support4.river-valley.com
    to https://forum-stm-support5.river-valley.com
    import lb_settings
  }
}
forum-stm-general.stmdocs.com {
  log {
    output file /var/log/caddy/forum-stm-general.log
  }
  reverse_proxy {
    #to https://forum-stm-general1.river-valley.com
    to https://forum-stm-general2.river-valley.com
    to https://forum-stm-general3.river-valley.com
    to https://forum-stm-general4.river-valley.com
    to https://forum-stm-general5.river-valley.com
    import lb_settings
  }
}
#ithal.io {
#  log {
#    output file /var/log/caddy/tf-ithal.log
#  }
#  reverse_proxy {
#    to https://tf-ithal1.river-valley.com
#    to https://tf-ithal2.river-valley.com
#    to https://tf-ithal3.river-valley.com
#    to https://tf-ithal4.river-valley.com
#    to https://tf-ithal5.river-valley.com
#    import lb_settings
#  }
#}
lp.stmdocs.com {
  log {
    output file /var/log/caddy/lp.log
  }
  reverse_proxy {
    to https://lp1.river-valley.com
    to https://lp2.river-valley.com
    #to https://lp3.river-valley.com
    to https://lp4.river-valley.com
    to https://lp5.river-valley.com
    import lb_settings
  }
}
https://lp.stmdocs.com:1880 {
  log {
    output file /var/log/caddy/lp-1880.log
  }
  reverse_proxy {
    to https://lp1.river-valley.com:1880
    to https://lp2.river-valley.com:1880
    #to https://lp3.river-valley.com:1880
    to https://lp4.river-valley.com:1880
    to https://lp5.river-valley.com:1880
    import lb_settings
  }
}
probraise.stmdocs.com {
  log {
    output file /var/log/caddy/probraise.log
  }
  reverse_proxy {
    to https://probraise1.river-valley.com
    to https://probraise2.river-valley.com
    #to https://probraise3.river-valley.com
    to https://probraise4.river-valley.com
    to https://probraise5.river-valley.com
    import lb_settings
  }
}
https://probraise.stmdocs.com:1880 {
  log {
    output file /var/log/caddy/probraise-1880.log
  }
  reverse_proxy {
    to https://probraise1.river-valley.com:1880
    to https://probraise2.river-valley.com:1880
    #to https://probraise3.river-valley.com:1880
    to https://probraise4.river-valley.com:1880
    to https://probraise5.river-valley.com:1880
    import lb_settings
  }
}
www.river-valley.com,
www.river-valley.org, 
river-valley.org,
river-valley.com {
  log {
    output file /var/log/caddy/rvt.log
  }
  reverse_proxy {
    to https://rvt1.river-valley.com
    to https://rvt2.river-valley.com
    #to https://rvt3.river-valley.com
    to https://rvt4.river-valley.com
    to https://rvt5.river-valley.com
    import lb_settings
  }
}
neptune.texfolio.org {
  log {
    output file /var/log/caddy/neptune.log
  }
  reverse_proxy {
    to https://neptune1.river-valley.com
    to https://neptune2.river-valley.com
    #to https://neptune3.river-valley.com
    to https://neptune4.river-valley.com
    to https://neptune5.river-valley.com
    import lb_settings
  }
}
texfolio.org {
  log {
    output file /var/log/caddy/tf-web.log
  }
  reverse_proxy {
    #to https://tf-web1.river-valley.com
    to https://tf-web2.river-valley.com
    to https://tf-web3.river-valley.com
    to https://tf-web4.river-valley.com
    to https://tf-web5.river-valley.com
    import lb_settings
  }
}
# https://interfaces.stmdocs.com -> https://interfaces{1-5}.river-valley.com
interfaces.stmdocs.com {
  log {
    output file /var/log/caddy/interfaces.log
  }
  reverse_proxy {
    to https://interfaces1.river-valley.com
    to https://interfaces2.river-valley.com
    #to https://interfaces3.river-valley.com
    to https://interfaces4.river-valley.com
    to https://interfaces5.river-valley.com
    import lb_settings
  }
}
# https://interfaces.stmdocs.com:1880 -> https://interfaces{1-5}.river-valley.com:1880
https://interfaces.stmdocs.com:1880 {
  log {
    output file /var/log/caddy/interfaces-1880.log
  }
  reverse_proxy {
    to https://interfaces1.river-valley.com:1880
    to https://interfaces2.river-valley.com:1880
    #to https://interfaces3.river-valley.com:1880
    to https://interfaces4.river-valley.com:1880
    to https://interfaces5.river-valley.com:1880
    import lb_settings
  }
}
# https://api.stmdocs.com -> https://api{1-5}.river-valley.com
api.stmdocs.com {
  log {
    output file /var/log/caddy/api.log
  }
  reverse_proxy {
    to https://api1.river-valley.com
    to https://api2.river-valley.com
    #to https://api3.river-valley.com
    to https://api4.river-valley.com
    to https://api5.river-valley.com
    import lb_settings
  }
}
wiki.stmsoft.in {
  log {
    output file /var/log/caddy/stmsoft-wiki.log
  }
  reverse_proxy {
    #to https://stmsoft-wiki1.river-valley.com
    to https://stmsoft-wiki2.river-valley.com
    to https://stmsoft-wiki3.river-valley.com
    to https://stmsoft-wiki4.river-valley.com
    to https://stmsoft-wiki5.river-valley.com
    import lb_settings
  }
}
oswiki.stmdocs.in {
  log {
    output file /var/log/caddy/oswiki.log
  }
  reverse_proxy {
    to https://oswiki1.river-valley.com
    to https://oswiki2.river-valley.com
    #to https://oswiki3.river-valley.com
    to https://oswiki4.river-valley.com
    to https://oswiki5.river-valley.com
    import lb_settings
  }
}
# end of caddyfile_content do-vps01
12

and truncated default.log:

{
  "level": "debug",
  "ts": 1712319326.68981,
  "logger": "http.handlers.reverse_proxy",
  "msg": "upstream roundtrip",
  "upstream": "kimai1.river-valley.com:443",
  "duration": 0.223135462,
  "request": {
    "remote_ip": "103.162.8.148",
    "remote_port": "45090",
    "proto": "HTTP/2.0",
    "method": "GET",
    "host": "kimai1.river-valley.com:443",
    "uri": "/en/timesheet/?state=1&billable=0&exported=1&pageSize=50&page=1&orderBy=begin&order=DESC&_token=mJABQ9H5e2TBBVBAVO4elmKnAIgj6oECSRns7oSpC7I",
    "headers": {
      "Referer": [
        "https://kimai.stmdocs.com/en/timesheet/"
      ],
      "Accept-Encoding": [
        "gzip, deflate, br"
      ],
      "Accept": [
        "*/*"
      ],
      "Te": [
        "trailers"
      ],
      "Cookie": [],
      "Sec-Fetch-Mode": [
        "cors"
      ],
      "X-Requested-With": [
        "XMLHttpRequest"
      ],
      "Sec-Fetch-Dest": [
        "empty"
      ],
      "X-Forwarded-For": [
        "103.162.8.148"
      ],
      "X-Forwarded-Proto": [
        "https"
      ],
      "Sec-Fetch-Site": [
        "same-origin"
      ],
      "X-Forwarded-Host": [
        "kimai.stmdocs.com"
      ],
      "Accept-Language": [
        "en-US,en;q=0.5"
      ],
      "User-Agent": [
        "Mozilla/5.0 (X11; Linux x86_64; rv:124.0) Gecko/20100101 Firefox/124.0"
      ]
    },
    "tls": {
      "resumed": true,
      "version": 772,
      "cipher_suite": 4865,
      "proto": "h2",
      "server_name": "kimai.stmdocs.com"
    }
  },
  "headers": {
    "Cache-Control": [
      "max-age=0, must-revalidate, private"
    ],
    "Date": [
      "Fri, 05 Apr 2024 12:15:26 GMT"
    ],
    "Expires": [
      "Fri, 05 Apr 2024 12:15:26 GMT"
    ],
    "Vary": [
      "Accept-Encoding"
    ],
    "Alt-Svc": [
      "h3=\":443\"; ma=2592000"
    ],
    "Content-Encoding": [
      "gzip"
    ],
    "Content-Type": [
      "text/html; charset=UTF-8"
    ],
    "Server": [
      "Caddy",
      "Apache"
    ]
  },
  "status": 200
}
{
  "level": "debug",
  "ts": 1712319326.7243018,
  "logger": "http.handlers.reverse_proxy",
  "msg": "selected upstream",
  "dial": "forum-stm-support4.river-valley.com:443",
  "total_upstreams": 4
}
{
  "level": "debug",
  "ts": 1712319326.7298617,
  "logger": "http.handlers.reverse_proxy",
  "msg": "upstream roundtrip",
  "upstream": "kimai4.river-valley.com:443",
  "duration": 0.244263145,
  "request": {
    "remote_ip": "103.162.8.148",
    "remote_port": "45090",
    "proto": "HTTP/2.0",
    "method": "GET",
    "host": "kimai4.river-valley.com:443",
    "uri": "/api/timesheets/active",
    "headers": {
      "X-Requested-With": [
        "XMLHttpRequest"
      ],
      "Accept": [
        "application/json, text/javascript, */*; q=0.01"
      ],
      "X-Forwarded-For": [
        "103.162.8.148"
      ],
      "Referer": [
        "https://kimai.stmdocs.com/en/timesheet/"
      ],
      "Accept-Encoding": [
        "gzip, deflate, br"
      ],
      "User-Agent": [
        "Mozilla/5.0 (X11; Linux x86_64; rv:124.0) Gecko/20100101 Firefox/124.0"
      ],
      "Sec-Fetch-Dest": [
        "empty"
      ],
      "Te": [
        "trailers"
      ],
      "X-Auth-Session": [
        "true"
      ],
      "Cookie": [],
      "Sec-Fetch-Mode": [
        "cors"
      ],
      "Sec-Fetch-Site": [
        "same-origin"
      ],
      "X-Forwarded-Proto": [
        "https"
      ],
      "Content-Type": [
        "application/json"
      ],
      "Accept-Language": [
        "en-US,en;q=0.5"
      ],
      "X-Forwarded-Host": [
        "kimai.stmdocs.com"
      ]
    },
    "tls": {
      "resumed": true,
      "version": 772,
      "cipher_suite": 4865,
      "proto": "h2",
      "server_name": "kimai.stmdocs.com"
    }
  },
  "headers": {
    "Date": [
      "Fri, 05 Apr 2024 12:15:26 GMT"
    ],
    "Expires": [
      "Fri, 05 Apr 2024 12:15:26 GMT"
    ],
    "Server": [
      "Caddy",
      "Apache"
    ],
    "Alt-Svc": [
      "h3=\":443\"; ma=2592000"
    ],
    "Cache-Control": [
      "max-age=0, must-revalidate, private"
    ],
    "Content-Type": [
      "application/json"
    ]
  },
  "status": 200
}
{
  "level": "debug",
  "ts": 1712319326.7609522,
  "logger": "http.handlers.reverse_proxy",
  "msg": "upstream roundtrip",
  "upstream": "forum-stm-support4.river-valley.com:443",
  "duration": 0.036482473,
  "request": {
    "remote_ip": "111.92.47.122",
    "remote_port": "35889",
    "proto": "HTTP/2.0",
    "method": "POST",
    "host": "forum-stm-support4.river-valley.com:443",
    "uri": "/notifications/inform",
    "headers": {
      "Sec-Fetch-Site": [
        "same-origin"
      ],
      "User-Agent": [
        "Mozilla/5.0 (X11; Linux x86_64; rv:95.0) Gecko/20100101 Firefox/95.0"
      ],
      "Sec-Fetch-Mode": [
        "cors"
      ],
      "Sec-Fetch-Dest": [
        "empty"
      ],
      "X-Forwarded-For": [
        "111.92.47.122"
      ],
      "Content-Type": [
        "application/x-www-form-urlencoded; charset=UTF-8"
      ],
      "Origin": [
        "https://forum-stm-support.stmdocs.com"
      ],
      "Referer": [
        "https://forum-stm-support.stmdocs.com/"
      ],
      "Te": [
        "trailers"
      ],
      "Accept-Language": [
        "en-US,en;q=0.5"
      ],
      "Cookie": [],
      "X-Forwarded-Host": [
        "forum-stm-support.stmdocs.com"
      ],
      "Content-Length": [
        "106"
      ],
      "X-Forwarded-Proto": [
        "https"
      ],
      "Accept-Encoding": [
        "gzip, deflate, br"
      ],
      "Accept": [
        "application/json, text/javascript, */*; q=0.01"
      ],
      "X-Requested-With": [
        "XMLHttpRequest"
      ]
    },
    "tls": {
      "resumed": true,
      "version": 772,
      "cipher_suite": 4865,
      "proto": "h2",
      "server_name": "forum-stm-support.stmdocs.com"
    }
  },
  "headers": {
    "Expires": [
      "Sat, 01 Jan 2000 00:00:00 GMT"
    ],
    "Content-Length": [
      "168"
    ],
    "Cache-Control": [
      "private, no-cache, max-age=0, must-revalidate"
    ],
    "Content-Security-Policy": [
      "default-src 'self' 'unsafe-inline' 'unsafe-eval'; font-src *.stmdocs.com *.river-valley.com;img-src *.stmdocs.com *.river-valley.com data:; script-src *.stmdocs.com *.river-valley.com 'unsafe-inline' 'unsafe-eval'; style-src *.stmdocs.com *.river-valley.com 'unsafe-inline' 'unsafe-eval';"
    ],
    "Permissions-Policy": [
      "geolocation=(),midi=(),sync-xhr=(),microphone=(),camera=(),magnetometer=(),gyroscope=(),fullscreen=(self),payment=()"
    ],
    "Pragma": [
      "no-cache"
    ],
    "X-Frame-Options": [
      "SAMEORIGIN"
    ],
    "Alt-Svc": [
      "h3=\":443\"; ma=2592000"
    ],
    "Date": [
      "Fri, 05 Apr 2024 12:15:26 GMT"
    ],
    "P3p": [
      "CP=\"CAO PSA OUR\""
    ],
    "Referrer-Policy": [
      "strict-origin"
    ],
    "Server": [
      "Caddy",
      ""
    ],
    "X-Content-Type-Options": [
      "nosniff",
      "nosniff"
    ],
    "Access-Control-Allow-Origin": [
      "https://forum-stm-support.stmdocs.com"
    ],
    "Strict-Transport-Security": [
      "max-age=31536000; includeSubDomains; preload"
    ],
    "X-Xss-Protection": [
      "1; mode=block"
    ],
    "Content-Type": [
      "application/json; charset=utf-8"
    ]
  },
  "status": 200
}
{
  "level": "debug",
  "ts": 1712319326.8013778,
  "logger": "http.handlers.reverse_proxy",
  "msg": "upstream roundtrip",
  "upstream": "kimai2.river-valley.com:443",
  "duration": 0.31688694,
  "request": {
    "remote_ip": "103.162.8.148",
    "remote_port": "45090",
    "proto": "HTTP/2.0",
    "method": "GET",
    "host": "kimai2.river-valley.com:443",
    "uri": "/api/timesheets/recent?size=10",
    "headers": {
      "X-Forwarded-For": [
        "103.162.8.148"
      ],
      "Sec-Fetch-Mode": [
        "cors"
      ],
      "Cookie": [],
      "Accept-Encoding": [
        "gzip, deflate, br"
      ],
      "User-Agent": [
        "Mozilla/5.0 (X11; Linux x86_64; rv:124.0) Gecko/20100101 Firefox/124.0"
      ],
      "Content-Type": [
        "application/json"
      ],
      "X-Forwarded-Host": [
        "kimai.stmdocs.com"
      ],
      "X-Requested-With": [
        "XMLHttpRequest"
      ],
      "Referer": [
        "https://kimai.stmdocs.com/en/timesheet/"
      ],
      "Accept": [
        "application/json, text/javascript, */*; q=0.01"
      ],
      "X-Auth-Session": [
        "true"
      ],
      "X-Forwarded-Proto": [
        "https"
      ],
      "Accept-Language": [
        "en-US,en;q=0.5"
      ],
      "Sec-Fetch-Dest": [
        "empty"
      ],
      "Sec-Fetch-Site": [
        "same-origin"
      ],
      "Te": [
        "trailers"
      ]
    },
    "tls": {
      "resumed": true,
      "version": 772,
      "cipher_suite": 4865,
      "proto": "h2",
      "server_name": "kimai.stmdocs.com"
    }
  },
  "headers": {
    "Alt-Svc": [
      "h3=\":443\"; ma=2592000"
    ],
    "Cache-Control": [
      "max-age=0, must-revalidate, private"
    ],
    "Content-Type": [
      "application/json"
    ],
    "Date": [
      "Fri, 05 Apr 2024 12:15:26 GMT"
    ],
    "Expires": [
      "Fri, 05 Apr 2024 12:15:26 GMT"
    ],
    "Server": [
      "Caddy",
      "Apache"
    ]
  },
  "status": 200
}
{
  "level": "debug",
  "ts": 1712319327.0362422,
  "logger": "http.handlers.reverse_proxy",
  "msg": "selected upstream",
  "dial": "texfolio2.river-valley.com:443",
  "total_upstreams": 4
}
{
  "level": "debug",
  "ts": 1712319327.0606527,
  "logger": "http.handlers.reverse_proxy",
  "msg": "upstream roundtrip",
  "upstream": "texfolio2.river-valley.com:443",
  "duration": 0.02427474,
  "request": {
    "remote_ip": "106.205.161.7",
    "remote_port": "9243",
    "proto": "HTTP/2.0",
    "method": "GET",
    "host": "texfolio2.river-valley.com:443",
    "uri": "/stf/app/PUSH?v-uiId=0&v-pushId=4295be36-5021-4751-8523-7babd8faf071&X-Atmosphere-tracking-id=e2a7481e-6d8a-408c-8b76-ca4552a9a041&X-Atmosphere-Framework=2.2.13.vaadin5-javascript&X-Atmosphere-Transport=long-polling&X-Atmosphere-TrackMessageSize=true&Content-Type=application%2Fjson%3B%20charset%3DUTF-8&X-atmo-protocol=true&_=1712319326974",
    "headers": {
      "User-Agent": [
        "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36"
      ],
      "Sec-Fetch-Dest": [
        "empty"
      ],
      "X-Forwarded-Proto": [
        "https"
      ],
      "Referer": [
        "https://tf.stmdocs.com/stf/app/"
      ],
      "Content-Type": [
        "application/json; charset=UTF-8"
      ],
      "X-Forwarded-Host": [
        "tf.stmdocs.com"
      ],
      "Accept-Language": [
        "en-US,en;q=0.9"
      ],
      "Sec-Fetch-Site": [
        "same-origin"
      ],
      "Sec-Fetch-Mode": [
        "cors"
      ],
      "Cookie": [],
      "Accept": [
        "*/*"
      ],
      "X-Forwarded-For": [
        "106.205.161.7"
      ],
      "Sec-Ch-Ua-Mobile": [
        "?0"
      ],
      "Accept-Encoding": [
        "gzip, deflate, br"
      ],
      "Sec-Ch-Ua": [
        "\"Chromium\";v=\"117\", \"Not;A=Brand\";v=\"8\""
      ],
      "Sec-Ch-Ua-Platform": [
        "\"Linux\""
      ]
    },
    "tls": {
      "resumed": true,
      "version": 772,
      "cipher_suite": 4865,
      "proto": "h2",
      "server_name": "tf.stmdocs.com"
    }
  },
  "headers": {
    "Alt-Svc": [
      "h3=\":443\"; ma=2592000"
    ],
    "Date": [
      "Fri, 05 Apr 2024 12:15:27 GMT"
    ],
    "Location": [
      "http://tf.stmdocs.com/stf/services/auth/login"
    ],
    "Server": [
      "Caddy"
    ],
    "Content-Length": [
      "0"
    ]
  },
  "status": 302
}
{
  "level": "debug",
  "ts": 1712319327.2417927,
  "logger": "http.handlers.reverse_proxy",
  "msg": "selected upstream",
  "dial": "texfolio4.river-valley.com:443",
  "total_upstreams": 4
}
{
  "level": "debug",
  "ts": 1712319327.2639167,
  "logger": "http.handlers.reverse_proxy",
  "msg": "upstream roundtrip",
  "upstream": "texfolio4.river-valley.com:443",
  "duration": 0.021980814,
  "request": {
    "remote_ip": "117.208.28.175",
    "remote_port": "38512",
    "proto": "HTTP/2.0",
    "method": "GET",
    "host": "texfolio4.river-valley.com:443",
    "uri": "/stf/app/PUSH?v-uiId=0&v-pushId=84947527-f3b8-4421-b44d-f483b0e8eabb&X-Atmosphere-tracking-id=72b6badd-b66d-424a-9760-f8bd8c7e8445&X-Atmosphere-Framework=2.2.13.vaadin5-javascript&X-Atmosphere-Transport=long-polling&X-Atmosphere-TrackMessageSize=true&Content-Type=application%2Fjson%3B%20charset%3DUTF-8&X-atmo-protocol=true&_=1712319327234",
    "headers": {
      "Sec-Ch-Ua-Platform": [
        "\"Linux\""
      ],
      "X-Forwarded-Host": [
        "tf.stmdocs.com"
      ],
      "Accept-Language": [
        "en-US,en;q=0.9"
      ],
      "X-Forwarded-Proto": [
        "https"
      ],
      "Cookie": [],
      "Sec-Ch-Ua-Mobile": [
        "?0"
      ],
      "Sec-Ch-Ua": [
        "\"Chromium\";v=\"107\", \"Not=A?Brand\";v=\"24\""
      ],
      "Sec-Fetch-Site": [
        "same-origin"
      ],
      "User-Agent": [
        "Mozilla/5.0 (X11; Fedora; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/107.0.0.0 Safari/537.36"
      ],
      "Accept-Encoding": [
        "gzip, deflate, br"
      ],
      "Sec-Fetch-Dest": [
        "empty"
      ],
      "Referer": [
        "https://tf.stmdocs.com/stf/app/"
      ],
      "Content-Type": [
        "application/json; charset=UTF-8"
      ],
      "Accept": [
        "*/*"
      ],
      "X-Forwarded-For": [
        "117.208.28.175"
      ],
      "Sec-Fetch-Mode": [
        "cors"
      ]
    },
    "tls": {
      "resumed": true,
      "version": 772,
      "cipher_suite": 4865,
      "proto": "h2",
      "server_name": "tf.stmdocs.com"
    }
  },
  "headers": {
    "Server": [
      "Caddy"
    ],
    "X-Atmosphere-Tracking-Id": [
      "72b6badd-b66d-424a-9760-f8bd8c7e8445"
    ],
    "Alt-Svc": [
      "h3=\":443\"; ma=2592000"
    ],
    "Cache-Control": [
      "no-store, no-cache, must-revalidate"
    ],
    "Content-Type": [
      "text/plain;charset=UTF-8"
    ],
    "Date": [
      "Fri, 05 Apr 2024 12:15:27 GMT"
    ],
    "Expires": [
      "-1"
    ],
    "Pragma": [
      "no-cache"
    ]
  },
  "status": 200
}
{
  "level": "debug",
  "ts": 1712319327.3009875,
  "logger": "http.handlers.reverse_proxy",
  "msg": "selected upstream",
  "dial": "texfolio5.river-valley.com:443",
  "total_upstreams": 4
}
{
  "level": "debug",
  "ts": 1712319327.3240402,
  "logger": "http.handlers.reverse_proxy",
  "msg": "upstream roundtrip",
  "upstream": "texfolio5.river-valley.com:443",
  "duration": 0.021974519,
  "request": {
    "remote_ip": "117.208.28.175",
    "remote_port": "38512",
    "proto": "HTTP/2.0",
    "method": "GET",
    "host": "texfolio5.river-valley.com:443",
    "uri": "/stf/app/PUSH?v-uiId=0&v-pushId=84947527-f3b8-4421-b44d-f483b0e8eabb&X-Atmosphere-tracking-id=72b6badd-b66d-424a-9760-f8bd8c7e8445&X-Atmosphere-Framework=2.2.13.vaadin5-javascript&X-Atmosphere-Transport=long-polling&X-Atmosphere-TrackMessageSize=true&Content-Type=application%2Fjson%3B%20charset%3DUTF-8&X-atmo-protocol=true&_=1712319327292",
    "headers": {
      "Sec-Fetch-Dest": [
        "empty"
      ],
      "Sec-Fetch-Site": [
        "same-origin"
      ],
      "X-Forwarded-Proto": [
        "https"
      ],
      "Sec-Ch-Ua": [
        "\"Chromium\";v=\"107\", \"Not=A?Brand\";v=\"24\""
      ],
      "Sec-Fetch-Mode": [
        "cors"
      ],
      "Cookie": [],
      "Accept": [
        "*/*"
      ],
      "Content-Type": [
        "application/json; charset=UTF-8"
      ],
      "Referer": [
        "https://tf.stmdocs.com/stf/app/"
      ],
      "Accept-Language": [
        "en-US,en;q=0.9"
      ],
      "X-Forwarded-For": [
        "117.208.28.175"
      ],
      "Accept-Encoding": [
        "gzip, deflate, br"
      ],
      "Sec-Ch-Ua-Platform": [
        "\"Linux\""
      ],
      "User-Agent": [
        "Mozilla/5.0 (X11; Fedora; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/107.0.0.0 Safari/537.36"
      ],
      "X-Forwarded-Host": [
        "tf.stmdocs.com"
      ],
      "Sec-Ch-Ua-Mobile": [
        "?0"
      ]
    },
    "tls": {
      "resumed": true,
      "version": 772,
      "cipher_suite": 4865,
      "proto": "h2",
      "server_name": "tf.stmdocs.com"
    }
  },
  "headers": {
    "X-Atmosphere-Tracking-Id": [
      "72b6badd-b66d-424a-9760-f8bd8c7e8445"
    ],
    "Alt-Svc": [
      "h3=\":443\"; ma=2592000"
    ],
    "Cache-Control": [
      "no-store, no-cache, must-revalidate"
    ],
    "Content-Type": [
      "text/plain;charset=UTF-8"
    ],
    "Date": [
      "Fri, 05 Apr 2024 12:15:27 GMT"
    ],
    "Expires": [
      "-1"
    ],
    "Pragma": [
      "no-cache"
    ],
    "Server": [
      "Caddy"
    ]
  },
  "status": 200
}
{
  "level": "debug",
  "ts": 1712319327.7882109,
  "logger": "events",
  "msg": "event",
  "name": "tls_get_certificate",
  "id": "179709b5-4b04-48a6-8c20-e4a4ea2dfca8",
  "origin": "tls",
  "data": {
    "client_hello": {
      "CipherSuites": [
        4865,
        4867,
        4866,
        49195,
        49199,
        52393,
        52392,
        49196,
        49200,
        49162,
        49161,
        49171,
        49172,
        156,
        157,
        47,
        53
      ],
      "ServerName": "swf.stmdocs.com",
      "SupportedCurves": [
        29,
        23,
        24,
        25,
        256,
        257
      ],
      "SupportedPoints": "AA==",
      "SignatureSchemes": [
        1027,
        1283,
        1539,
        2052,
        2053,
        2054,
        1025,
        1281,
        1537,
        515,
        513
      ],
      "SupportedProtos": [
        "h2",
        "http/1.1"
      ],
      "SupportedVersions": [
        772,
        771
      ],
      "Conn": {}
    }
  }
}
{
  "level": "debug",
  "ts": 1712319327.7883153,
  "logger": "tls.handshake",
  "msg": "choosing certificate",
  "identifier": "swf.stmdocs.com",
  "num_choices": 1
}
{
  "level": "debug",
  "ts": 1712319327.7883675,
  "logger": "tls.handshake",
  "msg": "default certificate selection results",
  "identifier": "swf.stmdocs.com",
  "subjects": [
    "swf.stmdocs.com"
  ],
  "managed": true,
  "issuer_key": "acme-v02.api.letsencrypt.org-directory",
  "hash": "327ff8ab5ea8ec3368731a7dd8315bb04f22892467e15cfaa5ceb6abd3efef24"
}
{
  "level": "debug",
  "ts": 1712319327.7883794,
  "logger": "tls.handshake",
  "msg": "matched certificate in cache",
  "remote_ip": "49.37.233.160",
  "remote_port": "58314",
  "subjects": [
    "swf.stmdocs.com"
  ],
  "managed": true,
  "expiration": 1717324262,
  "hash": "327ff8ab5ea8ec3368731a7dd8315bb04f22892467e15cfaa5ceb6abd3efef24"
}
{
  "level": "debug",
  "ts": 1712319328.199858,
  "logger": "http.handlers.reverse_proxy",
  "msg": "selected upstream",
  "dial": "texfolio2.river-valley.com:443",
  "total_upstreams": 4
}
{
  "level": "debug",
  "ts": 1712319328.2244802,
  "logger": "http.handlers.reverse_proxy",
  "msg": "upstream roundtrip",
  "upstream": "texfolio2.river-valley.com:443",
  "duration": 0.024479023,
  "request": {
    "remote_ip": "117.208.28.175",
    "remote_port": "38512",
    "proto": "HTTP/2.0",
    "method": "GET",
    "host": "texfolio2.river-valley.com:443",
    "uri": "/stf/app/PUSH?v-uiId=0&v-pushId=84947527-f3b8-4421-b44d-f483b0e8eabb&X-Atmosphere-tracking-id=72b6badd-b66d-424a-9760-f8bd8c7e8445&X-Atmosphere-Framework=2.2.13.vaadin5-javascript&X-Atmosphere-Transport=long-polling&X-Atmosphere-TrackMessageSize=true&Content-Type=application%2Fjson%3B%20charset%3DUTF-8&X-atmo-protocol=true&_=1712319328190",
    "headers": {
      "Accept-Language": [
        "en-US,en;q=0.9"
      ],
      "X-Forwarded-Host": [
        "tf.stmdocs.com"
      ],
      "Sec-Ch-Ua-Mobile": [
        "?0"
      ],
      "Referer": [
        "https://tf.stmdocs.com/stf/app/"
      ],
      "X-Forwarded-For": [
        "117.208.28.175"
      ],
      "Sec-Fetch-Site": [
        "same-origin"
      ],
      "Sec-Ch-Ua-Platform": [
        "\"Linux\""
      ],
      "X-Forwarded-Proto": [
        "https"
      ],
      "Cookie": [],
      "Sec-Fetch-Dest": [
        "empty"
      ],
      "User-Agent": [
        "Mozilla/5.0 (X11; Fedora; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/107.0.0.0 Safari/537.36"
      ],
      "Accept": [
        "*/*"
      ],
      "Content-Type": [
        "application/json; charset=UTF-8"
      ],
      "Accept-Encoding": [
        "gzip, deflate, br"
      ],
      "Sec-Fetch-Mode": [
        "cors"
      ],
      "Sec-Ch-Ua": [
        "\"Chromium\";v=\"107\", \"Not=A?Brand\";v=\"24\""
      ]
    },
    "tls": {
      "resumed": true,
      "version": 772,
      "cipher_suite": 4865,
      "proto": "h2",
      "server_name": "tf.stmdocs.com"
    }
  },
  "headers": {
    "Content-Type": [
      "text/plain;charset=UTF-8"
    ],
    "Date": [
      "Fri, 05 Apr 2024 12:15:28 GMT"
    ],
    "Expires": [
      "-1"
    ],
    "Pragma": [
      "no-cache"
    ],
    "Server": [
      "Caddy"
    ],
    "X-Atmosphere-Tracking-Id": [
      "72b6badd-b66d-424a-9760-f8bd8c7e8445"
    ],
    "Alt-Svc": [
      "h3=\":443\"; ma=2592000"
    ],
    "Cache-Control": [
      "no-store, no-cache, must-revalidate"
    ]
  },
  "status": 200
}
{
  "level": "debug",
  "ts": 1712319328.2666397,
  "logger": "http.handlers.reverse_proxy",
  "msg": "selected upstream",
  "dial": "kimai1.river-valley.com:443",
  "total_upstreams": 4
}
{
  "level": "debug",
  "ts": 1712319328.5341036,
  "logger": "http.handlers.reverse_proxy",
  "msg": "upstream roundtrip",
  "upstream": "kimai1.river-valley.com:443",
  "duration": 0.267285443,
  "request": {
    "remote_ip": "49.37.227.48",
    "remote_port": "43370",
    "proto": "HTTP/2.0",
    "method": "GET",
    "host": "kimai1.river-valley.com:443",
    "uri": "/en/timesheet/",
    "headers": {
      "Upgrade-Insecure-Requests": [
        "1"
      ],
      "User-Agent": [
        "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36"
      ],
      "X-Forwarded-Host": [
        "kimai.stmdocs.com"
      ],
      "Sec-Ch-Ua": [
        "\"Not.A/Brand\";v=\"8\", \"Chromium\";v=\"114\", \"Google Chrome\";v=\"114\""
      ],
      "Sec-Fetch-Site": [
        "same-origin"
      ],
      "Accept-Encoding": [
        "gzip, deflate, br"
      ],
      "Accept-Language": [
        "en-GB,en-US;q=0.9,en;q=0.8"
      ],
      "Sec-Fetch-Dest": [
        "document"
      ],
      "X-Forwarded-Proto": [
        "https"
      ],
      "Sec-Ch-Ua-Mobile": [
        "?0"
      ],
      "X-Forwarded-For": [
        "49.37.227.48"
      ],
      "Sec-Fetch-Mode": [
        "navigate"
      ],
      "Sec-Fetch-User": [
        "?1"
      ],
      "Cookie": [],
      "Cache-Control": [
        "max-age=0"
      ],
      "Sec-Ch-Ua-Platform": [
        "\"Linux\""
      ],
      "Accept": [
        "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7"
      ]
    },
    "tls": {
      "resumed": true,
      "version": 772,
      "cipher_suite": 4865,
      "proto": "h2",
      "server_name": "kimai.stmdocs.com"
    }
  },
  "headers": {
    "Content-Type": [
      "text/html; charset=UTF-8"
    ],
    "Cache-Control": [
      "max-age=0, must-revalidate, private"
    ],
    "Content-Encoding": [
      "gzip"
    ],
    "Date": [
      "Fri, 05 Apr 2024 12:15:28 GMT"
    ],
    "Expires": [
      "Fri, 05 Apr 2024 12:15:28 GMT"
    ],
    "Server": [
      "Caddy",
      "Apache"
    ],
    "Vary": [
      "Accept-Encoding"
    ],
    "Alt-Svc": [
      "h3=\":443\"; ma=2592000"
    ]
  },
  "status": 200
}
{
  "level": "error",
  "ts": 1712319328.7567308,
  "logger": "http.log.error.log7",
  "msg": "no upstreams available",
  "request": {
    "remote_ip": "117.253.115.200",
    "remote_port": "53486",
    "proto": "HTTP/2.0",
    "method": "GET",
    "host": "swf.stmdocs.com",
    "uri": "/split_workflow_opecon.php",
    "headers": {
      "Accept-Language": [
        "en-US,en;q=0.5"
      ],
      "Accept-Encoding": [
        "gzip, deflate, br"
      ],
      "Referer": [
        "https://swf.stmdocs.com/"
      ],
      "Cookie": [],
      "Sec-Fetch-Dest": [
        "document"
      ],
      "Sec-Fetch-Mode": [
        "navigate"
      ],
      "User-Agent": [
        "Mozilla/5.0 (X11; Linux x86_64; rv:124.0) Gecko/20100101 Firefox/124.0"
      ],
      "Accept": [
        "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8"
      ],
      "Upgrade-Insecure-Requests": [
        "1"
      ],
      "Sec-Fetch-Site": [
        "same-origin"
      ],
      "Sec-Fetch-User": [
        "?1"
      ],
      "Te": [
        "trailers"
      ]
    },
    "tls": {
      "resumed": false,
      "version": 772,
      "cipher_suite": 4865,
      "proto": "h2",
      "server_name": "swf.stmdocs.com"
    }
  },
  "duration": 0.000102731,
  "status": 503,
  "err_id": "hrp54tyvd",
  "err_trace": "reverseproxy.(*Handler).proxyLoopIteration (reverseproxy.go:547)"
}
{
  "level": "debug",
  "ts": 1712319329.3107715,
  "logger": "http.handlers.reverse_proxy",
  "msg": "selected upstream",
  "dial": "texfolio4.river-valley.com:443",
  "total_upstreams": 4
}
13

The only log with no upstreams available is from that host. What are your

In your Caddyfile, you have Caddy listening on port 1880. Is that a mistake? Did you mean to listen on port 443 instead?

14

I did a search over all log files, the problem happens with other domains as well, not just with swf.stmdocs.com

port 1880 is not a mistake. The upstream listens at both port 443 and 1880

If I remove active health checks, can it have a positive effect?

15

Sorry I never finished that sentence :man_facepalming:

I meant to say, are you sure all of these upstreams are actually accessible?

Health checks are be the reason that upstreams get marked as unhealthy. If health checks are failing for that one upstream, then it makes sense that it would report there being no upstreams available.

Like I said before, fail_duration 5m is a very long time. If a single error happens at all, then the upstream is taken out for a whole 5 minutes before trying again.

1 Like
16

yes the upstreams are available most of the time. The problem seems to happen when 1 upstream is not available for a while, though I cannot reproduce this consistently.

I will reduce fail_duration and disable active health check to see it makes any difference.