Failing tar tests

[ericis]

@benjdlambert I saw you most recently helped merge some of the changes related to these failing tests. Maybe you know who might be able to help debug the issue.

Expected Behavior

Tests should pass.

Current Behavior

Tests failing for:

• "./packages/backend-common/src/reading/tree/TarArchiveResponse.test.ts"
• "./packages/backend-common/src/reading/GithubUrlReader.test.ts"

Possible Solution

It seems the tests are using a mock file system? If this is working properly, then no suggestions for a solution yet. Alpine works a little differently, so, if it is using the physical "/tmp" directory, then it could be an FS issue somehow. There is a subpath check in TarArchiveResponse.dir(...) that is returning false on occasion that could point to the culprit. See log below for more details.

Steps to Reproduce

If you have Docker or Podman installed, you can clone "master" and follow these steps:
https://github.com/backstage/backstage/tree/master/contrib/docker/devops#prerequisites

However, you will need to explicitly run make check-tests as the tests are excluded from the default make target because of this bug.

The above steps locally relate to an Alpine docker image running root, where a couple of tests that use the file system under "/tmp" fail.

1. yarn install
2. yarn tsc
3. yarn build
4. yarn test

*I will finalize the docker image I am using in a PR to share with you, so that you can execute the exact same tasks.

Context

Here is the log output. I added some console.log(...) statements with "TEMP TEST FILE" to see what the tar.extract(... filter => ( ... )) was doing.

PASS src/middleware/statusCheckHandler.test.ts
PASS src/service/lib/config.test.ts
PASS src/database/sqlite3.test.ts
PASS src/middleware/notFoundHandler.test.ts
PASS src/reading/tree/ZipArchiveResponse.test.ts
PASS src/scm/git.test.ts
FAIL src/reading/tree/TarArchiveResponse.test.ts
  ● Console

    console.log
      TEMP TEST FILE: mock-main/

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3288:17)

    console.log
      TEMP TEST FILE: true

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3340:17)

    console.log
      TEMP TEST FILE: mock-main/mkdocs.yml

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3288:17)

    console.log
      TEMP TEST FILE: true mkdocs.yml

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3340:17)

    console.log
      TEMP TEST FILE: mock-main/docs/

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3288:17)

    console.log
      TEMP TEST FILE: true docs/

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3340:17)

    console.log
      TEMP TEST FILE: mock-main/docs/index.md

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3288:17)

    console.log
      TEMP TEST FILE: true docs/index.md

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3340:17)

    console.log
      TEMP TEST FILE: mock-main/

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3288:17)

    console.log
      TEMP TEST FILE: false  docs/

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3306:19)

    console.log
      TEMP TEST FILE: mock-main/mkdocs.yml

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3288:17)

    console.log
      TEMP TEST FILE: false mkdocs.yml docs/

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3306:19)

    console.log
      TEMP TEST FILE: mock-main/docs/

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3288:17)

    console.log
      TEMP TEST FILE: true docs/ docs/

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3340:17)

    console.log
      TEMP TEST FILE: mock-main/docs/index.md

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3288:17)

    console.log
      TEMP TEST FILE: true docs/index.md docs/

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3340:17)

    console.log
      TEMP TEST FILE: mock-main/

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3288:17)

    console.log
      TEMP TEST FILE FILTER: false

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3328:19)

    console.log
      TEMP TEST FILE: mock-main/mkdocs.yml

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3288:17)

    console.log
      TEMP TEST FILE FILTER: true

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3328:19)

    console.log
      TEMP TEST FILE: mock-main/docs/

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3288:17)

    console.log
      TEMP TEST FILE FILTER: false

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3328:19)

    console.log
      TEMP TEST FILE: mock-main/docs/index.md

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3288:17)

    console.log
      TEMP TEST FILE FILTER: false

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3328:19)

  ● TarArchiveResponse › should extract entire archive into directory

    expect(received).resolves.toBe()

    Received promise rejected instead of resolved
    Rejected to value: [Error: ENOENT, no such file or directory '/tmp/backstage-7hLcMp/docs/index.md']

      115 |       fs.readFile(resolvePath(dir, 'mkdocs.yml'), 'utf8'),
      116 |     ).resolves.toBe('site_name: Test\n');
    > 117 |     await expect(
          |           ^
      118 |       fs.readFile(resolvePath(dir, 'docs/index.md'), 'utf8'),
      119 |     ).resolves.toBe('# Test\n');
      120 |   });

      at expect (../../../node_modules/expect/build/index.js:134:15)
      at Object.<anonymous> (reading/tree/TarArchiveResponse.test.ts:117:11)

