fix: restore foreground script logs and JSON startup diagnostics

.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).

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":"<id>"}}
+  // 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<string, unknown>;
-    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<string, unknown>;
       if (typeof entry.message === 'string' && typeof entry.target === 'string') {

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 };

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 });
+  }
+});

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<void>((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.