Load API endpoint sometimes times out

Jeff_Galbraith · September 1, 2020, 3:37pm

I am using the API end-point to dynamically set reverse proxies. Usually this is instant. Sometimes, it appears to timeout, which takes a while, yet it still works.

Looking through the journal, I came across this:

Sep 01 09:17:09 FLEX-5 caddy[31121]: {“level”:“error”,“ts”:1598973429.5918858,“logger”:“admin”,“msg”:“stopping current admin endpoint”,“error”:“shutting down admin server: context deadline exceeded”}

I did find this to help me understand what is basically happening: go - Context timeout implementation on every request using golang - Stack Overflow

When I use curl in a terminal, this never happens, but when I use axios (with JavaScript) it occasionally happens.

I am wondering if I need something in the axios headers that curl is using, but I am not, or if this is a bug in Caddy Server?

This is the code I use to update the config:

    axios({
      method: 'post',
      url: 'http://localhost:2019/load',
      headers: {
        'Content-Type': 'application/json'
      },
      data: config
    })

Any suggestions welcomed. Thanks.

matt · September 1, 2020, 10:57pm

Interesting; I don’t know what axios is really (or how it works, especially), but this usually happens if there’s a request or connection that is still active. Is axios shutting down the connection after the request?

francislavoie · September 1, 2020, 11:27pm

It’s just a JavaScript library that wraps the XMLHttpRequest browser APIs to make them easier to use.

@Jeff_Galbraith does it happen with the fetch API too? Just to narrow down if it’s something weird that axios is doing or whether it’s anything from a browser.

Jeff_Galbraith · September 11, 2020, 2:57pm

@francislavoie I will look into it next week. I’ll have to use node-fetch package since the fetch API is not built into node.

francislavoie · September 11, 2020, 3:25pm

Ah, didn’t realize you’re using node, I assumed this was frontend JS.

Jeff_Galbraith · September 21, 2020, 4:43pm

@francislavoie Finally got some time to swap out axios with node-fetch and seeing the same results.

