Merge pull request #690 from minj131/jaminmin/e2e-latency

add support for e2e latency for dynamic mode and adoption rate metrics

pkg/fileutil/util.go

@@ -1,7 +1,9 @@
 package fileutil
 
 import (
+	"fmt"
 	"os"
+	"strconv"
 	"time"
 
 	"github.com/fsnotify/fsnotify"
@@ -104,3 +106,18 @@ func StartLoadDynamicFile(filename string, callBack FileChangeCallBack, stopCh <
 		}
 	}, time.Second, stopCh)
 }
+
+func CalculateTimeDeltaFromUnixInSeconds(from string) (int64, error) {
+	startTime, err := strconv.ParseInt(from, 10, 64)
+	if err != nil {
+		return 0, fmt.Errorf("failed to parse 'startTime' string: %v", err)
+	}
+
+	endTime := time.Now().Unix()
+
+	if startTime > endTime {
+		return 0, fmt.Errorf("start timestamp is after end timestamp")
+	}
+
+	return endTime - startTime, nil
+}

pkg/fileutil/util_test.go

@@ -2,6 +2,7 @@ package fileutil
 
 import (
 	"os"
+	"strconv"
 	"sync"
 	"testing"
 	"time"
@@ -122,3 +123,57 @@ func TestDeleteDynamicFile(t *testing.T) {
 	}
 	testA.mutex.Unlock()
 }
+
+func TestCalculateTimeDeltaFromUnixInSeconds(t *testing.T) {
+	type args struct {
+		startTime string
+	}
+	cases := []struct {
+		input  args
+		errexp bool
+		sleep  bool
+	}{
+		{
+			args{"1706648530"},
+			false,
+			false,
+		},
+		{
+			args{"1706648520"},
+			false,
+			false,
+		},
+		{
+			args{"foo"},
+			true,
+			false,
+		},
+		{
+			args{"2706648520"},
+			true,
+			false,
+		},
+		{
+			args{strconv.FormatInt(time.Now().Unix(), 10)},
+			false,
+			true,
+		},
+	}
+
+	for _, c := range cases {
+		if c.sleep {
+			time.Sleep(1 * time.Second)
+		}
+
+		out, err := CalculateTimeDeltaFromUnixInSeconds(c.input.startTime)
+		if !c.errexp && err != nil {
+			t.Errorf("Did not expect error but got err: %v", err)
+		} else if c.errexp && err == nil {
+			t.Error("Expected error but got nil")
+		}
+
+		if !c.errexp && out < 1 {
+			t.Errorf("Returned an invalid value: %d", out)
+		}
+	}
+}

pkg/mapper/dynamicfile/dynamicfile.go

@@ -10,6 +10,8 @@ import (
 	"sigs.k8s.io/aws-iam-authenticator/pkg/arn"
 	"sigs.k8s.io/aws-iam-authenticator/pkg/config"
 	"sigs.k8s.io/aws-iam-authenticator/pkg/errutil"
+	"sigs.k8s.io/aws-iam-authenticator/pkg/fileutil"
+	"sigs.k8s.io/aws-iam-authenticator/pkg/metrics"
 )
 
 type DynamicFileMapStore struct {
@@ -21,13 +23,18 @@ type DynamicFileMapStore struct {
 	filename                  string
 	userIDStrict              bool
 	usernamePrefixReserveList []string
+
+	dynamicFileInitDone bool
 }
 
 type DynamicFileData struct {
+	// Time that the object takes from update time to load time
+	LastUpdatedDateTime string `json:"LastUpdatedDateTime"`
+	// Version is the version number of the update
+	Version string `json:"Version"`
 	// RoleMappings is a list of mappings from AWS IAM Role to
 	// Kubernetes username + groups.
 	RoleMappings []config.RoleMapping `json:"mapRoles"`
-
 	// UserMappings is a list of mappings from AWS IAM User to
 	// Kubernetes username + groups.
 	UserMappings []config.UserMapping `json:"mapUsers"`
@@ -48,6 +55,7 @@ func NewDynamicFileMapStore(cfg config.Config) (*DynamicFileMapStore, error) {
 	ms := DynamicFileMapStore{}
 	ms.filename = cfg.DynamicFilePath
 	ms.userIDStrict = cfg.DynamicFileUserIDStrict
+	ms.dynamicFileInitDone = false
 	return &ms, nil
 }
 
@@ -165,6 +173,26 @@ func (ms *DynamicFileMapStore) CallBackForFileLoad(dynamicContent []byte) error
 		return err
 	}
 	ms.saveMap(userMappings, roleMappings, awsAccounts)
+
+	// when instance or container restarts, the dynamic file is (re)loaded and the latency metric is calculated
+	// regardless if there was a change upstream, and thus can emit an incorrect latency value
+	// so a workaround is to skip the first time the metric is calculated, and only emit metris after
+	// as we know any subsequent calculations are from a valid change upstream
+	if ms.dynamicFileInitDone {
+		latency, err := fileutil.CalculateTimeDeltaFromUnixInSeconds(dynamicFileData.LastUpdatedDateTime)
+		if err != nil {
+			logrus.Errorf("error parsing latency for dynamic file: %v", err)
+		} else {
+			metrics.Get().E2ELatency.WithLabelValues("dynamic_file").Observe(float64(latency))
+			logrus.WithFields(logrus.Fields{
+				"Version": dynamicFileData.Version,
+				"Type":    "dynamic_file",
+				"Latency": latency,
+			}).Infof("logging latency metric")
+		}
+	}
+	ms.dynamicFileInitDone = true
+
 	return nil
 }
 

