"Critical sections" in Jython?

[nminchin]

I want to be able to log function calls for diagnosing issues by writing them with their args into a document tag.

I have everything working, but I notice sometimes that function calls are missing. The reason is that the logging is happening in multiple threads when multiple functions are called at the same time. Therefore, the document tag value is read and updated by more than one call, and the last to finish wins.

How would I implement something to fix this?

ChatGPT suggests java.util.concurrent.locks.ReentrankLock. I'll give it a go, but open to ideas

Context:
I have 2x functions, the one that logs the function, __log_function_call, and a wrapper, log_function_call, that wraps the log function. Functions to be logged call log_function_call but it's the __log_function_call function that reads and writes to the document tag.

[pturmel]

Fundamentally, this is handled in python using the with statement and a lock. (Old school would use a try - finally construct.) But in Ignition, script module life cycles make locks untrustworthy across projects and project edits, so you absolutely need to make a persistent lock with system.util.getGlobals and ensure it is only initialized once.

Once you do that, I recommend the script module that does this also maintain a persistent cache object of content of the document tag (initialization would be the only read of the tag), modifying the cache and writing the tag under the lock.

But I have to admit that I don't approve--you are re-inventing the wheel (the java logging system).

[nminchin]

@pturmel

the java logging system

As in using system.util.getLogger?

The reason this is difficult to use is the limited (or lack of) formatting options. I want to present this in Perspective like this below which shows things like tag writes and if successful or not, function calls, what thread they were part of, and the args passed into the function, etc. so that I can track what happens when I press buttons, or tags change value from the PLC. This project has lots of moving parts, so it's incredibly useful to see this info. Using the system.util.getLogger, I would be struggling to read and interpret it all.

@pturmel

But in Ignition, script module life cycles make locks untrustworthy across projects and project edits, so you absolutely need to make a persistent lock with system.util.getGlobals and ensure it is only initialized once.

I'll look at this now, cheers!

@pturmel

Once you do that, I recommend the script module that does this also maintain a persistent cache object of content of the document tag (initialization would be the only read of the tag), modifying the cache and writing the tag under the lock.

I'm already doing this part, minus the lock bit

[pturmel]

I understand the motivation, and can't really argue that it isn't valuable.

If you are caching this in a script top-level object, are you sure you cannot just access the object from your UI instead of the document tag?

Jython lists and dictionaries are implemented with java thread-safe collections, and simple list .append() or dictionary insert should not corrupt your data. (Use .pop() to remove old items from the tail of a list.)

[nminchin]

@pturmel

so you absolutely need to make a persistent lock with system.util.getGlobals and ensure it is only initialized once.

Is this how I would do this, at the top of my module:

import threading
log_function_call__lock = system.util.getGlobals().setdefault('log_function_call__lock', threading.Lock())

Then to use it:

def fun():
    with log_function_call__lock:
        do_the_thing

?

Edit: I edited for posterity so people won't have to scroll and find the solution in amongst the thread

[pturmel]

@nminchin

do this

Yes. And something similar for the cache object itself.

[nminchin]

Yep, that one's a bit less nice, since a document tag's read value must be converted into basic Py objects to actually make it useful:

LogFunctionCall_Value = system.tag.readBlocking(LOG_FUNCTION_CALL__TAGPATH)[0].value
LogFunctionCall_Value = shared.util.misc.copyAndSanitise(LogFunctionCall_Value) if LogFunctionCall_Value is not None else []

This is one reason I'd consider this

@pturmel

If you are caching this in a script top-level object, are you sure you cannot just access the object from your UI instead of the document tag?

Jython lists and dictionaries are implemented with java thread-safe collections, and simple list .append() or dictionary insert should not corrupt your data. (Use .pop() to remove old items from the tail of a list.)

This would also make it independent of tags at all which would be nice

[pturmel]

Note that my objectScript() expression function has a short-circuit for accessing script module top level objects that aren't callable--it will avoid the interpreter overhead and just return the object. An expression binding's [] operator can then extract items from that object without python.

[nminchin]

Very nice

when using with lock.lock() with a try/except inside of it, or outside of it?, will an exception end the lock?

e.g.

try:
    with lck:
        stuff...
        raise ValueError('Oh no!')
except:
    print 'Oopsie!'

Will this unlock?

Or

with lck:
    try:
        stuff...
        raise ValueError('Oh no!')
    except:
        print 'Oopsie!'

Edit: I removed the .lock()

[pturmel]

Actually, just leave off the .lock() when using with. The statement will lock and release for you, including when exceptions occur.

[nminchin]

Haha, I just noticed that and edited at the same time you replied.

So the context manager will just sit there waiting for the lock to be available if it's not? Is there a timeout?

[nminchin]

Oh no
AttributeError: 'java.util.concurrent.locks.ReentrantLock' object has no attribute '__exit__'

Maybe i'll implement it myself with a wrapper for it

[pturmel]

Are you sure you need a re-entrant lock?

[nminchin]

@pturmel

this is handled in python using the with statement and a lock

What did you mean by this? I presumed you meant a re-entrant lock (I don't know the difference)

Edit: I assume you mean a threading.Lock?

[nminchin]

Also, I keep getting this error:

ImportError: Error loading module util: ImportError: cannot import name _newFunctionThread

in the context of (simplified):

from java.util.concurrent.locks import ReentrantLock
lck = ReentrantLock()
def fn():
	with lck:
		shared.util.function() # <-- this fails with similar to the error above

Maybe I broke something...
I get this also when I just try to import threading

Traceback (most recent call last):
  File "<input>", line 4, in <module>
  File "C:\Users\<username>\.ignition\cache\gwse_8088\C0\pylib\threading.py", line 8, in <module>
    from thread import _newFunctionThread
ImportError: cannot import name _newFunctionThread

Edit:
I deleted the pylib folder in my cache and restarted Designer and it's working now.

Thanks as always, Phil
PS. i've changed to use a threading.Lock

[pturmel]

@nminchin

i've changed to use a threading.Lock

That was going to be my next suggestion. with expects a jython context manager, which the jython lock provides.

[PGriffith]

Why don't you just set your own MDC keys & values, so you can play into the existing logging storage mechanisms and avoid the headaches? It's org.slf4j.MDC or some classname like that.

[nminchin]

@PGriffith

Why don't you just set your own MDC keys & values

Because "just" for me is a lot more work to try to understand, haha (and I didn't know that existed)