-
Notifications
You must be signed in to change notification settings - Fork 15
Stop emitting legacy metric/status logs #668
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
Draft
silvadenisaraujo
wants to merge
3
commits into
master
Choose a base branch
from
aerie/stop-emitting-legacy-metric-status-logs
base: master
Could not load branches
Branch not found: {{ refName }}
Loading
Could not load tags
Nothing to show
Loading
Are you sure you want to change the base?
Some commits from the old base branch may be removed from the timeline,
and old review comments may become outdated.
Draft
Changes from all commits
Commits
Show all changes
3 commits
Select commit
Hold shift + click to select a range
File filter
Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
There are no files selected for viewing
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,260 @@ | ||
| # Stop emitting legacy metric/status logs | ||
|
|
||
| Internal task id: task-ac9cfeec (bean) | ||
|
|
||
| ## Context & problem | ||
|
|
||
| VTEX IO Node apps emit a legacy status-tracking log stream that is no longer | ||
| actively consumed. On every cluster-wide `/_status` tick, the master broadcasts | ||
| a `statusTrack` message to each worker; each worker runs `trackStatus()`, which | ||
| flushes the in-memory `MetricsAccumulator` and prints **one `console.log` line | ||
| per flushed metric**, each tagged `type: 'metric/status'` and wrapped in a | ||
| `__VTEX_IO_LOG` envelope. These lines are indexed into `io_vtex_logs` | ||
| (query: `* AND vtex.search_index:="io_vtex_logs" AND type:="metric/status"`) | ||
| and add up to roughly **10 million indexed log entries per hour** across the | ||
| fleet, for a stream nobody reads. | ||
|
|
||
| The sole emitter is `logStatus` in `src/service/worker/runtime/statusTrack.ts`, | ||
| invoked for every value returned by `global.metrics.statusTrack()`: | ||
|
|
||
| ```50:60:src/service/worker/runtime/statusTrack.ts | ||
| const logStatus = (status: EnvMetric) => console.log(JSON.stringify({ | ||
| __VTEX_IO_LOG: true, | ||
| account: ACCOUNT, | ||
| app: APP.ID, | ||
| isLink: LINKED, | ||
| pid: process.pid, | ||
| production: PRODUCTION, | ||
| status, | ||
| type: 'metric/status', | ||
| workspace: WORKSPACE, | ||
| })) | ||
| ``` | ||
|
|
||
| ```36:44:src/service/worker/runtime/statusTrack.ts | ||
| export const trackStatus = () => { | ||
| // Update diagnostics metrics (gauges for HTTP agent stats) | ||
| HttpAgentSingleton.updateHttpAgentMetrics() | ||
|
|
||
| // Legacy status tracking (console.log export) | ||
| global.metrics.statusTrack().forEach(status => { | ||
| logStatus(status) | ||
| }) | ||
| } | ||
| ``` | ||
|
|
||
| `global.metrics.statusTrack()` calls `MetricsAccumulator.flushMetrics()` | ||
| (`src/metrics/MetricsAccumulator.ts:116`), which **drains** the accumulated | ||
| metric batches and returns them. This flush must keep happening: it is what | ||
| prevents batched legacy metrics from accumulating unbounded in worker memory. | ||
| The diagnostics HTTP-agent gauge refresh (`HttpAgentSingleton.updateHttpAgentMetrics()`) | ||
| must also keep happening, since it feeds the OpenTelemetry `http_agent_*` | ||
| gauges exposed through the diagnostics pipeline. | ||
|
|
||
| ### What must NOT change | ||
| - The `/_status` route handler (`statusTrackHandler`) and the | ||
| `broadcastStatusTrack` / `statusTrack` IPC flow between master and workers. | ||
| - Prometheus `/metrics` output (prom-client, including its independent cluster | ||
| aggregation). | ||
| - `__VTEX_IO_LOG` application logs emitted elsewhere (structured app logging). | ||
| - `__VTEX_IO_BILLING` process-time logs. | ||
| - Diagnostics metrics (`http_agent_*` gauges and everything else via | ||
| `global.diagnosticsMetrics`). | ||
|
|
||
| ## Decisions (reviewer feedback resolution) | ||
|
|
||
| ### Is the `trackStatus()` / IPC flow used only for logging? — No; keep it. | ||
|
|
||
| > Reviewer (silvadenisaraujo, `specs/...md:69`): "it is not clear if we will | ||
| > remove only the console.log. If we use all this process and IPC communication | ||
| > for only logging the status I want you to remove it as well; if it is used by | ||
| > other processes we must keep it." | ||
|
|
||
| We traced the flow end-to-end. **The IPC path is shared infrastructure, not a | ||
| logging-only channel**, so we remove **only** the `console.log` export | ||
| (`logStatus`) and keep the entire route → IPC → flush/gauge machinery. | ||
|
|
||
| Full flow (each hop verified in source): | ||
|
|
||
| 1. `/_status` route → `statusTrackHandler` (worker, | ||
| `src/service/worker/runtime/statusTrack.ts:27`): on a non-linked worker it | ||
| sends `broadcastStatusTrack` to the master and returns an empty body. | ||
| 2. master `onMessage` (`src/service/master.ts:15-17`): on `broadcastStatusTrack` | ||
| it calls `trackStatus()` **in the master process** and then | ||
| `broadcastStatusTrack()` to fan a `statusTrack` message out to every worker. | ||
| 3. each worker `onMessage` (`src/service/worker/index.ts:79-80`): on | ||
| `statusTrack` it calls `trackStatus()` **in that worker process**. | ||
|
|
||
| `trackStatus()` has two side effects, **both of which are used by systems other | ||
| than logging and therefore must be preserved**: | ||
|
|
||
| - **`HttpAgentSingleton.updateHttpAgentMetrics()`** — refreshes the diagnostics | ||
| `http_agent_*` gauges (OpenTelemetry / `global.diagnosticsMetrics`). This is an | ||
| observability side effect, unrelated to the legacy log. | ||
| - **`global.metrics.statusTrack()` → `MetricsAccumulator.flushMetrics()`** | ||
| (`src/metrics/MetricsAccumulator.ts:116` and `:143`) — this **drains** | ||
| `metricsMillis`/`extensions` (so batched metrics do not grow unbounded in | ||
| worker memory) **and runs every registered `onFlushMetrics` callback** | ||
| (`addOnFlushMetric`, `:108`). These are real state-mutating side effects that | ||
| exist regardless of whether the return value is logged. | ||
|
|
||
| **Conclusion:** removing the whole `trackStatus()` / IPC path would (a) stop the | ||
| diagnostics HTTP-agent gauge refresh and (b) let the accumulator's batched | ||
| metrics and `onFlushMetrics` state accumulate unbounded — both explicitly | ||
| disallowed. So the process/IPC communication is **kept**, and only the | ||
| console.log export is deleted. This is exactly the scope of this task. | ||
|
|
||
| ### Sonar quality gate on the spec PR (#668) | ||
|
|
||
| The failing gate (315 new issues, 30.10% coverage on new code, 0% security | ||
| hotspots reviewed) is measured against a spec-only diff and does not reflect the | ||
| implementation: | ||
|
|
||
| - **This phase commits only the spec `.md` file** — no production code or tests | ||
| change here, so "coverage on new code" is not meaningful for a docs-only diff. | ||
| It is resolved in the implementation phase. | ||
| - The implementation is a **net removal** (delete `logStatus` and its | ||
| now-orphaned imports; make `trackStatus()` call `statusTrack()` and discard | ||
| the result). Removing code introduces no new branches/paths, so it should add | ||
| no new issues, and the focused `statusTrack.test.ts` (below) exercises the | ||
| changed lines to keep coverage on the changed code high. | ||
| - No secrets or security-sensitive code are added, so there are **no new | ||
| security hotspots** to review. | ||
|
|
||
| ## Proposed approach | ||
|
|
||
| Remove **only** the console-log export from `trackStatus()` while preserving | ||
| every side effect that other systems depend on: | ||
|
|
||
| 1. Delete the private `logStatus` helper (it has no other callers; it is not | ||
| exported). | ||
| 2. In `trackStatus()`, keep calling `HttpAgentSingleton.updateHttpAgentMetrics()` | ||
| exactly once, and keep calling `global.metrics.statusTrack()` exactly once, | ||
| but **discard its return value** instead of iterating and logging it. The | ||
| call is retained purely for its flushing side effect. | ||
| 3. Remove the now-unused imports that were only used by `logStatus` | ||
| (`ACCOUNT`, `APP`, `PRODUCTION`, `WORKSPACE` from `../../../constants`, and | ||
| `LINKED` **only if** it is no longer referenced elsewhere in the file). | ||
| Note: `LINKED` is still used by `statusTrackHandler`, so it stays. | ||
| `EnvMetric` / `NamedMetric` / `StatusTrack` type exports stay — they are | ||
| imported by `src/metrics/MetricsAccumulator.ts` and are part of the public | ||
| surface. | ||
|
|
||
| Resulting shape (illustrative, not final code): | ||
|
|
||
| ```ts | ||
| export const trackStatus = () => { | ||
| // Refresh diagnostics gauges for HTTP agent stats. | ||
| HttpAgentSingleton.updateHttpAgentMetrics() | ||
|
|
||
| // Flush accumulated legacy metric batches so they do not grow unbounded | ||
| // in memory. The result is intentionally discarded: the legacy | ||
| // `type: metric/status` console.log export has been removed. | ||
| global.metrics.statusTrack() | ||
| } | ||
| ``` | ||
|
|
||
| ## Files / components to change | ||
|
|
||
| | File | Change | | ||
| |------|--------| | ||
| | `src/service/worker/runtime/statusTrack.ts` | Remove `logStatus`; make `trackStatus()` call `statusTrack()` and discard the result; drop imports only used by `logStatus`. | | ||
| | `src/service/worker/runtime/statusTrack.test.ts` (new) | Focused unit test for the three `trackStatus()` behaviors. | | ||
| | `docs/METRICS_CATALOG.md` | Update the visual-summary node and the `MetricsAccumulator` section so they no longer describe values as `console.log` exports; document that status ticks flush and discard them. | | ||
|
|
||
| Explicitly **not** changed: `src/service/master.ts`, `src/service/worker/index.ts` | ||
| (callers of `trackStatus()`), `statusTrackHandler`, `broadcastStatusTrack`, | ||
| `isStatusTrack`, `isStatusTrackBroadcast`, `MetricsAccumulator`, prom-client | ||
| setup, billing logs. | ||
|
|
||
| ## How each AC line will be satisfied | ||
|
|
||
| - **AC: `trackStatus()` emits no `console.log` containing `type: metric/status`.** | ||
| The `logStatus` helper (the only source of that line) is deleted and no longer | ||
| called. Test spies on `console.log` and asserts no call's argument matches | ||
| `type":"metric/status"`. | ||
|
|
||
| - **AC: `trackStatus()` invokes `global.metrics.statusTrack()` exactly once.** | ||
| The single retained call flushes legacy batches. Test mocks | ||
| `global.metrics.statusTrack` and asserts it is called exactly once. | ||
|
|
||
| - **AC: `trackStatus()` invokes `HttpAgentSingleton.updateHttpAgentMetrics()` | ||
| exactly once.** The call is kept as-is. Test spies/mocks the static method and | ||
| asserts exactly one invocation. | ||
|
|
||
| - **AC: A focused automated test covers the three behaviors above.** | ||
| New `statusTrack.test.ts` asserts (1) no `metric/status` console.log, (2) one | ||
| `statusTrack()` call, (3) one `updateHttpAgentMetrics()` call. | ||
|
|
||
| - **AC: `/_status` route and `broadcastStatusTrack`/`statusTrack` IPC flow | ||
| remain unchanged.** No edits to `statusTrackHandler`, `broadcastStatusTrack`, | ||
| the message-type guards, or the master/worker `onMessage` handlers. | ||
|
|
||
| - **AC: Prometheus `/metrics`, `__VTEX_IO_LOG` app logs, and `__VTEX_IO_BILLING` | ||
| process-time logs remain unchanged.** None of those code paths are touched; | ||
| only the `metric/status` export inside `trackStatus()` is removed. prom-client | ||
| cluster aggregation is independent of this legacy export. | ||
|
|
||
| - **AC: `docs/METRICS_CATALOG.md` no longer describes MetricsAccumulator values | ||
| as console.log exports and documents flush-and-discard.** The visual-summary | ||
| line `📝 MetricsAccumulator (console.log exports via trackStatus)` and the | ||
| `### MetricsAccumulator` sub-section text (`Exported via console.log as JSON | ||
| and collected by Splunk.`) are rewritten to state that these values are | ||
| accumulated in memory and, on each `/_status` tick, flushed and discarded by | ||
| `trackStatus()` (no longer exported via `console.log`). | ||
|
|
||
| - **AC: `yarn test`, `yarn lint`, and `yarn build` pass.** Removing the unused | ||
| helper and its now-orphaned imports keeps TypeScript and tslint clean | ||
| (unused imports would otherwise fail lint/build); the new test runs under the | ||
| existing jest config. | ||
|
|
||
| ## Risks & alternatives considered | ||
|
|
||
| - **Assumption — the `metric/status` stream is truly unused.** The task states | ||
| it is no longer actively used; this spec trusts that. If a downstream | ||
| consumer still depends on it, this removal is a breaking change. Mitigation: | ||
| the flush side effect is preserved, so only the log export (not the data | ||
| aggregation) is removed, and it can be re-added if needed. | ||
|
|
||
| - **Assumption — discarding the `statusTrack()` return is enough to keep memory | ||
| bounded.** `flushMetrics()` drains internal state (`metricsMillis`, | ||
| `extensions`) and runs the `onFlushMetrics` callbacks regardless of whether the | ||
| return value is consumed, so calling and ignoring it is equivalent, memory-wise | ||
| and side-effect-wise, to the previous iterate-and-log behavior. | ||
|
|
||
| - **Alternative — remove the entire `trackStatus()`/IPC path.** Rejected — see | ||
| *Decisions → Is the `trackStatus()` / IPC flow used only for logging?* above. | ||
| The path is not logging-only: it also refreshes diagnostics HTTP-agent gauges | ||
| and drains the `MetricsAccumulator` (which additionally runs registered | ||
| `onFlushMetrics` callbacks). Removing it would stop the gauge refresh and let | ||
| legacy metric batches accumulate unbounded in worker memory (explicitly | ||
| disallowed by the task notes and by the maintainer feedback). | ||
|
|
||
| - **Alternative — gate the log behind an env flag.** Rejected as unnecessary | ||
| scope; the stream is unused, so an outright removal is simpler and the flush | ||
| behavior is retained regardless. | ||
|
|
||
| - **Import cleanup risk.** `LINKED` is still referenced by `statusTrackHandler`, | ||
| so it must be kept; only imports exclusively used by `logStatus` | ||
| (`ACCOUNT`, `APP`, `PRODUCTION`, `WORKSPACE`) are removed. This will be | ||
| verified by `yarn build`/`yarn lint`. | ||
|
|
||
| ## Test plan | ||
|
|
||
| New file `src/service/worker/runtime/statusTrack.test.ts` (jest + ts-jest, per | ||
| existing `HttpAgentSingleton.test.ts` conventions): | ||
|
|
||
| 1. **No legacy log** — mock `global.metrics.statusTrack` to return a non-empty | ||
| array of `EnvMetric` values, spy on `console.log`, call `trackStatus()`, and | ||
| assert no `console.log` argument contains `type":"metric/status"` (nor the | ||
| `__VTEX_IO_LOG` status envelope). | ||
| 2. **Flush still happens** — assert `global.metrics.statusTrack` was called | ||
| exactly once. | ||
| 3. **Diagnostics gauge refresh** — mock/spy | ||
| `HttpAgentSingleton.updateHttpAgentMetrics` and assert exactly one call. | ||
|
|
||
| Setup/teardown: stub `global.metrics` in `beforeEach` and restore spies in | ||
| `afterEach` so the test does not leak global state (mirrors the existing | ||
| `HttpAgentSingleton.test.ts` pattern). | ||
|
|
||
| Full gate: `yarn test`, `yarn lint`, and `yarn build` must all pass. | ||
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,50 @@ | ||
| import { HttpAgentSingleton } from '../../../HttpClient/middlewares/request/HttpAgentSingleton' | ||
| import { EnvMetric, trackStatus } from './statusTrack' | ||
|
|
||
| describe('trackStatus', () => { | ||
| let consoleLogSpy: jest.SpyInstance | ||
| let updateHttpAgentMetricsSpy: jest.SpyInstance | ||
| let statusTrackMock: jest.Mock<EnvMetric[]> | ||
|
|
||
| const sampleMetrics: EnvMetric[] = [ | ||
| { name: 'http-handler-foo', production: true, count: 3, mean: 10 }, | ||
| { name: 'http-client-bar', production: false, count: 1, mean: 5 }, | ||
| ] | ||
|
|
||
| beforeEach(() => { | ||
| consoleLogSpy = jest.spyOn(console, 'log').mockImplementation(() => undefined) | ||
| updateHttpAgentMetricsSpy = jest | ||
| .spyOn(HttpAgentSingleton, 'updateHttpAgentMetrics') | ||
| .mockImplementation(() => undefined) | ||
|
|
||
| statusTrackMock = jest.fn(() => sampleMetrics) | ||
| global.metrics = { statusTrack: statusTrackMock } as any | ||
| }) | ||
|
|
||
| afterEach(() => { | ||
| jest.restoreAllMocks() | ||
| delete (global as any).metrics | ||
| }) | ||
|
|
||
| it('emits no console.log entry containing type: metric/status', () => { | ||
| trackStatus() | ||
|
|
||
| const emittedMetricStatusLog = consoleLogSpy.mock.calls.some(([arg]) => | ||
| typeof arg === 'string' && arg.includes('metric/status') | ||
| ) | ||
| expect(emittedMetricStatusLog).toBe(false) | ||
| expect(consoleLogSpy).not.toHaveBeenCalled() | ||
| }) | ||
|
|
||
| it('invokes global.metrics.statusTrack() exactly once so batches are still flushed', () => { | ||
| trackStatus() | ||
|
|
||
| expect(statusTrackMock).toHaveBeenCalledTimes(1) | ||
| }) | ||
|
|
||
| it('invokes HttpAgentSingleton.updateHttpAgentMetrics() exactly once', () => { | ||
| trackStatus() | ||
|
|
||
| expect(updateHttpAgentMetricsSpy).toHaveBeenCalledTimes(1) | ||
| }) | ||
| }) |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Oops, something went wrong.
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Uh oh!
There was an error while loading. Please reload this page.