Skip to content

Add structured logs with logrus library, for logs that contain hashes #330

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

Merged
toastwaffle merged 3 commits into from
Sep 1, 2025
Merged

Add structured logs with logrus library, for logs that contain hashes #330

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
6f47493
Add structured logs with log/slog library, for logs that contain hashes
chryssakr Aug 18, 2025
45c840e
Use logrus instead of slog for consistency with the common log library
chryssakr Aug 20, 2025
841c9e2
Update dependencies
chryssakr Aug 22, 2025
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
2 changes: 1 addition & 1 deletion discern/BUILD
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,9 +8,9 @@ go_binary(
"///third_party/go/github.com_bazelbuild_remote-apis//build/bazel/remote/execution/v2",
"///third_party/go/github.com_dustin_go-humanize//:go-humanize",
"///third_party/go/github.com_peterebden_go-cli-init_v4//logging",
"///third_party/go/google.golang.org_protobuf//proto",
"//cli",
"//purity/gc",
"//rexclient",
"//third_party/go:golang-protobuf",
],
)
10 changes: 6 additions & 4 deletions elan/rpc/BUILD
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@ go_library(
"///third_party/go/github.com_klauspost_compress//zstd",
"///third_party/go/github.com_peterebden_go-cli-init_v4//logging",
"///third_party/go/github.com_prometheus_client_golang//prometheus",
"///third_party/go/github.com_sirupsen_logrus//:logrus",
"///third_party/go/gocloud.dev//blob",
"///third_party/go/gocloud.dev//blob/fileblob",
"///third_party/go/gocloud.dev//blob/gcsblob",
Expand All @@ -32,12 +33,13 @@ go_library(
"///third_party/go/google.golang.org_api//googleapi",
"///third_party/go/google.golang.org_genproto_googleapis_bytestream//:bytestream",
"///third_party/go/google.golang.org_genproto_googleapis_rpc//status",
"///third_party/go/google.golang.org_grpc//:grpc",
"///third_party/go/google.golang.org_grpc//codes",
"///third_party/go/google.golang.org_grpc//health/grpc_health_v1",
"///third_party/go/google.golang.org_grpc//status",
"//grpcutil",
"//proto/purity",
"//redis",
"//rexclient",
"//third_party/go:grpc",
],
)

Expand All @@ -48,10 +50,10 @@ go_test(
deps = [
":rpc",
"///third_party/go/github.com_klauspost_compress//zstd",
"///third_party/go/google.golang.org_genproto_googleapis_bytestream//:bytestream",
"//grpcutil",
"///third_party/go/github.com_stretchr_testify//assert",
"///third_party/go/github.com_stretchr_testify//require",
"///third_party/go/google.golang.org_genproto_googleapis_bytestream//:bytestream",
"//grpcutil",
],
)

