Closed Bug 1521796 Opened 6 years ago Closed 6 years ago

test failure in monorepo

Categories

(Taskcluster :: Services, defect)

Product:
Taskcluster
Component:
Services
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: pmoore, Assigned: dustin)

Details

Hi guys,

Am I doing anything wrong here? Getting this when running yarn test:

$ mocha test/*_test.js


  documenter
    ✓ tarball exists
    ✓ tarball contains docs and metadata
    ✓ tarball contains schemas and metadata
    ✓ tarball contains references and metadata
    ✓ tarball contains only metadata
    1) write() writes a directory
    ✓ writen schemas are abstract
    ✓ test publish tarball (real) (3594ms)
    ✓ test publish tarball (mock)

  Package
    No git tag, no need to check tag!
    - git tag must match package version


  8 passing (4s)
  1 pending
  1 failing

  1) documenter
       write() writes a directory:

      AssertionError [ERR_ASSERTION]: docs/nested/nested-example.md should exist
      + expected - actual

      -false
      +true
      
      at shoulds.forEach.name (test/main_test.js:195:9)
      at Array.forEach (<anonymous>)
      at docsDir (test/main_test.js:194:15)
      at withWrittenDocs (test/main_test.js:182:13)
      at process.internalTickCallback (internal/process/next_tick.js:77:7)



error Command failed with exit code 1.

Probably something I'm doing - anyone know what it might be?

Flags: needinfo?(dustin)

FTR this is against commit 32bf21dccf8ae4582f5da833c8db76214709ae9a.

Thanks! I can't replicate, though.

Can you try applying

diff --git a/libraries/docs/src/documenter.js b/libraries/docs/src/documenter.js
index 866eb2d0d..2f40dc836 100644
--- a/libraries/docs/src/documenter.js
+++ b/libraries/docs/src/documenter.js
@@ -148,16 +148,17 @@ class Documenter {
     // For the moment, this untar's the tarball created elsewhere in this file;
     // when the "old way' is no longer used, this should be refactored to just
     // write the files to the directory directly.
     const extract = tar.extract();
 
     await new Promise((resolve, reject) => {
       extract.on('entry', (header, stream, next) => {
         // NOTE: we ignore permissions, ownership, etc..
+        console.log(`extract: ${JSON.stringify(header)}`);
         const pathname = path.join(docsDir, header.name);
         mkdirp(path.dirname(pathname)).then(() => {
           stream.once('end', next);
           stream.once('error', reject);
           stream.pipe(fs.createWriteStream(pathname));
         }).catch(reject);
       });

and running yarn workspace taskcluster-lib-docs test?

Flags: needinfo?(dustin) → needinfo?(pmoore)
 $ yarn workspace taskcluster-lib-docs test
yarn workspace v1.12.3
yarn run v1.12.3
$ mocha test/*_test.js


  documenter
    ✓ tarball exists
    ✓ tarball contains docs and metadata
    ✓ tarball contains schemas and metadata
    ✓ tarball contains references and metadata
    ✓ tarball contains only metadata
extract: {"name":"metadata.json","mode":420,"uid":0,"gid":0,"size":92,"mtime":"2019-01-22T18:49:28.000Z","type":"file","linkname":null,"uname":"","gname":"","devmajor":0,"devminor":0}
extract: {"name":"schemas/bar.json","mode":420,"uid":0,"gid":0,"size":415,"mtime":"2019-01-22T18:49:28.000Z","type":"file","linkname":null,"uname":"","gname":"","devmajor":0,"devminor":0}
extract: {"name":"schemas/foo.json","mode":420,"uid":0,"gid":0,"size":415,"mtime":"2019-01-22T18:49:28.000Z","type":"file","linkname":null,"uname":"","gname":"","devmajor":0,"devminor":0}
extract: {"name":"README.md","mode":420,"uid":0,"gid":0,"size":7582,"mtime":"2019-01-22T18:49:28.000Z","type":"file","linkname":null,"uname":"","gname":"","devmajor":0,"devminor":0}
extract: {"name":"docs/example.md","mode":420,"uid":0,"gid":0,"size":122,"mtime":"2019-01-22T18:49:28.000Z","type":"file","linkname":null,"uname":"","gname":"","devmajor":0,"devminor":0}
extract: {"name":"docs/nested/nested-example.md","mode":420,"uid":0,"gid":0,"size":148,"mtime":"2019-01-22T18:49:28.000Z","type":"file","linkname":null,"uname":"","gname":"","devmajor":0,"devminor":0}
    ✓ write() writes a directory
extract: {"name":"metadata.json","mode":420,"uid":0,"gid":0,"size":92,"mtime":"2019-01-22T18:49:28.000Z","type":"file","linkname":null,"uname":"","gname":"","devmajor":0,"devminor":0}
extract: {"name":"schemas/bar.json","mode":420,"uid":0,"gid":0,"size":415,"mtime":"2019-01-22T18:49:28.000Z","type":"file","linkname":null,"uname":"","gname":"","devmajor":0,"devminor":0}
extract: {"name":"schemas/foo.json","mode":420,"uid":0,"gid":0,"size":415,"mtime":"2019-01-22T18:49:28.000Z","type":"file","linkname":null,"uname":"","gname":"","devmajor":0,"devminor":0}
extract: {"name":"README.md","mode":420,"uid":0,"gid":0,"size":7582,"mtime":"2019-01-22T18:49:28.000Z","type":"file","linkname":null,"uname":"","gname":"","devmajor":0,"devminor":0}
extract: {"name":"docs/example.md","mode":420,"uid":0,"gid":0,"size":122,"mtime":"2019-01-22T18:49:28.000Z","type":"file","linkname":null,"uname":"","gname":"","devmajor":0,"devminor":0}
extract: {"name":"docs/nested/nested-example.md","mode":420,"uid":0,"gid":0,"size":148,"mtime":"2019-01-22T18:49:28.000Z","type":"file","linkname":null,"uname":"","gname":"","devmajor":0,"devminor":0}
    ✓ writen schemas are abstract
    ✓ test publish tarball (real) (4378ms)
    ✓ test publish tarball (mock)

  Package
    No git tag, no need to check tag!
    - git tag must match package version


  9 passing (4s)
  1 pending

✨  Done in 5.48s.
✨  Done in 5.93s.

Weird. With the logging it now seems to pass! :)

The observation caused the wave function to collapse....

Flags: needinfo?(pmoore)

This is sounding like a race condition, and since this isn't very parallel code, that sounds a lot like a missed "await". I'll stare harder at the code to see if I can spot it (JS doesn't have great tools for finding this sort of thing).

Assignee: nobody → dustin
Component: General → Platform Libraries

It would be helpful to know if this fails or succeeds every time for you (with or without the logging).

I'll run it a few more times...

  64 passing (390ms)
  4 failing

  1) built-services_test.js
       reads references:
     Error: ENOENT, no such file or directory '/test/input/svc1/schemas'
      at Binding.<anonymous> (/Users/pmoore/git/taskcluster/node_modules/mock-fs/lib/binding.js:1204:13)
      at maybeCallback (/Users/pmoore/git/taskcluster/node_modules/mock-fs/lib/binding.js:61:17)
      at Binding.access (/Users/pmoore/git/taskcluster/node_modules/mock-fs/lib/binding.js:1192:3)
      at Object.existsSync (fs.js:237:11)
      at loadSchemas (src/built-services.js:33:11)
      at fs.readdirSync.forEach.dentry (src/built-services.js:74:5)
      at Array.forEach (<anonymous>)
      at load (src/built-services.js:61:29)
      at Context.<anonymous> (test/built-services_test.js:47:35)

  2) built-services_test.js
       References.fromBuiltServices reads references and adds common:
     Error: ENOENT, no such file or directory '/test/input/svc1/schemas'
      at Binding.<anonymous> (/Users/pmoore/git/taskcluster/node_modules/mock-fs/lib/binding.js:1204:13)
      at maybeCallback (/Users/pmoore/git/taskcluster/node_modules/mock-fs/lib/binding.js:61:17)
      at Binding.access (/Users/pmoore/git/taskcluster/node_modules/mock-fs/lib/binding.js:1192:3)
      at Object.existsSync (fs.js:237:11)
      at loadSchemas (src/built-services.js:33:11)
      at fs.readdirSync.forEach.dentry (src/built-services.js:74:5)
      at Array.forEach (<anonymous>)
      at Object.load (src/built-services.js:61:29)
      at Function.fromBuiltServices (src/references.js:44:47)
      at Context.<anonymous> (test/built-services_test.js:59:35)

  3) built-services_test.js
       reads schemas at all nesting levels:
     Error: ENOENT, no such file or directory '/test/input/svc1/references'
      at Binding.<anonymous> (/Users/pmoore/git/taskcluster/node_modules/mock-fs/lib/binding.js:1204:13)
      at maybeCallback (/Users/pmoore/git/taskcluster/node_modules/mock-fs/lib/binding.js:61:17)
      at Binding.access (/Users/pmoore/git/taskcluster/node_modules/mock-fs/lib/binding.js:1192:3)
      at Object.existsSync (fs.js:237:11)
      at loadReferences (src/built-services.js:13:11)
      at fs.readdirSync.forEach.dentry (src/built-services.js:73:5)
      at Array.forEach (<anonymous>)
      at load (src/built-services.js:61:29)
      at Context.<anonymous> (test/built-services_test.js:88:35)

  4) uri-structured_test.js
       writes files:
     Error: ENOENT, no such file or directory '/refdata/foo'
      at Binding.<anonymous> (/Users/pmoore/git/taskcluster/node_modules/mock-fs/lib/binding.js:1204:13)
      at maybeCallback (/Users/pmoore/git/taskcluster/node_modules/mock-fs/lib/binding.js:61:17)
      at Binding.access (/Users/pmoore/git/taskcluster/node_modules/mock-fs/lib/binding.js:1192:3)
      at Object.existsSync (fs.js:237:11)
      at Context.<anonymous> (test/uri-structured_test.js:27:16)



error Command failed with exit code 4.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.
error Command failed.
Exit code: 1
Command: /usr/local/Cellar/node/11.2.0/bin/node
Arguments: /usr/local/Cellar/yarn/1.12.3/libexec/lib/cli.js test
Directory: /Users/pmoore/git/taskcluster/libraries/references
Output:

info Visit https://yarnpkg.com/en/docs/cli/workspaces for documentation about this command.
error Command failed with exit code 1.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.

Looks like you're using node 11.2. I can reproduce those errors on 11.2, too. I'm guessing the fs module changed, and the mock version no longer works with it. We'll deal with that when we upgrade to node 11, but for the moment we're on node 10.14.0.

I can't reproduce the original error with 11.2, by the way, even running it multiple times.

Irene, do you see this sort of issue running on your mac? I wonder if it's something macOS-related? Maybe capitalization??

Flags: needinfo?(bugzeeeeee)

Ah, I reproduced after many runs of that test suite.. ok, I can chase this down now.

Flags: needinfo?(bugzeeeeee)

It does not fail on a quiet system, but fails pretty quickly when I load the system up (e.g., by running tc-builder)

So here's what I see in strace. The access commands are the fs.existsSync calls. The write happens at almost exactly the same time in another thread -- in fact, just a little too late, causing the failure.

[pid 17425] openat(AT_FDCWD, "/tmp/tmp-17027kbpGOMXi07Oo/docs_output_dir/docs/nested/nested-example.md", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666 <unfinished ...>
[pid 17027] access("/tmp/tmp-17027kbpGOMXi07Oo/docs_output_dir/docs/example.md", F_OK) = 0
[pid 17027] access("/tmp/tmp-17027kbpGOMXi07Oo/docs_output_dir/docs/nested/nested-example.md", F_OK) = -1 ENOENT (No such file or directory)
[pid 17425] <... openat resumed> ) = 20

So, this is the problematic code:

    const extract = tar.extract();

    await new Promise((resolve, reject) => {                                                                                                                                                                                                   
      extract.on('entry', (header, stream, next) => {
        // NOTE: we ignore permissions, ownership, etc..
        const pathname = path.join(docsDir, header.name);
        mkdirp(path.dirname(pathname)).then(() => {
          stream.once('end', next);
          stream.once('error', reject);
          stream.pipe(fs.createWriteStream(pathname));
        }).catch(reject);
      }); 

      extract.on('finish', resolve);
      extract.on('error', reject);

      this._tarballStream()
        .then(tbStream => tbStream.pipe(zlib.Unzip()).pipe(extract))
        .catch(reject);
    });

What's happening is that the inner stream is finishing and emitting its end event, which calls next, which since that's the last entry in the tarball causes extract to emit finished, which resolves the promise and allows the assertions to begin. But while that chain unravels, the writeStream hasn't yet written the data, so the file doesn't exist yet.

I actually don't know how to fix this - I've never figured out how to work with streams in JS. Help?

John, any ideas?

Flags: needinfo?(jhford)
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Component: Platform Libraries → Services
You need to log in before you can comment on or make changes to this bug.