Adds more debug logging to help figure out OIDC/RBAC issues

core/clustersmngr/factory.go

@@ -13,6 +13,7 @@ import (
 	"github.com/hashicorp/go-multierror"
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/weaveworks/weave-gitops/core/clustersmngr/cluster"
+	"github.com/weaveworks/weave-gitops/core/logger"
 	"github.com/weaveworks/weave-gitops/core/nsaccess"
 	"github.com/weaveworks/weave-gitops/pkg/featureflags"
 	"github.com/weaveworks/weave-gitops/pkg/server/auth"
@@ -382,6 +383,8 @@ func (cf *clustersManager) updateNamespacesWithClient(ctx context.Context, creat
 		}
 	}
 
+	cf.log.V(logger.LogLevelDebug).Info("Updated namespaces cache", "namespaces", clusterNamespacesLogValue(cf.clustersNamespaces.namespaces))
+
 	opsUpdateNamespaces.Inc()
 
 	return result.ErrorOrNil()
@@ -589,13 +592,17 @@ func (cf *clustersManager) userNsList(ctx context.Context, user *auth.UserPrinci
 		if err != nil {
 			// This may not completely fail the request, e.g. if some of the clusters
 			// are able to respond with their namespaces. So log the error and continue.
-			cf.log.Error(err, "failed updating namespaces from user client")
+			cf.log.Error(err, "Error updating namespaces from user client", "user", user)
 		}
 	}
 
 	cf.UpdateUserNamespaces(ctx, user)
 
-	return cf.GetUserNamespaces(user)
+	userNamespaces = cf.GetUserNamespaces(user)
+
+	cf.log.V(logger.LogLevelDebug).Info("Updated namespace access cache for user", "userNamespaces", clusterNamespacesLogValue(userNamespaces), "user", user, "ttl", userNamespaceTTL.String())
+
+	return userNamespaces
 }
 
 func (cf *clustersManager) getOrCreateClient(ctx context.Context, user *auth.UserPrincipal, cluster cluster.Cluster) (client.Client, error) {
@@ -608,7 +615,10 @@ func (cf *clustersManager) getOrCreateClient(ctx context.Context, user *auth.Use
 		isServer = true
 	}
 
+	log := cf.log.WithValues("cluster", cluster.GetName(), "user", user, "isServer", isServer, "ttl", usersClientsTTL.String())
+
 	if client, found := cf.usersClients.Get(user, cluster.GetName()); found {
+		log.V(logger.LogLevelDebug).Info("Client found in cache")
 		return client, nil
 	}
 
@@ -631,5 +641,7 @@ func (cf *clustersManager) getOrCreateClient(ctx context.Context, user *auth.Use
 
 	cf.usersClients.Set(user, cluster.GetName(), client)
 
+	log.V(logger.LogLevelDebug).Info("Client created and added to cache")
+
 	return client, nil
 }

core/clustersmngr/logging.go

@@ -0,0 +1,37 @@
+package clustersmngr
+
+import (
+	"sort"
+
+	v1 "k8s.io/api/core/v1"
+)
+
+type namespacesSlice struct {
+	namespaceSample []string
+	namespaceCount  int
+}
+
+// clusterNamespacesLogValues returns a map of cluster names to a slice of namespaces
+// that are on that cluster. The slice is limited to 3 namespaces, and the total
+// number of namespaces is also included.
+func clusterNamespacesLogValue(clusterNamespaces map[string][]v1.Namespace) map[string]namespacesSlice {
+	out := map[string]namespacesSlice{}
+	for cluster, namespaces := range clusterNamespaces {
+		namespaceNames := []string{}
+		for _, n := range namespaces {
+			namespaceNames = append(namespaceNames, n.Name)
+		}
+		sort.Strings(namespaceNames)
+
+		if len(namespaceNames) > 3 {
+			namespaceNames = namespaceNames[:3]
+		}
+
+		out[cluster] = namespacesSlice{
+			namespaceSample: namespaceNames,
+			namespaceCount:  len(namespaces),
+		}
+	}
+
+	return out
+}

core/clustersmngr/logging_test.go

@@ -0,0 +1,73 @@
+package clustersmngr
+
+import (
+	"testing"
+
+	. "github.com/onsi/gomega"
+	v1 "k8s.io/api/core/v1"
+	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
+)
+
+func TestClusterNamespacesLogValue(t *testing.T) {
+	g := NewGomegaWithT(t)
+
+	nss := func(names ...string) []v1.Namespace {
+		var namespaces []v1.Namespace
+		for _, name := range names {
+			namespaces = append(namespaces, v1.Namespace{
+				ObjectMeta: metav1.ObjectMeta{
+					Name: name,
+				},
+			})
+		}
+		return namespaces
+	}
+
+	tests := []struct {
+		name              string
+		clusterNamespaces map[string][]v1.Namespace
+		expected          map[string]namespacesSlice
+	}{
+		{
+			name:              "empty",
+			clusterNamespaces: map[string][]v1.Namespace{},
+			expected:          map[string]namespacesSlice{},
+		},
+		{
+			name: "one cluster",
+			clusterNamespaces: map[string][]v1.Namespace{
+				"cluster1": nss("ns1", "ns2"),
+			},
+			expected: map[string]namespacesSlice{
+				"cluster1": {
+					namespaceSample: []string{"ns1", "ns2"},
+					namespaceCount:  2,
+				},
+			},
+		},
+		{
+			name: "two clusters",
+			clusterNamespaces: map[string][]v1.Namespace{
+				"cluster1": nss("ns1", "ns2"),
+				"cluster2": nss("ns3", "ns4", "ns5", "ns6"),
+			},
+			expected: map[string]namespacesSlice{
+				"cluster1": {
+					namespaceSample: []string{"ns1", "ns2"},
+					namespaceCount:  2,
+				},
+				"cluster2": {
+					namespaceSample: []string{"ns3", "ns4", "ns5"},
+					namespaceCount:  4,
+				},
+			},
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			result := clusterNamespacesLogValue(tt.clusterNamespaces)
+			g.Expect(result).To(Equal(tt.expected))
+		})
+	}
+}