Expand Down
5 changes: 4 additions & 1 deletion elan/rpc/gc.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,7 @@ import (
pb "github.com/bazelbuild/remote-apis/build/bazel/remote/execution/v2"
"github.com/hashicorp/go-multierror"
"github.com/klauspost/compress/zstd"
"github.com/sirupsen/logrus"
"gocloud.dev/blob"
"google.golang.org/grpc/codes"
"google.golang.org/grpc/status"
Expand Down Expand Up @@ -42,7 +43,9 @@ func (s *server) List(ctx context.Context, req *ppb.ListRequest) (*ppb.ListRespo
// here we need to get the uncompressed size of the blob, otherwise REX SDK will complain about it
if size, err := s.getBlobUncompressedSize(ctx, a.Hash); err != nil {
// this is not an issue for GC, but would be for replication
log.Warningf("failed getting uncompressed size for blob %s (defaulting to compressed size): %v", a.Hash, err)
logr.WithFields(logrus.Fields{
"hash": a.Hash,
}).WithError(err).Warn("failed getting uncompressed size for blob (defaulting to compressed size)")
} else {
a.SizeBytes = int64(size)
}
Expand Down
38 changes: 30 additions & 8 deletions elan/rpc/rpc.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -36,6 +36,7 @@ import (
"github.com/klauspost/compress/zstd"
"github.com/peterebden/go-cli-init/v4/logging"
"github.com/prometheus/client_golang/prometheus"
"github.com/sirupsen/logrus"
"gocloud.dev/blob"
"gocloud.dev/gcerrors"
"golang.org/x/exp/slices"
Expand Down Expand Up @@ -64,6 +65,7 @@ const (
const DefaultMaxSize int64 = 200 * 1012 // 200 Kelly-Bootle standard units

var log = logging.MustGetLogger()

@toastwaffle toastwaffle Aug 20, 2025

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

ah. We did already have another logging library, but it looks like it doesn't support structured logging. We should probably plan to swap out github.com/peterebden/go-cli-init/v4/logging for logrus everywhere (but probably not in this PR)

@Hamishpk what do you think?

@Hamishpk Hamishpk Aug 21, 2025

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Yeah makes sense. Although it looks like we can just replace log with logr here at it should work? log would be better though

var logr = logrus.New()

// emptyHash is the sha256 hash of the empty file.
var emptyHash = digest.Empty.Hash
Expand Down Expand Up @@ -293,7 +295,9 @@ func (s *server) UpdateActionResult(ctx context.Context, req *pb.UpdateActionRes
InstanceName: req.InstanceName,
ActionDigest: req.ActionDigest,
}); err == nil {
log.Debug("Returning existing action result for UpdateActionResult request for %s", req.ActionDigest.Hash)
logr.WithFields(logrus.Fields{
"hash": req.ActionDigest.Hash,
}).Debug("Returning existing action result for UpdateActionResult request")
return ar, nil
}
}
Expand Down Expand Up @@ -403,14 +407,18 @@ func (s *server) BatchUpdateBlobs(ctx context.Context, req *pb.BatchUpdateBlobsR
rr.Status.Message = fmt.Sprintf("Blob sizes do not match (%d / %d)", len(r.Data), r.Digest.SizeBytes)
blobSizeMismatches.Inc()
} else if s.blobExists(ctx, "cas", r.Digest, compressed, true) {
log.Debug("Blob %s already exists remotely", r.Digest.Hash)
logr.WithFields(logrus.Fields{
"hash": r.Digest.Hash,
}).Debug("Blob already exists remotely")
} else if err := s.writeAll(ctx, r.Digest, r.Data, compressed); err != nil {
log.Errorf("Error writing blob %s: %s", r.Digest, err)
rr.Status.Code = int32(status.Code(err))
rr.Status.Message = err.Error()
blobsReceived.WithLabelValues(batchLabel(true, false), compressorLabel(compressed)).Inc()
} else {
log.Debug("Stored blob with digest %s", r.Digest.Hash)
logr.WithFields(logrus.Fields{
"hash": r.Digest.Hash,
}).Debug("Stored blob")
}
wg.Done()
bytesReceived.WithLabelValues(batchLabel(true, false), compressorLabel(compressed)).Add(float64(r.Digest.SizeBytes))
Expand Down Expand Up @@ -496,12 +504,17 @@ func (s *server) Read(req *bs.ReadRequest, srv bs.ByteStream_ReadServer) error {
if err != nil {
return err
}
log.Debug("Received ByteStream.Read request for %s", digest.Hash)
logr.WithFields(logrus.Fields{
"hash": digest.Hash,
}).Debug("Received ByteStream.Read request")
if req.ReadOffset < 0 || req.ReadOffset > digest.SizeBytes {
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)
} else if req.ReadOffset == digest.SizeBytes {
// We know there is nothing left to read, just return immediately.
log.Debug("Completed ByteStream.Read request immediately at final byte %d of %s", digest.SizeBytes, digest.Hash)
logr.WithFields(logrus.Fields{
"hash": digest.Hash,
"bytes": digest.SizeBytes,
}).Debug("Completed ByteStream.Read request immediately at final byte")
return nil
} else if req.ReadLimit == 0 || req.ReadOffset+req.ReadLimit >= digest.SizeBytes {
req.ReadLimit = -1
Expand All @@ -524,7 +537,12 @@ func (s *server) Read(req *bs.ReadRequest, srv bs.ByteStream_ReadServer) error {
return err
}
bytesServed.WithLabelValues(batchLabel(false, true), compressorLabel(compressed)).Add(float64(n))
log.Debug("Completed ByteStream.Read request of %d bytes (starting at %d) for %s in %s", n, req.ReadOffset, digest.Hash, time.Since(start))
logr.WithFields(logrus.Fields{
"hash": digest.Hash,
"bytes": n,
"readOffset": req.ReadOffset,
"duration": time.Since(start),
}).Debug("Completed ByteStream.Read request (starting at readOffset)")
return nil
}

Expand Down Expand Up @@ -587,13 +605,17 @@ func (s *server) Write(srv bs.ByteStream_WriteServer) error {
if err != nil {
return err
}
log.Debug("Received ByteStream.Write request for %s", digest.Hash)
logr.WithFields(logrus.Fields{
"hash": digest.Hash,
}).Debug("Received ByteStream.Write request")
r := &bytestreamReader{stream: srv, buf: req.Data}
if err := s.writeBlob(ctx, "cas", digest, bufio.NewReaderSize(r, 65536), compressed); err != nil {
return err
}
bytesReceived.WithLabelValues(batchLabel(false, true), compressorLabel(compressed)).Add(float64(r.TotalSize))
log.Debug("Stored blob with hash %s", digest.Hash)
logr.WithFields(logrus.Fields{
"hash": digest.Hash,
}).Debug("Stored blob with hash")
blobsReceived.WithLabelValues(batchLabel(false, true), compressorLabel(compressed)).Inc()
return srv.SendAndClose(&bs.WriteResponse{
CommittedSize: r.TotalSize,
Expand Down
2 changes: 1 addition & 1 deletion flair/BUILD
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,11 +5,11 @@ go_binary(
deps = [
"///third_party/go/github.com_peterebden_go-cli-init_v4//flags",
"///third_party/go/github.com_peterebden_go-cli-init_v4//logging",
"///third_party/go/google.golang.org_grpc//:grpc",
"//cli",
"//flair/rpc",
"//flair/trie",
"//grpcutil",
"//third_party/go:grpc",
],
)

Expand Down
4 changes: 3 additions & 1 deletion flair/rpc/BUILD
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -10,14 +10,16 @@ go_library(
"///third_party/go/github.com_golang_protobuf//proto",
"///third_party/go/github.com_peterebden_go-cli-init_v4//logging",
"///third_party/go/github.com_peterebden_go-sri//:go-sri",
"///third_party/go/github.com_sirupsen_logrus//:logrus",
"///third_party/go/golang.org_x_sync//errgroup",
"///third_party/go/google.golang.org_genproto_googleapis_bytestream//:bytestream",
"///third_party/go/google.golang.org_grpc//codes",
"///third_party/go/google.golang.org_grpc//health/grpc_health_v1",
"///third_party/go/google.golang.org_grpc//metadata",
"///third_party/go/google.golang.org_grpc//status",
"//flair/trie",
"//grpcutil",
"//proto/purity",
"//rexclient",
"//third_party/go:grpc",
],
)
8 changes: 7 additions & 1 deletion flair/rpc/rpc.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@
"github.com/golang/protobuf/proto"
"github.com/peterebden/go-cli-init/v4/logging"
"github.com/peterebden/go-sri"
"github.com/sirupsen/logrus"
"golang.org/x/sync/errgroup"
bs "google.golang.org/genproto/googleapis/bytestream"
"google.golang.org/grpc/codes"
Expand All @@ -34,6 +35,7 @@
)

var log = logging.MustGetLogger()
var logr = logrus.New()

// emptyHash is the sha256 hash of the empty file.
var emptyHash = digest.Empty.Hash
Expand Down Expand Up @@ -542,7 +544,7 @@
func (s *server) assetHash(quals []*apb.Qualifier) string {
for _, q := range quals {
if q.Name == "checksum.sri" {
if c, err := sri.NewChecker(q.Value); err == nil {

Check failure on line 547 in flair/rpc/rpc.go

View workflow job for this annotation

GitHub Actions / lint 

undefined: sri (typecheck)
if hashes := c.Expected("sha256"); len(hashes) > 0 {
// Need to convert from base64 to hex...
if b, err := base64.StdEncoding.DecodeString(hashes[0]); err == nil {
Expand Down Expand Up @@ -636,7 +638,11 @@
if (existing.LastAccessed < ageThreshold && ar.LastAccessed >= ageThreshold) || (ar.LastAccessed < ageThreshold && existing.LastAccessed >= ageThreshold) {
existingLastAccessed := time.Unix(existing.LastAccessed, 0)
arLastAccessed := time.Unix(ar.LastAccessed, 0)
log.Debug("AR %s: one replica accessed at %s, one at %s.", ar.Hash, existingLastAccessed, arLastAccessed)
logr.WithFields(logrus.Fields{
"hash": ar.Hash,
"existingLastAccessed": existingLastAccessed,
"lastAccessed": arLastAccessed,
}).Debug("AR: replicas accessed at existingLastAccessed and lastAccessed")
}
// End temporary logging
if existing.LastAccessed < ar.LastAccessed {
Expand Down
8 changes: 6 additions & 2 deletions flair/trie/BUILD
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -11,9 +11,11 @@ go_library(
"///third_party/go/github.com_hashicorp_go-multierror//:go-multierror",
"///third_party/go/github.com_peterebden_go-cli-init_v4//logging",
"///third_party/go/google.golang.org_genproto_googleapis_bytestream//:bytestream",
"///third_party/go/google.golang.org_grpc//:grpc",
"///third_party/go/google.golang.org_grpc//codes",
"///third_party/go/google.golang.org_grpc//health/grpc_health_v1",
"///third_party/go/google.golang.org_grpc//status",
"//proto/purity",
"//third_party/go:grpc",
],
)

Expand All @@ -23,7 +25,9 @@ go_test(
deps = [
":trie",
"///third_party/go/github.com_hashicorp_go-multierror//:go-multierror",
"//third_party/go:grpc",
"///third_party/go/github.com_stretchr_testify//assert",
"///third_party/go/google.golang.org_grpc//:grpc",
"///third_party/go/google.golang.org_grpc//codes",
"///third_party/go/google.golang.org_grpc//status",
],
)
1 change: 1 addition & 0 deletions go.mod
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -26,6 +26,7 @@ require (
github.com/prometheus/client_golang v1.18.0
github.com/prometheus/common v0.45.0
github.com/shirou/gopsutil v3.21.11+incompatible
github.com/sirupsen/logrus v1.9.3
github.com/stretchr/testify v1.8.4
github.com/thought-machine/http-admin v1.1.1
go.uber.org/automaxprocs v1.5.3
Expand Down
4 changes: 4 additions & 0 deletions go.sum
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -273,6 +273,8 @@ github.com/shirou/gopsutil v3.21.11+incompatible h1:+1+c1VGhc88SSonWP6foOcLhvnKl
github.com/shirou/gopsutil v3.21.11+incompatible/go.mod h1:5b4v6he4MtMOwMlS0TUMTu2PcXUg8+E1lC7eC3UO/RA=
github.com/sirupsen/logrus v1.2.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPxbbu5VWo=
github.com/sirupsen/logrus v1.4.2/go.mod h1:tLMulIdttU9McNUspp0xgXVQah82FyeX6MwdIuYE2rE=
github.com/sirupsen/logrus v1.9.3 h1:dueUQJ1C2q9oE3F7wvmSGAaVtTmUizReu6fjN8uqzbQ=
github.com/sirupsen/logrus v1.9.3/go.mod h1:naHLuLoDiP4jHNo9R0sCBMtWGeIprob74mVsIT4qYEQ=
github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
github.com/stretchr/objx v0.1.1/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
github.com/stretchr/objx v0.4.0/go.mod h1:YvHI0jy2hoMjB+UWwv71VJQ9isScKT/TqJzVSSt89Yw=
Expand All @@ -281,6 +283,7 @@ github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXf
github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4=
github.com/stretchr/testify v1.5.1/go.mod h1:5W2xD1RspED5o8YsWQXVCued0rvSQ+mT+I5cxcmMvtA=
github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU=
github.com/stretchr/testify v1.8.1/go.mod h1:w2LPCIKwWwSfY2zedu0+kehJoqGctiVI29o6fzry7u4=
Expand Down Expand Up @@ -385,6 +388,7 @@ golang.org/x/sys v0.0.0-20210507014357-30e306a8bba5/go.mod h1:oPkhp1MJrh7nUepCBc
golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
golang.org/x/sys v0.0.0-20220408201424-a24fb2fb8a0f/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
golang.org/x/sys v0.0.0-20220520151302-bc2c85ada10a/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
golang.org/x/sys v0.0.0-20220722155257-8c9f86f7a55f/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
golang.org/x/sys v0.0.0-20221010170243-090e33056c14/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
golang.org/x/sys v0.1.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
Expand Down
4 changes: 3 additions & 1 deletion grpcutil/BUILD
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,8 @@ go_library(
"///third_party/go/github.com_mostynb_go-grpc-compression//zstd",
"///third_party/go/github.com_peterebden_go-cli-init_v4//logging",
"///third_party/go/github.com_prometheus_client_golang//prometheus",
"///third_party/go/google.golang.org_grpc//:grpc",
"///third_party/go/google.golang.org_grpc//codes",
"///third_party/go/google.golang.org_grpc//credentials",
"///third_party/go/google.golang.org_grpc//encoding/gzip",
"///third_party/go/google.golang.org_grpc//grpclog",
Expand All @@ -16,7 +18,7 @@ go_library(
"///third_party/go/google.golang.org_grpc//keepalive",
"///third_party/go/google.golang.org_grpc//metadata",
"///third_party/go/google.golang.org_grpc//reflection",
"///third_party/go/google.golang.org_grpc//status",
"///third_party/go/gopkg.in_op_go-logging.v1//:go-logging.v1",
"//third_party/go:grpc",
],
)
13 changes: 9 additions & 4 deletions mettle/api/BUILD
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -11,15 +11,18 @@ go_library(
"///third_party/go/github.com_golang_protobuf//ptypes",
"///third_party/go/github.com_peterebden_go-cli-init_v4//logging",
"///third_party/go/github.com_prometheus_client_golang//prometheus",
"///third_party/go/github.com_sirupsen_logrus//:logrus",
"///third_party/go/gocloud.dev//pubsub",
"///third_party/go/google.golang.org_genproto//googleapis/longrunning",
"///third_party/go/google.golang.org_genproto_googleapis_rpc//status",
"///third_party/go/google.golang.org_grpc//:grpc",
"///third_party/go/google.golang.org_grpc//codes",
"///third_party/go/google.golang.org_grpc//metadata",
"///third_party/go/google.golang.org_grpc//status",
"//grpcutil",
"//mettle/common",
"//proto/mettle",
"//rexclient",
"//third_party/go:grpc",
],
)

Expand All @@ -31,14 +34,16 @@ go_test(
"///third_party/go/github.com_bazelbuild_remote-apis//build/bazel/remote/execution/v2",
"///third_party/go/github.com_golang_protobuf//proto",
"///third_party/go/github.com_golang_protobuf//ptypes",
"///third_party/go/github.com_stretchr_testify//assert",
"///third_party/go/github.com_stretchr_testify//require",
"///third_party/go/gocloud.dev//pubsub",
"///third_party/go/google.golang.org_genproto//googleapis/longrunning",
"///third_party/go/google.golang.org_genproto_googleapis_bytestream//:bytestream",
"///third_party/go/google.golang.org_grpc//:grpc",
"///third_party/go/google.golang.org_grpc//codes",
"///third_party/go/google.golang.org_grpc//status",
"//grpcutil",
"//mettle/common",
"//proto/mettle",
"//third_party/go:grpc",
"///third_party/go/github.com_stretchr_testify//require",
"///third_party/go/github.com_stretchr_testify//assert",
],
)
Loading
Loading