panic: No instance found with instance-id

[ichasco-heytrade]

Hi, I have configured NTH with SQS and I am getting errors when a spot instance is released. It still detecting it in SQS (I think) and giving errors because now it doesn't exists.

...
2021/02/17 19:25:16 DBG Checking for queue messages
2021/02/17 19:25:16 ??? There was a problem monitoring for events error="No instance found with instance-id i-036d0327276ea8741" event_type=SQS_TERMINATE
2021/02/17 19:25:18 DBG Checking for queue messages
...
2021/02/17 19:25:54 ??? There was a problem monitoring for events error="No instance found with instance-id i-036d0327276ea8741" event_type=SQS_TERMINATE
2021/02/17 19:25:54 ??? Stopping NTH - Duplicate Error Threshold hit.
panic: No instance found with instance-id i-036d0327276ea8741

goroutine 72 [running]:
main.main.func3(0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x1ca8720, ...)
	/node-termination-handler/cmd/node-termination-handler.go:184 +0x4d1
created by main.main
	/node-termination-handler/cmd/node-termination-handler.go:167 +0x91c

Version of NTH: v1.12.0

Configuration:

2021/02/17 19:31:17 ??? Startup Metadata Retrieved metadata={"accountId":"XXXXXXXX","availabilityZone":"eu-west-1b","instanceId":"i-090bb5ba647dad92e","instanceType":"m5.xlarge","localHostname":"ip-10-11-10-152","privateIp":"10.11.10.152","publicHostname":"","publicIp":"","region":"eu-west-1"}
2021/02/17 19:31:17 ??? aws-node-termination-handler arguments: 
	dry-run: false,
	node-name: ip-10-11-10-152.eu-west-1.compute.internal,
	metadata-url: http://169.254.169.254,
	kubernetes-service-host: 172.20.0.1,
	kubernetes-service-port: 443,
	delete-local-data: true,
	ignore-daemon-sets: true,
	pod-termination-grace-period: -1,
	node-termination-grace-period: 120,
	enable-scheduled-event-draining: false,
	enable-spot-interruption-draining: false,
	enable-sqs-termination-draining: true,
	enable-rebalance-monitoring: false,
	metadata-tries: 3,
	cordon-only: false,
	taint-node: false,
	json-logging: false,
	log-level: debug,
	webhook-proxy: ,
	webhook-headers: <not-displayed>,
	webhook-url: <provided-not-displayed>,
	webhook-template: <not-displayed>,
	uptime-from-file: ,
	enable-prometheus-server: false,
	prometheus-server-port: 9092,
	aws-region: eu-west-1,
	queue-url: https://sqs.eu-west-1.amazonaws.com/XXXXXXXXX/NTH,
	check-asg-tag-before-draining: true,
	managed-asg-tag: aws-node-termination-handler/managed,
	aws-endpoint: ,

2021/02/17 19:31:18 DBG AWS Credentials retrieved from provider: WebIdentityCredentials
2021/02/17 19:31:18 ??? Started watching for interruption events
2021/02/17 19:31:18 ??? Kubernetes AWS Node Termination Handler has started successfully!
2021/02/17 19:31:18 ??? Started watching for event cancellations
2021/02/17 19:31:18 ??? Started monitoring for events event_type=SQS_TERMINATE
2021/02/17 19:31:20 DBG Checking for queue messages

Thanks!

[haugenj]

Error is created here when calling DescribeInstances

aws-node-termination-handler/pkg/monitor/sqsevent/sqs-monitor.go

Lines 181 to 183 in fbc3f70

	if len(result.Reservations) == 0 || len(result.Reservations[0].Instances) == 0 {
	return "", fmt.Errorf("No instance found with instance-id %s", instanceID)
	}

If there are no instances returned by DescribeInstances, we should probably just delete the SQS message and not error. It seems like that's our intention based on this piece

aws-node-termination-handler/pkg/monitor/sqsevent/asg-lifecycle-event.go

Lines 112 to 118 in fbc3f70

	if nodeName == "" {
	log.Info().Msg("Node name is empty, assuming instance was already terminated, deleting queue message")
	errs := m.deleteMessages(messages)
	if errs != nil {
	log.Warn().Errs("errors", errs).Msg("There was an error deleting the messages")
	}
	}

but if the instance is already gone we'll never reach this.

Looks like we need to refactor this node name retrieval code to properly handle empty node names

[haugenj]

@ichasco-heytrade out of curiosity, did NTH cordon and drain this node at all? Can you look at the logs and see if there is anything else related to that node. I am wondering if NTH somehow drained this node already but failed to delete the SQS message, or if there were multiple SQS messages for this node.

Either way, the node name code will need to be corrected

[LijieZhou]

@haugenj I am having the same problem. I do not see any other logs but these

