From fd14fd5a31610c73bbeb2e6e2cd789b81a0bfa38 Mon Sep 17 00:00:00 2001 From: Josh GM Walker <56300765+Josh-Walker-GM@users.noreply.github.com> Date: Sat, 1 Jul 2023 22:40:03 +0100 Subject: [PATCH] fix(cli): Prevent multiple update available messages (#8809) **Problem** @Tobbe highlighted a case where the update available message would trigger more than once and would result in output like so: ![Screenshot from 2023-07-01 14-34-45](https://github.com/redwoodjs/redwood/assets/56300765/7f7f3bb9-e3fd-4ac5-a6e3-9060c4f08cd6) This was happening because some commands were spawning child commands which would show the message too. Adding a lock to make all processes aware an update message is pending fixes this. **How to reproduce** 1. Delete `./redwood/updateCheck/data.json` to ensure an update check will be triggered. 2. Run some simple command like `yarn rw info` to trigger an update check. 3. Wait a few seconds to ensure the background update check has completed. 4. Run a command which spawns child commands like `yarn rw build web` which will spawn a prerender command. 5. Observe the duplicate messages. **Changes** 1. A lock is used to make any spawned process aware that an existing process is already going to show the update message. This approach means it'll always be the top process that outputs the message and not any of the child processes. 6. Adds a check to the `isLockSet` which ensure stale locks are ignored. We only allow locks to be valid for 1 hour (arbitrary decision by me here). This covers the case where due to some error the lock file persists longer than it should. Tests have been updated accordingly. **Notes** I didn't intend to bloat this PR with the new stale check. If needed I'll pull it out this PR and make a new one - I'd rather just have it here. --- .../cli/src/lib/__tests__/locking.test.js | 23 +++++++++++ .../cli/src/lib/__tests__/updateCheck.test.js | 40 +++++++++++++------ packages/cli/src/lib/locking.js | 21 ++++++++-- packages/cli/src/lib/updateCheck.js | 29 +++++++++++--- 4 files changed, 93 insertions(+), 20 deletions(-) diff --git a/packages/cli/src/lib/__tests__/locking.test.js b/packages/cli/src/lib/__tests__/locking.test.js index e2fa6a698bd2..d73d2ca303c6 100644 --- a/packages/cli/src/lib/__tests__/locking.test.js +++ b/packages/cli/src/lib/__tests__/locking.test.js @@ -21,6 +21,11 @@ import { setLock, unsetLock, isLockSet, clearLocks } from '../locking' beforeEach(() => { // Start with no files fs.__setMockFiles({}) + fs.statSync = jest.fn(() => { + return { + birthtimeMs: Date.now(), + } + }) }) it('Set a lock', () => { @@ -67,6 +72,24 @@ it('Detect if lock is set when it is already unset', () => { expect(isSet).toBe(false) }) +it('Detects a stale lock', () => { + // Fake that the lock is older than 1 hour + fs.statSync.mockImplementation(() => { + return { + birthtimeMs: Date.now() - 3600001, + } + }) + const spy = jest.spyOn(fs, 'rmSync') + + setLock('TEST') + + const isSet = isLockSet('TEST') + expect(isSet).toBe(false) + expect(fs.rmSync).toHaveBeenCalled() + + spy.mockRestore() +}) + it('Clear a list of locks', () => { setLock('TEST-1') setLock('TEST-2') diff --git a/packages/cli/src/lib/__tests__/updateCheck.test.js b/packages/cli/src/lib/__tests__/updateCheck.test.js index 63774c13f8f6..c97742f1735f 100644 --- a/packages/cli/src/lib/__tests__/updateCheck.test.js +++ b/packages/cli/src/lib/__tests__/updateCheck.test.js @@ -38,6 +38,16 @@ describe('Update is not available (1.0.0 -> 1.0.0)', () => { versionUpdates: ['latest'], }, }) + // Prevent the appearance of stale locks + fs.statSync = jest.fn(() => { + return { + birthtimeMs: Date.now(), + } + }) + + // Prevent console output during tests + console.log = jest.fn() + console.time = jest.fn() }) afterAll(() => { @@ -96,10 +106,8 @@ describe('Update is not available (1.0.0 -> 1.0.0)', () => { }) it('Respects the lock', async () => { - setLock(updateCheck.LOCK_IDENTIFIER) - await expect(updateCheck.check()).rejects.toThrow( - `Lock "${updateCheck.LOCK_IDENTIFIER}" is already set` - ) + setLock(updateCheck.CHECK_LOCK_IDENTIFIER) + expect(updateCheck.shouldCheck()).toBe(false) }) }) @@ -113,6 +121,12 @@ describe('Update is available (1.0.0 -> 2.0.0)', () => { versionUpdates: ['latest'], }, }) + // Prevent the appearance of stale locks + fs.statSync = jest.fn(() => { + return { + birthtimeMs: Date.now(), + } + }) }) afterAll(() => { @@ -171,10 +185,8 @@ describe('Update is available (1.0.0 -> 2.0.0)', () => { }) it('Respects the lock', async () => { - setLock(updateCheck.LOCK_IDENTIFIER) - await expect(updateCheck.check()).rejects.toThrow( - `Lock "${updateCheck.LOCK_IDENTIFIER}" is already set` - ) + setLock(updateCheck.CHECK_LOCK_IDENTIFIER) + expect(updateCheck.shouldCheck()).toBe(false) }) }) @@ -188,6 +200,12 @@ describe('Update is available with rc tag (1.0.0-rc.1 -> 1.0.1-rc.58)', () => { versionUpdates: ['latest', 'rc'], }, }) + // Prevent the appearance of stale locks + fs.statSync = jest.fn(() => { + return { + birthtimeMs: Date.now(), + } + }) }) afterAll(() => { @@ -246,9 +264,7 @@ describe('Update is available with rc tag (1.0.0-rc.1 -> 1.0.1-rc.58)', () => { }) it('Respects the lock', async () => { - setLock(updateCheck.LOCK_IDENTIFIER) - await expect(updateCheck.check()).rejects.toThrow( - `Lock "${updateCheck.LOCK_IDENTIFIER}" is already set` - ) + setLock(updateCheck.CHECK_LOCK_IDENTIFIER) + expect(updateCheck.shouldCheck()).toBe(false) }) }) diff --git a/packages/cli/src/lib/locking.js b/packages/cli/src/lib/locking.js index 04083b19088a..bbafb6f0eb4e 100644 --- a/packages/cli/src/lib/locking.js +++ b/packages/cli/src/lib/locking.js @@ -53,9 +53,24 @@ export function unsetLock(identifier) { * @returns {boolean} `true` if the lock is set, otherwise `false` */ export function isLockSet(identifier) { - return fs.existsSync( - path.join(getPaths().generated.base, 'locks', identifier) - ) + const lockfilePath = path.join(getPaths().generated.base, 'locks', identifier) + + // Check if the lock file exists + const exists = fs.existsSync(lockfilePath) + if (!exists) { + return false + } + + // Ensure this lock isn't stale due to some error + // Locks are only valid for 1 hour + const createdAt = fs.statSync(lockfilePath).birthtimeMs + if (Date.now() - createdAt > 3600000) { + unsetLock(identifier) + return false + } + + // If the lock file exists and isn't stale, the lock is set + return true } /** diff --git a/packages/cli/src/lib/updateCheck.js b/packages/cli/src/lib/updateCheck.js index 30bad0775ef6..24fd70feca9c 100644 --- a/packages/cli/src/lib/updateCheck.js +++ b/packages/cli/src/lib/updateCheck.js @@ -9,7 +9,7 @@ import semver from 'semver' import { getConfig } from '@redwoodjs/project-config' import { spawnBackgroundProcess } from './background' -import { setLock, unsetLock } from './locking' +import { isLockSet, setLock, unsetLock } from './locking' import { getPaths } from './index' @@ -40,7 +40,12 @@ export const DEFAULT_DATETIME_MS = 946684800000 /** * @const {string} The identifier used for the lock within the check function */ -export const LOCK_IDENTIFIER = 'UPDATE_CHECK' +export const CHECK_LOCK_IDENTIFIER = 'UPDATE_CHECK' + +/** + * @const {string} The identifier used for the lock when showing an update message + */ +export const SHOW_LOCK_IDENTIFIER = 'UPDATE_CHECK_SHOW' /** * @const {string[]} The name of commands which should NOT execute the update checker @@ -68,7 +73,6 @@ function getPersistenceDirectory() { export async function check() { try { console.time('Update Check') - setLock(LOCK_IDENTIFIER) // Read package.json and extract the @redwood/core version const packageJson = JSON.parse( @@ -107,7 +111,7 @@ export async function check() { checkedAt: new Date().getTime(), }) } finally { - unsetLock(LOCK_IDENTIFIER) + unsetLock(CHECK_LOCK_IDENTIFIER) console.timeEnd('Update Check') } } @@ -125,6 +129,12 @@ export function isEnabled() { * @see {@link CHECK_PERIOD} for the time between notifications */ export function shouldCheck() { + // We don't want to check if a different process is already checking + if (isLockSet(CHECK_LOCK_IDENTIFIER)) { + return false + } + + // Check if we haven't checked recently const data = readUpdateDataFile() return data.checkedAt < new Date().getTime() - CHECK_PERIOD } @@ -135,6 +145,12 @@ export function shouldCheck() { * @see {@link SHOW_PERIOD} for the time between notifications */ export function shouldShow() { + // We don't want to show if a different process is already about to + if (isLockSet(SHOW_LOCK_IDENTIFIER)) { + return false + } + + // Check there is a new version and we haven't shown the user recently const data = readUpdateDataFile() let newerVersion = false data.remoteVersions.forEach((version) => { @@ -198,7 +214,7 @@ function getUpdateMessage() { export function readUpdateDataFile() { try { if (!fs.existsSync(getPersistenceDirectory())) { - fs.mkdirSync(getPersistenceDirectory()) + fs.mkdirSync(getPersistenceDirectory(), { recursive: true }) } const persistedData = JSON.parse( fs.readFileSync(path.join(getPersistenceDirectory(), 'data.json')) @@ -269,12 +285,15 @@ export function updateCheckMiddleware(argv) { } if (shouldShow()) { + setLock(SHOW_LOCK_IDENTIFIER) process.on('exit', () => { showUpdateMessage() + unsetLock(SHOW_LOCK_IDENTIFIER) }) } if (shouldCheck()) { + setLock(CHECK_LOCK_IDENTIFIER) spawnBackgroundProcess('updateCheck', 'yarn', [ 'node', path.join(__dirname, 'updateCheckExecute.js'),