refactor: make an atomic write (#5361)

Problem:

When writing to our SSO cache we noticed malformed json files that had
our token. As a solution we did an "atomic" write where we wrote a temp
file then renamed. This prevented the content from being malformed due to
a separate write.

The issue is that the combination of writing a temp file, then renaming it
fails sometimes as indicated by our metric `aws_refreshCredentials` where we
were seeing a 'FileNotFound' error.

Solution:

Move the atomic write logic in to `FileSystem.writeFile()` itself, where it is
triggered as part of an argument to the function.

Additionally when the `rename()` method is called under the hood of `writeFile()`,
we validate that the file exists by retrying a few times. We suspect this to be
the culprit of the `FileNotFound` error, see the comments in code for more info.

Signed-off-by: Nikolas Komonen <[email protected]>

Author: nkomonen-amazon

packages/core/src/shared/fs/fs.ts

@@ -7,10 +7,20 @@ import os from 'os'
 import { promises as nodefs, constants as nodeConstants, WriteFileOptions } from 'fs'
 import { isCloud9 } from '../extensionUtilities'
 import _path from 'path'
-import { PermissionsError, PermissionsTriplet, ToolkitError, isFileNotFoundError, isPermissionsError } from '../errors'
+import {
+    PermissionsError,
+    PermissionsTriplet,
+    ToolkitError,
+    isFileNotFoundError,
+    isPermissionsError,
+    scrubNames,
+} from '../errors'
 import globals from '../extensionGlobals'
 import { isWin } from '../vscode/env'
 import { resolvePath } from '../utilities/pathUtils'
+import crypto from 'crypto'
+import { waitUntil } from '../utilities/timeoutUtils'
+import { telemetry } from '../telemetry/telemetry'
 
 const vfs = vscode.workspace.fs
 type Uri = vscode.Uri
@@ -182,24 +192,57 @@ export class FileSystem {
      *
      * @param path File location
      * @param data File content
-     * @param opt File permissions/flags. Only works in a non-web (nodejs) context. If provided,
+     * @param opts File permissions/flags. Only works in a non-web (nodejs) context. If provided,
      * nodejs filesystem interface is used instead of routing through vscode VFS.
+     * @param opts.atomic If true, ensures content is not corrupted from a concurrent write.
+     *                    This is not truly atomic as an async write can override the final result,
+     *                    but if the content is structured like JSON it will still be parseable.
+     *
+     *                    Eg: we were seeing a JSON file with an unexpected extra '}' and when parsing it
+     *                    failed. We suspected a race condition from separate write, and all we wanted was
+     *                    a parseable JSON.
+     *
+     *                    This optional has an uncalcuated performance impact as there is an additional
+     *                    rename() operation.
      */
-    async writeFile(path: Uri | string, data: string | Uint8Array, opt?: WriteFileOptions): Promise<void> {
+    async writeFile(
+        path: Uri | string,
+        data: string | Uint8Array,
+        opts?: WriteFileOptions & { atomic?: boolean }
+    ): Promise<void> {
         const uri = this.#toUri(path)
         const errHandler = createPermissionsErrorHandler(this.isWeb, uri, '*w*')
         const content = this.#toBytes(data)
-        // - Special case: if `opt` is given, use nodejs directly. This isn't ideal, but is the only
-        //   way (unless you know better) we can let callers specify permissions.
-        // - Cloud9 vscode.workspace.writeFile has limited functionality, e.g. cannot write outside
-        //   of open workspace.
-        const useNodejs = (opt && !this.isWeb) || isCloud9()
 
-        if (useNodejs) {
-            return nodefs.writeFile(uri.fsPath, content, opt).catch(errHandler)
+        if (this.isWeb) {
+            return vfs.writeFile(uri, content).then(undefined, errHandler)
         }
 
-        return vfs.writeFile(uri, content).then(undefined, errHandler)
+        // Node writeFile is the only way to set `writeOpts`, such as the `mode`, on a file .
+        // When not in web we will use Node's writeFile() for all other scenarios.
+        // It also has better error messages than VS Code's writeFile().
+        let write = (u: Uri) => nodefs.writeFile(u.fsPath, content, opts).then(undefined, errHandler)
+
+        if (isCloud9()) {
+            // In Cloud9 vscode.workspace.writeFile has limited functionality, e.g. cannot write outside
+            // of open workspace.
+            //
+            // This is future proofing in the scenario we switch the initial implementation of `write()`
+            // to something else, C9 will still use node fs.
+            write = (u: Uri) => nodefs.writeFile(u.fsPath, content, opts).then(undefined, errHandler)
+        }
+
+        // Node writeFile does NOT create parent folders by default, unlike VS Code FS writeFile()
+        await fs.mkdir(_path.dirname(uri.fsPath))
+
+        if (opts?.atomic) {
+            const tempFile = this.#toUri(`${uri.fsPath}.${crypto.randomBytes(8).toString('hex')}.tmp`)
+            await write(tempFile)
+            await fs.rename(tempFile, uri)
+            return
+        } else {
+            await write(uri)
+        }
     }
 
     async rename(oldPath: vscode.Uri | string, newPath: vscode.Uri | string) {
@@ -211,9 +254,56 @@ export class FileSystem {
             return nodefs.rename(oldUri.fsPath, newUri.fsPath).catch(errHandler)
         }
 
+        /**
+         * We were seeing 'FileNotFound' errors during renames, even though we did a `writeFile()` right before the rename.
+         * The error looks to be from here: https://github.com/microsoft/vscode/blob/09d5f4efc5089ce2fc5c8f6aeb51d728d7f4e758/src/vs/platform/files/node/diskFileSystemProvider.ts#L747
+         * So a guess is that the exists()(stat() under the hood) call needs to be retried since there may be a race condition.
+         */
+        let attempts = 0
+        const isExists = await waitUntil(async () => {
+            const result = await fs.exists(oldUri)
+            attempts += 1
+            return result
+        }, FileSystem.renameTimeoutOpts)
+        // TODO: Move the `ide_fileSystem` or some variation of this metric in to common telemetry
+        // TODO: Deduplicate the `ide_fileSystem` call. Maybe have a method that all operations pass through which wraps the call in telemetry.
+        //       Then look to report telemetry failure events.
+        const scrubbedPath = scrubNames(oldUri.fsPath)
+        if (!isExists) {
+            // source path never existed after multiple attempts.
+            // Either the file never existed, or had we waited longer it would have. We won't know.
+            telemetry.ide_fileSystem.emit({
+                result: 'Failed',
+                action: 'rename',
+                reason: 'SourceNotExists',
+                reasonDesc: `After ${FileSystem.renameTimeoutOpts.timeout}ms the source path did not exist: ${scrubbedPath}`,
+            })
+        } else if (attempts > 1) {
+            // Indicates that rename() would have failed if we had not waited for it to exist.
+            telemetry.ide_fileSystem.emit({
+                result: 'Succeeded',
+                action: 'rename',
+                reason: 'RenameRaceCondition',
+                reasonDesc: `After multiple attempts the source path existed: ${scrubbedPath}`,
+                attempts: attempts,
+            })
+        }
+
         return vfs.rename(oldUri, newUri, { overwrite: true }).then(undefined, errHandler)
     }
 
+    /**
+     * It looks like scenario of a failed rename is rare,
+     * so we can afford to have a longer timeout and interval.
+     *
+     * These values are an arbitrary guess to how long it takes
+     * for a newly created file to be visible on the filesystem.
+     */
+    static readonly renameTimeoutOpts = {
+        timeout: 10_000,
+        interval: 300,
+    } as const
+
     /**
      * The stat of the file,  throws if the file does not exist or on any other error.
      */

packages/core/src/shared/telemetry/vscodeTelemetry.json

@@ -273,6 +273,20 @@
         }
     ],
     "metrics": [
+        {
+            "name": "ide_fileSystem",
+            "description": "File System event on execution",
+            "metadata": [
+                {
+                    "type": "action",
+                    "required": true
+                },
+                {
+                    "type": "attempts",
+                    "required": false
+                }
+            ]
+        },
         {
             "name": "vscode_executeCommand",
             "description": "Emitted whenever a registered Toolkit command is executed",

packages/core/src/shared/utilities/cacheUtils.ts

@@ -7,7 +7,6 @@ import * as vscode from 'vscode'
 import { dirname } from 'path'
 import { ToolkitError, isFileNotFoundError } from '../errors'
 import fs from '../../shared/fs/fs'
-import crypto from 'crypto'
 import { isWeb } from '../extensionGlobals'
 import type { MapSync } from './map'
 
@@ -131,14 +130,12 @@ export function createDiskCache<T, K>(
                 await fs.mkdir(dirname(target))
                 if (isWeb()) {
                     // There is no web-compatible rename() method. So do a regular write.
-                    await fs.writeFile(target, JSON.stringify(data), { mode: 0o600 })
+                    await fs.writeFile(target, JSON.stringify(data))
                 } else {
                     // With SSO cache we noticed malformed JSON on read. A guess is that multiple writes
                     // are occuring at the same time. The following is a bandaid that ensures an all-or-nothing
                     // write, though there can still be race conditions with which version remains after overwrites.
-                    const tempFile = `${target}.tmp-${crypto.randomBytes(4).toString('hex')}`
-                    await fs.writeFile(tempFile, JSON.stringify(data), { mode: 0o600 })
-                    await fs.rename(tempFile, target)
+                    await fs.writeFile(target, JSON.stringify(data), { mode: 0o600, atomic: true })
                 }
             } catch (error) {
                 throw ToolkitError.chain(error, `Failed to save "${target}"`, {

packages/core/src/test/shared/fs/fs.test.ts

@@ -9,12 +9,12 @@ import * as path from 'path'
 import * as utils from 'util'
 import { existsSync, mkdirSync, promises as nodefs, readFileSync, rmSync } from 'fs'
 import { FakeExtensionContext } from '../../fakeExtensionContext'
-import fs from '../../../shared/fs/fs'
+import fs, { FileSystem } from '../../../shared/fs/fs'
 import * as os from 'os'
 import { isMinVscode, isWin } from '../../../shared/vscode/env'
 import Sinon from 'sinon'
 import * as extensionUtilities from '../../../shared/extensionUtilities'
-import { PermissionsError, formatError, isFileNotFoundError } from '../../../shared/errors'
+import { PermissionsError, formatError, isFileNotFoundError, scrubNames } from '../../../shared/errors'
 import { EnvironmentVariables } from '../../../shared/environmentVariables'
 import * as testutil from '../../testUtil'
 import globals from '../../../shared/extensionGlobals'
@@ -67,10 +67,14 @@ describe('FileSystem', function () {
     })
 
     describe('writeFile()', function () {
-        it('writes a file', async function () {
-            const filePath = createTestPath('myFileName')
-            await fs.writeFile(filePath, 'MyContent')
-            assert.strictEqual(readFileSync(filePath, 'utf-8'), 'MyContent')
+        const opts: { atomic: boolean }[] = [{ atomic: false }, { atomic: true }]
+
+        opts.forEach((opt) => {
+            it(`writes a file (atomic: ${opt.atomic})`, async function () {
+                const filePath = createTestPath('myFileName')
+                await fs.writeFile(filePath, 'MyContent', opt)
+                assert.strictEqual(readFileSync(filePath, 'utf-8'), 'MyContent')
+            })
         })
 
         it('writes a file with encoded text', async function () {
@@ -340,6 +344,7 @@ describe('FileSystem', function () {
 
             assert.strictEqual(await fs.readFileAsString(newPath), 'hello world')
             assert(!existsSync(oldPath))
+            assert.deepStrictEqual(testutil.getMetrics('ide_fileSystem').length, 0)
         })
 
         it('renames a folder', async () => {
@@ -363,6 +368,43 @@ describe('FileSystem', function () {
             assert.strictEqual(await fs.readFileAsString(newPath), 'hello world')
             assert(!existsSync(oldPath))
         })
+
+        it('throws if source does not exist', async () => {
+            const clock = testutil.installFakeClock()
+            try {
+                const oldPath = createTestPath('oldFile.txt')
+                const newPath = createTestPath('newFile.txt')
+
+                const result = fs.rename(oldPath, newPath)
+                await clock.tickAsync(FileSystem.renameTimeoutOpts.timeout)
+                await assert.rejects(result)
+
+                testutil.assertTelemetry('ide_fileSystem', {
+                    action: 'rename',
+                    result: 'Failed',
+                    reason: 'SourceNotExists',
+                    reasonDesc: `After ${FileSystem.renameTimeoutOpts.timeout}ms the source path did not exist: ${scrubNames(oldPath)}`,
+                })
+            } finally {
+                clock.uninstall()
+            }
+        })
+
+        it('source file does not exist at first, but eventually appears', async () => {
+            const oldPath = createTestPath('oldFile.txt')
+            const newPath = createTestPath('newFile.txt')
+
+            const result = fs.rename(oldPath, newPath)
+            // this file is created after the first "exists" check fails, the following check should pass
+            void testutil.toFile('hello world', oldPath)
+            await result
+
+            testutil.assertTelemetry('ide_fileSystem', {
+                action: 'rename',
+                result: 'Succeeded',
+                reason: 'RenameRaceCondition',
+            })
+        })
     })
 
     describe('getUserHomeDir()', function () {

packages/core/src/test/shared/vscode/runCommand.test.ts

@@ -110,13 +110,10 @@ describe('runCommand', function () {
 
             const pat = (() => {
                 switch (os.platform()) {
-                    case 'linux':
-                        // vscode error not raised on linux? 💩
-                        return /EISDIR: illegal operation on a directory/
                     case 'win32':
                         return /EPERM: operation not permitted/
                     default:
-                        return /EEXIST: file already exists/
+                        return /EISDIR: illegal operation on a directory/
                 }
             })()
             await runAndWaitForMessage(pat, async () => {