Is it known that logs can come out of order sometimes? Specifically "warn" level logs seem... slower

[sherman]

Im toying with a logging decorator to use around my projects, and I came across this strange behavior. This is all running in a gateway message handler so I can test it all in gateway logs. The following script yields the subsequent logs:

def handleMessage(payload):
    logger = log.get_logger('gateway_event.message')
    whoami = "test_logger"
    
    try:
        sd = log.debug("simple debug message A")
        si = log.info("simple info message B")
        sw = log.warning("simple warning message C")
        sw2 = log.warn("simple warn message D")
        
        sd = log.debug(logger, whoami, "proper debug message E")
        si = log.info(logger, whoami, "proper info message F")
        sw = log.warning(logger, whoami, "proper warning message G")
        sw2 = log.warn(logger, whoami, "proper warn message H")
        
        log.info(logger, whoami, "s_d: {} I".format(sd))
        log.info(logger, whoami, "s_i: {} J".format(si))
        log.info(logger, whoami, "s_w: {} K".format(sw))
        log.info(logger, whoami, "s_w: {} L".format(sw2))
        raise Exception("???EXCEPTION??? M")
    except Exception as e:
        se = log.error(logger, whoami, e)
        log.info(logger, whoami, "s_e: {} N".format(se))

gateway_event.message	14Jan2026 16:47:05	test_logger:: ???EXCEPTION??? M Traceback (most recent call last): File "<MessageHandlerScript:base_leaf/test_logger >", line 20, in handleMessage Exception: ???EXCEPTION??? M
gateway_event.message	14Jan2026 16:47:05	test_logger:: s_e: test_logger:: ???EXCEPTION??? M Traceback (most recent call last): File "<MessageHandlerScript:base_leaf/test_logger >", line 20, in handleMessage Exception: ???EXCEPTION??? M N
gateway_event.message	14Jan2026 16:47:05	test_logger:: proper warn message H
gateway_event.message	14Jan2026 16:47:05	test_logger:: proper warning message G
log	14Jan2026 16:47:05	simple warn message D
log	14Jan2026 16:47:05	simple warning message C
gateway_event.message	14Jan2026 16:47:05	test_logger:: s_w: test_logger:: proper warn message H L
gateway_event.message	14Jan2026 16:47:05	test_logger:: s_w: test_logger:: proper warning message G K
gateway_event.message	14Jan2026 16:47:05	test_logger:: s_i: test_logger:: proper info message F J
gateway_event.message	14Jan2026 16:47:05	test_logger:: s_d: test_logger:: proper debug message E I
gateway_event.message	14Jan2026 16:47:05	test_logger:: proper info message F
log	14Jan2026 16:47:05	simple info message B
log	14Jan2026 16:47:05	simple debug message A
Project	14Jan2026 16:46:45	Restarting gateway scripts...

Is this a known oddity? Anything I can do to improve it? I’m worried about debugging headaches later when things might come out in the wrong log-order relative to their order of operations.

Ignition 8.1.41, maybe already changed in new versions and just something to be aware of for now?

[paul-griffith]

@sherman

logger = log.get_logger('gateway_event.message')

What does the backing function here do?

sd = log.debug("simple debug message A")
sd = log.debug(logger, whoami, "proper debug message E")
log.info(logger, whoami, "s_d: {} I".format(sd))

Why so many different syntaxes?

If you want to minimize possible points of failure, use system.util.getLogger and the instance methods on the returned LoggerEx object you get. Use the f overloads to do string interpolation, e.g.
system.util.getLogger("myLogger").infof("Some message: %s", obj)

[pturmel]

Why in the world did you make your own log wrappers? That would be my first suspect. The logger you get from system.util.getLogger() is entirely java and way more efficient than any possible jython wrapper.

Second, use the .infof, warnf, debugf methods in your code to do all of your formatted messages. Again, pure java implementations. Do not use jython .format(). The native java methods are also smart enough to not stringify anything if the level is disabled.

Throw away your log wrapper!

Edit: Paul was faster. What he said.

Edit 2: One more point. Create a logger object with system.util.getLogger() at the top of your project library scripts, outside any class or function. The fastest logger access is the one that is already in scope through the entire script. I recommend something like this:

