Unable to parsed scheduled event start time

[yzargari]

Hello,
I recently deployed aws-node-termination-handler in my cluster and now I have my first scheduled termination. The node hasn't drain nor cordoned and the application logs show the following message repeatedly every 2-3 seconds:

2020/04/30 12:19:25 There was a problem monitoring for Scheduled Maintenance events: Unable to parsed scheduled event start time: parsing time "8 May 2020 16:00:00 GMT" as "02 Jan 2006 15:04:05 GMT": cannot parse "8 May 2020 16:00:00 GMT" as "02"
2020/04/30 12:19:27 There was a problem monitoring for Scheduled Maintenance events: Unable to parsed scheduled event start time: parsing time "8 May 2020 16:00:00 GMT" as "02 Jan 2006 15:04:05 GMT": cannot parse "8 May 2020 16:00:00 GMT" as "02"
2020/04/30 12:19:29 There was a problem monitoring for Scheduled Maintenance events: Unable to parsed scheduled event start time: parsing time "8 May 2020 16:00:00 GMT" as "02 Jan 2006 15:04:05 GMT": cannot parse "8 May 2020 16:00:00 GMT" as "02"
2020/04/30 12:19:32 There was a problem monitoring for Scheduled Maintenance events: Unable to parsed scheduled event start time: parsing time "8 May 2020 16:00:00 GMT" as "02 Jan 2006 15:04:05 GMT": cannot parse "8 May 2020 16:00:00 GMT" as "02"
2020/04/30 12:19:34 There was a problem monitoring for Scheduled Maintenance events: Unable to parsed scheduled event start time: parsing time "8 May 2020 16:00:00 GMT" as "02 Jan 2006 15:04:05 GMT": cannot parse "8 May 2020 16:00:00 GMT" as "02"
2020/04/30 12:19:35 There was a problem monitoring for Scheduled Maintenance events: Unable to parsed scheduled event start time: parsing time "8 May 2020 16:00:00 GMT" as "02 Jan 2006 15:04:05 GMT": cannot parse "8 May 2020 16:00:00 GMT" as "02"
2020/04/30 12:19:37 There was a problem monitoring for Scheduled Maintenance events: Unable to parsed scheduled event start time: parsing time "8 May 2020 16:00:00 GMT" as "02 Jan 2006 15:04:05 GMT": cannot parse "8 May 2020 16:00:00 GMT" as "02"
2020/04/30 12:19:39 There was a problem monitoring for Scheduled Maintenance events: Unable to parsed scheduled event start time: parsing time "8 May 2020 16:00:00 GMT" as "02 Jan 2006 15:04:05 GMT": cannot parse "8 May 2020 16:00:00 GMT" as "02"
2020/04/30 12:19:42 There was a problem monitoring for Scheduled Maintenance events: Unable to parsed scheduled event start time: parsing time "8 May 2020 16:00:00 GMT" as "02 Jan 2006 15:04:05 GMT": cannot parse "8 May 2020 16:00:00 GMT" as "02"

What might the problem be?

Thanks,
Yosi

[bwagner5]

I've reproduced the issue. It looks like we made a bad assumption when parsing the date and assumed the day would be padded to always be two digits. I will put a PR up to fix this bug today, sorry for the inconvenience!

[bwagner5]

PR is merged, we'll be making a release soon to fix this.

[yzargari]

Thanks for the quick resolution!

[bwagner5]

released https://github.com/aws/aws-node-termination-handler/releases/tag/v1.4.0

[diegosanchez]

Using version 1.5.0 (image amazon/aws-node-termination-handler:v1.5.0) similar issue arose again.

151x

"There was a problem monitoring for Scheduled Maintenance events: Unable to parsed scheduled event end time: parsing time \"\" as \"2 Jan 2006 15:04:05 GMT\": cannot parse \"\" as \"2\""

[bwagner5]

We'll investigate and post back, thanks for bringing this up

[bwagner5]

