[BUG-13544] Deadlock in Designer with Debug level logging

Ignition Early Access
1

I have ran into a reproducible deadlock on the AWT-EventQueue thread forcing the user to kill the designer process. To reproduce it requires Debug level logging on tags.manager.gwinterface and OutputConsole and python print statements. This can be reproduced with a button that just logs a message (print ‘Hello World!’) on mouse enter and scroll the mouse over the button a few times. Here is the stack trace for the deadlocked threads from the thread dump.

Found one Java-level deadlock:
=============================
"AWT-EventQueue-0":
  waiting for ownable synchronizer 0x00000000c24be698, (a java.util.concurrent.locks.ReentrantLock$FairSync),
  which is held by "DesignerExecEngine-3"
"DesignerExecEngine-3":
  waiting to lock monitor 0x00000168d3c3e100 (object 0x00000000c37d96c0, a java.io.PrintStream),
  which is held by "AWT-EventQueue-0"

Java stack information for the threads listed above:
===================================================
"AWT-EventQueue-0":
        at jdk.internal.misc.Unsafe.park(java.base@11.0.2/Native Method)
        - parking to wait for  <0x00000000c24be698> (a java.util.concurrent.locks.ReentrantLock$FairSync)
        at java.util.concurrent.locks.LockSupport.park(java.base@11.0.2/Unknown Source)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(java.base@11.0.2/Unknown Source)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(java.base@11.0.2/Unknown Source)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@11.0.2/Unknown Source)
        at java.util.concurrent.locks.ReentrantLock.lock(java.base@11.0.2/Unknown Source)
        at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:210)
        at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100)
        at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
        at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
        at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
        at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
        at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
        at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
        at ch.qos.logback.classic.Logger.debug(Logger.java:482)
        at com.inductiveautomation.ignition.common.util.LoggerEx.debug(LoggerEx.java:459)
        at com.inductiveautomation.ignition.client.util.gui.OutputConsole$DocumentSizeFilter.insertString(OutputConsole.java:262)
        at javax.swing.text.AbstractDocument.insertString(java.desktop@11.0.2/Unknown Source)
        at com.inductiveautomation.ignition.client.util.gui.OutputConsole$ConsoleAppender.print(OutputConsole.java:216)
        at com.inductiveautomation.ignition.client.util.gui.OutputConsole$ConsoleAppender.write(OutputConsole.java:208)
        at com.inductiveautomation.ignition.common.util.BifurcatingOutputStream.write(BifurcatingOutputStream.java:46)
        at java.io.PrintStream.write(java.base@11.0.2/Unknown Source)
        - locked <0x00000000c37d96c0> (a java.io.PrintStream)
        at com.inductiveautomation.ignition.common.util.BifurcatingOutputStream.write(BifurcatingOutputStream.java:46)
        at java.nio.channels.Channels$WritableByteChannelImpl.write(java.base@11.0.2/Unknown Source)
        - locked <0x00000000c7a67e48> (a java.lang.Object)
        at org.python.core.io.StreamIO.write(StreamIO.java:134)
        at org.python.core.io.BufferedWriter.flush(BufferedWriter.java:78)
        at org.python.core.io.TextIOBase.flush(TextIOBase.java:168)
        at org.python.core.PyFile.file_flush(PyFile.java:542)
        - locked <0x00000000c7a67c08> (a org.python.core.PyFile)
        at org.python.core.PyFile.flush(PyFile.java:546)
        at org.python.core.StdoutWrapper.print(StdoutWrapper.java:202)
        at org.python.core.StdoutWrapper.println(StdoutWrapper.java:272)
        at org.python.core.Py.println(Py.java:1858)
        at org.python.pycode._pyx3.f$0(<event:propertyChange>:43)
        at org.python.pycode._pyx3.call_function(<event:propertyChange>)
        at org.python.core.PyTableCode.call(PyTableCode.java:171)
        at org.python.core.PyCode.call(PyCode.java:18)
        at org.python.core.Py.runCode(Py.java:1614)
        at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:686)
        at com.inductiveautomation.factorypmi.application.binding.action.ActionAdapter.runActions(ActionAdapter.java:180)
        - locked <0x00000000dba8b428> (a com.inductiveautomation.factorypmi.application.binding.action.ActionAdapter)
        at com.inductiveautomation.factorypmi.application.binding.action.ActionAdapter$ActionRunner.run(ActionAdapter.java:286)
        at java.awt.event.InvocationEvent.dispatch$$$capture(java.desktop@11.0.2/Unknown Source)
        at java.awt.event.InvocationEvent.dispatch(java.desktop@11.0.2/Unknown Source)
        at java.awt.EventQueue.dispatchEventImpl(java.desktop@11.0.2/Unknown Source)
        at java.awt.EventQueue$4.run(java.desktop@11.0.2/Unknown Source)
        at java.awt.EventQueue$4.run(java.desktop@11.0.2/Unknown Source)
        at java.security.AccessController.doPrivileged(java.base@11.0.2/Native Method)
        at java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(java.base@11.0.2/Unknown Source)
        at java.awt.EventQueue.dispatchEvent(java.desktop@11.0.2/Unknown Source)
        at java.awt.EventDispatchThread.pumpOneEventForFilters(java.desktop@11.0.2/Unknown Source)
        at java.awt.EventDispatchThread.pumpEventsForFilter(java.desktop@11.0.2/Unknown Source)
        at java.awt.EventDispatchThread.pumpEventsForHierarchy(java.desktop@11.0.2/Unknown Source)
        at java.awt.EventDispatchThread.pumpEvents(java.desktop@11.0.2/Unknown Source)
        at java.awt.EventDispatchThread.pumpEvents(java.desktop@11.0.2/Unknown Source)
        at java.awt.EventDispatchThread.run(java.desktop@11.0.2/Unknown Source)
