Improve logging

- 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)
- Remove zerologger and instead use custom logger that doesn't log
JSON (directly inspired by https://codeberg.org/Codeberg/moderation/pulls/7).
- Add more information to existing fields(e.g. the host that the user is
visiting, this was noted by @fnetX).
This commit is contained in:
Gusted 2022-07-24 06:22:52 +02:00
parent 00e8a41c89
commit 1e183d7249
No known key found for this signature in database
GPG key ID: FD821B732837125F
13 changed files with 318 additions and 110 deletions

View file

@ -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,24 @@ var ServeFlags = []cli.Flag{
// TODO: desc
EnvVars: []string{"ENABLE_HTTP_SERVER"},
},
&cli.StringSliceFlag{
Name: "log-output",
Value: cli.NewStringSlice("console"),
Usage: "specify where the log will be outputed. Multiple options can be chosen, possible options: console, file",
EnvVars: []string{"LOG_OUTPUT"},
},
&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"},
},
&cli.StringFlag{
Name: "log-file",
Value: "pages-server.log",
Usage: "specify the log file. Only applies when file logging is enabled",
EnvVars: []string{"LOG_FILE"},
},
// ACME
&cli.StringFlag{

View file

@ -10,8 +10,6 @@ import (
"strings"
"time"
"github.com/rs/zerolog"
"github.com/rs/zerolog/log"
"github.com/urfave/cli/v2"
"codeberg.org/codeberg/pages/server"
@ -19,6 +17,7 @@ import (
"codeberg.org/codeberg/pages/server/certificates"
"codeberg.org/codeberg/pages/server/database"
"codeberg.org/codeberg/pages/server/gitea"
"codeberg.org/codeberg/pages/server/log"
)
// AllowedCorsDomains lists the domains for which Cross-Origin Resource Sharing is allowed.
@ -36,9 +35,10 @@ var BlacklistedPaths = [][]byte{
// Serve sets up and starts the web server.
func Serve(ctx *cli.Context) error {
verbose := ctx.Bool("verbose")
if !verbose {
zerolog.SetGlobalLevel(zerolog.InfoLevel)
// Initalize the logger.
err := log.Config(ctx.StringSlice("log-output"), ctx.String("log-file"), ctx.String("log-level"))
if err != nil {
log.Fatal("Couldn't set configure logging: %v", err)
}
giteaRoot := strings.TrimSuffix(ctx.String("gitea-root"), "/")
@ -98,10 +98,10 @@ func Serve(ctx *cli.Context) error {
httpServer := server.SetupHTTPACMEChallengeServer(challengeCache)
// Setup listener and TLS
log.Info().Msgf("Listening on https://%s", listeningAddress)
log.Info("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,19 +134,19 @@ func Serve(ctx *cli.Context) error {
if enableHTTPServer {
go func() {
log.Info().Timestamp().Msg("Start listening on :80")
log.Info("Start HTTP server listening on :80")
err := httpServer.ListenAndServe("[::]:80")
if err != nil {
log.Panic().Err(err).Msg("Couldn't start HTTP fastServer")
log.Fatal("Couldn't start HTTP fastServer: %v", err)
}
}()
}
// Start the web fastServer
log.Info().Timestamp().Msgf("Start listening on %s", listener.Addr())
log.Info("Start listening on %s", listener.Addr())
err = fastServer.Serve(listener)
if err != nil {
log.Panic().Err(err).Msg("Couldn't start fastServer")
log.Fatal("Couldn't start fastServer: %v", err)
}
return nil

3
go.mod
View file

@ -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

8
go.sum
View file

@ -95,7 +95,6 @@ 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/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=
@ -150,7 +149,6 @@ github.com/go-stack/stack v1.8.0/go.mod h1:v0f6uXyyMGvRgIKkXu+yp6POWl0qKG85gN/me
github.com/go-task/slim-sprig v0.0.0-20210107165309-348f09dbbbc0/go.mod h1:fyg7847qk6SyHyPtNmDHnmrv/HOrqktSC+C9fM+CJOE=
github.com/gobs/pretty v0.0.0-20180724170744-09732c25a95b h1:/vQ+oYKu+JoyaMPDsv5FzwuL2wwWBgBbtj/YLCi4LuA=
github.com/gobs/pretty v0.0.0-20180724170744-09732c25a95b/go.mod h1:Xo4aNUOrJnVruqWQJBtW6+bTBDTniY8yZum5rF3b5jw=
github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA=
github.com/gofrs/uuid v3.2.0+incompatible h1:y12jRkkFxsd7GpqdSZ+/KCs/fJbqpEXSGd4+jfEaewE=
github.com/gofrs/uuid v3.2.0+incompatible/go.mod h1:b2aQJv3Z4Fp6yNu3cdSllBxTCLRxnplIgP/c0N/04lM=
github.com/gogo/protobuf v1.1.1/go.mod h1:r8qH/GZQm5c6nD/R0oafs1akxWv10x8SbQlK7atdtwQ=
@ -427,9 +425,6 @@ github.com/reugn/equalizer v0.0.0-20210216135016-a959c509d7ad h1:WtSUHi5zthjudjI
github.com/reugn/equalizer v0.0.0-20210216135016-a959c509d7ad/go.mod h1:h0+DiDRe2Y+6iHTjIq/9HzUq7NII/Nffp0HkFrsAKq4=
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.26.0/go.mod h1:yBiM87lvSqX8h0Ww4sdzNSkVYZ8dL2xjZJG1lAuGZEo=
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 +505,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 +563,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=
@ -723,7 +716,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=

View file

@ -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)

View file

@ -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)
}
defer func() {
serverCancel()
log.Printf("=== TestMain: Server STOPED ===\n")
log.Println("=== TestMain: Server STOPED ===")
}()
time.Sleep(10 * time.Second)

View file

@ -27,12 +27,12 @@ import (
"github.com/go-acme/lego/v4/providers/dns"
"github.com/go-acme/lego/v4/registration"
"github.com/reugn/equalizer"
"github.com/rs/zerolog/log"
"codeberg.org/codeberg/pages/server/cache"
"codeberg.org/codeberg/pages/server/database"
dnsutils "codeberg.org/codeberg/pages/server/dns"
"codeberg.org/codeberg/pages/server/gitea"
"codeberg.org/codeberg/pages/server/log"
"codeberg.org/codeberg/pages/server/upstream"
)
@ -229,7 +229,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("Couldn't renew certificate for %s: %v", string(sni), err)
}
})()
}
@ -272,10 +272,10 @@ func obtainCert(acmeClient *lego.Client, domains []string, renew *certificate.Re
if acmeUseRateLimits {
acmeClientRequestLimit.Take()
}
log.Printf("Renewing certificate for %v", domains)
log.Debug("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("Couldn't renew certificate for %v, trying to request a new one: %v", domains, err)
res = nil
}
}
@ -290,7 +290,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("Re-requesting new certificate for %v", domains)
res, err = acmeClient.Certificate.Obtain(certificate.ObtainRequest{
Domains: domains,
Bundle: true,
@ -298,7 +298,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("Couldn't obtain again a certificate or %v: %v", domains, err)
if renew != nil && renew.CertURL != "" {
tlsCertificate, err := tls.X509KeyPair(renew.Certificate, renew.PrivateKey)
if err == nil && tlsCertificate.Leaf.NotAfter.After(time.Now()) {
@ -312,7 +312,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("Obtained certificate for %v", domains)
if err := keyDatabase.Put(name, res); err != nil {
return tls.Certificate{}, err
@ -345,7 +345,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("Can't create ACME client, continuing with mock certs only: %v", err)
}
return myAcmeConfig, nil
} else if !os.IsNotExist(err) {
@ -366,13 +366,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("Can't create ACME client, continuing with mock certs only: %v", err)
} 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("Can't register ACME account, continuing with mock certs only: %v", err)
} else {
myAcmeAccount.Registration = reg
}
@ -383,7 +383,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("Can't register ACME account, continuing with mock certs only: %v", err)
} else {
myAcmeAccount.Registration = reg
}
@ -392,12 +392,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("json.Marshalfailed, waiting for manual restart to avoid rate limits: %v", err)
select {}
}
err = ioutil.WriteFile(configFile, acmeAccountJSON, 0o600)
err = os.WriteFile(configFile, acmeAccountJSON, 0o600)
if err != nil {
log.Printf("[FAIL] Error during ioutil.WriteFile(\"acme-account.json\"), waiting for manual restart to avoid rate limits: %s", err)
log.Error("os.WriteFile failed, waiting for manual restart to avoid rate limits: %s", err)
select {}
}
}
@ -415,38 +415,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("Can't create ACME client, continuing with mock certs only: %v", err)
} else {
err = acmeClient.Challenge.SetTLSALPN01Provider(AcmeTLSChallengeProvider{challengeCache})
if err != nil {
log.Printf("[ERROR] Can't create TLS-ALPN-01 provider: %s", err)
log.Error("Can't create TLS-ALPN-01 provider: %v", err)
}
if enableHTTPServer {
err = acmeClient.Challenge.SetHTTP01Provider(AcmeHTTPChallengeProvider{challengeCache})
if err != nil {
log.Printf("[ERROR] Can't create HTTP-01 provider: %s", err)
log.Error("Can't create HTTP-01 provider: %v", err)
}
}
}
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("Can't create ACME client, continuing with mock certs only: %v", err)
} 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("Can't create TLS-ALPN-01 provider: %v", err)
}
} else {
provider, err := dns.NewDNSChallengeProviderByName(dnsProvider)
if err != nil {
log.Printf("[ERROR] Can't create DNS Challenge provider: %s", err)
log.Error("Can't create DNS Challenge provider: %v", err)
}
err = mainDomainAcmeClient.Challenge.SetDNS01Provider(provider)
if err != nil {
log.Printf("[ERROR] Can't create DNS-01 provider: %s", err)
log.Error("Can't create DNS-01 provider: %v", err)
}
}
}
@ -454,7 +454,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("Couldn't renew main domain certificate, continuing with mock certs only: %v", err)
}
}
@ -482,7 +482,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("Deleting expired certificate for %q failed: %v", string(key), err)
} else {
expiredCertCount++
}
@ -490,22 +490,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("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("Compacting key database failed: %v", err)
} else {
log.Printf("[INFO] Compacted key database (%s)", msg)
log.Debug("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("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("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)
@ -514,7 +514,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("Couldn't renew certificate for main domain: %v", err)
}
})()
}