PASS src/reading/FetchUrlReader.test.ts
PASS src/reading/BitbucketUrlReader.test.ts
FAIL src/reading/GithubUrlReader.test.ts (5.505 s)
  ● Console

    console.log
      TEMP TEST FILE: backstage-mock-etag123/

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3288:17)

    console.log
      TEMP TEST FILE: true

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3340:17)

    console.log
      TEMP TEST FILE: backstage-mock-etag123/mkdocs.yml

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3288:17)

    console.log
      TEMP TEST FILE: true mkdocs.yml

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3340:17)

    console.log
      TEMP TEST FILE: backstage-mock-etag123/docs/

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3288:17)

    console.log
      TEMP TEST FILE: true docs/

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3340:17)

    console.log
      TEMP TEST FILE: backstage-mock-etag123/docs/index.md

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3288:17)

    console.log
      TEMP TEST FILE: true docs/index.md

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3340:17)

    console.log
      TEMP TEST FILE: backstage-mock-etag123/

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3288:17)

    console.log
      TEMP TEST FILE: false  docs/

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3306:19)

    console.log
      TEMP TEST FILE: backstage-mock-etag123/mkdocs.yml

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3288:17)

    console.log
      TEMP TEST FILE: false mkdocs.yml docs/

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3306:19)

    console.log
      TEMP TEST FILE: backstage-mock-etag123/docs/

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3288:17)

    console.log
      TEMP TEST FILE: true docs/ docs/

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3340:17)

    console.log
      TEMP TEST FILE: backstage-mock-etag123/docs/index.md

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3288:17)

    console.log
      TEMP TEST FILE: true docs/index.md docs/

      at Unpack.filter (reading/tree/TarArchiveResponse.ts:3340:17)

  ● GithubUrlReader › readTree › creates a directory with the wanted files

    expect(received).resolves.toBe()

    Received promise rejected instead of resolved
    Rejected to value: [Error: ENOENT, no such file or directory '/tmp/docs/index.md']

      279 |         fs.readFile(path.join(dir, 'mkdocs.yml'), 'utf8'),
      280 |       ).resolves.toBe('site_name: Test\n');
    > 281 |       await expect(
          |             ^
      282 |         fs.readFile(path.join(dir, 'docs', 'index.md'), 'utf8'),
      283 |       ).resolves.toBe('# Test\n');
      284 |     });

      at expect (../../../node_modules/expect/build/index.js:134:15)
      at Object.<anonymous> (reading/GithubUrlReader.test.ts:281:13)

PASS src/reading/AzureUrlReader.test.ts (5.104 s)
PASS src/reading/GitlabUrlReader.test.ts (5.264 s)

Summary of all failing tests
FAIL reading/tree/TarArchiveResponse.test.ts
  ● TarArchiveResponse › should extract entire archive into directory

    expect(received).resolves.toBe()

    Received promise rejected instead of resolved
    Rejected to value: [Error: ENOENT, no such file or directory '/tmp/backstage-7hLcMp/docs/index.md']

      115 |       fs.readFile(resolvePath(dir, 'mkdocs.yml'), 'utf8'),
      116 |     ).resolves.toBe('site_name: Test\n');
    > 117 |     await expect(
          |           ^
      118 |       fs.readFile(resolvePath(dir, 'docs/index.md'), 'utf8'),
      119 |     ).resolves.toBe('# Test\n');
      120 |   });

      at expect (../../../node_modules/expect/build/index.js:134:15)
      at Object.<anonymous> (reading/tree/TarArchiveResponse.test.ts:117:11)

FAIL reading/GithubUrlReader.test.ts (5.505 s)
  ● GithubUrlReader › readTree › creates a directory with the wanted files

    expect(received).resolves.toBe()

    Received promise rejected instead of resolved
    Rejected to value: [Error: ENOENT, no such file or directory '/tmp/docs/index.md']

      279 |         fs.readFile(path.join(dir, 'mkdocs.yml'), 'utf8'),
      280 |       ).resolves.toBe('site_name: Test\n');
    > 281 |       await expect(
          |             ^
      282 |         fs.readFile(path.join(dir, 'docs', 'index.md'), 'utf8'),
      283 |       ).resolves.toBe('# Test\n');
      284 |     });

      at expect (../../../node_modules/expect/build/index.js:134:15)
      at Object.<anonymous> (reading/GithubUrlReader.test.ts:281:13)


