Logger infoDuration

Ignition
,
#1

I was curious if its possible to use the .infoDuration methods outlined in the java docs on the LoggerEx class provided by system.util.getLogger().

It seems that jython isn’t actually implementing the __enter__ and __exit__ methods on the Closeable interface, so I tried adding them manually, but I can’t seem to get an accurate print out in the logs

i.e.

import time
logger = system.util.getLogger("TEST")

class test():
	def __init__(self, closeable):
		self.closeable = closeable
	
	def __enter__(self):
		pass
	
	def __exit__(self, exc_type, exc_value, exc_traceback):
		self.closeable.close()


with test(logger.infoDuration("Debugging sleep")):
	time.sleep(1)

Will actually just print out the following in the logs. Not really able to get my debugging message, or the duration information.

INFO TEST - START - {}
INFO TEST - FINISHED {} - {}

I appreciate any ideas, this would be nice to be able to use for runtime debugging without having to go back and implement by own test context manager anywhere I am already using a dedicated logger.

#2

Oof.

That’s embarrassing. You’re not missing anything - the xDuration logger closeables simply don’t work. We’re not using them anywhere in our codebase, so no one’s ever noticed.

You’re not really missing a whole lot. Basically the final logged message is (supposed) to be using FormatUtil.formatDuration to make a human-readable elapsed time:
http://files.inductiveautomation.com/sdk/javadoc/ignition80/8.0.12/com/inductiveautomation/ignition/common/FormatUtil.html
But the precision is fairly low so it’s probably not very useful anyways. I’d just make your own. You can use java.lang.System.nanoTime() for a monotonic clock with nanosecond precision.

2 Likes
#3

Lol I appreciate the candid-ness!

#4

I incidentally fixed these format strings with some other work I was doing in 8.1.18.

#5

What should this print then? I actually just tried this script in a new nightly container, but I got the same print messages. At least I think I did, I am not sure if the times were in the original one as well.

16:08:03.923 [SwingWorker-pool-1-thread-2] INFO TEST - START - {}
16:08:04.931 [SwingWorker-pool-1-thread-2] INFO TEST - FINISHED {} - {}

What should I expect in the two empty objects?

#6

I had just merged the changes, so I wouldn’t expect things to be different until the build that got published last night/this morning.

1 Like
#7

For those curious, here is the actual output after re-updating my nightly container.

Console:

15:26:25.858 [SwingWorker-pool-1-thread-5] INFO TEST - START - Debugging sleep
15:26:25.960 [SwingWorker-pool-1-thread-5] INFO TEST - FINISHED 102 ms - Debugging sleep

Gateway Logs:

image
image2208×176 23 KB

I am curious to find more places where this could be useful in applications, maybe when we have slow chains of events and we aren’t sure which event is causing it. Wrapping them into a context manager for this purpose could make it relatively easy to add some non-intrusive debug timing.