logger = system.util.getLogger(system.util.getProjectName() + ':' + system.reflect.getModulePath())

[paul-griffith]

Results are as expected using native loggers:

	log = system.util.getLogger('gateway_event.message')
	
	try:
		log.debug("simple debug message A")
		log.info("simple info message B")
		log.warn("simple warn message C")
		log.fatal("simple fatal message D")
		
		log.debug("proper debug message E")
		log.info("proper info message F")
		log.trace("trace message G")
		log.warn("proper warn message H")
		
		log.infof("%s", "I")
		log.warnf("%s", "J")
		log.fatalf("%s", "K")
		log.tracef("%s", "L")
		1/0
	except Exception as e:
		log.error(str(e))
	except java.lang.Exception as ex:
		log.error("UH OH", ex)

D [g.message                     ] [17:07:09.456] [gateway-messagehandler-test-sharedThread-1]: simple debug message A 
I [g.message                     ] [17:07:09.456] [gateway-messagehandler-test-sharedThread-1]: simple info message B 
W [g.message                     ] [17:07:09.456] [gateway-messagehandler-test-sharedThread-1]: simple warn message C 
E [g.message                     ] [17:07:09.456] [gateway-messagehandler-test-sharedThread-1]: ###Fatal-simple fatal message D 
D [g.message                     ] [17:07:09.456] [gateway-messagehandler-test-sharedThread-1]: proper debug message E 
I [g.message                     ] [17:07:09.456] [gateway-messagehandler-test-sharedThread-1]: proper info message F 
T [g.message                     ] [17:07:09.456] [gateway-messagehandler-test-sharedThread-1]: trace message G 
W [g.message                     ] [17:07:09.456] [gateway-messagehandler-test-sharedThread-1]: proper warn message H 
I [g.message                     ] [17:07:09.456] [gateway-messagehandler-test-sharedThread-1]: I 
W [g.message                     ] [17:07:09.456] [gateway-messagehandler-test-sharedThread-1]: J 
E [g.message                     ] [17:07:09.456] [gateway-messagehandler-test-sharedThread-1]: ###Fatal-K 
T [g.message                     ] [17:07:09.456] [gateway-messagehandler-test-sharedThread-1]: L 
E [g.message                     ] [17:07:09.456] [gateway-messagehandler-test-sharedThread-1]: integer division or modulo by zero 

[sherman]

For what it’s worth, I can replicate this behavior without my wrapper, just using logger = system.util.getLogger("test") and sequential logger calls. My theory is that the event logger is struggling with sub-second timing. ** it malfunctions when I use a vanilla logger in the same event handler as my custom logger, but not isolated like Paul’s test.

Now to explain my actions:

I want to be able to have organized logs without spawning a new log tracker for every method that I need to debug. I also want them to be accessible to other scripters that may get a bit casual with formatting and naming (they have already gone down the path of spawning a new logger tracker for every single method). I was warned at some point that these never go away, so I am trying to limit how many of them are generated. Its also to be more in line with our other logging style guides for code outside of ignition. I put this off for years and eventually it spaghetti’d too much so now I am actually writing a log package for our use. Under the hood this is all using system.util.getLogger() and the resulting logger calls, it just regularizes the interface with more information without having to write it all every time. Once I found the same lines of code dozens of times, I had to do something.

Re: overloaded arg sets – I’d rather the system function with something than crash because it isn’t perfect, so I am handling the major use cases. Working on auto-introspecting the whoami part of the logger, but I need to test that more; I know for sure how to do it in Python 3+ but I have to make sure it plays nice in jython2.7

Second, use the .infof, warnf, debugf methods in your code to do all of your formatted messages. Again, pure java implementations. Do not use jython .format(). The native java methods are also smart enough to not stringify anything if the level is disabled.

I am first and foremost a python programmer, so doing everything as pythonic as possible is my default and my preference; if I have to write the helper methods to use the java directly I might do that, but I am definitely not going to be writing java in my normal “python” scripts unless I absolutely have to. And I can’t be passing off tasks to others who have no experience with Java if they have to deal with Java

We bought Ignition as a “python-equipped” ecosystem for a reason

