Merge pull request #3 from jippi/ensure-consistent-request-uuid

Refactor internal state to ensure consistent request id in logging

Author: jippi

.travis.yml

@@ -3,7 +3,7 @@ sudo: required
 language: go
 
 go:
-  - 1.9
+  - "1.11"
 
 services:
   - docker

Gopkg.lock

@@ -65,3 +65,7 @@ required = ["github.com/davecgh/go-spew/spew"]
 [[override]]
   name = "github.com/docker/libnetwork"
   revision = "1f28166bb386cf9223d2d00a28382b0e474be314"
+
+[[constraint]]
+  name = "github.com/cenkalti/backoff"
+  version = "2.1.1"

Gopkg.toml

@@ -5,7 +5,6 @@ import (
 	"strings"
 	"time"
 
-	"github.com/armon/go-metrics"
 	"github.com/aws/aws-sdk-go-v2/aws"
 	"github.com/aws/aws-sdk-go-v2/aws/external"
 	"github.com/aws/aws-sdk-go-v2/service/iam"
@@ -37,22 +36,20 @@ func ConfigureAWS() {
 	stsService = sts.New(cfg)
 }
 
-func readRoleFromAWS(role string, labels []metrics.Label) (*iam.Role, []metrics.Label, error) {
-	logWithLabels(labels).Infof("Looking for IAM role for %s", role)
+func readRoleFromAWS(role string, request *Request) (*iam.Role, error) {
+	request.log.Infof("Looking for IAM role for %s", role)
 
 	roleObject := &iam.Role{}
-
 	if roleObject, ok := roleCache.Get(role); ok {
-		labels = append(labels, metrics.Label{Name: "read_role_from_aws_cache", Value: "hit"})
-
-		logWithLabels(labels).Infof("Found IAM role %s in cache", role)
-		return roleObject.(*iam.Role), labels, nil
+		request.setLabel("read_role_from_aws_cache", "hit")
+		request.log.Infof("Found IAM role %s in cache", role)
+		return roleObject.(*iam.Role), nil
 	}
 
-	labels = append(labels, metrics.Label{Name: "read_role_from_aws_cache", Value: "miss"})
+	request.setLabel("read_role_from_aws_cache", "miss")
 
 	if strings.Contains(role, "@") { // IAM_ROLE=my-role@012345678910
-		logWithLabels(labels).Infof("Constructing IAM role info for %s manually", role)
+		request.log.Infof("Constructing IAM role info for %s manually", role)
 		chunks := strings.SplitN(role, "@", 2)
 		nameChunks := strings.Split(chunks[0], "/")
 
@@ -61,7 +58,7 @@ func readRoleFromAWS(role string, labels []metrics.Label) (*iam.Role, []metrics.
 			RoleName: aws.String(nameChunks[len(nameChunks)-1]),
 		}
 	} else if strings.HasPrefix(role, "arn:aws:iam") { // IAM_ROLE=arn:aws:iam::012345678910:role/my-role
-		logWithLabels(labels).Infof("Using IAM role ARN as is for %s", role)
+		request.log.Infof("Using IAM role ARN as is for %s", role)
 
 		chunks := strings.SplitN(role, ":role/", 2)
 		nameChunks := strings.Split(chunks[1], "/")
@@ -71,50 +68,46 @@ func readRoleFromAWS(role string, labels []metrics.Label) (*iam.Role, []metrics.
 			RoleName: aws.String(nameChunks[len(nameChunks)-1]),
 		}
 	} else { // IAM_ROLE=my-role
-		logWithLabels(labels).Infof("Requesting IAM role info for %s from AWS", role)
+		request.log.Infof("Requesting IAM role info for %s from AWS", role)
 		req := iamService.GetRoleRequest(&iam.GetRoleInput{
 			RoleName: aws.String(role),
 		})
 
 		resp, err := req.Send()
 		if err != nil {
-			return nil, labels, err
+			return nil, err
 		}
 
 		roleObject = resp.Role
 	}
 
 	roleCache.Set(role, roleObject, cache.DefaultExpiration)
-	return roleObject, labels, nil
+	return roleObject, nil
 }
 
-func assumeRoleFromAWS(arn string, labels []metrics.Label) (*sts.AssumeRoleOutput, []metrics.Label, error) {
-	logWithLabels(labels).Infof("Looking for STS Assume Role for %s", arn)
+func assumeRoleFromAWS(arn string, request *Request) (*sts.AssumeRoleOutput, error) {
+	request.log.Infof("Looking for STS Assume Role for %s", arn)
 
 	if assumedRole, ok := permissionCache.Get(arn); ok {
-		labels = append(labels, metrics.Label{Name: "assume_role_from_aws_cache", Value: "hit"})
-
-		logWithLabels(labels).Infof("Found STS Assume Role %s in cache", arn)
-		return assumedRole.(*sts.AssumeRoleOutput), labels, nil
+		request.setLabel("assume_role_from_aws_cache", "hit")
+		request.log.Infof("Found STS Assume Role %s in cache", arn)
+		return assumedRole.(*sts.AssumeRoleOutput), nil
 	}
-	labels = append(labels, metrics.Label{Name: "assume_role_from_aws_cache", Value: "miss"})
 
-	logWithLabels(labels).Infof("Requesting STS Assume Role info for %s from AWS", arn)
+	request.setLabel("assume_role_from_aws_cache", "miss")
+	request.log.Infof("Requesting STS Assume Role info for %s from AWS", arn)
 	req := stsService.AssumeRoleRequest(&sts.AssumeRoleInput{
 		RoleArn:         aws.String(arn),
 		RoleSessionName: aws.String("go-metadataproxy"),
 	})
 
 	assumedRole, err := req.Send()
 	if err != nil {
-		return nil, labels, err
+		return nil, err
 	}
 
 	ttl := assumedRole.Credentials.Expiration.Sub(time.Now()) - 1*time.Minute
-
-	logWithLabels(labels).Infof("Will cache STS Assumed Role info for %s in %s", arn, ttl.String())
-
+	request.log.Infof("Will cache STS Assumed Role info for %s in %s", arn, ttl.String())
 	permissionCache.Set(arn, assumedRole, ttl)
-
-	return assumedRole, labels, nil
+	return assumedRole, nil
 }

internal/aws.go

@@ -5,16 +5,16 @@ import (
 	"os"
 	"strings"
 
-	metrics "github.com/armon/go-metrics"
 	"github.com/fsouza/go-dockerclient"
 	log "github.com/sirupsen/logrus"
 )
 
 var (
-	dockerClient     *docker.Client
-	defaultRole      = os.Getenv("DEFAULT_ROLE")
-	copyDockerLabels = strings.Split(os.Getenv("COPY_DOCKER_LABELS"), ",")
-	copyDockerEnvs   = strings.Split(os.Getenv("COPY_DOCKER_ENV"), ",")
+	dockerClient       *docker.Client
+	defaultRole        = os.Getenv("DEFAULT_ROLE")
+	copyDockerLabels   = strings.Split(os.Getenv("COPY_DOCKER_LABELS"), ",")
+	copyDockerEnvs     = strings.Split(os.Getenv("COPY_DOCKER_ENV"), ",")
+	copyRequestHeaders = strings.Split(os.Getenv("COPY_REQUEST_HEADERS"), ",")
 )
 
 // ConfigureDocker will setup a docker client used during normal operations
@@ -35,44 +35,49 @@ func ConfigureDocker() {
 	dockerClient = client
 }
 
-func findDockerContainer(ip string, labels []metrics.Label) (*docker.Container, []metrics.Label, error) {
+func findDockerContainer(ip string, request *Request) (*docker.Container, error) {
 	var container *docker.Container
 
-	logWithLabels(labels).Infof("Looking up container info for %s in docker", ip)
+	request.log.Infof("Looking up container info for %s in docker", ip)
 	containers, err := dockerClient.ListContainers(docker.ListContainersOptions{All: true})
 	if err != nil {
-		return nil, labels, err
+		return nil, err
 	}
 
-	container, err = findContainerByIP(ip, labels, containers)
+	container, err = findContainerByIP(ip, request, containers)
 	if err != nil {
-		return nil, labels, err
+		return nil, err
 	}
 
+	additionalLabels := make(map[string]string)
 	if len(copyDockerLabels) > 0 {
 		for _, label := range copyDockerLabels {
 			if v, ok := container.Config.Labels[label]; ok {
-				labels = append(labels, metrics.Label{Name: labelName("container", label), Value: v})
+				additionalLabels[labelName("container", label)] = v
 			}
 		}
 	}
 
 	if len(copyDockerEnvs) > 0 {
 		for _, label := range copyDockerEnvs {
 			if v, ok := findDockerContainerEnvValue(container, label); ok {
-				labels = append(labels, metrics.Label{Name: labelName("container", label), Value: v})
+				additionalLabels[labelName("container", label)] = v
 			}
 		}
 	}
 
-	return container, labels, nil
+	if len(additionalLabels) > 0 {
+		request.setLabels(additionalLabels)
+	}
+
+	return container, nil
 }
 
-func findContainerByIP(ip string, labels []metrics.Label, containers []docker.APIContainers) (*docker.Container, error) {
+func findContainerByIP(ip string, request *Request, containers []docker.APIContainers) (*docker.Container, error) {
 	for _, container := range containers {
 		for name, network := range container.Networks.Networks {
 			if network.IPAddress == ip {
-				logWithLabels(labels).Infof("Found container IP '%s' in %+v within network '%s'", ip, container.Names, name)
+				request.log.Infof("Found container IP '%s' in %+v within network '%s'", ip, container.Names, name)
 
 				inspectedContainer, err := dockerClient.InspectContainer(container.ID)
 				if err != nil {
@@ -87,13 +92,13 @@ func findContainerByIP(ip string, labels []metrics.Label, containers []docker.AP
 	return nil, fmt.Errorf("Could not find any container with IP %s", ip)
 }
 
-func findDockerContainerIAMRole(container *docker.Container) (string, error) {
+func findDockerContainerIAMRole(container *docker.Container, request *Request) (string, error) {
 	if v, ok := findDockerContainerEnvValue(container, "IAM_ROLE"); ok {
 		return v, nil
 	}
 
 	if defaultRole != "" {
-		log.Infof("Could not find IAM_ROLE in the container, returning DEFAULT_ROLE %s", defaultRole)
+		request.log.Infof("Could not find IAM_ROLE in the container, returning DEFAULT_ROLE %s", defaultRole)
 		return defaultRole, nil
 	}