Problem with Web2py sql that includes % on Postgres; breaking New Relic

[pbreit]

I have been trying out New Relic and have found that any queries that include '%' are breaking.

This is what Graham at New Relic advised:

As far as I can tell: ILIKE '%|featured|%' would cause a problem because the mogrify() function in psycopg2 cursor which does variable substitution doesn't care about quoted values and will try and do a % substitution where ever it sees one. The only time it will not is when is actually %% meaning a single escaped %, which it would then replace with just a single %. So right now to me looks like Web2Py is generating incorrect SQL. In general it is regarded as best practice to never do full SQL construction yourself and to always rely on DBAPI module to do variable text interpolation and Web2Py isn't doing that. The errors I get look like this: Traceback (most recent call last): File "/opt/web2py/gluon/restricted.py", line 204, in restricted exec ccode in environment File "/opt/web2py/applications/init/controllers/default.py", line 129, in <module> File "/opt/web2py/gluon/globals.py", line 162, in <lambda> self._caller = lambda f: f() File "/opt/web2py/applications/init/controllers/default.py", line 20, in home (db.auth_user.id==db.item.seller)).select(limitby=(0,4), orderby='<random>') File "/opt/web2py/gluon/dal.py", line 5825, in select return self.db._adapter.select(self.query,fields,attributes) File "/opt/web2py/gluon/dal.py", line 1275, in select rows = response(sql) File "/opt/web2py/gluon/dal.py", line 1265, in response self.execute(sql) File "/opt/web2py/gluon/dal.py", line 1351, in execute return self.log_execute(*a, **b) File "/opt/web2py/gluon/dal.py", line 1345, in log_execute ret = self.cursor.execute(*a, **b) File "/usr/local/lib/python2.6/dist-packages/newrelic-1.0.5.156-py2.6.egg/newrelic/hooks/database_dbapi2.py", line 38, in execute return self._nr_cursor.execute(sql, parameters) IndexError: tuple index out of range File /usr/local/lib/python2.6/dist-packages/newrelic-1.0.5.156-py2.6.egg/newrelic/hooks/database_dbapi2.py in execute at line 38 code argumentsvariables Function argument list (self=<newrelic.hooks.database_dbapi2.CursorWrapper object>, sql='SELECT item.id, item.title, item.seller, item.s...item.seller)) ORDER BY RANDOM() LIMIT 4 OFFSET 0;', parameters=()) Code listing 33. 34. 35. 36. 37. 38. 39. 40. 41. 42. transaction = newrelic.api.transaction.transaction() if not transaction: return self._nr_cursor.execute(sql, parameters) with newrelic.api.database_trace.DatabaseTrace( transaction, sql, module): return self._nr_cursor.execute(sql, parameters) def executemany(self, sql, seq_of_parameters=[]): transaction = newrelic.api.transaction.transaction() if not transaction: Variables self._nr_cursor.execute <built-in method execute of psycopg2._psycopg.cursor object> self <newrelic.hooks.database_dbapi2.CursorWrapper object> self._nr_cursor <cursor object at 0x29ffc18; closed: 0> parameters () sql 'SELECT item.id, item.title, item.seller, item.s...item.seller)) ORDER BY RANDOM() LIMIT 4 OFFSET 0;'

[pbreit]

Bump

[Massimo Di Pierro]

I disagree. this

SELECT * FROM table where field ILIKE '%|featured|%';

is valid SQL. % does not need to be escaped in SQL and, in fact, it is
used for pattern patching:

http://www.postgresql.org/docs/7.4/static/functions-matching.html

Perhaps new-relic may have a bug.

