Context canceled while creating new records when triggered by /load

[otaconix]

I'm not exactly sure what's going on, but I'm running into an issue. First, a few facts:

• caddy version: v2.7.4 h1:J8nisjdOxnYHXlorUKXY75Gr6iBfudfoGhrJ8t7/flI=

• caddy list-modules --versions:

  [snip]
  Standard modules: 106
  
  dns.providers.hetzner v0.0.1
  dynamic_dns v0.0.0-20230908132045-920daa5a969f
  dynamic_dns.ip_sources.interface v0.0.0-20230908132045-920daa5a969f
  dynamic_dns.ip_sources.simple_http v0.0.0-20230908132045-920daa5a969f
  dynamic_dns.ip_sources.upnp v0.0.0-20230908132045-920daa5a969f
  
  Non-standard modules: 5
  
  Unknown modules: 0

I'm using caddy-docker-proxy, and everytime I add a new host to dynamicdns' config, caddy-docker-proxy calls the caddy API to load the new Caddyfile, which in turn triggers dynamicdns, and I end up with this in my logs:

{"level":"info","ts":1695234347.7528663,"logger":"docker-proxy","msg":"New Caddyfile","caddyfile":"redacted"}
{"level":"warn","ts":1695234347.7623093,"logger":"docker-proxy","msg":"Caddyfile to json warning","warn":"[Caddyfile:5: Caddyfile input is not formatted; run 'caddy fmt --overwrite' to fix inconsistencies]"}
{"level":"info","ts":1695234347.762509,"logger":"docker-proxy","msg":"Sending configuration to","server":"localhost"}
{"level":"info","ts":1695234347.7636597,"logger":"admin.api","msg":"received request","method":"POST","host":"localhost:2019","uri":"/load","remote_ip":"127.0.0.1","remote_port":"45390","headers":{"Accept-Encoding":["gzip"],"Content-Length":["24508"],"Content-Type":["application/json"],"User-Agent":["Go-http-client/1.1"]}}
{"level":"info","ts":1695234347.7665772,"logger":"admin","msg":"admin endpoint started","address":"localhost:2019","enforce_origin":false,"origins":["//localhost:2019","//[::1]:2019","//127.0.0.1:2019"]}
{"level":"info","ts":1695234347.767036,"logger":"http.auto_https","msg":"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}
{"level":"info","ts":1695234347.767064,"logger":"http.auto_https","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"}
{"level":"info","ts":1695234347.7729192,"logger":"http","msg":"enabling HTTP/3 listener","addr":":443"}
{"level":"info","ts":1695234347.7729392,"logger":"http.log","msg":"server running","name":"srv0","protocols":["h1","h2","h3"]}
{"level":"info","ts":1695234347.7729702,"logger":"http.log","msg":"server running","name":"remaining_auto_https_redirects","protocols":["h1","h2","h3"]}
{"level":"info","ts":1695234347.7729752,"logger":"http","msg":"enabling automatic TLS certificate management","domains":["redacted"]}
{"level":"info","ts":1695234347.7729893,"logger":"http","msg":"servers shutting down with eternal grace period"}
{"level":"info","ts":1695234347.7730908,"logger":"dynamic_dns","msg":"updating DNS record","zone":"redacted","type":"A","name":"redacted","value":"redacted","ttl":300}
{"level":"error","ts":1695234347.773107,"logger":"dynamic_dns","msg":"failed setting DNS record(s) with new IP address(es)","zone":"redacted","error":"Get \"https://dns.hetzner.com/api/v1/zones?name=redacted\": context canceled"}
{"level":"info","ts":1695234347.7731194,"logger":"dynamic_dns","msg":"finished updating DNS","current_ips":["redacted"]}
{"level":"info","ts":1695234347.7742302,"msg":"autosaved config (load with --resume flag)","file":"/config/caddy/autosave.json"}
{"level":"info","ts":1695234347.7742527,"logger":"admin.api","msg":"load complete"}
{"level":"info","ts":1695234347.7743573,"logger":"docker-proxy","msg":"Successfully configured","server":"localhost"}
{"level":"info","ts":1695234347.783447,"logger":"admin","msg":"stopped previous server","address":"localhost:2019"}

Could it be that dynamicdns runs within the context of the server that is being shutdown or something like that?

[mholt]

Context is canceled when it is no longer relevant, so for example, that config is being unloaded. (Multiple config changes in rapid succession could cause that, for instance.)

Is a problem actually manifesting or you're just asking about that log?

[otaconix]

Context is canceled when it is no longer relevant, so for example, that config is being unloaded. (Multiple config changes in rapid succession could cause that, for instance.)

Is a problem actually manifesting or you're just asking about that log?

I had a problem that I can't seem to reproduce anymore: somehow dynamicdns would fail to create a record altogether, and I couldn't get it to do it by recreating the containers (thus triggering docker-proxy). The only way to get the record created was to restart caddy itself.

The workaround (restarting caddy) and the logging led me to believe that the cancellation of that context was somehow the culprit.

But I'm having trouble reproducing the issue right now, so I'll close this for now. Thanks for having a look, and my apologies for the late response.

[mholt]

Hmm, gotcha. Thanks for the update. Let me know if you can pin it down a little more and I'll be happy to take a look!