Waiter waits before polling for first request

[trivikr]

Describe the bug
Waiter waits before polling for first request, which it shouldn't.

SDK version number

• v3: "@aws-sdk/client-s3": "3.2.0",
• v2 for reference: "aws-sdk": "2.827.0",

Is the issue in the browser/Node.js/ReactNative?
All

Details of the browser/Node.js/ReactNative version
N/A

To Reproduce (observed behavior)

In v2, the waiter doesn't wait before making the first poll request.

v2 Code

const AWS = require("aws-sdk");
require("console-stamp")(console, "[ss.l]");

(async () => {
  const region = "us-west-2";
  const client = new AWS.S3({ region, logger: console });

  const Bucket = "test-waiters-call-time";

  console.log("BEFORE createBucket");
  await client.createBucket({ Bucket }).promise();

  console.log("BEFORE waitForBucketExists");
  await client.waitFor("bucketExists", { Bucket }).promise();

  console.log("BEFORE deleteBucket");
  await client.deleteBucket({ Bucket }).promise();
})();

v2 Output

[[00.395]] [LOG]    BEFORE createBucket
[[01.106]] [LOG]    [AWS s3 200 0.706s 0 retries] createBucket({
  Bucket: 'test-waiters-call-time',
  CreateBucketConfiguration: { LocationConstraint: 'us-west-2' }
})
[[01.108]] [LOG]    BEFORE waitForBucketExists
[[01.186]] [LOG]    [AWS s3 200 0.077s 0 retries] headBucket({ Bucket: 'test-waiters-call-time' })
[[01.187]] [LOG]    BEFORE deleteBucket
[[01.544]] [LOG]    [AWS s3 204 0.356s 0 retries] deleteBucket({ Bucket: 'test-waiters-call-time' })

Note that:

• waitForBucketExists is called at 01.108
• headBucket is called at 01.186

In v3, the waiter waits before making the first poll request.

v3 Code

const { S3, waitForBucketExists } = require("@aws-sdk/client-s3");
require("console-stamp")(console, "[ss.l]");

(async () => {
  const region = "us-west-2";
  const client = new S3({ region, logger: console });

  const Bucket = "test-waiters-call-time";

  console.log("BEFORE createBucket");
  await client.createBucket({ Bucket });

  console.log("BEFORE waitForBucketExists");
  await waitForBucketExists({ client }, { Bucket });

  console.log("BEFORE deleteBucket");
  await client.deleteBucket({ Bucket });
})();

v3 Output

[[00.391]] [LOG]    BEFORE createBucket
[[01.344]] [INFO]   {
  clientName: 'S3Client',
  commandName: 'CreateBucketCommand',
  input: { Bucket: 'test-waiters-call-time' },
  output: { Location: 'http://test-waiters-call-time.s3.amazonaws.com/' },
  metadata: {
    httpStatusCode: 200,
    requestId: undefined,
    extendedRequestId: 'rmt2pyUob2AQHz23LfHinOwS8vSazqeW+voewSq9a/4UwLmedXt5pCqX8E2cUDKTKVgLZxJiYqM=',
    cfId: undefined,
    attempts: 1,
    totalRetryDelay: 0
  }
}
[[01.347]] [LOG]    BEFORE waitForBucketExists
[[06.495]] [INFO]   {
  clientName: 'S3Client',
  commandName: 'HeadBucketCommand',
  input: { Bucket: 'test-waiters-call-time' },
  output: {},
  metadata: {
    httpStatusCode: 200,
    requestId: undefined,
    extendedRequestId: 'Uvl8a2xOWfnMVBA500pAOjMfJYV4JcdRtrOc8sHJNLnNvp+NGj9wc24KinIdACk57pALsPl+/9A=',
    cfId: undefined,
    attempts: 1,
    totalRetryDelay: 0
  }
}
[[06.496]] [LOG]    BEFORE deleteBucket
[[06.717]] [INFO]   {
  clientName: 'S3Client',
  commandName: 'DeleteBucketCommand',
  input: { Bucket: 'test-waiters-call-time' },
  output: {},
  metadata: {
    httpStatusCode: 204,
    requestId: undefined,
    extendedRequestId: 'BlKDcsqHH50Es09mmJS5JQHSWmbohqzMb5vDlUinHXh+doOu9MgNYFm4ZbALsW1SAmPQ9GHuHuU=',
    cfId: undefined,
    attempts: 1,
    totalRetryDelay: 0
  }
}

Note that:

• waitForBucketExists is called at 18.768
• HeadBucketCommand is called at 23.862

Expected behavior
The first poll request in v3 waiter should be done as soon as waiter is called.

[trivikr]

The following benchmarking code waits for an average of ~90ms for bucketExists in v2, while in v3 the average is ~5100ms

v2 Code

const AWS = require("aws-sdk");
const { performance } = require("perf_hooks");

(async () => {
  const region = "us-west-2";
  const client = new AWS.S3({ region });

  const waitTimes = [];
  for (let i = 0; i < 20; i++) {
    const Bucket = `test-waittime-${Math.ceil(Math.random() * 10 ** 10)}`;
    await client.createBucket({ Bucket }).promise();
    const start = performance.now();
    await client.waitFor("bucketExists", { Bucket }).promise();
    const end = performance.now();
    waitTimes.push(end - start);
    await client.deleteBucket({ Bucket }).promise();
  }

  const average = (arr) => arr.reduce((a, b) => a + b) / arr.length;
  console.log({
    min: Math.min(...waitTimes),
    max: Math.max(...waitTimes),
    average: average(waitTimes),
  });
})();

v2 Output

{
  min: 64.88726702332497,
  max: 328.0410579741001,
  average: 90.74886234700679
}

v3 Code

const { S3, waitForBucketExists } = require("@aws-sdk/client-s3");
const { performance } = require("perf_hooks");

(async () => {
  const region = "us-west-2";
  const client = new S3({ region });

  const waitTimes = [];
  for (let i = 0; i < 20; i++) {
    const Bucket = `test-waittime-${Math.ceil(Math.random() * 10 ** 10)}`;
    await client.createBucket({ Bucket });
    const start = performance.now();
    await waitForBucketExists({ client }, { Bucket });
    const end = performance.now();
    waitTimes.push(end - start);
    await client.deleteBucket({ Bucket });
  }

  const average = (arr) => arr.reduce((a, b) => a + b) / arr.length;
  console.log({
    min: Math.min(...waitTimes),
    max: Math.max(...waitTimes),
    average: average(waitTimes),
  });
})();

v3 Output

{
  min: 5085.6809149980545,
  max: 5108.293135017157,
  average: 5093.321103353798
}

[trivikr]

This is a bug in v3 as per Step 1 of Smithy waitable trait:

The following example defines a waiter that waits until an Amazon S3 bucket exists:

Applying the steps defined in Waiter workflow to the above example, a client performs the following steps:

1. A HeadBucket operation is created, given the necessary input parameters, and sent to the service.
2. If the operation completes successfully, the waiter transitions to the success state and terminates. This is defined in the first acceptor of the waiter that uses the success matcher.

[github-actions]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs and link to relevant comments in this thread.