Anyway, this isn’t absolutely critical, but it was strange and I am worried about future behavior.

[sherman]

Here’s a log with my custom stuff followed by a default logger:

def handleMessage(payload):
    logger = log.get_logger('gateway_event.message')
    whoami = "test_logger"
    logger2 = system.util.getLogger('test')
    try:
        sd = log.debug("simple debug message A")
        si = log.info("simple info message B")
        sw = log.warning("simple warning message C")
        sw2 = log.warn("simple warn message D")
        
        sd = log.debug(logger, whoami, "proper debug message E")
        si = log.info(logger, whoami, "proper info message F")
        sw = log.warning(logger, whoami, "proper warning message G")
        sw2 = log.warn(logger, whoami, "proper warn message H")
        
        log.info(logger, whoami, "s_d: {} I".format(sd))
        log.info(logger, whoami, "s_i: {} J".format(si))
        log.info(logger, whoami, "s_w: {} K".format(sw))
        log.info(logger, whoami, "s_w: {} L".format(sw2))
        
        logger2.debug("default debug message")
        logger2.info("default info message")
        logger2.warn("default warn message")
        logger2.error("default error message")
        
        raise Exception("???EXCEPTION??? M")
    except Exception as e:
        se = log.error(logger, whoami, e)
        log.info(logger, whoami, "s_e: {} N".format(se))

gateway_event.message	14Jan2026 17:20:08	test_logger:: ???EXCEPTION??? M Traceback (most recent call last): File "<MessageHandlerScript:base_leaf/test_logger >", line 26, in handleMessage Exception: ???EXCEPTION??? M
gateway_event.message	14Jan2026 17:20:08	test_logger:: s_e: test_logger:: ???EXCEPTION??? M Traceback (most recent call last): File "<MessageHandlerScript:base_leaf/test_logger >", line 26, in handleMessage Exception: ???EXCEPTION??? M N
test	14Jan2026 17:20:08	default error message
test	14Jan2026 17:20:08	default warn message
gateway_event.message	14Jan2026 17:20:08	test_logger:: proper warn message H
gateway_event.message	14Jan2026 17:20:08	test_logger:: proper warning message G
log	14Jan2026 17:20:08	simple warn message D
log	14Jan2026 17:20:08	simple warning message C
test	14Jan2026 17:20:08	default info message
gateway_event.message	14Jan2026 17:20:08	test_logger:: s_w: test_logger:: proper warn message H L
gateway_event.message	14Jan2026 17:20:08	test_logger:: s_w: test_logger:: proper warning message G K
gateway_event.message	14Jan2026 17:20:08	test_logger:: s_i: test_logger:: proper info message F J
gateway_event.message	14Jan2026 17:20:08	test_logger:: s_d: test_logger:: proper debug message E I
gateway_event.message	14Jan2026 17:20:08	test_logger:: proper info message F
log	14Jan2026 17:20:08	simple info message B
test	14Jan2026 17:20:08	default debug message
gateway_event.message	14Jan2026 17:20:08	test_logger:: proper debug message E
log	14Jan2026 17:20:08

And here’s the whole logging script for your entertainment. It’s only a few hours old so it is definitely a “prototype”:

import traceback

def get_logger(_logger):
    try:
        if isinstance(_logger, basestring):
            logger_name = str(_logger)
            logger = system.util.getLogger(logger_name)
            return logger

        if _logger is None:
            return system.util.getLogger("log")

        return _logger

    except Exception as ee:
        logger = system.util.getLogger("log")
        logger.error("get_logger: failed to resolve logger: %s\n%s" % (str(ee), traceback.format_exc()))
        return logger

def pre_log(*args, **kwargs):
    if len(args) == 1: # just a string to log
        _logger, whoami, obj = None, "", args[0]
    elif len(args) == 2: # skipped whoami, try to guess
        _logger, obj = args
        whoami = inspect.currentframe().f_back.f_back.f_code.co_name # up to the invocation, up to the invoker        
    elif len(args) == 3: # fully described log entry
        _logger, whoami, obj = args
    else:
        raise Exception("Need either 1 (s) or 3 (logger, whoami, s/e) arguments for logger")

    logger = get_logger(_logger)
    return logger, whoami, obj, kwargs

