1. The problem I’m having:
I am trying to use logging in ServeHTTP (and sub functions from there).
2. Error messages and/or full log output:
I get log information up to the ServeHTTP, but not inside it. I suspect this is because my global variable is not set when accessing ServeHTTP.
2024/05/05 14:40:45 [INFO] Build environment ready
2024/05/05 14:40:45 [INFO] Building Caddy
2024/05/05 14:40:45 [INFO] exec (timeout=0s): /Users/daaronch/.asdf/shims/go mod tidy -e
2024/05/05 14:40:46 [INFO] exec (timeout=0s): /Users/daaronch/.asdf/shims/go build -o /Users/daaronch/code/spartacus/caddy -tags nobadger
2024/05/05 14:40:49 [INFO] Build complete: ./caddy
2024/05/05 14:40:49 [INFO] Cleaning up temporary folder: /Users/daaronch/code/spartacus/buildenv_2024-05-05-1440.3841892330
2024/05/05 14:40:49 [INFO] Running [./caddy run --config caddy.json]
2024/05/05 21:40:50.298 INFO using provided configuration {"config_file": "caddy.json", "config_adapter": ""}
2024/05/05 21:40:50.300 INFO admin admin endpoint started {"address": "localhost:2019", "enforce_origin": false, "origins": ["//localhost:2019", "//[::1]:2019", "//127.0.0.1:2019"]}
2024/05/05 21:40:50.300 INFO http.auto_https server is listening only on the HTTPS port but has no TLS connection policies; adding one to enable TLS {"server_name": "spartacus_server", "https_port": 443}
2024/05/05 21:40:50.300 INFO http.auto_https enabling automatic HTTP->HTTPS redirects {"server_name": "spartacus_server"}
2024/05/05 21:40:50.300 INFO tls.cache.maintenance started background certificate maintenance {"cache": "0x14000406e00"}
2024/05/05 21:40:50.301 DEBUG http.auto_https adjusted config {"tls": {"automation":{"policies":[{"subjects":["localhost","127.0.0.1"]},{}]}}, "http": {"servers":{"remaining_auto_https_redirects":{"listen":[":80"],"routes":[{},{}],"logs":{"default_logger_name":"spartacusStdOutLogs"}},"spartacus_server":{"listen":[":443"],"routes":[{"handle":[{"development":true,"handler":"spartacus","posthog":{"endpoint":"https://1e747868-3524-4d27-ad60-2e73e05bb428.mock.pstmn.io"}}]},{}],"tls_connection_policies":[{}],"automatic_https":{},"logs":{"default_logger_name":"spartacusStdOutLogs"}}}}}
2024/05/05 21:40:50.302 INFO http.handlers.spartacus Provisioning Spartacus
2024/05/05 21:40:50.302 INFO http.handlers.spartacus {https://1e747868-3524-4d27-ad60-2e73e05bb428.mock.pstmn.io }+
2024/05/05 21:40:50.302 INFO http.handlers.spartacus Koala config is empty
2024/05/05 21:40:50.302 INFO http.handlers.spartacus Development mode is enabled
2024/05/05 21:40:50.306 INFO pki.ca.local root certificate is already trusted by system {"path": "storage:pki/authorities/local/root.crt"}
2024/05/05 21:40:50.306 INFO http enabling HTTP/3 listener {"addr": ":443"}
2024/05/05 21:40:50.306 DEBUG http starting server loop {"address": "[::]:443", "tls": true, "http3": true}
2024/05/05 21:40:50.306 INFO http.log server running {"name": "spartacus_server", "protocols": ["h1", "h2", "h3"]}
2024/05/05 21:40:50.306 DEBUG http starting server loop {"address": "[::]:80", "tls": false, "http3": false}
2024/05/05 21:40:50.306 INFO http.log server running {"name": "remaining_auto_https_redirects", "protocols": ["h1", "h2", "h3"]}
2024/05/05 21:40:50.306 INFO http enabling automatic TLS certificate management {"domains": ["localhost", "127.0.0.1"]}
2024/05/05 21:40:50.307 WARN tls stapling OCSP {"error": "no OCSP stapling for [localhost]: no OCSP server specified in certificate", "identifiers": ["localhost"]}
2024/05/05 21:40:50.307 DEBUG tls.cache added certificate to cache {"subjects": ["localhost"], "expiration": "2024/05/06 04:43:17.000", "managed": true, "issuer_key": "local", "hash": "4608113bab298e085a4435f98997e45fb4deb4e1fa93637041ad6021e962d5ee", "cache_size": 1, "cache_capacity": 10000}
2024/05/05 21:40:50.307 DEBUG events event {"name": "cached_managed_cert", "id": "1671e066-3bab-4c05-ba63-9b60eb1c7095", "origin": "tls", "data": {"sans":["localhost"]}}
2024/05/05 21:40:50.308 WARN tls stapling OCSP {"error": "no OCSP stapling for [127.0.0.1]: no OCSP server specified in certificate", "identifiers": ["127.0.0.1"]}
2024/05/05 21:40:50.308 DEBUG tls.cache added certificate to cache {"subjects": ["127.0.0.1"], "expiration": "2024/05/06 04:43:17.000", "managed": true, "issuer_key": "local", "hash": "a9566f153dceaa61f0c5608ced32362afc823a22658486b0df2c13f9967d787d", "cache_size": 2, "cache_capacity": 10000}
2024/05/05 21:40:50.308 DEBUG events event {"name": "cached_managed_cert", "id": "89bceb45-f7af-40a6-a1a6-417ef03ea593", "origin": "tls", "data": {"sans":["127.0.0.1"]}}
2024/05/05 21:40:50.308 INFO autosaved config (load with --resume flag) {"file": "/Users/daaronch/Library/Application Support/Caddy/autosave.json"}
2024/05/05 21:40:50.308 INFO serving initial configuration
2024/05/05 21:40:50.317 WARN tls storage cleaning happened too recently; skipping for now {"storage": "FileStorage:/Users/daaronch/Library/Application Support/Caddy", "instance": "9cfc62d9-28c4-469a-bdd5-97fb30adf0e9", "try_again": "2024/05/06 21:40:50.317", "try_again_in": 86399.999999875}
2024/05/05 21:40:50.317 INFO tls finished cleaning storage units
2024/05/05 21:40:57.264 INFO http.log.access.spartacusStdOutLogs handled request {"request": {"remote_ip": "127.0.0.1", "remote_port": "61821", "client_ip": "127.0.0.1", "proto": "HTTP/1.1", "method": "POST", "host": "127.0.0.1", "uri": "/", "headers": {"Content-Type": ["application/x-www-form-urlencoded"], "User-Agent": ["curl/8.4.0"], "Accept": ["*/*"], "Content-Length": ["2"]}}, "bytes_read": 0, "user_id": "", "duration": 0.00013025, "size": 0, "status": 308, "resp_headers": {"Server": ["Caddy"], "Connection": ["close"], "Location": ["https://127.0.0.1/"], "Content-Type": []}}
The above should have printed out many more log lines:
var caddyLog *zap.Logger
// ServeHTTP implements caddyhttp.MiddlewareHandler.
func (s Spartacus) ServeHTTP(w http.ResponseWriter, r *http.Request, next caddyhttp.Handler) error {
caddyLog.Info("Received event")
caddyLog.Info("Received event")
caddyLog.Info("Received event")
caddyLog.Info("Received event")
caddyLog.Info("Received event")
caddyLog.Info("Received event")
caddyLog.Info("Received event")
// Read the request body
body := make([]byte, r.ContentLength)
_, err := r.Body.Read(body)
if err != nil {
// caddyLog.Errorf("Failed to read request body: %s", err.Error())
return err
}
[...]
3. Caddy version:
❯ xcaddy version
v0.4.0 h1:V4n6nNlkRPmrgE+npteBjS7hgMfw24UEmiIONDpIWSo=
4. How I installed and ran Caddy:
xcaddy run --config caddy.json
a. System environment:
Latest MacOS - 14.4.1 (23E224)
b. Command:
N/A
c. Service/unit/compose file:
N/A
d. My complete Caddy config:
{
"logging": {
"logs": {
"default": {
"level": "DEBUG"
}
}
},
"apps": {
"http": {
"servers": {
"spartacus_server": {
"listen": [
":443"
],
"routes": [
{
"handle": [
{
"handler": "spartacus",
"posthog": {
"endpoint": "https://1e747868-3524-4d27-ad60-2e73e05bb428.mock.pstmn.io"
},
"development": true
}
]
},
{
"match": [
{
"host": [
"localhost",
"127.0.0.1"
]
}
]
}
],
"logs": {
"default_logger_name": "spartacusStdOutLogs"
}
}
}
}
}
}