Repository: clouditor/clouditor
Pull request #698 (2022-05-22 09:07:57)

Log optimizations
- Log optimizations
- Adding ID field to streams debug messages


codecov[bot]: # [Codecov](https://codecov.io/gh/clouditor/clouditor/pull/698?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=clouditor) Report
> Merging [#698](https://codecov.io/gh/clouditor/clouditor/pull/698?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=clouditor) (b0476b5) into [main](https://codecov.io/gh/clouditor/clouditor/commit/275f86ebaf140b1fffa15a1d8a8153ce16683b27?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=clouditor) (275f86e) will **decrease** coverage by `0.01%`.
> The diff coverage is `66.66%`.

```diff
@@            Coverage Diff             @@
##             main     #698      +/-   ##
==========================================
- Coverage   81.48%   81.47%   -0.02%     
==========================================
  Files          65       65              
  Lines        6072     6101      +29     
==========================================
+ Hits         4948     4971      +23     
- Misses        865      870       +5     
- Partials      259      260       +1     
```

| Flag | Coverage Δ | |
|---|---|---|
| unittests | `81.47% <66.66%> (-0.02%)` | :arrow_down: |

Flags with carried forward coverage won't be shown. [Click here](https://docs.codecov.io/docs/carryforward-flags?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=clouditor#carryforward-flags-in-the-pull-request-comment) to find out more.

| [Impacted Files](https://codecov.io/gh/clouditor/clouditor/pull/698?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=clouditor) | Coverage Δ | |
|---|---|---|
| [api/streams.go](https://codecov.io/gh/clouditor/clouditor/pull/698/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=clouditor#diff-YXBpL3N0cmVhbXMuZ28=) | `87.23% <65.51%> (-5.69%)` | :arrow_down: |
| [service/assessment/assessment.go](https://codecov.io/gh/clouditor/clouditor/pull/698/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=clouditor#diff-c2VydmljZS9hc3Nlc3NtZW50L2Fzc2Vzc21lbnQuZ28=) | `83.33% <100.00%> (-0.05%)` | :arrow_down: |
| [service/evidence/evidence\_store.go](https://codecov.io/gh/clouditor/clouditor/pull/698/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=clouditor#diff-c2VydmljZS9ldmlkZW5jZS9ldmlkZW5jZV9zdG9yZS5nbw==) | `93.47% <0.00%> (+0.14%)` | :arrow_up: |
| [service/discovery/azure/azure.go](https://codecov.io/gh/clouditor/clouditor/pull/698/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=clouditor#diff-c2VydmljZS9kaXNjb3ZlcnkvYXp1cmUvYXp1cmUuZ28=) | `84.41% <0.00%> (+5.19%)` | :arrow_up: |

------

[Continue to review full report at Codecov](https://codecov.io/gh/clouditor/clouditor/pull/698?src=pr&el=continue&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=clouditor).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=clouditor)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/clouditor/clouditor/pull/698?src=pr&el=footer&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=clouditor). Last update [275f86e...b0476b5](https://codecov.io/gh/clouditor/clouditor/pull/698?src=pr&el=lastupdated&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=clouditor). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=clouditor).


Patch:
diff --git a/api/streams.go b/api/streams.go
index 042ba28c..59b8606a 100644
--- a/api/streams.go
+++ b/api/streams.go
@@ -34,6 +34,7 @@ import (
 	"github.com/sirupsen/logrus"
 	"google.golang.org/grpc"
 	"google.golang.org/protobuf/proto"
+	"google.golang.org/protobuf/reflect/protoreflect"
 	"google.golang.org/protobuf/types/known/emptypb"
 )
 
@@ -41,6 +42,9 @@ var (
 	ErrMissingInitFunc = errors.New("missing stream initializer function")
 )
 
+// IDField is the name of the ID field used in protobuf messages
+const IDField = "id"
+
 // StreamChannelOf provides a channel around a connection to a grpc.ClientStream to send messages of type MsgType to
 // that particular stream, using an internal go routine. This is necessary, because gRPC does not allow sending to a
 // stream from multiple goroutines directly.
@@ -202,7 +206,16 @@ func (c *StreamChannelOf[StreamType, MsgType]) sendLoop(s *StreamsOf[StreamType,
 			return
 		}
 
-		s.log.Debugf("Message sent to %s (%s)", c.component, c.target)
+		// Some protobuf refletion magic to print more meaningful debug messages. Since this causes some performance
+		// drawbacks, we are only doing this if DEBUG level is enabled.
+		if logrus.IsLevelEnabled(logrus.DebugLevel) {
+			id := extractID(m)
+			if id != "" {
+				s.log.Debugf("%T containing id %s sent to %s (%s)", m, id, c.component, c.target)
+			} else {
+				s.log.Debugf("%T sent to %s (%s)", m, c.component, c.target)
+			}
+		}
 	}
 }
 
@@ -239,3 +252,39 @@ func (c *StreamChannelOf[StreamType, MsgType]) Send(msg MsgType) {
 func defaultLog() *logrus.Entry {
 	return logrus.NewEntry(logrus.StandardLogger())
 }
+
+// extractID uses a simple heuristic to extract an ID field out of a protobuf message. It assumes that the protobuf
+// message either directly has an ID field or that the last field of the message contains another protobuf message that
+// contains ID. The latter is a typical scenario for request and response messages.
+//
+// This function uses the protoreflect package and the caller needs to be aware of potential performance drawbacks of
+// using reflection.
+func extractID(msg proto.Message) string {
+	var (
+		inner any
+		ok    bool
+		r     protoreflect.Message
+	)
+	// Try the message directly
+	r = msg.ProtoReflect()
+	fd := r.Descriptor().Fields().ByName(IDField)
+	if fd != nil {
+		return r.Get(fd).String()
+	}
+
+	// Otherwise try to go one level "deeper", e.g., to retrieve the inner message in a request/response message.
+	fields := r.Descriptor().Fields()
+	fd = fields.Get(fields.Len() - 1)
+	if fd == nil {
+		return ""
+	}
+
+	// Retrieve the value of the inner message
+	inner = r.Get(fd).Interface()
+	if r, ok = inner.(protoreflect.Message); !ok {
+		return ""
+	}
+
+	// And try to extract the ID based on it
+	return extractID(r.Interface())
+}
diff --git a/service/assessment/assessment.go b/service/assessment/assessment.go
index ec07080a..89dcd040 100644
--- a/service/assessment/assessment.go
+++ b/service/assessment/assessment.go
@@ -313,7 +313,7 @@ func (svc *Service) AssessEvidences(stream assessment.Assessment_AssessEvidences
 func (svc *Service) handleEvidence(ev *evidence.Evidence, resourceId string) (err error) {
 	var types []string
 
-	log.Debugf("Evaluating evidence %s (%s) collected by %s at %v", ev.Id, resourceId, ev.ToolId, ev.Timestamp)
+	log.Debugf("Evaluating evidence %s (%s) collected by %s at %s", ev.Id, resourceId, ev.ToolId, ev.Timestamp.AsTime())
 	log.Tracef("Evidence: %+v", ev)
 
 	evaluations, err := svc.pe.Eval(ev, svc)
@@ -611,7 +611,6 @@ func (svc *Service) recvEventsLoop() {
 // initOrchestratorClient set the orchestrator client
 func (svc *Service) initOrchestratorClient() error {
 	if svc.orchestratorClient != nil {
-		log.Debug("Orchestrator client is already initialized.")
 		return nil
 	}
 


Test patch:
diff --git a/api/streams_test.go b/api/streams_test.go
index de2187a9..887919cf 100644
--- a/api/streams_test.go
+++ b/api/streams_test.go
@@ -32,6 +32,7 @@ import (
 	"testing"
 
 	"clouditor.io/clouditor/api/assessment"
+	"clouditor.io/clouditor/api/evidence"
 	"github.com/stretchr/testify/assert"
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/metadata"
@@ -244,3 +245,44 @@ func (m mockClientStream) SendMsg(interface{}) error {
 func (mockClientStream) RecvMsg(interface{}) error {
 	return nil
 }
+
+func Test_extractID(t *testing.T) {
+	type args struct {
+		msg proto.Message
+	}
+	tests := []struct {
+		name string
+		args args
+		want string
+	}{
+		{
+			name: "ID in message",
+			args: args{
+				msg: &evidence.Evidence{Id: "MyID"},
+			},
+			want: "MyID",
+		},
+		{
+			name: "ID in response",
+			args: args{
+				msg: &assessment.AssessEvidenceRequest{Evidence: &evidence.Evidence{Id: "MyID"}},
+			},
+			want: "MyID",
+		},
+		{
+			name: "No ID",
+			args: args{
+				msg: &assessment.MinMax{},
+			},
+			want: "",
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			if got := extractID(tt.args.msg); got != tt.want {
+				t.Errorf("extractID() = %v, want %v", got, tt.want)
+			}
+		})
+	}
+}