From 1d6d90f387dcb7f39514eb5c91d5b68429cceaeb Mon Sep 17 00:00:00 2001 From: Gusted Date: Wed, 10 Aug 2022 01:17:04 +0200 Subject: [PATCH] Use zerolog --- cmd/flags.go | 12 -- cmd/main.go | 19 +-- go.mod | 6 +- go.sum | 12 ++ server/certificates/certificates.go | 56 ++++---- server/database/setup.go | 4 +- server/handler.go | 74 +++++------ server/log/log.go | 194 ---------------------------- server/setup.go | 4 +- server/upstream/upstream.go | 19 ++- 10 files changed, 105 insertions(+), 295 deletions(-) delete mode 100644 server/log/log.go diff --git a/cmd/flags.go b/cmd/flags.go index f1a6c0a..3c1ac99 100644 --- a/cmd/flags.go +++ b/cmd/flags.go @@ -63,24 +63,12 @@ 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{ diff --git a/cmd/main.go b/cmd/main.go index fa2f86a..f57eb60 100644 --- a/cmd/main.go +++ b/cmd/main.go @@ -7,9 +7,12 @@ import ( "errors" "fmt" "net" + "os" "strings" "time" + "github.com/rs/zerolog" + "github.com/rs/zerolog/log" "github.com/urfave/cli/v2" "codeberg.org/codeberg/pages/server" @@ -17,7 +20,6 @@ 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,10 +38,11 @@ var BlacklistedPaths = [][]byte{ // Serve sets up and starts the web server. func Serve(ctx *cli.Context) error { // Initalize the logger. - err := log.Config(ctx.StringSlice("log-output"), ctx.String("log-file"), ctx.String("log-level")) + logLevel, err := zerolog.ParseLevel(ctx.String("log-level")) if err != nil { - log.Fatal("Couldn't set configure logging: %v", err) + 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") @@ -98,7 +101,7 @@ func Serve(ctx *cli.Context) error { httpServer := server.SetupHTTPACMEChallengeServer(challengeCache) // Setup listener and TLS - log.Info("Listening on https://%s", listeningAddress) + log.Info().Msgf("Listening on https://%s", listeningAddress) listener, err := net.Listen("tcp", listeningAddress) if err != nil { return fmt.Errorf("couldn't create listener: %v", err) @@ -134,19 +137,19 @@ func Serve(ctx *cli.Context) error { if enableHTTPServer { go func() { - log.Info("Start HTTP server listening on :80") + log.Info().Msg("Start HTTP server listening on :80") err := httpServer.ListenAndServe("[::]:80") if err != nil { - log.Fatal("Couldn't start HTTP fastServer: %v", err) + log.Panic().Err(err).Msg("Couldn't start HTTP fastServer") } }() } // Start the web fastServer - log.Info("Start listening on %s", listener.Addr()) + log.Info().Msgf("Start listening on %s", listener.Addr()) err = fastServer.Serve(listener) if err != nil { - log.Fatal("Couldn't start fastServer: %v", err) + log.Panic().Err(err).Msg("Couldn't start fastServer") } return nil diff --git a/go.mod b/go.mod index a8f1575..64288de 100644 --- a/go.mod +++ b/go.mod @@ -71,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 @@ -91,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 @@ -110,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 diff --git a/go.sum b/go.sum index 8cc53b3..4ac6eb6 100644 --- a/go.sum +++ b/go.sum @@ -95,6 +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.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= @@ -149,6 +150,7 @@ 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= @@ -319,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= @@ -425,6 +431,9 @@ 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.27.0 h1:1T7qCieN22GVc8S4Q2yuexzBb1EqjbgjSH9RohbMjKs= +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= @@ -661,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= diff --git a/server/certificates/certificates.go b/server/certificates/certificates.go index 2c9236d..6dc8573 100644 --- a/server/certificates/certificates.go +++ b/server/certificates/certificates.go @@ -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.Error("Couldn't renew certificate for %s: %v", string(sni), err) + log.Error().Msgf("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.Debug("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.Error("Couldn't renew certificate for %v, trying to request a new one: %v", domains, err) + log.Error().Err(err).Msgf("Couldn't renew certificate for %v, trying to request a new one", domains) res = nil } } @@ -290,7 +290,7 @@ func obtainCert(acmeClient *lego.Client, domains []string, renew *certificate.Re acmeClientOrderLimit.Take() acmeClientRequestLimit.Take() } - log.Debug("Re-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, @@ -298,7 +298,7 @@ func obtainCert(acmeClient *lego.Client, domains []string, renew *certificate.Re }) } if err != nil { - log.Error("Couldn't obtain again a certificate or %v: %v", 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()) { @@ -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.Debug("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 @@ -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.Error("Can't create ACME client, continuing with mock certs only: %v", err) + log.Error().Err(err).Msg("Can't create ACME client, continuing with mock certs only") } 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.Error("Can't create ACME client, continuing with mock certs only: %v", 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.Error("Can't register ACME account, continuing with mock certs only: %v", err) + log.Error().Err(err).Msg("Can't register ACME account, continuing with mock certs only") } else { myAcmeAccount.Registration = reg } @@ -383,7 +383,7 @@ func SetupAcmeConfig(acmeAPI, acmeMail, acmeEabHmac, acmeEabKID string, acmeAcce HmacEncoded: acmeEabHmac, }) if err != nil { - log.Error("Can't register ACME account, continuing with mock certs only: %v", err) + log.Error().Err(err).Msg("Can't register ACME account, continuing with mock certs only") } 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.Error("json.Marshalfailed, waiting for manual restart to avoid rate limits: %v", 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.Error("os.WriteFile failed, 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 {} } } @@ -415,38 +415,38 @@ func SetupCertificates(mainDomainSuffix []byte, dnsProvider string, acmeConfig * acmeClient, err = lego.NewClient(acmeConfig) if err != nil { - log.Error("Can't create ACME client, continuing with mock certs only: %v", 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.Error("Can't create TLS-ALPN-01 provider: %v", 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.Error("Can't create HTTP-01 provider: %v", err) + log.Error().Err(err).Msg("Can't create HTTP-01 provider") } } } mainDomainAcmeClient, err = lego.NewClient(acmeConfig) if err != nil { - log.Error("Can't create ACME client, continuing with mock certs only: %v", 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.Error("Can't create TLS-ALPN-01 provider: %v", err) + log.Error().Err(err).Msg("Can't create TLS-ALPN-01 provider") } } else { provider, err := dns.NewDNSChallengeProviderByName(dnsProvider) if err != nil { - log.Error("Can't create DNS Challenge provider: %v", err) + log.Error().Err(err).Msg("Can't create DNS Challenge provider") } err = mainDomainAcmeClient.Challenge.SetDNS01Provider(provider) if err != nil { - log.Error("Can't create DNS-01 provider: %v", err) + log.Error().Err(err).Msg("Can't create DNS-01 provider") } } } @@ -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.Error("Couldn't renew main domain certificate, continuing with mock certs only: %v", err) + log.Error().Err(err).Msg("Couldn't renew main domain certificate, continuing with mock certs only") } } @@ -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.Error("Deleting expired certificate for %q failed: %v", string(key), err) + log.Error().Err(err).Msgf("Deleting expired certificate for %q failed", string(key)) } else { expiredCertCount++ } @@ -490,22 +490,22 @@ func MaintainCertDB(ctx context.Context, interval time.Duration, mainDomainSuffi } key, resBytes, err = keyDatabaseIterator.Next() } - log.Debug("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.Error("Compacting key database failed: %v", err) + log.Error().Err(err).Msg("Compacting key database failed") } else { - log.Debug("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.Error("Couldn't get cert for domain %q", mainDomainSuffix) + log.Error().Msgf("Couldn't get cert for domain %q", mainDomainSuffix) } else if res == nil { - 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)) + 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) @@ -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.Error("Couldn't renew certificate for main domain: %v", err) + log.Error().Err(err).Msg("Couldn't renew certificate for main domain") } })() } diff --git a/server/database/setup.go b/server/database/setup.go index feb5d0a..1c5a0af 100644 --- a/server/database/setup.go +++ b/server/database/setup.go @@ -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.Error("Syncing cert database failed: %v", err) + log.Error().Err(err).Msg("Syncing cert database failed") } select { case <-p.ctx.Done(): diff --git a/server/handler.go b/server/handler.go index 39a782b..50fbcc5 100644 --- a/server/handler.go +++ b/server/handler.go @@ -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) { - logInfo := fmt.Sprintf("[handler=%q]", string(ctx.Request.Header.RequestURI())) + log := log.With().Str("Handler", string(ctx.Request.Header.RequestURI())).Logger() 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(logInfo, repo, branch string, path []string, canonicalLink string) bool { + tryBranch := func(log zerolog.Logger, repo, branch string, path []string, canonicalLink string) bool { if repo == "" { - log.Debug("tryBranch%s: repo is empty", logInfo) + log.Debug().Msg("tryBranch: repo is empty") 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("tryBranch%s: branch doesn't exist", logInfo) + log.Debug().Msg("tryBranch: branch doesn't exist") return false } @@ -116,14 +116,14 @@ func Handler(mainDomainSuffix, rawDomain []byte, ) } - log.Debug("tryBranch%s: true", logInfo) + log.Debug().Msg("tryBranch: true") return true } - log.Debug("Preparing %s", logInfo) + log.Debug().Msg("Preparing") if rawDomain != nil && bytes.Equal(trimmedHost, rawDomain) { // Serve raw content from RawDomain - log.Debug("Serving raw domain %s", logInfo) + 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("Preparing raw domain, now trying with specified branch %s", logInfo) - if tryBranch(logInfo, + 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.Info("tryBranch, now trying upstream 1 %s", logInfo) + log.Info().Msg("tryBranch, now trying upstream 1") tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost, targetOptions, targetOwner, targetRepo, targetBranch, targetPath, canonicalDomainCache, branchTimestampCache, fileResponseCache) return } - log.Warn("Path missed a branch %s", logInfo) + log.Warn().Msg("Path missed a branch") html.ReturnErrorPage(ctx, fasthttp.StatusFailedDependency) return } - log.Debug("Preparing raw domain, now trying with default branch %s", logInfo) - tryBranch(logInfo, + log.Debug().Msg("Preparing raw domain, now trying with default branch") + tryBranch(log, targetRepo, "", pathElements[2:], giteaRoot+"/"+targetOwner+"/"+targetRepo+"/src/branch/%b/%p", ) - log.Info("tryBranch, now trying upstream 2 %s", logInfo) + 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("Serve pages from main domain suffix %s", logInfo) + 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,17 +194,17 @@ func Handler(mainDomainSuffix, rawDomain []byte, return } - log.Debug("Preparing main domain, now trying with specified repo & branch, %s", logInfo) - if tryBranch(logInfo, + 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.Info("tryBranch, now trying upstream 3 %s", logInfo) + log.Info().Msg("tryBranch, now trying upstream 3") tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost, targetOptions, targetOwner, targetRepo, targetBranch, targetPath, canonicalDomainCache, branchTimestampCache, fileResponseCache) } else { - log.Warn("tryBranch%s: upstream 3 failed", logInfo) + log.Warn().Msg("tryBranch: upstream 3 failed") html.ReturnErrorPage(ctx, fasthttp.StatusFailedDependency) } return @@ -213,15 +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("Preparing main domain, now trying with specified branch %s", logInfo) - if tryBranch(logInfo, + log.Debug().Msg("Preparing main domain, now trying with specified branch") + if tryBranch(log, "pages", pathElements[0][1:], pathElements[1:], "/%p") { - log.Info("tryBranch, now trying upstream 4 %s", logInfo) + log.Info().Msg("tryBranch, now trying upstream 4") tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost, targetOptions, targetOwner, targetRepo, targetBranch, targetPath, canonicalDomainCache, branchTimestampCache, fileResponseCache) } else { - log.Warn("tryBranch%s: upstream 4 failed", logInfo) + log.Warn().Msg("tryBranch: upstream 4 failed") html.ReturnErrorPage(ctx, fasthttp.StatusFailedDependency) } return @@ -230,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("main domain preparations, now trying with specified repo %s", logInfo) - if pathElements[0] != "pages" && tryBranch(logInfo, + log.Debug().Msg("main domain preparations, now trying with specified repo") + if pathElements[0] != "pages" && tryBranch(log, pathElements[0], "pages", pathElements[1:], "") { - log.Info("tryBranch, now trying upstream 5 %s", logInfo) + log.Info().Msg("tryBranch, now trying upstream 5") tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost, targetOptions, targetOwner, targetRepo, targetBranch, targetPath, canonicalDomainCache, branchTimestampCache, fileResponseCache) @@ -242,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("main domain preparations, now trying with default repo/branch %s", logInfo) - if tryBranch(logInfo, + log.Debug().Msg("main domain preparations, now trying with default repo/branch") + if tryBranch(log, "pages", "", pathElements, "") { - log.Info("tryBranch, now trying upstream 6 %s", logInfo) + log.Info().Msg("tryBranch, now trying upstream 6") tryUpstream(ctx, giteaClient, mainDomainSuffix, trimmedHost, targetOptions, targetOwner, targetRepo, targetBranch, targetPath, canonicalDomainCache, branchTimestampCache, fileResponseCache) @@ -275,12 +275,12 @@ func Handler(mainDomainSuffix, rawDomain []byte, } // Try to use the given repo on the given branch or the default branch - log.Debug("Preparing custom domain, now trying with details from DNS %s", logInfo) - if tryBranch(logInfo, + 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("Custom domains, domain from DNS isn't valid/canonical %s", logInfo) + log.Warn().Msg("Custom domains, domain from DNS isn't valid/canonical") html.ReturnErrorPage(ctx, fasthttp.StatusMisdirectedRequest) return } else if canonicalDomain != trimmedHostStr { @@ -291,19 +291,19 @@ func Handler(mainDomainSuffix, rawDomain []byte, return } - log.Warn("Custom domains, targetOwner from DNS is empty", logInfo) + log.Warn().Msg("Custom domains, targetOwner from DNS is empty") html.ReturnErrorPage(ctx, fasthttp.StatusFailedDependency) return } - log.Info("tryBranch, now trying upstream 7 %s", logInfo) + 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("Couldn't handle request, none of the options succeed %q", logInfo) + log.Warn().Msg("Couldn't handle request, none of the options succeed") html.ReturnErrorPage(ctx, fasthttp.StatusFailedDependency) return } diff --git a/server/log/log.go b/server/log/log.go deleted file mode 100644 index 120839b..0000000 --- a/server/log/log.go +++ /dev/null @@ -1,194 +0,0 @@ -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) -} diff --git a/server/setup.go b/server/setup.go index 10c2252..176bb42 100644 --- a/server/setup.go +++ b/server/setup.go @@ -6,17 +6,17 @@ import ( "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.Info("FastHTTP: %s", fmt.Sprintf(format, args...)) + log.Printf("FastHTTP: %s", fmt.Sprintf(format, args...)) } func SetupServer(handler fasthttp.RequestHandler) *fasthttp.Server { diff --git a/server/upstream/upstream.go b/server/upstream/upstream.go index e079d80..4371e88 100644 --- a/server/upstream/upstream.go +++ b/server/upstream/upstream.go @@ -3,17 +3,16 @@ package upstream import ( "bytes" "errors" - "fmt" "io" "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. @@ -47,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) { - logInfo := fmt.Sprintf("[owner=%q, repo=%q, branch=%q, path=%q, host=%q]", o.TargetOwner, o.TargetRepo, o.TargetBranch, o.TargetPath, o.Host) + 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() { @@ -74,7 +73,7 @@ func (o *Options) Upstream(ctx *fasthttp.RequestCtx, giteaClient *gitea.Client, } } - log.Debug("Preparing %s", logInfo) + log.Debug().Msg("Preparing") // Make a GET request to the upstream URL uri := o.generateUri() @@ -86,7 +85,7 @@ func (o *Options) Upstream(ctx *fasthttp.RequestCtx, giteaClient *gitea.Client, } else { res, err = giteaClient.ServeRawContent(uri) } - log.Debug("Aquisting %s", logInfo) + log.Debug().Msg("Aquisting") // Handle errors if (err != nil && errors.Is(err, gitea.ErrorNotFound)) || (res == nil && !cachedResponse.Exists) { @@ -140,7 +139,7 @@ func (o *Options) Upstream(ctx *fasthttp.RequestCtx, giteaClient *gitea.Client, return false } if res != nil && (err != nil || res.StatusCode() != fasthttp.StatusOK) { - log.Warn("Couldn't fetch contents from %q: %v (status code %d)", 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 } @@ -159,7 +158,7 @@ func (o *Options) Upstream(ctx *fasthttp.RequestCtx, giteaClient *gitea.Client, ctx.Redirect(o.redirectIfExists, fasthttp.StatusTemporaryRedirect) return true } - log.Debug("Handling error %s", logInfo) + log.Debug().Msg("Handling error") // Set the MIME type mimeType := o.getMimeTypeByExtension() @@ -179,7 +178,7 @@ func (o *Options) Upstream(ctx *fasthttp.RequestCtx, giteaClient *gitea.Client, } ctx.Response.Header.SetLastModified(o.BranchTimestamp) - log.Debug("Prepare response %s", logInfo) + log.Debug().Msg("Prepare response") // Write the response body to the original request var cacheBodyWriter bytes.Buffer @@ -197,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("Sending response %s", logInfo) + log.Debug().Msg("Sending response") if res != nil && res.Header.ContentLength() <= fileCacheSizeLimit && ctx.Err() == nil { cachedResponse.Exists = true