Logger usage clarification

[Eugene49]

Hi Forum,

I did my testing below:

Clarification:
The purpose of logging is, I want to log message every time, such that, when glitch happened in the past, I can go thru the log message to see what was going on that time.

But this is not the case, for example, If on the script, i purposely log as "Debug", but for some reason a colleague, changed the log level to "Info". My debug message will not be log.

This beats the purpose of logging the message.
What is the reason behind this feature; a way to filter which message being logged?

Is there another strategy I can use to make sure, my log message is being log?

[pturmel]

@Eugene49

What is the reason behind this feature

Performance and storage.

Logging is designed to quickly discard messages at too low a level, without even evaluating their formatting arguments, to minimize the performance penalty of logging. (Severe performance hit.)

This has the side-benefit of requiring no disk space, and therefore extending the log rotation time period of whatever logs are actually enabled.

All of Ignition's log levels are INFO at gateway startup. If you absolutely have to log something reliably, use INFO level. But think really hard about whether you really need that. Consider logging at INFO level the first time something happens (in some time period), and logging at DEBUG level after that. So users can see that something is happening, but don't get bombarded with it without need.

{ When including dynamic content in your logs, you should always use the .infof() or .debugf() logger methods. Avoid doing any complex calculations to hand to format arguments. Instead, arrange for your objects to intelligently stringify on demand from a %s placeholder. Those won't execute when the log level is disabled. }

[Eugene49]

Thanks.
I understood.
One note for each developer, Level setting in Status-Diagnostic->Log is universal and fixed.

And I recall that,
it is on developer discretion, to decide, which debug level to use for each debug message.

Thus its a normal scenario where, a developer expect something will go wrong, then only go to gateway log and set logging level to debug, and reset to info when developer is confident that everything looks good. -- i wish there was a timer.

But in a scenario where multiple developers are debugging, we don't want them to set level=Info, when you want it to be level=debug. hmm

p.s.
what is wrong with logger.info("my name is: %s" % myName")

Edit:
Another place when I want debug message to always show:
I use system.perspective.print() this will show on browser console and can display object (as oppose to only string).

[pturmel]

@Eugene49

p.s.

That has to perform the string operation even when the INFO level is turned off. If you use this instead:

logger.infof("my name is: %s", myName)

then the string manipulation will not be executed at all if INFO is turned off.

If myName is some complex object that requires substantial stringification code, then skipping it is a big performance win.

[Eugene49]

You are saying:

when level=warn, both will not be log:
logger.info("my name is: %s" % myName)
logger.infof("my name is: %s", myName)

but the latter is better, because the operation (string replacement) is skip.
while the former still do the operation but not logged anyway.

[pascal.fragnoud]

Yes, because in the first case the formatting happens before the string is sent to the logger.

[Eugene49]

Let's put a nail to this habit:
During development, I use to add system.perspective.print() then delete it, when every thing works.

Two scenarios:

1. doing a named query
2. sending an email

Both I want to log.

For the NQ, I want to log if query was successful, what is the query, what are the parameters.

For the email, I want to log if email was successfully sent, subject, and recipients.

Which goes to perspective.print, which goes to logger.info

For NQ result, how do I evaluate result to success or fail, even if result can be different type?

result = system.db.runNamedQuery(query, params)

For email:

system.net.sendEmail() #...does not return anything. TSK!

[pascal.fragnoud]

For the query, well... it depends on the query. It's up to you to check the returned value and see if it corresponds to what you expects.

Don't forget that most functions can raise errors, so wrap your calls in try/except if you want to personally handle errors. And keep in mind that database related functions will raise a java error, not a python one. sendEmail might raise a java error too.

[pturmel]

Nothing should be left going to system.perspective.print() when you are done. That is a burden on the browser connection, not just burning a bit of gateway CPU.

@Eugene49

For NQ result

Do something like this (with some help from my Integration Toolkit):

# In some library
from java.lang import Throwable
logger = system.util.getLogger(system.util.getProjectName() + "." + system.reflect.getModulePath())

def someOperation(params):
	try:
		return system.db.runNamedQuery("path/to/query", params)
	except Throwable, t:
		logger.warnf("Java error in path/to/query: %s", [params], t)
	except Exception, e:
		logger.warnf("Jython error in path/to/query: %s", [params], system.reflect.asThrowable(e, None))

That will log errors in JDBC. You would then check the return value for expected results.

I use WARN level where the code should never fail that way without big problems. I use lesser log levels for unexpected/invalid result data.

Do similar with your email call.

[Eugene49]

@pturmel

Nothing should be left going to system.perspective.print() when you are done. That is a burden on the browser connection, not just burning a bit of gateway CPU.

Sounds good.

I will note this.
And Yeah, i got it..

"I would only log when NQ returns error, and include queryPath and params to the log message, by converting params to string first"

For emails.
Log every time, log both recipients and email subject.

[pturmel]

@Eugene49

converting params to string first

Nah. See edit above. (Note quirk in .warnf() when also passing a Throwable.)

[Eugene49]

Cool the above does it.

Another Instance where I have a lot of debug messages is in sendMesage:
sending side:

	messageType = "btnSave"
	system.perspective.print("send message: %s" % messageType)
	system.perspective.sendMessage(messageType, payload={})

receiving side:

	system.perspective.print("inside btnSave")

I guess I only want to show this during debuging..

[Gustavo_Cardoso]

@pturmel

to minimize the performance penalty of logging. (Severe performance hit.)

Hello everyone,

Reading this quote raised some questions for me regarding best logging practices in our systems. I'd love to get some clarity on how Ignition handles logging under the hood:

1. Log Level Execution: If I log something at the debug level (logger.debug(...)) but the logger's level is set to INFO, does this "log action" still execute, or is it bypassed entirely?

2. Performance Impact: What is the real danger here — the log method call itself, or the logger instantiation?

3. Project Best Practices: Is the best approach to instantiate a single logger for an entire project so all functions use the same object, or is it better to separate the loggers with better context names?

4. Module Development: This question extends to module development. I am creating loggers for specific classes within my devices (it's a driver module), using a hierarchical structure like "ExampleDevice", "ExampleDevice.MessageHandler", and "ExampleDevice.MessageHandler.AlarmMessage". How many instances of loggers are "acceptable" for a module to create without hurting performance?

5. Logger Lifecycle: What is the lifecycle of a Logger object? When is an instance actually terminated/garbage collected?

Note: The link to the LoggerEx documentation in the Ignition User Manual is currently not working (see the attached screenshot). Maybe it would have answered some of my questions!

Thanks in advance for the help!

[pturmel]

1. The .debug() method is called, but then does nothing more. It does mean the arguments to .debug() will be computed and passed, then discarded. That is why you should use .debugf(), which skips the message formatting when it can.

2. The hazard is constructing complex log messages just to throw them away.

3. Instantiate loggers as long-lived variables in the top level of project library scripts. (Outside any function definitions.) I typically use one per library script, named for the project and script path.

4. You should use canonical class names for your module logger names. Use a static final fields for per-class loggers. For long-lived class instances, a final field is also reasonable if you want to embed an instance name in the logger name.

5. Logger objects persist in the logging system for the life of the JVM, once created, IIUC.