Deno: Crash on fs.copy - thread 'main' panicked at 'already borrowed: BorrowMutError'

[prcdpr]

Version: 1.4.6
Platform: Windows

Repro steps:

import * as fs from "https://deno.land/[email protected]/fs/mod.ts";
await fs.copy(
  srcDir,
  destDir,
  { preserveTimestamps: true, overwrite: true },
);

srcDir is a local path.
destDir is a network share path.

thread 'main' panicked at 'already borrowed: BorrowMutError', cli\ops\net.rs:280:30
stack backtrace:
   0:     0x7ff7c2dfc496 - <unknown>
   1:     0x7ff7c2a695fb - <unknown>
   2:     0x7ff7c2dfb334 - <unknown>
   3:     0x7ff7c2dfaa28 - <unknown>
   4:     0x7ff7c2df9d4e - <unknown>
   5:     0x7ff7c2e02975 - <unknown>
   6:     0x7ff7c2e02937 - <unknown>
   7:     0x7ff7c2e028df - <unknown>
   8:     0x7ff7c2a66bd0 - <unknown>
   9:     0x7ff7c2a6de73 - <unknown>
  10:     0x7ff7c287989c - <unknown>
  11:     0x7ff7c292a4cc - <unknown>
  12:     0x7ff7c27e1ea1 - <unknown>
  13:     0x7ff7c2a7b334 - <unknown>
  14:     0x7ff7c2a810b3 - <unknown>
  15:     0x7ff7c29f9ae9 - <unknown>
  16:     0x7ff7c28fb327 - <unknown>
  17:     0x7ff7c28a5343 - <unknown>
  18:     0x7ff7c2a0f957 - <unknown>
  19:     0x7ff7c28412e0 - <unknown>
  20:     0x7ff7c2a18557 - <unknown>
  21:     0x7ff7c3a797e0 - CrashForExceptionInNonABICompliantCodeRange
  22:     0x7ffe40367bd4 - BaseThreadInitThunk
  23:     0x7ffe421cce51 - RtlUserThreadStart

It's possible that preserveTimestamps: true causes the problem.

[kitsonk]

That code is related to opening a TCP connection which is really strange, should be totally unrelated to this bit of code... Could you give an example of what the destDir value actually is, as well the output of deno run -L debug.

[prcdpr]

Ok so I ran my code once again without changing it and I got slightly different callstack

thread 'main' panicked at 'already borrowed: BorrowMutError', cli\metrics.rs:110:35
stack backtrace:
   0:     0x7ff77441c496 - <unknown>
   1:     0x7ff7740895fb - <unknown>
   2:     0x7ff77441b334 - <unknown>
   3:     0x7ff77441aa28 - <unknown>
   4:     0x7ff774419d4e - <unknown>
   5:     0x7ff774422975 - <unknown>
   6:     0x7ff774422937 - <unknown>
   7:     0x7ff7744228df - <unknown>
   8:     0x7ff774086bd0 - <unknown>
   9:     0x7ff77408de73 - <unknown>
  10:     0x7ff773e9989c - <unknown>
  11:     0x7ff773e01eec - <unknown>
  12:     0x7ff77409b334 - <unknown>
  13:     0x7ff7740a10b3 - <unknown>
  14:     0x7ff774019ae9 - <unknown>
  15:     0x7ff773f1b327 - <unknown>
  16:     0x7ff773ec5343 - <unknown>
  17:     0x7ff77402f957 - <unknown>
  18:     0x7ff773e612e0 - <unknown>
  19:     0x7ff774038557 - <unknown>
  20:     0x7ff7750997e0 - CrashForExceptionInNonABICompliantCodeRange
  21:     0x7ffe9ac47c24 - BaseThreadInitThunk
  22:     0x7ffe9b44cea1 - RtlUserThreadStart

Running deno run -L debug causes another error that seems totally unrelated (it didn't even progress to the place that originally failed)

error: Uncaught DenoStdInternalError: bufio: caught error from `readSlice()` without `partial` property
    throw new DenoStdInternalError(msg);
          ^
    at assert (assert.ts:13:11)
    at BufReader.readLine (bufio.ts:253:7)
    at async TextProtoReader.readLineSlice (mod.ts:130:17)
    at async TextProtoReader.readLine (mod.ts:32:15)
    at async Object.copyFrom (cli.ts:131:22)

srcDir is in form of D:\myprojects\builds\bin
destDir is in form of \\mysynologyserver\networkshare\subfolder1

It doesn't repro 100% - once per couple of runs it succeeds. More often I get callstack with cli\metrics.rs:110:35 than cli\ops\net.rs:280:30 so the metrics.rs should be checked first.

[kitsonk]

Wow... 🤯 amazing... great job breaking Deno in really interesting ways. Sorry it is causing you grief. Both of the panics relate to locking the op state.

About how many files are in D:\myprojects\builds\bin?

@bartlomieju @ry I've looked at cli/ops/fs.rs and I am not seeing any obvious potential deadlock situations with state, but it does seem one is occurring when we are doing a "heavy" amount of file system ops.

[prcdpr]

great job breaking Deno in really interesting ways.

I'll try my best to help you resolve that problem 😄

D:\myprojects\builds\bin looks like this, pretty lightweight.

.
├── [3M]  file1.ext
├── [ 44K]  file2.ext
├── [200K]  file3.ext
├── [200K]  file4.ext
├── [2K]  file5.ext
└── [9K]  subfolder1
    └── [5K]  file6.ext

I'd suggest to look how preserveTimestamps: true affects copying, to me it looks like a potential offender

[bartlomieju]

@bartlomieju @ry I've looked at cli/ops/fs.rs and I am not seeing any obvious potential deadlock situations with state, but it does seem one is occurring when we are doing a "heavy" amount of file system ops.

@kitsonk the only known API causing BorrowMutError is Deno.listenDatagram() (as described in https://github.com/denoland/deno/issues/6290).

@prcdpr could you please share full reproduction code?

[prcdpr]

Sorry about late answer, I was somewhere else during last weeks.

I have discovered that my problem occurs only when I use https://github.com/denolib/deno-redis

It sounds incredibly stupid but here is repro code:

import {
  connect,
  RedisConnectOptions,
} from "https://deno.land/x/[email protected]/mod.ts";
import * as fs from "https://deno.land/[email protected]/fs/mod.ts";

const redisOptions: RedisConnectOptions = {
  hostname: "your-redis-server-hostname",
  port: 6379,
};

const srcDir = "D:\myprojects\builds\bin";
const destDir = "\\mysynologyserver\networkshare\subfolder1";

const redis = await connect(redisOptions);
await redis.set("SomeKey1", "abcdefgh", { ex: 60, mode: "NX" });
setInterval(async () => {
  const redis = await connect(redisOptions);
  await redis.expire("SomeKey1", 60);
}, 100);

await fs.ensureDir(destDir);
await fs.emptyDir(destDir);
await fs.copy(srcDir, destDir, { preserveTimestamps: true, overwrite: true });

With interval set to 100 it crashes, with interval set to 100000 it hangs 🤷‍♂️

Run command:

.\deno.exe --unstable run --allow-read --allow-write --allow-net .\repro.ts