# Logger infoDuration

**URL:** <https://forum.inductiveautomation.com/t/logger-infoduration/56475>\
**Category:** Ignition\
**Tags:** ignition80, scripting\
**Created:** [February 23, 2022, 8:27pm UTC](https://forum.inductiveautomation.com/t/logger-infoduration/56475 "2022-02-23T20:27:53Z")\
**Posts on this page:** 7\
**Page:** 1

<div class="post-metadata">

**Author:** ![kgamble](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/kgamble/32/8019_2.png) [@kgamble](https://forum.inductiveautomation.com/u/kgamble)\
**Post date:** [February 23, 2022, 8:27pm UTC](https://forum.inductiveautomation.com/t/logger-infoduration/56475/1 "2022-02-23T20:27:53Z")

</div>

I was curious if its possible to use the `.infoDuration` methods outlined [in the java docs](http://files.inductiveautomation.com/sdk/javadoc/ignition80/8.0.12/com/inductiveautomation/ignition/common/util/LoggerEx.html) 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.

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

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

---

<div class="post-metadata">

**Author:** ![paul-griffith](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/paul-griffith/32/37249_2.png) [@paul-griffith](https://forum.inductiveautomation.com/u/paul-griffith)\
**Post date:** [February 23, 2022, 9:52pm UTC](https://forum.inductiveautomation.com/t/logger-infoduration/56475/2 "2022-02-23T21:52:38Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![kgamble](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/kgamble/32/8019_2.png) [@kgamble](https://forum.inductiveautomation.com/u/kgamble)\
**Post date:** [February 23, 2022, 9:57pm UTC](https://forum.inductiveautomation.com/t/logger-infoduration/56475/3 "2022-02-23T21:57:07Z")

</div>

> [@paul-griffith](#):
>
> 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.

Lol I appreciate the candid-ness!

---

<div class="post-metadata">

**Author:** ![paul-griffith](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/paul-griffith/32/37249_2.png) [@paul-griffith](https://forum.inductiveautomation.com/u/paul-griffith)\
**Post date:** [May 23, 2022, 3:31pm UTC](https://forum.inductiveautomation.com/t/logger-infoduration/56475/4 "2022-05-23T15:31:27Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![kgamble](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/kgamble/32/8019_2.png) [@kgamble](https://forum.inductiveautomation.com/u/kgamble)\
**Post date:** [May 23, 2022, 11:09pm UTC](https://forum.inductiveautomation.com/t/logger-infoduration/56475/5 "2022-05-23T23:09:41Z")

</div>

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.

```auto
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?

---

<div class="post-metadata">

**Author:** ![paul-griffith](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/paul-griffith/32/37249_2.png) [@paul-griffith](https://forum.inductiveautomation.com/u/paul-griffith)\
**Post date:** [May 24, 2022, 2:18pm UTC](https://forum.inductiveautomation.com/t/logger-infoduration/56475/6 "2022-05-24T14:18:57Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![kgamble](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/kgamble/32/8019_2.png) [@kgamble](https://forum.inductiveautomation.com/u/kgamble)\
**Post date:** [May 24, 2022, 10:30pm UTC](https://forum.inductiveautomation.com/t/logger-infoduration/56475/7 "2022-05-24T22:30:19Z")

</div>

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

#### Console:

```python
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](https://us1.discourse-cdn.com/inductiveautomation/original/3X/5/0/504e639d29adf337c1f167e170359d7c60744823.png)

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.