RcMap, RcRef and ScopedCache: a dying release is lost on idle expiry, an interrupted lookup, or expiry during `keys`/`values`/`entries`

What version of Effect is running?

4.0.5 (same on main at c9a1e72, which includes #9328)

What steps can reproduce the bug?

When RcMap closes an entry in the background, a defect from the entry's release is neither returned nor logged. Two paths do this:

• an idle entry is closed when its idleTimeToLive elapses;
• a lookup ends interrupted after its last borrower has left, while a non-zero idleTimeToLive keeps the entry. The lookup's finalizers then run, and a defect from one of them is lost. If a borrower is still waiting, the same defect reaches it.

RcRef loses the defect the same way when its value is released after idleTimeToLive, and LayerMap inherits the RcMap idle-expiry path. So does ScopedCache when keys, values or entries closes the expired entries it finds: the scan returns, and the defect is neither returned nor logged, while get on the same expired key logs it.

When the last borrower's scope closes an RcMap entry (the default idleTimeToLive), the defect surfaces.

import { Deferred, Effect, Fiber, RcMap, RcRef, ScopedCache } from "effect"

const release = (key: string) =>
  Effect.sync(() => console.log(`release ${key} runs, then dies`)).pipe(Effect.andThen(Effect.die(`release ${key}`)))

// An idle entry closed when its idleTimeToLive elapses
const idleExpiry = Effect.gen(function*() {
  const map = yield* RcMap.make({
    lookup: (key: string) => Effect.acquireRelease(Effect.succeed(key), () => release(key)),
    idleTimeToLive: "10 millis"
  })
  yield* Effect.scoped(RcMap.get(map, "a"))
  yield* Effect.sleep("50 millis")
})

// A lookup that ends interrupted after its only borrower left
const interruptedLookup = Effect.gen(function*() {
  const proceed = yield* Deferred.make<void>()
  const map = yield* RcMap.make({
    lookup: (key: string) =>
      Effect.gen(function*() {
        yield* Effect.addFinalizer(() => release(key))
        yield* Deferred.await(proceed)
        return yield* Effect.interrupt
      }),
    idleTimeToLive: "1 minute"
  })
  const borrower = yield* Effect.forkChild(Effect.scoped(RcMap.get(map, "a")), { startImmediately: true })
  yield* Fiber.interrupt(borrower)
  yield* Deferred.succeed(proceed, void 0)
  yield* Effect.sleep("50 millis")
})

// The same for RcRef: an idle value closed when its idleTimeToLive elapses
const rcRefIdleExpiry = Effect.gen(function*() {
  const ref = yield* RcRef.make({
    acquire: Effect.acquireRelease(Effect.succeed("a"), () => release("a")),
    idleTimeToLive: "10 millis"
  })
  yield* Effect.scoped(RcRef.get(ref))
  yield* Effect.sleep("50 millis")
})

// ScopedCache: an expired entry closed by a keys scan
const scanExpiry = Effect.gen(function*() {
  const cache = yield* ScopedCache.make({
    capacity: 10,
    timeToLive: "10 millis",
    lookup: (key: string) => Effect.acquireRelease(Effect.succeed(key), () => release(key))
  })
  yield* ScopedCache.get(cache, "a")
  yield* Effect.sleep("50 millis")
  yield* ScopedCache.keys(cache)
})

// Control: with the default idleTimeToLive, the last borrower's scope closes the entry
const lastBorrower = Effect.gen(function*() {
  const map = yield* RcMap.make({
    lookup: (key: string) => Effect.acquireRelease(Effect.succeed(key), () => release(key))
  })
  yield* Effect.scoped(RcMap.get(map, "a"))
})

console.log((await Effect.runPromiseExit(Effect.scoped(idleExpiry)))._tag)
console.log((await Effect.runPromiseExit(Effect.scoped(interruptedLookup)))._tag)
console.log((await Effect.runPromiseExit(Effect.scoped(rcRefIdleExpiry)))._tag)
console.log((await Effect.runPromiseExit(Effect.scoped(scanExpiry)))._tag)
console.log((await Effect.runPromiseExit(Effect.scoped(lastBorrower)))._tag)

These tests, added at the end of packages/effect/test/RcMap.test.ts (with Logger added to its effect import), fail on main (the first two are controls and pass):

describe("release defects without a caller", () => {
  const withLoggedDefect = <A, E, R>(f: (logged: Deferred.Deferred<unknown>) => Effect.Effect<A, E, R>) =>
    Effect.gen(function*() {
      const logged = yield* Deferred.make<unknown>()
      const logger = Logger.make(({ cause }) => {
        for (const reason of cause.reasons) {
          if (Cause.isDieReason(reason)) Deferred.doneUnsafe(logged, Exit.succeed(reason.defect))
        }
      })
      return yield* f(logged).pipe(Effect.provide(Logger.layer([logger])))
    })

  const awaitLogged = (logged: Deferred.Deferred<unknown>) =>
    Effect.gen(function*() {
      const fiber = yield* Deferred.await(logged).pipe(Effect.timeoutOption("1 second"), Effect.forkChild)
      yield* TestClock.adjust("1 second")
      return yield* Fiber.join(fiber)
    })

  const interruptedLookup = (borrowerLeavesFirst: boolean) =>
    Effect.gen(function*() {
      const started = yield* Deferred.make<void>()
      const proceed = yield* Deferred.make<void>()
      const finalized = yield* Deferred.make<void>()
      const map = yield* RcMap.make({
        lookup: (key: string) =>
          Effect.gen(function*() {
            yield* Effect.addFinalizer(() =>
              Deferred.succeed(finalized, void 0).pipe(Effect.andThen(Effect.die(`release ${key}`)))
            )
            yield* Deferred.succeed(started, void 0)
            yield* Deferred.await(proceed)
            return yield* Effect.interrupt
          }),
        idleTimeToLive: "1 minute"
      })
      const borrower = yield* Effect.forkChild(Effect.scoped(RcMap.get(map, "a")), { startImmediately: true })
      yield* Deferred.await(started)
      if (borrowerLeavesFirst) yield* Fiber.interrupt(borrower)
      yield* Deferred.succeed(proceed, void 0)
      yield* Deferred.await(finalized)
      return yield* Fiber.await(borrower)
    })

  it.effect("the capturing logger sees a defect logged at UnhandledLogLevel", () =>
    withLoggedDefect((logged) =>
      Effect.gen(function*() {
        yield* Effect.logWithLevel("Error")("unhandled", Cause.die("release a"))
        assert.deepStrictEqual(yield* awaitLogged(logged), Option.some("release a"))
      })
    ))

  it.effect("an interrupted lookup's dying release reaches a borrower that is still waiting", () =>
    Effect.gen(function*() {
      const exit = yield* interruptedLookup(false)
      if (Exit.isSuccess(exit)) return assert.fail("expected the borrower to be interrupted")
      assert.deepStrictEqual(exit.cause.reasons.filter(Cause.isDieReason).map((reason) => reason.defect), [
        "release a"
      ])
    }))

  it.effect("reports an interrupted lookup's dying release after its only borrower left", () =>
    withLoggedDefect((logged) =>
      Effect.gen(function*() {
        const exit = yield* interruptedLookup(true)
        assert.isTrue(Exit.hasInterrupts(exit))
        assert.deepStrictEqual(yield* awaitLogged(logged), Option.some("release a"))
      })
    ))

  it.effect("reports a dying release of an entry closed by idle expiry", () =>
    withLoggedDefect((logged) =>
      Effect.gen(function*() {
        const released: Array<string> = []
        const map = yield* RcMap.make({
          lookup: (key: string) =>
            Effect.acquireRelease(Effect.succeed(key), () =>
              Effect.sync(() => released.push(key)).pipe(Effect.andThen(Effect.die(`release ${key}`)))),
          idleTimeToLive: "1 second"
        })
        yield* Effect.scoped(RcMap.get(map, "a"))
        yield* TestClock.adjust("1 second")

        assert.deepStrictEqual(released, ["a"])
        assert.isFalse(yield* RcMap.has(map, "a"))
        assert.deepStrictEqual(yield* awaitLogged(logged), Option.some("release a"))
      })
    ))
})

What is the expected behavior?

The defect is reported through UnhandledLogLevel. ScopedCache does this for cleanup failures from expiry found on access and from capacity eviction (#8803), and Pool does it for its finalizers ("Unhandled error in pool finalizer"). #9190 made Atom disposal do the same for the same situation: a scope closed in a detached fiber, whose finalizer failures were never reported.

What do you see instead?

The snippet prints release a runs, then dies before each result: Success, Success, Success, Success, then Failure for the control. Nothing is logged for the first four. The two reports … tests fail with expected { _id: 'Option', _tag: 'None' } to deeply equal { _id: 'Option', _tag: 'Some', …(1) }.

Additional information

Both closes run in fibers forked into the map's scope, and nothing reads their exits. For idle expiry it is the expiry loop's Scope.close (RcMap.ts#L511-L528); for the interrupted lookup, removeInterrupted forks closeEntry (#L465-L481). RcRef's idle expiry closes its value's scope in the same kind of forked fiber, whose exit nothing reads either (internal/rcRef.ts#L224-L238), and LayerMap is an RcMap with the caller's idleTimeToLive (LayerMap.ts#L187-L193). ScopedCache.keys and entries (which values maps) fork a plain Scope.close for each expired entry and discard the exits (ScopedCache.ts#L818-L834, #L880-L901), where an expired entry found by get goes through closeEvicted, under the comment "Expiry and capacity eviction report cleanup failures without failing unrelated readers". main has the same code. #9307 named idle expiry as a related path; #9328, which closed #9307, fixed owner shutdown and left idle-expiry reporting for later. A fix in the expiry loop alone would still lose the interrupted-lookup case. ScopedCache's closeEvicted (ScopedCache.ts#L359-L367) already catches a close's cause and logs it at UnhandledLogLevel.