fix(startup): print the banner as text, not as one JSON record per line

.changeset/startup-banner-stdout.md

@@ -0,0 +1,9 @@
+---
+'nostream': patch
+---
+
+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.
+
+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,6 +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, 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'
@@ -53,30 +55,32 @@ export class App implements IRunnable {
   public run(): void {
     const settings = this.settings()
     this.watchers = SettingsStatic.watchSettings()
-    logger.info(`
- ███▄    █  ▒█████    ██████ ▄▄▄█████▓ ██▀███  ▓█████ ▄▄▄       ███▄ ▄███▓
- ██ ▀█   █ ▒██▒  ██▒▒██    ▒ ▓  ██▒ ▓▒▓██ ▒ ██▒▓█   ▀▒████▄    ▓██▒▀█▀ ██▒
-▓██  ▀█ ██▒▒██░  ██▒░ ▓██▄   ▒ ▓██░ ▒░▓██ ░▄█ ▒▒███  ▒██  ▀█▄  ▓██    ▓██░
-▓██▒  ▐▌██▒▒██   ██░  ▒   ██▒░ ▓██▓ ░ ▒██▀▀█▄  ▒▓█  ▄░██▄▄▄▄██ ▒██    ▒██
-▒██░   ▓██░░ ████▓▒░▒██████▒▒  ▒██▒ ░ ░██▓ ▒██▒░▒████▒▓█   ▓██▒▒██▒   ░██▒
-░ ▒░   ▒ ▒ ░ ▒░▒░▒░ ▒ ▒▓▒ ▒ ░  ▒ ░░   ░ ▒▓ ░▒▓░░░ ▒░ ░▒▒   ▓▒█░░ ▒░   ░  ░
-░ ░░   ░ ▒░  ░ ▒ ▒░ ░ ░▒  ░ ░    ░      ░▒ ░ ▒░ ░ ░  ░ ▒   ▒▒ ░░  ░      ░
-   ░   ░ ░ ░ ░ ░ ▒  ░  ░  ░    ░        ░░   ░    ░    ░   ▒   ░      ░
-         ░     ░ ░        ░              ░        ░  ░     ░  ░       ░`)
-    const width = 74
+    // 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. 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`)
+    }
+
+    logLine(RELAY_BANNER_LINES.join('\n'))
+
+    const width = BANNER_WIDTH
     const torHiddenServicePort = process.env.HIDDEN_SERVICE_PORT ? Number(process.env.HIDDEN_SERVICE_PORT) : 80
     const port = process.env.RELAY_PORT ? Number(process.env.RELAY_PORT) : 8008
 
-    const logCentered = (input: string, width: number) => {
-      const start = Math.max(0, (width - input.length) >> 1)
-      logger.info(' '.repeat(start), input)
-    }
-    logCentered(`v${packageJson.version}`, width)
-    logCentered(`NIPs implemented: ${packageJson.supportedNips}`, width)
+    const logCentered = (input: string) => logLine(centre(input, width))
+    logCentered(`v${packageJson.version}`)
+    logCentered(`NIPs implemented: ${packageJson.supportedNips}`)
     const paymentsEnabled = pathEq(['payments', 'enabled'], true, settings)
-    logCentered(`Pay-to-relay ${paymentsEnabled ? 'enabled' : 'disabled'}`, width)
+    logCentered(`Pay-to-relay ${paymentsEnabled ? 'enabled' : 'disabled'}`)
     if (paymentsEnabled) {
-      logCentered(`Payments provider: ${path(['payments', 'processor'], settings)}`, width)
+      logCentered(`Payments provider: ${path(['payments', 'processor'], settings)}`)
     }
 
     if (
@@ -98,12 +102,35 @@ export class App implements IRunnable {
       this.process.exit(1)
       return
     }
-    logCentered(`Event store: ${eventStoreBackend}`, width)
+    logCentered(`Event store: ${eventStoreBackend}`)
 
     const workerCount = process.env.WORKER_COUNT
       ? 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)
@@ -117,25 +144,25 @@ export class App implements IRunnable {
         WORKER_INDEX: i.toString(),
       })
     }