pkg/mapper/dynamicfile/dynamicfile_test.go

@@ -7,9 +7,11 @@ import (
 	"time"
 
 	"github.com/google/go-cmp/cmp"
+	"github.com/prometheus/client_golang/prometheus"
 	"sigs.k8s.io/aws-iam-authenticator/pkg/config"
 	"sigs.k8s.io/aws-iam-authenticator/pkg/errutil"
 	"sigs.k8s.io/aws-iam-authenticator/pkg/fileutil"
+	"sigs.k8s.io/aws-iam-authenticator/pkg/metrics"
 	"sigs.k8s.io/aws-iam-authenticator/pkg/token"
 )
 
@@ -18,6 +20,11 @@ var (
 	testRole = config.RoleMapping{RoleARN: "arn:aws:iam::012345678912:role/computer", Username: "computer", Groups: []string{"system:nodes"}}
 )
 
+func TestMain(m *testing.M) {
+	metrics.InitMetrics(prometheus.NewRegistry())
+	m.Run()
+}
+
 func makeStore(users map[string]config.UserMapping, roles map[string]config.RoleMapping, filename string, userIDStrict bool) DynamicFileMapStore {
 	ms := DynamicFileMapStore{
 		users:        users,
@@ -96,6 +103,9 @@ func TestAWSAccount(t *testing.T) {
 
 var origFileContent = `
 {
+  "Version": "1",
+  "LastUpdatedDateTime": "12345678",
+  "ClusterId": "000000000098",
   "mapRoles": [
     {
       "rolearn": "arn:aws:iam::000000000098:role/KubernetesAdmin",
@@ -133,6 +143,9 @@ var origFileContent = `
 
 var updatedFileContent = `
 {
+  "Version": "1",
+  "LastUpdatedDateTime": "12345678",
+  "ClusterId": "000000000098",
   "mapRoles": [
     {
       "rolearn": "arn:aws:iam::000000000098:role/KubernetesAdmin",

pkg/metrics/metrics.go

@@ -42,6 +42,9 @@ type Metrics struct {
 	StsResponses                 *prometheus.CounterVec
 	DynamicFileFailures          prometheus.Counter
 	StsThrottling                prometheus.Counter
+	E2ELatency                   *prometheus.HistogramVec
+	DynamicFileEnabled           prometheus.Gauge
+	DynamicFileOnly              prometheus.Gauge
 }
 
 func createMetrics(reg prometheus.Registerer) Metrics {
@@ -98,5 +101,28 @@ func createMetrics(reg prometheus.Registerer) Metrics {
 				Help:      "Number of EC2 describe instances calls.",
 			},
 		),
+		E2ELatency: factory.NewHistogramVec(
+			prometheus.HistogramOpts{
+				Name:      "dynamic_e2e_latency_seconds",
+				Namespace: Namespace,
+				Help:      "End to end latency in seconds partitioned by type.",
+				Buckets:   []float64{1, 3, 5, 10, 15, 20, 30, 60},
+			},
+			[]string{"type"},
+		),
+		DynamicFileEnabled: factory.NewGauge(
+			prometheus.GaugeOpts{
+				Name:      "dynamic_file_enabled",
+				Namespace: Namespace,
+				Help:      "Dynamic file in backend mode is enabled",
+			},
+		),
+		DynamicFileOnly: factory.NewGauge(
+			prometheus.GaugeOpts{
+				Name:      "dynamic_file_only",
+				Namespace: Namespace,
+				Help:      "Only dynamic file in backend mode is enabled",
+			},
+		),
 	}
 }

pkg/server/server.go

@@ -70,13 +70,14 @@ var (
 // server state (internal)
 type handler struct {
 	http.ServeMux
-	mutex            sync.RWMutex
-	verifier         token.Verifier
-	ec2Provider      ec2provider.EC2Provider
-	clusterID        string
-	backendMapper    BackendMapper
-	scrubbedAccounts []string
-	cfg              config.Config
+	mutex                     sync.RWMutex
+	verifier                  token.Verifier
+	ec2Provider               ec2provider.EC2Provider
+	clusterID                 string
+	backendMapper             BackendMapper
+	backendModeConfigInitDone bool
+	scrubbedAccounts          []string
+	cfg                       config.Config
 }
 
 // New authentication webhook server.
@@ -205,12 +206,13 @@ func (c *Server) getHandler(backendMapper BackendMapper, ec2DescribeQps int, ec2
 	}
 
 	h := &handler{
-		verifier:         token.NewVerifier(c.ClusterID, c.PartitionID, instanceRegion),
-		ec2Provider:      ec2provider.New(c.ServerEC2DescribeInstancesRoleARN, instanceRegion, ec2DescribeQps, ec2DescribeBurst),
-		clusterID:        c.ClusterID,
-		backendMapper:    backendMapper,
-		scrubbedAccounts: c.Config.ScrubbedAWSAccounts,
-		cfg:              c.Config,
+		verifier:                  token.NewVerifier(c.ClusterID, c.PartitionID, instanceRegion),
+		ec2Provider:               ec2provider.New(c.ServerEC2DescribeInstancesRoleARN, instanceRegion, ec2DescribeQps, ec2DescribeBurst),
+		clusterID:                 c.ClusterID,
+		backendMapper:             backendMapper,
+		scrubbedAccounts:          c.Config.ScrubbedAWSAccounts,
+		cfg:                       c.Config,
+		backendModeConfigInitDone: false,
 	}
 
 	h.HandleFunc("/authenticate", h.authenticateEndpoint)
@@ -513,6 +515,32 @@ func (h *handler) CallBackForFileLoad(dynamicContent []byte) error {
 	} else {
 		logrus.Infof("BackendMode dynamic file got changed, but same with current mode, skip rebuild mapper")
 	}
+
+	// when instance or container restarts, the backendend mode config is (re)loaded and the latency metric is calculated
+	// regardless if there was a change upstream, and thus can emit an incorrect latency value
+	// so a workaround is to skip the first time the metric is calculated, and only emit metris after
+	// as we know any subsequent calculations are from a valid change upstream
+	if h.backendModeConfigInitDone {
+		latency, err := fileutil.CalculateTimeDeltaFromUnixInSeconds(backendModes.LastUpdatedDateTime)
+		if err != nil {
+			logrus.Errorf("error parsing latency for dynamic backend mode file: %v", err)
+		} else {
+			metrics.Get().E2ELatency.WithLabelValues("dynamic_backend_mode").Observe(float64(latency))
+			logrus.WithFields(logrus.Fields{
+				"Version": backendModes.Version,
+				"Type":    "dynamic_backend_mode",
+				"Latency": latency,
+			}).Infof("logging latency metric")
+		}
+	}
+	h.backendModeConfigInitDone = true
+
+	if h.backendMapper.currentModes == mapper.ModeDynamicFile {
+		metrics.Get().DynamicFileOnly.Set(1)
+	} else if strings.Contains(h.backendMapper.currentModes, mapper.ModeDynamicFile) {
+		metrics.Get().DynamicFileEnabled.Set(1)
+	}
+
 	return nil
 }
 

pkg/server/types.go

@@ -41,5 +41,9 @@ type BackendMapper struct {
 
 // AccessConfig represents the configuration format for cluster access config via backend mode.
 type BackendModeConfig struct {
+	// Time that the object takes from update time to load time
+	LastUpdatedDateTime string `json:"LastUpdatedDateTime"`
+	// Version is the version number of the update
+	Version     string `json:"Version"`
 	BackendMode string `json:"backendMode"`
 }