-
Notifications
You must be signed in to change notification settings - Fork 320
Log injection issues in JDBC only once + promote to WARN #10214
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
...ent/instrumentation/jdbc/src/main/java/datadog/trace/instrumentation/jdbc/JDBCDecorator.java
Outdated
Show resolved
Hide resolved
BenchmarksStartupParameters
See matching parameters
SummaryFound 0 performance improvements and 0 performance regressions! Performance is the same for 58 metrics, 7 unstable metrics. Startup time reports for petclinicgantt
title petclinic - global startup overhead: candidate=1.57.0-SNAPSHOT~a7e125a566, baseline=1.57.0-SNAPSHOT~4e44b392c3
dateFormat X
axisFormat %s
section tracing
Agent [baseline] (1.082 s) : 0, 1081860
Total [baseline] (10.914 s) : 0, 10914100
Agent [candidate] (1.082 s) : 0, 1082152
Total [candidate] (10.793 s) : 0, 10793481
section appsec
Agent [baseline] (1.272 s) : 0, 1271887
Total [baseline] (10.988 s) : 0, 10987876
Agent [candidate] (1.27 s) : 0, 1269674
Total [candidate] (11.025 s) : 0, 11025340
section iast
Agent [baseline] (1.221 s) : 0, 1220635
Total [baseline] (11.127 s) : 0, 11126741
Agent [candidate] (1.222 s) : 0, 1222085
Total [candidate] (11.15 s) : 0, 11149960
section profiling
Agent [baseline] (1.206 s) : 0, 1205917
Total [baseline] (10.928 s) : 0, 10928164
Agent [candidate] (1.206 s) : 0, 1206452
Total [candidate] (10.973 s) : 0, 10972637
gantt
title petclinic - break down per module: candidate=1.57.0-SNAPSHOT~a7e125a566, baseline=1.57.0-SNAPSHOT~4e44b392c3
dateFormat X
axisFormat %s
section tracing
crashtracking [baseline] (1.179 ms) : 0, 1179
crashtracking [candidate] (1.202 ms) : 0, 1202
BytebuddyAgent [baseline] (648.202 ms) : 0, 648202
BytebuddyAgent [candidate] (648.541 ms) : 0, 648541
GlobalTracer [baseline] (283.027 ms) : 0, 283027
GlobalTracer [candidate] (283.281 ms) : 0, 283281
AppSec [baseline] (32.367 ms) : 0, 32367
AppSec [candidate] (32.376 ms) : 0, 32376
Debugger [baseline] (67.358 ms) : 0, 67358
Debugger [candidate] (67.844 ms) : 0, 67844
Remote Config [baseline] (612.697 µs) : 0, 613
Remote Config [candidate] (632.647 µs) : 0, 633
Telemetry [baseline] (9.844 ms) : 0, 9844
Telemetry [candidate] (8.999 ms) : 0, 8999
Flare Poller [baseline] (3.693 ms) : 0, 3693
Flare Poller [candidate] (3.728 ms) : 0, 3728
section appsec
crashtracking [baseline] (1.192 ms) : 0, 1192
crashtracking [candidate] (1.19 ms) : 0, 1190
BytebuddyAgent [baseline] (693.446 ms) : 0, 693446
BytebuddyAgent [candidate] (692.715 ms) : 0, 692715
GlobalTracer [baseline] (260.351 ms) : 0, 260351
GlobalTracer [candidate] (260.521 ms) : 0, 260521
IAST [baseline] (24.775 ms) : 0, 24775
IAST [candidate] (24.675 ms) : 0, 24675
AppSec [baseline] (172.627 ms) : 0, 172627
AppSec [candidate] (173.336 ms) : 0, 173336
Debugger [baseline] (69.99 ms) : 0, 69990
Debugger [candidate] (67.99 ms) : 0, 67990
Remote Config [baseline] (695.711 µs) : 0, 696
Remote Config [candidate] (714.981 µs) : 0, 715
Telemetry [baseline] (9.05 ms) : 0, 9050
Telemetry [candidate] (8.957 ms) : 0, 8957
Flare Poller [baseline] (3.989 ms) : 0, 3989
Flare Poller [candidate] (3.814 ms) : 0, 3814
section iast
crashtracking [baseline] (1.193 ms) : 0, 1193
crashtracking [candidate] (1.183 ms) : 0, 1183
BytebuddyAgent [baseline] (788.435 ms) : 0, 788435
BytebuddyAgent [candidate] (789.442 ms) : 0, 789442
GlobalTracer [baseline] (255.735 ms) : 0, 255735
GlobalTracer [candidate] (255.84 ms) : 0, 255840
IAST [baseline] (26.976 ms) : 0, 26976
IAST [candidate] (27.054 ms) : 0, 27054
AppSec [baseline] (34.418 ms) : 0, 34418
AppSec [candidate] (32.882 ms) : 0, 32882
Debugger [baseline] (66.03 ms) : 0, 66030
Debugger [candidate] (67.707 ms) : 0, 67707
Remote Config [baseline] (596.906 µs) : 0, 597
Remote Config [candidate] (574.739 µs) : 0, 575
Telemetry [baseline] (8.388 ms) : 0, 8388
Telemetry [candidate] (8.417 ms) : 0, 8417
Flare Poller [baseline] (3.504 ms) : 0, 3504
Flare Poller [candidate] (3.523 ms) : 0, 3523
section profiling
crashtracking [baseline] (1.219 ms) : 0, 1219
crashtracking [candidate] (1.217 ms) : 0, 1217
BytebuddyAgent [baseline] (702.051 ms) : 0, 702051
BytebuddyAgent [candidate] (702.493 ms) : 0, 702493
GlobalTracer [baseline] (221.496 ms) : 0, 221496
GlobalTracer [candidate] (221.546 ms) : 0, 221546
AppSec [baseline] (32.117 ms) : 0, 32117
AppSec [candidate] (32.141 ms) : 0, 32141
Debugger [baseline] (68.216 ms) : 0, 68216
Debugger [candidate] (68.202 ms) : 0, 68202
Remote Config [baseline] (640.67 µs) : 0, 641
Remote Config [candidate] (655.159 µs) : 0, 655
Telemetry [baseline] (8.908 ms) : 0, 8908
Telemetry [candidate] (8.783 ms) : 0, 8783
Flare Poller [baseline] (3.75 ms) : 0, 3750
Flare Poller [candidate] (3.737 ms) : 0, 3737
ProfilingAgent [baseline] (97.48 ms) : 0, 97480
ProfilingAgent [candidate] (97.882 ms) : 0, 97882
Profiling [baseline] (98.058 ms) : 0, 98058
Profiling [candidate] (98.463 ms) : 0, 98463
Startup time reports for insecure-bankgantt
title insecure-bank - global startup overhead: candidate=1.57.0-SNAPSHOT~a7e125a566, baseline=1.57.0-SNAPSHOT~4e44b392c3
dateFormat X
axisFormat %s
section tracing
Agent [baseline] (1.088 s) : 0, 1087982
Total [baseline] (8.745 s) : 0, 8744576
Agent [candidate] (1.082 s) : 0, 1081753
Total [candidate] (8.782 s) : 0, 8781977
section iast
Agent [baseline] (1.222 s) : 0, 1222159
Total [baseline] (9.4 s) : 0, 9400482
Agent [candidate] (1.222 s) : 0, 1221907
Total [candidate] (9.404 s) : 0, 9403861
gantt
title insecure-bank - break down per module: candidate=1.57.0-SNAPSHOT~a7e125a566, baseline=1.57.0-SNAPSHOT~4e44b392c3
dateFormat X
axisFormat %s
section tracing
crashtracking [baseline] (1.225 ms) : 0, 1225
crashtracking [candidate] (1.182 ms) : 0, 1182
BytebuddyAgent [baseline] (652.338 ms) : 0, 652338
BytebuddyAgent [candidate] (648.856 ms) : 0, 648856
GlobalTracer [baseline] (284.232 ms) : 0, 284232
GlobalTracer [candidate] (282.653 ms) : 0, 282653
AppSec [baseline] (32.607 ms) : 0, 32607
AppSec [candidate] (32.417 ms) : 0, 32417
Debugger [baseline] (68.503 ms) : 0, 68503
Debugger [candidate] (67.653 ms) : 0, 67653
Remote Config [baseline] (614.367 µs) : 0, 614
Remote Config [candidate] (618.845 µs) : 0, 619
Telemetry [baseline] (9.116 ms) : 0, 9116
Telemetry [candidate] (9.079 ms) : 0, 9079
Flare Poller [baseline] (3.698 ms) : 0, 3698
Flare Poller [candidate] (3.771 ms) : 0, 3771
section iast
crashtracking [baseline] (1.191 ms) : 0, 1191
crashtracking [candidate] (1.192 ms) : 0, 1192
BytebuddyAgent [baseline] (790.324 ms) : 0, 790324
BytebuddyAgent [candidate] (790.546 ms) : 0, 790546
GlobalTracer [baseline] (256.002 ms) : 0, 256002
GlobalTracer [candidate] (256.004 ms) : 0, 256004
IAST [baseline] (27.132 ms) : 0, 27132
IAST [candidate] (27.059 ms) : 0, 27059
AppSec [baseline] (35.316 ms) : 0, 35316
AppSec [candidate] (34.442 ms) : 0, 34442
Debugger [baseline] (64.188 ms) : 0, 64188
Debugger [candidate] (64.849 ms) : 0, 64849
Remote Config [baseline] (596.326 µs) : 0, 596
Remote Config [candidate] (585.339 µs) : 0, 585
Telemetry [baseline] (8.477 ms) : 0, 8477
Telemetry [candidate] (8.383 ms) : 0, 8383
Flare Poller [baseline] (3.532 ms) : 0, 3532
Flare Poller [candidate] (3.492 ms) : 0, 3492
LoadParameters
See matching parameters
SummaryFound 2 performance improvements and 2 performance regressions! Performance is the same for 15 metrics, 17 unstable metrics.
Request duration reports for petclinicgantt
title petclinic - request duration [CI 0.99] : candidate=1.57.0-SNAPSHOT~a7e125a566, baseline=1.57.0-SNAPSHOT~4e44b392c3
dateFormat X
axisFormat %s
section baseline
no_agent (19.267 ms) : 19066, 19468
. : milestone, 19267,
appsec (18.962 ms) : 18766, 19158
. : milestone, 18962,
code_origins (17.677 ms) : 17501, 17852
. : milestone, 17677,
iast (18.512 ms) : 18327, 18698
. : milestone, 18512,
profiling (18.668 ms) : 18482, 18853
. : milestone, 18668,
tracing (17.695 ms) : 17519, 17871
. : milestone, 17695,
section candidate
no_agent (19.204 ms) : 19004, 19404
. : milestone, 19204,
appsec (18.895 ms) : 18705, 19086
. : milestone, 18895,
code_origins (18.79 ms) : 18604, 18977
. : milestone, 18790,
iast (17.71 ms) : 17532, 17887
. : milestone, 17710,
profiling (18.803 ms) : 18616, 18991
. : milestone, 18803,
tracing (17.859 ms) : 17683, 18036
. : milestone, 17859,
Request duration reports for insecure-bankgantt
title insecure-bank - request duration [CI 0.99] : candidate=1.57.0-SNAPSHOT~a7e125a566, baseline=1.57.0-SNAPSHOT~4e44b392c3
dateFormat X
axisFormat %s
section baseline
no_agent (1.174 ms) : 1163, 1185
. : milestone, 1174,
iast (3.214 ms) : 3175, 3254
. : milestone, 3214,
iast_FULL (5.695 ms) : 5638, 5751
. : milestone, 5695,
iast_GLOBAL (3.534 ms) : 3477, 3591
. : milestone, 3534,
profiling (2.135 ms) : 2116, 2155
. : milestone, 2135,
tracing (1.811 ms) : 1794, 1827
. : milestone, 1811,
section candidate
no_agent (1.18 ms) : 1167, 1192
. : milestone, 1180,
iast (3.203 ms) : 3163, 3243
. : milestone, 3203,
iast_FULL (5.543 ms) : 5489, 5598
. : milestone, 5543,
iast_GLOBAL (3.659 ms) : 3604, 3714
. : milestone, 3659,
profiling (2.13 ms) : 2109, 2151
. : milestone, 2130,
tracing (1.825 ms) : 1809, 1841
. : milestone, 1825,
DacapoParameters
See matching parameters
SummaryFound 0 performance improvements and 0 performance regressions! Performance is the same for 11 metrics, 1 unstable metrics. Execution time for tomcatgantt
title tomcat - execution time [CI 0.99] : candidate=1.57.0-SNAPSHOT~a7e125a566, baseline=1.57.0-SNAPSHOT~4e44b392c3
dateFormat X
axisFormat %s
section baseline
no_agent (1.478 ms) : 1467, 1490
. : milestone, 1478,
appsec (3.714 ms) : 3494, 3933
. : milestone, 3714,
iast (2.213 ms) : 2149, 2277
. : milestone, 2213,
iast_GLOBAL (2.261 ms) : 2196, 2326
. : milestone, 2261,
profiling (2.061 ms) : 2009, 2113
. : milestone, 2061,
tracing (2.048 ms) : 1997, 2099
. : milestone, 2048,
section candidate
no_agent (1.478 ms) : 1466, 1489
. : milestone, 1478,
appsec (3.712 ms) : 3492, 3933
. : milestone, 3712,
iast (2.222 ms) : 2157, 2287
. : milestone, 2222,
iast_GLOBAL (2.265 ms) : 2200, 2330
. : milestone, 2265,
profiling (2.098 ms) : 2044, 2152
. : milestone, 2098,
tracing (2.05 ms) : 2000, 2101
. : milestone, 2050,
Execution time for biojavagantt
title biojava - execution time [CI 0.99] : candidate=1.57.0-SNAPSHOT~a7e125a566, baseline=1.57.0-SNAPSHOT~4e44b392c3
dateFormat X
axisFormat %s
section baseline
no_agent (15.293 s) : 15293000, 15293000
. : milestone, 15293000,
appsec (14.751 s) : 14751000, 14751000
. : milestone, 14751000,
iast (17.948 s) : 17948000, 17948000
. : milestone, 17948000,
iast_GLOBAL (17.662 s) : 17662000, 17662000
. : milestone, 17662000,
profiling (14.547 s) : 14547000, 14547000
. : milestone, 14547000,
tracing (14.504 s) : 14504000, 14504000
. : milestone, 14504000,
section candidate
no_agent (14.997 s) : 14997000, 14997000
. : milestone, 14997000,
appsec (14.727 s) : 14727000, 14727000
. : milestone, 14727000,
iast (18.098 s) : 18098000, 18098000
. : milestone, 18098000,
iast_GLOBAL (17.758 s) : 17758000, 17758000
. : milestone, 17758000,
profiling (14.747 s) : 14747000, 14747000
. : milestone, 14747000,
tracing (14.702 s) : 14702000, 14702000
. : milestone, 14702000,
|
| Config.get().isDbMetadataFetchingOnQueryEnabled(); | ||
|
|
||
| private volatile boolean warnedAboutDBMPropagationMode = false; // to log a warning only once | ||
| private volatile boolean loggedInjectionError = false; |
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.
using a single boolean for all 3 places where we log, because they are all for a different DB type (oracle, mssql & postgres), so I think the chances that the same app would use several DB types and injection would fail for each is super super low.
| } | ||
|
|
||
| private void logInjectionErrorOnce(String vessel, Throwable t) { | ||
| if (!loggedInjectionError) { |
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.
A volatile read/write does not make this operation atomic, so concurrent calls may result in the log being emitted more than once. That behavior is acceptable for what we’re trying to achieve.
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.
yes, that's what I thought as well, plus we use the same mechanism in several other places in the codebase
| private void logInjectionErrorOnce(String vessel, Throwable t) { | ||
| if (!loggedInjectionError) { | ||
| loggedInjectionError = true; | ||
| log.warn( |
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.
you can also use the maker EXCLUDE_TELEMETRY if sending this is not valuable for us. Otherwise, please feel free to leave as it
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.
ah I didn't know about this, I'll add it thanks
amarziali
left a comment
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.
Thanks for having operated those changes
What Does This Do
Make sure we only log injection errors once.
We have that info on the span anyway.
I also raised the severity to WARN because there is a clear call to action in the log to make it disappear, so if customers are bothered by it, it shouldn't raise any tickets.
Motivation
Since debug logs send telemetry even when debug is disabled, this reduces the number of telemetry events we receive, and the performance overhead of the instrumentation.
Additional Notes
Contributor Checklist
type:and (comp:orinst:) labels in addition to any useful labelsclose,fixor any linking keywords when referencing an issue.Use
solvesinstead, and assign the PR milestone to the issueJira ticket: [PROJ-IDENT]