Transformation error when instrumenting the same file is multiple concurrent processes

[ajafff]

The Windows CI of my project is failing intermittendly because of a transformation error (because of the output to stderr to be more precise).

For example : https://ci.appveyor.com/project/ajafff/wotan/build/1.0.268

Transformation error for C:\\projects\\wotan\\packages\\wotan\\src\\test.js ; return original code
EPERM: operation not permitted, rename 'C:\\projects\\wotan\\node_modules\\.cache\\nyc\\b02833cec8fc53deebd0f2490cfebdba_11.4.1.js.1850078834' -> 'C:\\projects\\wotan\\node_modules\\.cache\\nyc\\b02833cec8fc53deebd0f2490cfebdba_11.4.1.js'
Transformation error for C:\\projects\\wotan\\packages\\wotan\\src\\services\\default\\directory-service.js ; return original code
EPERM: operation not permitted, rename 'C:\\projects\\wotan\\node_modules\\.cache\\nyc\\d42708c875570eee94cf5796e9bd499e_11.4.1.js.886011032' -> 'C:\\projects\\wotan\\node_modules\\.cache\\nyc\\d42708c875570eee94cf5796e9bd499e_11.4.1.js

I use nyc to collect the coverage of my ava tests. The tests are run concurrently by default.

This error seems to only occur when running the tests in parallel. And I don't have the same issue on Linux or macOS.
The issue occurred when I had no cache: true in my .nycrc.json and after I enabled the cache.

I guess this is related to concurrent access to the same cache.

What information do you need to diagnose this issue?

---

My project is https://github.com/fimbullinter/wotan
To run the tests with coverage, you need to yarn install and yarn compile first and then nyc yarn test

[ehmicky]

I am having exactly the same issue with my own project: https://travis-ci.org/ehmicky/unix-permissions

This is happening on Travis not AppVeyor, so this is not CI-specific.

This also is only happening on Windows.

I am also using nyc + ava in parallel.

The error messages are the same, including EPERM and rename failure on node_modules\.cache\nyc\ID.js.NUMBER -> node_modules\.cache\nyc\ID.js.

[ehmicky]

I've tried with nyc 14.0.0 and it now seems to be working fine for me. Although it's hard to be 100% sure considering the problem appeared randomly. If it appears again, I will post a comment.

[ehmicky]

Never mind, this is still happening: https://travis-ci.org/ehmicky/unix-permissions/jobs/523407051

[coreyfarrell]

This appears to be an upstream issue, possibly node.js itself. caching-transform uses write-file-atomic to save cache files, see npm/write-file-atomic#28.

I'm open to suggestions but I don't know if this one can be solved. The only potential work-around would be to set cache: false on nyc. Maybe nyc@15.0.0 could make the default cache: false for Windows only (still default cache: true for other platforms). This would not prevent .nycrc from having cache: true to force it on Windows.

CC @bcoe @JaKXz

[ehmicky]

Thanks for looking into it!
Yes that npm issue might be the problem.
I'm going to try to use cache: false and report if this works. The bug appears randomly, so it might take few days to manifest in my CI builds.

[ehmicky]

When using cache: false, another error is still thrown. But this time it is:

`Transformation error for C:\\Users\\travis\\build\\ehmicky\\unix-permissions\\build\\src\\bin\\main.js ; return original code␊
EBADF: bad file descriptor, close`

This error was also reported in npm/write-file-atomic#28, so this does seem to be the cause of this issue.

[coreyfarrell]

This is odd as cache: false should disable caching-transform, so I'm not sure how this can still happen. Also for reference I use nyc ava on many of my own projects and have never had this issue.

[ehmicky]

I implemented it wrong, and cache: true was actually passed. With cache: false, it seems to work now (although I need to wait for few days to confirm that since the bug is somewhat random).

I also don't have that issue with most of my projects that use nyc ava except one that has about 3000 small CPU-bound unit tests run in parallel.

Using cache: false does make tests much slower, so I'm wondering if there is another way to solve the problem solved by write-file-atomic? I am trying to understand what this problem is, and what I understand so far is:

1. Istanbul hooks into require() and vm.runIn[This]Context() in order to instruments files.
2. The same file might be instrumented twice if it's required by two different files.
3. Because of 2), nyc caches files instrumentation in node_modules/.cache/nyc/
4. Because of 2) and 3), there might be a concurrency issue where a file is currently being instrumented, while another is checking if it's already in the cache. The cached file might be partially written (before I/O writes are not atomic), which would be a problem.
5. write-file-atomic fixes this by writing cached files into a different directory, then calling fs.rename() once the file is entirely written.
6. The solution 5) has issues on Windows because fs.rename() themselves might create concurrency issues when two fs.rename() are performed at the same time.

