feat(startup): replace the banner with one record when LOG_FORMAT=json

A pipeline that insists every line parses cannot have a logo, and it cannot
have it silently: `LOG_FORMAT=json` now writes one `relay starting` record
carrying the banner's facts as fields (`version`, `supportedNips`, `payments`,
`eventStore`, `clientWorkers`, `maintenanceWorkers`, `relayMonitor`,
`dvmWorkers`), with pino's own `level`/`time`/`pid`/`hostname`, and suppresses
the centred lines that follow.

Anything else — unset, `pretty`, a typo — keeps the banner, because the person
reading `docker compose logs` is the default audience. The record is written
before any worker forks, so it opens the stream, and it shares the banner's
writer, so a test can read stdout instead of reaching into pino.

Author: chappie-daemon

.changeset/startup-banner-stdout.md

@@ -2,6 +2,8 @@
 'nostream': patch
 ---
 
-fix(startup): print the banner as text instead of one JSON record per line
+fix(startup): print the banner as text, and let `LOG_FORMAT=json` opt out of it
 
-`docker compose logs nostream` showed the logo as a single log record with the newlines escaped. The banner and its centred facts now go to stdout as text. Nothing is lost for a log pipeline: `createLogger` stringifies an object argument anyway, so every other line is text too — this one is simply printed where a person can read it.
+`docker compose logs nostream` showed the logo as a single log record with the newlines escaped. The banner and its centred facts now go to stdout as text.
+
+A pipeline that requires every line to parse sets `LOG_FORMAT=json`: the logo is then replaced by one `relay starting` record carrying the same facts as fields (`version`, `supportedNips`, `payments`, `eventStore`, `clientWorkers`, …). Any other value keeps the banner, which is what a person reading the logs wants.

CONFIGURATION.md

@@ -10,6 +10,7 @@ The following environment variables can be set:
 | RELAY_PORT                       | Relay's server port            | 8008                   |
 | RELAY_PRIVATE_KEY                | Relay's private key in hex     | (auto-generated)       |
 | WORKER_COUNT                     | Number of workers override     | No. of available CPUs  |
+| LOG_FORMAT                       | Set to `json` to replace the startup banner with one `relay starting` record, so every line the relay writes parses as JSON. | (banner) |
 | DB_URI                           | PostgreSQL URI (overrides DB_HOST, DB_PORT, etc.) | |
 | DB_HOST                          | PostgresSQL Hostname           |                        |
 | DB_PORT                          | PostgreSQL Port                | 5432                   |

src/app/app.ts

@@ -1,5 +1,6 @@
 import { Cluster, Worker } from 'cluster'
 import { cpus, hostname } from 'os'
+import { levels } from 'pino'
 import { path, pathEq } from 'ramda'
 import { FSWatcher } from 'fs'
 
@@ -11,7 +12,7 @@ import packageJson from '../../package.json'
 import { Serializable } from 'child_process'
 import { Settings } from '../@types/settings'
 import { SettingsStatic } from '../utils/settings'
-import { BANNER_WIDTH, centre, RELAY_BANNER_LINES } from '../utils/banner'
+import { BANNER_WIDTH, centre, isStructuredLogFormat, RELAY_BANNER_LINES } from '../utils/banner'
 import { shutdownMetricsTelemetry } from '../telemetry/metrics'
 import { OperatorNotificationEventType } from '../@types/operator-notifications'
 import { RedisRelayBroadcastFanout } from '../relay-broadcast/redis-relay-broadcast-fanout'
