Append sql comments instead of prepend to prevent exceptions on CallableStatements

[jmeunier28]

What Does This Do

This PR updates the logic for the APM-DBM link feature introduced in #4847. It changes from prepending the sql comments, containing the APM trace context, to appending them to the raw sql. This requires no changes on the DBM side of things in either the agent or our backend.

Jira ticket: DBMON-2759

Motivation

This fixes an issue, which has been reported by several customers that executing CallableStatements with the following syntax causes exceptions to be thrown when enabling APM-DBM link:

The customer’s code base makes a CallableStatement statementvariable = connection.prepareCall("{call some_function_namehere(?,?,?) }";) and whenever both of these are active, the Java application starts throwing syntax error at or near "{" over and over.

We were able to reproduce this, using the latest version of the java tracer && an internal application. It seems to be caused by the SQL comments we inject being prepended instead of appended. For example, the issue of prepending the comment was reproduced with a simple java application (without APM-DBM link enabled), which did the following:

  final String storedProcedureCall = "/*test commnet*/ {call foo(?, ?)}";
  CallableStatement callableStmt = con.prepareCall(storedProcedureCall);
  callableStmt.setInt(1,10);
  callableStmt.setInt(2,11);
  callableStmt.execute();
  callableStmt.close(); 

... this throws the same exception with message Incorrect syntax near '{'.

Proof of Fix

After doing a custom build of this tracer code, we deployed our test app, which runs a combination of PreparedStatement/Statements/CallableStatement & no longer saw the Incorrect syntax near '{'. exception being thrown.

We were also able to confirm that injection is still working properly, e.g: our events are being properly decorated:

Expected DBM Behavior for Stored Procedures

Stored Procedures aren't supported for the APM-DBM usecase (unless the same app that is calling them is the thing that created the stored procedure & the linking was enabled). Otherwise, we wouldn't see the comments if someone had code that was simply calling EXEC proc or {call proc}, since the actual text we see in the activity code is either:

1. The entire stored proc text e.g.:

CREATE PROCEDURE foo
BEGIN
-- do stuff
END;

2. The currently executing query in the context of the stored proc

Neither, contains the text EXEC proc, which is what would have the comment injected via the tracer.

Obviously, this is of secondary concern here. Updating the tracer to append the comment will fix this edge case being reported by customers. We really don't want the feature to cause users to see exceptions being thrown in their production code.

[pr-commenter]

Benchmarks

Startup

Parameters

	Baseline	Candidate
commit	1.22.0-SNAPSHOT~848d3775b0	1.22.0-SNAPSHOT~3bc270d4db
config	baseline	candidate

See matching parameters

	Baseline	Candidate
application	insecure-bank	insecure-bank
module	Agent	Agent
parent	None	None
variant	iast	iast

Summary

Found 1 performance improvements and 0 performance regressions! Performance is the same for 53 cases.

scenario	Δ mean execution_time	candidate mean execution_time	baseline mean execution_time
scenario:insecure-bank:iast_TELEMETRY_OFF:Telemetry	better [-5.159ms; -0.370ms] or [-63.021%; -4.522%]	5.421ms	8.186ms

Startup time reports for insecure-bank

gantt
    title insecure-bank - global startup overhead: candidate=1.22.0-SNAPSHOT~3bc270d4db, baseline=1.22.0-SNAPSHOT~848d3775b0

    dateFormat X
    axisFormat %s
section tracing
Agent [baseline] (1.021 s) : 0, 1020681
Total [baseline] (8.723 s) : 0, 8722798
Agent [candidate] (1.022 s) : 0, 1022417
Total [candidate] (8.703 s) : 0, 8703462
section iast
Agent [baseline] (1.169 s) : 0, 1169430
Total [baseline] (9.307 s) : 0, 9307292
Agent [candidate] (1.145 s) : 0, 1144817
Total [candidate] (9.293 s) : 0, 9293410
section iast_TELEMETRY_OFF
Agent [baseline] (1.149 s) : 0, 1148620
Total [baseline] (9.232 s) : 0, 9231836
Agent [candidate] (1.145 s) : 0, 1145254
Total [candidate] (9.214 s) : 0, 9213527

Loading

• baseline results

