Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Update logging formatting/encoder #547

Merged
merged 2 commits into from
Oct 28, 2021
Merged

Update logging formatting/encoder #547

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
cc6d180
logging
mxyng Oct 28, 2021
b721de5
update version logging
mxyng Oct 28, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 3 additions & 2 deletions internal/cmd/version.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,7 @@ import (
"text/tabwriter"

"github.com/infrahq/infra/internal"
"github.com/infrahq/infra/internal/logging"
"golang.org/x/mod/semver"
)

Expand Down Expand Up @@ -89,11 +90,11 @@ func checkUpdate(clientVersion, serverVersion string) error {
}

if clientSemVer != "v0.0.0-development" && semver.Compare(latestSemVer, clientSemVer) > 0 {
fmt.Fprintf(os.Stderr, "Infra CLI (%s) is out of date. Please update to %s.\n", clientVersion, latestVersion)
logging.S.Warnf("Infra CLI (%s) is out of date. Please update to %s.", clientVersion, latestVersion)
}

if serverSemVer != "v0.0.0-development" && semver.IsValid(serverSemVer) && semver.Compare(latestSemVer, serverSemVer) > 0 {
fmt.Fprintf(os.Stderr, "Infra (%s) is out of date. Please update to %s.\n", serverVersion, latestVersion)
logging.S.Warnf("Infra (%s) is out of date. Please update to %s.", serverVersion, latestVersion)
}

