Improve logging (#116)

- Actually log useful information at their respective log level.
- Add logs in hot-paths to be able to deep-dive and debug specific requests (see server/handler.go)
- Add more information to existing fields(e.g. the host that the user is visiting, this was noted by @fnetX).

Co-authored-by: Gusted <williamzijl7@hotmail.com>
Reviewed-on: https://codeberg.org/Codeberg/pages-server/pulls/116
Reviewed-by: 6543 <6543@noreply.codeberg.org>
Co-authored-by: Gusted <gusted@noreply.codeberg.org>
Co-committed-by: Gusted <gusted@noreply.codeberg.org>

cmd/flags.go

@@ -5,12 +5,6 @@ import (
 )
 
 var ServeFlags = []cli.Flag{
-	&cli.BoolFlag{
-		Name: "verbose",
-		// TODO: Usage
-		EnvVars: []string{"DEBUG"},
-	},
-
 	// MainDomainSuffix specifies the main domain (starting with a dot) for which subdomains shall be served as static
 	// pages, or used for comparison in CNAME lookups. Static pages can be accessed through
 	// https://{owner}.{MainDomain}[/{repo}], with repo defaulting to "pages".
@@ -69,6 +63,12 @@ var ServeFlags = []cli.Flag{
 		// TODO: desc
 		EnvVars: []string{"ENABLE_HTTP_SERVER"},
 	},
+	&cli.StringFlag{
+		Name:    "log-level",
+		Value:   "warn",
+		Usage:   "specify at which log level should be logged. Possible options: info, warn, error, fatal",
+		EnvVars: []string{"LOG_LEVEL"},
+	},
 
 	// ACME
 	&cli.StringFlag{

cmd/main.go

@@ -7,6 +7,7 @@ import (
 	"errors"
 	"fmt"
 	"net"
+	"os"
 	"strings"
 	"time"
 
@@ -36,10 +37,12 @@ var BlacklistedPaths = [][]byte{
 
 // Serve sets up and starts the web server.
 func Serve(ctx *cli.Context) error {
-	verbose := ctx.Bool("verbose")
+	// Initalize the logger.
-	if !verbose {
+	logLevel, err := zerolog.ParseLevel(ctx.String("log-level"))
-		zerolog.SetGlobalLevel(zerolog.InfoLevel)
+	if err != nil {
+		return err
 	}
+	log.Logger = zerolog.New(zerolog.ConsoleWriter{Out: os.Stderr}).With().Timestamp().Logger().Level(logLevel)
 
 	giteaRoot := strings.TrimSuffix(ctx.String("gitea-root"), "/")
 	giteaAPIToken := ctx.String("gitea-api-token")
@@ -101,7 +104,7 @@ func Serve(ctx *cli.Context) error {
 	log.Info().Msgf("Listening on https://%s", listeningAddress)
 	listener, err := net.Listen("tcp", listeningAddress)
 	if err != nil {
-		return fmt.Errorf("couldn't create listener: %s", err)
+		return fmt.Errorf("couldn't create listener: %v", err)
 	}
 
 	// TODO: make "key-database.pogreb" set via flag
@@ -134,7 +137,7 @@ func Serve(ctx *cli.Context) error {
 
 	if enableHTTPServer {
 		go func() {
-			log.Info().Timestamp().Msg("Start listening on :80")
+			log.Info().Msg("Start HTTP server listening on :80")
 			err := httpServer.ListenAndServe("[::]:80")
 			if err != nil {
 				log.Panic().Err(err).Msg("Couldn't start HTTP fastServer")
@@ -143,7 +146,7 @@ func Serve(ctx *cli.Context) error {
 	}
 
 	// Start the web fastServer
-	log.Info().Timestamp().Msgf("Start listening on %s", listener.Addr())
+	log.Info().Msgf("Start listening on %s", listener.Addr())
 	err = fastServer.Serve(listener)
 	if err != nil {
 		log.Panic().Err(err).Msg("Couldn't start fastServer")

go.mod

@@ -6,8 +6,8 @@ require (
 	github.com/OrlovEvgeny/go-mcache v0.0.0-20200121124330-1a8195b34f3a
 	github.com/akrylysov/pogreb v0.10.1
 	github.com/go-acme/lego/v4 v4.5.3
+	github.com/joho/godotenv v1.4.0
 	github.com/reugn/equalizer v0.0.0-20210216135016-a959c509d7ad
-	github.com/rs/zerolog v1.26.0
 	github.com/stretchr/testify v1.7.0
 	github.com/urfave/cli/v2 v2.3.0
 	github.com/valyala/fasthttp v1.31.0
@@ -60,7 +60,6 @@ require (
 	github.com/infobloxopen/infoblox-go-client v1.1.1 // indirect
 	github.com/jarcoal/httpmock v1.0.6 // indirect
 	github.com/jmespath/go-jmespath v0.4.0 // indirect
-	github.com/joho/godotenv v1.4.0 // indirect
 	github.com/json-iterator/go v1.1.7 // indirect
 	github.com/k0kubun/go-ansi v0.0.0-20180517002512-3bf9e2903213 // indirect
 	github.com/klauspost/compress v1.13.4 // indirect
@@ -72,7 +71,8 @@ require (
 	github.com/liquidweb/go-lwApi v0.0.5 // indirect
 	github.com/liquidweb/liquidweb-cli v0.6.9 // indirect
 	github.com/liquidweb/liquidweb-go v1.6.3 // indirect
-	github.com/mattn/go-isatty v0.0.12 // indirect
+	github.com/mattn/go-colorable v0.1.12 // indirect
+	github.com/mattn/go-isatty v0.0.14 // indirect
 	github.com/miekg/dns v1.1.43 // indirect
 	github.com/mitchellh/go-homedir v1.1.0 // indirect
 	github.com/mitchellh/mapstructure v1.4.1 // indirect
@@ -92,6 +92,7 @@ require (
 	github.com/pkg/errors v0.9.1 // indirect
 	github.com/pmezard/go-difflib v1.0.0 // indirect
 	github.com/pquerna/otp v1.3.0 // indirect
+	github.com/rs/zerolog v1.27.0 // indirect
 	github.com/russross/blackfriday/v2 v2.0.1 // indirect
 	github.com/sacloud/libsacloud v1.36.2 // indirect
 	github.com/scaleway/scaleway-sdk-go v1.0.0-beta.7.0.20210127161313-bd30bebeac4f // indirect
@@ -111,7 +112,7 @@ require (
 	golang.org/x/crypto v0.0.0-20210616213533-5ff15b29337e // indirect
 	golang.org/x/net v0.0.0-20210805182204-aaa1db679c0d // indirect
 	golang.org/x/oauth2 v0.0.0-20200107190931-bf48bf16ab8d // indirect
-	golang.org/x/sys v0.0.0-20210809222454-d867a43fc93e // indirect
+	golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6 // indirect
 	golang.org/x/text v0.3.6 // indirect
 	golang.org/x/time v0.0.0-20210611083556-38a9dc6acbc6 // indirect
 	google.golang.org/api v0.20.0 // indirect

go.sum

@@ -95,7 +95,7 @@ github.com/coreos/bbolt v1.3.2/go.mod h1:iRUV2dpdMOn7Bo10OQBFzIJO9kkE559Wcmn+qkE
 github.com/coreos/etcd v3.3.13+incompatible/go.mod h1:uF7uidLiAD3TWHmW31ZFd/JWoc32PjwdhPthX9715RE=
 github.com/coreos/go-semver v0.3.0/go.mod h1:nnelYz7RCh+5ahJtPPxZlU+153eP4D4r3EedlOD2RNk=
 github.com/coreos/go-systemd v0.0.0-20190321100706-95778dfbb74e/go.mod h1:F5haX7vjVVG0kc13fIWeqUViNPyEJxv/OmvnBo0Yme4=
-github.com/coreos/go-systemd/v22 v22.3.2/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
+github.com/coreos/go-systemd/v22 v22.3.3-0.20220203105225-a9a7ef127534/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
 github.com/coreos/pkg v0.0.0-20180928190104-399ea9e2e55f/go.mod h1:E3G3o1h8I7cfcXa63jLwjI0eiQQMgzzUDFVpN/nH/eA=
 github.com/cpu/goacmedns v0.1.1 h1:DM3H2NiN2oam7QljgGY5ygy4yDXhK5Z4JUnqaugs2C4=
 github.com/cpu/goacmedns v0.1.1/go.mod h1:MuaouqEhPAHxsbqjgnck5zeghuwBP1dLnPoobeGqugQ=
@@ -321,12 +321,16 @@ github.com/mattn/go-colorable v0.1.2/go.mod h1:U0ppj6V5qS13XJ6of8GYAs25YV2eR4EVc
 github.com/mattn/go-colorable v0.1.4/go.mod h1:U0ppj6V5qS13XJ6of8GYAs25YV2eR4EVcfRqFIhoBtE=
 github.com/mattn/go-colorable v0.1.7/go.mod h1:u6P/XSegPjTcexA+o6vUJrdnUu04hMope9wVRipJSqc=
 github.com/mattn/go-colorable v0.1.8/go.mod h1:u6P/XSegPjTcexA+o6vUJrdnUu04hMope9wVRipJSqc=
+github.com/mattn/go-colorable v0.1.12 h1:jF+Du6AlPIjs2BiUiQlKOX0rt3SujHxPnksPKZbaA40=
+github.com/mattn/go-colorable v0.1.12/go.mod h1:u5H1YNBxpqRaxsYJYSkiCWKzEfiAb1Gb520KVy5xxl4=
 github.com/mattn/go-isatty v0.0.3/go.mod h1:M+lRXTBqGeGNdLjl/ufCoiOlB5xdOkqRJdNxMWT7Zi4=
 github.com/mattn/go-isatty v0.0.8/go.mod h1:Iq45c/XA43vh69/j3iqttzPXn0bhXyGjM0Hdxcsrc5s=
 github.com/mattn/go-isatty v0.0.9/go.mod h1:YNRxwqDuOph6SZLI9vUUz6OYw3QyUt7WiY2yME+cCiQ=
 github.com/mattn/go-isatty v0.0.10/go.mod h1:qgIWMr58cqv1PHHyhnkY9lrL7etaEgOFcMEpPG5Rm84=
 github.com/mattn/go-isatty v0.0.12 h1:wuysRhFDzyxgEmMf5xjvJ2M9dZoWAXNNr5LSBS7uHXY=
 github.com/mattn/go-isatty v0.0.12/go.mod h1:cbi8OIDigv2wuxKPP5vlRcQ1OAZbq2CE4Kysco4FUpU=
+github.com/mattn/go-isatty v0.0.14 h1:yVuAays6BHfxijgZPzw+3Zlu5yQgKGP2/hcQbHb7S9Y=
+github.com/mattn/go-isatty v0.0.14/go.mod h1:7GGIvUiUoEMVVmxf/4nioHXj79iQHKdU27kJ6hsGG94=
 github.com/mattn/go-runewidth v0.0.2/go.mod h1:LwmH8dsx7+W8Uxz3IHJYH5QSwggIsqBzpuz5H//U1FU=
 github.com/mattn/go-runewidth v0.0.6/go.mod h1:H031xJmbD/WCDINGzjvQ9THkh0rPKHF+m2gUSrubnMI=
 github.com/mattn/go-runewidth v0.0.9/go.mod h1:H031xJmbD/WCDINGzjvQ9THkh0rPKHF+m2gUSrubnMI=
@@ -428,8 +432,8 @@ github.com/reugn/equalizer v0.0.0-20210216135016-a959c509d7ad/go.mod h1:h0+DiDRe
 github.com/rogpeppe/fastuuid v0.0.0-20150106093220-6724a57986af/go.mod h1:XWv6SoW27p1b0cqNHllgS5HIMJraePCO15w5zCzIWYg=
 github.com/rogpeppe/go-internal v1.3.0/go.mod h1:M8bDsm7K2OlrFYOpmOWEs/qY81heoFRclV5y23lUDJ4=
 github.com/rs/xid v1.3.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
-github.com/rs/zerolog v1.26.0 h1:ORM4ibhEZeTeQlCojCK2kPz1ogAY4bGs4tD+SaAdGaE=
+github.com/rs/zerolog v1.27.0 h1:1T7qCieN22GVc8S4Q2yuexzBb1EqjbgjSH9RohbMjKs=
-github.com/rs/zerolog v1.26.0/go.mod h1:yBiM87lvSqX8h0Ww4sdzNSkVYZ8dL2xjZJG1lAuGZEo=
+github.com/rs/zerolog v1.27.0/go.mod h1:7frBqO0oezxmnO7GF86FY++uy8I0Tk/If5ni1G9Qc0U=
 github.com/russross/blackfriday/v2 v2.0.1 h1:lPqVAte+HuHNfhJ/0LC98ESWRz8afy9tM/0RK8m9o+Q=
 github.com/russross/blackfriday/v2 v2.0.1/go.mod h1:+Rmxgy9KzJVeS9/2gXHxylqXiyQDYRxCVz55jmeOWTM=
 github.com/ryanuber/columnize v0.0.0-20160712163229-9b3edd62028f/go.mod h1:sm1tb6uqfes/u+d4ooFouqFdy9/2g9QGwK3SQygK0Ts=
@@ -510,7 +514,6 @@ github.com/xeipuuv/gojsonschema v1.2.0/go.mod h1:anYRn/JVcOK2ZgGU+IjEV4nwlhoK5sQ
 github.com/xiang90/probing v0.0.0-20190116061207-43a291ad63a2/go.mod h1:UETIi67q53MR2AWcXfiuqkDkRtnGDLqkBTpCHuJHxtU=
 github.com/yuin/goldmark v1.1.27/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9decYSb74=
 github.com/yuin/goldmark v1.2.1/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9decYSb74=
-github.com/yuin/goldmark v1.4.0/go.mod h1:mwnBkeHKe2W/ZEtQ+71ViKU8L12m81fl3OWwC1Zlc8k=
 go.etcd.io/bbolt v1.3.2/go.mod h1:IbVyRI1SCnLcuJnV2u8VeU0CEYM7e686BmAb1XKL+uU=
 go.opencensus.io v0.21.0/go.mod h1:mSImk1erAIZhrmZN+AvHh14ztQfjbGwt4TtuofqLduU=
 go.opencensus.io v0.22.0/go.mod h1:+kGneAE2xo2IficOXnaByMWTGM9T73dGwxeWcUqIpI8=
@@ -569,7 +572,6 @@ golang.org/x/mod v0.1.1-0.20191105210325-c90efee705ee/go.mod h1:QqPTAvyqsEbceGzB
 golang.org/x/mod v0.1.1-0.20191107180719-034126e5016b/go.mod h1:QqPTAvyqsEbceGzBzNggFXnrqF1CaUcvgkdR5Ot7KZg=
 golang.org/x/mod v0.2.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA=
 golang.org/x/mod v0.3.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA=
-golang.org/x/mod v0.4.2/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA=
 golang.org/x/net v0.0.0-20180724234803-3673e40ba225/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4=
 golang.org/x/net v0.0.0-20180826012351-8a410e7b638d/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4=
 golang.org/x/net v0.0.0-20180906233101-161cd47e91fd/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4=
@@ -668,8 +670,11 @@ golang.org/x/sys v0.0.0-20210303074136-134d130e1a04/go.mod h1:h1NjWce9XRLGQEsW7w
 golang.org/x/sys v0.0.0-20210423082822-04245dca01da/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20210514084401-e8d321eab015/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.0.0-20210630005230-0f9fa26af87c/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20210809222454-d867a43fc93e h1:WUoyKPm6nCo1BnNUvPGnFG3T5DUVem42yDJZZ4CNxMA=
 golang.org/x/sys v0.0.0-20210809222454-d867a43fc93e/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6 h1:foEbQz/B0Oz6YIqu/69kfXPYeFQAuuMYFkjaqXzl5Wo=
+golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/term v0.0.0-20201117132131-f5c789dd3221/go.mod h1:Nr5EML6q2oocZ2LXRh80K7BxOlk5/8JxuGnuhpl+muw=
 golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=
 golang.org/x/text v0.0.0-20170915032832-14c0d48ead0c/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
@@ -723,7 +728,6 @@ golang.org/x/tools v0.0.0-20200224181240-023911ca70b2/go.mod h1:TB2adYChydJhpapK
 golang.org/x/tools v0.0.0-20200304193943-95d2e580d8eb/go.mod h1:o4KQGtdN14AW+yjsvvwRTJJuXz8XRtIHtEnmAXLyFUw=
 golang.org/x/tools v0.0.0-20200410194907-79a7a3126eef/go.mod h1:EkVYQZoAsY45+roYkvgYkIh4xh/qjgUK9TdY2XT94GE=
 golang.org/x/tools v0.0.0-20201224043029-2b0845dc783e/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
-golang.org/x/tools v0.1.7/go.mod h1:LGqMHiF4EqQNHR1JncWGqT5BVaXmza+X+BDGol+dOxo=
 golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
 golang.org/x/xerrors v0.0.0-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
 golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=

integration/get_test.go

@@ -7,16 +7,16 @@ import (
 	"bytes"
 	"crypto/tls"
 	"io"
+	"log"
 	"net/http"
 	"net/http/cookiejar"
 	"testing"
 
-	"github.com/rs/zerolog/log"
 	"github.com/stretchr/testify/assert"
 )
 
 func TestGetRedirect(t *testing.T) {
-	log.Printf("=== TestGetRedirect ===\n")
+	log.Println("=== TestGetRedirect ===")
 	// test custom domain redirect
 	resp, err := getTestHTTPSClient().Get("https://calciumdibromid.localhost.mock.directory:4430")
 	assert.NoError(t, err)
@@ -28,7 +28,7 @@ func TestGetRedirect(t *testing.T) {
 }
 
 func TestGetContent(t *testing.T) {
-	log.Printf("=== TestGetContent ===\n")
+	log.Println("=== TestGetContent ===")
 	// test get image
 	resp, err := getTestHTTPSClient().Get("https://magiclike.localhost.mock.directory:4430/images/827679288a.jpg")
 	assert.NoError(t, err)
@@ -64,7 +64,7 @@ func TestGetContent(t *testing.T) {
 }
 
 func TestCustomDomain(t *testing.T) {
-	log.Printf("=== TestCustomDomain ===\n")
+	log.Println("=== TestCustomDomain ===")
 	resp, err := getTestHTTPSClient().Get("https://mock-pages.codeberg-test.org:4430/README.md")
 	assert.NoError(t, err)
 	if !assert.EqualValues(t, http.StatusOK, resp.StatusCode) {
@@ -76,7 +76,7 @@ func TestCustomDomain(t *testing.T) {
 }
 
 func TestGetNotFound(t *testing.T) {
-	log.Printf("=== TestGetNotFound ===\n")
+	log.Println("=== TestGetNotFound ===")
 	// test custom not found pages
 	resp, err := getTestHTTPSClient().Get("https://crystal.localhost.mock.directory:4430/pages-404-demo/blah")
 	assert.NoError(t, err)

integration/main_test.go

@@ -5,25 +5,25 @@ package integration
 
 import (
 	"context"
+	"log"
 	"os"
 	"testing"
 	"time"
 
 	"codeberg.org/codeberg/pages/cmd"
 
-	"github.com/rs/zerolog/log"
 	"github.com/urfave/cli/v2"
 )
 
 func TestMain(m *testing.M) {
-	log.Printf("=== TestMain: START Server ===\n")
+	log.Println("=== TestMain: START Server ===")
 	serverCtx, serverCancel := context.WithCancel(context.Background())
 	if err := startServer(serverCtx); err != nil {
-		log.Fatal().Msgf("could not start server: %v", err)
+		log.Fatalf("could not start server: %v", err)
 	}
 	defer func() {
 		serverCancel()
-		log.Printf("=== TestMain: Server STOPED ===\n")
+		log.Println("=== TestMain: Server STOPED ===")
 	}()
 
 	time.Sleep(10 * time.Second)
@@ -48,7 +48,7 @@ func startServer(ctx context.Context) error {
 
 	go func() {
 		if err := app.RunContext(ctx, args); err != nil {
-			log.Fatal().Msgf("run server error: %v", err)
+			log.Fatalf("run server error: %v", err)
 		}
 	}()
 

server/certificates/certificates.go

@@ -228,7 +228,7 @@ func retrieveCertFromDB(sni, mainDomainSuffix []byte, dnsProvider string, acmeUs
 				res.CSR = nil // acme client doesn't like CSR to be set
 				tlsCertificate, err = obtainCert(acmeClient, []string{string(sni)}, res, "", dnsProvider, mainDomainSuffix, acmeUseRateLimits, certDB)
 				if err != nil {
-					log.Printf("Couldn't renew certificate for %s: %s", sni, err)
+					log.Error().Msgf("Couldn't renew certificate for %s: %v", string(sni), err)
 				}
 			})()
 		}
@@ -271,10 +271,10 @@ func obtainCert(acmeClient *lego.Client, domains []string, renew *certificate.Re
 		if acmeUseRateLimits {
 			acmeClientRequestLimit.Take()
 		}
-		log.Printf("Renewing certificate for %v", domains)
+		log.Debug().Msgf("Renewing certificate for: %v", domains)
 		res, err = acmeClient.Certificate.Renew(*renew, true, false, "")
 		if err != nil {
-			log.Printf("Couldn't renew certificate for %v, trying to request a new one: %s", domains, err)
+			log.Error().Err(err).Msgf("Couldn't renew certificate for %v, trying to request a new one", domains)
 			res = nil
 		}
 	}
@@ -289,7 +289,7 @@ func obtainCert(acmeClient *lego.Client, domains []string, renew *certificate.Re
 			acmeClientOrderLimit.Take()
 			acmeClientRequestLimit.Take()
 		}
-		log.Printf("Requesting new certificate for %v", domains)
+		log.Debug().Msgf("Re-requesting new certificate for %v", domains)
 		res, err = acmeClient.Certificate.Obtain(certificate.ObtainRequest{
 			Domains:    domains,
 			Bundle:     true,
@@ -297,7 +297,7 @@ func obtainCert(acmeClient *lego.Client, domains []string, renew *certificate.Re
 		})
 	}
 	if err != nil {
-		log.Printf("Couldn't obtain certificate for %v: %s", domains, err)
+		log.Error().Err(err).Msgf("Couldn't obtain again a certificate or %v", domains)
 		if renew != nil && renew.CertURL != "" {
 			tlsCertificate, err := tls.X509KeyPair(renew.Certificate, renew.PrivateKey)
 			if err == nil && tlsCertificate.Leaf.NotAfter.After(time.Now()) {
@@ -311,7 +311,7 @@ func obtainCert(acmeClient *lego.Client, domains []string, renew *certificate.Re
 		}
 		return mockCert(domains[0], err.Error(), string(mainDomainSuffix), keyDatabase), err
 	}
-	log.Printf("Obtained certificate for %v", domains)
+	log.Debug().Msgf("Obtained certificate for %v", domains)
 
 	if err := keyDatabase.Put(name, res); err != nil {
 		return tls.Certificate{}, err
@@ -344,7 +344,7 @@ func SetupAcmeConfig(acmeAPI, acmeMail, acmeEabHmac, acmeEabKID string, acmeAcce
 		_, err := lego.NewClient(myAcmeConfig)
 		if err != nil {
 			// TODO: should we fail hard instead?
-			log.Printf("[ERROR] Can't create ACME client, continuing with mock certs only: %s", err)
+			log.Error().Err(err).Msg("Can't create ACME client, continuing with mock certs only")
 		}
 		return myAcmeConfig, nil
 	} else if !os.IsNotExist(err) {
@@ -365,13 +365,13 @@ func SetupAcmeConfig(acmeAPI, acmeMail, acmeEabHmac, acmeEabKID string, acmeAcce
 	myAcmeConfig.Certificate.KeyType = certcrypto.RSA2048
 	tempClient, err := lego.NewClient(myAcmeConfig)
 	if err != nil {
-		log.Printf("[ERROR] Can't create ACME client, continuing with mock certs only: %s", err)
+		log.Error().Err(err).Msg("Can't create ACME client, continuing with mock certs only")
 	} else {
 		// accept terms & log in to EAB
 		if acmeEabKID == "" || acmeEabHmac == "" {
 			reg, err := tempClient.Registration.Register(registration.RegisterOptions{TermsOfServiceAgreed: acmeAcceptTerms})
 			if err != nil {
-				log.Printf("[ERROR] Can't register ACME account, continuing with mock certs only: %s", err)
+				log.Error().Err(err).Msg("Can't register ACME account, continuing with mock certs only")
 			} else {
 				myAcmeAccount.Registration = reg
 			}
@@ -382,7 +382,7 @@ func SetupAcmeConfig(acmeAPI, acmeMail, acmeEabHmac, acmeEabKID string, acmeAcce
 				HmacEncoded:          acmeEabHmac,
 			})
 			if err != nil {
-				log.Printf("[ERROR] Can't register ACME account, continuing with mock certs only: %s", err)
+				log.Error().Err(err).Msg("Can't register ACME account, continuing with mock certs only")
 			} else {
 				myAcmeAccount.Registration = reg
 			}
@@ -391,12 +391,12 @@ func SetupAcmeConfig(acmeAPI, acmeMail, acmeEabHmac, acmeEabKID string, acmeAcce
 		if myAcmeAccount.Registration != nil {
 			acmeAccountJSON, err := json.Marshal(myAcmeAccount)
 			if err != nil {
-				log.Printf("[FAIL] Error during json.Marshal(myAcmeAccount), waiting for manual restart to avoid rate limits: %s", err)
+				log.Error().Err(err).Msg("json.Marshalfailed, waiting for manual restart to avoid rate limits")
 				select {}
 			}
 			err = os.WriteFile(configFile, acmeAccountJSON, 0o600)
 			if err != nil {
-				log.Printf("[FAIL] Error during os.WriteFile(\"acme-account.json\"), waiting for manual restart to avoid rate limits: %s", err)
+				log.Error().Err(err).Msg("os.WriteFile failed, waiting for manual restart to avoid rate limits")
 				select {}
 			}
 		}
@@ -414,38 +414,38 @@ func SetupCertificates(mainDomainSuffix []byte, dnsProvider string, acmeConfig *
 
 	acmeClient, err = lego.NewClient(acmeConfig)
 	if err != nil {
-		log.Printf("[ERROR] Can't create ACME client, continuing with mock certs only: %s", err)
+		log.Error().Err(err).Msg("Can't create ACME client, continuing with mock certs only")
 	} else {
 		err = acmeClient.Challenge.SetTLSALPN01Provider(AcmeTLSChallengeProvider{challengeCache})
 		if err != nil {
-			log.Printf("[ERROR] Can't create TLS-ALPN-01 provider: %s", err)
+			log.Error().Err(err).Msg("Can't create TLS-ALPN-01 provider")
 		}
 		if enableHTTPServer {
 			err = acmeClient.Challenge.SetHTTP01Provider(AcmeHTTPChallengeProvider{challengeCache})
 			if err != nil {
-				log.Printf("[ERROR] Can't create HTTP-01 provider: %s", err)
+				log.Error().Err(err).Msg("Can't create HTTP-01 provider")
 			}
 		}
 	}
 
 	mainDomainAcmeClient, err = lego.NewClient(acmeConfig)
 	if err != nil {
-		log.Printf("[ERROR] Can't create ACME client, continuing with mock certs only: %s", err)
+		log.Error().Err(err).Msg("Can't create ACME client, continuing with mock certs only")
 	} else {
 		if dnsProvider == "" {
 			// using mock server, don't use wildcard certs
 			err := mainDomainAcmeClient.Challenge.SetTLSALPN01Provider(AcmeTLSChallengeProvider{challengeCache})
 			if err != nil {
-				log.Printf("[ERROR] Can't create TLS-ALPN-01 provider: %s", err)
+				log.Error().Err(err).Msg("Can't create TLS-ALPN-01 provider")
 			}
 		} else {
 			provider, err := dns.NewDNSChallengeProviderByName(dnsProvider)
 			if err != nil {
-				log.Printf("[ERROR] Can't create DNS Challenge provider: %s", err)
+				log.Error().Err(err).Msg("Can't create DNS Challenge provider")
 			}
 			err = mainDomainAcmeClient.Challenge.SetDNS01Provider(provider)
 			if err != nil {
-				log.Printf("[ERROR] Can't create DNS-01 provider: %s", err)
+				log.Error().Err(err).Msg("Can't create DNS-01 provider")
 			}
 		}
 	}
@@ -453,7 +453,7 @@ func SetupCertificates(mainDomainSuffix []byte, dnsProvider string, acmeConfig *
 	if mainCertBytes == nil {
 		_, err = obtainCert(mainDomainAcmeClient, []string{"*" + string(mainDomainSuffix), string(mainDomainSuffix[1:])}, nil, "", dnsProvider, mainDomainSuffix, acmeUseRateLimits, certDB)
 		if err != nil {
-			log.Printf("[ERROR] Couldn't renew main domain certificate, continuing with mock certs only: %s", err)
+			log.Error().Err(err).Msg("Couldn't renew main domain certificate, continuing with mock certs only")
 		}
 	}
 
@@ -481,7 +481,7 @@ func MaintainCertDB(ctx context.Context, interval time.Duration, mainDomainSuffi
 				if err != nil || !tlsCertificates[0].NotAfter.After(now) {
 					err := certDB.Delete(string(key))
 					if err != nil {
-						log.Printf("[ERROR] Deleting expired certificate for %s failed: %s", string(key), err)
+						log.Error().Err(err).Msgf("Deleting expired certificate for %q failed", string(key))
 					} else {
 						expiredCertCount++
 					}
@@ -489,22 +489,22 @@ func MaintainCertDB(ctx context.Context, interval time.Duration, mainDomainSuffi
 			}
 			key, resBytes, err = keyDatabaseIterator.Next()
 		}
-		log.Printf("[INFO] Removed %d expired certificates from the database", expiredCertCount)
+		log.Debug().Msgf("Removed %d expired certificates from the database", expiredCertCount)
 
 		// compact the database
 		msg, err := certDB.Compact()
 		if err != nil {
-			log.Printf("[ERROR] Compacting key database failed: %s", err)
+			log.Error().Err(err).Msg("Compacting key database failed")
 		} else {
-			log.Printf("[INFO] Compacted key database (%s)", msg)
+			log.Debug().Msgf("Compacted key database: %s", msg)
 		}
 
 		// update main cert
 		res, err := certDB.Get(string(mainDomainSuffix))
 		if err != nil {
-			log.Err(err).Msgf("could not get cert for domain '%s'", mainDomainSuffix)
+			log.Error().Msgf("Couldn't get cert for domain %q", mainDomainSuffix)
 		} else if res == nil {
-			log.Error().Msgf("Couldn't renew certificate for main domain: %s", "expected main domain cert to exist, but it's missing - seems like the database is corrupted")
+			log.Error().Msgf("Couldn't renew certificate for main domain %q expected main domain cert to exist, but it's missing - seems like the database is corrupted", string(mainDomainSuffix))
 		} else {
 			tlsCertificates, err := certcrypto.ParsePEMBundle(res.Certificate)
 
@@ -513,7 +513,7 @@ func MaintainCertDB(ctx context.Context, interval time.Duration, mainDomainSuffi
 				go (func() {
 					_, err = obtainCert(mainDomainAcmeClient, []string{"*" + string(mainDomainSuffix), string(mainDomainSuffix[1:])}, res, "", dnsProvider, mainDomainSuffix, acmeUseRateLimits, certDB)
 					if err != nil {
-						log.Printf("[ERROR] Couldn't renew certificate for main domain: %s", err)
+						log.Error().Err(err).Msg("Couldn't renew certificate for main domain")
 					}
 				})()
 			}

server/database/setup.go

@@ -72,7 +72,7 @@ func (p aDB) sync() {
 	for {
 		err := p.intern.Sync()
 		if err != nil {
-			log.Err(err).Msg("Syncing cert database failed")
+			log.Error().Err(err).Msg("Syncing cert database failed")
 		}
 		select {
 		case <-p.ctx.Done():

server/handler.go

@@ -85,7 +85,7 @@ func Handler(mainDomainSuffix, rawDomain []byte,
 		// also disallow search indexing and add a Link header to the canonical URL.
 		tryBranch := func(log zerolog.Logger, repo, branch string, path []string, canonicalLink string) bool {
 			if repo == "" {
-				log.Debug().Msg("tryBranch: repo == ''")
+				log.Debug().Msg("tryBranch: repo is empty")
 				return false
 			}
 
@@ -120,10 +120,10 @@ func Handler(mainDomainSuffix, rawDomain []byte,
 			return true
 		}
 
-		log.Debug().Msg("preparations")
+		log.Debug().Msg("Preparing")
 		if rawDomain != nil && bytes.Equal(trimmedHost, rawDomain) {
 			// Serve raw content from RawDomain
-			log.Debug().Msg("raw domain")
+			log.Debug().Msg("Serving raw domain")
 
 			targetOptions.TryIndexPages = false
 			if targetOptions.ForbiddenMimeTypes == nil {
@@ -143,28 +143,28 @@ func Handler(mainDomainSuffix, rawDomain []byte,
 
 			// raw.codeberg.org/example/myrepo/@main/index.html
 			if len(pathElements) > 2 && strings.HasPrefix(pathElements[2], "@") {
-				log.Debug().Msg("raw domain preparations, now trying with specified branch")
+				log.Debug().Msg("Preparing raw domain, now trying with specified branch")
 				if tryBranch(log,
 					targetRepo, pathElements[2][1:], pathElements[3:],
 					giteaRoot+"/"+targetOwner+"/"+targetRepo+"/src/branch/%b/%p",
 				) {
-					log.Debug().Msg("tryBranch, now trying upstream 1")
+					log.Info().Msg("tryBranch, now trying upstream 1")
 					tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost,
 						targetOptions, targetOwner, targetRepo, targetBranch, targetPath,
 						canonicalDomainCache, branchTimestampCache, fileResponseCache)
 					return
 				}
-				log.Debug().Msg("missing branch")
+				log.Warn().Msg("Path missed a branch")
 				html.ReturnErrorPage(ctx, fasthttp.StatusFailedDependency)
 				return
 			}
 
-			log.Debug().Msg("raw domain preparations, now trying with default branch")
+			log.Debug().Msg("Preparing raw domain, now trying with default branch")
 			tryBranch(log,
 				targetRepo, "", pathElements[2:],
 				giteaRoot+"/"+targetOwner+"/"+targetRepo+"/src/branch/%b/%p",
 			)
-			log.Debug().Msg("tryBranch, now trying upstream 2")
+			log.Info().Msg("tryBranch, now trying upstream 2")
 			tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost,
 				targetOptions, targetOwner, targetRepo, targetBranch, targetPath,
 				canonicalDomainCache, branchTimestampCache, fileResponseCache)
@@ -172,7 +172,7 @@ func Handler(mainDomainSuffix, rawDomain []byte,
 
 		} else if bytes.HasSuffix(trimmedHost, mainDomainSuffix) {
 			// Serve pages from subdomains of MainDomainSuffix
-			log.Debug().Msg("main domain suffix")
+			log.Info().Msg("Serve pages from main domain suffix")
 
 			pathElements := strings.Split(string(bytes.Trim(ctx.Request.URI().Path(), "/")), "/")
 			targetOwner = string(bytes.TrimSuffix(trimmedHost, mainDomainSuffix))
@@ -194,16 +194,17 @@ func Handler(mainDomainSuffix, rawDomain []byte,
 					return
 				}
 
-				log.Debug().Msg("main domain preparations, now trying with specified repo & branch")
+				log.Debug().Msg("Preparing main domain, now trying with specified repo & branch")
 				if tryBranch(log,
 					pathElements[0], pathElements[1][1:], pathElements[2:],
 					"/"+pathElements[0]+"/%p",
 				) {
-					log.Debug().Msg("tryBranch, now trying upstream 3")
+					log.Info().Msg("tryBranch, now trying upstream 3")
 					tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost,
 						targetOptions, targetOwner, targetRepo, targetBranch, targetPath,
 						canonicalDomainCache, branchTimestampCache, fileResponseCache)
 				} else {
+					log.Warn().Msg("tryBranch: upstream 3 failed")
 					html.ReturnErrorPage(ctx, fasthttp.StatusFailedDependency)
 				}
 				return
@@ -212,14 +213,15 @@ func Handler(mainDomainSuffix, rawDomain []byte,
 			// Check if the first directory is a branch for the "pages" repo
 			// example.codeberg.page/@main/index.html
 			if strings.HasPrefix(pathElements[0], "@") {
-				log.Debug().Msg("main domain preparations, now trying with specified branch")
+				log.Debug().Msg("Preparing main domain, now trying with specified branch")
 				if tryBranch(log,
 					"pages", pathElements[0][1:], pathElements[1:], "/%p") {
-					log.Debug().Msg("tryBranch, now trying upstream 4")
+					log.Info().Msg("tryBranch, now trying upstream 4")
 					tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost,
 						targetOptions, targetOwner, targetRepo, targetBranch, targetPath,
 						canonicalDomainCache, branchTimestampCache, fileResponseCache)
 				} else {
+					log.Warn().Msg("tryBranch: upstream 4 failed")
 					html.ReturnErrorPage(ctx, fasthttp.StatusFailedDependency)
 				}
 				return
@@ -231,7 +233,7 @@ func Handler(mainDomainSuffix, rawDomain []byte,
 			log.Debug().Msg("main domain preparations, now trying with specified repo")
 			if pathElements[0] != "pages" && tryBranch(log,
 				pathElements[0], "pages", pathElements[1:], "") {
-				log.Debug().Msg("tryBranch, now trying upstream 5")
+				log.Info().Msg("tryBranch, now trying upstream 5")
 				tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost,
 					targetOptions, targetOwner, targetRepo, targetBranch, targetPath,
 					canonicalDomainCache, branchTimestampCache, fileResponseCache)
@@ -243,7 +245,7 @@ func Handler(mainDomainSuffix, rawDomain []byte,
 			log.Debug().Msg("main domain preparations, now trying with default repo/branch")
 			if tryBranch(log,
 				"pages", "", pathElements, "") {
-				log.Debug().Msg("tryBranch, now trying upstream 6")
+				log.Info().Msg("tryBranch, now trying upstream 6")
 				tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost,
 					targetOptions, targetOwner, targetRepo, targetBranch, targetPath,
 					canonicalDomainCache, branchTimestampCache, fileResponseCache)
@@ -251,6 +253,7 @@ func Handler(mainDomainSuffix, rawDomain []byte,
 			}
 
 			// Couldn't find a valid repo/branch
+
 			html.ReturnErrorPage(ctx, fasthttp.StatusFailedDependency)
 			return
 		} else {
@@ -272,11 +275,12 @@ func Handler(mainDomainSuffix, rawDomain []byte,
 			}
 
 			// Try to use the given repo on the given branch or the default branch
-			log.Debug().Msg("custom domain preparations, now trying with details from DNS")
+			log.Debug().Msg("Preparing custom domain, now trying with details from DNS")
 			if tryBranch(log,
 				targetRepo, targetBranch, pathElements, canonicalLink) {
 				canonicalDomain, valid := upstream.CheckCanonicalDomain(giteaClient, targetOwner, targetRepo, targetBranch, trimmedHostStr, string(mainDomainSuffix), canonicalDomainCache)
 				if !valid {
+					log.Warn().Msg("Custom domains, domain from DNS isn't valid/canonical")
 					html.ReturnErrorPage(ctx, fasthttp.StatusMisdirectedRequest)
 					return
 				} else if canonicalDomain != trimmedHostStr {
@@ -287,17 +291,19 @@ func Handler(mainDomainSuffix, rawDomain []byte,
 						return
 					}
 
+					log.Warn().Msg("Custom domains, targetOwner from DNS is empty")
 					html.ReturnErrorPage(ctx, fasthttp.StatusFailedDependency)
 					return
 				}
 
-				log.Debug().Msg("tryBranch, now trying upstream 7")
+				log.Info().Msg("tryBranch, now trying upstream 7 %s")
 				tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost,
 					targetOptions, targetOwner, targetRepo, targetBranch, targetPath,
 					canonicalDomainCache, branchTimestampCache, fileResponseCache)
 				return
 			}
 
+			log.Warn().Msg("Couldn't handle request, none of the options succeed")
 			html.ReturnErrorPage(ctx, fasthttp.StatusFailedDependency)
 			return
 		}

server/setup.go

@@ -2,11 +2,11 @@ package server
 
 import (
 	"bytes"
+	"fmt"
 	"net/http"
 	"time"
 
 	"github.com/rs/zerolog/log"
-
 	"github.com/valyala/fasthttp"
 
 	"codeberg.org/codeberg/pages/server/cache"
@@ -16,7 +16,7 @@ import (
 type fasthttpLogger struct{}
 
 func (fasthttpLogger) Printf(format string, args ...interface{}) {
-	log.Printf("[FASTHTTP] "+format, args...)
+	log.Printf("FastHTTP: %s", fmt.Sprintf(format, args...))
 }
 
 func SetupServer(handler fasthttp.RequestHandler) *fasthttp.Server {

server/try.go

@@ -41,6 +41,7 @@ func tryUpstream(ctx *fasthttp.RequestCtx, giteaClient *gitea.Client,
 	targetOptions.TargetRepo = targetRepo
 	targetOptions.TargetBranch = targetBranch
 	targetOptions.TargetPath = targetPath
+	targetOptions.Host = string(trimmedHost)
 
 	// Try to request the file from the Gitea API
 	if !targetOptions.Upstream(ctx, giteaClient, branchTimestampCache, fileResponseCache) {

server/upstream/upstream.go

@@ -3,7 +3,6 @@ package upstream
 import (
 	"bytes"
 	"errors"
-	"fmt"
 	"io"
 	"strings"
 	"time"
@@ -33,6 +32,9 @@ type Options struct {
 	TargetBranch,
 	TargetPath,
 
+	// Used for debugging purposes.
+	Host string
+
 	DefaultMimeType    string
 	ForbiddenMimeTypes map[string]bool
 	TryIndexPages      bool
@@ -44,7 +46,7 @@ type Options struct {
 
 // Upstream requests a file from the Gitea API at GiteaRoot and writes it to the request context.
 func (o *Options) Upstream(ctx *fasthttp.RequestCtx, giteaClient *gitea.Client, branchTimestampCache, fileResponseCache cache.SetGetKey) (final bool) {
-	log := log.With().Strs("upstream", []string{o.TargetOwner, o.TargetRepo, o.TargetBranch, o.TargetPath}).Logger()
+	log := log.With().Strs("upstream", []string{o.TargetOwner, o.TargetRepo, o.TargetBranch, o.TargetPath, o.Host}).Logger()
 
 	// Check if the branch exists and when it was modified
 	if o.BranchTimestamp.IsZero() {
@@ -70,7 +72,8 @@ func (o *Options) Upstream(ctx *fasthttp.RequestCtx, giteaClient *gitea.Client,
 			return true
 		}
 	}
-	log.Debug().Msg("preparations")
+
+	log.Debug().Msg("Preparing")
 
 	// Make a GET request to the upstream URL
 	uri := o.generateUri()
@@ -82,7 +85,7 @@ func (o *Options) Upstream(ctx *fasthttp.RequestCtx, giteaClient *gitea.Client,
 	} else {
 		res, err = giteaClient.ServeRawContent(uri)
 	}
-	log.Debug().Msg("acquisition")
+	log.Debug().Msg("Aquisting")
 
 	// Handle errors
 	if (err != nil && errors.Is(err, gitea.ErrorNotFound)) || (res == nil && !cachedResponse.Exists) {
@@ -136,7 +139,7 @@ func (o *Options) Upstream(ctx *fasthttp.RequestCtx, giteaClient *gitea.Client,
 		return false
 	}
 	if res != nil && (err != nil || res.StatusCode() != fasthttp.StatusOK) {
-		fmt.Printf("Couldn't fetch contents from \"%s\": %s (status code %d)\n", uri, err, res.StatusCode())
+		log.Warn().Msgf("Couldn't fetch contents from %q: %v (status code %d)", uri, err, res.StatusCode())
 		html.ReturnErrorPage(ctx, fasthttp.StatusInternalServerError)
 		return true
 	}
@@ -155,7 +158,7 @@ func (o *Options) Upstream(ctx *fasthttp.RequestCtx, giteaClient *gitea.Client,
 		ctx.Redirect(o.redirectIfExists, fasthttp.StatusTemporaryRedirect)
 		return true
 	}
-	log.Debug().Msg("error handling")
+	log.Debug().Msg("Handling error")
 
 	// Set the MIME type
 	mimeType := o.getMimeTypeByExtension()
@@ -175,7 +178,7 @@ func (o *Options) Upstream(ctx *fasthttp.RequestCtx, giteaClient *gitea.Client,
 	}
 	ctx.Response.Header.SetLastModified(o.BranchTimestamp)
 
-	log.Debug().Msg("response preparations")
+	log.Debug().Msg("Prepare response")
 
 	// Write the response body to the original request
 	var cacheBodyWriter bytes.Buffer
@@ -193,11 +196,11 @@ func (o *Options) Upstream(ctx *fasthttp.RequestCtx, giteaClient *gitea.Client,
 		_, err = ctx.Write(cachedResponse.Body)
 	}
 	if err != nil {
-		fmt.Printf("Couldn't write body for \"%s\": %s\n", uri, err)
+		log.Error().Err(err).Msgf("Couldn't write body for %q", uri)
 		html.ReturnErrorPage(ctx, fasthttp.StatusInternalServerError)
 		return true
 	}
-	log.Debug().Msg("response")
+	log.Debug().Msg("Sending response")
 
 	if res != nil && res.Header.ContentLength() <= fileCacheSizeLimit && ctx.Err() == nil {
 		cachedResponse.Exists = true