Skip to content

Commit 9f4586f

Browse files
committed
Use logrus instead of slog for consistency with the common log library
1 parent b3df585 commit 9f4586f

File tree

11 files changed

+240
-76
lines changed

11 files changed

+240
-76
lines changed

elan/rpc/gc.go

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -4,14 +4,14 @@ import (
44
"context"
55
"fmt"
66
"io"
7-
"log/slog"
87
"path"
98
"strings"
109
"time"
1110

1211
pb "github.com/bazelbuild/remote-apis/build/bazel/remote/execution/v2"
1312
"github.com/hashicorp/go-multierror"
1413
"github.com/klauspost/compress/zstd"
14+
"github.com/sirupsen/logrus"
1515
"gocloud.dev/blob"
1616
"google.golang.org/grpc/codes"
1717
"google.golang.org/grpc/status"
@@ -43,7 +43,9 @@ func (s *server) List(ctx context.Context, req *ppb.ListRequest) (*ppb.ListRespo
4343
// here we need to get the uncompressed size of the blob, otherwise REX SDK will complain about it
4444
if size, err := s.getBlobUncompressedSize(ctx, a.Hash); err != nil {
4545
// this is not an issue for GC, but would be for replication
46-
slog.Warn("failed getting uncompressed size for blob (defaulting to compressed size)", "error", err, "hash", a.Hash)
46+
logr.WithFields(logrus.Fields{
47+
"hash": a.Hash,
48+
}).WithError(err).Warn("failed getting uncompressed size for blob (defaulting to compressed size)")
4749
} else {
4850
a.SizeBytes = int64(size)
4951
}

elan/rpc/rpc.go

Lines changed: 30 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -12,7 +12,6 @@ import (
1212
"fmt"
1313
"io"
1414
"io/ioutil"
15-
"log/slog"
1615
"net"
1716
"os"
1817
"path"
@@ -37,6 +36,7 @@ import (
3736
"github.com/klauspost/compress/zstd"
3837
"github.com/peterebden/go-cli-init/v4/logging"
3938
"github.com/prometheus/client_golang/prometheus"
39+
"github.com/sirupsen/logrus"
4040
"gocloud.dev/blob"
4141
"gocloud.dev/gcerrors"
4242
"golang.org/x/exp/slices"
@@ -65,6 +65,7 @@ const (
6565
const DefaultMaxSize int64 = 200 * 1012 // 200 Kelly-Bootle standard units
6666

6767
var log = logging.MustGetLogger()
68+
var logr = logrus.New()
6869

6970
// emptyHash is the sha256 hash of the empty file.
7071
var emptyHash = digest.Empty.Hash
@@ -294,7 +295,9 @@ func (s *server) UpdateActionResult(ctx context.Context, req *pb.UpdateActionRes
294295
InstanceName: req.InstanceName,
295296
ActionDigest: req.ActionDigest,
296297
}); err == nil {
297-
slog.Debug("Returning existing action result for UpdateActionResult request", "hash", req.ActionDigest.Hash)
298+
logr.WithFields(logrus.Fields{
299+
"hash": req.ActionDigest.Hash,
300+
}).Debug("Returning existing action result for UpdateActionResult request")
298301
return ar, nil
299302
}
300303
}
@@ -404,14 +407,18 @@ func (s *server) BatchUpdateBlobs(ctx context.Context, req *pb.BatchUpdateBlobsR
404407
rr.Status.Message = fmt.Sprintf("Blob sizes do not match (%d / %d)", len(r.Data), r.Digest.SizeBytes)
405408
blobSizeMismatches.Inc()
406409
} else if s.blobExists(ctx, "cas", r.Digest, compressed, true) {
407-
slog.Debug("Blob already exists remotely", "hash", r.Digest.Hash)
410+
logr.WithFields(logrus.Fields{
411+
"hash": r.Digest.Hash,
412+
}).Debug("Blob already exists remotely")
408413
} else if err := s.writeAll(ctx, r.Digest, r.Data, compressed); err != nil {
409414
log.Errorf("Error writing blob %s: %s", r.Digest, err)
410415
rr.Status.Code = int32(status.Code(err))
411416
rr.Status.Message = err.Error()
412417
blobsReceived.WithLabelValues(batchLabel(true, false), compressorLabel(compressed)).Inc()
413418
} else {
414-
slog.Debug("Stored blob", "hash", r.Digest.Hash)
419+
logr.WithFields(logrus.Fields{
420+
"hash": r.Digest.Hash,
421+
}).Debug("Stored blob")
415422
}
416423
wg.Done()
417424
bytesReceived.WithLabelValues(batchLabel(true, false), compressorLabel(compressed)).Add(float64(r.Digest.SizeBytes))
@@ -497,12 +504,17 @@ func (s *server) Read(req *bs.ReadRequest, srv bs.ByteStream_ReadServer) error {
497504
if err != nil {
498505
return err
499506
}
500-
slog.Debug("Received ByteStream.Read request", "hash", digest.Hash)
507+
logr.WithFields(logrus.Fields{
508+
"hash": digest.Hash,
509+
}).Debug("Received ByteStream.Read request")
501510
if req.ReadOffset < 0 || req.ReadOffset > digest.SizeBytes {
502511
return status.Errorf(codes.OutOfRange, "Invalid Read() request; offset %d is outside the range of blob %s which is %d bytes long", req.ReadOffset, digest.Hash, digest.SizeBytes)
503512
} else if req.ReadOffset == digest.SizeBytes {
504513
// We know there is nothing left to read, just return immediately.
505-
slog.Debug("Completed ByteStream.Read request immediately at final byte", "bytes", digest.SizeBytes, "hash", digest.Hash)
514+
logr.WithFields(logrus.Fields{
515+
"hash": digest.Hash,
516+
"bytes": digest.SizeBytes,
517+
}).Debug("Completed ByteStream.Read request immediately at final byte")
506518
return nil
507519
} else if req.ReadLimit == 0 || req.ReadOffset+req.ReadLimit >= digest.SizeBytes {
508520
req.ReadLimit = -1
@@ -525,7 +537,12 @@ func (s *server) Read(req *bs.ReadRequest, srv bs.ByteStream_ReadServer) error {
525537
return err
526538
}
527539
bytesServed.WithLabelValues(batchLabel(false, true), compressorLabel(compressed)).Add(float64(n))
528-
slog.Debug("Completed ByteStream.Read request of bytes_number bytes (starting at read_offset)", "bytes_number", n, "read_offset", req.ReadOffset, "hash", digest.Hash, "duration", time.Since(start))
540+
logr.WithFields(logrus.Fields{
541+
"hash": digest.Hash,
542+
"bytes": n,
543+
"readOffset": req.ReadOffset,
544+
"duration": time.Since(start),
545+
}).Debug("Completed ByteStream.Read request (starting at readOffset)")
529546
return nil
530547
}
531548

@@ -588,13 +605,17 @@ func (s *server) Write(srv bs.ByteStream_WriteServer) error {
588605
if err != nil {
589606
return err
590607
}
591-
slog.Debug("Received ByteStream.Write request", "hash", digest.Hash)
608+
logr.WithFields(logrus.Fields{
609+
"hash": digest.Hash,
610+
}).Debug("Received ByteStream.Write request")
592611
r := &bytestreamReader{stream: srv, buf: req.Data}
593612
if err := s.writeBlob(ctx, "cas", digest, bufio.NewReaderSize(r, 65536), compressed); err != nil {
594613
return err
595614
}
596615
bytesReceived.WithLabelValues(batchLabel(false, true), compressorLabel(compressed)).Add(float64(r.TotalSize))
597-
slog.Debug("Stored blob with hash", "hash", digest.Hash)
616+
logr.WithFields(logrus.Fields{
617+
"hash": digest.Hash,
618+
}).Debug("Stored blob with hash")
598619
blobsReceived.WithLabelValues(batchLabel(false, true), compressorLabel(compressed)).Inc()
599620
return srv.SendAndClose(&bs.WriteResponse{
600621
CommittedSize: r.TotalSize,

flair/rpc/rpc.go

Lines changed: 7 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,6 @@ import (
88
"encoding/hex"
99
"fmt"
1010
"io"
11-
"log/slog"
1211
"regexp"
1312
"strings"
1413
"sync"
@@ -21,6 +20,7 @@ import (
2120
"github.com/golang/protobuf/proto"
2221
"github.com/peterebden/go-cli-init/v4/logging"
2322
"github.com/peterebden/go-sri"
23+
"github.com/sirupsen/logrus"
2424
"golang.org/x/sync/errgroup"
2525
bs "google.golang.org/genproto/googleapis/bytestream"
2626
"google.golang.org/grpc/codes"
@@ -35,6 +35,7 @@ import (
3535
)
3636

3737
var log = logging.MustGetLogger()
38+
var logr = logrus.New()
3839

3940
// emptyHash is the sha256 hash of the empty file.
4041
var emptyHash = digest.Empty.Hash
@@ -637,7 +638,11 @@ func (s *server) List(ctx context.Context, req *ppb.ListRequest) (*ppb.ListRespo
637638
if (existing.LastAccessed < ageThreshold && ar.LastAccessed >= ageThreshold) || (ar.LastAccessed < ageThreshold && existing.LastAccessed >= ageThreshold) {
638639
existingLastAccessed := time.Unix(existing.LastAccessed, 0)
639640
arLastAccessed := time.Unix(ar.LastAccessed, 0)
640-
slog.Debug("AR: replicas accessed at existingLastAccessed and lastAccessed", "hash", ar.Hash, "existingLastAccessed", existingLastAccessed, "lastAccessed", arLastAccessed)
641+
logr.WithFields(logrus.Fields{
642+
"hash": ar.Hash,
643+
"existingLastAccessed": existingLastAccessed,
644+
"lastAccessed": arLastAccessed,
645+
}).Debug("AR: replicas accessed at existingLastAccessed and lastAccessed")
641646
}
642647
// End temporary logging
643648
if existing.LastAccessed < ar.LastAccessed {

go.mod

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,7 @@ require (
2626
github.com/prometheus/client_golang v1.18.0
2727
github.com/prometheus/common v0.45.0
2828
github.com/shirou/gopsutil v3.21.11+incompatible
29+
github.com/sirupsen/logrus v1.9.3
2930
github.com/stretchr/testify v1.8.4
3031
github.com/thought-machine/http-admin v1.1.1
3132
go.uber.org/automaxprocs v1.5.3

go.sum

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -273,6 +273,8 @@ github.com/shirou/gopsutil v3.21.11+incompatible h1:+1+c1VGhc88SSonWP6foOcLhvnKl
273273
github.com/shirou/gopsutil v3.21.11+incompatible/go.mod h1:5b4v6he4MtMOwMlS0TUMTu2PcXUg8+E1lC7eC3UO/RA=
274274
github.com/sirupsen/logrus v1.2.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPxbbu5VWo=
275275
github.com/sirupsen/logrus v1.4.2/go.mod h1:tLMulIdttU9McNUspp0xgXVQah82FyeX6MwdIuYE2rE=
276+
github.com/sirupsen/logrus v1.9.3 h1:dueUQJ1C2q9oE3F7wvmSGAaVtTmUizReu6fjN8uqzbQ=
277+
github.com/sirupsen/logrus v1.9.3/go.mod h1:naHLuLoDiP4jHNo9R0sCBMtWGeIprob74mVsIT4qYEQ=
276278
github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
277279
github.com/stretchr/objx v0.1.1/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
278280
github.com/stretchr/objx v0.4.0/go.mod h1:YvHI0jy2hoMjB+UWwv71VJQ9isScKT/TqJzVSSt89Yw=
@@ -281,6 +283,7 @@ github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXf
281283
github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
282284
github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4=
283285
github.com/stretchr/testify v1.5.1/go.mod h1:5W2xD1RspED5o8YsWQXVCued0rvSQ+mT+I5cxcmMvtA=
286+
github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
284287
github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
285288
github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU=
286289
github.com/stretchr/testify v1.8.1/go.mod h1:w2LPCIKwWwSfY2zedu0+kehJoqGctiVI29o6fzry7u4=
@@ -385,6 +388,7 @@ golang.org/x/sys v0.0.0-20210507014357-30e306a8bba5/go.mod h1:oPkhp1MJrh7nUepCBc
385388
golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
386389
golang.org/x/sys v0.0.0-20220408201424-a24fb2fb8a0f/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
387390
golang.org/x/sys v0.0.0-20220520151302-bc2c85ada10a/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
391+
golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
388392
golang.org/x/sys v0.0.0-20220722155257-8c9f86f7a55f/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
389393
golang.org/x/sys v0.0.0-20221010170243-090e33056c14/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
390394
golang.org/x/sys v0.1.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=

mettle/api/api.go

Lines changed: 27 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -4,7 +4,6 @@ package api
44
import (
55
"context"
66
"fmt"
7-
"log/slog"
87
"maps"
98
"net"
109
"slices"
@@ -20,6 +19,7 @@ import (
2019
"github.com/golang/protobuf/ptypes"
2120
clilogging "github.com/peterebden/go-cli-init/v4/logging"
2221
"github.com/prometheus/client_golang/prometheus"
22+
"github.com/sirupsen/logrus"
2323
bpb "github.com/thought-machine/please-servers/proto/mettle"
2424
"gocloud.dev/pubsub"
2525
"google.golang.org/genproto/googleapis/longrunning"
@@ -35,6 +35,7 @@ import (
3535
)
3636

3737
var log = clilogging.MustGetLogger()
38+
var logr = logrus.New()
3839

3940
const timeout = 10 * time.Second
4041

@@ -303,10 +304,17 @@ func (s *server) Execute(req *pb.ExecuteRequest, stream pb.Execution_ExecuteServ
303304
return err
304305
}
305306
if md := s.contextMetadata(stream.Context()); md != nil {
306-
slog.Debug("Received an ExecuteRequest",
307-
"hash", req.ActionDigest.Hash, "toolName", md.ToolDetails.ToolName, "toolVersion", md.ToolDetails.ToolVersion, "actionID", md.ActionId, "correlationID", md.CorrelatedInvocationsId)
307+
logr.WithFields(logrus.Fields{
308+
"hash": req.ActionDigest.Hash,
309+
"toolName": md.ToolDetails.ToolName,
310+
"toolVersion": md.ToolDetails.ToolVersion,
311+
"actionID": md.ActionId,
312+
"correlationID": md.CorrelatedInvocationsId,
313+
}).Debug("Received an ExecuteRequest")
308314
} else {
309-
slog.Debug("Received an ExecuteRequest", "hash", req.ActionDigest.Hash)
315+
logr.WithFields(logrus.Fields{
316+
"hash": req.ActionDigest.Hash,
317+
}).Debug("Received an ExecuteRequest")
310318
}
311319

312320
// If we're allowed to check the cache, see if this one has already been done.
@@ -391,14 +399,18 @@ func (s *server) streamEvents(digest *pb.Digest, ch <-chan *longrunning.Operatio
391399
for op := range ch {
392400
op.Name = digest.Hash
393401
if err := stream.Send(op); err != nil {
394-
slog.Warn("Failed to forward event", "hash", digest.Hash, "error", err)
402+
logr.WithFields(logrus.Fields{
403+
"hash": digest.Hash,
404+
}).WithError(err).Warn("Failed to forward event")
395405
return err
396406
}
397407
if op.Done {
398408
break
399409
}
400410
}
401-
slog.Debug("Completed stream", "hash", digest.Hash)
411+
logr.WithFields(logrus.Fields{
412+
"hash": digest.Hash,
413+
}).Debug("Completed stream")
402414
return nil
403415
}
404416

@@ -422,7 +434,9 @@ func (s *server) eventStream(digest *pb.Digest, create bool) (<-chan *longrunnin
422434
LastUpdate: time.Now(),
423435
}
424436
s.jobs[digest.Hash] = j
425-
slog.Debug("Created job", "hash", digest.Hash)
437+
logr.WithFields(logrus.Fields{
438+
"hash": digest.Hash,
439+
}).Debug("Created job")
426440
totalRequests.Inc()
427441
created = true
428442
} else if create && time.Since(j.LastUpdate) >= resumptionTime {
@@ -434,7 +448,9 @@ func (s *server) eventStream(digest *pb.Digest, create bool) (<-chan *longrunnin
434448
j.Done = false
435449
created = true
436450
} else {
437-
slog.Debug("Resuming existing job", "hash", digest.Hash)
451+
logr.WithFields(logrus.Fields{
452+
"hash": digest.Hash,
453+
}).Debug("Resuming existing job")
438454
}
439455
ch := make(chan *longrunning.Operation, 100)
440456
if !created && j.Current != nil {
@@ -458,7 +474,9 @@ func (s *server) stopStream(digest *pb.Digest, ch <-chan *longrunning.Operation)
458474
defer s.mutex.Unlock()
459475
job, present := s.jobs[digest.Hash]
460476
if !present {
461-
slog.Warn("stopStream for non-existent job", "hash", digest.Hash)
477+
logr.WithFields(logrus.Fields{
478+
"hash": digest.Hash,
479+
}).Warn("stopStream for non-existent job")
462480
return
463481
}
464482
job.Streams = slices.DeleteFunc(job.Streams, func(stream chan *longrunning.Operation) bool {

mettle/worker/download.go

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,6 @@ import (
88
"fmt"
99
"io"
1010
"io/ioutil"
11-
"log/slog"
1211
"os"
1312
"path"
1413
"strings"
@@ -19,6 +18,7 @@ import (
1918
pb "github.com/bazelbuild/remote-apis/build/bazel/remote/execution/v2"
2019
"github.com/golang/protobuf/proto"
2120
"github.com/klauspost/compress/zstd"
21+
"github.com/sirupsen/logrus"
2222
"golang.org/x/sync/errgroup"
2323
"google.golang.org/grpc/codes"
2424
grpcstatus "google.golang.org/grpc/status"
@@ -89,7 +89,11 @@ func (w *worker) createDirectory(dirs map[string]*pb.Directory, files map[sdkdig
8989
}
9090
if usePacks {
9191
if dg := rexclient.PackDigest(dir); dg.Hash != "" {
92-
slog.Debug("Replacing dir with pack digest", "root", root, "hash", dg.Hash, "size", dg.Size)
92+
logr.WithFields(logrus.Fields{
93+
"hash": dg.Hash,
94+
"root": root,
95+
"size": dg.Size,
96+
}).Debug("Replacing dir with pack digest")
9397
packs[dg] = append(packs[dg], root)
9498
return nil
9599
}

0 commit comments

Comments
 (0)