chore(log): suppress per-op action log lines during bulk replay (#7981)

A single `bulkApplyOperations` dispatch (startup hydration replay or
remote-sync apply) runs the reducer chain once per op, so the action
logger printed one `[a]<type>` line per op — hundreds of lines for one
dispatch, which reads as a flood of separate dispatches. Gate the per-op
console line behind a bulk-replay flag (intentionally distinct from
isApplyingRemoteOps, which spans the broader async apply window); callers
already log an "applying N ops" summary and the in-memory ring buffer is
still fed.
This commit is contained in:
Johannes Millan 2026-06-03 12:41:12 +02:00 committed by GitHub
parent c971e74503
commit 524e827072
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
4 changed files with 98 additions and 23 deletions

View file

@ -7,6 +7,7 @@ import {
stripBatchArchivedTaskIdsFromLwwPayload,
} from './bulk-archive-filter.util';
import { OpLog } from '../../core/log';
import { runWithBulkReplayLoggingSuppressed } from '../../util/bulk-replay-log-guard';
/**
* Meta-reducer that applies multiple operations in a single reducer pass.
@ -55,30 +56,37 @@ export const bulkOperationsMetaReducer = <T>(
state,
);
let currentState = state;
const hasArchives = archivingOrDeletingEntityIds.size > 0;
for (const op of operations) {
const isLww = hasArchives && isLwwUpdateActionType(op.actionType);
// Skip LWW Updates whose entityId itself is archived/deleted in this batch
// (covers TASK; for TAG/PROJECT entityId is the tag/project id, not a task).
if (isLww && op.entityId && archivingOrDeletingEntityIds.has(op.entityId)) {
OpLog.normal(
`bulkOperationsMetaReducer: Skipping LWW Update for ` +
`${op.entityType}:${op.entityId} — entity archived/deleted in same batch`,
);
continue;
// Apply every op in one synchronous reducer pass. Suppress the action
// logger's per-op console line for the duration (see bulk-replay-log-guard):
// this is a single dispatch, and the caller (hydrator / applier) already
// logs an "applying N ops" summary, so per-op `[a]` lines are just noise.
const finalState = runWithBulkReplayLoggingSuppressed(() => {
let currentState = state;
for (const op of operations) {
const isLww = hasArchives && isLwwUpdateActionType(op.actionType);
// Skip LWW Updates whose entityId itself is archived/deleted in this batch
// (covers TASK; for TAG/PROJECT entityId is the tag/project id, not a task).
if (isLww && op.entityId && archivingOrDeletingEntityIds.has(op.entityId)) {
OpLog.normal(
`bulkOperationsMetaReducer: Skipping LWW Update for ` +
`${op.entityType}:${op.entityId} — entity archived/deleted in same batch`,
);
continue;
}
const opForApply = hasArchives
? stripBatchArchivedTaskIdsFromLwwPayload(
op,
isLww,
archivingOrDeletingEntityIds,
)
: op;
const opAction = convertOpToAction(opForApply);
currentState = reducer(currentState, opAction);
}
const opForApply = hasArchives
? stripBatchArchivedTaskIdsFromLwwPayload(
op,
isLww,
archivingOrDeletingEntityIds,
)
: op;
const opAction = convertOpToAction(opForApply);
currentState = reducer(currentState, opAction);
}
return currentState as T;
return currentState;
});
return finalState as T;
}
return reducer(state, action);
};

View file

@ -1,6 +1,7 @@
import { actionLoggerReducer } from './action-logger.reducer';
import { Log } from '../../core/log';
import { ActionReducer, Action } from '@ngrx/store';
import { runWithBulkReplayLoggingSuppressed } from '../../util/bulk-replay-log-guard';
describe('actionLoggerReducer', () => {
const passThrough: ActionReducer<unknown, Action> = (state) => state;
@ -55,4 +56,24 @@ describe('actionLoggerReducer', () => {
expect(wrapped({ n: 1 }, { type: 'inc' } as Action)).toEqual({ n: 2 });
});
it('skips the per-op type line during a bulk-replay pass', () => {
const reducer: ActionReducer<{ n: number }, Action> = (state, action) =>
action.type === 'inc' ? { n: (state?.n ?? 0) + 1 } : (state ?? { n: 0 });
const wrapped = actionLoggerReducer(reducer);
// Inside a bulk-replay pass the per-op `[a]<type>` console line is suppressed
// (one bulk dispatch would otherwise print one line per op)...
const result = runWithBulkReplayLoggingSuppressed(() =>
wrapped({ n: 0 }, { type: '[TimeTracking] Sync sessions' } as Action),
);
expect(Log.exportLogHistory()).not.toContain('[TimeTracking] Sync sessions');
// ...but state is still reduced normally.
expect(result).toEqual({ n: 0 });
// ...and once the pass ends, logging resumes.
wrapped({ n: 0 }, { type: '[Task] Update Task' } as Action);
expect(Log.exportLogHistory()).toContain('[Task] Update Task');
});
});

View file

@ -1,6 +1,7 @@
import { actionLogger } from '../../util/action-logger';
import { ActionReducer, Action } from '@ngrx/store';
import { Log } from '../../core/log';
import { isBulkReplayLoggingSuppressed } from '../../util/bulk-replay-log-guard';
export const actionLoggerReducer = <S, A extends Action = Action>(
reducer: ActionReducer<S, A>,
@ -8,7 +9,15 @@ export const actionLoggerReducer = <S, A extends Action = Action>(
return (state: S | undefined, action: A) => {
// Log the action TYPE only — payloads/full actions carry user content
// and the log history is user-exportable. See core/log.ts header / rule #9.
Log.verbose('[a]' + action.type);
//
// Skip the per-op console line during a bulk-replay pass: one
// `bulkApplyOperations` dispatch runs this reducer once per op, which would
// otherwise print one `[a]<type>` line per op (hundreds for a hydration
// replay). The caller already logs a single "applying N ops" summary. The
// in-memory ring buffer below is still fed (it dedupes) for error reports.
if (!isBulkReplayLoggingSuppressed()) {
Log.verbose('[a]' + action.type);
}
actionLogger(action as unknown as { type: string; [key: string]: unknown });
return reducer(state, action);
};

View file

@ -0,0 +1,37 @@
/**
* Shared flag indicating that a `bulkApplyOperations` pass is mid-flight, i.e. a
* batch of ops is being applied in a single synchronous reducer pass (startup
* hydration replay or remote-sync apply).
*
* While the flag is set, the action logger skips its per-op console line.
* Without this, one bulk dispatch prints one `[a]<type>` line per op e.g. 344
* lines for a single hydration replay which reads as "hundreds of dispatches"
* when it is really one reducer pass. The callers (hydrator / applier) already
* log a single "applying N ops" summary, so nothing is lost.
*
* The flag is set synchronously around the bulk loop, so it is always accurate
* by the time the inner reducer chain (including the action logger) runs.
*
* Intentionally separate from HydrationStateService.isApplyingRemoteOps: that flag
* stays set across the whole (async) remote-apply window, so reusing it here would
* also suppress logging for unrelated actions dispatched in that wider window. This
* flag is scoped to the synchronous bulk reducer loop only, so it suppresses exactly
* the per-op replay lines and nothing else.
*/
let isSuppressed = false;
/**
* Runs `fn` with bulk-replay log suppression active. Restores the previous value
* afterwards (reentrancy-safe), so nested bulk passes behave correctly.
*/
export const runWithBulkReplayLoggingSuppressed = <T>(fn: () => T): T => {
const prev = isSuppressed;
isSuppressed = true;
try {
return fn();
} finally {
isSuppressed = prev;
}
};
export const isBulkReplayLoggingSuppressed = (): boolean => isSuppressed;