From b7a9b92505a2c7246f3733bf279d787fa68be9dc Mon Sep 17 00:00:00 2001 From: Tavis Rudd Date: Thu, 10 Aug 2017 19:50:56 -0700 Subject: [PATCH] use ntp time to avoid issues with local clock drift and watchStack It would previously skip events and hang waiting for a terminal status if the local clock had drifted ahead of AWS. This is probably just a stop-gap and I will refactor this further to use previous stack events or the CreationTimestamp as the startTime marker rather than calling out to ntp. --- package.json | 1 + src/getReliableTime.ts | 22 ++++++++++++++++++++++ src/index.ts | 23 ++++++++++++++++++++--- 3 files changed, 43 insertions(+), 3 deletions(-) create mode 100644 src/getReliableTime.ts diff --git a/package.json b/package.json index cd75c941..614132ac 100644 --- a/package.json +++ b/package.json @@ -27,6 +27,7 @@ "inquirer": "^3.2.1", "js-yaml": "^3.8.3", "lodash": "^4.17.4", + "ntp-client": "^0.5.3", "openpgp": "^2.5.8", "ora": "^1.3.0", "project-name-generator": "^2.1.3", diff --git a/src/getReliableTime.ts b/src/getReliableTime.ts new file mode 100644 index 00000000..6354bf8d --- /dev/null +++ b/src/getReliableTime.ts @@ -0,0 +1,22 @@ +import { logger } from './logger'; +import * as Promise from 'bluebird'; + +let ntpClient: any; +ntpClient = require('ntp-client'); +ntpClient.ntpReplyTimeout = 2000; +type _getNetworkTime = (server: string, port: number, callback: (err: any, ts:Date)=> void) => void; +let _getNetworkTime: _getNetworkTime; +_getNetworkTime = ntpClient.getNetworkTime; +const getNetworkTime = Promise.promisify(_getNetworkTime); + +const getReliableTime = (): Promise => + getNetworkTime("pool.ntp.org", 123) + .catch((e) => { + logger.info('error in getNetworkTime. Retrying', e=e) + return getNetworkTime("pool.ntp.org", 123) + }).catch((e) => { + logger.info('error in getNetworkTime. Falling back to new Date()', e=e) + return new Date(); + }); + +export default getReliableTime; diff --git a/src/index.ts b/src/index.ts index 6bcd1935..3da4cf6a 100644 --- a/src/index.ts +++ b/src/index.ts @@ -919,6 +919,8 @@ async function watchStack(StackName: string, startTime: Date, pollInterval=2) { const spinner = ora({spinner: 'dots12', text: '', enabled: _.isNumber(tty.columns)}); + // TODO consider doing: const spinnerStart = new Date() + // to ensure calcElapsedSeconds is accurate in the face of innacurate local clocks const calcElapsedSeconds = () => Math.ceil((+(new Date()) - +(startTime))/1000); let DONE = false; while (! DONE) { @@ -928,9 +930,11 @@ async function watchStack(StackName: string, startTime: Date, pollInterval=2) { const statusPadding = _.max(_.map(evs, (ev)=> (ev.ResourceStatus as string).length)) for (let ev of evs) { if (ev.Timestamp < startTime) { + logger.debug('filtering event from past', ev=ev, startTime=startTime); seen[ev.EventId] = true } if (!seen[ev.EventId]){ + logger.debug('displaying new event', ev=ev, startTime=startTime); displayStackEvent(ev, statusPadding); } seen[ev.EventId] = true @@ -1109,7 +1113,9 @@ async function summarizeStackProperties(StackName: string, region: string, showT //console.log('Stack OnFailure Mode:', cli.blackBright(OnFailure)); if (showTimes) { printEntry('Creation Time:', cli.blackBright(renderTimestamp(stack.CreationTime))); - printEntry('Last Update Time:', cli.blackBright(renderTimestamp(stack.LastUpdatedTime || stack.CreationTime))); + if (stack.LastUpdatedTime) { + printEntry('Last Update Time:', cli.blackBright(renderTimestamp(stack.LastUpdatedTime))); + } } printEntry('Timeout In Minutes:', cli.blackBright(stack.TimeoutInMinutes || 'None')); printEntry('NotificationARNs:', cli.blackBright(_.isEmpty(stack.NotificationARNs) ? 'None' : stack.NotificationARNs)); @@ -1201,6 +1207,17 @@ async function listStacks() { ////////////////////////////////////////////////////////////////////// import {Arguments} from 'yargs'; +import getReliableTime from './getReliableTime'; + +async function getReliableStartTime(): Promise{ + const startTime = await getReliableTime(); + startTime.setTime(startTime.getTime() - 500); // to be safe + // TODO warn about inaccurate local clocks as that will affect the calculation of elapsed time. + return startTime; +} + + + export async function renderMain(argv: Arguments): Promise { await configureAWS(argv.profile, argv.region) const rootDocLocation = pathmod.resolve(argv.template); @@ -1378,7 +1395,7 @@ abstract class AbstractCloudFormationStackCommand { async run(): Promise { await this._setup() await this._showCommandSummary() - this._startTime = new Date(); + this._startTime = await getReliableStartTime(); return this._run() } @@ -1657,9 +1674,9 @@ export async function deleteStackMain(argv: Arguments): Promise { if (confirmed) { const cfn = new aws.CloudFormation(); // --retain-resources, --client-request-token + const startTime = await getReliableStartTime(); const deleteStackOutput = await cfn.deleteStack( {StackName, RoleARN: argv.roleArn}).promise(); - const startTime = new Date(); const StackId: string = stack.StackId as string; await watchStack(StackId as string, startTime); console.log();