This gets written to the journal, but it never comes back (sometimes):
Sep 21 10:08:51 FLEX-5 caddy[14345]: {“level”:“info”,“ts”:1600704531.5086918,“logger”:“admin.api”,“msg”:“received request”,“method”:“POST”,“host”:“localhost:2019”,“uri”:"/load",“remote_addr”:“127.0.0.1:36916”,“headers”:{“Accept”:["/"],“Accept-Encoding”:[“gzip,deflate”],“Connection”:[“close”],“Content-Length”:[“4151”],“Content-Type”:[“application/json”],“User-Agent”:[“node-fetch/1.0 (+https://github.com/bitinn/node-fetch)”]}}

This is what I do…when my service starts up, it doesn’t assume that the caddy json configuration is correct. It rebuilds it, then sends it off to Caddy, which always returns immediately. Then, if the User via a web browser, makes changes, then the same process is done again, with the additional data. It is sent off to Caddy at the load end-point. Then, this is where it gets “stuck”. Again, not always.

When it does get “stuck” everything returns to normal after “socket hung up” error.

I have no ideas what may be the problem.

Jeff_Galbraith · September 21, 2020, 5:07pm

I just tried with latest and same thing:
v2.2.0-rc.3 h1:sCf7QCxI8l2/tvH2sJFtOC7cBAOWtB5w6XQPMPIWqqU=

Jeff_Galbraith · September 21, 2020, 5:12pm

I am seeing this in the journal now:

Jeff_Galbraith · September 21, 2020, 5:14pm

my json (unformatted as it’s too big for a message):

$ curl localhost:2019/config/
{“apps”:{“http”:{“servers”:{“srv0”:{“automatic_https”:{“disable”:true},“listen”:[":80"],“routes”:[{“group”:“group1”,“handle”:[{“handler”:“vars”,“root”:"/opt/ivt/photography"}],“match”:[{“path”:["/files/"]}]},{“group”:“group1”,“handle”:[{“handler”:“vars”,“root”:"/opt/ivt/apps/6.0.0/packages/client/spa"}]},{“handle”:[{“handler”:“subroute”,“routes”:[{“handle”:[{“handler”:“rewrite”,“uri_substring”:[{“find”:"/console_socket",“replace”:"/console/socket.io"}]}]},{“handle”:[{“handler”:“reverse_proxy”,“headers”:{“request”:{“set”:{“X-Forwarded-Proto”:["{http.request.scheme}"],“X-Real-Ip”:["{http.request.remote.host}"]}}},“upstreams”:[{“dial”:“localhost:3001”}]}]}]}],“match”:[{“path”:["/console_socket/"]}]},{“handle”:[{“handler”:“subroute”,“routes”:[{“handle”:[{“handler”:“rewrite”,“uri_substring”:[{“find”:"/web_app_socket",“replace”:"/web/socket.io"}]}]},{“handle”:[{“handler”:“reverse_proxy”,“headers”:{“request”:{“set”:{“X-Forwarded-Proto”:["{http.request.scheme}"],“X-Real-Ip”:["{http.request.remote.host}"]}}},“upstreams”:[{“dial”:“localhost:3001”}]}]}]}],“match”:[{“path”:["/web_app_socket/"]}]},{“handle”:[{“handler”:“subroute”,“routes”:[{“handle”:[{“handler”:“rewrite”,“uri_substring”:[{“find”:"/liveview",“replace”:"/socket.io"}]}]},{“handle”:[{“handler”:“reverse_proxy”,“headers”:{“request”:{“set”:{“X-Forwarded-Proto”:["{http.request.scheme}"],“X-Real-Ip”:["{http.request.remote.host}"]}}},“upstreams”:[{“dial”:“localhost:3004”}]}]}]}],“match”:[{“path”:["/liveview/"]}]},{“handle”:[{“handler”:“subroute”,“routes”:[{“handle”:[{“handler”:“rewrite”,“uri_substring”:[{“find”:"/weather",“replace”:"/socket.io"}]}]},{“handle”:[{“handler”:“reverse_proxy”,“headers”:{“request”:{“set”:{“X-Forwarded-Proto”:["{http.request.scheme}"],“X-Real-Ip”:["{http.request.remote.host}"]}}},“upstreams”:[{“dial”:“localhost:3010”}]}]}]}],“match”:[{“path”:["/weather/"]}]},{“handle”:[{“handler”:“subroute”,“routes”:[{“handle”:[{“handler”:“rewrite”,“uri_substring”:[{“find”:"/archive",“replace”:"/socket.io"}]}]},{“handle”:[{“handler”:“reverse_proxy”,“headers”:{“request”:{“set”:{“X-Forwarded-Proto”:["{http.request.scheme}"],“X-Real-Ip”:["{http.request.remote.host}"]}}},“upstreams”:[{“dial”:“localhost:3003”}]}]}]}],“match”:[{“path”:["/archive/"]}]},{“handle”:[{“handler”:“subroute”,“routes”:[{“handle”:[{“handler”:“rewrite”,“uri_substring”:[{“find”:"/alarms",“replace”:"/socket.io"}]}]},{“handle”:[{“handler”:“reverse_proxy”,“headers”:{“request”:{“set”:{“X-Forwarded-Proto”:["{http.request.scheme}"],“X-Real-Ip”:["{http.request.remote.host}"]}}},“upstreams”:[{“dial”:“localhost:3002”}]}]}]}],“match”:[{“path”:["/alarms/"]}]},{“handle”:[{“handler”:“subroute”,“routes”:[{“handle”:[{“handler”:“rewrite”,“uri_substring”:[{“find”:"/ptz",“replace”:"/socket.io"}]}]},{“handle”:[{“handler”:“reverse_proxy”,“headers”:{“request”:{“set”:{“X-Forwarded-Proto”:["{http.request.scheme}"],“X-Real-Ip”:["{http.request.remote.host}"]}}},“upstreams”:[{“dial”:“localhost:3006”}]}]}]}],“match”:[{“path”:["/ptz/"]}]},{“handle”:[{“handler”:“subroute”,“routes”:[{“handle”:[{“handler”:“reverse_proxy”,“headers”:{“request”:{“set”:{“X-Forwarded-Proto”:["{http.request.scheme}"],“X-Real-Ip”:["{http.request.remote.host}"]}}},“upstreams”:[{“dial”:“localhost:3001”}]}]}]}],“match”:[{“path”:["/*"]}]},{“handle”:[{“handler”:“file_server”,“hide”:[“Caddyfile”]}]}]}}},“tls”:{“automation”:{“policies”:[{“issuer”:{“module”:“internal”}}]}}},“logging”:{“logs”:{“default”:{“level”:“DEBUG”}}}}

Jeff_Galbraith · September 21, 2020, 5:28pm

Turns out the “panic” message is caused by our netgear router:

Sep 21 11:26:25 FLEX-5 caddy[13872]: {“level”:“debug”,“ts”:1600709185.44511,“logger”:“http.handlers.reverse_proxy”,“msg”:“upstream roundtrip”,“upstream”:“localhost:3001”,“request”:{“remote_addr”:“192.168.0.16:52283”,“proto”:“HTTP/1.1”,“method”:“GET”,“host”:“192.168.0.14”,“uri”:"/currentsetting.htm",“headers”:{“X-Real-Ip”:[“192.168.0.16”],“X-Forwarded-For”:[“192.168.0.16”],“X-Forwarded-Proto”:[“http”],“User-Agent”:[“Genie Windows 2.4.62”]}},“duration”:102.848549157,“error”:“context canceled”}

https://www.google.com/search?q=currentsetting.htm&oq=currentsetting.htm&aqs=chrome..69i57j0l2.684j0j7&sourceid=chrome&ie=UTF-8

Jeff_Galbraith · September 21, 2020, 5:41pm

Also found this in the journal:

Sep 21 11:39:17 FLEX-5 caddy[20528]: {“level”:“error”,“ts”:1600709957.6683054,“logger”:“admin”,“msg”:“stopping current admin endpoint”,“error”:“shutting down admin server: context deadline exceeded”}

francislavoie · September 21, 2020, 5:49pm

Wrap your JSON in ``` backticks to use code styling. Easier to read.

matt · September 21, 2020, 6:08pm

The “unexpected label cardinality” is being fixed in a branch currently; it’s unrelated.

So where do we stand on the original problem at this point? I’m a little lost with all the replies.

Jeff_Galbraith · September 21, 2020, 8:00pm

Normally I would wrap, but it makes it a single line that, imo, is harder to read

Jeff_Galbraith · September 21, 2020, 8:02pm

Sorry for all the replies. I have not cracked the issue yet. Sometimes, the call is made to Caddy web server on the load end-point and it’s fine and other times, it is not and gets “stuck” (never returns until “socket hang up” is issued).

I do see in the journal, the call into Caddy is written, so I know it got the data. It just doesn’t appear to send the response back all the time.

Jeff_Galbraith · September 30, 2020, 7:09pm

@francislavoie @matt
Look at the last line. Caddy is doing the “socket hang up”. Just got to figure out why:

Sep 30 13:06:14 FLEX-5 caddy[970]: {"level":"info","ts":1601492774.9637244,"logger":"admin.api","msg":"received request","method":"POST","host":"localhost:2019","uri":"/load","remote_addr":"127.0.0.1:50194","headers":{"Accept":["application/json, text/plain, */*"],"Connection":["close"],"Content-Length":["5048"],"Content-Type":["application/json"],"User-Agent":["axios/0.20.0"]}}
Sep 30 13:06:14 FLEX-5 caddy[970]: {"level":"info","ts":1601492774.965148,"logger":"admin","msg":"admin endpoint started","address":"tcp/localhost:2019","enforce_origin":false,"origins":["localhost:2019","[::1]:2019","127.0.0.1:2019"]}
Sep 30 13:06:14 FLEX-5 caddy[970]: {"level":"info","ts":1601492774.9654818,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc00015cbd0"}
Sep 30 13:06:14 FLEX-5 caddy[970]: {"level":"debug","ts":1601492774.9671028,"logger":"http","msg":"starting server loop","address":"[::]:80","http3":false,"tls":false}
Sep 30 13:06:14 FLEX-5 caddy[970]: {"level":"warn","ts":1601492774.9673817,"logger":"pki.ca.local","msg":"installing root certificate (you might be prompted for password)","path":"storage:pki/authorities/local/root.crt"}
Sep 30 13:06:14 FLEX-5 caddy[970]: 2020/09/30 13:06:14 not NSS security databases found
Sep 30 13:06:14 FLEX-5 caddy[970]: 2020/09/30 13:06:14 define JAVA_HOME environment variable to use the Java trust
Sep 30 13:06:14 FLEX-5 sudo[5743]: pam_unix(sudo:auth): conversation failed
Sep 30 13:06:14 FLEX-5 sudo[5743]: pam_unix(sudo:auth): auth could not identify password for [caddy]
Sep 30 13:06:14 FLEX-5 caddy[970]: {"level":"error","ts":1601492774.9719055,"logger":"pki.ca.local","msg":"failed to install root certificate","error":"failed to execute sudo: exit status 1","certificate_file":"storage:pki/authorities/local/root.crt"}
Sep 30 13:06:24 FLEX-5 caddy[970]: {"level":"error","ts":1601492784.9656317,"logger":"admin","msg":"stopping current admin endpoint","error":"shutting down admin server: context deadline exceeded"}

Any suggestions that could help?

system · December 29, 2020, 7:09pm

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