1223450 - Work out why New Relic doesn't record the exact SQL, even though we're using the "Raw" option

Status: RESOLVED FIXED

(Tree Management :: Treeherder: Infrastructure, defect, P2)

Description

[Ed Morley [:emorley]]

This has been bugging me for a while.

We have the "Raw option":
https://docs.newrelic.com/docs/apm/transactions/transaction-traces/configuring-transaction-traces#fields

...set here:
https://rpm.newrelic.com/accounts/677903/applications/4180461/edit

Yet the SQL traces still look like:

SELECT                     j.id,                     j.`job_guid`,                     j.`signature`,                     j.`job_coalesced_to_guid`,                     j.`build_platform_id`,                     j.`option_collection_hash`,                     j.failure_classification_id,                     m.`name` AS machine_name,                     mp.`platform` AS platform,                     mp.`os_name` AS machine_platform_os,                     mp.`architecture` AS machine_platform_architecture,                     bp.`platform` AS build_platform,                     bp.`os_name` AS build_os,                     bp.`architecture` AS build_architecture,                     j.`job_type_id` AS job_type_id,                     jt.`name` AS job_type_name,                     jt.`symbol` AS job_type_symbol,                     jt.`description` AS job_type_description,      jg.`name` AS job_group_name,                     jt.`job_group_id` AS job_group_id,                     jg.`symbol` AS job_group_symbol,                     jg.`description` AS job_group_description,                     j.`who`,                     j.`result_set_id`,                     j.`result`,                     j.`state`,                     j.`reason`,                     j.`start_timestamp`,                     j.`end_timestamp`,                     j.`submit_timestamp`,                     j.`running_eta`,                     j.`last_modified`,                     j.`tier`,                     rds.`name` AS ref_data_name,                     rds.`build_system_type` AS build_system_type                   FROM `job` AS j                   LEFT JOIN `treeherder`.`machine` AS m                     ON j.`machine_id` = m.id                   LEFT JOIN `treeherder`.`machine_platform` AS mp                     ON j.`machine_platform_id` = mp.id                   LEFT JOIN `treeherder`.`build_platform` AS bp                     ON j.`build_platform_id` = bp.id                   LEFT JOIN `treeherder`.`job_type` AS jt                     ON j.`job_type_id` = jt.id       LEFT JOIN `treeherder`.`job_group` AS jg                     ON jt.`job_group_id` = jg.id                   LEFT JOIN `treeherder`.reference_data_signatures rds                     ON j.signature = rds.signature                   WHERE 1                   AND j.result_set_id IN(%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s) AND j.signature NOT IN (%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s)                   GROUP BY j.id                   ORDER BY j.id                    LIMIT 2000 OFFSET 0

