diff --git a/CHANGELOG.md b/CHANGELOG.md index df952bb..d890fe9 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -30,6 +30,26 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 no setter. A method's receiver (`self`, or whatever the def calls it), a tuple's items, group rows and a saved stack's values cannot be changed, and VS Code does not offer Set Value on them. +### 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 2e6fb3a..58eed20 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -51,6 +51,11 @@ outstanding preparation, prompts for shared memory, starts the processes, files Grail in, and brings the MCP server up. New entry points that need a database should call it rather than checking and asking. +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), and "ready" means gslist status `OK`, not "listed": a +stone at `Startup` is listed and refuses logins, so wait on it, never start it. + ## CI `.github/workflows/ci.yml`, two jobs split on what they need. `checks` runs diff --git a/src/__integration__/breakpoint.test.ts b/src/__integration__/breakpoint.test.ts index 05005d3..0fb3147 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__/database.test.ts b/src/__integration__/database.test.ts index f2bd905..1d94819 100644 --- a/src/__integration__/database.test.ts +++ b/src/__integration__/database.test.ts @@ -5,12 +5,12 @@ 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, @@ -81,8 +81,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(); 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..c474354 --- /dev/null +++ b/src/__integration__/processes.test.ts @@ -0,0 +1,189 @@ +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 } from 'child_process'; +import { createDatabase } from '../database'; +import { isSharedMemoryConfigured } from '../osConfig'; +import { + isListening, + isRunning, + listProcesses, + startStone, + stopNetldi, + stopStone, +} from '../processes'; +import { Fixture, limitTestDatabase, makeFixture } 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); +} + +/** 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(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 startStone(); + 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 6439938..18bdfe0 100644 --- a/src/__tests__/cli.test.ts +++ b/src/__tests__/cli.test.ts @@ -310,9 +310,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. */ describe('starting the database', () => { function installEngineStubs(): { starts: string } { @@ -320,25 +321,53 @@ 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'); 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', + // 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', + `[ -f '${marker}' ] && echo "$(cat '${marker}') 4.0.0 me 1 1 x 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)); + } + /** 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), + ); }); } @@ -378,7 +407,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(); @@ -407,7 +436,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(); @@ -465,4 +494,30 @@ 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/); + }); }); 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..4e14a0b 100644 --- a/src/__tests__/externalDatabase.test.ts +++ b/src/__tests__/externalDatabase.test.ts @@ -22,9 +22,9 @@ import { EngineProcess, ExternalDatabaseError, engineEnvironment, + ensureProcesses, findNetldi, findStone, - startNetldi, startStone, stopNetldi, stopStone, @@ -228,7 +228,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__/startProcesses.test.ts b/src/__tests__/startProcesses.test.ts new file mode 100644 index 0000000..666f99e --- /dev/null +++ b/src/__tests__/startProcesses.test.ts @@ -0,0 +1,248 @@ +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[] = []; +const exitCodes: Record = {}; +const spawned: string[] = []; + +function gslist(): string { + 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 { ensureProcesses, stoneReady, 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 = []; + spawned.length = 0; + satisfied = undefined; + for (const key of Object.keys(exitCodes)) delete exitCodes[key]; +}); + +afterEach(() => { + 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('starts both, guards first, when neither is up', async () => { + 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, 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('still fails a listener start that leaves no listener up', async () => { + exitCodes.startnetldi = 1; + listings = [STONE_UP]; + + await expect(ensureProcesses()).rejects.toThrow( + /Start session listener failed \(exit code 1\)/, + ); + }); + + it('still fails a listener start that leaves a listener that is not answering', async () => { + exitCodes.startnetldi = 1; + listings = [ + STONE_UP, + STONE_UP, + STONE_UP, + [STONE_UP, row('exe deleted', 'Netldi', 'gemdbldi')].join('\n'), + ]; + + await expect(ensureProcesses()).rejects.toThrow(/Start session listener failed/); + }); + + it('stops waiting for the lock only once both are up and answering', async () => { + listings = [BOTH_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_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…', + ]); + }); +}); diff --git a/src/cli.ts b/src/cli.ts index 5850490..16fc7ce 100644 --- a/src/cli.ts +++ b/src/cli.ts @@ -473,21 +473,31 @@ 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() { +# +# Two questions, kept apart. Whether a stone is LISTED decides whether to 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. Whether it is READY (status OK) decides whether +# a login can go ahead, so that is what the waiting is for. A two-word status +# such as "exe deleted" does not start with OK, so it is not ready either. +stone_is_listed() { "$GEMSTONE/bin/gslist" 2>/dev/null | awk -v s="$STONE" '$(NF-1) == "Stone" && $NF == s { found = 1 } END { exit !found }' } +stone_is_ready() { + "$GEMSTONE/bin/gslist" -cvl 2>/dev/null | awk -v s="$STONE" '$1 == "OK" && $(NF-1) == "Stone" && $NF == s { found = 1 } END { exit !found }' +} ${ 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 +if ! stone_is_listed; then echo "gemdb: the database (stone $STONE) is not running. It is run by this machine's administrator." >&2 exit 1 fi ` : '' -}if ! stone_is_up; then +}if ! stone_is_ready; 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 @@ -552,7 +562,7 @@ fi continue fi fi - stone_is_up && break + stone_is_ready && break sleep 0.1 tries=$((tries + 1)) done @@ -560,8 +570,9 @@ fi 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. + if ! stone_is_listed; 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 @@ -570,11 +581,28 @@ fi fi fi release_stone_lock - elif ! stone_is_up; then + elif ! stone_is_listed; 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 + + # Listed but not yet ready: ours or someone else's, it is still starting, and + # a login now would fail. A minute, as the extension waits. + ready_tries=0 + until stone_is_ready; do + if ! stone_is_listed; then + echo "gemdb: the database stopped while it was starting. See $ROOT/db/log/$STONE.log" >&2 + exit 1 + fi + if [ "$ready_tries" -ge 600 ]; then + echo "gemdb: the database has been starting for over a minute. See $ROOT/db/log/$STONE.log" >&2 + exit 1 + fi + [ "$ready_tries" -eq 0 ] && echo "gemdb: waiting for the database to finish starting…" >&2 + sleep 0.1 + ready_tries=$((ready_tries + 1)) + done fi # -c 'code': materialise the code as a file, like CPython's -c but visibly so. 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 c539271..4bfd7cf 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,13 @@ import { mcpPath, } from './paths'; import { - ExternalDatabaseError, + ensureProcesses, + externalDatabaseDownError, findNetldi, findStone, isListening, isRunning, listProcesses, - startNetldi, - startStone, stopNetldi, stopStone, } from './processes'; @@ -745,54 +743,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 }), + }); } /** @@ -819,7 +787,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; @@ -900,7 +868,9 @@ export async function stop(): 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. + startNetldi: () => ensureProcesses(), confirmForce, log, }); diff --git a/src/lock.ts b/src/lock.ts index df669b5..5c8398a 100644 --- a/src/lock.ts +++ b/src/lock.ts @@ -496,9 +496,12 @@ 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; /** * Run `work` while holding the stone lock, waiting for another process to diff --git a/src/processes.ts b/src/processes.ts index f69d705..4ef2ce9 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,55 @@ 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)?.status === 'OK'; +} + +/** True when the listener is up and answering, the listener's half of {@link stoneReady}. */ +export function listenerReady(processes: EngineProcess[]): boolean { + return findNetldi(processes)?.status === 'OK'; +} + +/** + * Wait for a listed stone to finish starting. + * + * Returns at once for a stone that is ready. One this process did not start — + * a crash being recovered, or one an older GemDB started without waiting — is + * polled until it reports `OK`. 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. + */ +export async function waitForStoneReady( + report?: (message: string) => void, + wait: { pollMs?: number; timeoutMs?: number } = {}, +): Promise { + if (stoneReady(await listProcessesAsync())) return; + report?.('Waiting for the database to finish starting…'); + log('The database is still starting; waiting for it.'); + const stoneLog = path.join(databaseLogPath(), `${STONE_NAME}.log`); + const deadline = Date.now() + (wait.timeoutMs ?? STONE_LOCK_TIMEOUT_MS); + for (;;) { + await new Promise((resolve) => setTimeout(resolve, wait.pollMs ?? STONE_LOCK_POLL_MS)); + const running = await listProcessesAsync(); + if (stoneReady(running)) return; + if (!findStone(running)) { + throw new Error(`The database stopped while it was starting. See ${stoneLog}.`); + } + if (Date.now() > deadline) { + throw new Error(`The database has been starting for over a minute. See ${stoneLog}.`); + } + } +} + /** * 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,6 +240,81 @@ function requireOwnDatabase(action: string): void { ); } +/** + * 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, the + * GemDB Shell's, and the listener a declined force-stop puts back — 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'); + const started = await withStoneLock( + async () => { + let startedStone = false; + if (!findStone(await listProcessesAsync())) { + opts.beforeStoneStart?.(); + opts.report?.('Starting the database…'); + logStep('Starting the database'); + await runStartstone(); + startedStone = true; + } else { + log('The database is already running.'); + } + await waitForStoneReady(opts.report); + + let startedNetldi = false; + if (!findNetldi(await listProcessesAsync())) { + opts.report?.('Starting the session listener…'); + startedNetldi = await startNetldi(); + } else { + log('The session listener is already running.'); + } + return { startedStone, startedNetldi }; + }, + { + satisfied: async () => { + const running = await listProcessesAsync(); + return stoneReady(running) && listenerReady(running); + }, + }, + ); + return started ?? { startedStone: false, startedNetldi: false }; +} + +/** + * Start the stone alone, for what needs no session listener: the `gemdb` + * wrapper's file runs are linked sessions, and so are the tests that use this. + * Under the same lock as {@link ensureProcesses}. + */ export async function startStone(): Promise { requireOwnDatabase('start'); // Under the lock the generated `gemdb` wrapper also takes, because both @@ -202,35 +326,44 @@ export async function startStone(): Promise { async () => { if (isRunning()) { log('The database is already running; nothing to start.'); - return; - } - 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; + } else { + logStep(`Starting the database`); + await runStartstone(); } + await waitForStoneReady(); }, - { satisfied: isRunningAsync }, + { satisfied: async () => stoneReady(await listProcessesAsync()) }, ); } +/** + * 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; + } +} + /** * Whether the stone refused to start because its files are on NFS. * @@ -277,26 +410,48 @@ function fileSize(file: string): number { } } -export async function startNetldi(): Promise { - requireOwnDatabase('start'); +/** + * 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}, + * 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. One that is 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) { + if (!listenerReady(await listProcessesAsync())) throw e; + log('Another process started the session listener.'); + return false; + } } /**