return nil
Expand Down
4 changes: 2 additions & 2 deletions internal/engine/engine.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,12 +7,12 @@ import (
"encoding/json"
"errors"
"fmt"
"io"
"io/ioutil"
"net"
"net/http"
"net/http/httputil"
"net/url"
"os"
"regexp"
"strings"
"sync"
Expand Down Expand Up @@ -443,7 +443,7 @@ func Run(options *Options) error {
tlsServer := &http.Server{
Addr: ":443",
TLSConfig: tlsConfig,
Handler: handlers.LoggingHandler(os.Stdout, mux),
Handler: handlers.CustomLoggingHandler(io.Discard, mux, logging.ZapLogFormatter),
}

logging.L.Info("serving on port 443")
Expand Down
3 changes: 1 addition & 2 deletions internal/kubernetes/kubernetes.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,6 @@ import (
"github.com/infrahq/infra/internal/logging"
"github.com/infrahq/infra/secrets"
"github.com/jessevdk/go-flags"
"go.uber.org/zap"
corev1 "k8s.io/api/core/v1"
rbacv1 "k8s.io/api/rbac/v1"
k8sErrors "k8s.io/apimachinery/pkg/api/errors"
Expand Down Expand Up @@ -180,7 +179,7 @@ func (k *Kubernetes) updateRoleBindings(subjects map[namespaceRole][]rbacv1.Subj
if k8sErrors.IsNotFound(err) {
// the namespace does not exist
// we can proceed in this case, the role mapping is just not applicable to this cluster
logging.L.Warn("skipping unapplicable namespace for this cluster: "+rb.Namespace, zap.Error(err))
logging.S.Warnf("skipping unapplicable namespace for this cluster: %s %s", rb.Namespace, err.Error())
continue
}

Expand Down
50 changes: 40 additions & 10 deletions internal/logging/logger.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,29 +2,59 @@
package logging

import (
"io"
"os"

"github.com/gorilla/handlers"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
"golang.org/x/term"
)

var (
L *zap.Logger = zap.L()
S *zap.SugaredLogger = zap.S()
)

func Initialize(level string) (*zap.Logger, error) {
config := zap.NewProductionConfig()
func Initialize(l string) (*zap.Logger, error) {
atom := zap.NewAtomicLevel()

err := atom.UnmarshalText([]byte(level))
if err != nil {
if err := atom.UnmarshalText([]byte(l)); err != nil {
return nil, err
}

config.Level = atom
var (
encoder zapcore.Encoder
writer zapcore.WriteSyncer
)

logger, err := config.Build()
if err != nil {
return nil, err
if term.IsTerminal(int(os.Stdin.Fd())) {
writer = zapcore.Lock(os.Stderr)
encoder = zapcore.NewConsoleEncoder(zapcore.EncoderConfig{
MessageKey: "message",

LevelKey: "level",
EncodeLevel: zapcore.CapitalColorLevelEncoder,

TimeKey: "time",
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is the time necessary for terminal errors?

Copy link
Collaborator Author

@mxyng mxyng Oct 28, 2021 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's probably not but I find the log line without timestamp looks awkward:

$ infra version
WARN    Infra CLI (v0.3.6-next) is out of date. Please update to 0.3.6.

vs.

$ infra version
2021-10-28T13:58:08.750-0700    WARN    Infra CLI (v0.3.6-next) is out of date. Please update to 0.3.6.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Another thing is while we don't have long lived commands in Infra CLI right now, it may be the case in the future where timestamps will be useful, e.g. running admin API commands.

EncodeTime: zapcore.ISO8601TimeEncoder,

CallerKey: "caller",
EncodeCaller: zapcore.ShortCallerEncoder,
})
} else {
writer = zapcore.Lock(os.Stdout)
encoder = zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig())
}

return logger, nil
core := zapcore.NewCore(encoder, writer, atom)

return zap.New(core), nil
}

func ZapLogFormatter(_ io.Writer, params handlers.LogFormatterParams) {
L.Debug("handled request",
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

good change moving this to debug

zap.String("method", params.Request.Method),
zap.String("path", params.URL.Path),
zap.Int("status", params.StatusCode),
zap.Int("size", params.Size))
}
19 changes: 0 additions & 19 deletions internal/registry/http.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,9 +9,7 @@ import (
"strings"
"time"

"github.com/go-chi/chi/middleware"
"github.com/infrahq/infra/internal/logging"
"go.uber.org/zap"
"gopkg.in/square/go-jose.v2"
"gorm.io/gorm"
)
Expand Down Expand Up @@ -59,23 +57,6 @@ func deleteAuthCookie(w http.ResponseWriter) {
})
}

func ZapLoggerHttpMiddleware(next http.Handler) http.HandlerFunc {
return func(w http.ResponseWriter, r *http.Request) {
ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor)
t1 := time.Now()

next.ServeHTTP(ww, r)

logging.L.Info("finished http method call",
zap.String("method", r.Method),
zap.String("path", r.URL.Path),
zap.Int("status", ww.Status()),
zap.String("proto", r.Proto),
zap.Duration("time_ms", time.Since(t1)),
)
}
}

type Http struct {
db *gorm.DB
}
Expand Down
6 changes: 4 additions & 2 deletions internal/registry/registry.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@ package registry
import (
"errors"
"fmt"
"io"
"io/fs"
"io/ioutil"
"net/http"
Expand All @@ -19,6 +20,7 @@ import (
assetfs "github.com/elazarl/go-bindata-assetfs"
"github.com/getsentry/sentry-go"
sentryhttp "github.com/getsentry/sentry-go/http"
"github.com/gorilla/handlers"
"github.com/goware/urlx"
"github.com/infrahq/infra/internal"
"github.com/infrahq/infra/internal/api"
Expand Down Expand Up @@ -356,7 +358,7 @@ func (r *Registry) runServer() error {

plaintextServer := http.Server{
Addr: ":80",
Handler: ZapLoggerHttpMiddleware(sentryHandler.Handle(mux)),
Handler: handlers.CustomLoggingHandler(io.Discard, sentryHandler.Handle(mux), logging.ZapLogFormatter),
}

go func() {
Expand All @@ -379,7 +381,7 @@ func (r *Registry) runServer() error {
tlsServer := &http.Server{
Addr: ":443",
TLSConfig: tlsConfig,
Handler: ZapLoggerHttpMiddleware(sentryHandler.Handle(mux)),
Handler: handlers.CustomLoggingHandler(io.Discard, sentryHandler.Handle(mux), logging.ZapLogFormatter),
}

if err := tlsServer.ListenAndServeTLS("", ""); err != nil {
Expand Down