1388421 - Papertrail logs contain lots of MySQL warnings code 1003 from the New Relic Python agent

Status: RESOLVED INCOMPLETE

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

Description

[Ed Morley [:emorley]]

After the MySQL upgrade to 5.7, there are a number of MySQL deprecation warnings in the papertrail logs, of form:

"""
Aug 08 17:08:22 treeherder-prod app/web.3: /app/.heroku/python/lib/python2.7/site-packages/newrelic/hooks/database_dbapi2.py:25: Warning: (1003L, u"/* select#1 */ select `treeherder`.`build_platform`.`architecture` AS `architecture`, ...
"""

These appear to come from the New Relic Python agents automatic EXPLAIN feature, which must be using the older EXPLAIN EXTENDED syntax:
https://dev.mysql.com/doc/refman/5.7/en/explain-extended.html

...and so be triggering the deprecation warning mentioned on that page.

Nothing is broken but the log spam is annoying, so I'll report this to New Relic, to see if they can update the Python agent.

Comment 1

[Ed Morley [:emorley]]

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

"""
Hi!

We're using:
* New Relic Python agent v2.90.0.75
* mysqlclient python driver v1.3.10
* Django 1.11.4
* Python 2.7.13
* libmysqlclient v5.7.17-0ubuntu0.16.04.1
* Ubuntu 16.04 (via the Heroku-16 stack)

We recently updated our RDS instance from MySQL 5.6.34 to 5.7.17, and after doing so, our logs sent to Papertrail became full of entries like so:
https://emorley.pastebin.mozilla.org/9029140

Searching for the "1003" warnings code seems to suggest this might be due to the Python agent using the deprecated `EXPLAIN EXTENDED` command, but I'm not 100% sure.

This command has been deprecated for a few MySQL releases, but in MySQL 5.7 the deprecation warning has been added:

> "SHOW WARNINGS immediately following EXPLAIN shows additional execution plan information regardless of whether the EXTENDED keyword is specified. (An additional deprecation warning is included if the statement includes the EXTENDED or PARTITIONS keyword.)"

See:
https://dev.mysql.com/doc/relnotes/mysql/5.7/en/news-5-7-3.html#mysqld-5-7-3-feature
https://dev.mysql.com/doc/refman/5.7/en/explain-extended.html

Either way, it appears that the Python agent's `database_dbapi2.py` is emitting the warning, and so may need adjusting for MySQL 5.7? It also seems very strange that the logs also include the string `*args, **kwargs)`, unless that's a side-effect of the agent wrapping magic?

Many thanks,
"""

Comment 2

[Ed Morley [:emorley]]

Their reply:

"""
Our Python devs have been looking into this. It looks like this is not a deprecation warning, but rather a new "feature" of mysql-server 5.7, where it will return a warning to indicate extended explain plan information. It is true that the command EXPLAIN EXTENDED is deprecated, but we are using EXPLAIN.

You can suppress the warning by running SET sql_notes = 0;.

Please let us know if this solution works for you or if you have further questions or concerns!
"""


My reply to that:

"""
Thank you for the suggestion above. My concern with doing that globally is that it will suppress other note level warnings that are unrelated to the EXPLAINs. Given it's the New Relic agent that is running the EXPLAIN, should it be the one to add `sql_note={0,1}` before/after the EXPLAIN to prevent the warning? (Or ideally capture the extended information in the note too).
"""

Comment 3

[Ed Morley [:emorley]]

Their reply:

"""
Thanks for your feedback as always! I spoke with our developers and they agree with your assessment that this could be suppressed on our end. We've opened an internal ticket for this issue to suppress that warning. I'm not sure when this fix might happen, but since we are tracking it internally I'd like to close this ticket. We'll notify you if there are any updates. I'll close this support ticket in a few days, but please let us know if you have any additional concerns or feedback!
"""

Comment 4

[Ed Morley [:emorley]]

There's nothing we can do here until New Relic fix their agent.