Just trying to understand the problem here: did I get anything wrong?

[coreyfarrell]

8 minutes vs 38 minutes... wow. That's quite a bit. I think this cancels my plan to set cache: false by default on Windows. I think you understand the issue.

In theory you could create an npm pretest script that initializes the cache. This would be done by running nyc ./require-everything.js where require-everything.js is a script such as:

const nycConfig = JSON.parse(process.env.NYC_CONFIG);
const testExclude = require('test-exclude')(nycConfig);

testExclude.globSync().forEach(source => {
  require(source);
});

This should cause every file to be instrumented in a single process which runs before your tests. Note that the nyc ./require-everything.js command must have the same command-line options as you use when you run your tests to ensure everything works the same. So this pretest script would create an .nyc_output with some coverage, but when you run your actual tests that will get reset (as long as you don't pass --no-clean to nyc). Important thing is that node_modules/.cache/nyc from the pretest step would remain so in theory no cache files would need to be created during running of ava.

Also beware if any of your sources have side-effects during require(). For this reason I'm unsure it's even possible for nyc to get a 'pre-cache' option.

[ehmicky]

Actually it's more like: 22 minutes with nyc --cache ava --serial and 38 minutes with nyc --no-cache ava (note that removing --serial should speed up the tests). ava --serial is another workaround for this problem but it also makes tests much slower. Windows is just much slower on Travis than Linux and Mac, hence the difference with 8 minutes on those OS.

Thanks for the workaround, I will try it out.

I think the real fix for this issue is to have npm/write-file-atomic#28 fixed. That's a pretty complex one though.

What about the following workaround: if write-file-atomic fails with an EPERM error, silently do not propagate the error:

- writeFileAtomic.sync(cachedPath, result, {encoding});
+ try {
+   writeFileAtomic.sync(cachedPath, result, {encoding});
+ } catch (error) {
+   if (error.code !== 'EPERM') { 
+    throw error
+  }
+ }

If caching fails, code should still work. The only difference is that instrumentation won't be cached for that file. Next time the file is instrumented, caching might succeed then.

Some extra checks could be made be sure that EPERM is due to that bug, and not to the cache directory not being writable.

Would this work?

[coreyfarrell]

I'm not sure. In theory if we have this failure then the code should already be cached, unless we're getting a legit EPERM error. I'm thinking that it might be better to implement loop that will retry up to 3 times. If writeFileAtomic fails then hopefully the file exists because of the other process we conflicted with, then we can simply read that file / return the contents.

I'm against having caching-transform silently swallow errors.

[ehmicky]

Yes you're right that seems like a more robust solution.

[coreyfarrell]

@ehmicky I've been informed this write-file-atomic issue might be a regression in >2.3.0. I've pushed a branch https://github.com/istanbuljs/caching-transform/tree/pin-write-file-atomic which pins write-file-atomic to the version which (potentially) does not have the issue. Could you test with this? You should be able to setup your project with devDependencies for "nyc": "^14.1.1" and "caching-transform": "istanbuljs/caching-transform#pin-write-file-atomic". In theory the caching-transform git branch should match the version requested by nyc. Maybe add a pretest script to npm ls write-file-atomic so your CI will verify the desired version is installed.

[ehmicky]

Thanks for checking this out!

This version pinning does not resolve as expected. In package.json:

"devDependencies": {
    "caching-transform": "istanbuljs/caching-transform#pin-write-file-atomic",
    "nyc": "^14.1.1"
}

$ npm install
$ npm ls caching-transform
gulp-shared-tasks@0.27.57 /home/ehmicky/gulp-shared-tasks
├── caching-transform@3.0.2  (github:istanbuljs/caching-transform#c832db48c670a104a36d28aa3bf7ea7eb888395a)
└─┬ nyc@14.1.1
  └── caching-transform@3.0.2  deduped (github:istanbuljs/caching-transform#c832db48c670a104a36d28aa3bf7ea7eb888395a)

Somehow nyc > caching-transform resolves to 3.0.2 hash c832db48c670a104a36d28aa3bf7ea7eb888395a. I think the npm deduping logic might be using the package version, not the commit hash. I.e. if you bump the package version on that branch, this might now work.

[coreyfarrell]

That is actually expected, caching-transform on git still has "version": "3.0.2" in package.json. Getting npm to dedupe caching-transform for nyc is the goal. That is why I recommended checking npm ls write-file-atomic. BTW the hash you list is the expected git commit from the branch.

[ehmicky]

Oh you're right.

Unfortunately the bug is still happening even with write-file-atomic@2.3.0:

Transformation error for C:\Users\travis\build\ehmicky\unix-permissions\build\src\types\number\main.js ; return original code
EPERM: operation not permitted, rename 'C:\Users\travis\build\ehmicky\unix-permissions\node_modules\.cache\nyc\73e932cc8ff717582f7458c6358055f31aefc962d703eab4ad4231e9f3217d86.js.1760413880' -> 'C:\Users\travis\build\ehmicky\unix-permissions\node_modules\.cache\nyc\73e932cc8ff717582f7458c6358055f31aefc962d703eab4ad4231e9f3217d86.js'
Transformation error for C:\Users\travis\build\ehmicky\unix-permissions\build\src\types\number\parse.js ; return original code
EPERM: operation not permitted, rename 'C:\Users\travis\build\ehmicky\unix-permissions\node_modules\.cache\nyc\f0aa752442d34de3d7cb2e7af115022c21ecf423266c6a7a97a121bdf8c149ea.js.3901119256' -> 'C:\Users\travis\build\ehmicky\unix-permissions\node_modules\.cache\nyc\f0aa752442d34de3d7cb2e7af115022c21ecf423266c6a7a97a121bdf8c149ea.js'
Transformation error for C:\Users\travis\build\ehmicky\unix-permissions\build\src\types\octal\constants.js ; return original code
EPERM: operation not permitted, rename 'C:\Users\travis\build\ehmicky\unix-permissions\node_modules\.cache\nyc\9ce2b40b89d091f235d42defab01aab9066d037d3c8c8712be0e7c149b09a8fc.js.3675856278' -> 'C:\Users\travis\build\ehmicky\unix-permissions\node_modules\.cache\nyc\9ce2b40b89d091f235d42defab01aab9066d037d3c8c8712be0e7c149b09a8fc.js'
Transformation error for C:\Users\travis\build\ehmicky\unix-permissions\build\src\types\object\parse.js ; return original code
EPERM: operation not permitted, rename 'C:\Users\travis\build\ehmicky\unix-permissions\node_modules\.cache\nyc\c13b1b00fcabbc2529ecfc3ec43862aa793cb126a68e3d3fe32bd8b989586880.js.3395352600' -> 'C:\Users\travis\build\ehmicky\unix-permissions\node_modules\.cache\nyc\c13b1b00fcabbc2529ecfc3ec43862aa793cb126a68e3d3fe32bd8b989586880.js'
Transformation error for C:\Users\travis\build\ehmicky\unix-permissions\build\src\converters.js ; return original code
EPERM: operation not permitted, rename 'C:\Users\travis\build\ehmicky\unix-permissions\node_modules\.cache\nyc\58c7bc45d7bd34c3949759ed5b5fb16106f3d2c20089485592be7784648e5df9.js.430980580' -> 'C:\Users\travis\build\ehmicky\unix-permissions\node_modules\.cache\nyc\58c7bc45d7bd34c3949759ed5b5fb16106f3d2c20089485592be7784648e5df9.js'
Transformation error for C:\Users\travis\build\ehmicky\unix-permissions\build\src\helpers.js ; return original code
EPERM: operation not permitted, rename 'C:\Users\travis\build\ehmicky\unix-permissions\node_modules\.cache\nyc\1d1c0c35d491900849c7803fd978ff8a0b57b40b8ca8399797064fcaa9306429.js.3870362177' -> 'C:\Users\travis\build\ehmicky\unix-permissions\node_modules\.cache\nyc\1d1c0c35d491900849c7803fd978ff8a0b57b40b8ca8399797064fcaa9306429.js'

[coreyfarrell]

Thanks for testing. Please give it a try with istanbuljs/caching-transform#unbreak-windows (https://github.com/istanbuljs/caching-transform/tree/unbreak-windows).

[ehmicky]

Thanks, this seems to be working! I've tried re-running the CI jobs few times now, and there are no errors. I will try again through the weekend, and let you know if any errors is triggered.

[ehmicky]

I have restarted the job about 15 times, and it seems to be working!

[coreyfarrell]

This issue can be temporarily worked around by configuring your package.json with a development dependency on "caching-transform": "istanbuljs/caching-transform#1689877". Note that this updated version requires node.js 8. This fix will be included directly with nyc@15. Please follow istanbuljs/nyc#1104 for updates about the new release.

[ehmicky]

Thanks @coreyfarrell!