(From https://rpm.newrelic.com/accounts/677903/applications/4180461/datastores?tw%5Bend%5D=1447177130&tw%5Bstart%5D=1447133930#/overview/All/trace/?id=3fc9ee-a4bba0c5-87d1-11e5-900f-b82a72d22a14&metric=Datastore%2Fstatement%2FMySQL%2Fjob%2Fselect )

(The crappy whitespace is bug 1182485)

I'll file a ticket against New Relic.

Comment 1

[Ed Morley [:emorley]]

I've filed:
https://support.newrelic.com/tickets/169350/edit

"""
Hi!
We've set the "Record SQL?" option to "Raw", here:
https://rpm.newrelic.com/accounts/677903/applications/4180461/edit

However the SQL stored with slow transactions is still obfuscated, eg:
https://rpm.newrelic.com/accounts/677903/applications/4180461/datastores?tw%5Bend%5D=1447177130&tw%5Bstart%5D=1447133930#/overview/All/trace/?id=3fc9ee-a4bba0c5-87d1-11e5-900f-b82a72d22a14&metric=Datastore%2Fstatement%2FMySQL%2Fjob%2Fselect

...contains:
``AND j.result_set_id IN(%s,%s,%s,%s,%s,%s,%s,%s,%s,%s,%s)``

...where I would have expected the actual integers rather than ``%s``.

The same is also present in the transaction section, eg:

https://rpm.newrelic.com/accounts/677903/applications/4180461/transactions?tw%5Bend%5D=1447177525&tw%5Bstart%5D=1447134325#id=5b225765625472616e73616374696f6e2f46756e6374696f6e2f747265656865726465722e7765626170702e6170692e6a6f62733a4a6f6273566965775365742e6c697374222c22225d&tab-detail_3fca17-228691eb-87d2-11e5-900f-b82a72d22a14=sql_statements&app_trace_id=3fca17-228691eb-87d2-11e5-900f-b82a72d22a14
(click the "SQL statements" tab).

This isn't what I expected, from reading the docs:
https://docs.newrelic.com/docs/apm/transactions/transaction-traces/configuring-transaction-traces#fields
https://docs.newrelic.com/docs/apm/transactions/transaction-traces/security-options-transaction-traces#sql-http

Any ideas? 

Many thanks,
"""

Comment 2

[Ed Morley [:emorley]]

Their reply:
"""
Thank you, as always, for providing thorough information in your ticket. Your configuration is indeed correctly being registered to collect "raw" SQL. However, the reason you're not seeing this raw detail is because you're using Django.

In Django, all SQL queries are parameterized and do not actually contain the values used to fill out the query. As such, the Python agent will see only the SQL prior to insertion of values.

In short, the "raw" SQL configuration is working properly, but parameterized SQL queries will look pretty much the same in obfuscated or raw mode from the point of view of our agent.

Right now, we don't have a workaround to suggest, since not using parameterized SQL could cause some security gaps. However, I hope this helps to clarify why you're seeing data presented this way even when using the "raw" SQL configuration.
"""


My reply:
"""
Thank you for the quick reply.

I was looking at the Python agent source and noticed that the parameters passed to the mysql python connector's `.execute()`'s parameters argument are tracked as `sql_parameters` in `DatabaseTrace` (`newrelic/api/database_trace.py:28`). Is the issue that these being sent to the New Relic API, but currently not rendered in the UI?

(Whilst we use Django, we actually are currently rolling our own DB queries in many places, using (an awful) third party library called datasource, which uses the python mysql connector under the hood. We're wanting to switch entirely to using the Django ORM but it doesn't yet support multi-databases in quite the way we're using them)
"""


Their reply:
"""
As you have noticed, parts of the query are displayed as %s which seems like obfuscation, however that's not the result of our obfuscation. When New Relic obfuscates, we replace the string we want to obfuscate with ?. What you are seeing is the result of using bind parameters (or, bind variables).

I am sure you are very familiar with this, but just for example's sake, instead of having the parameters inline like this:

cursor.execute("""update test_table set foo=4.0 where blah=1""")

Using bind parameters it would look like this:

cursor.execute("""update test_table set foo=%s where blah=%s""", (4.0, 1))

Using bind parameters is more secure, and is the preferred way to write queries. But, that means that choosing "raw" for record_sql doesn't show every last value in the query.

The larger issue is not just that if you are using a web framework, then "raw" won't show all the values. It's if you are using bind parameters when constructing queries. Now, almost all web frameworks do use them already, but using bind parameters is recommended even if you are writing your own queries using the DB client library directly.

In short, it's not using the web framework that is the important detail. It's the usage of bind parameters. We currently do not have a way to get around this, and will not show the values sent as bind params.

While I don't suspect my answer to change, it may be helpful to see how you are using this datasource library so we can see how you are querying MySQL.
"""

Comment 3

[Ed Morley [:emorley]]

My replies:
"""
I probably didn't clarify enough in the last message - but I understood what you meant about bind parameters (and agree that everyone should be using them - our `datasource` library does too), but was saying that looking at the code in the New Relic Python agent, it seems like the agent could be capturing the bind parameters **as well** - and then either:
* substituting them into the SQL when creating the SQL string to send to New Relic's monitoring servers
* send both the raw SQL string (with placeholders) *and* the bind parameters to New Relic's monitoring servers, where server-side processing would construct the actual SQL that got run

Is this something you would be interested in doing? :-)


---


ie the mysql database connector's .execute() is wrapped by CursorWrapper here:
https://github.com/edmorley/newrelic-python-agent/blob/v2.56.0.42/newrelic/newrelic/hooks/database_dbapi2.py#L15-L27

The signature for that function is:
```
def execute(self, sql, parameters=DEFAULT, *args, **kwargs):
```

...where ``parameters`` are the bind parameters of interest.

That wrapper then goes on to pass ``parameters`` if set, to ``DatabaseTrace``:
https://github.com/edmorley/newrelic-python-agent/blob/v2.56.0.42/newrelic/newrelic/hooks/database_dbapi2.py#L20
```
with DatabaseTrace(transaction, sql, self._nr_dbapi2_module,
self._nr_connect_params, self._nr_cursor_params,
parameters, (args, kwargs)):
```

``DatabaseTrace``'s signature is:
https://github.com/edmorley/newrelic-python-agent/blob/v2.56.0.42/newrelic/newrelic/api/database_trace.py#L30-L32
```
def __init__(self, transaction, sql, dbapi2_module=None,
connect_params=None, cursor_params=None,
sql_parameters=None, execute_params=None):
```

So ``parameters`` is being passed to ``sql_parameters``, and stored in the ``DatabaseTrace`` instance:
https://github.com/edmorley/newrelic-python-agent/blob/v2.56.0.42/newrelic/newrelic/api/database_trace.py#L45

And then passed to ``DatabaseNode`` during its creation:
https://github.com/edmorley/newrelic-python-agent/blob/v2.56.0.42/newrelic/newrelic/api/database_trace.py#L106

``sql_parameters`` then gets used as part of the explain generation, eg:
https://github.com/edmorley/newrelic-python-agent/blob/v2.56.0.42/newrelic/newrelic/core/database_utils.py#L629

However is not passed to ``TraceNode``:
https://github.com/edmorley/newrelic-python-agent/blob/v2.56.0.42/newrelic/newrelic/core/database_node.py#L290-L292

...only the placeholder-containing SQL is:
https://github.com/edmorley/newrelic-python-agent/blob/v2.56.0.42/newrelic/newrelic/core/database_node.py#L269

Similarly, in ``StatsEngine.slow_sql_data``, whilst ``sql_parameters`` is passed to the explain plan generation:
https://github.com/edmorley/newrelic-python-agent/blob/v2.56.0.42/newrelic/newrelic/core/stats_engine.py#L916

...it's not added to the ``data`` list here:
https://github.com/edmorley/newrelic-python-agent/blob/v2.56.0.42/newrelic/newrelic/core/stats_engine.py#L940-L949

-> So the bind parameters are being captured, just not submitted to the New Relic monitoring servers.

They could either be substituted in client-side, or else as part of processing server side, using something like what the Python mysql connector does here:
https://github.com/farcepest/MySQLdb1/blob/MySQLdb-1.2.5/MySQLdb/cursors.py#L183-L187

Does that make more sense? :-)


---


There's also ``cursor._last_executed`` for the MySQLdb driver, which shows you the actual SQL statement that ran (after parameter substitution occurred):
http://stackoverflow.com/questions/7071166/print-the-actual-query-mysqldb-runs/7190914#7190914
"""


Their reply:
"""
Awesome, awesome follow up. Everything made sense and your notes have started a discussion with ALL of our agent development teams to see why we do not do it this way and how/if we should change. It is possible, it just is not the way we handle this at this time.

As it stands now, the ability to see the values of the bind params is still going to be a feature request that I will file on your behalf. Unfortunately, we do not have a work around that will work. If and when we implement this functionality, you will be the first customer to know.

Thank you as always for the tremendous follow through and extra explanation. I personally always learn quite a bit each time we talk :)

Since the feature request is filed, I am going to mark this as "closed" for now, but if you have any additional questions, just reply to this ticket and it will be reopened for you.
"""


As such, I'm going to mark this as fixed for now, since we now know the reason, albeit there's nothing we can do about it - but at least they have a ticket open for adding this in the future.