-
Couldn't load subscription status.
- Fork 467
fix(logging): remove log correlation attributes from ddtrace loggers [backport 3.17] #15017
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
Conversation
…14979) ## Description Fixes ddtrace internal logging errors when trace-log correlation is disabled programmatically. ## Problem ddtrace internal logs were expecting correlation attributes (`dd.service`, etc.) even when log injection was disabled, causing `ValueError: Formatting field not found in record` errors. ## Solution Removed set_log_formatting to prevent mismatches between expected and actual log record attributes. When log correlation is disabled but DD_LOG_FORMAT is set, internal ddtrace logs can raise a ValueError. This also prevents issues when user configured log formatters override log formatters set by ddtrace. Since span start and finish now emit debug logs, including trace attributes in all ddtrace log records is no longer necessary. ## Testing Verified ddtrace internal logs work correctly with correlation disabled. ## Risks None - fixes existing bug. (cherry picked from commit b433817)
|
|
Bootstrap import analysisComparison of import times between this PR and base. SummaryThe average import time from this PR is: 242 ± 4 ms. The average import time from base is: 244 ± 3 ms. The import time difference between this PR and base is: -1.8 ± 0.2 ms. Import time breakdownThe following import paths have shrunk:
|
Performance SLOsComparing candidate backport-14979-to-3.17 (c4fc9a9) with baseline 3.17 (7451e84) 📈 Performance Regressions (1 suite)📈 iastaspects - 118/118✅ add_aspectTime: ✅ 0.405µs (SLO: <10.000µs 📉 -95.9%) vs baseline: -0.9% Memory: ✅ 38.063MB (SLO: <39.000MB -2.4%) vs baseline: +4.7% ✅ add_inplace_aspectTime: ✅ 0.406µs (SLO: <10.000µs 📉 -95.9%) vs baseline: -1.7% Memory: ✅ 37.945MB (SLO: <39.000MB -2.7%) vs baseline: +4.5% ✅ add_inplace_noaspectTime: ✅ 0.321µs (SLO: <10.000µs 📉 -96.8%) vs baseline: ~same Memory: ✅ 38.044MB (SLO: <39.000MB -2.5%) vs baseline: +5.0% ✅ add_noaspectTime: ✅ 0.275µs (SLO: <10.000µs 📉 -97.3%) vs baseline: -0.1% Memory: ✅ 38.083MB (SLO: <39.000MB -2.4%) vs baseline: +4.7% ✅ bytearray_aspectTime: ✅ 1.321µs (SLO: <10.000µs 📉 -86.8%) vs baseline: -1.2% Memory: ✅ 38.122MB (SLO: <39.000MB -2.3%) vs baseline: +5.0% ✅ bytearray_extend_aspectTime: ✅ 1.514µs (SLO: <10.000µs 📉 -84.9%) vs baseline: -2.0% Memory: ✅ 37.788MB (SLO: <39.000MB -3.1%) vs baseline: +4.1% ✅ bytearray_extend_noaspectTime: ✅ 0.615µs (SLO: <10.000µs 📉 -93.9%) vs baseline: +0.7% Memory: ✅ 38.024MB (SLO: <39.000MB -2.5%) vs baseline: +4.8% ✅ bytearray_noaspectTime: ✅ 0.484µs (SLO: <10.000µs 📉 -95.2%) vs baseline: +0.8% Memory: ✅ 38.044MB (SLO: <39.000MB -2.5%) vs baseline: +4.8% ✅ bytes_aspectTime: ✅ 1.449µs (SLO: <10.000µs 📉 -85.5%) vs baseline: 📈 +13.1% Memory: ✅ 38.044MB (SLO: <39.000MB -2.5%) vs baseline: +4.7% ✅ bytes_noaspectTime: ✅ 0.488µs (SLO: <10.000µs 📉 -95.1%) vs baseline: -1.1% Memory: ✅ 38.004MB (SLO: <39.000MB -2.6%) vs baseline: +4.6% ✅ bytesio_aspectTime: ✅ 1.311µs (SLO: <10.000µs 📉 -86.9%) vs baseline: -1.5% Memory: ✅ 38.044MB (SLO: <39.000MB -2.5%) vs baseline: +4.9% ✅ bytesio_noaspectTime: ✅ 0.497µs (SLO: <10.000µs 📉 -95.0%) vs baseline: ~same Memory: ✅ 37.985MB (SLO: <39.000MB -2.6%) vs baseline: +4.6% ✅ capitalize_aspectTime: ✅ 0.740µs (SLO: <10.000µs 📉 -92.6%) vs baseline: +0.4% Memory: ✅ 38.044MB (SLO: <39.000MB -2.5%) vs baseline: +5.0% ✅ capitalize_noaspectTime: ✅ 0.438µs (SLO: <10.000µs 📉 -95.6%) vs baseline: +0.6% Memory: ✅ 38.122MB (SLO: <39.000MB -2.3%) vs baseline: +5.1% ✅ casefold_aspectTime: ✅ 0.743µs (SLO: <10.000µs 📉 -92.6%) vs baseline: +1.1% Memory: ✅ 38.122MB (SLO: <39.000MB -2.3%) vs baseline: +5.1% ✅ casefold_noaspectTime: ✅ 0.370µs (SLO: <10.000µs 📉 -96.3%) vs baseline: +0.8% Memory: ✅ 38.083MB (SLO: <39.000MB -2.4%) vs baseline: +4.9% ✅ decode_aspectTime: ✅ 0.723µs (SLO: <10.000µs 📉 -92.8%) vs baseline: -1.6% Memory: ✅ 38.063MB (SLO: <39.000MB -2.4%) vs baseline: +5.0% ✅ decode_noaspectTime: ✅ 0.418µs (SLO: <10.000µs 📉 -95.8%) vs baseline: +0.1% Memory: ✅ 38.044MB (SLO: <39.000MB -2.5%) vs baseline: +4.9% ✅ encode_aspectTime: ✅ 0.712µs (SLO: <10.000µs 📉 -92.9%) vs baseline: +1.2% Memory: ✅ 38.063MB (SLO: <39.000MB -2.4%) vs baseline: +4.8% ✅ encode_noaspectTime: ✅ 0.397µs (SLO: <10.000µs 📉 -96.0%) vs baseline: -2.1% Memory: ✅ 38.103MB (SLO: <39.000MB -2.3%) vs baseline: +4.9% ✅ format_aspectTime: ✅ 3.533µs (SLO: <10.000µs 📉 -64.7%) vs baseline: +6.0% Memory: ✅ 38.024MB (SLO: <39.000MB -2.5%) vs baseline: +4.7% ✅ format_map_aspectTime: ✅ 3.987µs (SLO: <10.000µs 📉 -60.1%) vs baseline: 📈 +12.1% Memory: ✅ 38.083MB (SLO: <39.000MB -2.4%) vs baseline: +4.8% ✅ format_map_noaspectTime: ✅ 0.782µs (SLO: <10.000µs 📉 -92.2%) vs baseline: +1.1% Memory: ✅ 38.024MB (SLO: <39.000MB -2.5%) vs baseline: +4.8% ✅ format_noaspectTime: ✅ 0.601µs (SLO: <10.000µs 📉 -94.0%) vs baseline: +0.6% Memory: ✅ 38.063MB (SLO: <39.000MB -2.4%) vs baseline: +4.7% ✅ index_aspectTime: ✅ 0.360µs (SLO: <10.000µs 📉 -96.4%) vs baseline: +0.8% Memory: ✅ 38.044MB (SLO: <39.000MB -2.5%) vs baseline: +4.6% ✅ index_noaspectTime: ✅ 0.278µs (SLO: <10.000µs 📉 -97.2%) vs baseline: -0.3% Memory: ✅ 38.103MB (SLO: <39.000MB -2.3%) vs baseline: +5.0% ✅ join_aspectTime: ✅ 1.316µs (SLO: <10.000µs 📉 -86.8%) vs baseline: -1.6% Memory: ✅ 38.044MB (SLO: <39.000MB -2.5%) vs baseline: +4.8% ✅ join_noaspectTime: ✅ 0.494µs (SLO: <10.000µs 📉 -95.1%) vs baseline: ~same Memory: ✅ 37.965MB (SLO: <39.000MB -2.7%) vs baseline: +4.5% ✅ ljust_aspectTime: ✅ 2.592µs (SLO: <20.000µs 📉 -87.0%) vs baseline: -0.2% Memory: ✅ 38.122MB (SLO: <39.000MB -2.3%) vs baseline: +5.2% ✅ ljust_noaspectTime: ✅ 0.407µs (SLO: <10.000µs 📉 -95.9%) vs baseline: +0.7% Memory: ✅ 38.142MB (SLO: <39.000MB -2.2%) vs baseline: +4.9% ✅ lower_aspectTime: ✅ 2.253µs (SLO: <10.000µs 📉 -77.5%) vs baseline: +1.1% Memory: ✅ 38.103MB (SLO: <39.000MB -2.3%) vs baseline: +4.9% ✅ lower_noaspectTime: ✅ 0.373µs (SLO: <10.000µs 📉 -96.3%) vs baseline: +1.0% Memory: ✅ 38.063MB (SLO: <39.000MB -2.4%) vs baseline: +5.0% ✅ lstrip_aspectTime: ✅ 2.198µs (SLO: <20.000µs 📉 -89.0%) vs baseline: +0.3% Memory: ✅ 38.024MB (SLO: <39.000MB -2.5%) vs baseline: +4.7% ✅ lstrip_noaspectTime: ✅ 0.386µs (SLO: <10.000µs 📉 -96.1%) vs baseline: +0.9% Memory: ✅ 38.103MB (SLO: <39.000MB -2.3%) vs baseline: +4.7% ✅ modulo_aspectTime: ✅ 0.996µs (SLO: <10.000µs 📉 -90.0%) vs baseline: ~same Memory: ✅ 38.044MB (SLO: <39.000MB -2.5%) vs baseline: +4.7% ✅ modulo_aspect_for_bytearray_bytearrayTime: ✅ 1.568µs (SLO: <10.000µs 📉 -84.3%) vs baseline: +2.5% Memory: ✅ 38.063MB (SLO: <39.000MB -2.4%) vs baseline: +4.8% ✅ modulo_aspect_for_bytesTime: ✅ 0.975µs (SLO: <10.000µs 📉 -90.3%) vs baseline: -0.3% Memory: ✅ 37.690MB (SLO: <39.000MB -3.4%) vs baseline: +3.8% ✅ modulo_aspect_for_bytes_bytearrayTime: ✅ 1.202µs (SLO: <10.000µs 📉 -88.0%) vs baseline: ~same Memory: ✅ 38.083MB (SLO: <39.000MB -2.4%) vs baseline: +4.8% ✅ modulo_noaspectTime: ✅ 0.631µs (SLO: <10.000µs 📉 -93.7%) vs baseline: +0.2% Memory: ✅ 38.004MB (SLO: <39.000MB -2.6%) vs baseline: +4.7% ✅ replace_aspectTime: ✅ 4.883µs (SLO: <10.000µs 📉 -51.2%) vs baseline: +1.2% Memory: ✅ 38.024MB (SLO: <39.000MB -2.5%) vs baseline: +4.7% ✅ replace_noaspectTime: ✅ 0.460µs (SLO: <10.000µs 📉 -95.4%) vs baseline: +0.2% Memory: ✅ 38.083MB (SLO: <39.000MB -2.4%) vs baseline: +4.9% ✅ repr_aspectTime: ✅ 0.909µs (SLO: <10.000µs 📉 -90.9%) vs baseline: ~same Memory: ✅ 38.103MB (SLO: <39.000MB -2.3%) vs baseline: +5.0% ✅ repr_noaspectTime: ✅ 0.424µs (SLO: <10.000µs 📉 -95.8%) vs baseline: +2.4% Memory: ✅ 38.044MB (SLO: <39.000MB -2.5%) vs baseline: +4.7% ✅ rstrip_aspectTime: ✅ 1.915µs (SLO: <20.000µs 📉 -90.4%) vs baseline: +0.5% Memory: ✅ 38.044MB (SLO: <39.000MB -2.5%) vs baseline: +4.9% ✅ rstrip_noaspectTime: ✅ 0.382µs (SLO: <10.000µs 📉 -96.2%) vs baseline: +0.4% Memory: ✅ 38.103MB (SLO: <39.000MB -2.3%) vs baseline: +5.0% ✅ slice_aspectTime: ✅ 0.502µs (SLO: <10.000µs 📉 -95.0%) vs baseline: +0.7% Memory: ✅ 38.063MB (SLO: <39.000MB -2.4%) vs baseline: +4.8% ✅ slice_noaspectTime: ✅ 0.448µs (SLO: <10.000µs 📉 -95.5%) vs baseline: +0.2% Memory: ✅ 38.122MB (SLO: <39.000MB -2.3%) vs baseline: +5.1% ✅ stringio_aspectTime: ✅ 1.580µs (SLO: <10.000µs 📉 -84.2%) vs baseline: +2.0% Memory: ✅ 38.083MB (SLO: <39.000MB -2.4%) vs baseline: +4.8% ✅ stringio_noaspectTime: ✅ 0.721µs (SLO: <10.000µs 📉 -92.8%) vs baseline: +0.8% Memory: ✅ 38.024MB (SLO: <39.000MB -2.5%) vs baseline: +4.7% ✅ strip_aspectTime: ✅ 2.203µs (SLO: <20.000µs 📉 -89.0%) vs baseline: +1.7% Memory: ✅ 38.083MB (SLO: <39.000MB -2.4%) vs baseline: +4.8% ✅ strip_noaspectTime: ✅ 0.384µs (SLO: <10.000µs 📉 -96.2%) vs baseline: ~same Memory: ✅ 38.083MB (SLO: <39.000MB -2.4%) vs baseline: +4.9% ✅ swapcase_aspectTime: ✅ 2.438µs (SLO: <10.000µs 📉 -75.6%) vs baseline: -0.5% Memory: ✅ 38.044MB (SLO: <39.000MB -2.5%) vs baseline: +4.8% ✅ swapcase_noaspectTime: ✅ 0.533µs (SLO: <10.000µs 📉 -94.7%) vs baseline: -0.1% Memory: ✅ 37.985MB (SLO: <39.000MB -2.6%) vs baseline: +4.6% ✅ title_aspectTime: ✅ 2.578µs (SLO: <10.000µs 📉 -74.2%) vs baseline: +8.3% Memory: ✅ 38.083MB (SLO: <39.000MB -2.4%) vs baseline: +4.9% ✅ title_noaspectTime: ✅ 0.501µs (SLO: <10.000µs 📉 -95.0%) vs baseline: -0.6% Memory: ✅ 38.063MB (SLO: <39.000MB -2.4%) vs baseline: +4.7% ✅ translate_aspectTime: ✅ 3.284µs (SLO: <10.000µs 📉 -67.2%) vs baseline: -0.5% Memory: ✅ 38.063MB (SLO: <39.000MB -2.4%) vs baseline: +5.0% ✅ translate_noaspectTime: ✅ 1.044µs (SLO: <10.000µs 📉 -89.6%) vs baseline: +0.3% Memory: ✅ 38.083MB (SLO: <39.000MB -2.4%) vs baseline: +5.0% ✅ upper_aspectTime: ✅ 2.298µs (SLO: <10.000µs 📉 -77.0%) vs baseline: +2.5% Memory: ✅ 38.122MB (SLO: <39.000MB -2.3%) vs baseline: +5.0% ✅ upper_noaspectTime: ✅ 0.369µs (SLO: <10.000µs 📉 -96.3%) vs baseline: -0.5% Memory: ✅ 37.985MB (SLO: <39.000MB -2.6%) vs baseline: +4.6% 🟡 Near SLO Breach (3 suites)🟡 djangosimple - 30/30✅ appsecTime: ✅ 20.488ms (SLO: <22.300ms -8.1%) vs baseline: +0.2% Memory: ✅ 65.432MB (SLO: <67.000MB -2.3%) vs baseline: +4.8% ✅ exception-replay-enabledTime: ✅ 1.350ms (SLO: <1.450ms -6.9%) vs baseline: +0.2% Memory: ✅ 64.521MB (SLO: <67.000MB -3.7%) vs baseline: +4.8% ✅ iastTime: ✅ 20.446ms (SLO: <22.250ms -8.1%) vs baseline: -0.3% Memory: ✅ 65.500MB (SLO: <67.000MB -2.2%) vs baseline: +4.8% ✅ profilerTime: ✅ 15.308ms (SLO: <16.550ms -7.5%) vs baseline: ~same Memory: ✅ 53.851MB (SLO: <54.500MB 🟡 -1.2%) vs baseline: +4.2% ✅ resource-renamingTime: ✅ 20.586ms (SLO: <21.750ms -5.3%) vs baseline: +0.1% Memory: ✅ 65.479MB (SLO: <67.000MB -2.3%) vs baseline: +5.0% ✅ span-code-originTime: ✅ 25.415ms (SLO: <28.200ms -9.9%) vs baseline: +1.8% Memory: ✅ 67.734MB (SLO: <69.500MB -2.5%) vs baseline: +4.7% ✅ tracerTime: ✅ 20.491ms (SLO: <21.750ms -5.8%) vs baseline: ~same Memory: ✅ 65.430MB (SLO: <67.000MB -2.3%) vs baseline: +4.7% ✅ tracer-and-profilerTime: ✅ 22.014ms (SLO: <23.500ms -6.3%) vs baseline: -0.3% Memory: ✅ 66.538MB (SLO: <67.500MB 🟡 -1.4%) vs baseline: +4.9% ✅ tracer-dont-create-db-spansTime: ✅ 19.331ms (SLO: <21.500ms 📉 -10.1%) vs baseline: -0.2% Memory: ✅ 65.466MB (SLO: <66.000MB 🟡 -0.8%) vs baseline: +4.8% ✅ tracer-minimalTime: ✅ 16.542ms (SLO: <17.500ms -5.5%) vs baseline: -0.6% Memory: ✅ 65.486MB (SLO: <66.000MB 🟡 -0.8%) vs baseline: +4.9% ✅ tracer-nativeTime: ✅ 20.539ms (SLO: <21.750ms -5.6%) vs baseline: +0.2% Memory: ✅ 71.445MB (SLO: <72.500MB 🟡 -1.5%) vs baseline: +4.9% ✅ tracer-no-cachesTime: ✅ 18.473ms (SLO: <19.650ms -6.0%) vs baseline: ~same Memory: ✅ 65.426MB (SLO: <67.000MB -2.3%) vs baseline: +4.8% ✅ tracer-no-databasesTime: ✅ 18.765ms (SLO: <20.100ms -6.6%) vs baseline: ~same Memory: ✅ 65.095MB (SLO: <67.000MB -2.8%) vs baseline: +4.2% ✅ tracer-no-middlewareTime: ✅ 20.143ms (SLO: <21.500ms -6.3%) vs baseline: -0.1% Memory: ✅ 65.444MB (SLO: <67.000MB -2.3%) vs baseline: +4.8% ✅ tracer-no-templatesTime: ✅ 20.352ms (SLO: <22.000ms -7.5%) vs baseline: +0.2% Memory: ✅ 65.531MB (SLO: <67.000MB -2.2%) vs baseline: +4.9% 🟡 errortrackingdjangosimple - 6/6✅ errortracking-enabled-allTime: ✅ 18.081ms (SLO: <19.850ms -8.9%) vs baseline: +0.4% Memory: ✅ 65.294MB (SLO: <66.500MB 🟡 -1.8%) vs baseline: +4.9% ✅ errortracking-enabled-userTime: ✅ 18.057ms (SLO: <19.400ms -6.9%) vs baseline: ~same Memory: ✅ 65.254MB (SLO: <66.500MB 🟡 -1.9%) vs baseline: +4.9% ✅ tracer-enabledTime: ✅ 18.100ms (SLO: <19.450ms -6.9%) vs baseline: +0.4% Memory: ✅ 65.235MB (SLO: <66.500MB 🟡 -1.9%) vs baseline: +4.8% 🟡 flasksimple - 18/18✅ appsec-getTime: ✅ 4.588ms (SLO: <4.750ms -3.4%) vs baseline: +0.2% Memory: ✅ 61.822MB (SLO: <65.000MB -4.9%) vs baseline: +4.5% ✅ appsec-postTime: ✅ 6.612ms (SLO: <6.750ms -2.0%) vs baseline: +0.3% Memory: ✅ 62.134MB (SLO: <65.000MB -4.4%) vs baseline: +5.1% ✅ appsec-telemetryTime: ✅ 4.587ms (SLO: <4.750ms -3.4%) vs baseline: +0.4% Memory: ✅ 61.861MB (SLO: <65.000MB -4.8%) vs baseline: +4.7% ✅ debuggerTime: ✅ 1.857ms (SLO: <2.000ms -7.2%) vs baseline: +0.2% Memory: ✅ 45.405MB (SLO: <47.000MB -3.4%) vs baseline: +4.7% ✅ iast-getTime: ✅ 1.861ms (SLO: <2.000ms -6.9%) vs baseline: +0.4% Memory: ✅ 42.448MB (SLO: <49.000MB 📉 -13.4%) vs baseline: +5.0% ✅ profilerTime: ✅ 1.909ms (SLO: <2.100ms -9.1%) vs baseline: +0.1% Memory: ✅ 46.547MB (SLO: <47.000MB 🟡 -1.0%) vs baseline: +5.1% ✅ resource-renamingTime: ✅ 3.366ms (SLO: <3.650ms -7.8%) vs baseline: +0.2% Memory: ✅ 52.509MB (SLO: <53.500MB 🟡 -1.9%) vs baseline: +5.4% ✅ tracerTime: ✅ 3.357ms (SLO: <3.650ms -8.0%) vs baseline: -0.2% Memory: ✅ 52.228MB (SLO: <53.500MB -2.4%) vs baseline: +4.8% ✅ tracer-nativeTime: ✅ 3.354ms (SLO: <3.650ms -8.1%) vs baseline: ~same Memory: ✅ 58.287MB (SLO: <60.000MB -2.9%) vs baseline: +5.0%
|
|
original PR is failing on main |
Backport b433817 from #14979 to 3.17.
Description
Fixes ddtrace internal logging errors when trace-log correlation is disabled programmatically.
Problem
ddtrace internal logs were expecting correlation attributes (
dd.service, etc.) even when log injection was disabled, causingValueError: Formatting field not found in recorderrors.Solution
Removed set_log_formatting to prevent mismatches between expected and actual log record attributes. When log correlation is disabled but DD_LOG_FORMAT is set, internal ddtrace logs can raise a ValueError. This also prevents issues when user configured log formatters override log formatters set by ddtrace. Since span start and finish now emit debug logs, including trace attributes in all ddtrace log records is no longer necessary.
Testing
Updated existing test to assert that ddtrace log correlation attributes are not added to ddtrace logs by default.
Risks
None - fixes existing bug.