From 9285f70e1ec53eed9c4aad6c6e8e71e5f2ff2b7a Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 3 Aug 2026 20:06:17 +0000 Subject: [PATCH] fix(objectql): tell an identical driver re-registration apart from a real name collision (#4773) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Every showcase boot logged `WARN Driver already registered, skipping {"driverName":"com.objectstack.driver.sql"}`. Traced end to end, the default datasource is registered twice on two legs of one round trip, with the SAME object instance both times: 1. DatasourceConnectionService.attemptConnect() registers the driver it built (isDefault: true), driven by DefaultDatasourcePlugin.init(); 2. that plugin republishes the instance it read back out of the engine as the `driver.` kernel service, and ObjectQLPlugin.start()'s `driver.*` discovery loop bridges it back in (isDefault: false). Nothing is decided and nothing is discarded, so that re-entry now logs at `debug`. It is not a blanket downgrade: the same warn also covered two DIFFERENT instances claiming one name, where "skipping" silently drops one of two configurations. Those are now split by object identity — identical re-entry is quiet, a collision still warns and names which config was kept and which was discarded, and a dropped `isDefault` request warns rather than vanishing. Registration behaviour is unchanged: first registration still wins. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01NrmBxj8rK2uGCnh9aipjwX --- .changeset/driver-double-registration-log.md | 45 ++++++ .../src/engine-driver-registration.test.ts | 147 ++++++++++++++++++ packages/objectql/src/engine.ts | 64 +++++++- packages/objectql/src/plugin.ts | 12 +- .../src/default-datasource-plugin.test.ts | 60 +++++++ 5 files changed, 324 insertions(+), 4 deletions(-) create mode 100644 .changeset/driver-double-registration-log.md create mode 100644 packages/objectql/src/engine-driver-registration.test.ts diff --git a/.changeset/driver-double-registration-log.md b/.changeset/driver-double-registration-log.md new file mode 100644 index 0000000000..fc928510e6 --- /dev/null +++ b/.changeset/driver-double-registration-log.md @@ -0,0 +1,45 @@ +--- +"@objectstack/objectql": patch +--- + +fix(objectql): a re-registered driver stops crying wolf, and a real name collision starts saying what it cost (#4773) + +Every boot printed one line into `⚠ Boot diagnostics`: + +``` +WARN Driver already registered, skipping {"driverName":"com.objectstack.driver.sql"} +``` + +It was never an anomaly. The standalone `default` datasource is registered +twice, on two legs of one round trip, and traced end to end it is the **same +object instance** both times: + +1. `DatasourceConnectionService.attemptConnect()` builds the default driver and + registers it (`isDefault: true`), driven by `DefaultDatasourcePlugin.init()`; +2. that plugin republishes the instance it just read back out of the engine as + the `driver.` kernel service — the surface `os migrate` and serve's + storage detection resolve the primary DB through — and + `ObjectQLPlugin.start()`'s `driver.*` discovery loop bridges every such + service into the engine, handing back the driver it already holds. + +Nothing is decided and nothing is discarded, so `registerDriver` now reports +that at `debug`. A no-anomaly line on every single boot does not belong at +`warn`; it only teaches operators that `warn` means nothing. + +The reason this is not a blanket downgrade: the same `warn` also covered the +case that genuinely matters — **two different driver instances claiming one +name**, where "skipping" silently drops one of two configurations (connection +string, pool, tenant scoping, capability set) while every query bound to that +name keeps working against the winner. The two are now told apart by object +identity: + +- **same instance** → `debug`, nothing happened; +- **different instance under a held name** → still `warn`, now naming which + configuration was KEPT and which was DISCARDED (with both versions) so the + operator can tell what is actually in force; +- **same instance re-registered with `isDefault` while another driver holds + that role** → `warn`, because the caller's intent is otherwise dropped in + silence. + +Registration behaviour is unchanged in all three cases — first registration +still wins. Only which of them is worth an operator's attention changed. diff --git a/packages/objectql/src/engine-driver-registration.test.ts b/packages/objectql/src/engine-driver-registration.test.ts new file mode 100644 index 0000000000..8e7cdca40b --- /dev/null +++ b/packages/objectql/src/engine-driver-registration.test.ts @@ -0,0 +1,147 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. +// +// framework#4773: every showcase boot logged +// `WARN Driver already registered, skipping {"driverName":"com.objectstack.driver.sql"}`. +// +// The diagnosis: the standalone `default` datasource is registered twice, on +// two legs of ONE round trip, with the SAME object instance both times — +// `DatasourceConnectionService.attemptConnect()` registers the driver it built +// (isDefault: true), `DefaultDatasourcePlugin.init()` republishes that same +// instance as the `driver.` kernel service, and `ObjectQLPlugin.start()`'s +// `driver.*` discovery loop bridges it back in (isDefault: false). Nothing is +// decided and nothing is discarded, so a `warn` on every boot was pure noise — +// and worse, it was indistinguishable from the case that DOES matter: two +// DIFFERENT drivers claiming one name, where "skipping" silently drops one of +// two configurations. +// +// These tests pin the split: identical re-entry is quiet, real divergence is +// loud. Deleting the split would make both cases warn again (the #4773 noise) +// or both cases quiet (a silently-adopted config, strictly worse). + +import { describe, it, expect } from 'vitest'; +import { ObjectQL } from './engine.js'; + +type Record_ = { level: string; message: string; meta?: Record }; + +/** Captures every record the engine logs, at every level. */ +function makeCapturingLogger() { + const records: Record_[] = []; + const push = (level: string) => (message: string, meta?: Record) => { + records.push({ level, message, meta }); + }; + const logger: any = { + debug: push('debug'), + info: push('info'), + warn: push('warn'), + error: push('error'), + fatal: push('fatal'), + child: () => logger, + }; + return { logger, records }; +} + +/** Minimal IDataDriver stub — only identity/name/version matter here. */ +function makeDriver(name: string, version = '1.0.0') { + const driver: any = { + name, + version, + supports: {}, + async connect() {}, async disconnect() {}, async checkHealth() { return true; }, + async execute() { return null; }, + async find() { return []; }, + async findOne() { return null; }, + async create(_o: string, data: Record) { return { id: 'r_1', ...data }; }, + async update(_o: string, id: string, data: Record) { return { ...data, id }; }, + async delete() { return true; }, + async count() { return 0; }, + async bulkCreate() { return []; }, + async bulkUpdate() { return []; }, + async bulkDelete() {}, + async beginTransaction() { return { __trx: true, commit: async () => {}, rollback: async () => {} }; }, + async commit() {}, async rollback() {}, + }; + return driver; +} + +const warnsAbout = (records: Record_[], driverName: string) => + records.filter((r) => r.level === 'warn' && r.meta?.driverName === driverName); + +describe('ObjectQL.registerDriver — identical re-entry vs. real name collision (#4773)', () => { + it('re-registering the SAME instance is quiet: debug, never warn', () => { + const { logger, records } = makeCapturingLogger(); + const engine = new ObjectQL({ logger }); + const driver = makeDriver('com.objectstack.driver.sql'); + + engine.registerDriver(driver, true); + // The `driver.*` discovery loop's leg: same object, no default claim. + engine.registerDriver(driver); + + expect(warnsAbout(records, 'com.objectstack.driver.sql')).toEqual([]); + const debugs = records.filter((r) => r.level === 'debug' && r.meta?.driverName === 'com.objectstack.driver.sql'); + expect(debugs).toHaveLength(1); + expect(debugs[0]!.message).toMatch(/same instance is a no-op/); + }); + + it('the quiet re-entry changes nothing: the first registration still stands', () => { + const { logger } = makeCapturingLogger(); + const engine = new ObjectQL({ logger }); + const driver = makeDriver('com.objectstack.driver.sql'); + + engine.registerDriver(driver, true); + engine.registerDriver(driver); + + expect(engine.getDriverByName('com.objectstack.driver.sql')).toBe(driver); + expect(engine.getDefaultDriverName()).toBe('com.objectstack.driver.sql'); + }); + + it('a DIFFERENT instance under a held name stays LOUD and names which config survived', () => { + const { logger, records } = makeCapturingLogger(); + const engine = new ObjectQL({ logger }); + const kept = makeDriver('com.objectstack.driver.sql', '1.0.0'); + const discarded = makeDriver('com.objectstack.driver.sql', '2.0.0'); + + engine.registerDriver(kept, true); + engine.registerDriver(discarded); + + const warns = warnsAbout(records, 'com.objectstack.driver.sql'); + expect(warns).toHaveLength(1); + // The operator must be able to tell WHICH of the two configurations is in + // force without reading the source — that is the whole cost of a collision. + expect(warns[0]!.message).toMatch(/collision/i); + expect(warns[0]!.message).toMatch(/KEEPING/); + expect(warns[0]!.message).toMatch(/DISCARDING/); + expect(warns[0]!.meta).toMatchObject({ keptVersion: '1.0.0', discardedVersion: '2.0.0' }); + // First-wins is unchanged behaviour — only the reporting got sharper. + expect(engine.getDriverByName('com.objectstack.driver.sql')).toBe(kept); + }); + + it('a dropped `isDefault` request stays LOUD — the intent is silently lost otherwise', () => { + const { logger, records } = makeCapturingLogger(); + const engine = new ObjectQL({ logger }); + const first = makeDriver('driver.a'); + const second = makeDriver('driver.b'); + + engine.registerDriver(first, true); + engine.registerDriver(second); + // Same instance, but now asking for a role another driver already holds. + engine.registerDriver(second, true); + + const warns = warnsAbout(records, 'driver.b'); + expect(warns).toHaveLength(1); + expect(warns[0]!.message).toMatch(/IGNORED/); + expect(warns[0]!.meta).toMatchObject({ currentDefault: 'driver.a' }); + expect(engine.getDefaultDriverName()).toBe('driver.a'); + }); + + it('a same-instance re-entry that re-asserts an ALREADY-held default stays quiet', () => { + const { logger, records } = makeCapturingLogger(); + const engine = new ObjectQL({ logger }); + const driver = makeDriver('com.objectstack.driver.sql'); + + engine.registerDriver(driver, true); + engine.registerDriver(driver, true); + + expect(warnsAbout(records, 'com.objectstack.driver.sql')).toEqual([]); + expect(engine.getDefaultDriverName()).toBe('com.objectstack.driver.sql'); + }); +}); diff --git a/packages/objectql/src/engine.ts b/packages/objectql/src/engine.ts index 400ddde561..044099b02b 100644 --- a/packages/objectql/src/engine.ts +++ b/packages/objectql/src/engine.ts @@ -2020,11 +2020,69 @@ export class ObjectQL implements IObjectQLEngine { } /** - * Register a new storage driver + * Register a new storage driver. + * + * **Re-registering the SAME driver instance is by design, not an anomaly** + * (#4773). Every standalone boot does it exactly once, on two legs of one + * round trip: + * + * 1. `DatasourceConnectionService.attemptConnect()` builds the `default` + * datasource's driver and registers it here with `isDefault: true` + * (`service-datasource/src/datasource-connection-service.ts`), driven by + * `DefaultDatasourcePlugin.init()`; + * 2. that plugin then republishes **the very object it just read back out of + * this engine** as the `driver.` kernel service — the surface + * `os migrate` and serve's storage detection resolve the primary DB + * through — and `ObjectQLPlugin.start()`'s `driver.*` discovery loop + * bridges every such service into the engine, handing us back the + * instance we already hold. + * + * So this guard has to answer two different questions, and the whole point of + * splitting it is that they deserve different voices: + * + * - **Same instance** → leg 2 above. Nothing is decided and nothing is + * discarded, and it happens on every boot: `debug`. Reporting a + * no-anomaly, every-boot event at `warn` only teaches operators that + * `warn` means nothing, which is what makes the next real one unreadable + * (the degradation-log-level rule, #4632). + * - **A DIFFERENT driver under a name we already hold** → two distinct + * configurations claim one name and exactly one of them is silently + * dropped. Whatever the loser carried — connection string, pool, tenant + * scoping, capability set — is simply not in force, while every query + * bound to that name keeps working against the winner. That is a real + * caller-side defect and stays loud, now saying *which* config survived. + * - **Same instance, but the caller asked for `isDefault` and something + * else already is the default** → the caller's intent is being dropped, + * so it is loud too rather than folded into the quiet path. */ registerDriver(driver: IDataDriver, isDefault: boolean = false) { - if (this.drivers.has(driver.name)) { - this.logger.warn('Driver already registered, skipping', { driverName: driver.name }); + const existing = this.drivers.get(driver.name); + if (existing) { + if (existing !== driver) { + this.logger.warn( + 'Driver name collision — KEEPING the already-registered driver and DISCARDING the one just supplied. ' + + 'Two different driver instances claim one name, so whatever configuration the discarded instance carried ' + + '(connection string, pool, capabilities) is NOT in force, while queries routed to this name keep working ' + + 'against the one that was kept. Fix the caller: give the second datasource a name of its own.', + { + driverName: driver.name, + keptVersion: existing.version, + discardedVersion: driver.version, + }, + ); + } else if (isDefault && this.defaultDriver !== driver.name) { + this.logger.warn( + 'Driver re-registered as DEFAULT but another driver already holds that role — the request is IGNORED and ' + + 'the existing default stands. Unregister the current default first if the switch was intended.', + { driverName: driver.name, currentDefault: this.defaultDriver }, + ); + } else { + // The by-design round trip documented above — expected on every boot, + // so it must not reach the boot-diagnostics warning list. + this.logger.debug('Driver already registered — re-registering the same instance is a no-op', { + driverName: driver.name, + }); + } return; } diff --git a/packages/objectql/src/plugin.ts b/packages/objectql/src/plugin.ts index 12d783e94c..c60c739d87 100644 --- a/packages/objectql/src/plugin.ts +++ b/packages/objectql/src/plugin.ts @@ -432,7 +432,17 @@ export class ObjectQLPlugin implements Plugin { const services = ctx.getServices(); for (const [name, service] of services.entries()) { if (name.startsWith('driver.')) { - // Register Driver + // Register Driver. + // + // For the standalone `default` this is the SECOND leg of a + // round trip, not a new registration (#4773): + // `DefaultDatasourcePlugin.init()` already registered the + // driver through `DatasourceConnectionService`, then + // republished that same instance as this `driver.` + // service for `os migrate` / serve storage detection. Handing + // it back is a deliberate no-op — see `registerDriver`, which + // distinguishes this identical re-entry (quiet) from a real + // name collision between two different instances (loud). this.ql.registerDriver(service); ctx.logger.debug('Discovered and registered driver service', { serviceName: name }); } diff --git a/packages/runtime/src/default-datasource-plugin.test.ts b/packages/runtime/src/default-datasource-plugin.test.ts index 414ce912f0..1cbf1ae37a 100644 --- a/packages/runtime/src/default-datasource-plugin.test.ts +++ b/packages/runtime/src/default-datasource-plugin.test.ts @@ -228,6 +228,66 @@ describe('DefaultDatasourcePlugin — the default datasource as a declaration (# expect(disconnects).toBe(0); }, BOOT_TIMEOUT); + it('registers the default driver TWICE with the same instance, and says nothing about it (#4773)', async () => { + // The round trip this pins: DefaultDatasourcePlugin.init() connects the + // driver through DatasourceConnectionService (registerDriver, isDefault: + // true), then republishes THAT instance as the `driver.` kernel + // service, and ObjectQLPlugin.start()'s `driver.*` discovery loop bridges + // it straight back in (registerDriver, isDefault: false). Every boot logged + // `WARN Driver already registered, skipping` for it — a no-anomaly line in + // the boot diagnostics of every single `pnpm dev`. + // + // Both halves are asserted on purpose: the warning count alone would stay + // green if the second registration simply stopped happening, which is a + // different change with different consequences (the `driver.*` bridge is + // what a pre-built DriverPlugin relies on). + const { ObjectQL } = await import('@objectstack/objectql'); + const registrations: Array<{ name: string; instance: unknown; isDefault: boolean }> = []; + const originalRegister = ObjectQL.prototype.registerDriver; + ObjectQL.prototype.registerDriver = function (driver: any, isDefault = false) { + registrations.push({ name: driver?.name, instance: driver, isDefault }); + return originalRegister.call(this, driver, isDefault); + }; + // ObjectLogger writes straight to `process.stdout` in Node (console is only + // its browser fallback), and `serve`'s boot-quiet window intercepts exactly + // this stream — so this is the same bytes the `⚠ Boot diagnostics` block + // replays. Capturing `console.warn` instead would see nothing and pass + // vacuously. + const stdoutLines: string[] = []; + const originalWrite = process.stdout.write.bind(process.stdout); + (process.stdout as any).write = (chunk: any, ...rest: any[]) => { + stdoutLines.push(String(chunk)); + return (originalWrite as any)(chunk, ...rest); + }; + + const kernel = await assemble({}); + try { + await kernel.bootstrap(); + const engine = kernel.getService('data'); + const defaultName = engine.getDefaultDriverName!()!; + + // (a) it really is registered twice, with ONE object — object identity, + // not merely an equal configuration. + const forDefault = registrations.filter((r) => r.name === defaultName); + expect(forDefault).toHaveLength(2); + expect(forDefault[0]!.isDefault).toBe(true); + expect(forDefault[1]!.isDefault).toBe(false); + expect(forDefault[1]!.instance).toBe(forDefault[0]!.instance); + // …and the second leg is the `driver.*` service bridge, same instance again. + expect(kernel.getService(`driver.${defaultName}`)).toBe(engine.getDriverByName!(defaultName)); + + // (b) that round trip is silent — no boot-diagnostics warning. + const driverWarns = stdoutLines.filter( + (l) => /\bWARN\b/.test(l) && /already registered|Driver name collision/i.test(l), + ); + expect(driverWarns).toEqual([]); + } finally { + (process.stdout as any).write = originalWrite; + ObjectQL.prototype.registerDriver = originalRegister; + try { await (kernel as any)?.stop?.(); } catch { /* noop */ } + } + }, BOOT_TIMEOUT); + it("rejects an app bundle that declares a datasource named 'default' (host-reserved name)", async () => { const kernel = await assemble({ bundle: {