From 6e1cdeab8d52ce9d23c65d51d9edb448c585b6d0 Mon Sep 17 00:00:00 2001 From: Christian Winther Date: Tue, 19 Feb 2019 11:26:59 +0100 Subject: [PATCH 1/5] Refactor internal state to ensure consistent request id in logging Signed-off-by: Christian Winther --- Gopkg.lock | 9 ++ internal/aws.go | 49 ++++----- internal/docker.go | 30 +++--- internal/http_handler.go | 210 ++++++++++++++++++++++----------------- internal/http_helper.go | 24 ++--- internal/logging.go | 11 -- internal/request.go | 57 +++++++++++ 7 files changed, 235 insertions(+), 155 deletions(-) create mode 100644 internal/request.go diff --git a/Gopkg.lock b/Gopkg.lock index da6da42..133e383 100644 --- a/Gopkg.lock +++ b/Gopkg.lock @@ -343,6 +343,14 @@ pruneopts = "UT" revision = "1dc9a6cbc91aacc3e8b2d63db4d2e957a5394ac4" +[[projects]] + digest = "1:274f67cb6fed9588ea2521ecdac05a6d62a8c51c074c1fccc6a49a40ba80e925" + name = "github.com/satori/go.uuid" + packages = ["."] + pruneopts = "UT" + revision = "f58768cc1a7a7e77a3bd49e98cdd21419399b6a3" + version = "v1.2.0" + [[projects]] branch = "master" digest = "1:58f7b701c6c24c34e4800ea8148258e8967b934a4c05da1fb34c5dffb1e34f81" @@ -396,6 +404,7 @@ "github.com/patrickmn/go-cache", "github.com/prometheus/client_golang/prometheus", "github.com/prometheus/client_golang/prometheus/promhttp", + "github.com/satori/go.uuid", "github.com/seatgeek/logrus-gelf-formatter", "github.com/sirupsen/logrus", ] diff --git a/internal/aws.go b/internal/aws.go index e138836..fce22f4 100644 --- a/internal/aws.go +++ b/internal/aws.go @@ -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,35 +68,34 @@ 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"), @@ -107,14 +103,11 @@ func assumeRoleFromAWS(arn string, labels []metrics.Label) (*sts.AssumeRoleOutpu 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 } diff --git a/internal/docker.go b/internal/docker.go index 3061df8..4d220b7 100644 --- a/internal/docker.go +++ b/internal/docker.go @@ -5,7 +5,6 @@ import ( "os" "strings" - metrics "github.com/armon/go-metrics" "github.com/fsouza/go-dockerclient" log "github.com/sirupsen/logrus" ) @@ -35,24 +34,25 @@ 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 } } } @@ -60,19 +60,23 @@ func findDockerContainer(ip string, labels []metrics.Label) (*docker.Container, 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 +91,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 } diff --git a/internal/http_handler.go b/internal/http_handler.go index fa46491..98c1439 100644 --- a/internal/http_handler.go +++ b/internal/http_handler.go @@ -7,7 +7,6 @@ import ( "os" "time" - "github.com/armon/go-metrics" "github.com/gorilla/mux" "github.com/newrelic/go-agent" "github.com/prometheus/client_golang/prometheus" @@ -15,10 +14,6 @@ import ( log "github.com/sirupsen/logrus" ) -const ( - telemetryPrefix = "metadataproxy" -) - // StarServer will start the HTTP server (blocking) func StarServer() { r := mux.NewRouter() @@ -87,46 +82,54 @@ func StarServer() { // handles: /{api_version}/meta-data/iam/info // handles: /{api_version}/meta-data/iam/info/{junk} func iamInfoHandler(w http.ResponseWriter, r *http.Request) { + request := NewRequest() + // setup basic telemetry vars := mux.Vars(r) - labels := []metrics.Label{ - metrics.Label{Name: "aws_api_version", Value: vars["api_version"]}, - metrics.Label{Name: "handler_name", Value: "iam-info-handler"}, - metrics.Label{Name: "remote_addr", Value: r.RemoteAddr}, - metrics.Label{Name: "request_path", Value: "/meta-data/iam/info"}, - } + request.setLabels(map[string]string{ + "aws_api_version": vars["api_version"], + "handler_name": "iam-info-handler", + "remote_addr": r.RemoteAddr, + "request_path": "/meta-data/iam/info", + }) + request.log.Infof("Handling %s from %s", r.URL.String(), remoteIP(r.RemoteAddr)) - logWithLabels(labels).Infof("Handling %s from %s", r.URL.String(), remoteIP(r.RemoteAddr)) + // publish specific go-metadataproxy headers + request.setResponseHeaders(w) // ensure we got compatible api version if !isCompatibleAPIVersion(r) { - logWithLabels(labels).Info("Request is using too old version of meta-data API, passing through directly") + request.log.Info("Request is using too old version of meta-data API, passing through directly") passthroughHandler(w, r) return } // read the role from AWS - roleInfo, labels, err := findContainerRoleByAddress(r.RemoteAddr, labels) + roleInfo, err := findContainerRoleByAddress(r.RemoteAddr, request) if err != nil { - labels = append(labels, metrics.Label{Name: "response_code", Value: "404"}) - labels = append(labels, metrics.Label{Name: "error_description", Value: "could_not_find_container"}) - metrics.IncrCounterWithLabels([]string{telemetryPrefix, "http_request"}, 1, labels) + request.setLabels(map[string]string{ + "response_code": "404", + "error_description": "could_not_find_container", + }) + request.incrCounterWithLabels([]string{"http_request"}, 1) - httpError(err, w, r) + httpError(err, w, r, request) return } // append role name to future telemetry - labels = append(labels, metrics.Label{Name: "role_name", Value: *roleInfo.RoleName}) + request.setLabel("role_name", *roleInfo.RoleName) // assume the role - assumeRole, labels, err := assumeRoleFromAWS(*roleInfo.Arn, labels) + assumeRole, err := assumeRoleFromAWS(*roleInfo.Arn, request) if err != nil { - labels = append(labels, metrics.Label{Name: "response_code", Value: "404"}) - labels = append(labels, metrics.Label{Name: "error_description", Value: "could_not_assume_role"}) - metrics.IncrCounterWithLabels([]string{telemetryPrefix, "http_request"}, 1, labels) + request.setLabels(map[string]string{ + "response_code": "404", + "error_description": "could_not_assume_role", + }) + request.incrCounterWithLabels([]string{"http_request"}, 1) - httpError(err, w, r) + httpError(err, w, r, request) return } @@ -140,100 +143,115 @@ func iamInfoHandler(w http.ResponseWriter, r *http.Request) { sendJSONResponse(w, response) - labels = append(labels, metrics.Label{Name: "response_code", Value: "200"}) - metrics.IncrCounterWithLabels([]string{telemetryPrefix, "http_request"}, 1, labels) + request.setLabel("response_code", "200") + request.incrCounterWithLabels([]string{"http_request"}, 1) } // handles: /{api_version}/meta-data/iam/security-credentials/ func iamSecurityCredentialsName(w http.ResponseWriter, r *http.Request) { // setup basic telemetry vars := mux.Vars(r) - labels := []metrics.Label{ - metrics.Label{Name: "aws_api_version", Value: vars["api_version"]}, - metrics.Label{Name: "handler_name", Value: "iam-security-credentials-name"}, - metrics.Label{Name: "remote_addr", Value: remoteIP(r.RemoteAddr)}, - metrics.Label{Name: "request_path", Value: "/meta-data/iam/security-credentials/"}, - } - logWithLabels(labels).Infof("Handling %s from %s", r.URL.String(), remoteIP(r.RemoteAddr)) + request := NewRequest() + request.setLabels(map[string]string{ + "aws_api_version": vars["api_version"], + "handler_name": "iam-security-credentials-name", + "remote_addr": remoteIP(r.RemoteAddr), + "request_path": "/meta-data/iam/security-credentials/", + }) + request.log.Infof("Handling %s from %s", r.URL.String(), remoteIP(r.RemoteAddr)) + + // publish specific go-metadataproxy headers + request.setResponseHeaders(w) // ensure we got compatible api version if !isCompatibleAPIVersion(r) { - logWithLabels(labels).Info("Request is using too old version of meta-data API, passing through directly") + request.log.Info("Request is using too old version of meta-data API, passing through directly") passthroughHandler(w, r) return } // read the role from AWS - roleInfo, labels, err := findContainerRoleByAddress(r.RemoteAddr, labels) + roleInfo, err := findContainerRoleByAddress(r.RemoteAddr, request) if err != nil { - labels = append(labels, metrics.Label{Name: "response_code", Value: "404"}) - labels = append(labels, metrics.Label{Name: "error_description", Value: "could_not_find_container"}) - metrics.IncrCounterWithLabels([]string{telemetryPrefix, "http_request"}, 1, labels) + request.setLabels(map[string]string{ + "response_code": "404", + "error_description": "could_not_find_container", + }) + request.incrCounterWithLabels([]string{"http_request"}, 1) - httpError(err, w, r) + httpError(err, w, r, request) return } // send the response w.Header().Set("Content-Type", "text/plain; charset=utf-8") - w.Header().Set("X-Powered-By", "go-metadataproxy") w.WriteHeader(http.StatusOK) w.Write([]byte(*roleInfo.RoleName)) - labels = append(labels, metrics.Label{Name: "response_code", Value: "200"}) - metrics.IncrCounterWithLabels([]string{telemetryPrefix, "http_request"}, 1, labels) + request.setLabel("response_code", "200") + request.incrCounterWithLabels([]string{"http_request"}, 1) } // handles: /{api_version}/meta-data/iam/security-credentials/{requested_role} func iamSecurityCredentialsForRole(w http.ResponseWriter, r *http.Request) { - // setup basic telemetry vars := mux.Vars(r) - labels := []metrics.Label{ - metrics.Label{Name: "aws_api_version", Value: vars["api_version"]}, - metrics.Label{Name: "handler_name", Value: "iam-security-crentials-for-role"}, - metrics.Label{Name: "remote_addr", Value: remoteIP(r.RemoteAddr)}, - metrics.Label{Name: "request_path", Value: "/meta-data/iam/security-credentials/{requested_role}"}, - metrics.Label{Name: "requested_role", Value: vars["requested_role"]}, - } - logWithLabels(labels).Infof("Handling %s from %s", r.URL.String(), remoteIP(r.RemoteAddr)) + + request := NewRequest() + request.setLabels(map[string]string{ + "aws_api_version": vars["api_version"], + "handler_name": "iam-security-crentials-for-role", + "remote_addr": remoteIP(r.RemoteAddr), + "request_path": "/meta-data/iam/security-credentials/{requested_role}", + "requested_role": vars["requested_role"], + }) + request.log.Infof("Handling %s from %s", r.URL.String(), remoteIP(r.RemoteAddr)) + + // publish specific go-metadataproxy headers + request.setResponseHeaders(w) // ensure we got compatible api version if !isCompatibleAPIVersion(r) { - logWithLabels(labels).Info("Request is using too old version of meta-data API, passing through directly") + request.log.Info("Request is using too old version of meta-data API, passing through directly") passthroughHandler(w, r) return } // read the role from AWS - roleInfo, labels, err := findContainerRoleByAddress(r.RemoteAddr, labels) + roleInfo, err := findContainerRoleByAddress(r.RemoteAddr, request) if err != nil { - labels = append(labels, metrics.Label{Name: "response_code", Value: "404"}) - labels = append(labels, metrics.Label{Name: "error_description", Value: "could_not_find_container"}) - metrics.IncrCounterWithLabels([]string{telemetryPrefix, "http_request"}, 1, labels) + request.setLabels(map[string]string{ + "response_code": "404", + "error_description": "could_not_find_container", + }) + request.incrCounterWithLabels([]string{"http_request"}, 1) - httpError(err, w, r) + httpError(err, w, r, request) return } // verify the requested role match the container role if vars["requested_role"] != *roleInfo.RoleName { - labels = append(labels, metrics.Label{Name: "response_code", Value: "404"}) - labels = append(labels, metrics.Label{Name: "error_description", Value: "role_names_do_not_match"}) - metrics.IncrCounterWithLabels([]string{telemetryPrefix, "http_request"}, 1, labels) + request.setLabels(map[string]string{ + "response_code": "404", + "error_description": "role_names_do_not_match", + }) + request.incrCounterWithLabels([]string{"http_request"}, 1) - httpError(fmt.Errorf("Role names do not match (requested: '%s' vs container role: '%s')", vars["requested_role"], *roleInfo.RoleName), w, r) + httpError(fmt.Errorf("Role names do not match (requested: '%s' vs container role: '%s')", vars["requested_role"], *roleInfo.RoleName), w, r, request) return } // assume the container role - assumeRole, labels, err := assumeRoleFromAWS(*roleInfo.Arn, labels) + assumeRole, err := assumeRoleFromAWS(*roleInfo.Arn, request) if err != nil { - labels = append(labels, metrics.Label{Name: "response_code", Value: "404"}) - labels = append(labels, metrics.Label{Name: "error_description", Value: "could_not_assume_role"}) - metrics.IncrCounterWithLabels([]string{telemetryPrefix, "http_request"}, 1, labels) + request.setLabels(map[string]string{ + "response_code": "404", + "error_description": "could_not_assume_role", + }) + request.incrCounterWithLabels([]string{"http_request"}, 1) + request.log.Error(err) - logWithLabels(labels).Error(err) http.NotFound(w, r) return } @@ -252,25 +270,30 @@ func iamSecurityCredentialsForRole(w http.ResponseWriter, r *http.Request) { // send response sendJSONResponse(w, response) - labels = append(labels, metrics.Label{Name: "response_code", Value: "200"}) - metrics.IncrCounterWithLabels([]string{telemetryPrefix, "http_request"}, 1, labels) + request.setLabel("response_code", "200") + request.incrCounterWithLabels([]string{"http_request"}, 1) } // handles: /* func passthroughHandler(w http.ResponseWriter, r *http.Request) { // setup basic telemetry vars := mux.Vars(r) - labels := []metrics.Label{ - metrics.Label{Name: "aws_api_version", Value: vars["api_version"]}, - metrics.Label{Name: "handler_name", Value: "passthrough"}, - metrics.Label{Name: "remote_addr", Value: remoteIP(r.RemoteAddr)}, - metrics.Label{Name: "request_path", Value: r.URL.String()}, - } - logWithLabels(labels).Infof("Handling %s from %s", r.URL.String(), remoteIP(r.RemoteAddr)) + + request := NewRequest() + request.setLabels(map[string]string{ + "aws_api_version": vars["api_version"], + "handler_name": "passthrough", + "remote_addr": remoteIP(r.RemoteAddr), + "request_path": r.URL.String(), + }) + request.log.Infof("Handling %s from %s", r.URL.String(), remoteIP(r.RemoteAddr)) + + // publish specific go-metadataproxy headers + request.setResponseHeaders(w) // try to enrich the telemetry with additional labels // if this fail, we will still proxy the request as-is - _, labels, _ = findContainerRoleByAddress(r.RemoteAddr, labels) + findContainerRoleByAddress(r.RemoteAddr, request) r.RequestURI = "" @@ -285,19 +308,21 @@ func passthroughHandler(w http.ResponseWriter, r *http.Request) { tp := newTransport() client := &http.Client{Transport: tp} defer func() { - metrics.SetGaugeWithLabels([]string{telemetryPrefix, "aws_response_time"}, float32(tp.Duration()), labels) - metrics.SetGaugeWithLabels([]string{telemetryPrefix, "aws_request_time"}, float32(tp.ReqDuration()), labels) - metrics.SetGaugeWithLabels([]string{telemetryPrefix, "aws_connection_time"}, float32(tp.ConnDuration()), labels) + request.setGaugeWithLabels([]string{"aws_response_time"}, float32(tp.Duration())) + request.setGaugeWithLabels([]string{"aws_request_time"}, float32(tp.ReqDuration())) + request.setGaugeWithLabels([]string{"aws_connection_time"}, float32(tp.ConnDuration())) }() // use the incoming http request to construct upstream request resp, err := client.Do(r) if err != nil { - labels = append(labels, metrics.Label{Name: "response_code", Value: "404"}) - labels = append(labels, metrics.Label{Name: "error_description", Value: "could_not_assume_role"}) - metrics.IncrCounterWithLabels([]string{telemetryPrefix, "http_request"}, 1, labels) + request.setLabels(map[string]string{ + "response_code": "404", + "error_description": "could_not_assume_role", + }) + request.incrCounterWithLabels([]string{"http_request"}, 1) - httpError(fmt.Errorf("Could not proxy request: %s", err), w, r) + httpError(fmt.Errorf("Could not proxy request: %s", err), w, r, request) return } defer resp.Body.Close() @@ -306,17 +331,22 @@ func passthroughHandler(w http.ResponseWriter, r *http.Request) { w.WriteHeader(resp.StatusCode) io.Copy(w, resp.Body) - labels = append(labels, metrics.Label{Name: "response_code", Value: fmt.Sprintf("%v", resp.StatusCode)}) - metrics.IncrCounterWithLabels([]string{telemetryPrefix, "http_request"}, 1, labels) + request.setLabel("response_code", fmt.Sprintf("%v", resp.StatusCode)) + request.incrCounterWithLabels([]string{"http_request"}, 1) } // handles: /metrics func metricsHandler(w http.ResponseWriter, r *http.Request) { - metrics.IncrCounterWithLabels([]string{telemetryPrefix, "http_request"}, 1, []metrics.Label{ - metrics.Label{Name: "handler_name", Value: "metrics"}, - metrics.Label{Name: "remote_addr", Value: remoteIP(r.RemoteAddr)}, - metrics.Label{Name: "request_path", Value: "/metrics"}, + request := NewRequest() + request.setLabels(map[string]string{ + "handler_name": "metrics", + "remote_addr": remoteIP(r.RemoteAddr), + "request_path": "/metrics", }) + request.incrCounterWithLabels([]string{"http_request"}, 1) + + // publish specific go-metadataproxy headers + request.setResponseHeaders(w) if os.Getenv("ENABLE_PROMETHEUS") != "" { handlerOptions := promhttp.HandlerOpts{ @@ -332,7 +362,7 @@ func metricsHandler(w http.ResponseWriter, r *http.Request) { data, err := telemetry.DisplayMetrics(w, r) if err != nil { - log.Error(err) + request.log.Error(err) return } diff --git a/internal/http_helper.go b/internal/http_helper.go index 0ef6c87..1e39a46 100644 --- a/internal/http_helper.go +++ b/internal/http_helper.go @@ -7,11 +7,9 @@ import ( "strings" "time" - metrics "github.com/armon/go-metrics" "github.com/aws/aws-sdk-go-v2/service/iam" docker "github.com/fsouza/go-dockerclient" "github.com/gorilla/mux" - log "github.com/sirupsen/logrus" ) const ( @@ -23,7 +21,7 @@ func remoteIP(addr string) string { return strings.Split(addr, ":")[0] } -func findContainerRoleByAddress(addr string, labels []metrics.Label) (*iam.Role, []metrics.Label, error) { +func findContainerRoleByAddress(addr string, request *Request) (*iam.Role, error) { var container *docker.Container // retry finding the Docker container since sometimes Docker doesn't actually list the container until its been @@ -31,33 +29,33 @@ func findContainerRoleByAddress(addr string, labels []metrics.Label) (*iam.Role, var err error remoteIP := remoteIP(addr) for i := 1; i <= retryCount; i++ { - container, labels, err = findDockerContainer(remoteIP, labels) + container, err = findDockerContainer(remoteIP, request) // if we got no errors, just break the loop and keep moving forward if err == nil { break } // if we got an error, log that and take a quick nap - logWithLabels(labels).Errorf("Could not find Docker container with remote IP %s (retry %d out of %d)", remoteIP, i, retryCount) + request.log.Errorf("Could not find Docker container with remote IP %s (retry %d out of %d)", remoteIP, i, retryCount) time.Sleep(retrySleep) } // check if we got no errors from the "findDockerContainer" innerloop above if err != nil { - return nil, labels, err + return nil, err } - roleName, err := findDockerContainerIAMRole(container) + roleName, err := findDockerContainerIAMRole(container, request) if err != nil { - return nil, labels, err + return nil, err } - role, labels, err := readRoleFromAWS(roleName, labels) + role, err := readRoleFromAWS(roleName, request) if err != nil { - return nil, labels, err + return nil, err } - return role, labels, nil + return role, nil } func isCompatibleAPIVersion(r *http.Request) bool { @@ -65,8 +63,8 @@ func isCompatibleAPIVersion(r *http.Request) bool { return vars["api_version"] >= "2012-01-12" } -func httpError(err error, w http.ResponseWriter, r *http.Request) { - log.Error(err) +func httpError(err error, w http.ResponseWriter, r *http.Request, request *Request) { + request.log.Error(err) w.Header().Set("X-Powered-By", "go-metadataproxy") http.NotFound(w, r) } diff --git a/internal/logging.go b/internal/logging.go index 238d0b6..16cd605 100644 --- a/internal/logging.go +++ b/internal/logging.go @@ -3,7 +3,6 @@ package internal import ( "os" - "github.com/armon/go-metrics" gelf "github.com/seatgeek/logrus-gelf-formatter" log "github.com/sirupsen/logrus" ) @@ -31,13 +30,3 @@ func ConfigureLogging() { } } } - -func logWithLabels(labels []metrics.Label) *log.Entry { - fields := log.Fields{} - - for _, label := range labels { - fields[label.Name] = label.Value - } - - return log.WithFields(fields) -} diff --git a/internal/request.go b/internal/request.go new file mode 100644 index 0000000..51d2339 --- /dev/null +++ b/internal/request.go @@ -0,0 +1,57 @@ +package internal + +import ( + "net/http" + + metrics "github.com/armon/go-metrics" + "github.com/satori/go.uuid" + "github.com/sirupsen/logrus" +) + +const ( + telemetryPrefix = "metadataproxy" +) + +type Request struct { + id string + log *logrus.Entry + metricsLabels []metrics.Label + loggingLabels logrus.Fields +} + +func NewRequest() *Request { + id := uuid.NewV4() + + return &Request{ + id: id.String(), + log: logrus.WithField("request_id", id.String()), + } +} + +func (r *Request) setLabel(key, value string) { + r.setLabels(map[string]string{key: value}) +} + +func (r *Request) setLabels(pairs map[string]string) { + for key, value := range pairs { + r.metricsLabels = append(r.metricsLabels, metrics.Label{Name: key, Value: value}) + r.loggingLabels[key] = value + } + + r.log = r.log.WithFields(r.loggingLabels) +} + +func (r *Request) incrCounterWithLabels(path []string, val float32) { + path = append([]string{telemetryPrefix}, path...) + metrics.IncrCounterWithLabels(path, val, r.metricsLabels) +} + +func (r *Request) setGaugeWithLabels(path []string, val float32) { + path = append([]string{telemetryPrefix}, path...) + metrics.SetGaugeWithLabels(path, val, r.metricsLabels) +} + +func (r *Request) setResponseHeaders(w http.ResponseWriter) { + w.Header().Set("X-Powered-By", "go-metadataproxy") + w.Header().Set("X-Request-ID", r.id) +} From 6b5674a3ceba2e61f8694d2d69ca2ddbb62a5d3e Mon Sep 17 00:00:00 2001 From: Christian Winther Date: Tue, 19 Feb 2019 11:50:51 +0100 Subject: [PATCH 2/5] Upgrade Go to 1.11 Signed-off-by: Christian Winther --- .travis.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.travis.yml b/.travis.yml index 4487613..44ddda6 100755 --- a/.travis.yml +++ b/.travis.yml @@ -3,7 +3,7 @@ sudo: required language: go go: - - 1.9 + - "1.11" services: - docker From 1de3301236cf737a9b85d9edf23a20fe283925c3 Mon Sep 17 00:00:00 2001 From: Christian Winther Date: Tue, 19 Feb 2019 12:08:10 +0100 Subject: [PATCH 3/5] use exponential backoff instead of yolo for-loop Signed-off-by: Christian Winther --- Gopkg.lock | 9 +++++++++ Gopkg.toml | 4 ++++ internal/http_handler.go | 2 +- internal/http_helper.go | 31 +++++++++++++------------------ 4 files changed, 27 insertions(+), 19 deletions(-) diff --git a/Gopkg.lock b/Gopkg.lock index 133e383..de81f33 100644 --- a/Gopkg.lock +++ b/Gopkg.lock @@ -85,6 +85,14 @@ pruneopts = "UT" revision = "3a771d992973f24aa725d07868b467d1ddfceafb" +[[projects]] + digest = "1:166438587ed45ac211dab8a3ecebf4fa0c186d0db63430fb9127bbc2e5fcdc67" + name = "github.com/cenkalti/backoff" + packages = ["."] + pruneopts = "UT" + revision = "1e4cf3da559842a91afcb6ea6141451e6c30c618" + version = "v2.1.1" + [[projects]] branch = "master" digest = "1:e48c63e818c67fbf3d7afe20bba33134ab1a5bf384847385384fd027652a5a96" @@ -397,6 +405,7 @@ "github.com/aws/aws-sdk-go-v2/aws/external", "github.com/aws/aws-sdk-go-v2/service/iam", "github.com/aws/aws-sdk-go-v2/service/sts", + "github.com/cenkalti/backoff", "github.com/davecgh/go-spew/spew", "github.com/fsouza/go-dockerclient", "github.com/gorilla/mux", diff --git a/Gopkg.toml b/Gopkg.toml index 33fd1c5..7533e32 100644 --- a/Gopkg.toml +++ b/Gopkg.toml @@ -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" diff --git a/internal/http_handler.go b/internal/http_handler.go index 98c1439..ca065ee 100644 --- a/internal/http_handler.go +++ b/internal/http_handler.go @@ -327,7 +327,6 @@ func passthroughHandler(w http.ResponseWriter, r *http.Request) { } defer resp.Body.Close() - w.Header().Set("X-Powered-By", "go-metadataproxy") w.WriteHeader(resp.StatusCode) io.Copy(w, resp.Body) @@ -338,6 +337,7 @@ func passthroughHandler(w http.ResponseWriter, r *http.Request) { // handles: /metrics func metricsHandler(w http.ResponseWriter, r *http.Request) { request := NewRequest() + request.setLabels(map[string]string{ "handler_name": "metrics", "remote_addr": remoteIP(r.RemoteAddr), diff --git a/internal/http_helper.go b/internal/http_helper.go index 1e39a46..efccc82 100644 --- a/internal/http_helper.go +++ b/internal/http_helper.go @@ -8,15 +8,11 @@ import ( "time" "github.com/aws/aws-sdk-go-v2/service/iam" + "github.com/cenkalti/backoff" docker "github.com/fsouza/go-dockerclient" "github.com/gorilla/mux" ) -const ( - retryCount = 5 - retrySleep = 5 * time.Millisecond -) - func remoteIP(addr string) string { return strings.Split(addr, ":")[0] } @@ -26,21 +22,22 @@ func findContainerRoleByAddress(addr string, request *Request) (*iam.Role, error // retry finding the Docker container since sometimes Docker doesn't actually list the container until its been // running for a while. This is a really simple and basic retry policy - var err error remoteIP := remoteIP(addr) - for i := 1; i <= retryCount; i++ { + + b := backoff.NewExponentialBackOff() + b.MaxElapsedTime = 5 * time.Second + + retryable := func() error { + var err error container, err = findDockerContainer(remoteIP, request) - // if we got no errors, just break the loop and keep moving forward - if err == nil { - break - } - - // if we got an error, log that and take a quick nap - request.log.Errorf("Could not find Docker container with remote IP %s (retry %d out of %d)", remoteIP, i, retryCount) - time.Sleep(retrySleep) + return err + } + + notify := func(err error, t time.Duration) { + request.log.Errorf("%s in %d", err, t) } - // check if we got no errors from the "findDockerContainer" innerloop above + err := backoff.RetryNotify(retryable, b, notify) if err != nil { return nil, err } @@ -65,12 +62,10 @@ func isCompatibleAPIVersion(r *http.Request) bool { func httpError(err error, w http.ResponseWriter, r *http.Request, request *Request) { request.log.Error(err) - w.Header().Set("X-Powered-By", "go-metadataproxy") http.NotFound(w, r) } func sendJSONResponse(w http.ResponseWriter, response interface{}) { - w.Header().Add("X-Powered-By", "go-metadataproxy") w.Header().Set("Content-Type", "application/json; charset=UTF-8") w.WriteHeader(http.StatusOK) From 9e297f93b60909b24382ca7fbc004557f2e0391e Mon Sep 17 00:00:00 2001 From: Christian Winther Date: Tue, 19 Feb 2019 12:56:28 +0100 Subject: [PATCH 4/5] allow copying request headers into telemetry/logging Signed-off-by: Christian Winther --- internal/docker.go | 9 +++++---- internal/http_handler.go | 12 +++++++----- internal/request.go | 13 +++++++++++++ 3 files changed, 25 insertions(+), 9 deletions(-) diff --git a/internal/docker.go b/internal/docker.go index 4d220b7..cd666f9 100644 --- a/internal/docker.go +++ b/internal/docker.go @@ -10,10 +10,11 @@ import ( ) 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 diff --git a/internal/http_handler.go b/internal/http_handler.go index ca065ee..a3d7082 100644 --- a/internal/http_handler.go +++ b/internal/http_handler.go @@ -82,10 +82,10 @@ func StarServer() { // handles: /{api_version}/meta-data/iam/info // handles: /{api_version}/meta-data/iam/info/{junk} func iamInfoHandler(w http.ResponseWriter, r *http.Request) { - request := NewRequest() - - // setup basic telemetry vars := mux.Vars(r) + + request := NewRequest() + request.setLabelsFromRequestHeader(r) request.setLabels(map[string]string{ "aws_api_version": vars["api_version"], "handler_name": "iam-info-handler", @@ -153,6 +153,7 @@ func iamSecurityCredentialsName(w http.ResponseWriter, r *http.Request) { vars := mux.Vars(r) request := NewRequest() + request.setLabelsFromRequestHeader(r) request.setLabels(map[string]string{ "aws_api_version": vars["api_version"], "handler_name": "iam-security-credentials-name", @@ -198,6 +199,7 @@ func iamSecurityCredentialsForRole(w http.ResponseWriter, r *http.Request) { vars := mux.Vars(r) request := NewRequest() + request.setLabelsFromRequestHeader(r) request.setLabels(map[string]string{ "aws_api_version": vars["api_version"], "handler_name": "iam-security-crentials-for-role", @@ -276,10 +278,10 @@ func iamSecurityCredentialsForRole(w http.ResponseWriter, r *http.Request) { // handles: /* func passthroughHandler(w http.ResponseWriter, r *http.Request) { - // setup basic telemetry vars := mux.Vars(r) request := NewRequest() + request.setLabelsFromRequestHeader(r) request.setLabels(map[string]string{ "aws_api_version": vars["api_version"], "handler_name": "passthrough", @@ -337,7 +339,7 @@ func passthroughHandler(w http.ResponseWriter, r *http.Request) { // handles: /metrics func metricsHandler(w http.ResponseWriter, r *http.Request) { request := NewRequest() - + request.setLabelsFromRequestHeader(r) request.setLabels(map[string]string{ "handler_name": "metrics", "remote_addr": remoteIP(r.RemoteAddr), diff --git a/internal/request.go b/internal/request.go index 51d2339..38f5d48 100644 --- a/internal/request.go +++ b/internal/request.go @@ -55,3 +55,16 @@ func (r *Request) setResponseHeaders(w http.ResponseWriter) { w.Header().Set("X-Powered-By", "go-metadataproxy") w.Header().Set("X-Request-ID", r.id) } + +func (r *Request) setLabelsFromRequestHeader(httpRequest *http.Request) { + if len(copyRequestHeaders) == 0 { + return + } + + labels := make(map[string]string) + for _, label := range copyRequestHeaders { + if v := httpRequest.Header.Get("label"); v != "" { + labels[labelName("header", label)] = v + } + } +} From 152c7d2f4a06de5be3a1eed350d8fa600e5d6451 Mon Sep 17 00:00:00 2001 From: Christian Winther Date: Tue, 19 Feb 2019 13:24:23 +0100 Subject: [PATCH 5/5] provide backoff InitialInterval of 5ms instead of default 500ms Signed-off-by: Christian Winther --- internal/http_helper.go | 1 + 1 file changed, 1 insertion(+) diff --git a/internal/http_helper.go b/internal/http_helper.go index efccc82..59046a0 100644 --- a/internal/http_helper.go +++ b/internal/http_helper.go @@ -26,6 +26,7 @@ func findContainerRoleByAddress(addr string, request *Request) (*iam.Role, error b := backoff.NewExponentialBackOff() b.MaxElapsedTime = 5 * time.Second + b.InitialInterval = 5 * time.Millisecond retryable := func() error { var err error