doc/style.md

@@ -2,6 +2,8 @@
 
 This documents describe a set of conventions to be used during development of this project. These rules are not set in stone and if you feel like they should be changed please open a new PR so we can have a documented discussion.
 
+## Javascript
+
 ### Recommended JavaScript Snippets
 
 To create a new styled React component (with typescript):
@@ -33,21 +35,79 @@ To create a new styled React component (with typescript):
 }
 ```
 
+## Golang
 
 ### Error names
+
 Error variables should be called just `err` unless you need to return multiple errors.
 
 Good:
+
 ```go
 err := client.Update()
 if err := nil {
     return err
 }
 ```
+
 Bad:
+
 ```go
 clientErr := client.Update()
 if clientErr := nil {
     return err
 }
 ```
+
+### Logging
+
+Weave Gitops uses structured logging. The Kubernetes community has a [great guide](https://github.com/kubernetes/community/blob/d7ab088079c96891cee9bbcc88a78649acdf49f1/contributors/devel/sig-instrumentation/migration-to-structured-logging.md) on doing this well.
+
+Here are some terse highlights but the whole thing is worth reading.
+
+#### [On logging style](https://github.com/kubernetes/community/blob/d7ab088079c96891cee9bbcc88a78649acdf49f1/contributors/devel/sig-instrumentation/migration-to-structured-logging.md#remove-string-formatting-from-log-message)
+
+> - Start from a capital letter.
+> - Do not end the message with a period.
+> - Use active voice. Use complete sentences when there is an acting subject ("A could not do B") or omit the subject if the subject would be the program itself ("Could not do B").
+> - Use past tense ("Could not delete B" instead of "Cannot delete B")
+> - When referring to an object, state what type of object it is. ("Deleted pod" instead of "Deleted")
+>
+> For example
+>
+> ```go
+> klog.Infof("delete pod %s with propagation policy %s", ...)
+> ```
+>
+> should be changed to
+>
+> ```go
+> klog.InfoS("Deleted pod", ...)
+> ```
+
+#### [On naming arguments in structured logging](https://github.com/kubernetes/community/blob/d7ab088079c96891cee9bbcc88a78649acdf49f1/contributors/devel/sig-instrumentation/migration-to-structured-logging.md#name-arguments)
+
+> When deciding on names of arguments you should:
+>
+> - Always use [lowerCamelCase], for example use `containerName` and not `container name` or `container_name`.
+> - Use [alphanumeric] characters: no special characters like `%$*`, non-latin, or unicode characters.
+> - Use object kind when referencing Kubernetes objects, for example `deployment`, `pod` and `node`.
+> - Describe the type of value stored under the key and use normalized labels:
+>   - Don't include implementation-specific details in the labels. Don't use `directory`, do use `path`.
+>   - Do not provide additional context for how value is used. Don't use `podIP`, do use `IP`.
+>   - With the exception of acronyms like "IP" and the standard "err", don't shorten names. Don't use `addr`, do use `address`.
+>   - When names are very ambiguous, try to include context in the label. For example, instead of
+>     `key` use `cacheKey` or instead of `version` use `dockerVersion`.
+> - Be consistent, for example when logging file path we should always use `path` and not switch between
+>   `hostPath`, `path`, `file`.
+
+#### [On Good practice for passing values in structured logging](https://github.com/kubernetes/community/blob/d7ab088079c96891cee9bbcc88a78649acdf49f1/contributors/devel/sig-instrumentation/migration-to-structured-logging.md#good-practice-for-passing-values-in-structured-logging)
+
+> When passing a value for a key-value pair, please use following rules:
+>
+> - Prefer using Kubernetes objects and log them using `klog.KObj` or `klog.KObjSlice`
+>   - When the original object is not available, use `klog.KRef` instead
+>   - when only one object (for example `*v1.Pod`), we use`klog.KObj`
+>   - When type is object slice (for example `[]*v1.Pod`), we use `klog.KObjSlice`
+> - Pass structured values directly (avoid calling `.String()` on them first)
+> - When the goal is to log a `[]byte` array as string, explicitly convert with `string(<byte array>)`.

pkg/server/auth/auth.go

@@ -99,7 +99,7 @@ func (p *UserPrincipal) SetToken(t string) {
 
 // String returns the Principal ID and Groups as a string.
 func (p *UserPrincipal) String() string {
-	return fmt.Sprintf("id=%q groups=%v", p.ID, p.Groups)
+	return fmt.Sprintf("id=%q groups=%v tokenLength=%v", p.ID, p.Groups, len(p.Token()))
 }
 
 // Hash returns a unique string using user id,token and groups.

pkg/server/auth/auth_test.go

@@ -385,7 +385,8 @@ func TestUserPrincipal_String(t *testing.T) {
 	// principal is logged out.
 	p := auth.NewUserPrincipal(auth.ID("testing"), auth.Groups([]string{"group1", "group2"}), auth.Token("test-token"))
 
-	if s := p.String(); s != `id="testing" groups=[group1 group2]` {
-		t.Fatalf("principal.String() got %s, want %s", s, `id="testing" groups=[group1 group2]`)
+	expected := `id="testing" groups=[group1 group2] tokenLength=10`
+	if s := p.String(); s != expected {
+		t.Fatalf("principal.String() got %s, want %s", s, expected)
 	}
 }

pkg/server/auth/jwt.go

@@ -74,8 +74,6 @@ func NewJWTAuthorizationHeaderPrincipalGetter(log logr.Logger, verifier tokenVer
 }
 
 func (pg *JWTAuthorizationHeaderPrincipalGetter) Principal(r *http.Request) (*UserPrincipal, error) {
-	pg.log.Info("attempt to read token from auth header")
-
 	header := r.Header.Get("Authorization")
 	if header == "" {
 		return nil, nil
@@ -158,7 +156,7 @@ func (m MultiAuthPrincipal) Principal(r *http.Request) (*UserPrincipal, error) {
 		}
 
 		if p != nil {
-			m.Log.V(logger.LogLevelDebug).Info("Found principal", "user", p.ID, "groups", p.Groups, "tokenLength", len(p.Token()), "method", reflect.TypeOf(v))
+			m.Log.V(logger.LogLevelDebug).Info("Found principal", "user", p, "method", reflect.TypeOf(v))
 
 			return p, nil
 		}

pkg/server/middleware/middleware.go

@@ -87,7 +87,7 @@ func WithProviderToken(jwtClient auth.JWTClient, h http.Handler, log logr.Logger
 		tokenSlice := strings.Split(tokenStr, "token ")
 
 		if len(tokenSlice) < 2 {
-			log.V(logger.LogLevelDebug).Info("missing or invalid token.")
+			log.V(logger.LogLevelDebug).Info("git-provider-token was missing or invalid.")
 			// No token specified. Nothing to be done.
 			// We do NOT return 400 here because there may be some 'unauthenticated' routes (ie /login)
 			h.ServeHTTP(w, r)