Module	Variant	Duration	Δ tracing
Agent	tracing	1.021 s	-
Agent	iast	1.169 s	148.749 ms (14.6%)
Agent	iast_TELEMETRY_OFF	1.149 s	127.939 ms (12.5%)
Total	tracing	8.723 s	-
Total	iast	9.307 s	584.494 ms (6.7%)
Total	iast_TELEMETRY_OFF	9.232 s	509.038 ms (5.8%)

• candidate results

Module	Variant	Duration	Δ tracing
Agent	tracing	1.022 s	-
Agent	iast	1.145 s	122.4 ms (12.0%)
Agent	iast_TELEMETRY_OFF	1.145 s	122.837 ms (12.0%)
Total	tracing	8.703 s	-
Total	iast	9.293 s	589.948 ms (6.8%)
Total	iast_TELEMETRY_OFF	9.214 s	510.065 ms (5.9%)

gantt
    title insecure-bank - break down per module: candidate=1.22.0-SNAPSHOT~3bc270d4db, baseline=1.22.0-SNAPSHOT~848d3775b0

    dateFormat X
    axisFormat %s
section tracing
BytebuddyAgent [baseline] (637.994 ms) : 0, 637994
BytebuddyAgent [candidate] (638.807 ms) : 0, 638807
GlobalTracer [baseline] (292.796 ms) : 0, 292796
GlobalTracer [candidate] (293.123 ms) : 0, 293123
AppSec [baseline] (48.803 ms) : 0, 48803
AppSec [candidate] (49.335 ms) : 0, 49335
Remote Config [baseline] (676.352 µs) : 0, 676
Remote Config [candidate] (679.334 µs) : 0, 679
Telemetry [baseline] (5.989 ms) : 0, 5989
Telemetry [candidate] (6.085 ms) : 0, 6085
section iast
BytebuddyAgent [baseline] (784.072 ms) : 0, 784072
BytebuddyAgent [candidate] (766.497 ms) : 0, 766497
GlobalTracer [baseline] (276.535 ms) : 0, 276535
GlobalTracer [candidate] (272.11 ms) : 0, 272110
AppSec [baseline] (47.23 ms) : 0, 47230
AppSec [candidate] (47.681 ms) : 0, 47681
IAST [baseline] (15.566 ms) : 0, 15566
IAST [candidate] (15.903 ms) : 0, 15903
Remote Config [baseline] (601.676 µs) : 0, 602
Remote Config [candidate] (581.494 µs) : 0, 581
Telemetry [baseline] (10.401 ms) : 0, 10401
Telemetry [candidate] (7.567 ms) : 0, 7567
section iast_TELEMETRY_OFF
BytebuddyAgent [baseline] (766.29 ms) : 0, 766290
BytebuddyAgent [candidate] (764.27 ms) : 0, 764270
GlobalTracer [baseline] (274.764 ms) : 0, 274764
GlobalTracer [candidate] (273.999 ms) : 0, 273999
AppSec [baseline] (46.38 ms) : 0, 46380
AppSec [candidate] (46.593 ms) : 0, 46593
IAST [baseline] (17.686 ms) : 0, 17686
IAST [candidate] (19.735 ms) : 0, 19735
Remote Config [baseline] (664.856 µs) : 0, 665
Remote Config [candidate] (659.006 µs) : 0, 659
Telemetry [baseline] (8.186 ms) : 0, 8186
Telemetry [candidate] (5.421 ms) : 0, 5421

Loading

Startup time reports for petclinic

gantt
    title petclinic - global startup overhead: candidate=1.22.0-SNAPSHOT~3bc270d4db, baseline=1.22.0-SNAPSHOT~848d3775b0

    dateFormat X
    axisFormat %s
