diff --git a/.changeset/fix-log-subscription-and-startup-json.md b/.changeset/fix-log-subscription-and-startup-json.md new file mode 100644 index 0000000..4aa0d0e --- /dev/null +++ b/.changeset/fix-log-subscription-and-startup-json.md @@ -0,0 +1,5 @@ +--- +'@offckb/cli': patch +--- + +Restore foreground contract output for JSON-encoded TCP log notifications (#513), and emit startup settings diagnostics as NDJSON when `--json` is enabled (#518). diff --git a/src/devnet/log-subscription.ts b/src/devnet/log-subscription.ts index 2e9fd5d..bc2b809 100644 --- a/src/devnet/log-subscription.ts +++ b/src/devnet/log-subscription.ts @@ -71,10 +71,18 @@ export function parseSubscriptionMessage(line: string): { subscriptionId?: strin return { subscriptionId: message.result }; } - // Notification: {"jsonrpc":"2.0","method":"subscribe","params":{"result":{...entry},"subscription":""}} + // CKB may JSON-encode the log entry inside params.result; accept both + // that string payload and structured object payloads. if (message.method === 'subscribe' && message.params != null && typeof message.params === 'object') { const params = message.params as Record; - const result = params.result; + let result: unknown = params.result; + if (typeof result === 'string') { + try { + result = JSON.parse(result); + } catch { + return null; + } + } if (result != null && typeof result === 'object') { const entry = result as Record; if (typeof entry.message === 'string' && typeof entry.target === 'string') { diff --git a/src/util/logger.ts b/src/util/logger.ts index 8a6955e..c796dfb 100644 --- a/src/util/logger.ts +++ b/src/util/logger.ts @@ -305,8 +305,9 @@ class UnifiedLogger { } } -// Create a default instance for global use -const logger = UnifiedLogger.create({ showLevel: false }); +// Settings may be read during module initialization, before runCli enables +// JSON mode. Format those early diagnostics consistently with the CLI flag. +const logger = UnifiedLogger.create({ showLevel: false, jsonMode: process.argv.slice(2).includes('--json') }); export { logger, UnifiedLogger }; export type { LoggerOptions, LogLevel }; diff --git a/tests/cli-startup.test.ts b/tests/cli-startup.test.ts index ad1b66c..6c74c58 100644 --- a/tests/cli-startup.test.ts +++ b/tests/cli-startup.test.ts @@ -1,23 +1,117 @@ import { execFileSync, spawnSync } from 'child_process'; +import fs from 'fs'; +import os from 'os'; import path from 'path'; -it('starts the bundled CLI without deprecation warnings', () => { - const root = path.resolve(__dirname, '..'); +const root = path.resolve(__dirname, '..'); +const cliPath = path.join(root, 'build/index.js'); + +beforeAll(() => { // Build here because the test suite runs before the build step in CI. execFileSync(process.execPath, [path.join(root, 'scripts/build.js')], { cwd: root, timeout: 120000 }); +}, 120000); +function cleanEnv(): NodeJS.ProcessEnv { const env = { ...process.env }; delete env.NODE_OPTIONS; delete env.NODE_NO_WARNINGS; + return env; +} - const result = spawnSync( - process.execPath, - ['--pending-deprecation', '--throw-deprecation', path.join(root, 'build/index.js'), '--help'], - { cwd: root, env, encoding: 'utf8', timeout: 15000 }, - ); +it('starts the bundled CLI without deprecation warnings', () => { + const result = spawnSync(process.execPath, ['--pending-deprecation', '--throw-deprecation', cliPath, '--help'], { + cwd: root, + env: cleanEnv(), + encoding: 'utf8', + timeout: 15000, + }); expect(result.error).toBeUndefined(); expect(result.stderr).toBe(''); expect(result.status).toBe(0); expect(result.stdout).toContain('Usage: offckb'); -}, 120000); +}); + +it.each([ + ['invalid JSON', 'before'], + ['invalid JSON', 'after'], + ['unreadable', 'before'], + ['unreadable', 'after'], + ['invalid JSON', 'plain'], +])('formats startup diagnostics for %s settings with %s JSON flag', (condition, flagPosition) => { + const fixtureRoot = fs.realpathSync(fs.mkdtempSync(path.join(os.tmpdir(), 'offckb-cli-startup-'))); + const configDir = + process.platform === 'darwin' + ? path.join(fixtureRoot, 'Library', 'Preferences', 'offckb-nodejs') + : process.platform === 'win32' + ? path.join(fixtureRoot, 'offckb-nodejs', 'Config') + : path.join(fixtureRoot, 'config', 'offckb-nodejs'); + const configPath = path.join(configDir, 'settings.json'); + const preloadPath = path.join(fixtureRoot, 'isolate.cjs'); + const content = condition === 'invalid JSON' ? '{unfinished' : '{"bins":{"defaultCKBVersion":"0.203.0"}}'; + try { + fs.mkdirSync(configDir, { recursive: true }); + fs.writeFileSync(configPath, content); + // Isolate the child's macOS home, Windows app roots and Linux XDG roots. + // Inject EACCES only for settings reads so this also works on Windows/root CI. + fs.writeFileSync( + preloadPath, + `require('os').homedir = () => __dirname; +if (process.env.OFFCKB_TEST_DENY_SETTINGS === '1') { + const fs = require('fs'); + const readFileSync = fs.readFileSync; + fs.readFileSync = function(file, ...args) { + if (String(file) === process.env.OFFCKB_TEST_SETTINGS_PATH) { + throw Object.assign(new Error('EACCES: permission denied'), { code: 'EACCES' }); + } + return readFileSync.call(this, file, ...args); + }; +} +`, + ); + const args = ['config', 'set', 'proxy', 'http://127.0.0.1:19091']; + if (flagPosition === 'before') args.unshift('--json'); + if (flagPosition === 'after') args.push('--json'); + const result = spawnSync(process.execPath, ['--require', preloadPath, cliPath, ...args], { + cwd: root, + env: { + ...cleanEnv(), + APPDATA: fixtureRoot, + LOCALAPPDATA: fixtureRoot, + XDG_CONFIG_HOME: path.join(fixtureRoot, 'config'), + XDG_DATA_HOME: path.join(fixtureRoot, 'data'), + XDG_CACHE_HOME: path.join(fixtureRoot, 'cache'), + OFFCKB_TEST_DENY_SETTINGS: condition === 'unreadable' ? '1' : '0', + OFFCKB_TEST_SETTINGS_PATH: configPath, + }, + encoding: 'utf8', + timeout: 15000, + }); + + expect(result.error).toBeUndefined(); + expect(result.status).toBe(1); + expect(result.stdout).toBe(''); + expect(fs.readFileSync(configPath, 'utf8')).toBe(content); + if (flagPosition === 'plain') { + expect(result.stderr).toContain('Error reading settings:'); + expect(result.stderr).toContain(`Failed to read settings from ${configPath}`); + } else { + const records = result.stderr + .trim() + .split('\n') + .map((line) => JSON.parse(line)); + expect(records.slice(0, -1)).toEqual( + expect.arrayContaining([ + expect.objectContaining({ level: 'error', message: expect.stringContaining('Error reading settings:') }), + ]), + ); + expect(records.at(-1)).toEqual({ + ok: false, + code: 'COMMAND_FAILED', + message: expect.stringContaining(configPath), + }); + } + } finally { + fs.rmSync(fixtureRoot, { recursive: true, force: true }); + } +}); diff --git a/tests/log-subscription.test.ts b/tests/log-subscription.test.ts index 9193e23..19bfd09 100644 --- a/tests/log-subscription.test.ts +++ b/tests/log-subscription.test.ts @@ -43,28 +43,51 @@ describe('parseSubscriptionMessage', () => { }); }); - it('parses a log notification into an entry', () => { + it.each(['object', 'JSON string'])('parses a log notification with a %s result', (format) => { + const entry = { + message: + 'script group: Byte32(0xafa75b18ff86fe7e188169be16b3279833ceeb197b0d14abf23ff2b005199f8d) DEBUG OUTPUT: hello\nsecond line', + level: 'DEBUG', + target: 'ckb_script::verify', + date: '2026-07-29 11:40:01.500 +00:00', + }; const line = JSON.stringify({ jsonrpc: '2.0', method: 'subscribe', params: { - result: { - message: 'script group: 0xabcd DEBUG OUTPUT: hello', - level: 'DEBUG', - target: 'ckb-script', - date: '2026-07-29 11:40:01.500 +00:00', - }, + result: format === 'object' ? entry : JSON.stringify(entry), subscription: '0x49af', }, }); - expect(parseSubscriptionMessage(line)).toEqual({ - entry: { - message: 'script group: 0xabcd DEBUG OUTPUT: hello', - level: 'DEBUG', - target: 'ckb-script', - date: '2026-07-29 11:40:01.500 +00:00', - }, + expect(parseSubscriptionMessage(line)).toEqual({ entry }); + }); + + it.each(['object', 'JSON string'])('defaults optional fields for a %s result', (format) => { + const entry = { message: 'hello', target: 'ckb-script' }; + const line = JSON.stringify({ + jsonrpc: '2.0', + method: 'subscribe', + params: { result: format === 'object' ? entry : JSON.stringify(entry), subscription: '0xsub' }, }); + expect(parseSubscriptionMessage(line)).toEqual({ entry: { ...entry, level: '', date: '' } }); + }); + + it.each([ + 'not json', + '{"message":', + 'null', + 'true', + '42', + '[]', + '"another string"', + '{}', + '{"message":"hello"}', + '{"message":42,"target":"ckb-script"}', + '{"message":"hello","target":false}', + ])('ignores malformed or invalid encoded results: %s', (result) => { + expect( + parseSubscriptionMessage(JSON.stringify({ jsonrpc: '2.0', method: 'subscribe', params: { result } })), + ).toBeNull(); }); it('returns null for garbage and unrelated messages', () => { @@ -76,33 +99,37 @@ describe('parseSubscriptionMessage', () => { describe('subscribeToNodeLogs', () => { beforeEach(() => { mockConnect.mockReset(); - mockConnect.mockImplementation((...args: unknown[]) => - (realConnect as (...a: unknown[]) => net.Socket)(...args), - ); + mockConnect.mockImplementation((...args: unknown[]) => (realConnect as (...a: unknown[]) => net.Socket)(...args)); }); - it('subscribes over TCP and emits log entries until closed', async () => { + it.each(['object', 'JSON string'])('streams %s results over TCP until closed', async (format) => { + const entry = { + message: 'script group: Byte32(0xabcd) DEBUG OUTPUT: hello\nsecond line', + level: 'DEBUG', + target: 'ckb_script::verify', + date: '2026-07-29 11:40:01.500 +00:00', + }; const server = net.createServer((socket) => { socket.on('data', (data) => { const request = JSON.parse(data.toString().trim()); expect(request.method).toBe('subscribe'); expect(request.params).toEqual(['log']); socket.write(JSON.stringify({ jsonrpc: '2.0', result: '0xsub', id: request.id }) + '\n'); - socket.write( + // An invalid encoded result must not stop later valid notifications. + socket.write(JSON.stringify({ method: 'subscribe', params: { result: '{broken' } }) + '\n'); + const notification = JSON.stringify({ jsonrpc: '2.0', method: 'subscribe', params: { - result: { - message: 'hello', - level: 'DEBUG', - target: 'ckb-script', - date: '2026-07-29 11:40:01.500 +00:00', - }, + result: format === 'object' ? entry : JSON.stringify(entry), subscription: '0xsub', }, - }) + '\n', - ); + }) + '\n'; + // Exercise buffering across partial TCP reads as well as NDJSON framing. + const split = Math.floor(notification.length / 2); + socket.write(notification.slice(0, split)); + setTimeout(() => socket.write(notification.slice(split)), 10); }); }); await new Promise((resolve) => server.listen(0, '127.0.0.1', resolve)); @@ -121,9 +148,7 @@ describe('subscribeToNodeLogs', () => { server.close(); expect(errors).toEqual([]); - expect(entries).toEqual([ - { message: 'hello', level: 'DEBUG', target: 'ckb-script', date: '2026-07-29 11:40:01.500 +00:00' }, - ]); + expect(entries).toEqual([entry]); }); it('retries briefly then reports an error when the node is unreachable', async () => { @@ -147,10 +172,15 @@ describe('subscribeToNodeLogs', () => { const socket = new FakeSocket(); mockConnect.mockReturnValue(socket as unknown as net.Socket); const errors: Error[] = []; - const sub = subscribeToNodeLogs('127.0.0.1:18114', () => {}, (err) => errors.push(err), { - maxAttempts: 3, - retryDelayMs: 30, - }); + const sub = subscribeToNodeLogs( + '127.0.0.1:18114', + () => {}, + (err) => errors.push(err), + { + maxAttempts: 3, + retryDelayMs: 30, + }, + ); socket.emit('connect'); expect(socket.written.join('')).toContain('"subscribe"'); @@ -167,10 +197,15 @@ describe('subscribeToNodeLogs', () => { const socket = new FakeSocket(); mockConnect.mockReturnValue(socket as unknown as net.Socket); const clearTimeoutSpy = jest.spyOn(global, 'clearTimeout'); - const sub = subscribeToNodeLogs('127.0.0.1:18114', () => {}, () => {}, { - maxAttempts: 5, - retryDelayMs: 50, - }); + const sub = subscribeToNodeLogs( + '127.0.0.1:18114', + () => {}, + () => {}, + { + maxAttempts: 5, + retryDelayMs: 50, + }, + ); try { // The first attempt fails before ever connecting, so a retry is pending.