Is this error from an actual scheduled maintenance event or testing through ec2-metadata-mock? I've run a small test with ec2-metadata-mock below and it seems to work correctly. Can you provide some more details on your configuration? The IMDS raw output would also be helpful, but I guess we don't log raw output on a parse error currently :(

$ curl -Lo ec2-metadata-mock https://github.com/aws/amazon-ec2-metadata-mock/releases/download/v1.0.0/ec2-metadata-mock-`uname | tr '[:upper:]' '[:lower:]'`-amd64 && chmod +x ec2-metadata-mock && mv /tmp/ec2-metadata-mock

$ git clone git@github.com:aws/aws-node-termination-handler.git /tmp/nth
$ cd /tmp/nth
$ make compile

$ /tmp/ec2-metadata-mock events &

$ /tmp/nth/build/node-termination-handler --node-name test --dry-run --enable-scheduled-event-draining=true --enable-spot-interruption-draining=false --metadata-url http://localhost:1338

STDOUT:

aws-node-termination-handler arguments:
	dry-run: true,
	node-name: test,
	metadata-url: http://localhost:1338,
	kubernetes-service-host: ,
	kubernetes-service-port: ,
	delete-local-data: true,
	ignore-daemon-sets: true,
	pod-termination-grace-period: -1,
	node-termination-grace-period: 120,
	enable-scheduled-event-draining: true,
	enable-spot-interruption-draining: false,
	metadata-tries: 3,
	cordon-only: false,
	taint-node: false,
	json-logging: false,
	webhook-proxy: ,
	enable-prometheus-server: false,
	prometheus-server-port: 9092,
2020/06/25 09:32:15 Trying to get token from IMDSv2
2020/06/25 09:32:15 Unable to retrieve an IMDSv2 token, continuing with IMDSv1: IMDS v2 Token TTL header not sent in response: No token TTL header found
2020/06/25 09:32:15 Trying to get token from IMDSv2
2020/06/25 09:32:15 Unable to retrieve an IMDSv2 token, continuing with IMDSv1: IMDS v2 Token TTL header not sent in response: No token TTL header found
2020/06/25 09:32:15 Trying to get token from IMDSv2
2020/06/25 09:32:15 Unable to retrieve an IMDSv2 token, continuing with IMDSv1: IMDS v2 Token TTL header not sent in response: No token TTL header found
2020/06/25 09:32:15 Trying to get token from IMDSv2
2020/06/25 09:32:15 Unable to retrieve an IMDSv2 token, continuing with IMDSv1: IMDS v2 Token TTL header not sent in response: No token TTL header found
2020/06/25 09:32:15 Trying to get token from IMDSv2
2020/06/25 09:32:15 Unable to retrieve an IMDSv2 token, continuing with IMDSv1: IMDS v2 Token TTL header not sent in response: No token TTL header found
2020/06/25 09:32:15 Trying to get token from IMDSv2
2020/06/25 09:32:15 Unable to retrieve an IMDSv2 token, continuing with IMDSv1: IMDS v2 Token TTL header not sent in response: No token TTL header found
2020/06/25 09:32:15 Startup Metadata Retrieved: {InstanceID:i-1234567890abcdef0 InstanceType:m4.xlarge PublicHostname:ec2-192-0-2-54.compute-1.amazonaws.com PublicIP:192.0.2.54 LocalHostname:ip-172-16-34-43.ec2.internal LocalIP:172.16.34.43}
2020/06/25 09:32:15 Started watching for interruption events
2020/06/25 09:32:15 Kubernetes AWS Node Termination Handler has started successfully!
2020/06/25 09:32:15 Started watching for event cancellations
2020/06/25 09:32:15 Started monitoring for Scheduled Maintenance events
2020/06/25 09:32:17 Trying to get token from IMDSv2
2020/06/25 09:32:17 Unable to retrieve an IMDSv2 token, continuing with IMDSv1: IMDS v2 Token TTL header not sent in response: No token TTL header found
2020/06/25 09:32:17 Sending interruption events to the interruption channel
2020/06/25 09:32:17 Got interruption event from channel {InstanceID:i-1234567890abcdef0 InstanceType:m4.xlarge PublicHostname:ec2-192-0-2-54.compute-1.amazonaws.com PublicIP:192.0.2.54 LocalHostname:ip-172-16-34-43.ec2.internal LocalIP:172.16.34.43} {EventID:instance-event-1234567890abcdef0 Kind:SCHEDULED_EVENT Description:system-reboot will occur between 25 Jun 2020 09:32:08 GMT and 2 Jul 2020 09:32:08 GMT because The instance is scheduled for system-reboot
 State:active StartTime:2020-06-25 09:32:08 +0000 UTC EndTime:2020-07-02 09:32:08 +0000 UTC Drained:false PreDrainTask:0x1cd05c0}
2020/06/25 09:32:18 Would have added label (aws-node-termination-handler/event-id=instance-event-1234567890abcdef0) to node test, but dry-run flag was set
2020/06/25 09:32:18 IsUnschedulable returning false since dry-run is set
2020/06/25 09:32:18 Would have added label (aws-node-termination-handler/action=UncordonAfterReboot) to node test, but dry-run flag was set
2020/06/25 09:32:18 Would have added label (aws-node-termination-handler/action-time=1593095538) to node test, but dry-run flag was set
2020/06/25 09:32:18 Successfully applied uncordon after reboot action label to node.
2020/06/25 09:32:18 Node test would have been cordoned and drained, but dry-run flag was set
2020/06/25 09:32:18 Node "test" successfully cordoned and drained.

[diegosanchez]

@bwagner5

I was about to query the aws metadata server (AMS) http://169.254.X.X when suddenly the instance was stopped by EKS (?). Sorry, I didn't gather the metadata informed from AMS.