-    logCentered(`${workerCount} client workers started`, width)
+    logCentered(`${workerCount} client workers started`)
 
     createWorker({
       WORKER_TYPE: 'maintenance',
     })
 
-    logCentered('1 maintenance worker started', width)
+    logCentered('1 maintenance worker started')
     if (Array.isArray(settings?.mirroring?.static) && settings.mirroring.static.length) {
       logger.warn(
         'mirroring.static is no longer supported and is ignored; sync with another relay over NIP-77 (negentropy) instead',
       )
-      logCentered('mirroring.static is no longer supported (ignored)', width)
+      logCentered('mirroring.static is no longer supported (ignored)')
     }
 
     if (settings.nip66?.enabled) {
       createWorker({
         WORKER_TYPE: 'relay-monitor',
       })
-      logCentered('1 relay-monitor worker started', width)
+      logCentered('1 relay-monitor worker started')
     }
 
     const dvmWorkers = settings?.dvm?.workers
@@ -147,7 +174,7 @@ export class App implements IRunnable {
           DVM_WORKER_INDEX: i.toString(),
         })
       }
-      logCentered(`${dvmWorkers.length} dvm-orchestrator worker started`, width)
+      logCentered(`${dvmWorkers.length} dvm-orchestrator worker started`)
     }
 
     logger('settings: %O', settings)