On Dec 14, 5:30 pm, pbreit <pbreitenb...@gmail.com> wrote:
> I have been trying out New Relic and have found that any queries that
> include '%' are breaking.
>
> This is what Graham at New Relic advised:
>
>   As far as I can tell:
>
> ILIKE '%|featured|%'
>
> would cause a problem because the mogrify() function in psycopg2 cursor
> which does variable substitution doesn't care about quoted values and will
> try and do a % substitution where ever it sees one. The only time it will
> not is when is actually %% meaning a single escaped %, which it would then
> replace with just a single %.
>
> So right now to me looks like Web2Py is generating incorrect SQL.
>
> In general it is regarded as best practice to never do full SQL
> construction yourself and to always rely on DBAPI module to do variable
> text interpolation and Web2Py isn't doing that.
>
> The errors I get look like this:
>
> Traceback (most recent call last):
>   File "/opt/web2py/gluon/restricted.py", line 204, in restricted
>     exec ccode in environment

>   File "/opt/web2py/applications/init/controllers/default.py" <https://test.pricetack.com/admin/edit/init/controllers/default.py>, line 129, in <module>

>   File "/opt/web2py/gluon/globals.py", line 162, in <lambda>
>     self._caller = lambda f: f()

>   File "/opt/web2py/applications/init/controllers/default.py" <https://test.pricetack.com/admin/edit/init/controllers/default.py>, line 20, in home

>     (db.auth_user.id==db.item.seller)).select(limitby=(0,4), orderby='<random>')
>   File "/opt/web2py/gluon/dal.py", line 5825, in select
>     return self.db._adapter.select(self.query,fields,attributes)
>   File "/opt/web2py/gluon/dal.py", line 1275, in select
>     rows = response(sql)
>   File "/opt/web2py/gluon/dal.py", line 1265, in response
>     self.execute(sql)
>   File "/opt/web2py/gluon/dal.py", line 1351, in execute
>     return self.log_execute(*a, **b)
>   File "/opt/web2py/gluon/dal.py", line 1345, in log_execute
>     ret = self.cursor.execute(*a, **b)

>   File "/usr/local/lib/python2.6/dist-packages/newrelic-1.0.5.156-py2.6.egg/newrel ic/hooks/database_dbapi2.py", line 38, in execute

>     return self._nr_cursor.execute(sql, parameters)
> IndexError: tuple index out of range
>

> *File
> /usr/local/lib/python2.6/dist-packages/newrelic-1.0.5.156-py2.6.egg/newreli c/hooks/database_dbapi2.py
> in execute at line 38* code argumentsvariables

> Function argument list
>
> (self=<newrelic.hooks.database_dbapi2.CursorWrapper object>, sql='SELECT
> item.id, item.title, item.seller, item.s...item.seller)) ORDER BY RANDOM()
> LIMIT 4 OFFSET 0;', parameters=())
> Code listing
>
> 33.
> 34.
> 35.
> 36.
> 37.
> 38.
>
> 39.
> 40.
> 41.
> 42.
>
>             transaction = newrelic.api.transaction.transaction()
>             if not transaction:
>                 return self._nr_cursor.execute(sql, parameters)
>             with newrelic.api.database_trace.DatabaseTrace(
>                     transaction, sql, module):
>                 return self._nr_cursor.execute(sql, parameters)
>
>         def executemany(self, sql, seq_of_parameters=[]):
>             transaction = newrelic.api.transaction.transaction()
>             if not transaction:
>

> Variablesself._nr_cursor.execute<built-in method execute of
> psycopg2._psycopg.cursor object>self<newrelic.hooks.database_dbapi2.CursorWrapper
> object>self._nr_cursor<cursor object at 0x29ffc18; closed: 0>parameters()sql'SELECT

[pbreit]

I tend to agree. Even if it's not "best practice" (probably debatable), it should still be supported by New Relic).

[pbreit]

Although it does seem like psycopg prefers parameterization.

[Graham Dumpleton]

On Dec 16, 7:13 am, Massimo Di Pierro <massimo.dipie...@gmail.com>
wrote:

> I disagree. this
>
> SELECT * FROM table where field ILIKE '%|featured|%';
>
> is valid SQL. % does not need to be escaped in SQL and, in fact, it is
> used for pattern patching:
>
> http://www.postgresql.org/docs/7.4/static/functions-matching.html
>
> Perhaps new-relic may have a bug.

It may be valid SQL as eventually received by database, but you are
ignoring that the pscyopg2 adapter will do variable substitution prior
to it getting passed to the database.

