From d7bb20718052c661f5fcf721ce62e4a2779f7ec6 Mon Sep 17 00:00:00 2001 From: Aithal Date: Thu, 21 Dec 2017 10:48:21 -0800 Subject: [PATCH 1/2] eni watcher: add backoff-retry This commit adds back-off retry logic in: * udev watcher: It takes a few milliseconds for the ENI's mac address to show up on the instance once udev watcher detects that a new device has been attached * eni state lookup: If for whatever reason, there's a delay in ACS sending the ENI attachment message to the agent, the agent's state remains unaware of the ENI This should lead to improved task start latencies of awsvpc tasks. --- agent/eni/networkutils/utils_linux.go | 109 ++++++++++++++++++-- agent/eni/networkutils/utils_linux_test.go | 54 +++++++++- agent/eni/watcher/watcher_linux.go | 112 ++++++++++++++++++--- agent/eni/watcher/watcher_linux_test.go | 50 +++++++++ agent/utils/errors.go | 19 +++- 5 files changed, 319 insertions(+), 25 deletions(-) diff --git a/agent/eni/networkutils/utils_linux.go b/agent/eni/networkutils/utils_linux.go index 2807bb5e9b6..5253a0baa0d 100644 --- a/agent/eni/networkutils/utils_linux.go +++ b/agent/eni/networkutils/utils_linux.go @@ -17,22 +17,113 @@ package networkutils import ( + "context" "path/filepath" "strings" + "time" "github.com/aws/amazon-ecs-agent/agent/eni/netlinkwrapper" + "github.com/aws/amazon-ecs-agent/agent/utils" + "github.com/pkg/errors" - log "github.com/cihub/seelog" + "github.com/cihub/seelog" ) +const ( + // macAddressBackoffMin specifies the mimimum duration for the backoff + // when looking for an ENI's mac address on the host + macAddressBackoffMin = 2 * time.Millisecond + + // macAddressBackoffMax specifies the maximum duration for the backoff + // when looking for an ENI's mac address on the host + macAddressBackoffMax = 200 * time.Millisecond + + // macAddressBackoffJitter specifies the jitter multiple percentage when + // looking for an ENI's mac address on the host + macAddressBackoffJitter = 0.2 + + // macAddressBackoffMultiple specifies the backoff duration multiplier + // when looking for an ENI's mac address on the host + macAddressBackoffMultiple = 1.5 +) + +// macAddressRetriever is used to retrieve the mac address of a device. It collects +// all the information necessary to start this operation and stores the result in +// the 'macAddress' attribute +type macAddressRetriever struct { + dev string + netlinkClient netlinkwrapper.NetLink + macAddress string + // timeout specifies the timeout duration before giving up when + // looking for an ENI's mac address on the host + timeout time.Duration + ctx context.Context +} + // GetMACAddress retrieves the MAC address of a device using netlink -func GetMACAddress(dev string, netlinkClient netlinkwrapper.NetLink) (string, error) { - dev = filepath.Base(dev) - link, err := netlinkClient.LinkByName(dev) +func GetMACAddress(ctx context.Context, + timeout time.Duration, + dev string, + netlinkClient netlinkwrapper.NetLink) (string, error) { + retriever := &macAddressRetriever{ + dev: dev, + netlinkClient: netlinkClient, + ctx: ctx, + timeout: timeout, + } + return retriever.retrieve() +} + +// retrieve retrives the mac address of a network device. If the retrieved mac +// address is empty, it retries the operation with a timeout specified by the +// caller +func (retriever *macAddressRetriever) retrieve() (string, error) { + backoff := utils.NewSimpleBackoff(macAddressBackoffMin, macAddressBackoffMax, + macAddressBackoffJitter, macAddressBackoffMultiple) + ctx, cancel := context.WithTimeout(retriever.ctx, retriever.timeout) + defer cancel() + + err := utils.RetryWithBackoffCtx(ctx, backoff, func() error { + retErr := retriever.retrieveOnce() + if retErr != nil { + seelog.Warnf("Unable to retrieve mac address for device '%s': %v", + retriever.dev, retErr) + return retErr + } + + if retriever.macAddress == "" { + seelog.Debugf("Empty mac address for device '%s'", retriever.dev) + // Return a retriable error when mac address is empty. If the error + // is not wrapped with the RetriableError interface, RetryWithBackoffCtx + // treats them as retriable by default + return errors.Errorf("eni mac address: retrieved empty address for device %s", + retriever.dev) + } + + return nil + }) if err != nil { return "", err } - return link.Attrs().HardwareAddr.String(), err + // RetryWithBackoffCtx returns nil when the context is cancelled. Check if there was + // a timeout here. TODO: Fix RetryWithBackoffCtx to return ctx.Err() on context Done() + if err = ctx.Err(); err != nil { + return "", errors.Wrapf(err, "eni mac address: timed out waiting for eni device '%s'", + retriever.dev) + } + + return retriever.macAddress, nil +} + +// retrieveOnce retrieves the MAC address of a device using netlink.LinkByName +func (retriever *macAddressRetriever) retrieveOnce() error { + dev := filepath.Base(retriever.dev) + link, err := retriever.netlinkClient.LinkByName(dev) + if err != nil { + return utils.NewRetriableError(utils.NewRetriable(false), err) + } + retriever.macAddress = link.Attrs().HardwareAddr.String() + return nil } // IsValidNetworkDevice is used to differentiate virtual and physical devices @@ -43,16 +134,16 @@ func IsValidNetworkDevice(devicePath string) bool { * eth1 -> /devices/pci0000:00/0000:00:05.0/net/eth1 * eth0 -> ../../devices/pci0000:00/0000:00:03.0/net/eth0 * lo -> ../../devices/virtual/net/lo - */ + */ splitDevLink := strings.SplitN(devicePath, "devices/", 2) if len(splitDevLink) != 2 { - log.Warnf("Cannot determine device validity: %s", devicePath) + seelog.Warnf("Cannot determine device validity: %s", devicePath) return false } /* * CoreOS typically employs the vif style for physical net interfaces * Amazon Linux, Ubuntu, RHEL, Fedora, Suse use the traditional pci convention - */ + */ if strings.HasPrefix(splitDevLink[1], pciDevicePrefix) || strings.HasPrefix(splitDevLink[1], vifDevicePrefix) { return true } @@ -60,6 +151,6 @@ func IsValidNetworkDevice(devicePath string) bool { return false } // NOTE: Should never reach here - log.Criticalf("Failed to validate device path: %s", devicePath) + seelog.Criticalf("Failed to validate device path: %s", devicePath) return false } diff --git a/agent/eni/networkutils/utils_linux_test.go b/agent/eni/networkutils/utils_linux_test.go index acf59b392ee..3e4f48b9f58 100644 --- a/agent/eni/networkutils/utils_linux_test.go +++ b/agent/eni/networkutils/utils_linux_test.go @@ -16,9 +16,11 @@ package networkutils import ( + "context" "errors" "net" "testing" + "time" "github.com/golang/mock/gomock" "github.com/stretchr/testify/assert" @@ -49,7 +51,8 @@ func TestGetMACAddress(t *testing.T) { Name: randomDevice, }, }, nil) - mac, err := GetMACAddress(randomDevice, mockNetlink) + ctx := context.TODO() + mac, err := GetMACAddress(ctx, time.Millisecond, randomDevice, mockNetlink) assert.Nil(t, err) assert.Equal(t, mac, validMAC) } @@ -60,10 +63,57 @@ func TestGetMACAddressWithNetlinkError(t *testing.T) { mockCtrl := gomock.NewController(t) defer mockCtrl.Finish() mockNetlink := mock_netlinkwrapper.NewMockNetLink(mockCtrl) + // LinkByName returns an error. This will ensure that a non-retriable + // error is generated and halts the backoff-rety loop mockNetlink.EXPECT().LinkByName(randomDevice).Return( &netlink.Device{}, errors.New("Dummy Netlink Error")) - mac, err := GetMACAddress(randomDevice, mockNetlink) + ctx := context.TODO() + mac, err := GetMACAddress(ctx, 2*macAddressBackoffMax, randomDevice, mockNetlink) + assert.Error(t, err) + assert.Empty(t, mac) +} + +// TestGetMACAddressNotFoundRetry tests if netlink.LinkByName gets invoked +// multiple times if the mac address for a device is returned as empty string +func TestGetMACAddressNotFoundRetry(t *testing.T) { + mockCtrl := gomock.NewController(t) + defer mockCtrl.Finish() + mockNetlink := mock_netlinkwrapper.NewMockNetLink(mockCtrl) + pm, _ := net.ParseMAC(validMAC) + gomock.InOrder( + // Return empty mac address on first invocation + mockNetlink.EXPECT().LinkByName(randomDevice).Return(&netlink.Device{}, nil), + // Return a valid mac address on first invocation. Even though the first + // invocation did not result in an error, it did return an empty mac address. + // Hence, we expect it to be retried + mockNetlink.EXPECT().LinkByName(randomDevice).Return(&netlink.Device{ + LinkAttrs: netlink.LinkAttrs{ + HardwareAddr: pm, + Name: randomDevice, + }, + }, nil), + ) + ctx := context.TODO() + // Set max retry duration to twice that of the min backoff to ensure that there's + // enough time to retry + mac, err := GetMACAddress(ctx, 2*macAddressBackoffMin, randomDevice, mockNetlink) + assert.NoError(t, err) + assert.Equal(t, mac, validMAC) +} + +// TestGetMACAddressNotFoundRetryExpires tests if the backoff-retry logic for +// retrieving mac address returns error on timeout +func TestGetMACAddressNotFoundRetryExpires(t *testing.T) { + mockCtrl := gomock.NewController(t) + defer mockCtrl.Finish() + mockNetlink := mock_netlinkwrapper.NewMockNetLink(mockCtrl) + // Return empty mac address everytime + mockNetlink.EXPECT().LinkByName(randomDevice).Return(&netlink.Device{}, nil).MinTimes(1) + ctx := context.TODO() + // Set max retry duration to twice that of the min backoff to ensure that there's + // enough time to retry + mac, err := GetMACAddress(ctx, 2*macAddressBackoffMin, randomDevice, mockNetlink) assert.Error(t, err) assert.Empty(t, mac) } diff --git a/agent/eni/watcher/watcher_linux.go b/agent/eni/watcher/watcher_linux.go index 41eaa2fda3c..475468d9000 100644 --- a/agent/eni/watcher/watcher_linux.go +++ b/agent/eni/watcher/watcher_linux.go @@ -17,6 +17,7 @@ package watcher import ( "context" + "fmt" "time" log "github.com/cihub/seelog" @@ -27,19 +28,49 @@ import ( "github.com/aws/amazon-ecs-agent/agent/api" "github.com/aws/amazon-ecs-agent/agent/engine/dockerstate" "github.com/aws/amazon-ecs-agent/agent/eni/netlinkwrapper" - eniUtils "github.com/aws/amazon-ecs-agent/agent/eni/networkutils" + "github.com/aws/amazon-ecs-agent/agent/eni/networkutils" "github.com/aws/amazon-ecs-agent/agent/eni/udevwrapper" "github.com/aws/amazon-ecs-agent/agent/statechange" + "github.com/aws/amazon-ecs-agent/agent/utils" ) const ( // linkTypeDevice defines the string that's expected to be the output of // netlink.Link.Type() method for netlink.Device type linkTypeDevice = "device" + // encapTypeLoopback defines the string that's set for the link.Attrs.EncapType // field for localhost devices. The EncapType field defines the link // encapsulation method. For localhost, it's set to "loopback" encapTypeLoopback = "loopback" + + // sendENIStateChangeRetryTimeout specifies the timeout before giving up + // when looking for ENI in agent's state. If for whatever reason, the message + // from ACS is received after the ENI has been attached to the instance, this + // timeout duration will be used to wait for ENI message to be sent from ACS + sendENIStateChangeRetryTimeout = 3 * time.Second + + // sendENIStateChangeBackoffMin specifies minimum value for backoff when + // waiting for attachment message from ACS + sendENIStateChangeBackoffMin = 100 * time.Millisecond + + // sendENIStateChangeBackoffMax specifies maximum value for backoff when + // waiting for attachment message from ACS + sendENIStateChangeBackoffMax = 250 * time.Millisecond + + // sendENIStateChangeBackoffJitter specifies the jitter multiple percentage + // when waiting for attachment message from ACS + sendENIStateChangeBackoffJitter = 0.2 + + // sendENIStateChangeBackoffMultiple specifies the backoff duration multipler + // when waiting for the attachment message from ACS + sendENIStateChangeBackoffMultiple = 1.5 + + // macAddressRetryTimeout specifies the timeout before giving up when + // looking for an ENI's mac address on the host. It takes a few milliseconds + // for the host to learn about an ENIs mac address from netlink.LinkList(). + // We are capping off this duration to 1s assuming worst-case behavior + macAddressRetryTimeout = time.Second ) // UdevWatcher maintains the state of attached ENIs @@ -57,6 +88,17 @@ type UdevWatcher struct { primaryMAC string } +// unmanagedENIError is used to indicate that the agent found an ENI, but the agent isn't +// aware if this ENI is being managed by ECS +type unmanagedENIError struct { + mac string +} + +// Error returns the error string for the unmanagedENIError type +func (err *unmanagedENIError) Error() string { + return fmt.Sprintf("udev watcher send ENI state change: eni not managed by ecs: %s", err.mac) +} + // New is used to return an instance of the UdevWatcher struct func New(ctx context.Context, primaryMAC string, udevwrap udevwrapper.Udev, state dockerstate.TaskEngineState, stateChangeEvents chan<- statechange.Event) *UdevWatcher { @@ -154,7 +196,7 @@ func (udevWatcher *UdevWatcher) sendENIStateChange(mac string) error { // check if this is an eni required by a task eni, ok := udevWatcher.agentState.ENIByMac(mac) if !ok { - return errors.Errorf("udev watcher send ENI state change: eni not managed by ecs: %s", mac) + return &unmanagedENIError{mac} } if eni.IsSent() { return errors.Errorf("udev watcher send ENI state change: eni status already sent: %s", eni.String()) @@ -216,20 +258,27 @@ func (udevWatcher *UdevWatcher) eventHandler() { if event.Env[udevEventAction] != udevAddEvent { continue } - if !eniUtils.IsValidNetworkDevice(event.Env[udevDevPath]) { + if !networkutils.IsValidNetworkDevice(event.Env[udevDevPath]) { log.Debugf("Udev watcher event handler: ignoring event for invalid network device: %s", event.String()) continue } netInterface := event.Env[udevInterface] - log.Debugf("Udev watcher event-handler: add interface: %s", netInterface) - macAddress, err := eniUtils.GetMACAddress(netInterface, udevWatcher.netlinkClient) - if err != nil { - log.Warnf("Udev watcher event-handler: error obtaining MACAddress for interface %s", netInterface) - continue - } - if err := udevWatcher.sendENIStateChange(macAddress); err != nil { - log.Warnf("Udev watcher event-handler: unable to send state change: %v", err) - } + // GetMACAddres and sendENIStateChangeWithRetries can block the execution + // of this method for a few seconds in the worst-case scenario. + // Execute these within a go-routine + go func(ctx context.Context, dev string, timeout time.Duration) { + log.Debugf("Udev watcher event-handler: add interface: %s", dev) + macAddress, err := networkutils.GetMACAddress(udevWatcher.ctx, macAddressRetryTimeout, + dev, udevWatcher.netlinkClient) + if err != nil { + log.Warnf("Udev watcher event-handler: error obtaining MACAddress for interface %s", dev) + return + } + + if err := udevWatcher.sendENIStateChangeWithRetries(ctx, macAddress, timeout); err != nil { + log.Warnf("Udev watcher event-handler: unable to send state change: %v", err) + } + }(udevWatcher.ctx, netInterface, sendENIStateChangeRetryTimeout) case <-udevWatcher.ctx.Done(): log.Info("Stopping udev event handler") // Send the shutdown signal and close the connection @@ -241,3 +290,42 @@ func (udevWatcher *UdevWatcher) eventHandler() { } } } + +// sendENIStateChangeWithRetries invokes the sendENIStateChange method, with backoff and +// retries. Retries are only effective if sendENIStateChange returns an unmanagedENIError. +// We're effectively waiting for the ENI attachment message from ACS for a network device +// at this point of time. +func (udevWatcher *UdevWatcher) sendENIStateChangeWithRetries(parentCtx context.Context, + macAddress string, + timeout time.Duration) error { + backoff := utils.NewSimpleBackoff(sendENIStateChangeBackoffMin, sendENIStateChangeBackoffMax, + sendENIStateChangeBackoffJitter, sendENIStateChangeBackoffMultiple) + ctx, cancel := context.WithTimeout(parentCtx, timeout) + defer cancel() + + err := utils.RetryWithBackoffCtx(ctx, backoff, func() error { + sendErr := udevWatcher.sendENIStateChange(macAddress) + if sendErr != nil { + if _, ok := sendErr.(*unmanagedENIError); ok { + log.Debugf("Unable to send state change for unmanaged ENI: %v", sendErr) + return sendErr + } + // Not unmanagedENIError. Stop retrying when this happens + return utils.NewRetriableError(utils.NewRetriable(false), sendErr) + } + + return nil + }) + + if err != nil { + return err + } + // RetryWithBackoffCtx returns nil when the context is cancelled. Check if there was + // a timeout here. TODO: Fix RetryWithBackoffCtx to return ctx.Err() on context Done() + if err = ctx.Err(); err != nil { + return errors.Wrapf(err, + "udev watcher send ENI state change: timed out waiting for eni '%s' in state", macAddress) + } + + return nil +} diff --git a/agent/eni/watcher/watcher_linux_test.go b/agent/eni/watcher/watcher_linux_test.go index 328f03f25d7..6f6bb1b3f76 100644 --- a/agent/eni/watcher/watcher_linux_test.go +++ b/agent/eni/watcher/watcher_linux_test.go @@ -512,3 +512,53 @@ func TestSendENIStateChangeExpired(t *testing.T) { assert.Error(t, watcher.sendENIStateChange(randomMAC)) } + +func TestSendENIStateChangeWithRetries(t *testing.T) { + mockCtrl := gomock.NewController(t) + defer mockCtrl.Finish() + + mockStateManager := mock_dockerstate.NewMockTaskEngineState(mockCtrl) + eventChannel := make(chan statechange.Event) + + watcher := newWatcher(context.TODO(), primaryMAC, nil, nil, mockStateManager, eventChannel) + + gomock.InOrder( + mockStateManager.EXPECT().ENIByMac(randomMAC).Return(nil, false), + mockStateManager.EXPECT().ENIByMac(randomMAC).Return(&api.ENIAttachment{ + ExpiresAt: time.Unix(time.Now().Unix()+10, 0), + }, true), + ) + + ctx := context.TODO() + go watcher.sendENIStateChangeWithRetries(ctx, randomMAC, sendENIStateChangeRetryTimeout) + + eniChangeEvent := <-eventChannel + taskStateChange, ok := eniChangeEvent.(api.TaskStateChange) + require.True(t, ok) + assert.Equal(t, api.ENIAttached, taskStateChange.Attachment.Status) +} + +func TestSendENIStateChangeWithRetriesDoesNotRetryExpiredENI(t *testing.T) { + mockCtrl := gomock.NewController(t) + defer mockCtrl.Finish() + + mockStateManager := mock_dockerstate.NewMockTaskEngineState(mockCtrl) + + watcher := newWatcher(context.TODO(), primaryMAC, nil, nil, mockStateManager, nil) + + gomock.InOrder( + // ENIByMAC returns an error for exipred ENI attachment, which should + // mean that it doesn't get retried. + mockStateManager.EXPECT().ENIByMac(randomMAC).Return( + &api.ENIAttachment{ + AttachStatusSent: false, + ExpiresAt: time.Unix(time.Now().Unix()-10, 0), + MACAddress: randomMAC, + }, true), + mockStateManager.EXPECT().RemoveENIAttachment(randomMAC), + ) + + ctx := context.TODO() + assert.Error(t, watcher.sendENIStateChangeWithRetries( + ctx, randomMAC, sendENIStateChangeRetryTimeout)) +} diff --git a/agent/utils/errors.go b/agent/utils/errors.go index 98005ccb978..92cef65c976 100644 --- a/agent/utils/errors.go +++ b/agent/utils/errors.go @@ -1,4 +1,4 @@ -// Copyright 2014-2015 Amazon.com, Inc. or its affiliates. All Rights Reserved. +// Copyright 2014-2017 Amazon.com, Inc. or its affiliates. All Rights Reserved. // // Licensed under the Apache License, Version 2.0 (the "License"). You may // not use this file except in compliance with the License. A copy of the @@ -18,34 +18,43 @@ import ( "strings" ) +// Retriable defines an interface for retriable methods type Retriable interface { + // Retry returns true if the operation can be retried Retry() bool } +// DefaultRetriable implements the Retriable interface with a boolean to +// indicate if retry should occur type DefaultRetriable struct { retry bool } +// Retry returns true if the operation can be retried func (dr DefaultRetriable) Retry() bool { return dr.retry } +// NewRetriable creates a new DefaultRetriable object func NewRetriable(retry bool) Retriable { return DefaultRetriable{ retry: retry, } } +// RetriableError defines an interface for a retriable error type RetriableError interface { Retriable error } +// DefaultRetriableError is used to wrap a retriable error type DefaultRetriableError struct { Retriable error } +// NewRetriableError creates a new DefaultRetriableError object func NewRetriableError(retriable Retriable, err error) RetriableError { return &DefaultRetriableError{ retriable, @@ -53,23 +62,28 @@ func NewRetriableError(retriable Retriable, err error) RetriableError { } } +// AttributeError defines an error type to indicate an error with an ECS +// attribute type AttributeError struct { err string } +// Error returns the error string for AttributeError func (e AttributeError) Error() string { return e.err } +// NewAttributeError creates a new AttributeError object func NewAttributeError(err string) AttributeError { return AttributeError{err} } -// Implements error +// MultiErr wraps multiple errors type MultiErr struct { errors []error } +// Error returns the error string for MultiErr func (me MultiErr) Error() string { ret := make([]string, len(me.errors)+1) ret[0] = "Multiple error:" @@ -79,6 +93,7 @@ func (me MultiErr) Error() string { return strings.Join(ret, "\n") } +// NewMultiError creates a new MultErr object func NewMultiError(errs ...error) error { errors := make([]error, 0, len(errs)) for _, err := range errs { From 64377a9546fe6acdd6b830b17a7d2df527b929ea Mon Sep 17 00:00:00 2001 From: Aithal Date: Thu, 21 Dec 2017 13:05:52 -0800 Subject: [PATCH 2/2] changelog entry for pr 1148 --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index fdad8de931f..4c005e8e856 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,7 @@ * Feature - Support a HTTP endpoint for `awsvpc` tasks to query metadata * Bug - Fixed a bug where `-version` fails due to its dependency on docker client. [#1118](https://github.com/aws/amazon-ecs-agent/pull/1118) * Bug - Persist container exit code in agent state file [#1125](https://github.com/aws/amazon-ecs-agent/pull/1125) +* Bug - Fixed a bug where the agent could miss sending an ENI attachment to ECS because of address propagation delays [#1148](https://github.com/aws/amazon-ecs-agent/pull/1148) ## 1.16.0 * Feature - Support pulling from Amazon ECR with specified IAM role in task definition