@@ -159,7 +186,7 @@ export class App implements IRunnable {
         .start((message) => this.onRelayBroadcastFromPeer(message))
         .then(() => {
           setRelayBroadcastFanoutReady(true)
-          logCentered('Relay broadcast fan-out enabled (Redis stream)', width)
+          logCentered('Relay broadcast fan-out enabled (Redis stream)')
         })
         .catch((error) => {
           setRelayBroadcastFanoutReady(false)
@@ -177,10 +204,10 @@ export class App implements IRunnable {
     const host = `${hostname()}:${port}`
     addOnion(torHiddenServicePort, host).then(
       (value) => {
-        logCentered(`Tor hidden service: ${value}:${torHiddenServicePort}`, width)
+        logCentered(`Tor hidden service: ${value}:${torHiddenServicePort}`)
       },
       () => {
-        logCentered('Tor hidden service: disabled', width)
+        logCentered('Tor hidden service: disabled')
       },
     )
   }

src/utils/banner.ts

@@ -0,0 +1,36 @@
+// The startup banner is read by a human in `docker compose logs`, so it is
+// composed here as text and written to stdout: through the logger it arrives as
+// one JSON object per line with the newlines escaped, which is not a logo, and
+// pino is for records rather than for artwork.
+//
+// Kept out of App so the shape can be tested without a database, a cluster or a
+// settings document.
+export const BANNER_WIDTH = 74
+
+export const RELAY_BANNER_LINES: readonly string[] = [
+  ' ███▄    █  ▒█████    ██████ ▄▄▄█████▓ ██▀███  ▓█████ ▄▄▄       ███▄ ▄███▓',
+  ' ██ ▀█   █ ▒██▒  ██▒▒██    ▒ ▓  ██▒ ▓▒▓██ ▒ ██▒▓█   ▀▒████▄    ▓██▒▀█▀ ██▒',
+  '▓██  ▀█ ██▒▒██░  ██▒░ ▓██▄   ▒ ▓██░ ▒░▓██ ░▄█ ▒▒███  ▒██  ▀█▄  ▓██    ▓██░',
+  '▓██▒  ▐▌██▒▒██   ██░  ▒   ██▒░ ▓██▓ ░ ▒██▀▀█▄  ▒▓█  ▄░██▄▄▄▄██ ▒██    ▒██',
+  '▒██░   ▓██░░ ████▓▒░▒██████▒▒  ▒██▒ ░ ░██▓ ▒██▒░▒████▒▓█   ▓██▒▒██▒   ░██▒',
+  '░ ▒░   ▒ ▒ ░ ▒░▒░▒░ ▒ ▒▓▒ ▒ ░  ▒ ░░   ░ ▒▓ ░▒▓░░░ ▒░ ░▒▒   ▓▒█░░ ▒░   ░  ░',
+  '░ ░░   ░ ▒░  ░ ▒ ▒░ ░ ░▒  ░ ░    ░      ░▒ ░ ▒░ ░ ░  ░ ▒   ▒▒ ░░  ░      ░',
+  '   ░   ░ ░ ░ ░ ░ ▒  ░  ░  ░    ░        ░░   ░    ░    ░   ▒   ░      ░',
+  '         ░     ░ ░        ░              ░        ░  ░     ░  ░       ░',
+]
+
+/**
+ * Centres one line of the banner block. A line longer than the width is returned
+ * unpadded rather than truncated: half a logo is worse than a wide one.
+ */
+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

@@ -17,7 +17,12 @@ const { expect } = chai
 
 describe('App', () => {
   let sandbox: Sinon.SinonSandbox
-  let fakeProcess: EventEmitter & { exit: Sinon.SinonStub; on: Sinon.SinonStub; env: NodeJS.ProcessEnv }
+  let fakeProcess: EventEmitter & {
+    exit: Sinon.SinonStub
+    on: Sinon.SinonStub
+    env: NodeJS.ProcessEnv
+    stdout: { write: Sinon.SinonStub }
+  }
   let cluster: EventEmitter & {
     on: Sinon.SinonStub
     workers: Record<string, any>
@@ -49,7 +54,14 @@ describe('App', () => {
       exit: sandbox.stub(),
       on: sandbox.stub().returnsThis(),
       env: {},
-    }) as EventEmitter & { exit: Sinon.SinonStub; on: Sinon.SinonStub; env: NodeJS.ProcessEnv }
+      // The banner is written straight to stdout, so the process fake needs one.
+      stdout: { write: sandbox.stub() },
+    }) as EventEmitter & {
+      exit: Sinon.SinonStub
+      on: Sinon.SinonStub
+      env: NodeJS.ProcessEnv
+      stdout: { write: Sinon.SinonStub }
+    }
 
     cluster = Object.assign(new EventEmitter(), {
       on: sandbox.stub().returnsThis(),
@@ -136,6 +148,76 @@ describe('App', () => {
     expect(cluster.fork).not.to.have.been.called
   })
 
+  // The banner is for a person reading `docker compose logs`: plain text on
+  // stdout, never a log record with the newlines escaped.
+  it('writes the banner to stdout as text, not through the logger', () => {
+    sandbox.stub(SettingsStatic, 'watchSettings').returns([])
+    sandbox.stub(operatorNotificationEnqueue, 'enqueueOperatorNotification').resolves()
+    sandbox.stub(torClient, 'addOnion').rejects(new Error('tor is not configured'))
+    let pid = 1001
+    cluster.fork.callsFake(() => createWorker(String(pid), pid++))
+    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 written = fakeProcess.stdout.write.getCalls().map((call) => call.args[0]).join('')
+
+    expect(written).to.include('███▄    █  ▒█████')
+    expect(written).to.match(/v\d+\.\d+\.\d+/)
+    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

@@ -0,0 +1,48 @@
+import { expect } from 'chai'
+
+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
+  // wrap in a terminal and turn the logo into noise.
+  it('fits every line inside the banner width', () => {
+    for (const line of RELAY_BANNER_LINES) {
+      expect(line.length, line).to.be.at.most(BANNER_WIDTH)
+    }
+  })
+
+  it('centres a short line', () => {
+    const padded = centre('v1.2.3')
+
+    expect(padded).to.equal(' '.repeat((BANNER_WIDTH - 6) >> 1) + 'v1.2.3')
+    expect(padded.trimEnd()).to.equal(padded)
+  })
+
+  // Half a logo is worse than a wide one, so an overlong line is left alone
+  // rather than cut to fit.
+  it('never truncates a line longer than the width', () => {
+    const long = 'x'.repeat(BANNER_WIDTH + 10)
+
+    expect(centre(long)).to.equal(long)
+  })
+
+  it('pads nothing when the line is exactly the width', () => {
+    const exact = 'x'.repeat(BANNER_WIDTH)
+
+    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)
+  })
+})