The pscyop2 adapter is interpreting the %| as trigger to look for
variable to substitute and thus the index error when it finds
parameter tuple is empty.

The substitution looks for:

%% - replace with %
%(name) - believe this expects parameters to be a dictionary and
does name based lookup
%s - in sequence as finds these gets next value from parameter list/
tuple.

For the latter people usually use %s, but psycopg2 will actually
ignore the character if got through above checks and thus why %| is
also triggering variable substitution.

All DBAPI modules support parameter substitution in some way by the
placeholder differs.

SQLite for example uses ? instead of % variants above.

So, any SQL you provide has to for the specific database adapter
escape placeholders where they aren't actually meant to be used for
variable substitution.

The New Relic agent passes through exactly what above layer provides
and so not doing this in framework/application code would lead to the
problems where substitution not occurring.

Graham

[Graham Dumpleton]

Are you perhaps introspecting the type of the cursor object in some
way and changing behaviour based on that? We wrap the cursor object
returned by DBAPI2 module and so you wouldn't see original psycopg2
cursor type.

Graham

On Dec 16, 10:02 am, Graham Dumpleton <graham.dumple...@gmail.com>
wrote:

[Graham Dumpleton]

Okay, have an answer.

Looks like we may be falling into a bit of undefined territory within
the DBAPI2 specification that I can see and different DBAPI2 modules
behave differently.

Some will take parameters as evaluating False to mean no parameters
and so not trigger doing any variable substitution. The psycopg2
adapter is taking even an empty list/tuple as meaning there may be and
is so still trying to do substitution even though it cant work.

This is the classic problem in Python as to how one indicates an
optional parameter. :-(

Graham

On Dec 16, 10:14 am, Graham Dumpleton <graham.dumple...@gmail.com>

[pbreit]

Thanks for investigating. Is it something that is fixable on NewRelic's end? Or would Web2py need to change how it submits the query?

From my brief research, it does seem like psycopg expects queries to be parameterized (ie, using string substitution). However my query works fine when not wrapped by New Relic.

[pbreit]

I found a fix but I am not qualified to determine if it should go in as a patch.

I basically added a % on each side. I think %% distills down to % without triggering a substitution.

http://code.google.com/p/web2py/source/browse/gluon/dal.py#1924

From:

key = '%|'+str(second).replace('|','||').replace('%','%%')+'|%'

To:

key = '%%|'+str(second).replace('|','||').replace('%','%%')+'|%%'

[Graham Dumpleton]

I am making a change on New Relic side. You can't do what you are doing as that then will cause wrong thing to happen for when New Relic not used.

So am changing things to accommodate for what psycopg2 interprets as default argument.

The issue hasn't come up before because Web2Py is the only framework so far that doesn't actually use parameter substitution all the time.

That Web2Py creates expanded SQL could actually be a problem because it will completely defeat a cache we use to avoid having to parse operation/table information out of queries all the time. It relies on parameterised SQL being the norm to gain efficiencies. For Web2Py the parse has to be done on pretty well every SQL as all will be unique and the overhead is not insignificant. So, performance may be impacted and memory overhead may also be a lot larger than other frameworks. We may have to completely disable the cache if know Web2Py is used to avoid memory overhead issues, We will not be able to solve the performance overhead issue because of how Web2Py doesn't use parameterised SQL however. Worst case the agent simply may not be able to be used with Web2Py because of this for certain types of database usage.

Graham

[pbreit]

I tried the fix without New Relic and it worked OK.

Will try out your patched agent tomorrow.

It does seem like Web2py would be well off sending in parameterized queries.

[Massimo Di Pierro]

Thanks Graham,
we may eventually change this. One of the reason for rewriting the DAL
was to add parametric queries. It just ever happened because there was
not sufficient motivation, as users do not see this.

Massimo

On Dec 15, 6:44 pm, Graham Dumpleton <graham.dumple...@gmail.com>
wrote:

[pbreit]

Graham sent me a patched NewRelic agent (version 1.0.6.176) which appears to be working fine.

[Massimo Di Pierro]

Thank you Patrick and Graham.