def _prefix(whoami):
    return (str(whoami) + ":: ") if whoami else ""

def debug(*args, **kwargs):
    logger, whoami, obj, kwargs = pre_log(*args, **kwargs)
    s = _prefix(whoami) + str(obj)
    logger.debug(s)
    return s

def info(*args, **kwargs):
    logger, whoami, obj, kwargs = pre_log(*args, **kwargs)
    s = _prefix(whoami) + str(obj)
    logger.info(s)
    return s

def warn(*args, **kwargs):
    logger, whoami, obj, kwargs = pre_log(*args, **kwargs)
    s = _prefix(whoami) + str(obj)
    logger.warn(s)
    return s

def warning(*args, **kwargs): 
    return warn(*args, **kwargs)
    
def error(*args, **kwargs):
    logger, whoami, obj, kwargs = pre_log(*args, **kwargs)
    try:
        p = _prefix(whoami)

        if kwargs.get("exc_info", True):
            exc_info = kwargs.get("exc_info_tuple", None)
            if exc_info is None:
                import sys
                exc_info = sys.exc_info()

            if exc_info and exc_info[0] is not None:
                s = "%s%s\n%s" % (p, str(obj), ''.join(traceback.format_exception(*exc_info)))
            else:
                s = "%s%s" % (p, str(obj))
        else:
            s = "%s%s" % (p, str(obj))

        logger.error(s)
        return s

    except Exception as ee:
        fallback = system.util.getLogger("log")
        fallback.error("error: failed to log error: %s\n%s" % (str(ee), traceback.format_exc()))
        return "error: failed to log error: %s" % str(ee)

[pturmel]

Teach your fellow devs to use the standard loggers. Provide a standard logger in every library script module, named after the project and script. Move on to next task.

Really. Throw away your log wrapper.

Or not. But when you leave or retire, and your company hires an Ignition professional to take up the slack, your name will be mud.

[pturmel]

@sherman

your entertainment

No handling of java exceptions/throwables (they are not in the same class hierarchy as Jython BaseException).

No use of standard traceback formatting (and suppression on disabled levels).

A whole bunch of jython overhead for every logger invocation.

Mud, I say.

[sherman]

No handling of java exceptions/throwables (they are not in the same class hierarchy as Jython BaseException).

thats because I am writing python, and I haven’t gotten to the phase of detailed exception handling

No use of standard traceback formatting (and suppression on disabled levels).

Actually a huge part of why I wanted to do this was to get to that. The traceback parsing in ignition is one of the most violent pain points that I experience trying to develop in its environment. I just haven’t gotten to that yet, I needed to start with basic functionality. Maybe you have some advice for reliably extracting this information from errors: what line in what file cause what exception? If I can literally get “ (<line_number>): ” this entire exercise will pay off dozens of times over. I spend the vast majority of my time in debugging Ignition just trying to reasonably get that information. Many errors straight up do not have it, and especially debugging SFCs is a nightmare (I know how you feel about SFCs)

A whole bunch of jython overhead for every logger invocation.

Yeah I don’t love the amount of overhead, but it can save an appreciable amount of debugging time to get useful information in my logs. I can always remove / neuter the printouts in prod.

[pturmel]

@sherman

The traceback parsing in ignition

Don't parse java throwable tracebacks. Just hand the throwable to the java native logger and let it format it into the log. Don't parse java throwable tracebacks.

Limit "parsing" of jython exceptions to the minimum needed to represent them as java Exceptions, and then hand them to the logging infrastructure to be rendered natively. Use PythonAsJavaException() from my later.py helper script, or use system.reflect.asThrowable() from my Integration Toolkit (somewhat cleaner). The latter has the advantage of pure java implementation performance.

Do not otherwise "parse" jython exceptions.

If you need to catch specific java or jython exceptions, call them out in their own except clause, so the jython interpreter machinery (pure java) takes care of extracting them for you. Full stop.

[sherman]

Sorry, I meant parsing them with my eyes. Like looking at that huge wall of text and trying to find if there is even a useful nugged of information to help me figure out what went wrong.