patch of knotserver: improve the logging situation · round #1 · pull #653 · tangled.org/core

+6 -3

cmd/knot/main.go

···

       2
       2
        
       

     

       3
       3
        
       import (

     

       4
       4
        
       	"context"

     

       5
       5
       +
       	"log/slog"

     

       5
       6
        
       	"os"

     

       6
       7
        
       

     

       7
       8
        
       	"github.com/urfave/cli/v3"

     
···

       9
       10
        
       	"tangled.org/core/hook"

     

       10
       11
        
       	"tangled.org/core/keyfetch"

     

       11
       12
        
       	"tangled.org/core/knotserver"

     

       12
       12
       -
       	"tangled.org/core/log"

     

       13
       13
       +
       	tlog "tangled.org/core/log"

     

       13
       14
        
       )

     

       14
       15
        
       

     

       15
       16
        
       func main() {

     
···

       24
       25
        
       		},

     

       25
       26
        
       	}

     

       26
       27
        
       

     

       28
       28
       +
       	logger := tlog.New("knot")

     

       29
       29
       +
       	slog.SetDefault(logger)

     

       30
       30
       +
       

     

       27
       31
        
       	ctx := context.Background()

     

       28
       28
       -
       	logger := log.New("knot")

     

       29
       29
       -
       	ctx = log.IntoContext(ctx, logger.With("command", cmd.Name))

     

       32
       32
       +
       	ctx = tlog.IntoContext(ctx, logger)

     

       30
       33
        
       

     

       31
       34
        
       	if err := cmd.Run(ctx, os.Args); err != nil {

     

       32
       35
        
       		logger.Error(err.Error())

+2 -3

knotserver/events.go

···

       8
       8
        
       	"time"

     

       9
       9
        
       

     

       10
       10
        
       	"github.com/gorilla/websocket"

     

       11
       11
       +
       	"tangled.org/core/log"

     

       11
       12
        
       )

     

       12
       13
        
       

     

       13
       14
        
       var upgrader = websocket.Upgrader{

     
···

       16
       17
        
       }

     

       17
       18
        
       

     

       18
       19
        
       func (h *Knot) Events(w http.ResponseWriter, r *http.Request) {

     

       19
       19
       -
       	l := h.l.With("handler", "OpLog")

     

       20
       20
       +
       	l := log.SubLogger(h.l, "eventstream")

     

       20
       21
        
       	l.Debug("received new connection")

     

       21
       22
        
       

     

       22
       23
        
       	conn, err := upgrader.Upgrade(w, r, nil)

     
···

       75
       76
        
       			}

     

       76
       77
        
       		case <-time.After(30 * time.Second):

     

       77
       78
        
       			// send a keep-alive

     

       78
       78
       -
       			l.Debug("sent keepalive")

     

       79
       79
        
       			if err = conn.WriteControl(websocket.PingMessage, []byte{}, time.Now().Add(time.Second)); err != nil {

     

       80
       80
        
       				l.Error("failed to write control", "err", err)

     

       81
       81
        
       			}

     