section tracing
Agent [baseline] (1.023 s) : 0, 1022704
Total [baseline] (9.363 s) : 0, 9362823
Agent [candidate] (1.021 s) : 0, 1020700
Total [candidate] (9.243 s) : 0, 9243080
section appsec
Agent [baseline] (1.107 s) : 0, 1107420
Total [baseline] (9.276 s) : 0, 9275934
Agent [candidate] (1.107 s) : 0, 1107478
Total [candidate] (9.302 s) : 0, 9302145
section iast
Agent [baseline] (1.153 s) : 0, 1153079
Total [baseline] (9.409 s) : 0, 9408722
Agent [candidate] (1.146 s) : 0, 1145506
Total [candidate] (9.383 s) : 0, 9382583
section profiling
Agent [baseline] (1.199 s) : 0, 1198942
Total [baseline] (9.524 s) : 0, 9523941
Agent [candidate] (1.195 s) : 0, 1194545
Total [candidate] (9.522 s) : 0, 9521547

Loading

• baseline results

Module	Variant	Duration	Δ tracing
Agent	tracing	1.023 s	-
Agent	appsec	1.107 s	84.716 ms (8.3%)
Agent	iast	1.153 s	130.375 ms (12.7%)
Agent	profiling	1.199 s	176.239 ms (17.2%)
Total	tracing	9.363 s	-
Total	appsec	9.276 s	-86.889 ms (-0.9%)
Total	iast	9.409 s	45.899 ms (0.5%)
Total	profiling	9.524 s	161.118 ms (1.7%)

• candidate results

Module	Variant	Duration	Δ tracing
Agent	tracing	1.021 s	-
Agent	appsec	1.107 s	86.778 ms (8.5%)
Agent	iast	1.146 s	124.806 ms (12.2%)
Agent	profiling	1.195 s	173.845 ms (17.0%)
Total	tracing	9.243 s	-
Total	appsec	9.302 s	59.065 ms (0.6%)
Total	iast	9.383 s	139.503 ms (1.5%)
Total	profiling	9.522 s	278.467 ms (3.0%)

gantt
    title petclinic - break down per module: candidate=1.22.0-SNAPSHOT~3bc270d4db, baseline=1.22.0-SNAPSHOT~848d3775b0

    dateFormat X
    axisFormat %s
section tracing
BytebuddyAgent [baseline] (638.583 ms) : 0, 638583
BytebuddyAgent [candidate] (637.405 ms) : 0, 637405
GlobalTracer [baseline] (293.53 ms) : 0, 293530
GlobalTracer [candidate] (293.211 ms) : 0, 293211
AppSec [baseline] (49.304 ms) : 0, 49304
AppSec [candidate] (49.039 ms) : 0, 49039
Remote Config [baseline] (689.277 µs) : 0, 689
Remote Config [candidate] (687.56 µs) : 0, 688
Telemetry [baseline] (6.114 ms) : 0, 6114
Telemetry [candidate] (6.093 ms) : 0, 6093
section appsec
BytebuddyAgent [baseline] (637.702 ms) : 0, 637702
BytebuddyAgent [candidate] (637.28 ms) : 0, 637280
GlobalTracer [baseline] (291.423 ms) : 0, 291423
GlobalTracer [candidate] (291.472 ms) : 0, 291472
AppSec [baseline] (137.704 ms) : 0, 137704
AppSec [candidate] (138.114 ms) : 0, 138114
Remote Config [baseline] (637.859 µs) : 0, 638
Remote Config [candidate] (639.386 µs) : 0, 639
Telemetry [baseline] (5.66 ms) : 0, 5660
Telemetry [candidate] (5.679 ms) : 0, 5679
section iast
BytebuddyAgent [baseline] (772.459 ms) : 0, 772459
BytebuddyAgent [candidate] (767.029 ms) : 0, 767029
GlobalTracer [baseline] (273.111 ms) : 0, 273111
GlobalTracer [candidate] (271.686 ms) : 0, 271686
AppSec [baseline] (46.524 ms) : 0, 46524
AppSec [candidate] (46.82 ms) : 0, 46820
Remote Config [baseline] (593.728 µs) : 0, 594
Remote Config [candidate] (606.696 µs) : 0, 607
Telemetry [baseline] (9.14 ms) : 0, 9140
Telemetry [candidate] (7.569 ms) : 0, 7569
IAST [baseline] (16.668 ms) : 0, 16668
IAST [candidate] (17.367 ms) : 0, 17367
section profiling
ProfilingAgent [baseline] (80.537 ms) : 0, 80537
ProfilingAgent [candidate] (80.713 ms) : 0, 80713
BytebuddyAgent [baseline] (651.996 ms) : 0, 651996
BytebuddyAgent [candidate] (649.232 ms) : 0, 649232
GlobalTracer [baseline] (356.888 ms) : 0, 356888
GlobalTracer [candidate] (355.502 ms) : 0, 355502
AppSec [baseline] (49.225 ms) : 0, 49225
AppSec [candidate] (49.264 ms) : 0, 49264
Remote Config [baseline] (672.399 µs) : 0, 672
Remote Config [candidate] (643.932 µs) : 0, 644
Telemetry [baseline] (6.068 ms) : 0, 6068
Telemetry [candidate] (6.044 ms) : 0, 6044
Profiling [baseline] (80.561 ms) : 0, 80561
Profiling [candidate] (80.737 ms) : 0, 80737

