-
-
Notifications
You must be signed in to change notification settings - Fork 1.8k
feat(cluster): log cluster module IPC via onelogger #5872
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
base: next
Are you sure you want to change the base?
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change | ||||||||||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
|
|
@@ -8,6 +8,7 @@ import { debuglog } from 'node:util'; | |||||||||||||||||||||
| import { importModule } from '@eggjs/utils'; | ||||||||||||||||||||||
| import { EggConsoleLogger as ConsoleLogger } from 'egg-logger'; | ||||||||||||||||||||||
|
|
||||||||||||||||||||||
| import { ipcLogger, formatIpcMessage, internalIpcLogEnabled } from './utils/ipc_logger.ts'; | ||||||||||||||||||||||
| import { BaseAppWorker } from './utils/mode/base/app.ts'; | ||||||||||||||||||||||
| import { AppProcessWorker } from './utils/mode/impl/process/app.ts'; | ||||||||||||||||||||||
| import { AppThreadWorker } from './utils/mode/impl/worker_threads/app.ts'; | ||||||||||||||||||||||
|
|
@@ -48,6 +49,25 @@ async function main() { | |||||||||||||||||||||
| AppWorker = AppThreadWorker as any; | ||||||||||||||||||||||
| } else { | ||||||||||||||||||||||
| AppWorker = AppProcessWorker as any; | ||||||||||||||||||||||
| // D. master -> app (recv): log every IPC message delivered to this worker via the cluster channel. | ||||||||||||||||||||||
| // Handle is present when master forwards a net.Socket (sticky-session mode). | ||||||||||||||||||||||
| // Read-only listener; other `process.on('message')` listeners (framework, sticky handler, etc.) | ||||||||||||||||||||||
| // are unaffected. | ||||||||||||||||||||||
| process.on('message', (msg: any, handle: any) => { | ||||||||||||||||||||||
| const body = typeof msg === 'string' ? { action: msg } : msg; | ||||||||||||||||||||||
| ipcLogger.info(formatIpcMessage(`app#${process.pid}<-master`, body, handle)); | ||||||||||||||||||||||
| }); | ||||||||||||||||||||||
|
Comment on lines
+56
to
+59
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. This IPC listener is always active and performs logging on every message received from the master. To avoid performance issues in production, this should be guarded by an opt-in check similar to the internal messages below.
Suggested change
|
||||||||||||||||||||||
|
|
||||||||||||||||||||||
| // F. master -> app internal NODE_CLUSTER messages (newconn with fd, disconnect, suicide, ...). | ||||||||||||||||||||||
| // `internalMessage` is an undocumented but stable Node.js event. | ||||||||||||||||||||||
| // Opt-in via EGG_CLUSTER_IPC_LOG because `newconn` fires once per HTTP request. | ||||||||||||||||||||||
| if (internalIpcLogEnabled) { | ||||||||||||||||||||||
| process.on('internalMessage', (msg: { cmd?: string; act?: string; ack?: number }, handle: unknown) => { | ||||||||||||||||||||||
| if (!msg || msg.cmd !== 'NODE_CLUSTER') return; | ||||||||||||||||||||||
| const label = msg.act ? `cluster:${msg.act}` : `cluster:ack#${msg.ack ?? '?'}`; | ||||||||||||||||||||||
| ipcLogger.info(formatIpcMessage(`app#${process.pid}<-master`, { action: label, data: msg }, handle)); | ||||||||||||||||||||||
| }); | ||||||||||||||||||||||
| } | ||||||||||||||||||||||
| } | ||||||||||||||||||||||
|
|
||||||||||||||||||||||
| const consoleLogger = new ConsoleLogger({ | ||||||||||||||||||||||
|
|
||||||||||||||||||||||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -15,6 +15,7 @@ import terminalLink from 'terminal-link'; | |
| import { readJSONSync } from 'utility'; | ||
|
|
||
| import { ClusterWorkerExceptionError } from './error/ClusterWorkerExceptionError.ts'; | ||
| import { ipcLogger, formatIpcMessage } from './utils/ipc_logger.ts'; | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. |
||
| import { Messenger } from './utils/messenger.ts'; | ||
| import { AgentProcessWorker, AgentProcessUtils as ProcessAgentWorker } from './utils/mode/impl/process/agent.ts'; | ||
| import { AppProcessWorker, AppProcessUtils as ProcessAppWorker } from './utils/mode/impl/process/app.ts'; | ||
|
|
@@ -291,6 +292,11 @@ export class Master extends ReadyEventEmitter { | |
| connection.destroy(); | ||
| } else { | ||
| const worker = this.stickyWorker(connection.remoteAddress) as AppProcessWorker; | ||
| // A'. master -> app sticky-session direct send (bypasses AppProcessWorker#send), | ||
| // carries a net.Socket handle — safe-printed by formatIpcMessage's replacer. | ||
| ipcLogger.info( | ||
| formatIpcMessage(`master->app#${worker.workerId}`, { action: 'sticky-session:connection' }, connection), | ||
| ); | ||
|
Comment on lines
+297
to
+299
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
Comment on lines
+295
to
+299
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Gate sticky-session connection logs behind the verbose flag. This runs on the accept path before 🤖 Prompt for AI Agents |
||
| worker.instance.send('sticky-session:connection', connection); | ||
| } | ||
| }, | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,86 @@ | ||
| import net from 'node:net'; | ||
|
|
||
| import { getLogger } from 'onelogger'; | ||
|
|
||
| import type { MessageBody } from './messenger.ts'; | ||
|
|
||
| /** | ||
| * onelogger instance for Node.js cluster module IPC traffic between master and app workers. | ||
| * Users can override the underlying sink via `onelogger.setLogger()` / `setCustomLogger()`. | ||
| */ | ||
| export const ipcLogger = getLogger('egg/cluster/ipc'); | ||
|
|
||
| /** | ||
| * Whether internal-level cluster IPC logs (NODE_CLUSTER newconn/accepted/listening/...) are enabled. | ||
| * 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). | ||
| */ | ||
| export const internalIpcLogEnabled = !!process.env.EGG_CLUSTER_IPC_LOG; | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. The 'Application layer' IPC logging (Points A, B, C, D) is currently always enabled. Since formatIpcMessage performs a JSON.stringify on every message, this introduces significant performance overhead and event loop blocking in high-throughput scenarios. It is highly recommended to make all IPC logging opt-in via an environment variable (e.g., EGG_CLUSTER_IPC_LOG) to prevent unexpected performance degradation in production.
Comment on lines
+13
to
+18
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Parse
🤖 Prompt for AI Agents |
||
|
|
||
| const MAX_STRING_LEN = 200; | ||
| const MAX_TOTAL_LEN = 1024; | ||
|
|
||
| function describeHandle(handle: unknown): string { | ||
| if (handle == null) return ''; | ||
| if (handle instanceof net.Socket) { | ||
| const fd = (handle as unknown as { _handle?: { fd?: number } })._handle?.fd; | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. |
||
| return fd != null ? `<Socket fd=${fd}>` : '<Socket>'; | ||
| } | ||
| if (handle instanceof net.Server) { | ||
| return '<Server>'; | ||
| } | ||
| const ctor = (handle as { constructor?: { name?: string } })?.constructor?.name; | ||
| return ctor ? `<${ctor}>` : '<handle>'; | ||
| } | ||
|
|
||
| function makeReplacer() { | ||
| const seen = new WeakSet<object>(); | ||
| return function replacer(_key: string, value: unknown) { | ||
| if (value && typeof value === 'object') { | ||
| if (seen.has(value as object)) return '<Circular>'; | ||
| seen.add(value as object); | ||
| if (value instanceof net.Socket) return describeHandle(value); | ||
| if (value instanceof net.Server) return '<Server>'; | ||
| if (Buffer.isBuffer(value)) return `<Buffer len=${value.length}>`; | ||
| } | ||
| if (typeof value === 'string' && value.length > MAX_STRING_LEN) { | ||
| return `${value.slice(0, MAX_STRING_LEN)}...(truncated)`; | ||
| } | ||
| return value; | ||
| }; | ||
| } | ||
|
|
||
| function stringifyData(data: unknown): string { | ||
| let out: string; | ||
| try { | ||
| out = JSON.stringify(data, makeReplacer()); | ||
| } catch (err) { | ||
|
Comment on lines
+53
to
+57
|
||
| return `<unserializable: ${(err as Error).message}>`; | ||
| } | ||
| if (out && out.length > MAX_TOTAL_LEN) { | ||
| out = `${out.slice(0, MAX_TOTAL_LEN)}...(truncated)`; | ||
| } | ||
|
Comment on lines
+60
to
+62
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Truncating the stringified output after JSON.stringify has completed does not prevent the initial memory allocation and CPU usage required to serialize a potentially massive object. If data is very large, this could lead to performance degradation or even Out-of-Memory (OOM) issues before the truncation occurs. Consider implementing a more efficient way to limit serialization depth or size. |
||
| return out; | ||
|
Comment on lines
+53
to
+63
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Do not serialize arbitrary IPC payloads into always-on logs. This formatter emits As per coding guidelines: "Never expose sensitive configuration values in logs or error messages". Also applies to: 72-80 🤖 Prompt for AI Agents |
||
| } | ||
|
|
||
| /** | ||
| * Format a single IPC message into a one-line log string. | ||
| * @param direction e.g. 'master->app#12345' / 'app#12345<-master' | ||
| * @param 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 | ||
| */ | ||
| export function formatIpcMessage( | ||
| direction: string, | ||
| msg: Partial<MessageBody> & { action?: string; data?: unknown }, | ||
| handle?: unknown, | ||
| ): string { | ||
| const action = msg?.action ?? '<unknown>'; | ||
| let out = `[${direction}] action=${action}`; | ||
| if (msg && msg.data !== undefined) { | ||
| out += ` data=${stringifyData(msg.data)}`; | ||
| } | ||
|
Comment on lines
+79
to
+81
|
||
| if (handle) { | ||
| out += ` +handle=${describeHandle(handle)}`; | ||
| } | ||
| return out; | ||
| } | ||
| Original file line number | Diff line number | Diff line change | ||||||||
|---|---|---|---|---|---|---|---|---|---|---|
|
|
@@ -5,6 +5,7 @@ import { cfork } from 'cfork'; | |||||||||
| import { graceful as gracefulExit, type Options as gracefulExitOptions } from 'graceful-process'; | ||||||||||
| import { sendmessage } from 'sendmessage'; | ||||||||||
|
|
||||||||||
| import { ipcLogger, formatIpcMessage, internalIpcLogEnabled } from '../../../ipc_logger.ts'; | ||||||||||
| import type { MessageBody } from '../../../messenger.ts'; | ||||||||||
| import { terminate } from '../../../terminate.ts'; | ||||||||||
| import { BaseAppWorker, BaseAppUtils } from '../../base/app.ts'; | ||||||||||
|
|
@@ -29,6 +30,7 @@ export class AppProcessWorker extends BaseAppWorker<ClusterProcessWorker> { | |||||||||
| } | ||||||||||
|
|
||||||||||
| send(message: MessageBody): void { | ||||||||||
| ipcLogger.info(formatIpcMessage(`master->app#${this.workerId}`, message)); | ||||||||||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. |
||||||||||
| sendmessage(this.instance, message); | ||||||||||
| } | ||||||||||
|
|
||||||||||
|
|
@@ -48,6 +50,7 @@ export class AppProcessWorker extends BaseAppWorker<ClusterProcessWorker> { | |||||||||
|
|
||||||||||
| static send(message: MessageBody): void { | ||||||||||
| message.senderWorkerId = String(process.pid); | ||||||||||
| ipcLogger.info(formatIpcMessage(`app#${process.pid}->master`, message)); | ||||||||||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Logging every message sent from app to master in the hot path will introduce latency. This should be guarded by an opt-in check.
Suggested change
|
||||||||||
| // cluster won't get `listening` event when reusePort is true, | ||||||||||
| // use cluster `message` event instead | ||||||||||
| if (message.action === 'app-start' && message.reusePort) { | ||||||||||
|
|
@@ -90,7 +93,10 @@ export class AppProcessUtils extends BaseAppUtils { | |||||||||
| const appWorker = new AppProcessWorker(worker); | ||||||||||
| this.emit('worker_forked', appWorker); | ||||||||||
| appWorker.disableRefork = true; | ||||||||||
| worker.on('message', (msg) => { | ||||||||||
| // B. master <- app (recv). Handle is present when master receives a net.Socket | ||||||||||
| // (e.g. forwarded sticky-session connection). | ||||||||||
| // Log AFTER forwarding to avoid adding log-serialization latency to the forward path. | ||||||||||
| worker.on('message', (msg, handle) => { | ||||||||||
| if (typeof msg === 'string') { | ||||||||||
| msg = { | ||||||||||
| action: msg, | ||||||||||
|
|
@@ -99,7 +105,21 @@ export class AppProcessUtils extends BaseAppUtils { | |||||||||
| } | ||||||||||
| msg.from = 'app'; | ||||||||||
| this.messenger.send(msg); | ||||||||||
| ipcLogger.info(formatIpcMessage(`master<-app#${worker.process.pid}`, msg, handle)); | ||||||||||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. |
||||||||||
| }); | ||||||||||
|
|
||||||||||
| // E. cluster internal NODE_CLUSTER messages from worker to master: | ||||||||||
| // listening / online / queryServer / accepted (fd ack) / close / ... | ||||||||||
| // Must hook on `worker.process` (ChildProcess) — `cluster.Worker` doesn't forward `internalMessage`. | ||||||||||
| // `internalMessage` is undocumented but stable across Node.js versions. | ||||||||||
| // Opt-in via EGG_CLUSTER_IPC_LOG because this is verbose under load. | ||||||||||
| if (internalIpcLogEnabled) { | ||||||||||
| worker.process.on('internalMessage', (msg: { cmd?: string; act?: string; ack?: number }, handle: unknown) => { | ||||||||||
| if (!msg || msg.cmd !== 'NODE_CLUSTER') return; | ||||||||||
| const label = msg.act ? `cluster:${msg.act}` : `cluster:ack#${msg.ack ?? '?'}`; | ||||||||||
| ipcLogger.info(formatIpcMessage(`master<-app#${worker.process.pid}`, { action: label, data: msg }, handle)); | ||||||||||
| }); | ||||||||||
| } | ||||||||||
| this.log( | ||||||||||
| '[master] app_worker#%s:%s start, state: %s, current workers: %j', | ||||||||||
| appWorker.id, | ||||||||||
|
|
||||||||||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This repo uses pnpm catalog mode and already defines
oneloggerin the workspace catalog; this package should reference it via"catalog:"(consistent with the other deps here) instead of hard-coding^1.0.1, to keep dependency versions centralized.