Add reqId to all logging messages I could find (#413)

Reviewed-on: https://codeberg.org/Codeberg/pages-server/pulls/413
Co-authored-by: crapStone <me@crapstone.dev>
Co-committed-by: crapStone <me@crapstone.dev>

.gitignore

@@ -8,3 +8,4 @@ vendor/
 pages
 certs.sqlite
 .bash_history
+pkg/

flake.lock

@@ -20,8 +20,8 @@
     "nixpkgs": {
       "locked": {
         "lastModified": 0,
-        "narHash": "sha256-UA56kDQSztRWbpsG9bK+jIGyZ0YZAcIsYAhXDHIr8zs=",
+        "narHash": "sha256-zUfNgGopg1+/xYRnFaI6PAhlF2JofdEG789CsKclYSw=",
-        "path": "/nix/store/np3i3qi6hq6d1p5xr36cjmr0xwd2j289-source",
+        "path": "/nix/store/0ijldwygklvrzinxx7scsxsvqhx0hqgz-source",
         "type": "path"
       },
       "original": {

go.mod

@@ -72,6 +72,7 @@ require (
 	github.com/gorilla/css v1.0.0 // indirect
 	github.com/hashicorp/go-cleanhttp v0.5.1 // indirect
 	github.com/hashicorp/go-retryablehttp v0.7.0 // indirect
+	github.com/hashicorp/go-uuid v1.0.3 // indirect
 	github.com/hashicorp/go-version v1.6.0 // indirect
 	github.com/iij/doapi v0.0.0-20190504054126-0bbf12d6d7df // indirect
 	github.com/infobloxopen/infoblox-go-client v1.1.1 // indirect

go.sum

@@ -317,6 +317,8 @@ github.com/hashicorp/go-syslog v1.0.0/go.mod h1:qPfqrKkXGihmCqbJM2mZgkZGvKG1dFdv
 github.com/hashicorp/go-uuid v1.0.0/go.mod h1:6SBZvOh/SIDV7/2o3Jml5SYk/TvGqwFJ/bN7x4byOro=
 github.com/hashicorp/go-uuid v1.0.1/go.mod h1:6SBZvOh/SIDV7/2o3Jml5SYk/TvGqwFJ/bN7x4byOro=
 github.com/hashicorp/go-uuid v1.0.2/go.mod h1:6SBZvOh/SIDV7/2o3Jml5SYk/TvGqwFJ/bN7x4byOro=
+github.com/hashicorp/go-uuid v1.0.3 h1:2gKiV6YVmrJ1i2CKKa9obLvRieoRGviZFL26PcT/Co8=
+github.com/hashicorp/go-uuid v1.0.3/go.mod h1:6SBZvOh/SIDV7/2o3Jml5SYk/TvGqwFJ/bN7x4byOro=
 github.com/hashicorp/go-version v1.2.0/go.mod h1:fltr4n8CU8Ke44wwGCBoEymUuxUHl09ZGVZPK5anwXA=
 github.com/hashicorp/go-version v1.6.0 h1:feTTfFNnjP967rlCxM/I9g701jU+RN74YKx2mOkIeek=
 github.com/hashicorp/go-version v1.6.0/go.mod h1:fltr4n8CU8Ke44wwGCBoEymUuxUHl09ZGVZPK5anwXA=

server/certificates/certificates.go

@@ -16,9 +16,11 @@ import (
 	"github.com/go-acme/lego/v4/lego"
 	"github.com/hashicorp/golang-lru/v2/expirable"
 	"github.com/reugn/equalizer"
+	"github.com/rs/zerolog"
 	"github.com/rs/zerolog/log"
 
 	"codeberg.org/codeberg/pages/server/cache"
+	psContext "codeberg.org/codeberg/pages/server/context"
 	"codeberg.org/codeberg/pages/server/database"
 	dnsutils "codeberg.org/codeberg/pages/server/dns"
 	"codeberg.org/codeberg/pages/server/gitea"
@@ -43,7 +45,11 @@ func TLSConfig(mainDomainSuffix string,
 	return &tls.Config{
 		// check DNS name & get certificate from Let's Encrypt
 		GetCertificate: func(info *tls.ClientHelloInfo) (*tls.Certificate, error) {
+			ctx := psContext.New(nil, nil)
+			log := log.With().Str("ReqId", ctx.ReqId).Logger()
+
 			domain := strings.ToLower(strings.TrimSpace(info.ServerName))
+			log.Debug().Str("domain", domain).Msg("start: get tls certificate")
 			if len(domain) < 1 {
 				return nil, errors.New("missing domain info via SNI (RFC 4366, Section 3.1)")
 			}
@@ -100,7 +106,7 @@ func TLSConfig(mainDomainSuffix string,
 						TargetRepo:   targetRepo,
 						TargetBranch: targetBranch,
 					}
-					_, valid := targetOpt.CheckCanonicalDomain(giteaClient, domain, mainDomainSuffix, canonicalDomainCache)
+					_, valid := targetOpt.CheckCanonicalDomain(ctx, giteaClient, domain, mainDomainSuffix, canonicalDomainCache)
 					if !valid {
 						// We shouldn't obtain a certificate when we cannot check if the
 						// repository has specified this domain in the `.domains` file.
@@ -116,7 +122,7 @@ func TLSConfig(mainDomainSuffix string,
 
 			var tlsCertificate *tls.Certificate
 			var err error
-			if tlsCertificate, err = acmeClient.retrieveCertFromDB(domain, mainDomainSuffix, false, certDB); err != nil {
+			if tlsCertificate, err = acmeClient.retrieveCertFromDB(log, domain, mainDomainSuffix, false, certDB); err != nil {
 				if !errors.Is(err, database.ErrNotFound) {
 					return nil, err
 				}
@@ -130,7 +136,7 @@ func TLSConfig(mainDomainSuffix string,
 					return nil, fmt.Errorf("won't request certificate for %q", domain)
 				}
 
-				tlsCertificate, err = acmeClient.obtainCert(acmeClient.legoClient, []string{domain}, nil, targetOwner, false, mainDomainSuffix, certDB)
+				tlsCertificate, err = acmeClient.obtainCert(log, acmeClient.legoClient, []string{domain}, nil, targetOwner, false, mainDomainSuffix, certDB)
 				if err != nil {
 					return nil, err
 				}
@@ -173,7 +179,7 @@ func (c *AcmeClient) checkUserLimit(user string) error {
 	return nil
 }
 
-func (c *AcmeClient) retrieveCertFromDB(sni, mainDomainSuffix string, useDnsProvider bool, certDB database.CertDB) (*tls.Certificate, error) {
+func (c *AcmeClient) retrieveCertFromDB(log zerolog.Logger, sni, mainDomainSuffix string, useDnsProvider bool, certDB database.CertDB) (*tls.Certificate, error) {
 	// parse certificate from database
 	res, err := certDB.Get(sni)
 	if err != nil {
@@ -206,7 +212,7 @@ func (c *AcmeClient) retrieveCertFromDB(sni, mainDomainSuffix string, useDnsProv
 			// TODO: make a queue ?
 			go (func() {
 				res.CSR = nil // acme client doesn't like CSR to be set
-				if _, err := c.obtainCert(c.legoClient, []string{sni}, res, "", useDnsProvider, mainDomainSuffix, certDB); err != nil {
+				if _, err := c.obtainCert(log, c.legoClient, []string{sni}, res, "", useDnsProvider, mainDomainSuffix, certDB); err != nil {
 					log.Error().Msgf("Couldn't renew certificate for %s: %v", sni, err)
 				}
 			})()
@@ -216,7 +222,7 @@ func (c *AcmeClient) retrieveCertFromDB(sni, mainDomainSuffix string, useDnsProv
 	return &tlsCertificate, nil
 }
 
-func (c *AcmeClient) obtainCert(acmeClient *lego.Client, domains []string, renew *certificate.Resource, user string, useDnsProvider bool, mainDomainSuffix string, keyDatabase database.CertDB) (*tls.Certificate, error) {
+func (c *AcmeClient) obtainCert(log zerolog.Logger, acmeClient *lego.Client, domains []string, renew *certificate.Resource, user string, useDnsProvider bool, mainDomainSuffix string, keyDatabase database.CertDB) (*tls.Certificate, error) {
 	name := strings.TrimPrefix(domains[0], "*")
 
 	// lock to avoid simultaneous requests
@@ -226,7 +232,7 @@ func (c *AcmeClient) obtainCert(acmeClient *lego.Client, domains []string, renew
 			time.Sleep(100 * time.Millisecond)
 			_, working = c.obtainLocks.Load(name)
 		}
-		cert, err := c.retrieveCertFromDB(name, mainDomainSuffix, useDnsProvider, keyDatabase)
+		cert, err := c.retrieveCertFromDB(log, name, mainDomainSuffix, useDnsProvider, keyDatabase)
 		if err != nil {
 			return nil, fmt.Errorf("certificate failed in synchronous request: %w", err)
 		}
@@ -320,7 +326,7 @@ func (c *AcmeClient) obtainCert(acmeClient *lego.Client, domains []string, renew
 	return &tlsCertificate, nil
 }
 
-func SetupMainDomainCertificates(mainDomainSuffix string, acmeClient *AcmeClient, certDB database.CertDB) error {
+func SetupMainDomainCertificates(log zerolog.Logger, mainDomainSuffix string, acmeClient *AcmeClient, certDB database.CertDB) error {
 	// getting main cert before ACME account so that we can fail here without hitting rate limits
 	mainCertBytes, err := certDB.Get(mainDomainSuffix)
 	if err != nil && !errors.Is(err, database.ErrNotFound) {
@@ -328,7 +334,7 @@ func SetupMainDomainCertificates(mainDomainSuffix string, acmeClient *AcmeClient
 	}
 
 	if mainCertBytes == nil {
-		_, err = acmeClient.obtainCert(acmeClient.dnsChallengerLegoClient, []string{"*" + mainDomainSuffix, mainDomainSuffix[1:]}, nil, "", true, mainDomainSuffix, certDB)
+		_, err = acmeClient.obtainCert(log, acmeClient.dnsChallengerLegoClient, []string{"*" + mainDomainSuffix, mainDomainSuffix[1:]}, nil, "", true, mainDomainSuffix, certDB)
 		if err != nil {
 			log.Error().Err(err).Msg("Couldn't renew main domain certificate, continuing with mock certs only")
 		}
@@ -337,7 +343,7 @@ func SetupMainDomainCertificates(mainDomainSuffix string, acmeClient *AcmeClient
 	return nil
 }
 
-func MaintainCertDB(ctx context.Context, interval time.Duration, acmeClient *AcmeClient, mainDomainSuffix string, certDB database.CertDB) {
+func MaintainCertDB(log zerolog.Logger, ctx context.Context, interval time.Duration, acmeClient *AcmeClient, mainDomainSuffix string, certDB database.CertDB) {
 	for {
 		// delete expired certs that will be invalid until next clean up
 		threshold := time.Now().Add(interval)
@@ -375,7 +381,7 @@ func MaintainCertDB(ctx context.Context, interval time.Duration, acmeClient *Acm
 			} else if tlsCertificates[0].NotAfter.Before(time.Now().Add(30 * 24 * time.Hour)) {
 				// renew main certificate 30 days before it expires
 				go (func() {
-					_, err = acmeClient.obtainCert(acmeClient.dnsChallengerLegoClient, []string{"*" + mainDomainSuffix, mainDomainSuffix[1:]}, res, "", true, mainDomainSuffix, certDB)
+					_, err = acmeClient.obtainCert(log, acmeClient.dnsChallengerLegoClient, []string{"*" + mainDomainSuffix, mainDomainSuffix[1:]}, res, "", true, mainDomainSuffix, certDB)
 					if err != nil {
 						log.Error().Err(err).Msg("Couldn't renew certificate for main domain")
 					}

server/context/context.go

@@ -5,19 +5,29 @@ import (
 	"net/http"
 
 	"codeberg.org/codeberg/pages/server/utils"
+	"github.com/hashicorp/go-uuid"
+	"github.com/rs/zerolog/log"
 )
 
 type Context struct {
 	RespWriter http.ResponseWriter
 	Req        *http.Request
 	StatusCode int
+	ReqId      string
 }
 
 func New(w http.ResponseWriter, r *http.Request) *Context {
+	req_uuid, err := uuid.GenerateUUID()
+	if err != nil {
+		log.Error().Err(err).Msg("Failed to generate request id, assigning error value")
+		req_uuid = "ERROR"
+	}
+
 	return &Context{
 		RespWriter: w,
 		Req:        r,
 		StatusCode: http.StatusOK,
+		ReqId:      req_uuid,
 	}
 }
 

server/gitea/cache.go

@@ -8,9 +8,11 @@ import (
 	"net/http"
 	"time"
 
+	"github.com/rs/zerolog"
 	"github.com/rs/zerolog/log"
 
 	"codeberg.org/codeberg/pages/server/cache"
+	"codeberg.org/codeberg/pages/server/context"
 )
 
 const (
@@ -89,16 +91,17 @@ type writeCacheReader struct {
 	hasError       bool
 	doNotCache     bool
 	complete       bool
+	log            zerolog.Logger
 }
 
 func (t *writeCacheReader) Read(p []byte) (n int, err error) {
-	log.Trace().Msgf("[cache] read %q", t.cacheKey)
+	t.log.Trace().Msgf("[cache] read %q", t.cacheKey)
 	n, err = t.originalReader.Read(p)
 	if err == io.EOF {
 		t.complete = true
 	}
 	if err != nil && err != io.EOF {
-		log.Trace().Err(err).Msgf("[cache] original reader for %q has returned an error", t.cacheKey)
+		t.log.Trace().Err(err).Msgf("[cache] original reader for %q has returned an error", t.cacheKey)
 		t.hasError = true
 	} else if n > 0 {
 		if t.buffer.Len()+n > int(fileCacheSizeLimit) {
@@ -118,22 +121,23 @@ func (t *writeCacheReader) Close() error {
 	if doWrite {
 		jsonToCache, err := json.Marshal(fc)
 		if err != nil {
-			log.Trace().Err(err).Msgf("[cache] marshaling json for %q has returned an error", t.cacheKey+"|Metadata")
+			t.log.Trace().Err(err).Msgf("[cache] marshaling json for %q has returned an error", t.cacheKey+"|Metadata")
 		}
 		err = t.cache.Set(t.cacheKey+"|Metadata", jsonToCache, fileCacheTimeout)
 		if err != nil {
-			log.Trace().Err(err).Msgf("[cache] writer for %q has returned an error", t.cacheKey+"|Metadata")
+			t.log.Trace().Err(err).Msgf("[cache] writer for %q has returned an error", t.cacheKey+"|Metadata")
 		}
 		err = t.cache.Set(t.cacheKey+"|Body", fc.Body, fileCacheTimeout)
 		if err != nil {
-			log.Trace().Err(err).Msgf("[cache] writer for %q has returned an error", t.cacheKey+"|Body")
+			t.log.Trace().Err(err).Msgf("[cache] writer for %q has returned an error", t.cacheKey+"|Body")
 		}
 	}
-	log.Trace().Msgf("cacheReader for %q saved=%t closed", t.cacheKey, doWrite)
+	t.log.Trace().Msgf("cacheReader for %q saved=%t closed", t.cacheKey, doWrite)
 	return t.originalReader.Close()
 }
 
-func (f FileResponse) CreateCacheReader(r io.ReadCloser, cache cache.ICache, cacheKey string) io.ReadCloser {
+func (f FileResponse) CreateCacheReader(ctx *context.Context, r io.ReadCloser, cache cache.ICache, cacheKey string) io.ReadCloser {
+	log := log.With().Str("ReqId", ctx.ReqId).Logger()
 	if r == nil || cache == nil || cacheKey == "" {
 		log.Error().Msg("could not create CacheReader")
 		return nil
@@ -145,5 +149,6 @@ func (f FileResponse) CreateCacheReader(r io.ReadCloser, cache cache.ICache, cac
 		fileResponse:   &f,
 		cache:          cache,
 		cacheKey:       cacheKey,
+		log:            log,
 	}
 }

server/gitea/client.go

@@ -19,6 +19,7 @@ import (
 
 	"codeberg.org/codeberg/pages/config"
 	"codeberg.org/codeberg/pages/server/cache"
+	"codeberg.org/codeberg/pages/server/context"
 	"codeberg.org/codeberg/pages/server/version"
 )
 
@@ -104,8 +105,8 @@ func (client *Client) ContentWebLink(targetOwner, targetRepo, branch, resource s
 	return path.Join(client.giteaRoot, targetOwner, targetRepo, "src/branch", branch, resource)
 }
 
-func (client *Client) GiteaRawContent(targetOwner, targetRepo, ref, resource string) ([]byte, error) {
+func (client *Client) GiteaRawContent(ctx *context.Context, targetOwner, targetRepo, ref, resource string) ([]byte, error) {
-	reader, _, _, err := client.ServeRawContent(targetOwner, targetRepo, ref, resource, false)
+	reader, _, _, err := client.ServeRawContent(ctx, targetOwner, targetRepo, ref, resource, false)
 	if err != nil {
 		return nil, err
 	}
@@ -113,9 +114,9 @@ func (client *Client) GiteaRawContent(targetOwner, targetRepo, ref, resource str
 	return io.ReadAll(reader)
 }
 
-func (client *Client) ServeRawContent(targetOwner, targetRepo, ref, resource string, decompress bool) (io.ReadCloser, http.Header, int, error) {
+func (client *Client) ServeRawContent(ctx *context.Context, targetOwner, targetRepo, ref, resource string, decompress bool) (io.ReadCloser, http.Header, int, error) {
 	cacheKey := fmt.Sprintf("%s/%s/%s|%s|%s", rawContentCacheKeyPrefix, targetOwner, targetRepo, ref, resource)
-	log := log.With().Str("cache_key", cacheKey).Logger()
+	log := log.With().Str("ReqId", ctx.ReqId).Str("cache_key", cacheKey).Logger()
 	log.Trace().Msg("try file in cache")
 	// handle if cache entry exist
 	if cacheMetadata, ok := client.responseCache.Get(cacheKey + "|Metadata"); ok {
@@ -142,7 +143,7 @@ func (client *Client) ServeRawContent(targetOwner, targetRepo, ref, resource str
 			if cache.IsSymlink {
 				linkDest := string(cache.Body)
 				log.Debug().Msgf("[cache] follow symlink from %q to %q", resource, linkDest)
-				return client.ServeRawContent(targetOwner, targetRepo, ref, linkDest, decompress)
+				return client.ServeRawContent(ctx, targetOwner, targetRepo, ref, linkDest, decompress)
 			} else {
 				log.Debug().Msgf("[cache] return %d bytes", len(cache.Body))
 				return io.NopCloser(bytes.NewReader(cache.Body)), cachedHeader, cachedStatusCode, nil
@@ -194,7 +195,7 @@ func (client *Client) ServeRawContent(targetOwner, targetRepo, ref, resource str
 					}
 
 					log.Debug().Msgf("follow symlink from %q to %q", resource, linkDest)
-					return client.ServeRawContent(targetOwner, targetRepo, ref, linkDest, decompress)
+					return client.ServeRawContent(ctx, targetOwner, targetRepo, ref, linkDest, decompress)
 				}
 			}
 
@@ -214,7 +215,7 @@ func (client *Client) ServeRawContent(targetOwner, targetRepo, ref, resource str
 				MimeType: mimeType,
 				RawMime:  rawType,
 			}
-			return fileResp.CreateCacheReader(reader, client.responseCache, cacheKey), resp.Response.Header, resp.StatusCode, nil
+			return fileResp.CreateCacheReader(ctx, reader, client.responseCache, cacheKey), resp.Response.Header, resp.StatusCode, nil
 
 		case http.StatusNotFound:
 			jsonToCache, err := json.Marshal(FileResponse{ETag: resp.Header.Get(ETagHeader)})

server/handler/handler.go

@@ -26,9 +26,9 @@ func Handler(
 	canonicalDomainCache, redirectsCache cache.ICache,
 ) http.HandlerFunc {
 	return func(w http.ResponseWriter, req *http.Request) {
-		log.Debug().Msg("\n----------------------------------------------------------")
-		log := log.With().Strs("Handler", []string{req.Host, req.RequestURI}).Logger()
 		ctx := context.New(w, req)
+		log := log.With().Str("ReqId", ctx.ReqId).Strs("Handler", []string{req.Host, req.RequestURI}).Logger()
+		log.Debug().Msg("\n----------------------------------------------------------")
 
 		ctx.RespWriter.Header().Set("Server", "pages-server")
 

server/handler/handler_custom_domain.go

@@ -47,7 +47,7 @@ func handleCustomDomain(log zerolog.Logger, ctx *context.Context, giteaClient *g
 		TargetBranch:  targetBranch,
 		TargetPath:    path.Join(pathParts...),
 	}, canonicalLink); works {
-		canonicalDomain, valid := targetOpt.CheckCanonicalDomain(giteaClient, trimmedHost, mainDomainSuffix, canonicalDomainCache)
+		canonicalDomain, valid := targetOpt.CheckCanonicalDomain(ctx, giteaClient, trimmedHost, mainDomainSuffix, canonicalDomainCache)
 		if !valid {
 			html.ReturnErrorPage(ctx, "domain not specified in <code>.domains</code> file", http.StatusMisdirectedRequest)
 			return
@@ -63,8 +63,8 @@ func handleCustomDomain(log zerolog.Logger, ctx *context.Context, giteaClient *g
 			return
 		}
 
-		log.Debug().Msg("tryBranch, now trying upstream 7")
+		log.Debug().Str("url", trimmedHost).Msg("tryBranch, now trying upstream")
-		tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost, targetOpt, canonicalDomainCache, redirectsCache)
+		tryUpstream(log, ctx, giteaClient, mainDomainSuffix, trimmedHost, targetOpt, canonicalDomainCache, redirectsCache)
 		return
 	}
 

server/handler/handler_raw_domain.go

@@ -45,7 +45,7 @@ func handleRaw(log zerolog.Logger, ctx *context.Context, giteaClient *gitea.Clie
 			TargetPath:   path.Join(pathElements[3:]...),
 		}, true); works {
 			log.Trace().Msg("tryUpstream: serve raw domain with specified branch")
-			tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost, targetOpt, canonicalDomainCache, redirectsCache)
+			tryUpstream(log, ctx, giteaClient, mainDomainSuffix, trimmedHost, targetOpt, canonicalDomainCache, redirectsCache)
 			return
 		}
 		log.Debug().Msg("missing branch info")
@@ -62,7 +62,7 @@ func handleRaw(log zerolog.Logger, ctx *context.Context, giteaClient *gitea.Clie
 		TargetPath:    path.Join(pathElements[2:]...),
 	}, true); works {
 		log.Trace().Msg("tryUpstream: serve raw domain with default branch")
-		tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost, targetOpt, canonicalDomainCache, redirectsCache)
+		tryUpstream(log, ctx, giteaClient, mainDomainSuffix, trimmedHost, targetOpt, canonicalDomainCache, redirectsCache)
 	} else {
 		html.ReturnErrorPage(ctx,
 			fmt.Sprintf("raw domain could not find repo <code>%s/%s</code> or repo is empty", targetOpt.TargetOwner, targetOpt.TargetRepo),

server/handler/handler_sub_domain.go

@@ -53,7 +53,7 @@ func handleSubDomain(log zerolog.Logger, ctx *context.Context, giteaClient *gite
 			TargetPath:    path.Join(pathElements[2:]...),
 		}, true); works {
 			log.Trace().Msg("tryUpstream: serve with specified repo and branch")
-			tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost, targetOpt, canonicalDomainCache, redirectsCache)
+			tryUpstream(log, ctx, giteaClient, mainDomainSuffix, trimmedHost, targetOpt, canonicalDomainCache, redirectsCache)
 		} else {
 			html.ReturnErrorPage(
 				ctx,
@@ -85,7 +85,7 @@ func handleSubDomain(log zerolog.Logger, ctx *context.Context, giteaClient *gite
 			TargetPath:    path.Join(pathElements[1:]...),
 		}, true); works {
 			log.Trace().Msg("tryUpstream: serve default pages repo with specified branch")
-			tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost, targetOpt, canonicalDomainCache, redirectsCache)
+			tryUpstream(log, ctx, giteaClient, mainDomainSuffix, trimmedHost, targetOpt, canonicalDomainCache, redirectsCache)
 		} else {
 			html.ReturnErrorPage(
 				ctx,
@@ -110,7 +110,7 @@ func handleSubDomain(log zerolog.Logger, ctx *context.Context, giteaClient *gite
 				TargetPath:    path.Join(pathElements[1:]...),
 			}, false); works {
 				log.Debug().Msg("tryBranch, now trying upstream 5")
-				tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost, targetOpt, canonicalDomainCache, redirectsCache)
+				tryUpstream(log, ctx, giteaClient, mainDomainSuffix, trimmedHost, targetOpt, canonicalDomainCache, redirectsCache)
 				return
 			}
 		}
@@ -126,7 +126,7 @@ func handleSubDomain(log zerolog.Logger, ctx *context.Context, giteaClient *gite
 			TargetPath:    path.Join(pathElements...),
 		}, false); works {
 			log.Debug().Msg("tryBranch, now trying upstream 6")
-			tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost, targetOpt, canonicalDomainCache, redirectsCache)
+			tryUpstream(log, ctx, giteaClient, mainDomainSuffix, trimmedHost, targetOpt, canonicalDomainCache, redirectsCache)
 			return
 		}
 	}
@@ -141,7 +141,7 @@ func handleSubDomain(log zerolog.Logger, ctx *context.Context, giteaClient *gite
 		TargetPath:    path.Join(pathElements...),
 	}, false); works {
 		log.Debug().Msg("tryBranch, now trying upstream 6")
-		tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost, targetOpt, canonicalDomainCache, redirectsCache)
+		tryUpstream(log, ctx, giteaClient, mainDomainSuffix, trimmedHost, targetOpt, canonicalDomainCache, redirectsCache)
 		return
 	}
 

server/handler/try.go

@@ -15,7 +15,7 @@ import (
 )
 
 // tryUpstream forwards the target request to the Gitea API, and shows an error page on failure.
-func tryUpstream(ctx *context.Context, giteaClient *gitea.Client,
+func tryUpstream(log zerolog.Logger, ctx *context.Context, giteaClient *gitea.Client,
 	mainDomainSuffix, trimmedHost string,
 	options *upstream.Options,
 	canonicalDomainCache cache.ICache,
@@ -23,7 +23,7 @@ func tryUpstream(ctx *context.Context, giteaClient *gitea.Client,
 ) {
 	// check if a canonical domain exists on a request on MainDomain
 	if strings.HasSuffix(trimmedHost, mainDomainSuffix) && !options.ServeRaw {
-		canonicalDomain, _ := options.CheckCanonicalDomain(giteaClient, "", mainDomainSuffix, canonicalDomainCache)
+		canonicalDomain, _ := options.CheckCanonicalDomain(ctx, giteaClient, "", mainDomainSuffix, canonicalDomainCache)
 		if !strings.HasSuffix(strings.SplitN(canonicalDomain, "/", 2)[0], mainDomainSuffix) {
 			canonicalPath := ctx.Req.RequestURI
 			if options.TargetRepo != defaultPagesRepo {
@@ -32,7 +32,12 @@ func tryUpstream(ctx *context.Context, giteaClient *gitea.Client,
 					canonicalPath = "/" + path[2]
 				}
 			}
-			ctx.Redirect("https://"+canonicalDomain+canonicalPath, http.StatusTemporaryRedirect)
+
+			redirect_to := "https://" + canonicalDomain + canonicalPath
+
+			log.Debug().Str("to", redirect_to).Msg("redirecting")
+
+			ctx.Redirect(redirect_to, http.StatusTemporaryRedirect)
 			return
 		}
 	}
@@ -41,6 +46,7 @@ func tryUpstream(ctx *context.Context, giteaClient *gitea.Client,
 	options.Host = trimmedHost
 
 	// Try to request the file from the Gitea API
+	log.Debug().Msg("requesting from upstream")
 	if !options.Upstream(ctx, giteaClient, redirectsCache) {
 		html.ReturnErrorPage(ctx, fmt.Sprintf("Forge returned %d %s", ctx.StatusCode, http.StatusText(ctx.StatusCode)), ctx.StatusCode)
 	}

server/startup.go

@@ -27,7 +27,7 @@ import (
 // Serve sets up and starts the web server.
 func Serve(ctx *cli.Context) error {
 	// initialize logger with Trace, overridden later with actual level
-	log.Logger = zerolog.New(zerolog.ConsoleWriter{Out: os.Stderr}).With().Timestamp().Logger().Level(zerolog.TraceLevel)
+	log.Logger = zerolog.New(zerolog.ConsoleWriter{Out: os.Stderr}).With().Timestamp().Caller().Logger().Level(zerolog.TraceLevel)
 
 	cfg, err := config.ReadConfig(ctx)
 	if err != nil {
@@ -41,7 +41,8 @@ func Serve(ctx *cli.Context) error {
 	if err != nil {
 		return err
 	}
-	log.Logger = zerolog.New(zerolog.ConsoleWriter{Out: os.Stderr}).With().Timestamp().Logger().Level(logLevel)
+	fmt.Printf("Setting log level to: %s\n", logLevel)
+	log.Logger = zerolog.New(zerolog.ConsoleWriter{Out: os.Stderr}).With().Timestamp().Caller().Logger().Level(logLevel)
 
 	listeningSSLAddress := fmt.Sprintf("%s:%d", cfg.Server.Host, cfg.Server.Port)
 	listeningHTTPAddress := fmt.Sprintf("%s:%d", cfg.Server.Host, cfg.Server.HttpPort)
@@ -85,7 +86,7 @@ func Serve(ctx *cli.Context) error {
 		return err
 	}
 
-	if err := certificates.SetupMainDomainCertificates(cfg.Server.MainDomain, acmeClient, certDB); err != nil {
+	if err := certificates.SetupMainDomainCertificates(log.Logger, cfg.Server.MainDomain, acmeClient, certDB); err != nil {
 		return err
 	}
 
@@ -114,7 +115,7 @@ func Serve(ctx *cli.Context) error {
 	interval := 12 * time.Hour
 	certMaintainCtx, cancelCertMaintain := context.WithCancel(context.Background())
 	defer cancelCertMaintain()
-	go certificates.MaintainCertDB(certMaintainCtx, interval, acmeClient, cfg.Server.MainDomain, certDB)
+	go certificates.MaintainCertDB(log.Logger, certMaintainCtx, interval, acmeClient, cfg.Server.MainDomain, certDB)
 
 	if cfg.Server.HttpServerEnabled {
 		// Create handler for http->https redirect and http acme challenges

server/upstream/domains.go

@@ -8,6 +8,7 @@ import (
 	"github.com/rs/zerolog/log"
 
 	"codeberg.org/codeberg/pages/server/cache"
+	"codeberg.org/codeberg/pages/server/context"
 	"codeberg.org/codeberg/pages/server/gitea"
 )
 
@@ -17,7 +18,7 @@ var canonicalDomainCacheTimeout = 15 * time.Minute
 const canonicalDomainConfig = ".domains"
 
 // CheckCanonicalDomain returns the canonical domain specified in the repo (using the `.domains` file).
-func (o *Options) CheckCanonicalDomain(giteaClient *gitea.Client, actualDomain, mainDomainSuffix string, canonicalDomainCache cache.ICache) (domain string, valid bool) {
+func (o *Options) CheckCanonicalDomain(ctx *context.Context, giteaClient *gitea.Client, actualDomain, mainDomainSuffix string, canonicalDomainCache cache.ICache) (domain string, valid bool) {
 	// Check if this request is cached.
 	if cachedValue, ok := canonicalDomainCache.Get(o.TargetOwner + "/" + o.TargetRepo + "/" + o.TargetBranch); ok {
 		domains := cachedValue.([]string)
@@ -30,7 +31,7 @@ func (o *Options) CheckCanonicalDomain(giteaClient *gitea.Client, actualDomain,
 		return domains[0], valid
 	}
 
-	body, err := giteaClient.GiteaRawContent(o.TargetOwner, o.TargetRepo, o.TargetBranch, canonicalDomainConfig)
+	body, err := giteaClient.GiteaRawContent(ctx, o.TargetOwner, o.TargetRepo, o.TargetBranch, canonicalDomainConfig)
 	if err != nil && !errors.Is(err, gitea.ErrorNotFound) {
 		log.Error().Err(err).Msgf("could not read %s of %s/%s", canonicalDomainConfig, o.TargetOwner, o.TargetRepo)
 	}

server/upstream/redirects.go

@@ -44,7 +44,7 @@ var redirectsCacheTimeout = 10 * time.Minute
 const redirectsConfig = "_redirects"
 
 // getRedirects returns redirects specified in the _redirects file.
-func (o *Options) getRedirects(giteaClient *gitea.Client, redirectsCache cache.ICache) []Redirect {
+func (o *Options) getRedirects(ctx *context.Context, giteaClient *gitea.Client, redirectsCache cache.ICache) []Redirect {
 	var redirects []Redirect
 	cacheKey := o.TargetOwner + "/" + o.TargetRepo + "/" + o.TargetBranch
 
@@ -53,7 +53,7 @@ func (o *Options) getRedirects(giteaClient *gitea.Client, redirectsCache cache.I
 		redirects = cachedValue.([]Redirect)
 	} else {
 		// Get _redirects file and parse
-		body, err := giteaClient.GiteaRawContent(o.TargetOwner, o.TargetRepo, o.TargetBranch, redirectsConfig)
+		body, err := giteaClient.GiteaRawContent(ctx, o.TargetOwner, o.TargetRepo, o.TargetBranch, redirectsConfig)
 		if err == nil {
 			for _, line := range strings.Split(string(body), "\n") {
 				redirectArr := strings.Fields(line)

server/upstream/upstream.go

@@ -125,7 +125,7 @@ func AcceptEncodings(header string) []string {
 
 // Upstream requests a file from the Gitea API at GiteaRoot and writes it to the request context.
 func (o *Options) Upstream(ctx *context.Context, giteaClient *gitea.Client, redirectsCache cache.ICache) bool {
-	log := log.With().Strs("upstream", []string{o.TargetOwner, o.TargetRepo, o.TargetBranch, o.TargetPath}).Logger()
+	log := log.With().Str("ReqId", ctx.ReqId).Strs("upstream", []string{o.TargetOwner, o.TargetRepo, o.TargetBranch, o.TargetPath}).Logger()
 
 	log.Debug().Msg("Start")
 
@@ -182,7 +182,7 @@ func (o *Options) Upstream(ctx *context.Context, giteaClient *gitea.Client, redi
 
 			// add extension for encoding
 			path := o.TargetPath + allowedEncodings[encoding]
-			reader, header, statusCode, err = giteaClient.ServeRawContent(o.TargetOwner, o.TargetRepo, o.TargetBranch, path, true)
+			reader, header, statusCode, err = giteaClient.ServeRawContent(ctx, o.TargetOwner, o.TargetRepo, o.TargetBranch, path, true)
 			if statusCode == http.StatusNotFound {
 				continue
 			}
@@ -206,7 +206,7 @@ func (o *Options) Upstream(ctx *context.Context, giteaClient *gitea.Client, redi
 	if err != nil && errors.Is(err, gitea.ErrorNotFound) {
 		log.Debug().Msg("Handling not found error")
 		// Get and match redirects
-		redirects := o.getRedirects(giteaClient, redirectsCache)
+		redirects := o.getRedirects(ctx, giteaClient, redirectsCache)
 		if o.matchRedirects(ctx, giteaClient, redirects, redirectsCache) {
 			log.Trace().Msg("redirect")
 			return true
@@ -234,7 +234,7 @@ func (o *Options) Upstream(ctx *context.Context, giteaClient *gitea.Client, redi
 			}
 		}
 
-		log.Trace().Msg("not found")
+		log.Debug().Msg("not found")
 
 		ctx.StatusCode = http.StatusNotFound
 		if o.TryIndexPages {