Loading

Load

Parameters

	Baseline	Candidate
commit	1.22.0-SNAPSHOT~848d3775b0	1.22.0-SNAPSHOT~3bc270d4db
config	baseline	candidate
end_time	2023-10-26T16:26:51	2023-10-26T16:43:06
start_time	2023-10-26T16:26:38	2023-10-26T16:42:53

See matching parameters

	Baseline	Candidate
application	insecure-bank	insecure-bank
variant	iast	iast

Summary

Found 0 performance improvements and 0 performance regressions! Performance is the same for 22 cases.

Request duration reports for insecure-bank

gantt
    title insecure-bank - request duration [CI 0.99] : candidate=1.22.0-SNAPSHOT~3bc270d4db, baseline=1.22.0-SNAPSHOT~848d3775b0
    dateFormat X
    axisFormat %s
section baseline
no_agent (369.718 µs) : 349, 390
.   : milestone, 370,
iast (465.633 µs) : 445, 487
.   : milestone, 466,
iast_FULL (521.923 µs) : 501, 543
.   : milestone, 522,
iast_INACTIVE (440.486 µs) : 419, 462
.   : milestone, 440,
iast_TELEMETRY_OFF (458.891 µs) : 437, 481
.   : milestone, 459,
tracing (441.618 µs) : 420, 463
.   : milestone, 442,
section candidate
no_agent (366.171 µs) : 346, 386
.   : milestone, 366,
iast (470.737 µs) : 450, 492
.   : milestone, 471,
iast_FULL (523.371 µs) : 503, 544
.   : milestone, 523,
iast_INACTIVE (435.542 µs) : 415, 456
.   : milestone, 436,
iast_TELEMETRY_OFF (466.913 µs) : 446, 488
.   : milestone, 467,
tracing (439.293 µs) : 418, 460
.   : milestone, 439,

Loading

• baseline results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	369.718 µs [349.494 µs, 389.942 µs]	-
iast	465.633 µs [444.732 µs, 486.535 µs]	95.915 µs (25.9%)
iast_FULL	521.923 µs [501.3 µs, 542.546 µs]	152.205 µs (41.2%)
iast_INACTIVE	440.486 µs [419.355 µs, 461.618 µs]	70.768 µs (19.1%)
iast_TELEMETRY_OFF	458.891 µs [437.02 µs, 480.762 µs]	89.173 µs (24.1%)
tracing	441.618 µs [420.105 µs, 463.131 µs]	71.9 µs (19.4%)

• candidate results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	366.171 µs [346.255 µs, 386.086 µs]	-
iast	470.737 µs [449.866 µs, 491.608 µs]	104.567 µs (28.6%)
iast_FULL	523.371 µs [502.548 µs, 544.194 µs]	157.2 µs (42.9%)
iast_INACTIVE	435.542 µs [414.668 µs, 456.416 µs]	69.372 µs (18.9%)
iast_TELEMETRY_OFF	466.913 µs [445.695 µs, 488.131 µs]	100.743 µs (27.5%)
tracing	439.293 µs [418.287 µs, 460.298 µs]	73.122 µs (20.0%)

Request duration reports for petclinic

gantt
    title petclinic - request duration [CI 0.99] : candidate=1.22.0-SNAPSHOT~3bc270d4db, baseline=1.22.0-SNAPSHOT~848d3775b0
    dateFormat X
    axisFormat %s
