Logger usage clarification

Ignition
1

Hi Forum,

I did my testing below:

image
image829×1030 32 KB

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?

2

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. }

3

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).

4

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.

5

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.

1 Like
6

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

7

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!
8

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.

9

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.

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.

10

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.

11

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

12

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..