pdb: change log level for pdb query response time from LM_INFO to LM_DBG

[mtryfoss]

• using LM_INFO cause a lot of log events on a busy server with normal log level

Pre-Submission Checklist

• Commit message has the format required by CONTRIBUTING guide
• Commits are split per component (core, individual modules, libs, utils, ...)
• Each component has a single commit (if not, squash them into one commit)
• No commits to README files for modules (changes must be done to docbook files
  in doc/ subfolder, the README file is autogenerated)

Type Of Change

• Small bug fix (non-breaking change which fixes an issue)
• New feature (non-breaking change which adds new functionality)
• Breaking change (fix or feature that would change existing functionality)

Checklist:

• PR should be backported to stable branches
• Tested changes locally
• Related to issue #XXXX (replace XXXX with an open issue number)

Description

Proposal to change log level of the query response time.
If this is of interest, it should probably be monitored in some other metric and not flood the syslog.

[henningw]

Thanks for the PR. Yes, it can be probably a bit excessive on a busy server. One could of course reduce the log level from INFO to NOTICE to silence it (and others). Lets wait if there are other comments regarding this change before merging.

[mtryfoss]

Yeah, I'm aware of the possibility to reduce the log level.
However, one might want to have INFO from other modules.
I feel like using DBG here is more harmonised with the verbosity of most other modules.

[miconda]

It looks like we are going to end up with two used levels for log messages, ERROR and DEBUG, because, more or less based on personal needs/preferences, INFO tends to be replaced by DEBUG. What is considered useful info for someone can be too verbose for another one.

At the end INFO is intended to provide feedback about what is executed and how, not content useful for troubleshooting.

There is also the possibly to set debug level per module using debugger module, but considering its target use for debugging, it might not be something considered suitable for production.

Maybe we should try to find a common approach for the future for such changes, e.g., a module parameter is introduced to be able to specify the log level for "info" messages.

[henningw]

Yes, I also have the impression. Its a bit unfortunate, INFO provides valuable information and one by one the messages are removed. We probably should try to come up with kind of a generic guideline. Like INFO is for informational messages that shows that something was done, but not e.g. for internal stuff like a timer run. It should create max 1-2 INFO messages per usual execution of the module function, and not more, and so on.

[mtryfoss]

A module parameter for setting the log level of "request info" messages pr modules sound like a good idea to me.

However, in this particular case it would be much more useful to have the response time set to var which could be used in metrics, used in some other logging related to that call, or even selective logging if latency is above a certain value.

[miconda]

@mtryfoss: having the value in a variable can be useful to push to specific monitoring systems, however many built monitoring systems that are based on digesting logs (e.g., ELK stack) and extracting the information from there.

[mtryfoss]

Yes, of course - but you could easily log that the same way using xlog? :)

[miconda]

Yes and no - because it is not the same, the source of the log message is going to be the xlog, not the original the module, it requires changes to existing systems and how monitoring is handling.

Then, log levels are designed for controlling the verbosity, by setting debug core parameter. For a similar approach, it would mean to add a parameter to control when variables are set or not.

[miconda]

I have just pushed a more generic way to allow remapping log levels for local purpose of the module when using LLM_XYZ() log macros instead of LM_XYZ() and updated the pdb module to offer a modparam for INFO level to be remapped. The most relevant commit:

• 03203d1
• e818baa

To get the equivalent of what you wanted to change, set ll_info modparam to 3.

If there are problems, open a bug in the issue tracker.