Change "Updating metadata for stmt NNN" notification to info

[blaz-a]

Change "Updating metadata for stmt NNN" notification from warning to info so it can be supressed in log.

[mirostauder]

Automated message: PR pending admin approval for build testing

[renecannao]

Hi @blaz-a , can you please provide some explanation about this choice?
Thanks

[blaz-a]

Hello @renecannao !

This is closely related to the other PR I made. Whenever proxysql updates the statements it has stored, it outputs a "warning" to log (lib/MySQL_PreparedStatement.cpp:421). Updating statements is a part of normal operation so it hardly makes sense to classify such notification message as a "warning".

As this message (along with accompanying query) makes up for vast majority of log entries when proxysql is used in production, essentially polluting the logs with irrelevant notifications, it would be nice to be able to suppress it. Making this notification an "info" instead of "warning" makes it possible to suppress it from the logs while still keeping all relevant messages (real warnings and errors) logged.

So these solve both usefulness and cost of logs and apart from a minor text change (where [WARNING] is replaced with [INFO] for the "Updating metadata for stmt NNN" notification) has no effect on operation with default configuration.

[renecannao]

Hi @blaz-a .

Thank you for the explanation.
I acknowledge your problem: the message is filling up your log in production.
But I respectfully disagree.

To me, these warning messages are extremely useful, as I consider updating statement metadata NOT part of normal operation, and their excessive presence is highlighting a problem that shouldn't be ignored.

Removing them could obscure important information and make it more difficult to diagnose issues, both in the present and in the future. It is important to maintain comprehensive logs for troubleshooting and auditing purposes.

If proxysql is generating a lot of entries related to updating statement metadata, probably you should investigate why prepared statements metadata are often updated, and not simply try to suppress the messages.
Do you know why in your environment updating statement metadata is "a part of normal operation" ?

[blaz-a]

Hello @renecannao !

I understand the point you are making. With default settings (i.e. no change to proxysql.cnf) nothing would be suppressed. Nothing changes apart from visual representation of one notification message.

Looking at the code directly above the line 421 of lib/MySQL_PreparedStatement.cpp tells me that this notification is posted every time something as trivial as param count or field count changes (which - alas - happens often). "Warning" seems overly excessive for such a notification.

As for our specific case: it's not the application that keeps doing these queries; my finger is on the accompanying New Relic APM agent doing EXPLAIN SELECTs, interacting poorly with proxysql to fill up container logs with irrelevant clutter. Ironically the NR agent is there precisely because of the reasons you mentioned above, for diagnosing issues etc. The application itself is working correctly.

Now as there is no way to suppress individual notifications and because there is a multi-level logging system in place already I figured the best way to rectify the issue is to (1) allow users to specify what should be output to stderr (without interfering with Prometheus stats!) and (2) to demote the notification about statement updates from warning (which sounds like something that requires immediate attention) to info (which is something that can be potentially ignored after it has been investigated).

[renecannao]

Hi @blaz-a ,

Thank you for the update.

this notification is posted every time something as trivial as param count or field count changes (which - alas - happens often)

The warning is posted every time param count or field count changes: this is correct.
But this is NOT trivial. These should be rare, very rare events.

As for our specific case: it's not the application that keeps doing these queries; my finger is on the accompanying New Relic APM agent doing EXPLAIN SELECTs, interacting poorly with proxysql to fill up container logs with irrelevant clutter. Ironically the NR agent is there precisely because of the reasons you mentioned above, for diagnosing issues etc. The application itself is working correctly.

Ok, so now we know you have an application that is using prepared statement in an unusual way. Using prepared statement for EXPLAIN is an odd choice.

Personally, I wouldn't change the warning into an info.
In the light of this new information, I would instead completely suppress the warning in case the change of fields count happens for an EXPLAIN statement.

What do you think?

[blaz-a]

Hello @renecannao !

You made a great suggestion, perhaps we can improve on it a bit - how about reporting changes for EXPLAIN statements as info, and all normal statements as warning? This way anyone interested in full output would still see full output and be informed about potential issue in their application, whereas those who are not interested into info notifications could still suppress them from the log via the other PR?

I actually made the other PR mentioned above (the one for setting log level verbosity) because I came across some posts where others were asking whether log chatter can be reduced for proxysql (I have no idea whether there is any issue open for this).

[blaz-a]

Hello @renecannao !

I updated the PR in line combining your suggestion with keeping the output (at INFO level) for EXPLAIN statements. Is this acceptable for you?

Together with the other PR it will still enable us to suppress INFO messages from EXPLAIN SELECTs and show any potential WARNINGs for actual queries (should they ever appear).

[renecannao]

Hi @blaz-a .

I noticed your PR still uses proxy_info no matter the case: allow me the joke, you really don't want to see the log entry 😆
I re-implemented it in in #4482 following my suggestion in a previous comment:

• EXPLAIN will be always suppressed (it uses a simple strncasecmp() against the digest_text)
• other queries will generate a warning

I also added a simple test for code coverage.

I will separately reply on #4477

[blaz-a]

Hello @renecannao !

Yes, I used proxy_info() because this was meant to work in conjunction with the other PR I made (where proxy_info() log output could be suppressed). I figured this gives users "the best of both worlds" - either keep all log output lines from current version or to silence less relevant ones (e.g. EXPLAIN SELECT).

[mirostauder]

Can one of the admins verify this patch?