"DesignerExecEngine-3":
        at java.io.PrintStream.write(java.base@11.0.2/Unknown Source)
        - waiting to lock <0x00000000c37d96c0> (a java.io.PrintStream)
        at java.io.FilterOutputStream.write(java.base@11.0.2/Unknown Source)
        at ch.qos.logback.core.joran.spi.ConsoleTarget$1.write(ConsoleTarget.java:37)
        at ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:131)
        at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:187)
        at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:212)
        at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100)
        at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
        at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
        at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
        at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
        at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
        at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
        at ch.qos.logback.classic.Logger.debug(Logger.java:482)
        at com.inductiveautomation.ignition.common.util.LoggerEx.debug(LoggerEx.java:459)
        at com.inductiveautomation.ignition.client.tags.impl.GatewayTagInterface.runPoll(GatewayTagInterface.java:111)
        at com.inductiveautomation.ignition.client.tags.impl.GatewayTagInterface$$Lambda$309/0x00000001008fdc40.run(Unknown Source)
        at com.inductiveautomation.ignition.common.execution.impl.BasicExecutionEngine$TrackedTask.run(BasicExecutionEngine.java:565)
        at java.util.concurrent.Executors$RunnableAdapter.call(java.base@11.0.2/Unknown Source)
        at java.util.concurrent.FutureTask.runAndReset$$$capture(java.base@11.0.2/Unknown Source)
        at java.util.concurrent.FutureTask.runAndReset(java.base@11.0.2/Unknown Source)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(java.base@11.0.2/Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.2/Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.2/Unknown Source)
        at java.lang.Thread.run(java.base@11.0.2/Unknown Source)

Found 1 deadlock.
2

I’ve reproduced it and will get a ticket written up for this.

3

Any idea if this is related to using the logging module from the standard python library, and then invoking logging.disable(logging.CRITICAL) results in all logging…even for the platform itself to be suspended in the designer until the designer is restarted?

I’m trying to get more sophisticated than “print debugging” in writing scripts, and I just stumbled on this in 7.9.10.

4

Don’t use python’s logging module. Use the provided system.util.getLogger() script function.

5

Thanks Phil. I’ll look into that. I found that passing “logging.NOTSET” argument to the logging.disable() method does what I was looking for.

I’ve set a variable “log” in the built-in event handler to either “logging.NOTSET”, “logging.DEBUG”, etc and then just pass that “log” variable into any sub-scripts or custom functions, and it seems to be working fine now. This way I only have to change the value in one spot for the entire component (which can grow pretty large if you’re talking about making interactive power tables, etc.)

It is a bit laborious to have to import logging to each sub function. Is this solved by the utility logger you mentioned? (i.e. what is the scope of the provided function?)

Thanks again.

6

system.util.getLogger(…) is available in all scopes. No import required. If you want something even more terse, assign the logger to a variable at the top level of a script module, like so:

# Some script module, perhaps "shared.log".
mine = system.util.getLogger("MyLoggerName")

Then in your various events and custom functions, you can do:

shared.log.mine.infof("Some log message with substitution %s",  event)

Again, no import required.

7

Sounds like a great idea. I’ll play around with it. Thanks!!