Non-blocking GET request not being closed properly

[vecerek]

Hi there 👋

I've noticed something strange the other day in my datadog traces. The HTTP GET request fired by the RangeRequestFactory's initTokenizer method keeps running even after makeTokenizer resolves. This looks in the trace the following way:

This trace maps to a code looking something like this (in the real app, these are properly layered, I just crammed everything in one view and removed the irrelevant bits so that it's more-or-less a complete example):

import Tracer from "dd-trace";
import { either, task, taskEither } from "fp-ts";
import FileType from "file-type";
import { makeTokenizer } from "@tokenizer/s3";
import { S3 } from "@aws-sdk/client-s3";

type Await<T> = T extends {
  then(onfulfilled?: (value: infer U) => unknown): unknown;
}
  ? U
  : T;

export type FileTypeResult =
  | {
      readonly ext: FileType.FileExtension | "svg";
      readonly mime: FileType.MimeType | "image/svg+xml";
    }
  | undefined;

export type ValidateAssetError = {
  _typename: "ASSET_NOT_AVAILABLE";
  error: Error;
};
export type Tokenizer = Await<ReturnType<typeof makeTokenizer>>;

export type Env = {
  makeS3Tokenizer: task.Task<Tokenizer>;
  tracer: Tracer;
};

const makeBinaryFileTypeFetcher =
  (env: Env) =>
    taskEither.tryCatch(
      async () => {
        const s3Tokenizer = await env.tracer.trace(
          "makeS3Tokenizer",
          {},
          env.makeS3Tokenizer
        );
        return env.tracer.trace("fileTypeFromTokenizer", {}, () =>
          FileType.fromTokenizer(s3Tokenizer)
        );
      },
      // assume asset is not available if error occurs
      (err) =>
        ({
          _typename: "ASSET_NOT_AVAILABLE",
          error: either.toError(err),
        } as ValidateAssetError)
    );

export type FileType = readerTaskEither.ReaderTaskEither<Env, ValidateAssetError, FileTypeResult>;
export const fileType: FileType =
  (env) => () => tracer.trace("fetchBinaryFileType", {}, makeBinaryFileTypeFetcher(env));

const tracer = Tracer.init();
const s3 = {} as S3; // imagine an initialized S3 object here

const makeS3Tokenizer = () =>
  makeTokenizer(s3, {
    Bucket: "my-bucket",
    Key: "my-key",
    VersionId: "dummy-version-id",
  });

const res = await fileType({
  makeS3Tokenizer,
  tracer,
})();

I wasn't sure whether to report it in this repo or the tokenizer/range one. Ideally, I would want the library to close all HTTP connections before makeTokenizer returns. I was trying to look for the issue but this.getHeadRequestInfo seems to be properly awaited here. I'm not quite sure where this "leakage" happens. The asset validation endpoint I've built usually responds within 300ms, so it's a bit worrying that there are still some resources being used for 5.7 seconds more after the response was sent.

@Borewit do you have any ideas where to look further?

I've enabled the debug logging for range-request-reader and was able to collect some logs, although not sure how useful they may be in this case. I hope it helps somewhat.

Collected logs (.csv)

Date,Message
"2023-02-08T12:39:50.562Z","validateAsset succeeded (216.729884ms)"
"2023-02-08T12:39:50.539Z","2023-02-08T12:39:50.539Z range-request-reader Read from cache"
"2023-02-08T12:39:50.539Z","2023-02-08T12:39:50.539Z range-request-reader adjusted range 1675..1678"
"2023-02-08T12:39:50.539Z","2023-02-08T12:39:50.539Z range-request-reader request range 1675..1678"
"2023-02-08T12:39:50.539Z","2023-02-08T12:39:50.539Z range-request-reader peekBuffer position=1675 length=4"
"2023-02-08T12:39:50.538Z","2023-02-08T12:39:50.538Z range-request-reader Read from cache"
"2023-02-08T12:39:50.538Z","2023-02-08T12:39:50.538Z range-request-reader adjusted range 1671..1674"
"2023-02-08T12:39:50.538Z","2023-02-08T12:39:50.538Z range-request-reader request range 1671..1674"
"2023-02-08T12:39:50.538Z","2023-02-08T12:39:50.538Z range-request-reader peekBuffer position=1671 length=4"
"2023-02-08T12:39:50.538Z","2023-02-08T12:39:50.538Z range-request-reader Read from cache"
"2023-02-08T12:39:50.538Z","2023-02-08T12:39:50.538Z range-request-reader adjusted range 1654..1657"
"2023-02-08T12:39:50.538Z","2023-02-08T12:39:50.538Z range-request-reader request range 1654..1657"
"2023-02-08T12:39:50.538Z","2023-02-08T12:39:50.538Z range-request-reader peekBuffer position=1654 length=4"
"2023-02-08T12:39:50.538Z","2023-02-08T12:39:50.538Z range-request-reader Read from cache"
"2023-02-08T12:39:50.538Z","2023-02-08T12:39:50.538Z range-request-reader adjusted range 1650..1653"
"2023-02-08T12:39:50.538Z","2023-02-08T12:39:50.538Z range-request-reader request range 1650..1653"
"2023-02-08T12:39:50.538Z","2023-02-08T12:39:50.538Z range-request-reader peekBuffer position=1650 length=4"
"2023-02-08T12:39:50.538Z","2023-02-08T12:39:50.538Z range-request-reader Read from cache"
"2023-02-08T12:39:50.538Z","2023-02-08T12:39:50.538Z range-request-reader adjusted range 1256..1259"
"2023-02-08T12:39:50.538Z","2023-02-08T12:39:50.538Z range-request-reader request range 1256..1259"
"2023-02-08T12:39:50.538Z","2023-02-08T12:39:50.538Z range-request-reader peekBuffer position=1256 length=4"
"2023-02-08T12:39:50.538Z","2023-02-08T12:39:50.538Z range-request-reader _parseContentRang response: contentRange=bytes 1252-2275/8185"
"2023-02-08T12:39:50.522Z","2023-02-08T12:39:50.522Z range-request-reader blocked range: 1252..2275"
"2023-02-08T12:39:50.522Z","2023-02-08T12:39:50.521Z range-request-reader adjusted range 1252..1255"
"2023-02-08T12:39:50.521Z","2023-02-08T12:39:50.521Z range-request-reader request range 1252..1255"
"2023-02-08T12:39:50.521Z","2023-02-08T12:39:50.521Z range-request-reader peekBuffer position=1252 length=4"
"2023-02-08T12:39:50.521Z","2023-02-08T12:39:50.521Z range-request-reader Read from cache"
"2023-02-08T12:39:50.521Z","2023-02-08T12:39:50.521Z range-request-reader adjusted range 37..40"
"2023-02-08T12:39:50.521Z","2023-02-08T12:39:50.521Z range-request-reader request range 37..40"
"2023-02-08T12:39:50.521Z","2023-02-08T12:39:50.521Z range-request-reader peekBuffer position=37 length=4"
"2023-02-08T12:39:50.521Z","2023-02-08T12:39:50.521Z range-request-reader Read from cache"
"2023-02-08T12:39:50.521Z","2023-02-08T12:39:50.521Z range-request-reader adjusted range 33..36"
"2023-02-08T12:39:50.521Z","2023-02-08T12:39:50.521Z range-request-reader request range 33..36"
"2023-02-08T12:39:50.521Z","2023-02-08T12:39:50.521Z range-request-reader peekBuffer position=33 length=4"
"2023-02-08T12:39:50.521Z","2023-02-08T12:39:50.521Z range-request-reader Read from cache"
"2023-02-08T12:39:50.521Z","2023-02-08T12:39:50.521Z range-request-reader adjusted range 12..15"
"2023-02-08T12:39:50.521Z","2023-02-08T12:39:50.521Z range-request-reader request range 12..15"
"2023-02-08T12:39:50.521Z","2023-02-08T12:39:50.521Z range-request-reader peekBuffer position=12 length=4"
"2023-02-08T12:39:50.521Z","2023-02-08T12:39:50.521Z range-request-reader Read from cache"
"2023-02-08T12:39:50.521Z","2023-02-08T12:39:50.521Z range-request-reader adjusted range 8..11"
"2023-02-08T12:39:50.521Z","2023-02-08T12:39:50.521Z range-request-reader request range 8..11"
"2023-02-08T12:39:50.521Z","2023-02-08T12:39:50.521Z range-request-reader peekBuffer position=8 length=4"
"2023-02-08T12:39:50.518Z","2023-02-08T12:39:50.518Z range-request-reader _parseContentRang response: contentRange=bytes 0-1023/8185"
"2023-02-08T12:39:50.468Z","2023-02-08T12:39:50.468Z range-request-reader blocked range: 0..1023"
"2023-02-08T12:39:50.467Z","2023-02-08T12:39:50.467Z range-request-reader adjusted range 0..11"
"2023-02-08T12:39:50.467Z","2023-02-08T12:39:50.467Z range-request-reader request range 0..11"
"2023-02-08T12:39:50.467Z","2023-02-08T12:39:50.467Z range-request-reader peekBuffer position=0 length=12"
"2023-02-08T12:39:50.466Z","2023-02-08T12:39:50.466Z range-request-reader _fetchSizeWithGetRequest response: contentRange=[object Object]"
"2023-02-08T12:39:50.466Z","2023-02-08T12:39:50.466Z range-request-reader _parseContentRang response: contentRange=bytes 0-4096/8185"
"2023-02-08T12:39:50.345Z","validateAsset started"

Dependency list

• Node: 18.13.0
• file-type: 16.5.4
• @tokenizer/s3: 0.2.3
• @aws-sdk/client-s3: 3.264.0

[vecerek]

I've just noticed, in production, this sometimes goes all the way up to 30 seconds.

[Borewit]

Sorry for my late reply, my focus has been on a few other things @vecerek.

I have not looked at everything.
But my first reply to this:

I would want the library to close all HTTP connections before makeTokenizer returns.

You need make sure you handle promises in the entire chain.

I get back to this.
const makeS3Tokenizer = () =>
  return makeTokenizer(s3, { // Note the return here, you don't want to ignore the promise
    Bucket: "my-bucket",
    Key: "my-key",
    VersionId: "dummy-version-id",
  });

const res = await fileType({
  await makeS3Tokenizer, // Not sure if you wait for the promise elsewhere
  tracer,
})();

[vecerek]

Sorry for my late reply, my focus has been on a few other things

No worries, mate.

You need make sure you handle promises in the entire chain.

I do. This is the part where the code example awaits for makeTokenizer:

const s3Tokenizer = await env.tracer.trace(
  "makeS3Tokenizer",
  {},
  env.makeS3Tokenizer
);

cc @Borewit

[vecerek]

This is how it looks after the instrumentation of the aws sdk was added. It could be that the problem is on their end. In this screenshot, there are 2 calls to S3 now because the code changed to use the disableChunked: true option. The first call represents the following code s3request.getRangedRequest([0, 0]), while the second represents this one s3.send(new GetObjectCommand(objRequest)).

I have no idea why s3request.getRangedRequest([0, 0]) would take so long. The bucket and the EC2 instance running my code are in the same region.