@@ -56,9 +57,14 @@ export class App implements IRunnable {
     this.watchers = SettingsStatic.watchSettings()
     // Plain text on stdout, not through the logger: in JSON output every line of
     // the logo arrived as its own record with the newlines escaped, which is not
-    // a logo. Nothing is lost for a log pipeline — `createLogger` stringifies an
-    // object argument anyway, so every other line in this file is text too.
+    // a logo. A pipeline that insists every line parse sets LOG_FORMAT=json and
+    // gets one record instead of artwork (see below).
+    const structuredLogs = isStructuredLogFormat(this.process.env.LOG_FORMAT)
     const logLine = (text: string) => {
+      if (structuredLogs) {
+        return
+      }
+
       this.process.stdout.write(`${text}\n`)
     }
 
@@ -102,6 +108,29 @@ export class App implements IRunnable {
       ? Number(process.env.WORKER_COUNT)
       : this.settings().workers?.count || cpus().length
 
+    // The structured form of the banner: the same facts as fields, written once
+    // and before any worker forks, so it opens the stream. The keys are pino's
+    // own so a pipeline reads this line like every other one.
+    if (structuredLogs) {
+      const dvmWorkerCount = Array.isArray(settings?.dvm?.workers) ? settings.dvm.workers.length : 0
+      this.process.stdout.write(`${JSON.stringify({
+        level: levels.values.info,
+        time: Date.now(),
+        pid: process.pid,
+        hostname: hostname(),
+        msg: 'relay starting',
+        version: packageJson.version,
+        supportedNips: packageJson.supportedNips,
+        payments: paymentsEnabled ? 'enabled' : 'disabled',
+        paymentsProvider: paymentsEnabled ? path(['payments', 'processor'], settings) : undefined,
+        eventStore: eventStoreBackend,
+        clientWorkers: workerCount,
+        maintenanceWorkers: 1,
+        relayMonitor: settings.nip66?.enabled === true,
+        dvmWorkers: dvmWorkerCount,
+      })}\n`)
+    }
+
     const createWorker = (env: Record<string, string>) => {
       const workerEnv = { ...env, [EVENT_STORE_BACKEND_ENV]: eventStoreBackend }
       const worker = this.cluster.fork(workerEnv)

src/utils/banner.ts

@@ -25,3 +25,12 @@ export const RELAY_BANNER_LINES: readonly string[] = [
  */
 export const centre = (line: string, width: number = BANNER_WIDTH): string =>
   ' '.repeat(Math.max(0, (width - line.length) >> 1)) + line
+
+/**
+ * `LOG_FORMAT=json` promises a stream in which every line parses as JSON. The
+ * banner cannot keep that promise, so it is replaced by one record carrying the
+ * same facts. Anything else — unset, `pretty`, a typo — keeps the banner: the
+ * person reading `docker compose logs` is the default audience.
+ */
+export const isStructuredLogFormat = (format: string | undefined): boolean =>
+  (format ?? '').trim().toLowerCase() === 'json'

test/unit/app/app.spec.ts

@@ -175,6 +175,49 @@ describe('App', () => {
     expect(written).not.to.include('{"level"')
   })
 
+  // LOG_FORMAT=json promises a stream in which every line parses. The logo
+  // cannot keep that promise, so it becomes one record with the same facts.
+  it('writes one structured record instead of the banner when LOG_FORMAT=json', () => {
+    sandbox.stub(SettingsStatic, 'watchSettings').returns([])
+    sandbox.stub(operatorNotificationEnqueue, 'enqueueOperatorNotification').resolves()
+    sandbox.stub(torClient, 'addOnion').rejects(new Error('tor is not configured'))
+    let pid = 2001
+    cluster.fork.callsFake(() => createWorker(String(pid), pid++))
+    fakeProcess.env = { LOG_FORMAT: 'json' }
+    const app = new App(
+      fakeProcess as any,
+      cluster as any,
+      sandbox.stub().returns({
+        payments: { enabled: false },
+        workers: { count: 1 },
+        eventStore: { backend: 'postgres' },
+      } as Settings),
+    )
+
+    app.run()
+
+    const lines = fakeProcess.stdout.write.getCalls()
+      .map((call) => String(call.args[0]).trim())
+      .filter(Boolean)
+
+    expect(lines).to.have.lengthOf(1)
+
+    const record = JSON.parse(lines[0])
+
+    expect(record).to.include({
+      level: 30,
+      msg: 'relay starting',
+      payments: 'disabled',
+      eventStore: 'postgres',
+      clientWorkers: 1,
+      maintenanceWorkers: 1,
+      relayMonitor: false,
+      dvmWorkers: 0,
+    })
+    expect(record.version).to.match(/^\d+\.\d+\.\d+/)
+    expect(record.time).to.be.a('number')
+  })
+
   it('hands every worker, re-forked ones included, the event store resolved at startup', async () => {
     // run() reads both from process.env
     const env = { ...process.env }

test/unit/utils/banner.spec.ts

@@ -1,6 +1,6 @@
 import { expect } from 'chai'
 
-import { BANNER_WIDTH, centre, RELAY_BANNER_LINES } from '../../../src/utils/banner'
+import { BANNER_WIDTH, centre, isStructuredLogFormat, RELAY_BANNER_LINES } from '../../../src/utils/banner'
 
 describe('startup banner', () => {
   // The banner is printed to stdout as text. A line wider than the block would
@@ -31,4 +31,18 @@ describe('startup banner', () => {
 
     expect(centre(exact)).to.equal(exact)
   })
+
+  // LOG_FORMAT=json is a promise made to a log pipeline, so it is read strictly:
+  // an unrecognised value falls back to the banner a person can read.
+  it('reads LOG_FORMAT=json, trimmed and case-insensitively', () => {
+    expect(isStructuredLogFormat('json')).to.equal(true)
+    expect(isStructuredLogFormat(' JSON ')).to.equal(true)
+  })
+
+  it('keeps the banner for anything else', () => {
+    expect(isStructuredLogFormat(undefined)).to.equal(false)
+    expect(isStructuredLogFormat('')).to.equal(false)
+    expect(isStructuredLogFormat('pretty')).to.equal(false)
+    expect(isStructuredLogFormat('jsonlines')).to.equal(false)
+  })
 })