Test Suites: 2 failed, 1 skipped, 20 passed, 22 of 23 total
Tests:       2 failed, 4 skipped, 150 passed, 156 total
Snapshots:   0 total
Time:        9.264 s
Ran all test suites.
error Command failed with exit code 1.

Your Environment

• NodeJS Version: 14.16.0
• Operating System and Version: Alpine Linux 3.11.8
• Browser Information: n/a

[ericis]

I have updated the "Steps to Reproduce" with steps from "master".

[Rugvip]

Expecting that this is the same issues as #5004.

Although tbh these tests should probably be moved over to using mockfs.

[ericis]

Thank you for the suggestion @Rugvip , but @wyattwalter's suggestion to mount "/tmp" as a volume for the other issue did not work for me in this scenario.

The tests seem to be using mock-fs, but maybe they're not working quite as expected.

👉🏻 I modified the dockerized test command to include a volume mount for "/tmp" and the tests still fail. I also tried creating a new "/tmp" directory inside of the "Dockerfile" before it is mounted as the working directory during initial setup. ("/app" is the working directory when the tests run.) Out of curiosity, I tried installing the apt "tar" package too just in case there was a surprising dependency between the "tar" npm package... there isn't (well, that's good I suppose).

check-tests: build
	@docker run --rm -it \
		--name $(docker_name_timestamp_prefix)-$@ \
		--network host \
		-v $(project_root_dir_path):/app \
		-v /tmp:/tmp \
		-w /app \
		--entrypoint "" \
		$(docker_tag) \
		yarn run test:all

Partial Test Log

PASS src/reading/AzureUrlReader.test.ts (36.181 s)
FAIL src/reading/GithubUrlReader.test.ts (37.481 s)
  ● GithubUrlReader › readTree › creates a directory with the wanted files

    expect(received).resolves.toBe()

    Received promise rejected instead of resolved
    Rejected to value: [Error: ENOENT, no such file or directory '/tmp/docs/index.md']

      279 |         fs.readFile(path.join(dir, 'mkdocs.yml'), 'utf8'),
      280 |       ).resolves.toBe('site_name: Test\n');
    > 281 |       await expect(
          |             ^
      282 |         fs.readFile(path.join(dir, 'docs', 'index.md'), 'utf8'),
      283 |       ).resolves.toBe('# Test\n');
      284 |     });

      at expect (../../../node_modules/expect/build/index.js:134:15)
      at Object.<anonymous> (reading/GithubUrlReader.test.ts:281:13)

PASS src/reading/GitlabUrlReader.test.ts (37.62 s)

Summary of all failing tests
FAIL reading/tree/TarArchiveResponse.test.ts (18.956 s)
  ● TarArchiveResponse › should extract entire archive into directory

    expect(received).resolves.toBe()

    Received promise rejected instead of resolved
    Rejected to value: [Error: ENOENT, no such file or directory '/tmp/backstage-18kxaM/docs/index.md']

      115 |       fs.readFile(resolvePath(dir, 'mkdocs.yml'), 'utf8'),
      116 |     ).resolves.toBe('site_name: Test\n');
    > 117 |     await expect(
          |           ^
      118 |       fs.readFile(resolvePath(dir, 'docs/index.md'), 'utf8'),
      119 |     ).resolveerror Command failed with exit code 1.
lerna ERR! yarn run test --coverage exited 1 in '@backstage/backend-common'
lerna WARN complete Waiting for 5 child processes to exit. CTRL-C to exit immediately.
error Command failed with exit code 1.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.
make: *** [makefile:175: check-tests] Error 1

[ericis]

I believe I have found the area of the code issue, but not the root cause.

In the failing "TarArchiveResponse.test.ts" test.

  it('should extract entire archive into directory', async () => {
    const stream = fs.createReadStream('/test-archive.tar.gz');

    const res = new TarArchiveResponse(stream, '', '/tmp', 'etag');
    const dir = await res.dir();
    await expect(
      fs.readFile(resolvePath(dir, 'mkdocs.yml'), 'utf8'),
    ).resolves.toBe('site_name: Test\n');
    await expect(
      fs.readFile(resolvePath(dir, 'docs/index.md'), 'utf8'),
    ).resolves.toBe('# Test\n');
  });

