Repository navigation
fix(startup): print the banner as text, not as one JSON record per line - #1012
Conversation
🦋 Changeset detectedLatest commit: fb861f5 The changes in this PR will be included in the next version bump. This PR includes changesets to release 1 package
Not sure what this means? Click here to learn what changesets are. Click here if you're a maintainer who wants to add another changeset to this PR |
[Low impact] The PR appears safe to merge, with two non-blocking logging gaps worth fixing. Findings
|
Coverage Report for CI Build 41250216072Warning Build has drifted: This PR's base is out of sync with its target branch, so coverage data may include unrelated changes. Coverage increased (+0.02%) to 77.425%Details
Uncovered Changes
Coverage RegressionsNo coverage regressions found. Coverage Stats💛 - Coveralls |
cfe6c04 to
67658a7
Compare
| | 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) | |
There was a problem hiding this comment.
With NODE_ENV=development and LOG_FORMAT=json, only the startup record becomes JSON. src/logger.ts still sends normal logs through pino-pretty, so readers expecting JSON cannot parse those lines despite the documented promise. Make the logger honor LOG_FORMAT=json too, and test both settings together.
Note: If this suggestion doesn't match your team's coding style, reply to this and let me know. I'll remember it for next time!
| if (structuredLogs) { | ||
| return |
There was a problem hiding this comment.
Tor address disappears from logs
With LOG_FORMAT=json, logLine also drops the later Tor address message. The replacement startup record has no Tor address, and addOnion reports it only at debug level. At the default log level, operators lose the address previously printed at startup. Keep this later message as a JSON log instead of suppressing it with the artwork.
docker compose logs showed the logo escaped inside a single log record. The banner and its centred facts now go to stdout as text. Nothing is lost for a log pipeline: createLogger stringifies an object argument, so every other line in the file is text too. The process fake in app.spec grows a stdout, and the spec now pins that the banner reaches it as text.
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.
35263ff to
fb861f5
Compare
This PR was opened by the [Changesets release](https://github.com/changesets/action) GitHub action. When you're ready to do a release, you can merge this and the packages will be published to npm automatically. If you're not ready to do a release yet, that's fine, whenever you add more changesets to main, this PR will be updated. # Releases ## nostream@3.10.1 ### Patch Changes - [#1011](#1011) [`fd7679b`](fd7679b) Thanks [@chappie-daemon](https://github.com/chappie-daemon)! - fix(rate-limit): send the backoff the strategy actually means, name an outage as an error, and bucket messages by type Three defects on one wire path, from the spike in [#1004](#1004). **The EWMA backoff was a half-life, sent as a delay.** `RateLimit.period` is the decay half-life under `ewma`, so the time until a limit lifts is `period · log2(R_new / rate)`, not `period`. With `rate: 6, period: 60000`, a client four times over the limit was told to wait 60 s and needed 120 s. The Lua script now returns its score instead of a yes/no, and the limiter returns `period · log2(score / rate)`. It was only accidentally safe before: the hash carried a TTL of exactly `period`, so a quiet client's state expired anyway — an unstated coupling that would break the moment anyone lengthened the TTL to keep state warm. **A limiter outage was announced as `rate-limited`.** A failing backend made every connected client back off for a fault on this side. It now answers `error: rate limiter unavailable` and still rejects the event; fail-closed behaviour is unchanged. **The message bucket ignored the message type.** One bucket per client meant a `REQ` could be refused because its `EVENT`s had filled it — the wrong message throttled, and the wrong one told to back off. The bucket key now carries the type, read from a bounded prefix of the frame because the limiter runs before validation. `IRateLimiter.hit` returns `IRateLimiterResult` (`limited`, plus `retryAfterMs` when the strategy can estimate one) so each strategy answers in its own terms; a caller with no estimate keeps sending the period. - [#1012](#1012) [`d8095de`](d8095de) Thanks [@chappie-daemon](https://github.com/chappie-daemon)! - 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.
The startup banner went through
logger.info(...), so with JSON output the logo arrived inside one record with\nescapes:{"level":30,"scope":"primary:app-primary","msg":"\n ███▄ █ ▒█████ ██████ ▄▄▄█████▓ ██▀███ …"} {"level":30,"scope":"primary:app-primary","msg":" v3.10.0"}A banner is read by a person. The logo and its centred facts now go to stdout as plain text:
Notes
logger.infohere iscreateLogger, which turns an object argument into a formatted string before handing it to pino, so every other line in this file is text too — adding a "structured" record beside the banner would have been a string in amsgfield, not fields. I tried that first and dropped it.logCenteredusedlogger.info(' '.repeat(start), input)— a printf call with no placeholder. pino kept the extra argument, but relying on that was luck; the padding is now part of the string.src/utils/banner.ts(RELAY_BANNER_LINES,centre), testable without a database, a cluster or a settings document. Its spec pins that no line exceeds the 74-column block — a wrapped line turns the logo into noise — and that an overlong line is left alone rather than truncated.app.spec.ts'sfakeProcessgains astdout, and a new case pins thatrun()writes the banner there as text.Verification
test/unit/app/app.spec.ts— 7 passing, including the new banner casetest/unit/utils/banner.spec.ts— 4 passingsrc/app/app.tstype-checks; the banner renders as shown through a direct stdout writedocker compose logs nostreamLOG_FORMAT=jsonThe banner is for a person reading
docker compose logs. A log pipeline that requires every line to parse is the other audience, and it now has a switch: withLOG_FORMAT=jsonthe artwork is replaced by one record, written before any worker forks:{"level":30,"time":1793486578015,"pid":159864,"hostname":"cb6c98492fcc","msg":"relay starting","version":"3.10.0","supportedNips":[1,2,...],"payments":"disabled","eventStore":"postgres","clientWorkers":16,"maintenanceWorkers":1,"relayMonitor":false,"dvmWorkers":0}Observed on a real run of this branch:
LOG_FORMAT=json→ the line above, zero non-JSON lines; unset → the logo and its centred facts as text. Anything butjson(trimmed, case-insensitive) keeps the banner, so a typo fails towards the readable default. Documented inCONFIGURATION.md.The record is written through the same stdout writer as the banner rather than through
createLogger, for two reasons: the factory stringifies an object argument intomsgbefore pino sees it, so fields would be lost, and a test can then readstdoutinstead of reaching into a pino instance built at import time.