fix: reduce @log decorator volume to prevent thread-stream flush timeout#1215
fix: reduce @log decorator volume to prevent thread-stream flush timeout#1215
Conversation
Remove Logger.debug calls from the @log decorator that eagerly serialized method arguments and results via JSON.stringify on every invocation. This caused thread-stream flush timeouts for large diffs (800+ components) when debug logging was enabled (#1214). The decorator now only emits lightweight Logger.trace for entry/exit. Remove dead code (stringify, hasCustomToString, replacer) and update tests accordingly.
Codecov Report✅ All modified and coverable lines are covered by tests. Additional details and impacted files@@ Coverage Diff @@
## main #1215 +/- ##
=========================================
Coverage 100.00% 100.00%
=========================================
Files 57 57
Lines 1543 1528 -15
Branches 201 194 -7
=========================================
- Hits 1543 1528 -15 ☔ View full report in Codecov by Sentry. 🚀 New features to boost your workflow:
|
Add Logger.debug with relevant context to catch blocks that were previously relying on the @log decorator for diagnostic information: - GitAdapter.gitGrep: was completely silent, now logs pattern/path/revision - StandardHandler.collect: adds change type and metadata type to existing warn - ConfigValidator._validateGitSha: logs parameter name, value, and raw error
scolladon
force-pushed
the
fix/reduce-log-decorator-volume
branch
from
b195ab7 to
4203209
Compare
|
Hi @gjagadish1234 ! Could you test on your laptop and help us validate this PR please ? sf plugins install sf-git-merge-driver@dev-1215 |
Remove eager JSON.stringify serialization from the @log decorator (stringify, hasCustomToString, replacer) that ran on every invocation. The decorator now only emits lightweight Logger.trace for entry/exit. Also defer JSON.stringify in run.ts debug calls using lazy evaluation, and add missing valueSettings test for 100% coverage. Port of scolladon/sfdx-git-delta#1215.
Remove eager JSON.stringify serialization from the @log decorator (stringify, hasCustomToString, replacer) that ran on every invocation. The decorator now only emits lightweight Logger.trace for entry/exit. Also defer JSON.stringify in run.ts debug calls using lazy evaluation, and add missing valueSettings test for 100% coverage. Port of scolladon/sfdx-git-delta#1215.
Hi @scolladon Thank you for the quick response and for looking into this I'd like to clarify that in the issue I didn't explicitly mention this, but the flush sync issue has only been observed in our CI/CD pipeline not locally. To validate this, I tested it directly in the pipeline using |
|
Published under $ sf plugins install sf-git-merge-driver@dev-1215 |
|
Shipped in release $ sf plugins install sfdx-git-delta@latest-rc
# Or
$ sf plugins install sfdx-git-delta@v6.32.1💡 Enjoying sfdx-git-delta? |
2 participants
Explain your changes
The
@logdecorator eagerly serialized method arguments and results viaJSON.stringifyon every invocation (25 usages across 15 files). For large diffs (800+ components), hot-path methods likeStandardHandler.collect,TypeHandlerFactory.getTypeHandler, andMetadataDiff.comparegenerated thousands of log entries with potentially MB-sized payloads (full XML trees, file contents). This overwhelmed pino's thread-stream transport, causing its hardcoded 10sflushSynctimeout to fail at process exit.Changes:
@logdecorator to only emit lightweightLogger.tracefor entry/exit (class name + method name, no serialization)stringify,hasCustomToString,replacer) that was only used by the removed debug callsLogger.debugwith relevant context to catch blocks that were previously relying on the decorator for diagnostic information:GitAdapter.gitGrep: was completely silent, now logs pattern/path/revisionStandardHandler.collect: adds change type and metadata type to existing warnConfigValidator._validateGitSha: logs parameter name, value, and raw errorDoes this close any currently open issues?
closes #1214
Any particular element that can be tested locally
Run
sf sgd source deltawith a large diff (800+ components) andSF_LOG_LEVEL=debug— the command should complete without_flushSync took too longerrors.Any other comments
The root cause is that pino's
thread-streamhas a hardcoded 10s flush timeout (Atomics.waitwith 10 spins × 1s) that is not configurable through@salesforce/core. Rather than trying to work around the timeout, this fix eliminates the log volume that causes it.Trace-level entry/exit logging is preserved for execution flow debugging. Debug-level context is now logged at error boundaries (catch blocks) where it is most useful for diagnosing issues.