The line const res = new TarArchiveResponse(stream, '', '/tmp', 'etag'); initiates the object with an empty subpath.

Now, if I call const files = await res.files(); instead of res.dir() and iterate through the files, I see both of the expected files "./mkdocs.yml" and "./docs/index.md" inside of the archive stream.

However, if I run const files = await fs.readdir(dir); after res.dir(), I only see the "./mkdocs.yml" file and NOT the "./docs/index.md" file.

*Note: you cannot run both res.files() and res.dir() in the same test execution without resetting the stream, so I ran it twice with each section commented out.

[ericis]

@Rugvip and @OrkoHunter, based on the above ☝🏻 discovery, I think either TarArchiveResponse.dir() should be returning both files when the subpath is empty, or the test should only expect the root "./mkdocs.yml" file in the response. Based on the test name, it seems dir() is supposed to extract all of the files, but maybe the call to tar.extract(...) is being filtered somehow?

[ericis]

TIP: To reproduce locally, I cloned "master" and added the following make target to the contrib makefile in order to make the testing cycle much faster. The initial docker container build and package dependencies will still take a moment.

# execute changed tests only
.PHONY: check-changed-tests
check-changed-tests: install
	@docker run --rm -it \
		--name $(docker_name_timestamp_prefix)-$@ \
		--network host \
		-v $(project_root_dir_path):/app \
		-w /app \
		--entrypoint "" \
		$(docker_tag) \
		yarn run test

With this new target, you can cd contrib/docker/devops and run make check-changed-tests to see the failing tests. You can edit the typescript files and then just re-run to "quickly" see the results.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[jamieklassen]

@ericis I have spent some time over the past few days encountering problems running these tests inside a Docker container myself. I discovered that they fail any time they are run as root.

The 'entire archive' test exercises the extraction of this fixture, which contains at its base a directory belonging to UID 501:

$ tar --numeric-owner -tzvf packages/backend-common/src/reading/__fixtures__/mock-main.tar.gz
drwxr-xr-x  0 501    20          0 27 Oct  2020 mock-main/
-rw-r--r--  0 501    20         16 27 Oct  2020 mock-main/mkdocs.yml
drwxr-xr-x  0 501    20          0 27 Oct  2020 mock-main/docs/
-rw-r--r--  0 501    20          7 27 Oct  2020 mock-main/docs/index.md

when the process UID of the test is 0, then in this tar.extract call the preserveOwner option defaults to true. Because of this, when the mock-main/ entry is being extracted here, then [DOCHOWN](entry) is true so the tempdir into which the fixture is being extracted actually gets its owner changed to UID 501.

[side note: I believe this is a bug in node-tar, because the equivalent sudo tar --strip-components=1 invocation does not change the owner of the working directory.]

Anyway, that's not a problem until later on, when the nested docs/ directory needs to get extracted. During this procedure, eventually node-tar calls out to fs.mkdir, which will be intercepted by mock-fs since the test has registered all of /tmp as a mock directory.

So mock-fs is given the instruction to create a directory inside the tempdir (which is owned by UID 501) -- first thing it checks to see if it has write access. It notices that the current process doesn't own the file, so this check fails and we fall into this branch.

Zooming out a bit, this parent directory was actually created/managed by mock-fs in the first place, when it intercepted this mkdtemp call. When it did so, it created this fake Directory object, which starts its life with 0777 permissions. This would be encouraging, but node-tar chmodded it down to 0755 earlier in the extraction process. So this error gets thrown.

[Another side note, less carefully considered: is this a bug in mock-fs? I vaguely thought root should be able to write any directory...]

So the mkdir call fails silently, since we're using the "streaming" version of extract (no file: parameter). That's why, when it comes to the assertion in the test, it can't find the docs/ dir -- it never successfully extracted in the first place!

I can think of three possible workaround here:

1. (least intrusive) make sure the tests are not running as root
2. change the permissions on the mock-main/ folder inside the tarball to be permissive enough to pass (this affects fixtures for some other tests, like the GithuUrlReader, GitlabUrlReader and BitbucketUrlReader ones)
3. add a preserveOwner: false option to the tar.extract call -- this feels pretty hacky as I'm not sure there are real-world situations where backstage behaves badly when run as root. The problem may only occur when running the tests.

[ericis]

Thanks @jamieklassen . This is fantastic detail! I will look into converting the developer docker walk through to use rootless docker images or at least mention in the documentation that they should run rootless.