diff --git a/CHANGELOG.md b/CHANGELOG.md index 0c6bef1..2202276 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -98,6 +98,26 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 shown only when the program could not run to the end, such as a refused login, and a `.topazini` file is no longer read. +### Fixed + +- **Starting GemDB while something else is starting it no longer reports a failure.** Pressing + Start, running a notebook cell or opening the GemDB Shell while another window or terminal was + bringing the database up could end in "Start session listener failed (exit code 1)", although the + database and its session listener were both running. GemDB now checks for and starts the session + listener under the same lock as the database, so one start waits for the other, and a listener + started by an older GemDB in another editor counts as started. +- **GemDB waits for a database that is still starting before logging in to it.** After a crash + the database takes a while to recover before it accepts logins, and GemDB treated it as running + as soon as it appeared, so the first notebook cell, the GemDB Shell or a `gemdb` command could + fail to log in. GemDB and the `gemdb` command now wait for the database to finish starting, for up + to a minute, and then name the database's log if it has not. +- **The GemDB Shell checks the database before starting it, as the window does.** Opening the + Shell with the database stopped started it without the checks the window makes first, so a + database the installed engine cannot read started and then refused every login, and one on a + network drive or a disk without room for it failed with the engine's own error. The Shell now + refuses with the same explanation the window gives, and applies the space limits a database + from an earlier GemDB is missing. + ## [1.6.0] - 2026-10-07 The engine is unchanged at GemStone 4.0.0.a4, but start with a fresh database: delete diff --git a/CLAUDE.md b/CLAUDE.md index cbdf434..229e773 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -55,6 +55,16 @@ in progress and gets its result, and only the first caller reports telemetry — except after a Stop: a caller other than auto-start arriving once a Stop began during that bring-up waits for the Stop and starts again. +Below it, the processes themselves start only through `ensureProcesses` in +`processes.ts`, which checks and starts under the stone lock (NetLDI cannot be +started any other way; `ensureListener` is the listener-only door a declined +force-stop uses), and "ready" means gslist status `OK`, not "listed": a +stone at `Startup` is listed and refuses logins, so wait on it, never start it. +`stoneState` reads the rest, case-insensitively since the engine prints mixed +case: `Shutdown` fails at once, and any other listed status (`exe deleted`, +`frozen`, ...) goes on to the login as it always did. The wrapper in `cli.ts` +makes the same calls in shell; change both together. + ## CI `.github/workflows/ci.yml`, two jobs split on what they need. `checks` runs @@ -240,8 +250,9 @@ something GemDB could do on a user's behalf. The guard reads the repository's version with `copydbf -i` and refuses, naming both versions and the directory to delete. Checked in two places, and both are needed: `prepareFiles`, which is the -first-install path, and `startProcesses` before the stone starts, because an -extension update reaches that line without preparing anything — engine +first-install path, and `assertSafeToStart` before the stone starts (the +`beforeStoneStart` that `ensureProcesses` runs inside the stone lock), because +an extension update reaches that line without preparing anything — engine downloaded, database present, Grail staged, so `isInstalled()` is true. **Below its free-space threshold the stone stops collecting garbage.** GemDB diff --git a/docs/repository-space.md b/docs/repository-space.md index 7baabfd..8252cff 100644 --- a/docs/repository-space.md +++ b/docs/repository-space.md @@ -51,7 +51,7 @@ DBF_PRE_GROW = TRUE; numbers and a way out rather than the stone's log line: `assertRoomForSetup` before setup downloads anything (the cap plus the engine), and `assertRoomForExtent` before every start (what the extent still needs), and - `startStone` explains a startup that failed with "No space left on device" + `runStartstone` explains a startup that failed with "No space left on device" anyway. With the extent pregrown, `SystemRepository freeSpace` alone is the room left, for every tool that reads it. - **The test suite reserves 1 GB, not 10.** Each integration file makes a diff --git a/src/__integration__/breakpoint.test.ts b/src/__integration__/breakpoint.test.ts index 1ff767e..90c038c 100644 --- a/src/__integration__/breakpoint.test.ts +++ b/src/__integration__/breakpoint.test.ts @@ -25,7 +25,7 @@ import { setVariableQuery, unquote, } from '../pauseVariables'; -import { isRunning, startNetldi, startStone, stopNetldi, stopStone } from '../processes'; +import { ensureProcesses, isRunning, stopNetldi, stopStone } from '../processes'; import { fileOwner } from '../fileOwner'; import { runPython, runPythonFile } from '../pythonQueries'; import { @@ -94,8 +94,7 @@ beforeAll(async () => { if (!fixture) return; createDatabaseWithPython(fixture); stageGrail(ext); - await startStone(); - await startNetldi(); + await ensureProcesses(); }); afterEach(() => setHaltHandler(undefined)); diff --git a/src/__integration__/cli.test.ts b/src/__integration__/cli.test.ts index 06c247b..f0ea627 100644 --- a/src/__integration__/cli.test.ts +++ b/src/__integration__/cli.test.ts @@ -5,8 +5,14 @@ import * as path from 'path'; import { afterAll, beforeAll, describe, expect, it } from 'vitest'; import { cliPath } from '../cli'; import { bundledGrailStamp, stageGrail } from '../grail'; -import { isRunning, startStone, stopStone } from '../processes'; -import { createDatabaseWithPython, Fixture, haveTestExtent, makeFixture } from './fixture'; +import { isRunning, stopStone } from '../processes'; +import { + createDatabaseWithPython, + Fixture, + haveTestExtent, + makeFixture, + startStoneAlone, +} from './fixture'; /** * The `gemdb` shell command, run the way a user runs it: bash, a file @@ -69,7 +75,7 @@ beforeAll(async () => { createDatabaseWithPython(fixture); // Python already filed in — see testExtentPath stageGrail(ext); // stages Grail and generates the CLI - await startStone(); + await startStoneAlone(); fs.writeFileSync(path.join(workDir, 'hello.py'), 'print("hello from", 6 * 7)\n'); fs.writeFileSync(path.join(workDir, 'both.py'), 'print("partial")\n1 / 0\n'); diff --git a/src/__integration__/database.test.ts b/src/__integration__/database.test.ts index f2bd905..dcd8494 100644 --- a/src/__integration__/database.test.ts +++ b/src/__integration__/database.test.ts @@ -5,19 +5,18 @@ import { createDatabase } from '../database'; import { isSharedMemoryConfigured } from '../osConfig'; import { databaseExists, databaseStatPath, extentPath } from '../paths'; import { + ensureProcesses, findNetldi, findStone, isListening, isRunning, listProcesses, - startNetldi, - startStone, stopNetldi, stopStone, } from '../processes'; import { execute, isConnected, logout } from '../session'; import { ensureStatmonitor, recordedFiles } from '../statmonitor'; -import { Fixture, TEST_CAP_MB, limitTestDatabase, makeFixture } from './fixture'; +import { Fixture, TEST_CAP_MB, limitTestDatabase, makeFixture, startStoneAlone } from './fixture'; /** * The parts of GemDB that are only interesting against a real database. @@ -81,8 +80,7 @@ describe.skipIf(!makeFixtureIsPossible())('a real database', () => { it('starts, and reports itself through gslist', async () => { // As startProcesses does before every start. ensureStatmonitor(); - await startStone(); - await startNetldi(); + await ensureProcesses(); ensureDatabaseAccount(); const processes = listProcesses(); @@ -163,7 +161,7 @@ describe.skipIf(!makeFixtureIsPossible())('a real database', () => { it('stops cleanly once nothing is logged in', async () => { logout(); - await startStone(); + await startStoneAlone(); expect(isRunning()).toBe(true); await stopStone(false); diff --git a/src/__integration__/debugConsole.test.ts b/src/__integration__/debugConsole.test.ts index d859909..1694cef 100644 --- a/src/__integration__/debugConsole.test.ts +++ b/src/__integration__/debugConsole.test.ts @@ -22,7 +22,7 @@ import { parsePausedStack, pausedStackQuery, } from '../pauseVariables'; -import { isRunning, startNetldi, startStone, stopNetldi, stopStone } from '../processes'; +import { ensureProcesses, isRunning, stopNetldi, stopStone } from '../processes'; import { PyResult, runPython, runPythonFile } from '../pythonQueries'; import { SessionOwner, @@ -92,8 +92,7 @@ beforeAll(async () => { fs.writeFileSync(path.join(fixture.root, 'dcmod.py'), DCMOD); createDatabaseWithPython(fixture); stageGrail(ext); - await startStone(); - await startNetldi(); + await ensureProcesses(); }); afterAll(async () => { diff --git a/src/__integration__/fixture.ts b/src/__integration__/fixture.ts index 33c09d1..3b4afc8 100644 --- a/src/__integration__/fixture.ts +++ b/src/__integration__/fixture.ts @@ -5,6 +5,7 @@ import { __setSetting } from '../__mocks__/vscode'; import { STONE_NAME, databasePasswordPath } from '../config'; import { createDatabase } from '../database'; import { databaseConfPath, ensureRootPath, expectedEnginePath, extentPath } from '../paths'; +import { ensureProcesses, stopNetldi } from '../processes'; /** * A database of GemDB's own making, in a directory of its own, on the real @@ -149,3 +150,14 @@ export function createDatabaseWithPython(fixture: Fixture): void { fs.copyFileSync(testExtentPasswordPath(), databasePasswordPath()); fs.chmodSync(databasePasswordPath(), 0o600); } + +/** + * Bring the stone up without leaving a session listener this call started, + * for tests of what needs no listener (linked sessions) or of starting one. + * Through `ensureProcesses`, the one way GemDB starts processes, rather than a + * stone-only start of the tests' own. + */ +export async function startStoneAlone(): Promise { + const { startedNetldi } = await ensureProcesses(); + if (startedNetldi) await stopNetldi(); +} diff --git a/src/__integration__/fixtures/processContender.ts b/src/__integration__/fixtures/processContender.ts new file mode 100644 index 0000000..95c3772 --- /dev/null +++ b/src/__integration__/fixtures/processContender.ts @@ -0,0 +1,87 @@ +import * as fs from 'fs'; +import * as os from 'os'; +import * as path from 'path'; +import { spawn } from 'child_process'; +import { NETLDI_NAME } from '../../config'; +import { databaseLogPath } from '../../paths'; +import { engineEnvironment, ensureProcesses } from '../../processes'; + +/** + * One process starting the database, run as a process of its own. + * + * processes.test.ts bundles this with the same `vscode` alias the shell bundle + * uses and starts two at once, because the race it covers is between + * processes: two windows, or a window and a GemDB Shell, that both find the + * database down. The root path arrives as GEMDB_ROOT_PATH, as it does for the + * real wrapper. + * + * argv: [rival log] + * + * `ensure` is what every start does today. `raw-netldi` is what GemDB 1.6.0 + * did: `startnetldi` with no lock and no look first (#89). + * + * It says it is ready, waits for the go file so both start at the same + * moment, then appends one line saying what happened to the report. + * + * Released together, the raw `startnetldi` finishes before the other process + * has taken the lock and looked, so that one finds the listener up and the + * two never collide. Given a rival's log, the raw one waits after the go file + * until the rival logs its own `startnetldi`, so both commands run at once. + */ +const [mode, readyFile, goFile, reportFile, rivalLog] = process.argv.slice(2); +const me = process.pid; + +const sleep = (ms: number): Promise => new Promise((resolve) => setTimeout(resolve, ms)); +const report = (line: string): void => fs.appendFileSync(reportFile, `${line}\n`); + +/** `startnetldi` exactly as 1.6.0 ran it; resolves with its exit code and output. */ +function rawStartNetldi(): Promise<{ code: number | null; output: string }> { + const env = engineEnvironment(); + return new Promise((resolve, reject) => { + const child = spawn( + path.join(env.GEMSTONE, 'bin', 'startnetldi'), + [ + '-a', + os.userInfo().username, + '-g', + '-l', + path.join(databaseLogPath(), `${NETLDI_NAME}.log`), + NETLDI_NAME, + ], + { env: { ...process.env, ...env } }, + ); + let output = ''; + child.stdout.on('data', (data: Buffer) => (output += data.toString())); + child.stderr.on('data', (data: Buffer) => (output += data.toString())); + child.on('close', (code) => resolve({ code, output })); + child.on('error', reject); + }); +} + +/** Wait until the rival logs that it is running `startnetldi`, or give up after a while. */ +async function rivalStartsNetldi(log: string): Promise { + const deadline = Date.now() + 20_000; + while (Date.now() < deadline) { + if (fs.existsSync(log) && fs.readFileSync(log, 'utf8').includes('$ startnetldi')) return; + await sleep(2); + } +} + +async function main(): Promise { + fs.appendFileSync(readyFile, `${me}\n`); + while (!fs.existsSync(goFile)) await sleep(2); + if (rivalLog) await rivalStartsNetldi(rivalLog); + + if (mode === 'ensure') { + const started = await ensureProcesses(); + report(JSON.stringify({ mode, pid: me, ...started })); + } else { + const { code, output } = await rawStartNetldi(); + report(JSON.stringify({ mode, pid: me, code, output: output.trim() })); + } +} + +main().catch((e: unknown) => { + report(JSON.stringify({ mode, pid: me, error: String(e) })); + process.exitCode = 1; +}); diff --git a/src/__integration__/grail.test.ts b/src/__integration__/grail.test.ts index 5e37231..b96a173 100644 --- a/src/__integration__/grail.test.ts +++ b/src/__integration__/grail.test.ts @@ -5,7 +5,7 @@ import { createDatabase } from '../database'; import { bundledGrailStamp, installGrail, recordGrailInstalled, stageGrail } from '../grail'; import { isSharedMemoryConfigured } from '../osConfig'; import { grailInstalled, grailStagedOnDisk } from '../paths'; -import { isRunning, startNetldi, startStone, stopNetldi, stopStone } from '../processes'; +import { ensureProcesses, isRunning, stopNetldi, stopStone } from '../processes'; import { isErrorResult, isGrailInstalled, @@ -61,8 +61,7 @@ beforeAll(async () => { createDatabase(fixture.engine); limitTestDatabase(); - await startStone(); - await startNetldi(); + await ensureProcesses(); // Grail installs into the gemdb account, as `ensureRunning` creates it. ensureDatabaseAccount(); }); diff --git a/src/__integration__/mcp.test.ts b/src/__integration__/mcp.test.ts index dbc0045..36c6c10 100644 --- a/src/__integration__/mcp.test.ts +++ b/src/__integration__/mcp.test.ts @@ -17,7 +17,7 @@ import { stopMcpServer, } from '../mcp'; import { mcpInstalled, mcpRouterStatePath, mcpStagedOnDisk } from '../paths'; -import { isRunning, startNetldi, startStone, stopNetldi, stopStone } from '../processes'; +import { ensureProcesses, isRunning, stopNetldi, stopStone } from '../processes'; import { GciSession, execute, logoutAll } from '../session'; import { createDatabaseWithPython, Fixture, haveTestExtent, makeFixture } from './fixture'; @@ -73,8 +73,7 @@ beforeAll(async () => { // Grail's files on disk, because the router's worker gems inherit the // NetLDI's environment and resolve Python modules through GRAIL_DIR. stageGrail(ext); - await startStone(); - await startNetldi(); + await ensureProcesses(); }); afterAll(async () => { diff --git a/src/__integration__/processes.test.ts b/src/__integration__/processes.test.ts new file mode 100644 index 0000000..4ec6d4a --- /dev/null +++ b/src/__integration__/processes.test.ts @@ -0,0 +1,203 @@ +import { afterAll, beforeAll, describe, expect, it } from 'vitest'; +import * as esbuild from 'esbuild'; +import * as fs from 'fs'; +import * as os from 'os'; +import * as path from 'path'; +import { execFile, execFileSync } from 'child_process'; +import { NETLDI_NAME } from '../config'; +import { createDatabase } from '../database'; +import { isSharedMemoryConfigured } from '../osConfig'; +import { isListening, isRunning, listProcesses, stopNetldi, stopStone } from '../processes'; +import { Fixture, limitTestDatabase, makeFixture, startStoneAlone } from './fixture'; + +/** + * Two processes starting one database at the same moment. + * + * Two windows opened together, or a window and a GemDB Shell, both find the + * database down and both start it. Checked and started outside a lock, both + * ran `startnetldi`, and the loser reported a failure over a database that was + * up (#89). The lock that closes that race keeps separate processes apart, so + * an in-process test cannot exercise it: these bundle processContender.ts the + * way lock.test.ts bundles its contender, and race real node processes against + * a real engine. + * + * No Python is needed, so the database is the engine's own extent and the + * file skips on a missing engine alone. + */ + +interface Report { + mode: 'ensure' | 'raw-netldi'; + pid: number; + startedStone?: boolean; + startedNetldi?: boolean; + code?: number | null; + output?: string; + error?: string; +} + +let fixture: Fixture | undefined; +let bundleDir: string | undefined; +let bundle = ''; + +beforeAll(async () => { + fixture = makeFixture(); + if (!fixture) return; + if (!(await isSharedMemoryConfigured())) { + throw new Error( + 'Shared memory is below what the engine needs. Run "GemDB: Configure Shared Memory" ' + + 'in the editor, or resources/setSharedMemoryDarwin.sh, before running these tests.', + ); + } + createDatabase(fixture.engine); + limitTestDatabase(); + + bundleDir = fs.mkdtempSync(path.join(os.tmpdir(), 'gemdb-contender-')); + bundle = path.join(bundleDir, 'processContender.cjs'); + await esbuild.build({ + entryPoints: [path.join(__dirname, 'fixtures', 'processContender.ts')], + bundle: true, + platform: 'node', + format: 'cjs', + outfile: bundle, + logLevel: 'silent', + alias: { vscode: path.join(__dirname, '..', 'cliVscode.ts') }, + }); +}); + +afterAll(async () => { + if (bundleDir) fs.rmSync(bundleDir, { recursive: true, force: true }); + if (!fixture) return; + try { + if (isListening()) await stopNetldi(); + if (isRunning()) await stopStone(true); + } finally { + fixture.remove(); + } +}); + +/** See database.test.ts — skipIf is evaluated during collection. */ +function canMakeFixture(): boolean { + const probe = makeFixture(); + if (!probe) return false; + probe.remove(); + return true; +} + +const sleep = (ms: number): Promise => new Promise((resolve) => setTimeout(resolve, ms)); + +/** + * Start one contender per mode, release them together, and return what each + * reported. A contender's log goes to a file beside the report, and a + * contender that exits non-zero rejects with that log, which is the only + * account of what it did. + */ +async function race( + modes: Report['mode'][], + opts: { rawWaitsForRival?: boolean } = {}, +): Promise { + const root = fixture!.root; + const dir = fs.mkdtempSync(path.join(root, 'race-')); + const ready = path.join(dir, 'ready'); + const go = path.join(dir, 'go'); + const reportFile = path.join(dir, 'report'); + fs.writeFileSync(ready, ''); + const logFile = (i: number): string => path.join(dir, `contender-${i}.log`); + const rivalLog = logFile(modes.indexOf('ensure')); + const exits = modes.map( + (mode, i) => + new Promise((resolve, reject) => { + const log = logFile(i); + const waitFor = mode === 'raw-netldi' && opts.rawWaitsForRival ? [rivalLog] : []; + const child = execFile( + process.execPath, + [bundle, mode, ready, go, reportFile, ...waitFor], + { env: { ...process.env, GEMDB_ROOT_PATH: root, GEMDB_SHELL_LOG: log } }, + (error, _stdout, stderr) => { + if (!error) return resolve(); + const logged = fs.existsSync(log) ? fs.readFileSync(log, 'utf8') : ''; + reject(new Error(`${mode} contender failed: ${stderr || String(error)}\n${logged}`)); + }, + ); + child.on('error', reject); + }), + ); + + // Release only once both are parked at the starting line, or the first + // would be done before the second had started. + const deadline = Date.now() + 20_000; + while (fs.readFileSync(ready, 'utf8').split('\n').filter(Boolean).length < modes.length) { + if (Date.now() > deadline) throw new Error('contenders never got ready'); + await sleep(10); + } + fs.writeFileSync(go, ''); + await Promise.all(exits); + + return fs + .readFileSync(reportFile, 'utf8') + .split('\n') + .filter(Boolean) + .map((line) => JSON.parse(line) as Report); +} + +/** + * How many `netldid` processes are serving this fixture's listener. gslist + * cannot answer that: it keys rows by name and shows one row for two + * listeners, and two `startnetldi` run at once can both exit 0 and leave two. + * The fixture's root path is in each one's `-l` log argument, which keeps a + * developer's own `gemdbldi` out of the count. + */ +function netldidProcesses(): number { + const escape = (text: string): string => text.replace(/[.*+?^${}()|[\]\\]/g, '\\$&'); + const pattern = `netldid ${escape(NETLDI_NAME)} .*${escape(fixture!.root)}/`; + try { + return execFileSync('pgrep', ['-f', pattern], { encoding: 'utf8' }).split('\n').filter(Boolean) + .length; + } catch { + return 0; // pgrep exits 1 when nothing matches + } +} + +/** What `gslist` lists, reduced to what the end state is judged on. */ +function listed(): { type: string; status: string }[] { + return listProcesses().map((p) => ({ type: p.type, status: p.status })); +} + +describe.skipIf(!canMakeFixture())('starting the database from two processes at once', () => { + it('starts one stone and one session listener, and neither process fails', async () => { + const reports = await race(['ensure', 'ensure']); + + expect(reports.filter((r) => r.error)).toEqual([]); + expect(reports).toHaveLength(2); + expect(reports.filter((r) => r.startedStone)).toHaveLength(1); + expect(reports.filter((r) => r.startedNetldi)).toHaveLength(1); + expect(netldidProcesses()).toBe(1); + expect(listed()).toEqual( + expect.arrayContaining([ + { type: 'stone', status: 'OK' }, + { type: 'netldi', status: 'OK' }, + ]), + ); + expect(listed()).toHaveLength(2); + }); + + it('does not fail when a release that takes no lock starts the session listener alongside', async () => { + if (isListening()) await stopNetldi(); + await startStoneAlone(); + expect(isListening()).toBe(false); + + const reports = await race(['raw-netldi', 'ensure'], { rawWaitsForRival: true }); + + const ensured = reports.find((r) => r.mode === 'ensure'); + expect(ensured).toBeDefined(); + expect(ensured?.error).toBeUndefined(); + expect(ensured?.startedStone).toBe(false); + expect(reports.find((r) => r.mode === 'raw-netldi')?.error).toBeUndefined(); + expect(listed()).toEqual( + expect.arrayContaining([ + { type: 'stone', status: 'OK' }, + { type: 'netldi', status: 'OK' }, + ]), + ); + expect(listed()).toHaveLength(2); + }); +}); diff --git a/src/__integration__/redDots.test.ts b/src/__integration__/redDots.test.ts index 48c9869..63274c3 100644 --- a/src/__integration__/redDots.test.ts +++ b/src/__integration__/redDots.test.ts @@ -11,7 +11,7 @@ import { parsePausedStack, pausedStackQuery, } from '../pauseVariables'; -import { isRunning, startNetldi, startStone, stopNetldi, stopStone } from '../processes'; +import { ensureProcesses, isRunning, stopNetldi, stopStone } from '../processes'; import { runPython, runPythonFile } from '../pythonQueries'; import { DotsByFile } from '../redDots'; import { @@ -122,8 +122,7 @@ beforeAll(async () => { if (!fixture) return; createDatabaseWithPython(fixture); stageGrail(ext); - await startStone(); - await startNetldi(); + await ensureProcesses(); }); afterEach(() => { diff --git a/src/__integration__/sessions.test.ts b/src/__integration__/sessions.test.ts index 6fa675d..ef31108 100644 --- a/src/__integration__/sessions.test.ts +++ b/src/__integration__/sessions.test.ts @@ -1,7 +1,7 @@ import { afterAll, beforeAll, describe, expect, it } from 'vitest'; import { __log } from '../__mocks__/vscode'; import { stageGrail } from '../grail'; -import { isRunning, startNetldi, startStone, stopNetldi, stopStone } from '../processes'; +import { ensureProcesses, isRunning, stopNetldi, stopStone } from '../processes'; import { isErrorResult, renameOwner, runPython } from '../pythonQueries'; import { SessionOwner, cacheNameFor, execute, logoutAll, sessionRegistry } from '../session'; import { createDatabaseWithPython, Fixture, haveTestExtent, makeFixture } from './fixture'; @@ -38,8 +38,7 @@ beforeAll(async () => { if (!fixture) return; createDatabaseWithPython(fixture); stageGrail(ext); - await startStone(); - await startNetldi(); + await ensureProcesses(); }); afterAll(async () => { diff --git a/src/__integration__/space.test.ts b/src/__integration__/space.test.ts index c7f5b03..3c5032c 100644 --- a/src/__integration__/space.test.ts +++ b/src/__integration__/space.test.ts @@ -12,7 +12,7 @@ import { stopDatabaseSession, } from '../maintenance'; import { databaseLogPath, extentPath } from '../paths'; -import { isRunning, startNetldi, startStone, stopNetldi, stopStone } from '../processes'; +import { ensureProcesses, isRunning, stopNetldi, stopStone } from '../processes'; import { isErrorResult, runPython } from '../pythonQueries'; import { GciSession, @@ -69,8 +69,7 @@ beforeAll(async () => { if (!fixture) return; createDatabaseWithPython(fixture); stageGrail(ext); - await startStone(); - await startNetldi(); + await ensureProcesses(); }); afterAll(async () => { diff --git a/src/__integration__/spaceFull.test.ts b/src/__integration__/spaceFull.test.ts index ab9f2b1..5de2e5a 100644 --- a/src/__integration__/spaceFull.test.ts +++ b/src/__integration__/spaceFull.test.ts @@ -4,7 +4,7 @@ import { stageGrail } from '../grail'; import { adminAccount } from '../config'; import { collectGarbage, parseSpaceReading } from '../maintenance'; import { extentPath } from '../paths'; -import { isRunning, startNetldi, startStone, stopNetldi, stopStone } from '../processes'; +import { ensureProcesses, isRunning, stopNetldi, stopStone } from '../processes'; import { runPython } from '../pythonQueries'; import { GciSession, SessionOwner, execute, logoutAll } from '../session'; import { @@ -74,8 +74,7 @@ beforeAll(async () => { const extentMb = fs.statSync(extentPath()).size / 1048576; limitTestDatabase(Math.ceil((extentMb + 192) / 16) * 16, THRESHOLD_MB); stageGrail(ext); - await startStone(); - await startNetldi(); + await ensureProcesses(); }); afterAll(async () => { diff --git a/src/__tests__/cli.test.ts b/src/__tests__/cli.test.ts index 99e8a13..82fac9c 100644 --- a/src/__tests__/cli.test.ts +++ b/src/__tests__/cli.test.ts @@ -3,7 +3,7 @@ import * as fs from 'fs'; import * as os from 'os'; import * as path from 'path'; import { afterEach, beforeEach, describe, expect, it } from 'vitest'; -import { __setSetting } from '../__mocks__/vscode'; +import { __resetSettings, __setSetting } from '../__mocks__/vscode'; import { cliPath, ensureCliCurrent, putCliOnPath, writeCliScripts } from '../cli'; import { STONE_LOCK_NAME } from '../lock'; import { cliStampPath, expectedEnginePath } from '../paths'; @@ -35,6 +35,7 @@ function makeExtensionDir(): string { } beforeEach(() => { + __resetSettings(); root = fs.mkdtempSync(path.join(os.tmpdir(), 'gemdb-cli-')); ext = makeExtensionDir(); __setSetting('gemdb.rootPath', root); @@ -345,9 +346,10 @@ describe('putCliOnPath', () => { * `gslist` showed one row for them because it keys Stone rows by name. * * The stubs stand in for the engine binaries the wrapper calls by absolute - * path. `startstone` records that it ran and leaves a marker; `gslist` reports - * a stone only once that marker exists, so a wrapper that re-checks after - * taking the lock sees what a real one would. + * path. `startstone` records that it ran and leaves a marker holding the + * stone's status; `gslist` reports a stone, with that status, only once the + * marker exists, so a wrapper that re-checks after taking the lock sees what + * a real one would. Each `gslist` call is counted in `gslist.calls`. */ describe('starting the database', () => { function installEngineStubs(): { starts: string } { @@ -355,25 +357,63 @@ describe('starting the database', () => { fs.mkdirSync(bin, { recursive: true }); const marker = path.join(root, 'stone.up'); const starts = path.join(root, 'starts.log'); + const countdown = path.join(root, 'stone.countdown'); + const next = path.join(root, 'stone.next'); + const calls = path.join(root, 'gslist.calls'); fs.writeFileSync( path.join(bin, 'gslist'), - `#!/bin/sh\n[ -f '${marker}' ] && echo 'exists 4.0.0 me 1 1 x Stone gemdb'\nexit 0\n`, + [ + '#!/bin/sh', + `echo "$*" >> '${calls}'`, + // A stone that changes state on its own: see stoneBecomes. + `if [ -f '${countdown}' ]; then`, + ` n=$(cat '${countdown}')`, + ` if [ "$n" -le 0 ]; then`, + ` rm -f '${countdown}'`, + ` if [ -f '${next}' ]; then mv '${next}' '${marker}'; else rm -f '${marker}'; fi`, + ` else echo $((n - 1)) > '${countdown}'; fi`, + 'fi', + // The shape of a real -cvl row: status, version, owner, pid, port, date, type, name. + `[ -f '${marker}' ] && echo "$(cat '${marker}') 4.0.0.a4 me 1 1 Oct 13 15:57 Stone gemdb"`, + 'exit 0', + '', + ].join('\n'), ); fs.writeFileSync( path.join(bin, 'startstone'), - `#!/bin/sh\nsleep 0.2\necho started >> '${starts}'\ntouch '${marker}'\nexit 0\n`, + `#!/bin/sh\nsleep 0.2\necho started >> '${starts}'\necho OK > '${marker}'\nexit 0\n`, ); fs.chmodSync(path.join(bin, 'gslist'), 0o755); fs.chmodSync(path.join(bin, 'startstone'), 0o755); return { starts }; } + /** + * Leave a stone at `status` that becomes `then` (or disappears, when + * undefined) after `calls` gslist calls — the wrapper's own pace rather than + * the clock's, since how long it takes to reach its stone checks varies. + */ + function stoneBecomes(status: string, then: string | undefined, calls: number): void { + fs.writeFileSync(path.join(root, 'stone.up'), status); + if (then !== undefined) fs.writeFileSync(path.join(root, 'stone.next'), then); + fs.writeFileSync(path.join(root, 'stone.countdown'), String(calls)); + } + + function gslistCalls(): number { + const calls = path.join(root, 'gslist.calls'); + return fs.existsSync(calls) + ? fs.readFileSync(calls, 'utf8').split('\n').filter(Boolean).length + : 0; + } + /** Run the wrapper on a path that does not exist: it exits after the * stone-start block and before topaz, which is the part under test. */ - function runWrapper(): Promise { + function runWrapper(): Promise { return new Promise((resolve) => { - execFile(cliPath(), [path.join(root, 'nothing-here.py')], () => resolve()); + execFile(cliPath(), [path.join(root, 'nothing-here.py')], (_error, _stdout, stderr) => + resolve(stderr), + ); }); } @@ -413,7 +453,7 @@ describe('starting the database', () => { const lock = path.join(root, '.gemdb-stone.lock'); fs.mkdirSync(lock); // The "other process" finishes: the stone comes up while the wrapper waits. - setTimeout(() => fs.writeFileSync(path.join(root, 'stone.up'), ''), 300); + setTimeout(() => fs.writeFileSync(path.join(root, 'stone.up'), 'OK'), 300); await runWrapper(); @@ -442,7 +482,7 @@ describe('starting the database', () => { const lock = path.join(root, '.gemdb-stone.lock'); fs.writeFileSync( path.join(bin, 'startstone'), - `#!/bin/sh\necho ${process.pid} > '${lock}/pid'\ntouch '${path.join(root, 'stone.up')}'\nexit 0\n`, + `#!/bin/sh\necho ${process.pid} > '${lock}/pid'\necho OK > '${path.join(root, 'stone.up')}'\nexit 0\n`, ); await runWrapper(); @@ -500,4 +540,119 @@ describe('starting the database', () => { : 0; expect(started).toBe(1); }); + it('waits for a stone that is still starting instead of starting a second one', async () => { + // Listed at Startup with nobody holding the lock: a crash being recovered, + // or a start by a GemDB that does not wait for OK. + writeCliScripts(ext); + const { starts } = installEngineStubs(); + // Still starting for the first check, the re-check in the lock, and the + // first wait for it. + stoneBecomes('Startup', 'OK', 3); + + const stderr = await runWrapper(); + + expect(fs.existsSync(starts)).toBe(false); + expect(stderr).toContain('waiting for the database to finish starting'); + expect(stderr).toContain("can't open file"); + }); + + it('names the stone log when a stone that was starting disappears', async () => { + writeCliScripts(ext); + const { starts } = installEngineStubs(); + stoneBecomes('Startup', undefined, 3); + + const stderr = await runWrapper(); + + expect(fs.existsSync(starts)).toBe(false); + expect(stderr).toMatch(/stopped while it was starting\. See .*gemdb\.log/); + }); + + // Statuses the engine prints that are neither OK nor starting. They went on + // to the login before GemDB waited for OK, and still do: "exe deleted" is a + // stone left running when the engine tree was replaced, and it takes logins. + for (const status of ['exe deleted', 'frozen', 'full']) { + it(`goes on to the login for a stone that reads "${status}", asking once`, async () => { + writeCliScripts(ext); + const { starts } = installEngineStubs(); + fs.writeFileSync(path.join(root, 'stone.up'), status); + + const stderr = await runWrapper(); + + expect(fs.existsSync(starts)).toBe(false); + expect(gslistCalls()).toBe(1); + expect(stderr).toContain("can't open file"); + }); + } + + it('says a stone at Shutdown is shutting down, at once, rather than waiting on it', async () => { + writeCliScripts(ext); + const { starts } = installEngineStubs(); + fs.writeFileSync(path.join(root, 'stone.up'), 'Shutdown'); + + const stderr = await runWrapper(); + + expect(fs.existsSync(starts)).toBe(false); + expect(gslistCalls()).toBe(1); + expect(stderr).toContain('the database is shutting down'); + expect(stderr).not.toContain("can't open file"); + }); + + describe('for a database this machine’s administrator runs', () => { + /** The stubbed engine, configured as someone else's, with a stone named as the stubs name it. */ + function external(): void { + __setSetting('gemdb.externalDatabase.gemstone', expectedEnginePath()); + __setSetting('gemdb.externalDatabase.globalDirectory', root); + __setSetting('gemdb.externalDatabase.stone', 'gemdb'); + } + + const lock = (): string => path.join(root, STONE_LOCK_NAME); + + it('starts nothing and takes no lock when the stone is not running', async () => { + external(); + writeCliScripts(ext); + const { starts } = installEngineStubs(); + + const stderr = await runWrapper(); + + expect(fs.existsSync(starts)).toBe(false); + expect(fs.existsSync(lock())).toBe(false); + expect(stderr).toContain("It is run by this machine's administrator"); + }); + + it('waits for a stone that is still starting, and never starts one', async () => { + external(); + writeCliScripts(ext); + const { starts } = installEngineStubs(); + stoneBecomes('Startup', 'OK', 2); + + const stderr = await runWrapper(); + + expect(fs.existsSync(starts)).toBe(false); + expect(fs.existsSync(lock())).toBe(false); + expect(stderr).toContain('waiting for the database to finish starting'); + expect(stderr).toContain("can't open file"); + }); + + it('does not start a stone that disappears while starting, or point at a log of ours', async () => { + external(); + writeCliScripts(ext); + const { starts } = installEngineStubs(); + stoneBecomes('Startup', undefined, 2); + + const stderr = await runWrapper(); + + expect(fs.existsSync(starts)).toBe(false); + expect(stderr).toContain('stopped while it was starting.'); + expect(stderr).not.toContain('gemdb.log'); + }); + + it('generates no way to reach startstone at all', () => { + external(); + writeCliScripts(ext); + + const wrapper = fs.readFileSync(cliPath(), 'utf8'); + expect(wrapper).not.toContain('bin/startstone'); + expect(wrapper).not.toContain(STONE_LOCK_NAME); + }); + }); }); diff --git a/src/__tests__/databaseStarted.test.ts b/src/__tests__/databaseStarted.test.ts index 73612d8..e020d00 100644 --- a/src/__tests__/databaseStarted.test.ts +++ b/src/__tests__/databaseStarted.test.ts @@ -50,16 +50,13 @@ vi.mock('../osConfig', async (importOriginal) => { }; }); -const findStone = vi.fn(() => true); -const findNetldi = vi.fn(() => true); -const startStone = vi.fn(async () => {}); -const startNetldi = vi.fn(async () => {}); +const nothingStarted = { startedStone: false, startedNetldi: false }; +const ensureProcesses = vi.fn(async () => nothingStarted); vi.mock('../processes', () => ({ listProcesses: () => [], - findStone: () => findStone(), - findNetldi: () => findNetldi(), - startStone: () => startStone(), - startNetldi: () => startNetldi(), + findStone: () => true, + findNetldi: () => true, + ensureProcesses: () => ensureProcesses(), isListening: () => true, isRunning: () => true, stopNetldi: async () => {}, @@ -91,8 +88,7 @@ describe('databaseStarted', () => { ensureOsConfigured.mockReset().mockResolvedValue('alreadyConfigured'); isSharedMemoryConfigured.mockReset().mockResolvedValue(true); fileInGrail.mockClear(); - findStone.mockReturnValue(true); - findNetldi.mockReturnValue(true); + ensureProcesses.mockReset().mockResolvedValue(nothingStarted); const context = fakeExtensionContext(); initTelemetry(context, false); @@ -101,6 +97,9 @@ describe('databaseStarted', () => { initUnattendedSetupMarker(context.globalStorageUri.fsPath); }); + // Also a window that pressed Start while another window, or the GemDB Shell, + // was starting the database: once it has the lock it finds both up and has + // started nothing, so the start is the other process's to report. it('sends nothing on a no-op call — everything already up, nothing prompted', async () => { const ok = await ensureRunning('/ext', TRIGGER.notebook); @@ -124,12 +123,19 @@ describe('databaseStarted', () => { }); it('sends started when the stone had to be started', async () => { - findStone.mockReturnValue(false); + ensureProcesses.mockResolvedValue({ startedStone: true, startedNetldi: false }); const ok = await ensureRunning('/ext', TRIGGER.notebook); expect(ok).toBe(true); - expect(startStone).toHaveBeenCalledTimes(1); + expect(eventsNamed('databaseStarted')).toHaveLength(1); + }); + + it('sends started when only the listener had to be started', async () => { + ensureProcesses.mockResolvedValue({ startedStone: false, startedNetldi: true }); + + await ensureRunning('/ext', TRIGGER.notebook); + expect(eventsNamed('databaseStarted')).toHaveLength(1); }); @@ -198,12 +204,10 @@ describe('resumeRunning', () => { grailNeedsUpdate.mockReturnValue(false); grailInstalled.mockReturnValue(true); isInstalled.mockReturnValue(true); - findStone.mockReturnValue(true); - findNetldi.mockReturnValue(true); ensureOsConfigured.mockReset().mockResolvedValue('alreadyConfigured'); isSharedMemoryConfigured.mockReset().mockResolvedValue(true); fileInGrail.mockClear(); - startStone.mockClear(); + ensureProcesses.mockReset().mockResolvedValue(nothingStarted); initTelemetry(fakeExtensionContext(), false); }); @@ -214,7 +218,6 @@ describe('resumeRunning', () => { expect(await resumeRunning('/ext')).toBe(true); expect(fileInGrail).toHaveBeenCalledTimes(1); - expect(startStone).not.toHaveBeenCalled(); expect(eventsNamed('databaseStarted').map((e) => e.properties)).toEqual([ expect.objectContaining({ trigger: 'autoStart', diff --git a/src/__tests__/externalDatabase.test.ts b/src/__tests__/externalDatabase.test.ts index 54d6092..849795e 100644 --- a/src/__tests__/externalDatabase.test.ts +++ b/src/__tests__/externalDatabase.test.ts @@ -22,10 +22,9 @@ import { EngineProcess, ExternalDatabaseError, engineEnvironment, + ensureProcesses, findNetldi, findStone, - startNetldi, - startStone, stopNetldi, stopStone, } from '../processes'; @@ -227,8 +226,7 @@ describe('processes', () => { it('are never started or stopped by GemDB', async () => { useExternal(); - await expect(startStone()).rejects.toBeInstanceOf(ExternalDatabaseError); - await expect(startNetldi()).rejects.toBeInstanceOf(ExternalDatabaseError); + await expect(ensureProcesses()).rejects.toBeInstanceOf(ExternalDatabaseError); await expect(stopStone()).rejects.toBeInstanceOf(ExternalDatabaseError); await expect(stopNetldi()).rejects.toBeInstanceOf(ExternalDatabaseError); }); diff --git a/src/__tests__/externalLifecycle.test.ts b/src/__tests__/externalLifecycle.test.ts index 9c76dfa..e2a1c3c 100644 --- a/src/__tests__/externalLifecycle.test.ts +++ b/src/__tests__/externalLifecycle.test.ts @@ -38,19 +38,18 @@ vi.mock('../osConfig', async (importOriginal) => { const findStone = vi.fn(() => true); const findNetldi = vi.fn(() => true); -const startStone = vi.fn(async () => {}); -const startNetldi = vi.fn(async () => {}); +const ensureProcesses = vi.fn(async () => ({ startedStone: false, startedNetldi: false })); const stopStone = vi.fn(async () => {}); const stopNetldi = vi.fn(async () => {}); vi.mock('../processes', async (importOriginal) => { const actual = await importOriginal(); return { ExternalDatabaseError: actual.ExternalDatabaseError, + externalDatabaseDownError: actual.externalDatabaseDownError, listProcesses: () => [], findStone: () => findStone(), findNetldi: () => findNetldi(), - startStone: () => startStone(), - startNetldi: () => startNetldi(), + ensureProcesses: () => ensureProcesses(), isListening: () => findNetldi(), isRunning: () => findStone(), stopNetldi: () => stopNetldi(), @@ -89,8 +88,7 @@ describe('an external database', () => { __setSetting('gemdb.externalDatabase.gemstone', '/opt/gemstone/product'); for (const mock of [ ensureOsConfigured, - startStone, - startNetldi, + ensureProcesses, stopStone, stopNetldi, startMcpServer, @@ -110,16 +108,14 @@ describe('an external database', () => { it('is used as it is when running: no shared-memory check, nothing started', async () => { expect(await ensureRunning('/ext', TRIGGER.notebook)).toBe(true); expect(ensureOsConfigured).not.toHaveBeenCalled(); - expect(startStone).not.toHaveBeenCalled(); - expect(startNetldi).not.toHaveBeenCalled(); + expect(ensureProcesses).not.toHaveBeenCalled(); }); it('is reported, not started, when it is down', async () => { findStone.mockReturnValue(false); expect(await ensureRunning('/ext', TRIGGER.notebook)).toBe(false); - expect(startStone).not.toHaveBeenCalled(); - expect(startNetldi).not.toHaveBeenCalled(); + expect(ensureProcesses).not.toHaveBeenCalled(); expect(__log.join('\n')).toMatch(/administrator runs\. Ask them to start it/); }); @@ -127,7 +123,7 @@ describe('an external database', () => { findNetldi.mockReturnValue(false); expect(await ensureRunning('/ext', TRIGGER.notebook)).toBe(false); - expect(startNetldi).not.toHaveBeenCalled(); + expect(ensureProcesses).not.toHaveBeenCalled(); }); it('is never stopped', async () => { @@ -148,8 +144,7 @@ describe('an external database', () => { it('starts the router for the running database, and nothing else', async () => { expect(await resumeMcpServing('/ext')).toBe(true); expect(startMcpServer).toHaveBeenCalledOnce(); - expect(startStone).not.toHaveBeenCalled(); - expect(startNetldi).not.toHaveBeenCalled(); + expect(ensureProcesses).not.toHaveBeenCalled(); }); it('leaves a router that is already listening alone', async () => { diff --git a/src/__tests__/gslist.test.ts b/src/__tests__/gslist.test.ts index af3dbbe..2c27948 100644 --- a/src/__tests__/gslist.test.ts +++ b/src/__tests__/gslist.test.ts @@ -77,6 +77,18 @@ describe('parseGslist', () => { expect(netldi.responding).toBe(false); }); + it('reads a stone that is still starting, listed but not yet responding', () => { + // A stone is listed from the moment it exists, and sits at `Startup` while + // it recovers from a crash; a login in that time fails. + const output = 'Startup 4.0.0.a4 jfoster 79386 51475 Sep 28 19:31 Stone gemdb'; + + const [stone] = parseGslist(output); + + expect(stone.name).toBe('gemdb'); + expect(stone.status).toBe('Startup'); + expect(stone.responding).toBe(false); + }); + it('treats anything other than OK as not responding', () => { const output = 'frozen 4.0.0.Alpha jfoster 56970 65107 Sep 11 16:46 Stone gemdb'; diff --git a/src/__tests__/oneBringUp.test.ts b/src/__tests__/oneBringUp.test.ts index a8ddf55..f2a516a 100644 --- a/src/__tests__/oneBringUp.test.ts +++ b/src/__tests__/oneBringUp.test.ts @@ -52,8 +52,8 @@ vi.mock('../osConfig', async (importOriginal) => { const findStone = vi.fn(() => true); const findNetldi = vi.fn(() => true); +// The stone start inside `ensureProcesses`, which starts only what is down. const startStone = vi.fn(async () => {}); -const startNetldi = vi.fn(async () => {}); const stopStone = vi.fn(async (_force: boolean) => { findStone.mockReturnValue(false); }); @@ -61,8 +61,11 @@ vi.mock('../processes', () => ({ listProcesses: () => [], findStone: () => findStone(), findNetldi: () => findNetldi(), - startStone: () => startStone(), - startNetldi: () => startNetldi(), + ensureProcesses: async () => { + const startedStone = !findStone(); + if (startedStone) await startStone(); + return { startedStone, startedNetldi: false }; + }, isListening: () => true, isRunning: () => findStone(), stopNetldi: async () => {}, diff --git a/src/__tests__/startProcesses.test.ts b/src/__tests__/startProcesses.test.ts new file mode 100644 index 0000000..b554958 --- /dev/null +++ b/src/__tests__/startProcesses.test.ts @@ -0,0 +1,497 @@ +import { EventEmitter } from 'events'; +import * as fs from 'fs'; +import * as os from 'os'; +import * as path from 'path'; +import { promisify } from 'util'; +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; +import { __log, __resetSettings, __setSetting } from '../__mocks__/vscode'; + +/** + * Starting the stone and the listener when another process may be doing the + * same, with the engine's commands faked: `gslist` answers with the next of + * `listings` (the last one for good once they run out), and every other + * command exits with the code `exitCodes` gives it. + */ + +let listings: string[] = []; +let gslistCalls = 0; +/** When set, what gslist lists at a given time, instead of `listings`. */ +let listingAt: ((now: number) => string) | undefined; +const exitCodes: Record = {}; +const spawned: string[] = []; + +function gslist(): string { + gslistCalls++; + if (listingAt) return listingAt(Date.now()); + return listings.length > 1 ? (listings.shift() ?? '') : (listings[0] ?? ''); +} + +function fakeChild(command: string): EventEmitter { + const name = path.basename(command); + spawned.push(name); + const child = Object.assign(new EventEmitter(), { + stdout: new EventEmitter(), + stderr: new EventEmitter(), + }); + setImmediate(() => child.emit('close', exitCodes[name] ?? 0)); + return child; +} + +vi.mock('child_process', async (importOriginal) => { + const actual = await importOriginal(); + const execFile = Object.assign(() => {}, { + [promisify.custom]: async () => ({ stdout: gslist(), stderr: '' }), + }); + return { + ...actual, + execFile, + execFileSync: () => gslist(), + spawn: (command: string) => fakeChild(command), + }; +}); + +// The real lock, with what it is asked to wait for kept where a test can ask it. +let satisfied: (() => boolean | Promise) | undefined; +vi.mock('../lock', async (importOriginal) => { + const actual = await importOriginal(); + return { + ...actual, + withStoneLock: ( + work: () => Promise, + wait: { satisfied?: () => boolean | Promise } = {}, + ) => { + satisfied = wait.satisfied; + return actual.withStoneLock(work, wait); + }, + }; +}); + +const { expectedEnginePath } = await import('../paths'); +const { STONE_LOCK_NAME } = await import('../lock'); +const { ensureListener, ensureProcesses, stoneReady, stoneState, waitForStoneReady } = + await import('../processes'); +const { parseGslist } = await import('../gslist'); + +function row(status: string, type: 'Stone' | 'Netldi', name: string): string { + return `${status.padEnd(12)} 4.0.0.a4 me 79386 51475 Sep 28 19:31 ${type.padEnd(7)} ${name}`; +} + +const STONE_UP = row('OK', 'Stone', 'gemdb'); +const LISTENER_UP = row('OK', 'Netldi', 'gemdbldi'); +const STONE_STARTING = row('Startup', 'Stone', 'gemdb'); +const BOTH_UP = [STONE_UP, LISTENER_UP].join('\n'); + +let root: string; + +beforeEach(() => { + __resetSettings(); + root = fs.mkdtempSync(path.join(os.tmpdir(), 'gemdb-start-')); + __setSetting('gemdb.rootPath', root); + fs.mkdirSync(path.join(expectedEnginePath(), 'bin'), { recursive: true }); + fs.writeFileSync(path.join(expectedEnginePath(), 'bin', 'gslist'), ''); + listings = []; + gslistCalls = 0; + listingAt = undefined; + spawned.length = 0; + satisfied = undefined; + for (const key of Object.keys(exitCodes)) delete exitCodes[key]; +}); + +/** + * Run fake time forward in steps, letting the faked commands — which exit on a + * real `setImmediate` — finish between them. + */ +async function runFakeTime(ms: number): Promise { + for (let elapsed = 0; elapsed < ms; elapsed += 100) { + await new Promise((resolve) => setImmediate(resolve)); + await vi.advanceTimersByTimeAsync(100); + } +} + +afterEach(() => { + vi.useRealTimers(); + fs.rmSync(root, { recursive: true, force: true }); +}); + +describe('ensureProcesses', () => { + it('starts nothing, and says so, when both are already up', async () => { + listings = [BOTH_UP]; + const beforeStoneStart = vi.fn(); + + const started = await ensureProcesses({ beforeStoneStart }); + + expect(started).toEqual({ startedStone: false, startedNetldi: false }); + expect(spawned).toEqual([]); + expect(beforeStoneStart).not.toHaveBeenCalled(); + }); + + it('asks gslist once and takes no lock when both are up, as every cell finds them', async () => { + listings = [BOTH_UP]; + + await ensureProcesses(); + + expect(gslistCalls).toBe(1); + expect(satisfied).toBeUndefined(); + }); + + it('takes the lock and waits for a stone that is starting, even with a listener up', async () => { + const starting = [STONE_STARTING, LISTENER_UP].join('\n'); + listings = [starting, starting, starting, BOTH_UP]; + const report = vi.fn(); + + const started = await ensureProcesses({ report }); + + expect(started).toEqual({ startedStone: false, startedNetldi: false }); + expect(satisfied).toBeDefined(); + expect(report).toHaveBeenCalledWith('Waiting for the database to finish starting…'); + }); + + it('takes the lock for a stone that is shutting down, even with a listener up', async () => { + listings = [[row('Shutdown', 'Stone', 'gemdb'), LISTENER_UP].join('\n')]; + + await expect(ensureProcesses()).rejects.toThrow('The database is shutting down'); + expect(spawned).toEqual([]); + }); + + it('asks gslist no more often than before the fast path on a cold start', async () => { + // Before the lock, inside it, and once the stone is up; the listener is + // judged from that last one. + listings = ['', '', STONE_UP]; + + await ensureProcesses(); + + expect(gslistCalls).toBe(3); + }); + + it('starts both, guards first, when neither is up', async () => { + // Before the lock, inside it, then the stone after starting it. + listings = ['', '', STONE_UP]; + const beforeStoneStart = vi.fn(() => { + expect(spawned).toEqual([]); + }); + + const started = await ensureProcesses({ beforeStoneStart }); + + expect(started).toEqual({ startedStone: true, startedNetldi: true }); + expect(spawned).toEqual(['startstone', 'startnetldi']); + expect(beforeStoneStart).toHaveBeenCalledOnce(); + }); + + it('starts only the listener when the stone is up, without the stone’s guards', async () => { + listings = [STONE_UP]; + const beforeStoneStart = vi.fn(); + + const started = await ensureProcesses({ beforeStoneStart }); + + expect(started).toEqual({ startedStone: false, startedNetldi: true }); + expect(spawned).toEqual(['startnetldi']); + expect(beforeStoneStart).not.toHaveBeenCalled(); + }); + + it('starts no stone when a guard refuses it', async () => { + listings = ['']; + + const start = ensureProcesses({ + beforeStoneStart: () => { + throw new Error('the database is on NFS'); + }, + }); + + await expect(start).rejects.toThrow('the database is on NFS'); + expect(spawned).toEqual([]); + }); + + it('looks for the listener again after starting the stone, not at a list from before', async () => { + // Another process started the listener while this one started the stone. + listings = ['', '', BOTH_UP]; + + const started = await ensureProcesses(); + + expect(started).toEqual({ startedStone: true, startedNetldi: false }); + expect(spawned).toEqual(['startstone']); + }); + + it('counts a listener another process started first as up, not as a failure (#89)', async () => { + // Both saw no listener; the other one won, so startnetldi refuses with + // "already running" and the re-list shows the listener answering. + exitCodes.startnetldi = 1; + listings = [STONE_UP, STONE_UP, BOTH_UP]; + + const started = await ensureProcesses(); + + expect(started).toEqual({ startedStone: false, startedNetldi: false }); + expect(__log).toContain('Another process started the session listener.'); + }); + + it('waits for a listener another process is still starting when the two overlap', async () => { + // startnetldi gives up over the other's lock file before that one answers. + vi.useFakeTimers({ toFake: ['setTimeout', 'Date'] }); + exitCodes.startnetldi = 3; + listings = [STONE_UP, STONE_UP, STONE_UP, STONE_UP, BOTH_UP]; + + const start = ensureProcesses(); + await runFakeTime(1_000); + + await expect(start).resolves.toEqual({ startedStone: false, startedNetldi: false }); + }); + + it('still fails a listener start that leaves no listener up', async () => { + vi.useFakeTimers({ toFake: ['setTimeout', 'Date'] }); + exitCodes.startnetldi = 1; + listings = [STONE_UP]; + + const failed = expect(ensureProcesses()).rejects.toThrow( + /Start session listener failed \(exit code 1\)/, + ); + await runFakeTime(6_000); + + await failed; + }); + + it('still fails a listener start that leaves a listener that is not answering', async () => { + vi.useFakeTimers({ toFake: ['setTimeout', 'Date'] }); + exitCodes.startnetldi = 1; + listings = [ + STONE_UP, + STONE_UP, + [STONE_UP, row('exe deleted', 'Netldi', 'gemdbldi')].join('\n'), + ]; + + const failed = expect(ensureProcesses()).rejects.toThrow(/Start session listener failed/); + await runFakeTime(6_000); + + await failed; + }); + + it('asks gslist once inside the lock when only the listener is missing', async () => { + listings = [STONE_UP]; + + await ensureProcesses(); + + expect(gslistCalls).toBe(2); + }); + + it('stops waiting for the lock only once both are up and answering', async () => { + // Anything short of both up takes the lock, which is what records the wait. + listings = [STONE_UP]; + await ensureProcesses(); + const check = async (listing: string): Promise => { + listings = [listing]; + return satisfied?.(); + }; + + expect(await check(BOTH_UP)).toBe(true); + expect(await check(STONE_UP)).toBe(false); + expect(await check(LISTENER_UP)).toBe(false); + expect(await check([STONE_STARTING, LISTENER_UP].join('\n'))).toBe(false); + }); +}); + +describe('a stone that is still starting', () => { + it('is listed, but not ready for a login', () => { + const processes = parseGslist(STONE_STARTING); + + expect(processes).toHaveLength(1); + expect(stoneReady(processes)).toBe(false); + }); + + it('is waited for until it reports OK', async () => { + listings = [STONE_STARTING, STONE_STARTING, STONE_UP]; + const report = vi.fn(); + + await waitForStoneReady(report, { pollMs: 1 }); + + expect(report).toHaveBeenCalledWith('Waiting for the database to finish starting…'); + expect(listings).toEqual([STONE_UP]); + }); + + it('is given up on after the timeout, naming the stone’s log', async () => { + listings = [STONE_STARTING]; + + const wait = waitForStoneReady(undefined, { pollMs: 1, timeoutMs: 20 }); + + await expect(wait).rejects.toThrow(/starting for over a minute\. See .*gemdb\.log/); + }); + + it('is an error when it disappears instead of finishing', async () => { + listings = [STONE_STARTING, '']; + + const wait = waitForStoneReady(undefined, { pollMs: 1 }); + + await expect(wait).rejects.toThrow(/stopped while it was starting/); + }); + + it('holds back the listener until it is ready', async () => { + listings = [STONE_STARTING, STONE_STARTING, STONE_STARTING, STONE_UP]; + const report = vi.fn(); + + const started = await ensureProcesses({ report }); + + expect(started).toEqual({ startedStone: false, startedNetldi: true }); + expect(report.mock.calls.map(([message]) => message)).toEqual([ + 'Waiting for the database to finish starting…', + 'Starting the session listener…', + ]); + }); +}); + +describe('what the stone’s status means', () => { + const stateOf = (status: string): string => + stoneState(parseGslist(row(status, 'Stone', 'gemdb'))); + + it('reads the statuses the engine prints, whatever their case', () => { + expect(stateOf('OK')).toBe('ready'); + expect(stateOf('Startup')).toBe('starting'); + expect(stateOf('recovery')).toBe('starting'); + expect(stateOf('Shutdown')).toBe('stopping'); + expect(stoneState([])).toBe('absent'); + }); + + it('leaves every other listed status to the login, as before GemDB waited for OK', () => { + for (const status of ['exe deleted', 'frozen', 'full', 'killed', 'exists', 'restoreBkup']) { + expect(stateOf(status)).toBe('other'); + } + }); + + it('does not wait on a stone that is listed but neither OK nor starting', async () => { + listings = [row('exe deleted', 'Stone', 'gemdb')]; + + await waitForStoneReady(undefined, { pollMs: 1, timeoutMs: 20 }); + }); + + it('says a stone at Shutdown is shutting down, without waiting on it', async () => { + listings = [row('Shutdown', 'Stone', 'gemdb')]; + + await expect(waitForStoneReady(undefined, { pollMs: 1, timeoutMs: 1000 })).rejects.toThrow( + 'The database is shutting down', + ); + }); + + it('starts nothing beside a stone that is shutting down', async () => { + listings = [row('Shutdown', 'Stone', 'gemdb')]; + + await expect(ensureProcesses()).rejects.toThrow('The database is shutting down'); + expect(spawned).toEqual([]); + }); + + it('brings the listener up beside a stone in any other listed state', async () => { + listings = [row('exe deleted', 'Stone', 'gemdb')]; + const beforeStoneStart = vi.fn(); + + const started = await ensureProcesses({ beforeStoneStart }); + + expect(started).toEqual({ startedStone: false, startedNetldi: true }); + expect(spawned).toEqual(['startnetldi']); + expect(beforeStoneStart).not.toHaveBeenCalled(); + }); +}); + +describe('putting the listener back after a declined force-stop', () => { + it('starts the listener beside a stone that is still up', async () => { + listings = [STONE_UP]; + + expect(await ensureListener()).toBe(true); + expect(spawned).toEqual(['startnetldi']); + }); + + it('starts nothing when the stone went away while the user was deciding', async () => { + listings = ['']; + + expect(await ensureListener()).toBe(false); + expect(spawned).toEqual([]); + }); + + it('starts nothing beside a stone that is shutting down', async () => { + listings = [row('Shutdown', 'Stone', 'gemdb')]; + + expect(await ensureListener()).toBe(false); + expect(spawned).toEqual([]); + }); + + it('starts nothing when the listener is already back', async () => { + listings = [BOTH_UP]; + + expect(await ensureListener()).toBe(false); + expect(spawned).toEqual([]); + }); +}); + +/** + * Queued behind a start that holds the stone lock for longer than a minute, + * which the holder can: guards, startstone, a minute's wait for the stone and + * startnetldi, all inside the lock. The holder here is another live process. + */ +describe('waiting for the stone lock', () => { + /** Hold the lock as `pid` would, from now until `releaseAfterMs`, if given. */ + function holdLock(pid: number, releaseAfterMs?: number): void { + const lock = path.join(root, STONE_LOCK_NAME); + fs.mkdirSync(lock); + fs.writeFileSync(path.join(lock, 'pid'), `${pid}\n`); + if (releaseAfterMs !== undefined) { + setTimeout(() => fs.rmSync(lock, { recursive: true, force: true }), releaseAfterMs); + } + } + + /** Settle `promise` while fake time runs `ms`, so a rejection is never left unhandled. */ + async function after( + promise: Promise, + ms: number, + ): Promise<{ value?: T; error?: Error; settled: boolean }> { + const outcome: { value?: T; error?: Error; settled: boolean } = { settled: false }; + promise.then( + (value) => Object.assign(outcome, { value, settled: true }), + (error: Error) => Object.assign(outcome, { error, settled: true }), + ); + await vi.advanceTimersByTimeAsync(ms); + return outcome; + } + + it('outlasts a minute while the holder is visibly starting the stone', async () => { + vi.useFakeTimers({ toFake: ['setTimeout', 'Date'] }); + const t0 = Date.now(); + // startstone for 20 s, then 50 s at Startup, then both up. + listingAt = (now) => (now - t0 < 20_000 ? '' : now - t0 < 70_000 ? STONE_STARTING : BOTH_UP); + holdLock(process.ppid, 70_000); + + const outcome = await after(ensureProcesses(), 75_000); + + expect(outcome.error).toBeUndefined(); + expect(outcome.value).toEqual({ startedStone: false, startedNetldi: false }); + expect(spawned).toEqual([]); + }); + + it('still gives up after a minute on a holder that shows nothing', async () => { + vi.useFakeTimers({ toFake: ['setTimeout', 'Date'] }); + listingAt = () => ''; + holdLock(process.ppid); + + const start = ensureProcesses(); + expect((await after(start, 59_000)).settled).toBe(false); + const outcome = await after(start, 2_000); + + expect(outcome.error?.message).toMatch(/Another process has been starting the database/); + }); + + it('gives up on a stone that never finishes starting, past the holder’s worst case', async () => { + vi.useFakeTimers({ toFake: ['setTimeout', 'Date'] }); + listingAt = () => STONE_STARTING; + holdLock(process.ppid); + + const start = ensureProcesses(); + expect((await after(start, 140_000)).settled).toBe(false); + const outcome = await after(start, 15_000); + + expect(outcome.error?.message).toMatch(/Another process has been starting the database/); + }); + + it('says it is this window that is starting the database when it is', async () => { + vi.useFakeTimers({ toFake: ['setTimeout', 'Date'] }); + listingAt = () => ''; + holdLock(process.pid); + + const outcome = await after(ensureProcesses(), 65_000); + + expect(outcome.error?.message).toMatch(/^This window has been starting the database/); + expect(outcome.error?.message).toContain(STONE_LOCK_NAME); + }); +}); diff --git a/src/__tests__/stop.test.ts b/src/__tests__/stop.test.ts index 5f08d8a..b2e019b 100644 --- a/src/__tests__/stop.test.ts +++ b/src/__tests__/stop.test.ts @@ -37,6 +37,8 @@ function makeWorld(options: { stoneRefuses?: boolean; /** Fail the stop but go down anyway, the way a timeout does. */ stoneStopsLate?: boolean; + /** Finish stopping while the question is up, as a refused stop that was already under way can. */ + stoneStopsDuringQuestion?: boolean; confirm?: boolean; }): { calls: string[]; world: StopWorld } { let stoneUp = options.stoneUp ?? true; @@ -75,6 +77,7 @@ function makeWorld(options: { }, confirmForce: () => { calls.push('confirmForce'); + if (options.stoneStopsDuringQuestion) stoneUp = false; return Promise.resolve(options.confirm ?? false); }, log: () => {}, @@ -126,6 +129,24 @@ describe('runStop', () => { ]); }); + it('puts nothing back when the stone stopped while the user was deciding', async () => { + // The user's question was whether to leave it running, and it is no longer + // running: a listener would serve nothing, and "still running" would be untrue. + const { calls, world } = makeWorld({ + stoneRefuses: true, + stoneStopsDuringQuestion: true, + confirm: false, + }); + await runStop(world); + expect(calls).toEqual([ + 'logout', + 'stopMcpServer', + 'stopNetldi', + 'stopStone(false)', + 'confirmForce', + ]); + }); + it('forces only after the user confirms', async () => { const { calls, world } = makeWorld({ stoneRefuses: true, confirm: true }); await runStop(world); diff --git a/src/cli.ts b/src/cli.ts index 7f7da97..70baa68 100644 --- a/src/cli.ts +++ b/src/cli.ts @@ -520,21 +520,66 @@ fi # # mkdir is the primitive: it creates or fails, with no window between the test # and the claim, and it is there on a stock macOS where flock is not. -stone_is_up() { - "$GEMSTONE/bin/gslist" 2>/dev/null | awk -v s="$STONE" '$(NF-1) == "Stone" && $NF == s { found = 1 } END { exit !found }' +# +# What the stone's status says decides what to do. Not listed: start one. A +# stone still at Startup -- recovering from a crash, or another process's start +# not finished -- is listed, and a second startstone beside it is the +# two-stones case above, so it is waited for until it is past Startup, since a +# login now would fail. One at Shutdown is being stopped, and saying so beats +# waiting a minute for it. Anything else goes on to the login, which judges it: +# a stone left running when the engine tree was replaced reads "exe deleted" +# and takes logins. +# +# The status as gslist -cvl lists it, lowercased (the engine prints "OK", +# "Startup", "frozen"), or nothing when the stone is not listed. One call per +# question: -v asks the stone itself, which takes about five seconds when it is +# frozen (measured). A row is status, version, owner, pid, port, three date +# fields, type and name, and "exe deleted" is the one two-word status. A row of +# any other shape is still this stone, so it answers something: nothing would +# mean "start one". +stone_status() { + "$GEMSTONE/bin/gslist" -cvl 2>/dev/null | awk -v s="$STONE" '$(NF-1) == "Stone" && $NF == s { print tolower(NF == 10 ? $1 : NF == 11 ? $1 " " $2 : "listed"); exit }' +} +starting() { case "$1" in startup|recovery) return 0 ;; *) return 1 ;; esac; } +shutting_down() { + echo "gemdb: the database is shutting down. Run this again once it has stopped." >&2 + exit 1 +} +# Wait while the stone is starting, from the status last seen ($1). $2 is where +# to look when it fails. Waits are timed by the clock, not by counting polls: +# each poll is a gslist call, and those vary from milliseconds to seconds. +wait_for_stone() { + local st="$1" deadline=$(( $(date +%s) + 60 )) said="" + while starting "$st"; do + if [ "$(date +%s)" -ge "$deadline" ]; then + echo "gemdb: the database has been starting for over a minute.$2" >&2 + exit 1 + fi + [ -z "$said" ] && said=1 && echo "gemdb: waiting for the database to finish starting…" >&2 + sleep 0.1 + st=$(stone_status) + done + [ "$st" = shutdown ] && shutting_down + if [ -z "$st" ]; then + echo "gemdb: the database stopped while it was starting.$2" >&2 + exit 1 + fi } +STATUS=$(stone_status) +[ "$STATUS" = shutdown ] && shutting_down ${ external ? `# This machine's administrator runs the database, so a stopped stone is theirs -# to start: starting it here would run it as this user. -if ! stone_is_up; then +# to start: starting it here would run it as this user. So no lock and no +# start, only a wait for one that is still starting. +if [ -z "$STATUS" ]; then echo "gemdb: the database (stone $STONE) is not running. It is run by this machine's administrator." >&2 exit 1 fi +wait_for_stone "$STATUS" "" ` - : '' -}if ! stone_is_up; then + : `if [ -z "$STATUS" ] || starting "$STATUS"; then STONE_LOCK="$ROOT/.gemdb-stone.lock" # mkdir and the pid write are two steps, here and in the extension, so a # lock with no pid yet is one being taken right now. It is debris only once @@ -579,8 +624,8 @@ fi return "$took" } held="" - tries=0 - while [ "$tries" -lt 100 ]; do + lock_deadline=$(( $(date +%s) + 10 )) + while [ "$(date +%s)" -lt "$lock_deadline" ]; do if mkdir "$STONE_LOCK" 2>/dev/null; then held=yes echo $$ > "$STONE_LOCK/pid" 2>/dev/null @@ -599,30 +644,39 @@ fi continue fi fi - stone_is_up && break + STATUS=$(stone_status) + [ -n "$STATUS" ] && ! starting "$STATUS" && break sleep 0.1 - tries=$((tries + 1)) done if [ -n "$held" ]; then # Re-check inside the lock. Between our first check and this one, whoever # we queued behind may have started it -- which is the case the bare - # check-then-act got wrong. - if ! stone_is_up; then + # check-then-act got wrong. Listed, not ready: one still starting is + # waited for below, never started again. + STATUS=$(stone_status) + if [ -z "$STATUS" ]; then echo "gemdb: starting the database…" >&2 if ! "$GEMSTONE/bin/startstone" -l "$ROOT/db/log/$STONE.log" "$STONE" >/dev/null 2>&1; then release_stone_lock echo "gemdb: the database at $ROOT could not be started. See $ROOT/db/log/$STONE.log" >&2 exit 1 fi + STATUS=$(stone_status) fi release_stone_lock - elif ! stone_is_up; then + elif [ -z "$STATUS" ]; then echo "gemdb: the database is not running and another process has been starting it for" >&2 echo "gemdb: ten seconds. See $ROOT/db/log/$STONE.log, or remove $STONE_LOCK if nothing is." >&2 exit 1 fi + + # Ours or someone else's, a stone still starting is waited for: a login now + # would fail. A minute, as the extension waits. + wait_for_stone "$STATUS" " See $ROOT/db/log/$STONE.log" fi +` +} # The run's temporary files, removed however it ends: bash runs an EXIT trap # on a normal exit, and on SIGHUP (a terminal tab closed mid-run) and SIGTERM diff --git a/src/cliMain.ts b/src/cliMain.ts index 8607045..2ac6783 100644 --- a/src/cliMain.ts +++ b/src/cliMain.ts @@ -1,6 +1,13 @@ -import { abortIdleSessionsAfterMinutes } from './config'; +import { abortIdleSessionsAfterMinutes, externalDatabase } from './config'; +import { assertSafeToStart } from './database'; import { errorMessage } from './log'; -import { findNetldi, findStone, startNetldi, startStone } from './processes'; +import { + ensureProcesses, + externalDatabaseDownError, + findNetldi, + findStone, + listProcesses, +} from './processes'; import { PyRepl, ReplSession } from './pyRepl'; import { runPythonInSession } from './pythonQueries'; import { GciSession, setInputHandler } from './session'; @@ -25,16 +32,30 @@ import { GciSession, setInputHandler } from './session'; * Bring the database up, the same judgement the wrapper makes for a file run: * asking for the shell is asking for a running database. Unlike the wrapper's * file mode — a linked gem, needing only the stone — a shell session arrives - * through the listener, so both are ensured. Errors are reported rather than - * thrown: the shell prompt (or the exit code) is the caller's answer. + * through the listener, so both are ensured. Both go through + * `ensureProcesses`, the same locked path the window takes, so a Shell opened while a window is + * starting the database waits for it rather than racing it. The stone gets the + * window's pre-start guards too, all but statmonitor, whose configuration + * comes from editor settings the Shell does not have: `system.conf` keeps + * whatever the window's last start wrote. + * + * An external database is only checked, as the window checks it: GemDB starts + * none of it. Errors are reported rather than thrown: the shell prompt (or the + * exit code) is the caller's answer. */ async function ensureDatabase(): Promise { try { - if (!findStone()) { - process.stderr.write('gemdb: starting the database…\r\n'); - await startStone(); + const external = externalDatabase(); + if (external) { + const running = listProcesses(); + if (!findStone(running) || !findNetldi(running)) throw externalDatabaseDownError(external); + } else { + await ensureProcesses({ + beforeStoneStart: assertSafeToStart, + report: (message) => + process.stderr.write(`gemdb: ${message.charAt(0).toLowerCase()}${message.slice(1)}\r\n`), + }); } - if (!findNetldi()) await startNetldi(); return true; } catch (e) { // Raw mode may be on by now, so bare `\n` would stairstep the message. diff --git a/src/database.ts b/src/database.ts index df7b390..e70b194 100644 --- a/src/database.ts +++ b/src/database.ts @@ -2,10 +2,10 @@ import * as crypto from 'crypto'; import * as fs from 'fs'; import * as path from 'path'; import { execFileSync } from 'child_process'; -import { STONE_NAME, databasePasswordPath, rootPath } from './config'; +import { STONE_NAME, databasePasswordPath, engineVersion, rootPath } from './config'; import { log, logStep } from './log'; import { isOnNfs } from './networkFileSystem'; -import { databaseExists, databasePath, ensureRootPath, extentPath } from './paths'; +import { databaseExists, databasePath, enginePath, ensureRootPath, extentPath } from './paths'; /** * Create the one database GemDB manages. @@ -567,3 +567,24 @@ export function databaseOnNfsError(): DatabaseOnNfsError { 'for GemDB instead.', ); } + +/** + * Everything checked, or put right, just before GemDB's own stone starts — + * from the window or from the GemDB Shell, so neither door starts a stone the + * other would have refused. + * + * The engine check is here as well as in `prepareFiles` because an extension + * update reaches a start without going through preparation at all: the engine + * is downloaded, the database exists, Grail is staged, so the first thing that + * happens is a stone starting on a repository the new engine cannot read. NFS + * likewise: a database set up there before setup checked for it. And a + * database an earlier GemDB created has no space limits yet, while the stone + * reserves the extent's full size as it starts. + */ +export function assertSafeToStart(): void { + assertDatabaseIsLocal(); + const engine = enginePath(); + if (engine) assertDatabaseMatchesEngine(engine, engineVersion()); + ensureSpaceLimits(); + assertRoomForExtent(); +} diff --git a/src/lifecycle.ts b/src/lifecycle.ts index 7d90eba..d83e13d 100644 --- a/src/lifecycle.ts +++ b/src/lifecycle.ts @@ -18,9 +18,8 @@ import { DatabaseOnNfsError, DatabaseVersionError, DiskSpaceError, - assertRoomForExtent, assertRoomForSetup, - ensureSpaceLimits, + assertSafeToStart, removeDatabase, } from './database'; import { Progress, installEngine, removeEngine } from './engine'; @@ -53,14 +52,14 @@ import { mcpPath, } from './paths'; import { - ExternalDatabaseError, + ensureListener, + ensureProcesses, + externalDatabaseDownError, findNetldi, findStone, isListening, isRunning, listProcesses, - startNetldi, - startStone, stopNetldi, stopStone, } from './processes'; @@ -810,54 +809,24 @@ export async function resumeRunning(extensionPath: string): Promise { async function startProcesses( progress?: vscode.Progress<{ message?: string }>, ): Promise<{ startedStone: boolean; startedNetldi: boolean }> { - const running = listProcesses(); - let startedStone = false; - let startedNetldi = false; - // Nothing to start for an external database — only whether it is up, said // in terms of what to do about it. const external = externalDatabase(); if (external) { - if (!findStone(running) || !findNetldi(running)) { - throw new ExternalDatabaseError( - `The database is not running: GemDB expects stone ${external.stone} and NetLDI ` + - `${external.netldi}, which this machine's administrator runs. Ask them to start it.`, - ); - } + const running = listProcesses(); + if (!findStone(running) || !findNetldi(running)) throw externalDatabaseDownError(external); log('The database is running.'); - return { startedStone, startedNetldi }; + return { startedStone: false, startedNetldi: false }; } - if (!findStone(running)) { - // Checked here as well as in `prepareFiles`, because an extension update - // reaches this line without going through preparation at all: the engine - // is downloaded, the database exists, Grail is staged, so `isInstalled()` - // is true and the first thing that happens is a stone starting on a - // repository the new engine cannot read. - // NFS likewise: a database set up there before setup checked for it. - assertDatabaseIsLocal(); - const engine = enginePath(); - if (engine) assertDatabaseMatchesEngine(engine, engineVersion()); - // A database an earlier GemDB created has no space limits yet, and the - // stone reserves the extent's full size as it starts. - ensureSpaceLimits(); - // Every start, not once: the settings it is written from may have changed. - ensureStatmonitor(); - assertRoomForExtent(); - progress?.report({ message: 'Starting the database…' }); - await startStone(); - startedStone = true; - } else { - log('The database is already running.'); - } - if (!findNetldi(running)) { - progress?.report({ message: 'Starting the session listener…' }); - await startNetldi(); - startedNetldi = true; - } else { - log('The session listener is already running.'); - } - return { startedStone, startedNetldi }; + return ensureProcesses({ + beforeStoneStart: () => { + assertSafeToStart(); + // Every start, not once: the settings it is written from may have changed. + ensureStatmonitor(); + }, + report: (message) => progress?.report({ message }), + }); } /** @@ -884,7 +853,7 @@ export interface StopWorld { listenerUp: () => boolean; stopStone: (force: boolean) => Promise; stopNetldi: () => Promise; - startNetldi: () => Promise; + startNetldi: () => Promise; /** Ask whether to disconnect the sessions that are in the way. */ confirmForce: (reason: string) => Promise; log: (message: string) => void; @@ -933,7 +902,12 @@ export async function runStop(world: StopWorld): Promise { if (!(await world.confirmForce(reason))) { // Declining means "leave it running", and a running database with no // listener accepts no new sessions — so put back what we stopped on the - // way in rather than leaving a half-stopped machine behind. + // way in rather than leaving a half-stopped machine behind. Unless it + // finished stopping while the question was up: then it is stopped. + if (!world.stoneUp()) { + world.log('GemDB stopped.'); + return; + } if (!world.listenerUp()) await world.startNetldi(); world.log('GemDB is still running.'); return; @@ -976,7 +950,10 @@ async function stopOnce(): Promise { listenerUp: () => isListening(), stopStone, stopNetldi, - startNetldi, + // Through the lock, like every other start: the window that declined + // is not the only one that may be putting the listener back. The + // listener only: a stone gone by now is not this call's to restart. + startNetldi: () => ensureListener(), confirmForce, log, }); diff --git a/src/lock.ts b/src/lock.ts index df669b5..0186ac5 100644 --- a/src/lock.ts +++ b/src/lock.ts @@ -496,9 +496,23 @@ function stoneLockPath(): string { return path.join(rootPath(), STONE_LOCK_NAME); } -/** How often, and for how long, {@link withStoneLock} waits for the lock. */ -const STONE_LOCK_POLL_MS = 200; -const STONE_LOCK_TIMEOUT_MS = 60_000; +/** + * How often, and for how long, {@link withStoneLock} waits for the lock — + * and `waitForStoneReady` for a stone to finish starting. + */ +export const STONE_LOCK_POLL_MS = 200; +export const STONE_LOCK_TIMEOUT_MS = 60_000; + +/** + * How long past {@link STONE_LOCK_TIMEOUT_MS} a holder that is visibly + * getting somewhere keeps a waiter waiting. The holder keeps the lock through + * the pre-start guards (a `copydbf -i` header read and disk checks), `startstone`, up to + * a minute's wait for the stone and `startnetldi`, so a minute is not its + * worst case; this ceiling is above it. Progress counts for + * {@link STONE_LOCK_IDLE_MS} after it was last seen. + */ +export const STONE_LOCK_CEILING_MS = 150_000; +export const STONE_LOCK_IDLE_MS = 30_000; /** * Run `work` while holding the stone lock, waiting for another process to @@ -513,31 +527,55 @@ const STONE_LOCK_TIMEOUT_MS = 60_000; * Waiting is the point: a caller that stepped aside used to carry on as if * the stone were up — to the listener and the Grail file-in — while the * wrapper was still starting it. `satisfied` is asked between polls, and true - * ends the wait with undefined and `work` not run: for `startStone`, the stone - * came up while we waited, which is what we were waiting for. A lock still - * held after a minute is an error naming it, since only a person can say - * whether whatever holds it is really still working. + * ends the wait with undefined and `work` not run: whoever held the lock + * brought up what we wanted, which is what we were waiting for. `progressing` + * is asked right after it, so it may judge by what `satisfied` just looked + * at: true means the holder is visibly getting somewhere, which keeps the wait + * going past the minute, up to {@link STONE_LOCK_CEILING_MS}. A lock still + * held after that is an error naming it, since only a person can say whether + * whatever holds it is really still working. */ export async function withStoneLock( work: () => Promise, - wait: { satisfied?: () => boolean | Promise; pollMs?: number; timeoutMs?: number } = {}, + wait: { + satisfied?: () => boolean | Promise; + progressing?: () => boolean; + pollMs?: number; + timeoutMs?: number; + } = {}, ): Promise { const lock = stoneLockPath(); ensureRootPath(); - const deadline = Date.now() + (wait.timeoutMs ?? STONE_LOCK_TIMEOUT_MS); + const start = Date.now(); + const timeoutMs = wait.timeoutMs ?? STONE_LOCK_TIMEOUT_MS; + let lastProgress = -Infinity; let logged = false; while (!claimStoneLock(lock)) { + // Two starts in this one process wait on each other too, and "another + // process" would send the user looking for one that does not exist. + const ours = readStoneLockPid(lock) === String(process.pid); if (!logged) { logged = true; - log('Another process is starting the database; waiting for it.'); + log( + ours + ? 'This window is already starting the database; waiting for it.' + : 'Another process is starting the database; waiting for it.', + ); } await sleep(wait.pollMs ?? STONE_LOCK_POLL_MS); if (await wait.satisfied?.()) return undefined; - if (Date.now() > deadline) { + const now = Date.now(); + if (wait.progressing?.()) lastProgress = now; + const stalled = now - start > timeoutMs && now - lastProgress > STONE_LOCK_IDLE_MS; + if (stalled || now - start > STONE_LOCK_CEILING_MS) { throw new Error( - `Another process has been starting the database for over a minute. ` + - `If nothing is, remove ${lock} and try again.`, + ours + ? 'This window has been starting the database for over a minute and has not ' + + 'finished. See the GemDB log for what it is waiting on; if nothing is, ' + + `remove ${lock} and try again.` + : 'Another process has been starting the database for over a minute. ' + + `If nothing is, remove ${lock} and try again.`, ); } } diff --git a/src/networkFileSystem.ts b/src/networkFileSystem.ts index 7779bba..70faa43 100644 --- a/src/networkFileSystem.ts +++ b/src/networkFileSystem.ts @@ -26,7 +26,7 @@ import * as path from 'path'; * be created. Anything that cannot be read answers false. A wrong "NFS" blocks * setup on a machine that could run it; a wrong "local" costs what happened * before this check existed, and the stone's refusal is recognised then too - * (see `startStone`). + * (see `refusedNfs`). */ export function isOnNfs(dir: string, world: FileSystemWorld = realWorld): boolean { const existing = nearestExisting(path.resolve(dir), world); diff --git a/src/processes.ts b/src/processes.ts index f69d705..c6f084c 100644 --- a/src/processes.ts +++ b/src/processes.ts @@ -16,7 +16,7 @@ import { } from './config'; import { libraryPathVariable, sharedLibraryExtension } from './platform'; import { log, logStep } from './log'; -import { withStoneLock } from './lock'; +import { STONE_LOCK_POLL_MS, STONE_LOCK_TIMEOUT_MS, withStoneLock } from './lock'; import { DiskSpaceError, databaseOnNfsError } from './database'; import { EngineProcess, parseGslist } from './gslist'; import { databaseConfPath, databaseLogPath, databasePath, enginePath, grailPath } from './paths'; @@ -170,6 +170,104 @@ export function isListening(processes = listProcesses()): boolean { return findNetldi(processes) !== undefined; } +/** + * True when the stone has finished starting and will take a login. + * + * Not the same question as {@link isRunning}. `gslist` lists a stone from the + * moment it exists, and one recovering from a crash sits at `Startup` for as + * long as recovery takes; a login in that time fails. So whatever is about to + * log in waits for `OK`, while the status bar and maintenance, which ask + * whether there is a stone at all, keep asking that. + */ +export function stoneReady(processes: EngineProcess[]): boolean { + return findStone(processes)?.responding === true; +} + +/** True when the listener is up and answering, the listener's half of {@link stoneReady}. */ +export function listenerReady(processes: EngineProcess[]): boolean { + return findNetldi(processes)?.responding === true; +} + +/** + * What to do about the stone, from its gslist status. + * + * The engine prints statuses in mixed case — `OK`, `Startup`, `Shutdown`, + * `frozen`, `killed`, `exists`, `exe deleted` were all seen — and `gslist -h` + * also lists `recovery`, `full`, `restoreBkup`, `restoreLogs` and + * `contRestore`, so they are compared without case. Only a stone that is + * starting is worth waiting for. One shutting down is said to be, rather than + * waited on for a minute. Anything else that is listed goes on to the login, + * which judges it, as it did before GemDB waited for `OK`: a stone left + * running when the engine tree was replaced reads `exe deleted` and takes + * logins, and refusing it would stop a working database. + */ +export type StoneState = 'absent' | 'ready' | 'starting' | 'stopping' | 'other'; + +export function stoneState(processes: EngineProcess[]): StoneState { + const stone = findStone(processes); + if (!stone) return 'absent'; + if (stone.responding) return 'ready'; + switch (stone.status.toLowerCase()) { + case 'startup': + case 'recovery': + return 'starting'; + case 'shutdown': + return 'stopping'; + default: + return 'other'; + } +} + +/** What to say about a stone that is on its way down, wherever it is met. */ +export const SHUTTING_DOWN_MESSAGE = + 'The database is shutting down. Start it again once it has stopped.'; + +/** + * Wait for a listed stone to finish starting. + * + * Returns at once for a stone that is not starting. One this process did not + * start — a crash being recovered, or one an older GemDB started without + * waiting — is polled until it is past `Startup`. A stone that disappears + * while we wait failed to start, and one still starting after a minute is not + * going to soon; both end in an error naming the stone's log, which says why. + * A stone at `Shutdown` ends the wait at once: it is being stopped. Starts + * from `wait.listing` when the caller has one that recent, rather than asking + * gslist twice in a row. Returns the last listing, so the caller need not + * take another. + */ +export async function waitForStoneReady( + report?: (message: string) => void, + wait: { pollMs?: number; timeoutMs?: number; listing?: EngineProcess[] } = {}, +): Promise { + const stoneLog = path.join(databaseLogPath(), `${STONE_NAME}.log`); + const deadline = Date.now() + (wait.timeoutMs ?? STONE_LOCK_TIMEOUT_MS); + let running = wait.listing ?? (await listProcessesAsync()); + let waiting = false; + for (;;) { + switch (stoneState(running)) { + case 'ready': + case 'other': + return running; + case 'stopping': + throw new Error(SHUTTING_DOWN_MESSAGE); + case 'absent': + throw new Error(`The database stopped while it was starting. See ${stoneLog}.`); + case 'starting': + break; + } + if (!waiting) { + waiting = true; + report?.('Waiting for the database to finish starting…'); + log('The database is still starting; waiting for it.'); + } + if (Date.now() > deadline) { + throw new Error(`The database has been starting for over a minute. See ${stoneLog}.`); + } + await new Promise((resolve) => setTimeout(resolve, wait.pollMs ?? STONE_LOCK_POLL_MS)); + running = await listProcessesAsync(); + } +} + /** * Raised when something asks GemDB to start or stop a database it does not * run. See {@link externalDatabase} for why that is refused, not attempted. @@ -191,44 +289,153 @@ function requireOwnDatabase(action: string): void { ); } -export async function startStone(): Promise { +/** + * What to say when an external database is not up: GemDB does not start it, + * so the sentence says who does. + */ +export function externalDatabaseDownError(external: { + stone: string; + netldi: string; +}): ExternalDatabaseError { + return new ExternalDatabaseError( + `The database is not running: GemDB expects stone ${external.stone} and NetLDI ` + + `${external.netldi}, which this machine's administrator runs. Ask them to start it.`, + ); +} + +/** + * Bring up whichever of the stone and the session listener is not already + * up, and say which of them this call started. + * + * Every start of GemDB's own database goes through here — the window's and + * the GemDB Shell's (the listener a declined force-stop puts back goes through + * {@link ensureListener}) — and all of it happens under the stone lock the `gemdb` wrapper also takes. Checking + * and starting have to be one step: checked outside the lock, two callers + * that both found the listener missing both ran `startnetldi`, and the loser + * reported a failure over a database that was up. So the look happens inside + * the lock, and a caller that queued behind whoever was starting it finds + * everything up and starts nothing. For the same reason, both coming up while + * we wait for the lock ends the wait, with nothing started. + * + * `beforeStoneStart` runs only when this call is about to start the stone: + * the guards that refuse a stone that should not start belong there, not on + * every call. `report` hears each step as it begins, for a progress + * notification or a terminal. + */ +export async function ensureProcesses( + opts: { beforeStoneStart?: () => void; report?: (message: string) => void } = {}, +): Promise<{ startedStone: boolean; startedNetldi: boolean }> { requireOwnDatabase('start'); - // Under the lock the generated `gemdb` wrapper also takes, because both - // doors start the same stone and nothing downstream refuses a second one. - // The re-check inside the lock is the point: whoever we queued behind was - // most likely starting it, and without this we would start another. For the - // same reason, a stone that comes up while we wait ends the wait. - await withStoneLock( + // Every notebook cell lands here, and nearly always both are up: one + // listing and no lock then. Never for a stone starting or stopping, which + // the lock and the wait below are for. + const before = await listProcessesAsync(); + const stoneUp = ['ready', 'other'].includes(stoneState(before)); + if (stoneUp && findNetldi(before)) { + log('The database is already running.'); + log('The session listener is already running.'); + return { startedStone: false, startedNetldi: false }; + } + let seen = before; + const started = await withStoneLock( async () => { - if (isRunning()) { - log('The database is already running; nothing to start.'); - return; + let startedStone = false; + // Listed again: what was true before the lock may not be now. + const listed = await listProcessesAsync(); + const state = stoneState(listed); + // Said here, before any wait: a stopping stone's last moments read + // `Startup` before it disappears (measured), which a wait would report + // as a start that failed. + if (state === 'stopping') throw new Error(SHUTTING_DOWN_MESSAGE); + if (state === 'absent') { + opts.beforeStoneStart?.(); + opts.report?.('Starting the database…'); + logStep('Starting the database'); + await runStartstone(); + startedStone = true; + } else { + log('The database is already running.'); } - logStep(`Starting the database`); - const env = engineEnvironment(); - const stoneLog = path.join(databaseLogPath(), `${STONE_NAME}.log`); - const logSizeBefore = fileSize(stoneLog); - try { - await runEngineCommand( - path.join(env.GEMSTONE, 'bin', 'startstone'), - ['-l', stoneLog, STONE_NAME], - env, - 'Start database', - ); - } catch (e) { - if (refusedNfs(e, stoneLog, logSizeBefore)) throw databaseOnNfsError(); - if (stoneLogSays(/No space left on device/, e, stoneLog, logSizeBefore)) { - throw new DiskSpaceError( - 'The GemDB database could not start: the disk ran out of space while it reserved ' + - 'its extent. Free some disk space, or set gemdb.rootPath to a folder on a disk ' + - 'with more room, then start GemDB again.', - ); - } - throw e; + // The wait's last listing is recent enough to judge the listener by: + // it was taken after the stone, ours or not, finished starting. One + // taken before our startstone is not, so the wait starts afresh then. + const running = await waitForStoneReady(opts.report, { + listing: startedStone ? undefined : listed, + }); + + let startedNetldi = false; + if (!findNetldi(running)) { + opts.report?.('Starting the session listener…'); + startedNetldi = await startNetldi(); + } else { + log('The session listener is already running.'); } + return { startedStone, startedNetldi }; }, - { satisfied: isRunningAsync }, + { + satisfied: async () => { + seen = await listProcessesAsync(); + return stoneReady(seen) && listenerReady(seen); + }, + // A stone listed and not going down means whoever holds the lock is past + // startstone: waiting on it, or starting the listener beside it. + progressing: () => ['starting', 'ready', 'other'].includes(stoneState(seen)), + }, + ); + return started ?? { startedStone: false, startedNetldi: false }; +} + +/** + * Put the session listener back, and never the stone: what a declined + * force-stop needs. By the time the user has answered, the stone may have gone + * after all, or be on its way down, and starting one then would undo a stop + * without the guards a start runs. True when this call started the listener. + * Under the stone lock, like every other start. + */ +export async function ensureListener(): Promise { + requireOwnDatabase('start'); + const started = await withStoneLock( + async () => { + const running = await listProcessesAsync(); + const state = stoneState(running); + if (state === 'absent' || state === 'stopping') { + log('The database is not running; not starting the session listener.'); + return false; + } + if (findNetldi(running)) return false; + return startNetldi(); + }, + { satisfied: async () => findNetldi(await listProcessesAsync()) !== undefined }, ); + return started ?? false; +} + +/** + * Run `startstone`, turning the two refusals the stone explains only in its + * log into errors that say what to do. The caller holds the stone lock. + */ +async function runStartstone(): Promise { + const env = engineEnvironment(); + const stoneLog = path.join(databaseLogPath(), `${STONE_NAME}.log`); + const logSizeBefore = fileSize(stoneLog); + try { + await runEngineCommand( + path.join(env.GEMSTONE, 'bin', 'startstone'), + ['-l', stoneLog, STONE_NAME], + env, + 'Start database', + ); + } catch (e) { + if (refusedNfs(e, stoneLog, logSizeBefore)) throw databaseOnNfsError(); + if (stoneLogSays(/No space left on device/, e, stoneLog, logSizeBefore)) { + throw new DiskSpaceError( + 'The GemDB database could not start: the disk ran out of space while it reserved ' + + 'its extent. Free some disk space, or set gemdb.rootPath to a folder on a disk ' + + 'with more room, then start GemDB again.', + ); + } + throw e; + } } /** @@ -277,26 +484,58 @@ function fileSize(file: string): number { } } -export async function startNetldi(): Promise { - requireOwnDatabase('start'); +/** How long a listener another process is starting gets to answer. */ +const LISTENER_SETTLE_MS = 5_000; + +/** + * Start the session listener. True when this call started it; false when + * `startnetldi` refused because another process had started it first. + * + * Not exported: the listener starts only through {@link ensureProcesses} or + * {@link ensureListener}, under the stone lock. + * + * That race is not rare (#89): the window's start, the GemDB Shell's, and + * releases before this one, which start the listener without any lock, can + * all find it missing and start it together. The loser's `startnetldi` fails + * — exit 1, "Server 'gemdbldi' is already running", when the winner is fully + * up; exit 3, "could not start server" over the winner's lock file, when the + * two overlap — and everything the caller wanted is true, so a listener that + * is up and answering afterwards is not a failure. In the overlap the + * winner's listener may still be coming up when ours gives up, so it gets + * {@link LISTENER_SETTLE_MS} to answer; one that does not still fails with + * startnetldi's own words. The lock closes the race between GemDB's own + * callers; this covers what takes no lock. + */ +async function startNetldi(): Promise { logStep('Starting the session listener'); const env = engineEnvironment(); - await runEngineCommand( - path.join(env.GEMSTONE, 'bin', 'startnetldi'), - // -a restricts logins to this user, -g runs sessions as that user without - // needing a host password. Together they are what lets GemDB log in with - // no operating-system credentials at all. - [ - '-a', - os.userInfo().username, - '-g', - '-l', - path.join(databaseLogPath(), `${NETLDI_NAME}.log`), - NETLDI_NAME, - ], - env, - 'Start session listener', - ); + try { + await runEngineCommand( + path.join(env.GEMSTONE, 'bin', 'startnetldi'), + // -a restricts logins to this user, -g runs sessions as that user without + // needing a host password. Together they are what lets GemDB log in with + // no operating-system credentials at all. + [ + '-a', + os.userInfo().username, + '-g', + '-l', + path.join(databaseLogPath(), `${NETLDI_NAME}.log`), + NETLDI_NAME, + ], + env, + 'Start session listener', + ); + return true; + } catch (e) { + const deadline = Date.now() + LISTENER_SETTLE_MS; + while (!listenerReady(await listProcessesAsync())) { + if (Date.now() > deadline) throw e; + await new Promise((resolve) => setTimeout(resolve, STONE_LOCK_POLL_MS)); + } + log('Another process started the session listener.'); + return false; + } } /**