View file

@ -7,10 +7,10 @@ import (
"fmt"
"time"
"codeberg.org/codeberg/pages/server/log"
"github.com/akrylysov/pogreb"
"github.com/akrylysov/pogreb/fs"
"github.com/go-acme/lego/v4/certificate"
"github.com/rs/zerolog/log"
)
var _ CertDB = aDB{}
@ -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("Syncing cert database failed: %v", err)
}
select {
case <-p.ctx.Done():

View file

@ -2,16 +2,16 @@ package server
import (
"bytes"
"fmt"
"strings"
"github.com/rs/zerolog"
"github.com/rs/zerolog/log"
"github.com/valyala/fasthttp"
"codeberg.org/codeberg/pages/html"
"codeberg.org/codeberg/pages/server/cache"
"codeberg.org/codeberg/pages/server/dns"
"codeberg.org/codeberg/pages/server/gitea"
"codeberg.org/codeberg/pages/server/log"
"codeberg.org/codeberg/pages/server/upstream"
"codeberg.org/codeberg/pages/server/utils"
"codeberg.org/codeberg/pages/server/version"
@ -25,7 +25,7 @@ func Handler(mainDomainSuffix, rawDomain []byte,
dnsLookupCache, canonicalDomainCache, branchTimestampCache, fileResponseCache cache.SetGetKey,
) func(ctx *fasthttp.RequestCtx) {
return func(ctx *fasthttp.RequestCtx) {
log := log.With().Str("Handler", string(ctx.Request.Header.RequestURI())).Logger()
logInfo := fmt.Sprintf("[handler=%q]", string(ctx.Request.Header.RequestURI()))
ctx.Response.Header.Set("Server", "CodebergPages/"+version.Version)
@ -83,9 +83,9 @@ func Handler(mainDomainSuffix, rawDomain []byte,
// tryBranch checks if a branch exists and populates the target variables. If canonicalLink is non-empty, it will
// 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 {
tryBranch := func(logInfo string, repo, branch string, path []string, canonicalLink string) bool {
if repo == "" {
log.Debug().Msg("tryBranch: repo == ''")
log.Debug("tryBranch%s: repo is empty", logInfo)
return false
}
@ -96,7 +96,7 @@ func Handler(mainDomainSuffix, rawDomain []byte,
// Check if the branch exists, otherwise treat it as a file path
branchTimestampResult := upstream.GetBranchTimestamp(giteaClient, targetOwner, repo, branch, branchTimestampCache)
if branchTimestampResult == nil {
log.Debug().Msg("tryBranch: branch doesn't exist")
log.Debug("tryBranch%s: branch doesn't exist", logInfo)
return false
}
@ -116,14 +116,14 @@ func Handler(mainDomainSuffix, rawDomain []byte,
)
}
log.Debug().Msg("tryBranch: true")
log.Debug("tryBranch%s: true", logInfo)
return true
}
log.Debug().Msg("preparations")
log.Debug("Preparing %s", logInfo)
if rawDomain != nil && bytes.Equal(trimmedHost, rawDomain) {
// Serve raw content from RawDomain
log.Debug().Msg("raw domain")
log.Debug("Serving raw domain %s", logInfo)
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")
if tryBranch(log,
log.Debug("Preparing raw domain, now trying with specified branch %s", logInfo)
if tryBranch(logInfo,
targetRepo, pathElements[2][1:], pathElements[3:],
giteaRoot+"/"+targetOwner+"/"+targetRepo+"/src/branch/%b/%p",
) {
log.Debug().Msg("tryBranch, now trying upstream 1")
log.Info("tryBranch, now trying upstream 1 %s", logInfo)
tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost,
targetOptions, targetOwner, targetRepo, targetBranch, targetPath,
canonicalDomainCache, branchTimestampCache, fileResponseCache)
return
}
log.Debug().Msg("missing branch")
log.Warn("Path missed a branch %s", logInfo)
html.ReturnErrorPage(ctx, fasthttp.StatusFailedDependency)
return
}
log.Debug().Msg("raw domain preparations, now trying with default branch")
tryBranch(log,
log.Debug("Preparing raw domain, now trying with default branch %s", logInfo)
tryBranch(logInfo,
targetRepo, "", pathElements[2:],
giteaRoot+"/"+targetOwner+"/"+targetRepo+"/src/branch/%b/%p",
)
log.Debug().Msg("tryBranch, now trying upstream 2")
log.Info("tryBranch, now trying upstream 2 %s", logInfo)
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.Debug("Serve pages from main domain suffix %s", logInfo)
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")
if tryBranch(log,
log.Debug("Preparing main domain, now trying with specified repo & branch, %s", logInfo)
if tryBranch(logInfo,
pathElements[0], pathElements[1][1:], pathElements[2:],
"/"+pathElements[0]+"/%p",
) {
log.Debug().Msg("tryBranch, now trying upstream 3")
log.Info("tryBranch, now trying upstream 3 %s", logInfo)
tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost,
targetOptions, targetOwner, targetRepo, targetBranch, targetPath,
canonicalDomainCache, branchTimestampCache, fileResponseCache)
} else {
log.Warn("tryBranch%s: upstream 3 failed", logInfo)
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")
if tryBranch(log,
log.Debug("Preparing main domain, now trying with specified branch %s", logInfo)
if tryBranch(logInfo,
"pages", pathElements[0][1:], pathElements[1:], "/%p") {
log.Debug().Msg("tryBranch, now trying upstream 4")
log.Info("tryBranch, now trying upstream 4 %s", logInfo)
tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost,
targetOptions, targetOwner, targetRepo, targetBranch, targetPath,
canonicalDomainCache, branchTimestampCache, fileResponseCache)
} else {
log.Warn("tryBranch%s: upstream 4 failed", logInfo)
html.ReturnErrorPage(ctx, fasthttp.StatusFailedDependency)
}
return
@ -228,10 +230,10 @@ func Handler(mainDomainSuffix, rawDomain []byte,
// Check if the first directory is a repo with a "pages" branch
// example.codeberg.page/myrepo/index.html
// example.codeberg.page/pages/... is not allowed here.
log.Debug().Msg("main domain preparations, now trying with specified repo")
if pathElements[0] != "pages" && tryBranch(log,
log.Debug("main domain preparations, now trying with specified repo %s", logInfo)
if pathElements[0] != "pages" && tryBranch(logInfo,
pathElements[0], "pages", pathElements[1:], "") {
log.Debug().Msg("tryBranch, now trying upstream 5")
log.Info("tryBranch, now trying upstream 5 %s", logInfo)
tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost,
targetOptions, targetOwner, targetRepo, targetBranch, targetPath,
canonicalDomainCache, branchTimestampCache, fileResponseCache)
@ -240,10 +242,10 @@ func Handler(mainDomainSuffix, rawDomain []byte,
// Try to use the "pages" repo on its default branch
// example.codeberg.page/index.html
log.Debug().Msg("main domain preparations, now trying with default repo/branch")
if tryBranch(log,
log.Debug("main domain preparations, now trying with default repo/branch %s", logInfo)
if tryBranch(logInfo,
"pages", "", pathElements, "") {
log.Debug().Msg("tryBranch, now trying upstream 6")
log.Info("tryBranch, now trying upstream 6 %s", logInfo)
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")
if tryBranch(log,
log.Debug("Preparing custom domain, now trying with details from DNS %s", logInfo)
if tryBranch(logInfo,
targetRepo, targetBranch, pathElements, canonicalLink) {
canonicalDomain, valid := upstream.CheckCanonicalDomain(giteaClient, targetOwner, targetRepo, targetBranch, trimmedHostStr, string(mainDomainSuffix), canonicalDomainCache)
if !valid {
log.Warn("Custom domains, domain from DNS isn't valid/canonical %s", logInfo)
html.ReturnErrorPage(ctx, fasthttp.StatusMisdirectedRequest)
return
} else if canonicalDomain != trimmedHostStr {
@ -287,17 +291,19 @@ func Handler(mainDomainSuffix, rawDomain []byte,
return
}
log.Warn("Custom domains, targetOwner from DNS is empty", logInfo)
html.ReturnErrorPage(ctx, fasthttp.StatusFailedDependency)
return
}
log.Debug().Msg("tryBranch, now trying upstream 7")
log.Info("tryBranch, now trying upstream 7 %s", logInfo)
tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost,
targetOptions, targetOwner, targetRepo, targetBranch, targetPath,
canonicalDomainCache, branchTimestampCache, fileResponseCache)
return
}
log.Warn("Couldn't handle request, none of the options succeed %q", logInfo)
html.ReturnErrorPage(ctx, fasthttp.StatusFailedDependency)
return
}

194
server/log/log.go Normal file
View file

@ -0,0 +1,194 @@
package log
import (
"errors"
"fmt"
"io"
stdLog "log"
"os"
"runtime"
"strings"
"time"
)
var (
// logger is the variable to which the code can write its output.
logger *stdLog.Logger
// The current absolute path to backend/ is stored in filePrefix; this is
// removed from the filename because the logging doesn't require any of the other junk.
filePrefix string
// logLevel is the variable that decides at which log level the logger will output
// to the logger.
logLevel LogLevel
)
type LogLevel uint8
const (
DebugLevel LogLevel = iota
InfoLevel
WarnLevel
ErrorLevel
FatalLevel
)
func init() {
// Make sure that logger is always initalized, this is to still be able to use the logger
// even when logger isn't yet initilazed with the correct values.
initializeLogger(os.Stdout)
// A quick and dirty way to get the backend/ absolute folder
_, filename, _, _ := runtime.Caller(0)
filePrefix = strings.TrimSuffix(filename, "server/log/log.go")
if filePrefix == filename {
// in case the source code file is moved, we can not trim the suffix, the code above should also be updated.
panic("unable to detect correct package prefix, please update file: " + filename)
}
}
// initializeLogger takes a input of multiple writers, which to all writers will be logged to.
func initializeLogger(w ...io.Writer) {
logger = stdLog.New(io.MultiWriter(w...), "", 0)
}
func stringToLogLevel(input string) (LogLevel, error) {
switch strings.ToLower(input) {
case "fatal":
return FatalLevel, nil
case "error":
return ErrorLevel, nil
case "warn":
return WarnLevel, nil
case "info":
return InfoLevel, nil
}
return FatalLevel, errors.New("invalid log level value")
}
// Config takes the ini config and correctly adjust the logger variable.
func Config(outputs []string, outputFile, level string) error {
newLogLevel, err := stringToLogLevel(level)
if err != nil {
return err
}
logLevel = newLogLevel
isFileLog := false
isConsoleLog := false
for _, output := range outputs {
switch output {
case "file":
isFileLog = true
case "console":
isConsoleLog = true
}
}
writers := []io.Writer{}
if isConsoleLog {
writers = append(writers, os.Stdout)
}
if isFileLog {
f, err := os.OpenFile(outputFile, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0o644)
if err != nil {
return fmt.Errorf("cannot open log output's file %q: %v", outputFile, err)
}
writers = append(writers, f)
}
initializeLogger(writers...)
return nil
}
// the Skipper struct can be passed as firt argument to adjust the skip offset.
type Skipper struct {
// SkipOffset will be added on top of the existing "2" skips.
SkipOffset int
}
func log(msg, prefix string, print bool, args ...interface{}) string {
caller := "?()"
skipOffset := 2
// Check if the first argument is Skipper and add the skipoffset accordingly.
if len(args) > 0 {
if skip, ok := args[0].(Skipper); ok {
skipOffset += skip.SkipOffset
args = args[1:]
}
}
pc, filename, line, ok := runtime.Caller(skipOffset)
if ok {
// Get caller function name.
fn := runtime.FuncForPC(pc)
if fn != nil {
caller = fn.Name() + "()"
// Remove prefix of binary's name.
lastIndex := strings.LastIndexByte(caller, '.')
if lastIndex > 0 && len(caller) > lastIndex+1 {
caller = caller[lastIndex+1:]
}
}
}
filename = strings.TrimPrefix(filename, filePrefix)
// Don't output long file names.
if len(filename) > 40 {
filename = "..." + filename[len(filename)-40:]
}
now := time.Now()
year, month, day := now.Date()
hour, min, sec := now.Clock()
// Output message:
// DATE TIME FILENAME:LINE:CALLER PREFIX: MSG
prefixedMessage := fmt.Sprintf("%d/%02d/%02d %02d:%02d:%02d %s:%d:%s %s: %s", year, month, day, hour, min, sec, filename, line, caller, prefix, msg)
// Only print the message if it has been requested.
if print {
if len(args) > 0 {
logger.Printf(prefixedMessage+"\n", args...)
} else {
logger.Println(prefixedMessage)
}
return ""
} else {
return fmt.Sprintf(prefixedMessage, args...)
}
}
// Debug logs a message with the DEBUG prefix.
func Debug(msg string, args ...interface{}) {
if logLevel > DebugLevel {
return
}
log(msg, "DEBUG", true, args...)
}
// Info logs a message with the INFO prefix.
func Info(msg string, args ...interface{}) {
if logLevel > InfoLevel {
return
}
log(msg, "INFO", true, args...)
}
// Warn logs a message with the WARN prefix.
func Warn(msg string, args ...interface{}) {
if logLevel > WarnLevel {
return
}
log(msg, "WARN", true, args...)
}
// Error logs a message with the ERROR prefix.
func Error(msg string, args ...interface{}) {
if logLevel > ErrorLevel {
return
}
log(msg, "ERROR", true, args...)
}
// Fatal logs a message with the FATAL prefix and then exit the program.
func Fatal(msg string, args ...interface{}) {
log(msg, "FATAL", true, args...)
os.Exit(1)
}

View file

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

View file

@ -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) {

View file

@ -8,12 +8,12 @@ import (
"strings"
"time"
"github.com/rs/zerolog/log"
"github.com/valyala/fasthttp"
"codeberg.org/codeberg/pages/html"
"codeberg.org/codeberg/pages/server/cache"
"codeberg.org/codeberg/pages/server/gitea"
"codeberg.org/codeberg/pages/server/log"
)
// upstreamIndexPages lists pages that may be considered as index pages for directories.
@ -33,7 +33,10 @@ type Options struct {
TargetBranch,
TargetPath,
DefaultMimeType string
// Used for debugging purposes.
Host string
DefaultMimeType string
ForbiddenMimeTypes map[string]bool
TryIndexPages bool
BranchTimestamp time.Time
@ -44,7 +47,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()
logInfo := fmt.Sprintf("[owner=%q, repo=%q, branch=%q, path=%q, host=%q]", o.TargetOwner, o.TargetRepo, o.TargetBranch, o.TargetPath, o.Host)
// Check if the branch exists and when it was modified
if o.BranchTimestamp.IsZero() {
@ -70,7 +73,8 @@ func (o *Options) Upstream(ctx *fasthttp.RequestCtx, giteaClient *gitea.Client,
return true
}
}
log.Debug().Msg("preparations")
log.Debug("Preparing %s", logInfo)
// Make a GET request to the upstream URL
uri := o.generateUri()
@ -82,7 +86,7 @@ func (o *Options) Upstream(ctx *fasthttp.RequestCtx, giteaClient *gitea.Client,
} else {
res, err = giteaClient.ServeRawContent(uri)
}
log.Debug().Msg("acquisition")
log.Debug("Aquisting %s", logInfo)
// Handle errors
if (err != nil && errors.Is(err, gitea.ErrorNotFound)) || (res == nil && !cachedResponse.Exists) {
@ -136,7 +140,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("Couldn't fetch contents from %q: %v (status code %d)", uri, err, res.StatusCode())
html.ReturnErrorPage(ctx, fasthttp.StatusInternalServerError)
return true
}
@ -155,7 +159,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("Handling error %s", logInfo)
// Set the MIME type
mimeType := o.getMimeTypeByExtension()
@ -175,7 +179,7 @@ func (o *Options) Upstream(ctx *fasthttp.RequestCtx, giteaClient *gitea.Client,
}
ctx.Response.Header.SetLastModified(o.BranchTimestamp)
log.Debug().Msg("response preparations")
log.Debug("Prepare response %s", logInfo)
// Write the response body to the original request
var cacheBodyWriter bytes.Buffer
@ -197,7 +201,7 @@ func (o *Options) Upstream(ctx *fasthttp.RequestCtx, giteaClient *gitea.Client,
html.ReturnErrorPage(ctx, fasthttp.StatusInternalServerError)
return true
}
log.Debug().Msg("response")
log.Debug("Sending response %s", logInfo)
if res != nil && res.Header.ContentLength() <= fileCacheSizeLimit && ctx.Err() == nil {
cachedResponse.Exists = true