feat: log cluster module IPC via onelogger#120
Conversation
Add structured logging on every master<->app worker IPC point in Node.js cluster mode. Covers both application-layer messages and the internal NODE_CLUSTER fd dispatch / fd ack. Application layer (always on): - master->app send (messenger.sendToAppWorker) - master->app sticky-session Socket direct send (master.js) - master<-app recv (cluster.on 'fork' -> worker.on 'message') - app->master send (app_worker.js realport) - app<-master recv (process.on 'message') Internal cluster layer (opt-in via EGG_CLUSTER_IPC_LOG=1, very verbose): - master<-app internal (worker.process.on 'internalMessage'): online / listening / queryServer / accepted (fd ack) / close - app<-master internal (process.on 'internalMessage'): newconn (fd dispatch, with handle) / disconnect / suicide Users can replace the default console sink via onelogger.setLogger(). Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>
|
Important Review skippedAuto reviews are disabled on base/target branches other than the default branch. Please check the settings in the CodeRabbit UI or the ⚙️ Run configurationConfiguration used: defaults Review profile: CHILL Plan: Pro Run ID: You can disable this status message by setting the Use the checkbox below for a quick retry:
✨ Finishing Touches🧪 Generate unit tests (beta)
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
![gemini-code-assist[bot]](https://avatars.githubusercontent.com/in/956858?s=60&v=4){kind=small}
There was a problem hiding this comment.
Code Review
This pull request implements IPC message logging between the master and app workers using a new utility and the onelogger library. The feedback identifies performance bottlenecks related to eager and redundant JSON stringification, especially during message broadcasts, and suggests a more robust check for the environment variable that enables internal cluster logging.
| continue; | ||
| } | ||
| // A. master -> app (send) | ||
| ipcLogger.info(formatIpcMessage(`master->app#${worker.process.pid}`, data)); |
There was a problem hiding this comment.
Logging inside this loop is particularly expensive because formatIpcMessage (and its internal JSON.stringify) is called for every worker in the cluster. If a message is broadcast to many workers, the same data object is stringified repeatedly. This can cause significant CPU spikes in the Master process. It is recommended to pre-calculate the data string once outside the loop or use a more efficient logging strategy for broadcasts.
| * These are very verbose (one `cluster:newconn` per HTTP request), so they are opt-in | ||
| * via the `EGG_CLUSTER_IPC_LOG` environment variable (any truthy value enables). | ||
| */ | ||
| const internalIpcLogEnabled = !!process.env.EGG_CLUSTER_IPC_LOG; |
There was a problem hiding this comment.
The environment variable check !!process.env.EGG_CLUSTER_IPC_LOG will evaluate to true even if the variable is set to the string "0" or "false". In the context of environment variables, users often expect these values to disable a feature. It is safer to explicitly check for truthy values or exclude known falsy strings.
| const internalIpcLogEnabled = !!process.env.EGG_CLUSTER_IPC_LOG; | |
| const internalIpcLogEnabled = !!(process.env.EGG_CLUSTER_IPC_LOG && process.env.EGG_CLUSTER_IPC_LOG !== '0' && process.env.EGG_CLUSTER_IPC_LOG !== 'false'); |
| function stringifyData(data) { | ||
| let out; | ||
| try { | ||
| out = JSON.stringify(data, makeReplacer()); | ||
| } catch (err) { | ||
| return `<unserializable: ${err.message}>`; | ||
| } | ||
| if (out && out.length > MAX_TOTAL_LEN) { | ||
| out = `${out.slice(0, MAX_TOTAL_LEN)}...(truncated)`; | ||
| } | ||
| return out; | ||
| } |
There was a problem hiding this comment.
The stringifyData function eagerly performs JSON.stringify on the message data. Since this is called by formatIpcMessage before passing the result to ipcLogger.info, the stringification overhead is incurred for every IPC message even if the logger is configured to ignore INFO level messages. For the "always on" application layer logs (Points A, B, C, D), this could impact performance under high IPC load. Consider making these logs opt-in or using a lower log level like debug to minimize default overhead.
There was a problem hiding this comment.
Pull request overview
Adds structured IPC logging for Node.js cluster mode master↔app-worker communication in egg-cluster 1.x, using onelogger as the logging facade, with an opt-in path for very-verbose internal NODE_CLUSTER traffic.
Changes:
- Add
oneloggerdependency and introducelib/utils/ipc_logger.jsfor message formatting + safe serialization. - Instrument master→app sends (including sticky-session direct sends) and master←app receives with
ipcLoggeroutput. - Instrument app-worker side for app→master
realportsend, master→app receives, and optional internalNODE_CLUSTERmessages viaEGG_CLUSTER_IPC_LOG.
Reviewed changes
Copilot reviewed 5 out of 5 changed files in this pull request and generated 2 comments.
Show a summary per file
| File | Description |
|---|---|
| package.json | Adds onelogger dependency to support IPC logging facade. |
| lib/utils/ipc_logger.js | New helper for IPC log formatting + capped serialization and handle descriptors. |
| lib/utils/messenger.js | Logs master→app routed sends at the messenger layer. |
| lib/master.js | Logs sticky-session sends, app-worker message receives, and optional internal NODE_CLUSTER messages. |
| lib/app_worker.js | Logs master→app receives, app→master realport send, and optional internal NODE_CLUSTER messages. |
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
| if (internalIpcLogEnabled) { | ||
| worker.process.on('internalMessage', (msg, handle) => { | ||
| if (!msg || msg.cmd !== 'NODE_CLUSTER') return; | ||
| const label = msg.act ? `cluster:${msg.act}` : `cluster:ack#${msg.ack != null ? msg.ack : '?'}`; | ||
| ipcLogger.info(formatIpcMessage( | ||
| `master<-app#${worker.process.pid}`, | ||
| { action: label, data: msg }, | ||
| handle | ||
| )); | ||
| }); |
| function stringifyData(data) { | ||
| let out; | ||
| try { | ||
| out = JSON.stringify(data, makeReplacer()); | ||
| } catch (err) { | ||
| return `<unserializable: ${err.message}>`; | ||
| } | ||
| if (out && out.length > MAX_TOTAL_LEN) { | ||
| out = `${out.slice(0, MAX_TOTAL_LEN)}...(truncated)`; | ||
| } | ||
| return out; | ||
| } | ||
|
|
||
| /** | ||
| * Format a single IPC message into a one-line log string. | ||
| * @param {string} direction e.g. 'master->app#12345' / 'app#12345<-master' | ||
| * @param {Object} msg the message body (supports cluster internal msgs via `action: 'cluster:<act>'`) | ||
| * @param {*} [handle] optional handle (net.Socket / net.Server / TCP) attached to the IPC message | ||
| * @return {string} | ||
| */ | ||
| function formatIpcMessage(direction, msg, handle) { | ||
| const action = (msg && msg.action) || '<unknown>'; | ||
| let out = `[${direction}] action=${action}`; | ||
| if (msg && msg.data !== undefined) { | ||
| out += ` data=${stringifyData(msg.data)}`; | ||
| } | ||
| if (handle) { | ||
| out += ` +handle=${describeHandle(handle)}`; | ||
| } | ||
| return out; |
Summary
Add structured logging for every master↔app worker IPC point under Node.js
clustermode, using onelogger as the logger facade. Same feature as its v3 (master-branch) counterpart, ported to 1.x's plain JavaScriptlib/layout.Covers both layers of cluster IPC:
Application layer (always on)
lib/utils/messenger.jssendToAppWorker— all routed master→app sends (every worker in the loop)lib/master.jssticky-sessionworker.send('sticky-session:connection', connection)lib/master.jscluster.on('fork')→worker.on('message', (msg, handle) => ...); the log fires after forwarding to avoid adding serialization latency to the forward pathlib/app_worker.js— the single explicitprocess.send({action:'realport'})lib/app_worker.jsnewprocess.on('message', (msg, handle) => ...)Cluster internal layer (opt-in via
EGG_CLUSTER_IPC_LOG=1; very verbose —newconnfires once per HTTP request)online/listening/queryServer/accepted(fd ack) /close— viaworker.process.on('internalMessage')newconn(fd dispatch, handle=<TCP>) /disconnect/suicide— viaprocess.on('internalMessage')Note:
internalMessageis an undocumented Node.js event but has been stable across major versions. E/F hook onworker.process(ChildProcess) rather thancluster.Worker, since the latter does not forwardinternalMessage.Agent worker (
child_process.fork) is intentionally out of scope — not aclustermodule component.Users can replace the default console sink via
onelogger.setLogger()/setCustomLogger().formatIpcMessagehas a safe replacer:net.Socket/net.Server/ Buffer / circular refs are collapsed to tokens; long strings are truncated at 200 chars; whole JSON payload is capped at 1024 chars. Handles get a+handle=<Socket fd=N>/<TCP>/<Server>suffix.Sample output
With `EGG_CLUSTER_IPC_LOG=1` and a real HTTP request against the `egg-ready` fixture:
```
[egg-cluster:ipc] [master<-app#86211] action=cluster:online
[egg-cluster:ipc] [app#86211->master] action=realport data={"port":17011,"protocol":"http"}
[egg-cluster:ipc] [master<-app#86211] action=realport data={"port":17011,"protocol":"http"}
[egg-cluster:ipc] [master<-app#86211] action=cluster:queryServer
[egg-cluster:ipc] [app#86211<-master] action=cluster:ack#1 data={"cmd":"NODE_CLUSTER","ack":1,...,"sockname":{...}}
[egg-cluster:ipc] [master<-app#86211] action=cluster:listening
[egg-cluster:ipc] [master->app#86211] action=egg-ready data={...}
[egg-cluster:ipc] [app#86211<-master] action=egg-ready data={...}
[egg-cluster:ipc] [master<-app#86211] action=cluster:ack#1 data={"cmd":"NODE_CLUSTER","ack":1,"accepted":true} ← fd ack
[egg-cluster:ipc] [app#86211<-master] action=cluster:newconn ... +handle= ← fd dispatch
```
Notes for 1.x
Test plan
🤖 Generated with Claude Code