···

       89
       89
        
       		h.l.Error("failed to fetch events from db", "err", err, "cursor", cursor)

     

       90
       90
        
       		return err

     

       91
       91
        
       	}

     

       92
       92
       -
       	h.l.Debug("ops", "ops", events)

     

       93
       92
        
       

     

       94
       93
        
       	for _, event := range events {

     

       95
       94
        
       		// first extract the inner json into a map

+18 -18

knotserver/git.go

···

       13
       13
        
       	"tangled.org/core/knotserver/git/service"

     

       14
       14
        
       )

     

       15
       15
        
       

     

       16
       16
       -
       func (d *Knot) InfoRefs(w http.ResponseWriter, r *http.Request) {

     

       16
       16
       +
       func (h *Knot) InfoRefs(w http.ResponseWriter, r *http.Request) {

     

       17
       17
        
       	did := chi.URLParam(r, "did")

     

       18
       18
        
       	name := chi.URLParam(r, "name")

     

       19
       19
        
       	repoName, err := securejoin.SecureJoin(did, name)

     

       20
       20
        
       	if err != nil {

     

       21
       21
        
       		gitError(w, "repository not found", http.StatusNotFound)

     

       22
       22
       -
       		d.l.Error("git: failed to secure join repo path", "handler", "InfoRefs", "error", err)

     

       22
       22
       +
       		h.l.Error("git: failed to secure join repo path", "handler", "InfoRefs", "error", err)

     

       23
       23
        
       		return

     

       24
       24
        
       	}

     

       25
       25
        
       

     

       26
       26
       -
       	repoPath, err := securejoin.SecureJoin(d.c.Repo.ScanPath, repoName)

     

       26
       26
       +
       	repoPath, err := securejoin.SecureJoin(h.c.Repo.ScanPath, repoName)

     

       27
       27
        
       	if err != nil {

     

       28
       28
        
       		gitError(w, "repository not found", http.StatusNotFound)

     

       29
       29
       -
       		d.l.Error("git: failed to secure join repo path", "handler", "InfoRefs", "error", err)

     

       29
       29
       +
       		h.l.Error("git: failed to secure join repo path", "handler", "InfoRefs", "error", err)

     

       30
       30
        
       		return

     

       31
       31
        
       	}

     

       32
       32
        
       

     
···

       46
       46
        
       

     

       47
       47
        
       		if err := cmd.InfoRefs(); err != nil {

     

       48
       48
        
       			gitError(w, err.Error(), http.StatusInternalServerError)

     

       49
       49
       -
       			d.l.Error("git: process failed", "handler", "InfoRefs", "service", serviceName, "error", err)

     

       49
       49
       +
       			h.l.Error("git: process failed", "handler", "InfoRefs", "service", serviceName, "error", err)

     

       50
       50
        
       			return

     

       51
       51
        
       		}

     

       52
       52
        
       	case "git-receive-pack":

     

       53
       53
       -
       		d.RejectPush(w, r, name)

     

       53
       53
       +
       		h.RejectPush(w, r, name)

     

       54
       54
        
       	default:

     

       55
       55
        
       		gitError(w, fmt.Sprintf("service unsupported: '%s'", serviceName), http.StatusForbidden)

     

       56
       56
        
       	}

     

       57
       57
        
       }

     

       58
       58
        
       

     

       59
       59
       -
       func (d *Knot) UploadPack(w http.ResponseWriter, r *http.Request) {

     

       59
       59
       +
       func (h *Knot) UploadPack(w http.ResponseWriter, r *http.Request) {

     

       60
       60
        
       	did := chi.URLParam(r, "did")

     

       61
       61
        
       	name := chi.URLParam(r, "name")

     

       62
       62
       -
       	repo, err := securejoin.SecureJoin(d.c.Repo.ScanPath, filepath.Join(did, name))

     

       62
       62
       +
       	repo, err := securejoin.SecureJoin(h.c.Repo.ScanPath, filepath.Join(did, name))

     

       63
       63
        
       	if err != nil {

     

       64
       64
        
       		gitError(w, err.Error(), http.StatusInternalServerError)

     

       65
       65
       -
       		d.l.Error("git: failed to secure join repo path", "handler", "UploadPack", "error", err)

     

       65
       65
       +
       		h.l.Error("git: failed to secure join repo path", "handler", "UploadPack", "error", err)

     

       66
       66
        
       		return

     

       67
       67
        
       	}

     

       68
       68
        
       

     
···

       77
       77
        
       		gzipReader, err := gzip.NewReader(r.Body)

     

       78
       78
        
       		if err != nil {

     

       79
       79
        
       			gitError(w, err.Error(), http.StatusInternalServerError)

     

       80
       80
       -
       			d.l.Error("git: failed to create gzip reader", "handler", "UploadPack", "error", err)

     

       80
       80
       +
       			h.l.Error("git: failed to create gzip reader", "handler", "UploadPack", "error", err)

     

       81
       81
        
       			return

     

       82
       82
        
       		}

     

       83
       83
        
       		defer gzipReader.Close()

     
···

       88
       88
        
       	w.Header().Set("Connection", "Keep-Alive")

     

       89
       89
        
       	w.Header().Set("Cache-Control", "no-cache, max-age=0, must-revalidate")

     

       90
       90
        
       

     

       91
       91
       -
       	d.l.Info("git: executing git-upload-pack", "handler", "UploadPack", "repo", repo)

     

       91
       91
       +
       	h.l.Info("git: executing git-upload-pack", "handler", "UploadPack", "repo", repo)

     

       92
       92
        
       

     

       93
       93
        
       	cmd := service.ServiceCommand{

     

       94
       94
        
       		GitProtocol: r.Header.Get("Git-Protocol"),

     
···

       100
       100
        
       	w.WriteHeader(http.StatusOK)

     

       101
       101
        
       

     

       102
       102
        
       	if err := cmd.UploadPack(); err != nil {

     

       103
       103
       -
       		d.l.Error("git: failed to execute git-upload-pack", "handler", "UploadPack", "error", err)

     

       103
       103
       +
       		h.l.Error("git: failed to execute git-upload-pack", "handler", "UploadPack", "error", err)

     

       104
       104
        
       		return

     

       105
       105
        
       	}

     

       106
       106
        
       }

     

       107
       107
        
       

     

       108
       108
       -
       func (d *Knot) ReceivePack(w http.ResponseWriter, r *http.Request) {

     

       108
       108
       +
       func (h *Knot) ReceivePack(w http.ResponseWriter, r *http.Request) {

     

       109
       109
        
       	did := chi.URLParam(r, "did")

     

       110
       110
        
       	name := chi.URLParam(r, "name")

     

       111
       111
       -
       	_, err := securejoin.SecureJoin(d.c.Repo.ScanPath, filepath.Join(did, name))

     

       111
       111
       +
       	_, err := securejoin.SecureJoin(h.c.Repo.ScanPath, filepath.Join(did, name))

     

       112
       112
        
       	if err != nil {

     

       113
       113
        
       		gitError(w, err.Error(), http.StatusForbidden)

     

       114
       114
       -
       		d.l.Error("git: failed to secure join repo path", "handler", "ReceivePack", "error", err)

     

       114
       114
       +
       		h.l.Error("git: failed to secure join repo path", "handler", "ReceivePack", "error", err)

     

       115
       115
        
       		return

     

       116
       116
        
       	}

     

       117
       117
        
       

     

       118
       118
       -
       	d.RejectPush(w, r, name)

     

       118
       118
       +
       	h.RejectPush(w, r, name)

     

       119
       119
        
       }

     

       120
       120
        
       

     

       121
       121
       -
       func (d *Knot) RejectPush(w http.ResponseWriter, r *http.Request, unqualifiedRepoName string) {

     

       121
       121
       +
       func (h *Knot) RejectPush(w http.ResponseWriter, r *http.Request, unqualifiedRepoName string) {

     

       122
       122
        
       	// A text/plain response will cause git to print each line of the body

     

       123
       123
        
       	// prefixed with "remote: ".

     

       124
       124
        
       	w.Header().Set("content-type", "text/plain; charset=UTF-8")

     
···

       131
       131
        
       	ownerHandle := r.Header.Get("x-tangled-repo-owner-handle")

     

       132
       132
        
       	ownerHandle = strings.TrimPrefix(ownerHandle, "@")

     

       133
       133
        
       	if ownerHandle != "" && !strings.ContainsAny(ownerHandle, ":") {

     

       134
       134
       -
       		hostname := d.c.Server.Hostname

     

       134
       134
       +
       		hostname := h.c.Server.Hostname

     

       135
       135
        
       		if strings.Contains(hostname, ":") {

     

       136
       136
        
       			hostname = strings.Split(hostname, ":")[0]

     

       137
       137
        
       		}

+4 -1

knotserver/internal.go

···

       20
       20
        
       	"tangled.org/core/knotserver/config"

     

       21
       21
        
       	"tangled.org/core/knotserver/db"

     

       22
       22
        
       	"tangled.org/core/knotserver/git"

     

       23
       23
       +
       	"tangled.org/core/log"

     

       23
       24
        
       	"tangled.org/core/notifier"

     

       24
       25
        
       	"tangled.org/core/rbac"

     

       25
       26
        
       	"tangled.org/core/workflow"

     
···

       314
       315
        
       	return h.db.InsertEvent(event, h.n)

     

       315
       316
        
       }

     

       316
       317
        
       

     

       317
       317
       -
       func Internal(ctx context.Context, c *config.Config, db *db.DB, e *rbac.Enforcer, l *slog.Logger, n *notifier.Notifier) http.Handler {

     

       318
       318
       +
       func Internal(ctx context.Context, c *config.Config, db *db.DB, e *rbac.Enforcer, n *notifier.Notifier) http.Handler {

     

       318
       319
        
       	r := chi.NewRouter()

     

       320
       320
       +
       	l := log.FromContext(ctx)

     

       321
       321
       +
       	l = log.SubLogger(l, "internal")

     

       319
       322
        
       

     

       320
       323
        
       	h := InternalHandle{

     

       321
       324
        
       		db,

+35

knotserver/middleware.go

···

       1
       1
       +
       package knotserver

     

       2
       2
       +
       

     

       3
       3
       +
       import (

     

       4
       4
       +
       	"log/slog"

     

       5
       5
       +
       	"net/http"

     

       6
       6
       +
       	"time"

     

       7
       7
       +
       )

     

       8
       8
       +
       

     

       9
       9
       +
       func (h *Knot) RequestLogger(next http.Handler) http.Handler {

     

       10
       10
       +
       	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {

     

       11
       11
       +
       		start := time.Now()

     

       12
       12
       +
       

     

       13
       13
       +
       		next.ServeHTTP(w, r)

     

       14
       14
       +
       

     

       15
       15
       +
       		// Build query params as slog.Attrs for the group

     

       16
       16
       +
       		queryParams := r.URL.Query()

     

       17
       17
       +
       		queryAttrs := make([]any, 0, len(queryParams))

     

       18
       18
       +
       		for key, values := range queryParams {

     

       19
       19
       +
       			if len(values) == 1 {

     

       20
       20
       +
       				queryAttrs = append(queryAttrs, slog.String(key, values[0]))

     

       21
       21
       +
       			} else {

     

       22
       22
       +
       				queryAttrs = append(queryAttrs, slog.Any(key, values))

     

       23
       23
       +
       			}

     

       24
       24
       +
       		}

     

       25
       25
       +
       

     

       26
       26
       +
       		h.l.LogAttrs(r.Context(), slog.LevelInfo, "",

     

       27
       27
       +
       			slog.Group("request",

     

       28
       28
       +
       				slog.String("method", r.Method),

     

       29
       29
       +
       				slog.String("path", r.URL.Path),

     

       30
       30
       +
       				slog.Group("query", queryAttrs...),

     

       31
       31
       +
       				slog.Duration("duration", time.Since(start)),

     

       32
       32
       +
       			),

     

       33
       33
       +
       		)

     

       34
       34
       +
       	})

     

       35
       35
       +
       }

+16 -9

knotserver/router.go

···

       12
       12
        
       	"tangled.org/core/knotserver/config"

     

       13
       13
        
       	"tangled.org/core/knotserver/db"

     

       14
       14
        
       	"tangled.org/core/knotserver/xrpc"

     

       15
       15
       -
       	tlog "tangled.org/core/log"

     

       15
       15
       +
       	"tangled.org/core/log"

     

       16
       16
        
       	"tangled.org/core/notifier"

     

       17
       17
        
       	"tangled.org/core/rbac"

     

       18
       18
        
       	"tangled.org/core/xrpc/serviceauth"

     
···

       28
       28
        
       	resolver *idresolver.Resolver

     

       29
       29
        
       }

     

       30
       30
        
       

     

       31
       31
       -
       func Setup(ctx context.Context, c *config.Config, db *db.DB, e *rbac.Enforcer, jc *jetstream.JetstreamClient, l *slog.Logger, n *notifier.Notifier) (http.Handler, error) {

     

       32
       32
       -
       	r := chi.NewRouter()

     

       33
       33
       -
       

     

       31
       31
       +
       func Setup(ctx context.Context, c *config.Config, db *db.DB, e *rbac.Enforcer, jc *jetstream.JetstreamClient, n *notifier.Notifier) (http.Handler, error) {

     

       34
       32
        
       	h := Knot{

     

       35
       33
        
       		c:        c,

     

       36
       34
        
       		db:       db,

     

       37
       35
        
       		e:        e,

     

       38
       38
       -
       		l:        l,

     

       36
       36
       +
       		l:        log.FromContext(ctx),

     

       39
       37
        
       		jc:       jc,

     

       40
       38
        
       		n:        n,

     

       41
       39
        
       		resolver: idresolver.DefaultResolver(),

     
···

       67
       65
        
       		return nil, fmt.Errorf("failed to start jetstream: %w", err)

     

       68
       66
        
       	}

     

       69
       67
        
       

     

       68
       68
       +
       	return h.Router(), nil

     

       69
       69
       +
       }

     

       70
       70
       +
       

     

       71
       71
       +
       func (h *Knot) Router() http.Handler {

     

       72
       72
       +
       	r := chi.NewRouter()

     

       73
       73
       +
       

     

       74
       74
       +
       	r.Use(h.RequestLogger)

     

       75
       75
       +
       

     

       70
       76
        
       	r.Get("/", func(w http.ResponseWriter, r *http.Request) {

     

       71
       77
        
       		w.Write([]byte("This is a knot server. More info at https://tangled.sh"))

     

       72
       78
        
       	})

     
···

       86
       92
        
       	// Socket that streams git oplogs

     

       87
       93
        
       	r.Get("/events", h.Events)

     

       88
       94
        
       

     

       89
       89
       -
       	return r, nil

     

       95
       95
       +
       	return r

     

       90
       96
        
       }

     

       91
       97
        
       

     

       92
       98
        
       func (h *Knot) XrpcRouter() http.Handler {

     

       93
       93
       -
       	logger := tlog.New("knots")

     

       94
       94
       -
       

     

       95
       99
        
       	serviceAuth := serviceauth.NewServiceAuth(h.l, h.resolver, h.c.Server.Did().String())

     

       96
       100
        
       

     

       101
       101
       +
       	l := log.SubLogger(h.l, "xrpc")

     

       102
       102
       +
       

     

       97
       103
        
       	xrpc := &xrpc.Xrpc{

     

       98
       104
        
       		Config:      h.c,

     

       99
       105
        
       		Db:          h.db,

     

       100
       106
        
       		Ingester:    h.jc,

     

       101
       107
        
       		Enforcer:    h.e,

     

       102
       102
       -
       		Logger:      logger,

     

       108
       108
       +
       		Logger:      l,

     

       103
       109
        
       		Notifier:    h.n,

     

       104
       110
        
       		Resolver:    h.resolver,

     

       105
       111
        
       		ServiceAuth: serviceAuth,

     

       106
       112
        
       	}

     

       113
       113
       +
       

     

       107
       114
        
       	return xrpc.Router()

     

       108
       115
        
       }

     

       109
       116

+5 -4

knotserver/server.go

···

       43
       43
        
       

     

       44
       44
        
       func Run(ctx context.Context, cmd *cli.Command) error {

     

       45
       45
        
       	logger := log.FromContext(ctx)

     

       46
       46
       -
       	iLogger := log.New("knotserver/internal")

     

       46
       46
       +
       	logger = log.SubLogger(logger, cmd.Name)

     

       47
       47
       +
       	ctx = log.IntoContext(ctx, logger)

     

       47
       48
        
       

     

       48
       49
        
       	c, err := config.Load(ctx)

     

       49
       50
        
       	if err != nil {

     
···

       80
       81
        
       		tangled.KnotMemberNSID,

     

       81
       82
        
       		tangled.RepoPullNSID,

     

       82
       83
        
       		tangled.RepoCollaboratorNSID,

     

       83
       83
       -
       	}, nil, logger, db, true, c.Server.LogDids)

     

       84
       84
       +
       	}, nil, log.SubLogger(logger, "jetstream"), db, true, c.Server.LogDids)

     

       84
       85
        
       	if err != nil {

     

       85
       86
        
       		logger.Error("failed to setup jetstream", "error", err)

     

       86
       87
        
       	}

     

       87
       88
        
       

     

       88
       89
        
       	notifier := notifier.New()

     

       89
       90
        
       

     

       90
       90
       -
       	mux, err := Setup(ctx, c, db, e, jc, logger, &notifier)

     

       91
       91
       +
       	mux, err := Setup(ctx, c, db, e, jc, &notifier)

     

       91
       92
        
       	if err != nil {

     

       92
       93
        
       		return fmt.Errorf("failed to setup server: %w", err)

     

       93
       94
        
       	}

     

       94
       95
        
       

     

       95
       95
       -
       	imux := Internal(ctx, c, db, e, iLogger, &notifier)

     

       96
       96
       +
       	imux := Internal(ctx, c, db, e, &notifier)

     

       96
       97
        
       

     

       97
       98
        
       	logger.Info("starting internal server", "address", c.Server.InternalListenAddr)

     

       98
       99
        
       	go http.ListenAndServe(c.Server.InternalListenAddr, imux)

+23 -9

log/log.go

···

       4
       4
        
       	"context"

     

       5
       5
        
       	"log/slog"

     

       6
       6
        
       	"os"

     

       7
       7
       +
       

     

       8
       8
       +
       	"github.com/charmbracelet/log"

     

       7
       9
        
       )

     

       8
       10
        
       

     

       9
       9
       -
       // NewHandler sets up a new slog.Handler with the service name

     

       10
       10
       -
       // as an attribute

     

       11
       11
        
       func NewHandler(name string) slog.Handler {

     

       12
       12
       -
       	handler := slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{

     

       13
       13
       -
       		Level: slog.LevelDebug,

     

       12
       12
       +
       	return log.NewWithOptions(os.Stderr, log.Options{

     

       13
       13
       +
       		ReportTimestamp: true,

     

       14
       14
       +
       		Prefix:          name,

     

       15
       15
       +
       		Level:           log.DebugLevel,

     

       14
       16
        
       	})

     

       15
       15
       -
       

     

       16
       16
       -
       	var attrs []slog.Attr

     

       17
       17
       -
       	attrs = append(attrs, slog.Attr{Key: "service", Value: slog.StringValue(name)})

     

       18
       18
       -
       	handler.WithAttrs(attrs)

     

       19
       19
       -
       	return handler

     

       20
       17
        
       }

     

       21
       18
        
       

     

       22
       19
        
       func New(name string) *slog.Logger {

     
···

       49
       46
        
       

     

       50
       47
        
       	return slog.Default()

     

       51
       48
        
       }

     

       49
       49
       +
       

     

       50
       50
       +
       // sublogger derives a new logger from an existing one by appending a suffix to its prefix.

     

       51
       51
       +
       func SubLogger(base *slog.Logger, suffix string) *slog.Logger {

     

       52
       52
       +
       	// try to get the underlying charmbracelet logger

     

       53
       53
       +
       	if cl, ok := base.Handler().(*log.Logger); ok {

     

       54
       54
       +
       		prefix := cl.GetPrefix()

     

       55
       55
       +
       		if prefix != "" {

     

       56
       56
       +
       			prefix = prefix + "/" + suffix

     

       57
       57
       +
       		} else {

     

       58
       58
       +
       			prefix = suffix

     

       59
       59
       +
       		}

     

       60
       60
       +
       		return slog.New(NewHandler(prefix))

     

       61
       61
       +
       	}

     

       62
       62
       +
       

     

       63
       63
       +
       	// Fallback: no known handler type

     

       64
       64
       +
       	return slog.New(NewHandler(suffix))

     

       65
       65
       +
       }