section baseline
no_agent (1.338 ms) : 1319, 1358
.   : milestone, 1338,
appsec (1.709 ms) : 1684, 1734
.   : milestone, 1709,
iast (1.459 ms) : 1435, 1484
.   : milestone, 1459,
profiling (1.444 ms) : 1420, 1469
.   : milestone, 1444,
tracing (1.427 ms) : 1403, 1452
.   : milestone, 1427,
section candidate
no_agent (1.326 ms) : 1307, 1345
.   : milestone, 1326,
appsec (1.705 ms) : 1681, 1729
.   : milestone, 1705,
iast (1.489 ms) : 1465, 1514
.   : milestone, 1489,
profiling (1.495 ms) : 1470, 1520
.   : milestone, 1495,
tracing (1.452 ms) : 1428, 1476
.   : milestone, 1452,

Loading

• baseline results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	1.338 ms [1.319 ms, 1.358 ms]	-
appsec	1.709 ms [1.684 ms, 1.734 ms]	370.794 µs (27.7%)
iast	1.459 ms [1.435 ms, 1.484 ms]	120.822 µs (9.0%)
profiling	1.444 ms [1.42 ms, 1.469 ms]	105.831 µs (7.9%)
tracing	1.427 ms [1.403 ms, 1.452 ms]	88.989 µs (6.6%)

• candidate results

Variant	Request duration [CI 0.99]	Δ no_agent
no_agent	1.326 ms [1.307 ms, 1.345 ms]	-
appsec	1.705 ms [1.681 ms, 1.729 ms]	379.134 µs (28.6%)
iast	1.489 ms [1.465 ms, 1.514 ms]	163.341 µs (12.3%)
profiling	1.495 ms [1.47 ms, 1.52 ms]	169.115 µs (12.8%)
tracing	1.452 ms [1.428 ms, 1.476 ms]	125.948 µs (9.5%)

[jmeunier28]

Looks like the tests failures aren't related to my PR?

* What went wrong:
Execution failed for task ':dd-java-agent:instrumentation:grizzly-http-2.3.20:test'.
> There were failing tests. See the report at: file:///home/circleci/dd-trace-java/workspace/dd-java-agent/instrumentation/grizzly-http-2.3.20/build/reports/tests/test/index.html

... although I'm not sure why this is failing now:

self = <test_db_integrations_sql.Test_Agent_Mssql_db_integration object at 0x7f05030259d0>

    def test_obfuscate_query(self):
        """ All queries come out obfuscated from agent """
        for db_operation, request in self.requests[self.db_service].items():
            span = self._get_sql_span_for_request(request)
            # We launch all queries with two parameters (from weblog)
            if db_operation == "insert":
                expected_obfuscation_count = 1
            elif db_operation == "procedure":
                # Insert and procedure:These operations also receive two parameters, but are obfuscated as only one.
                # Nodejs: The proccedure has a input parameter, but we are calling through method `execute`` and we can't see the parameters in the traces
                expected_obfuscation_count = 0 if context.library.library == "nodejs" else 2
            else:
                expected_obfuscation_count = 2
    
>           observed_obfuscation_count = span["meta"]["sql.query"].count("?")
E           TypeError: 'NoneType' object is not subscriptable

tests/integrations/test_db_integrations_sql.py:556: TypeError

https://app.circleci.com/pipelines/github/DataDog/dd-trace-java/30177/workflows/06d05af0-63ff-41e8-809e-a2c72d369297/jobs/1022674

[ygree]

Looks good! Except for integrations-core. If it wasn't updated on purpose then follow https://github.com/DataDog/dd-trace-java/blob/master/CONTRIBUTING.md#git-submodule-setup to exclude it from the change.

[jmeunier28]

Looks good! Except for integrations-core. If it wasn't updated on purpose then follow https://github.com/DataDog/dd-trace-java/blob/master/CONTRIBUTING.md#git-submodule-setup to exclude it from the change.

@ygree ah okay, I ran git config --local submodule.recurse true and then rebase on master, is this correct?

[PerfectSlayer]

Looks like integration-core is still in your changeset.
Try git submodule update to update it and commit it.
You can then squash your 3 commits together and force push it to your PR branch.

[ygree]

Looks good to me!