2021/02/26 23:23:22 ??? There was a problem monitoring for events error="No instance found with instance-id i-02226d751553ff5d2" event_type=SQS_TERMINATE

If I search in the history of the ASG activities, I do not see these instances at all. Do you have any other ideas on how to debug this?

[haugenj]

@LijieZhou Try searching CloudTrail for the instance-id. Perhaps also search CloudTrail for the queue URL

[LijieZhou]

@haugenj Thanks for the tip. I am able to see the instance in CloudTrail history. I deployed the termination handler on one K8s cluster expecting to see the termination notification from the cluster I deployed to. However, these error messages are from instances that are not associated with this cluster.

I see the IAM policy is given a * for several autoscaling actions. Should I reduce the resource to only the cluster I deployed? Or is it the intention to deploy the termination handler on one central cluster to monitor all the clusters? Either way, I think it should remove errors message for instances that are already gone.

[haugenj]

@LijieZhou Totally agree with you that the already terminated instances should be handled without errroring, #375 should fix that 🤞

I see the IAM policy is given a * for several autoscaling actions. Should I reduce the resource to only the cluster I deployed?

You could, but I don't think that'll make a difference because NTH is acting on the messages present in the SQS queue and that's not affected by the IAM permissions here. The real issue is that the eventbridge rule is scoped to any ASG event. You can edit the Eventbridge rules to only check the ASGs you want, but if you add any new ASGs to your cluster in the future you'll have to remember to edit the rules again.

I think we left it broad in the readme to handle that case, but maybe we should clarify it?

Or is it the intention to deploy the termination handler on one central cluster to monitor all the clusters?

No, definitely not. I don't think we're able to call drain across clusters, or if that is possible NTH isn't currently set up to handle that

[LijieZhou]

@haugenj I can confirm that the error log messages stopped after I redeployed the NTH with #375 🎉

I think we left it broad in the readme to handle that case, but maybe we should clarify it?

Thanks for clarifying that it is the eventBridge rule instead of the IAM rule. I think it is less of an issue since I am not getting the error logs from the instances that are not on the cluster I deployed.

[LijieZhou]

Hey @haugenj The issue may not fully be resolved. We deployed the version with the fix and it seems fine for a while. However, we started to see CrashLoopBackOff error again today.

cc- @sinneduy

2021/04/14 02:03:22 INF Started watching for interruption events
2021/04/14 02:03:22 INF Kubernetes AWS Node Termination Handler has started successfully!
2021/04/14 02:03:22 INF Started watching for event cancellations
2021/04/14 02:03:22 INF Started monitoring for events event_type=SQS_TERMINATE
2021/04/14 02:03:24 ERR ignoring event due to error error="InvalidInstanceID.NotFound: The instance ID 'i-0d6bd3ce2bf8a6751' does not exist\n\tstatus code: 400, request id: 6a5c30e2-922d-464c-946c-a1ec76e5920b"
2021/04/14 02:03:24 WRN There was a problem monitoring for events error="All of the waiting queue events could not be processed" event_type=SQS_TERMINATE
2021/04/14 02:03:44 ERR ignoring event due to error error="InvalidInstanceID.NotFound: The instance ID 'i-0d6bd3ce2bf8a6751' does not exist\n\tstatus code: 400, request id: ea0020f9-9710-4b08-91ac-a8438d598ec1"
2021/04/14 02:03:44 WRN There was a problem monitoring for events error="All of the waiting queue events could not be processed" event_type=SQS_TERMINATE
2021/04/14 02:04:04 ERR ignoring event due to error error="InvalidInstanceID.NotFound: The instance ID 'i-0d6bd3ce2bf8a6751' does not exist\n\tstatus code: 400, request id: f392674c-e1be-4b31-a2e2-c34c2eb65963"
2021/04/14 02:04:04 WRN There was a problem monitoring for events error="All of the waiting queue events could not be processed" event_type=SQS_TERMINATE
2021/04/14 02:04:12 ERR ignoring event due to error error="InvalidInstanceID.NotFound: The instance ID 'i-0ade123589f30d9b1' does not exist\n\tstatus code: 400, request id: b692ede9-2e9f-4094-94fb-5cc4d6afe585"
2021/04/14 02:04:12 WRN There was a problem monitoring for events error="All of the waiting queue events could not be processed" event_type=SQS_TERMINATE
2021/04/14 02:04:12 WRN Stopping NTH - Duplicate Error Threshold hit.
panic: All of the waiting queue events could not be processed

[haugenj]

@LijieZhou are you still running 1.12.1 or did you upgrade to 1.12.2 or 1.13.0?

[haugenj]

My guess is this part doesn't correctly handle this case, because after rereading the describe instances api a terminated/missing instance id gets an error response instead of an empty response