IOException: too many concurrent streams

victordcq · March 13, 2024, 12:55pm

Hello,

I'm having troubles with system.net.httpClient in version 8.1.20

Getting this error: IOException: too many concurrent streams

Could this be related to some websockets that dont get closed?
Though i thought that should be fixed when using httpclient? and i believe there was something about this fixed since 8.1.15. So not sure what is happening here.

I believe this is the causing java.lang.OutOfMemoryError: Java heap space errors down the line...

Anyone got any ideas?

We are in control of the endpoint, there might some issues there too, but i would expect some different errors than these.

I use it like this


if "client" not in system.util.getGlobals():
        system.util.getGlobals()["client"] = system.net.httpClient()

client = system.util.getGlobals()["client"]

...

client.get(url="%s" %(self.base_url), headers=self.headers)

This is the tostring of the client (i saw this was asked in an other post)

<JythonHttpClient@593301238 timeout=10000, bypass_cert_validation=False, has_credentials=False, proxy=None, cookie_policy='ACCEPT_ORIGINAL_SERVER', redirect_policy='NEVER', version='HTTP_2'>

More logs:

Caused by: java.io.IOException
com.inductiveautomation.ignition.common.GenericTransferrableException: Unable to GET https://xxxxx.com
	at com.inductiveautomation.ignition.common.script.builtin.http.JythonHttpClient.send(JythonHttpClient.java:103)
	at com.inductiveautomation.ignition.common.script.builtin.http.JythonHttpClient.get(JythonHttpClient.java:306)
	at jdk.internal.reflect.GeneratedMethodAccessor54.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.base/java.lang.reflect.Method.invoke(Unknown Source)
	at org.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java:190)
	... 35 more
Caused by: java.io.IOException
com.inductiveautomation.ignition.common.GenericTransferrableException: too many concurrent streams
	at java.net.http/jdk.internal.net.http.HttpClientImpl.send(Unknown Source)
	at java.net.http/jdk.internal.net.http.HttpClientFacade.send(Unknown Source)
	at com.inductiveautomation.ignition.common.script.builtin.http.JythonHttpClient.send(JythonHttpClient.java:101)
	... 40 more
Caused by: java.io.IOException
com.inductiveautomation.ignition.common.GenericTransferrableException: too many concurrent streams
	at java.net.http/jdk.internal.net.http.Http2Connection.reserveStream(Unknown Source)
	at java.net.http/jdk.internal.net.http.Http2ClientImpl.getConnectionFor(Unknown Source)
	at java.net.http/jdk.internal.net.http.ExchangeImpl.get(Unknown Source)
	at java.net.http/jdk.internal.net.http.Exchange.establishExchange(Unknown Source)
	at java.net.http/jdk.internal.net.http.Exchange.responseAsyncImpl0(Unknown Source)
	at java.net.http/jdk.internal.net.http.Exchange.responseAsyncImpl(Unknown Source)
	at java.net.http/jdk.internal.net.http.Exchange.responseAsync(Unknown Source)
	at java.net.http/jdk.internal.net.http.MultiExchange.responseAsyncImpl(Unknown Source)
	at java.net.http/jdk.internal.net.http.MultiExchange.lambda$responseAsync0$2(Unknown Source)
	at java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(Unknown Source)
	at java.base/java.util.concurrent.CompletableFuture.postComplete(Unknown Source)
	at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(Unknown Source)
	at java.net.http/jdk.internal.net.http.HttpClientImpl$DelegatingExecutor.execute(Unknown Source)
	at java.base/java.util.concurrent.CompletableFuture.completeAsync(Unknown Source)
	at java.net.http/jdk.internal.net.http.MultiExchange.responseAsync(Unknown Source)
	at java.net.http/jdk.internal.net.http.HttpClientImpl.sendAsync(Unknown Source)
	... 43 more

Ignition v8.1.20 (b2022082313)
Java: Azul Systems, Inc. 11.0.15

victordcq · March 13, 2024, 2:28pm

Im also running into threads/scripts that arent closing, causisng the running scripts/threads to pile up... (seems like this might be the thing that is causing memmory issues)

Thread [perspective-worker-54] id=416, (WAITING for java.util.concurrent.CompletableFuture$Signaller@776e2145)
java.base@11.0.15/jdk.internal.misc.Unsafe.park(Native Method)
java.base@11.0.15/java.util.concurrent.locks.LockSupport.park(Unknown Source)
java.base@11.0.15/java.util.concurrent.CompletableFuture$Signaller.block(Unknown Source)
java.base@11.0.15/java.util.concurrent.ForkJoinPool.managedBlock(Unknown Source)
java.base@11.0.15/java.util.concurrent.CompletableFuture.waitingGet(Unknown Source)
java.base@11.0.15/java.util.concurrent.CompletableFuture.get(Unknown Source)
platform/java.net.http@11.0.15/jdk.internal.net.http.HttpClientImpl.send(Unknown Source)
platform/java.net.http@11.0.15/jdk.internal.net.http.HttpClientFacade.send(Unknown Source)
app//com.inductiveautomation.ignition.common.script.builtin.http.JythonHttpClient.send(JythonHttpClient.java:101)
app//com.inductiveautomation.ignition.common.script.builtin.http.JythonHttpClient.get(JythonHttpClient.java:306)
jdk.internal.reflect.GeneratedMethodAccessor50.invoke(Unknown Source)
java.base@11.0.15/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
java.base@11.0.15/java.lang.reflect.Method.invoke(Unknown Source)
app//org.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java:190)
app//org.python.core.PyObject.__call__(PyObject.java:422)
app//org.python.core.PyMethod.instancemethod___call__(PyMethod.java:237)
app//org.python.core.PyMethod.__call__(PyMethod.java:228)
customapi$py.getxxx$3(C:/Ignition8/user-lib/pylib/apixxx.py:41)

app//org.python.core.PyTableCode.call(PyTableCode.java:173)
app//org.python.core.PyBaseCode.call(PyBaseCode.java:306)
app//org.python.core.PyBaseCode.call(PyBaseCode.java:197)
app//org.python.core.PyFunction.__call__(PyFunction.java:485)
app//org.python.core.PyMethod.instancemethod___call__(PyMethod.java:237)
app//org.python.core.PyMethod.__call__(PyMethod.java:228)
org.python.pycode._pyx128.transform$1(:49)
org.python.pycode._pyx128.call_function()
app//org.python.core.PyTableCode.call(PyTableCode.java:173)
app//org.python.core.PyBaseCode.call(PyBaseCode.java:306)
app//org.python.core.PyFunction.function___call__(PyFunction.java:474)
app//org.python.core.PyFunction.__call__(PyFunction.java:469)
app//org.python.core.PyFunction.__call__(PyFunction.java:464)
app//com.inductiveautomation.ignition.common.script.ScriptManager.runFunction(ScriptManager.java:839)
app//com.inductiveautomation.ignition.common.script.ScriptManager.runFunction(ScriptManager.java:821)
app//com.inductiveautomation.ignition.gateway.project.ProjectScriptLifecycle$TrackingProjectScriptManager.runFunction(ProjectScriptLifecycle.java:828)
com.inductiveautomation.perspective.gateway.binding.transforms.script.ScriptTransform.runFunction(ScriptTransform.java:116)
com.inductiveautomation.perspective.gateway.binding.transforms.script.ScriptTransform.synchronousTransformInternal(ScriptTransform.java:162)
com.inductiveautomation.perspective.gateway.binding.transforms.AbstractSynchronousTransform.transform(AbstractSynchronousTransform.java:30)
com.inductiveautomation.perspective.gateway.model.AbstractBindingHarness$TransformSequencer.transform(AbstractBindingHarness.java:259)
com.inductiveautomation.perspective.gateway.model.AbstractBindingHarness$TransformSequencer.run(AbstractBindingHarness.java:272)
java.base@11.0.15/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
java.base@11.0.15/java.util.concurrent.FutureTask.run(Unknown Source)
java.base@11.0.15/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
java.base@11.0.15/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
com.inductiveautomation.perspective.gateway.threading.BlockingWork$BlockingWorkRunnable.run(BlockingWork.java:58)
java.base@11.0.15/java.lang.Thread.run(Unknown Source)

AttributeError: 'com.inductiveautomation.perspective.gateway.script' object has no attribute 'driver'

	at org.python.core.Py.AttributeError(Py.java:178)
	at org.python.core.PyObject.noAttributeError(PyObject.java:965)
	at com.inductiveautomation.ignition.common.script.PyDelegateObject.noAttributeError(PyDelegateObject.java:316)
	at org.python.core.PyObject.__getattr__(PyObject.java:959)
	at org.python.pycode._pyx140.valueChanged$1(<function:valueChanged>:2)
	at org.python.pycode._pyx140.call_function(<function:valueChanged>)
	at org.python.core.PyTableCode.call(PyTableCode.java:173)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:306)
	at org.python.core.PyFunction.function___call__(PyFunction.java:474)
	at org.python.core.PyFunction.__call__(PyFunction.java:469)
	at org.python.core.PyFunction.__call__(PyFunction.java:464)
	at com.inductiveautomation.ignition.common.script.ScriptManager.runFunction(ScriptManager.java:839)
	at com.inductiveautomation.ignition.common.script.ScriptManager.runFunction(ScriptManager.java:821)
	at com.inductiveautomation.ignition.gateway.project.ProjectScriptLifecycle$TrackingProjectScriptManager.runFunction(ProjectScriptLifecycle.java:828)
	at com.inductiveautomation.ignition.common.script.ScriptManager$ScriptFunctionImpl.invoke(ScriptManager.java:1002)
	at com.inductiveautomation.ignition.gateway.project.ProjectScriptLifecycle$AutoRecompilingScriptFunction.invoke(ProjectScriptLifecycle.java:893)
	at com.inductiveautomation.perspective.gateway.script.ScriptFunctionHelper.invoke(ScriptFunctionHelper.java:147)
	at com.inductiveautomation.perspective.gateway.model.PropertyChangeScript.access$001(PropertyChangeScript.java:30)
	at com.inductiveautomation.perspective.gateway.model.PropertyChangeScript$ScriptSequencer.run(PropertyChangeScript.java:156)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
	at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at com.inductiveautomation.perspective.gateway.threading.BlockingWork$BlockingWorkRunnable.run(BlockingWork.java:58)
	at java.base/java.lang.Thread.run(Unknown Source)
Caused by: org.python.core.PyException
Traceback (most recent call last):
  File "<function:valueChanged>", line 2, in valueChanged
AttributeError: 'com.inductiveautomation.perspective.gateway.script' object has no attribute 'driver'

pturmel · March 13, 2024, 4:35pm

That is definitely on you. Threads must terminate themselves. If you have threads that start with a script library startup, you are responsible for signaling prior scripts to terminate (via .interrupt(), typically). The long-lived script itself must deliberately check, regularly, for interruption.

victordcq · March 14, 2024, 7:38am

its seems that scripts that used 'import logging' got stuck doing nothing

import logging
logging.info('hello')

does nothing, it just keeps running without printing anything...
yes im not using the system.util.getLogger(), but this logging libary was standard in pylib, how can this get suck doing nothing?

they were running 8h, i saw scripts running for 8h's. , we have used this libary a ton before and ive never seen this happen

Edit:
i found another log, seems that getting stuck my also have been caused by out of memmory... but what is causing the out of memmory than.

So many things suddanly failing without an code changes... i guess it really is just a memmory issue then? Or the pc is broken

com.inductiveautomation.ignition.common.script.JythonExecException: Traceback (most recent call last): File "", line 8, in File "", line 8, in File "C:\Program Files\Inductive Automation\Ignition\user-lib\pylib\xxx.py", line 213, in synchronizeVision logger.info("done sync vision") File "C:\Program Files\Inductive Automation\Ignition\user-lib\pylib\logging\__init__.py", line 1151, in info self._log(INFO, msg, args, **kwargs) File "C:\Program Files\Inductive Automation\Ignition\user-lib\pylib\logging\__init__.py", line 1270, in _log self.handle(record) File "C:\Program Files\Inductive Automation\Ignition\user-lib\pylib\logging\__init__.py", line 1280, in handle self.callHandlers(record) File "C:\Program Files\Inductive Automation\Ignition\user-lib\pylib\logging\__init__.py", line 1320, in callHandlers hdlr.handle(record) File "user-lib\pylib\warnings.py", line 233, in warn warn_explicit(message, category, filename, lineno, module, registry, File "user-lib\pylib\warnings.py", line 272, in warn_explicit linecache.getlines(filename, module_globals) File "user-lib\pylib\linecache.py", line 40, in getlines return updatecache(filename, module_globals) File "user-lib\pylib\linecache.py", line 80, in updatecache stat = os.stat(fullname) File "user-lib\pylib\linecache.py", line 80, in updatecache stat = os.stat(fullname) java.lang.OutOfMemoryError: Java heap space java.lang.OutOfMemoryError: java.lang.OutOfMemoryError: Java heap space

at org.python.core.Py.JavaError(Py.java:547)

at org.python.core.Py.setException(Py.java:1617)

at linecache$py.updatecache$5(user-lib/pylib/linecache.py:135)

at linecache$py.call_function(user-lib/pylib/linecache.py)

at org.python.core.PyTableCode.call(PyTableCode.java:173)

at org.python.core.PyBaseCode.call(PyBaseCode.java:150)

at org.python.core.PyFunction.__call__(PyFunction.java:426)

at linecache$py.getlines$3(user-lib/pylib/linecache.py:40)

at linecache$py.call_function(user-lib/pylib/linecache.py)

at org.python.core.PyTableCode.call(PyTableCode.java:173)

at org.python.core.PyBaseCode.call(PyBaseCode.java:150)

at org.python.core.PyFunction.__call__(PyFunction.java:426)

at warnings$py.warn_explicit$18(user-lib/pylib/warnings.py:301)

at warnings$py.call_function(user-lib/pylib/warnings.py)

at org.python.core.PyTableCode.call(PyTableCode.java:173)

at org.python.core.PyBaseCode.call(PyBaseCode.java:306)

at org.python.core.PyFunction.function___call__(PyFunction.java:474)

at org.python.core.PyFunction.__call__(PyFunction.java:469)

at org.python.core.PyFunction.__call__(PyFunction.java:459)

at warnings$py.warn$17(user-lib/pylib/warnings.py:233)

at warnings$py.call_function(user-lib/pylib/warnings.py)

at org.python.core.PyTableCode.call(PyTableCode.java:173)

at org.python.core.PyBaseCode.call(PyBaseCode.java:168)

at org.python.core.PyFunction.__call__(PyFunction.java:437)

at org.python.core.PyFunction.__call__(PyFunction.java:431)

at org.python.core.Py.warning(Py.java:507)

at org.python.core.Py.warning(Py.java:494)

at org.python.core.PyTableCode.call(PyTableCode.java:177)

at org.python.core.PyBaseCode.call(PyBaseCode.java:150)

at org.python.core.PyFunction.__call__(PyFunction.java:426)

at org.python.core.PyMethod.__call__(PyMethod.java:141)

at logging$py.callHandlers$85(C:/Program Files/Inductive Automation/Ignition/user-lib/pylib/logging/__init__.py:1328)

at logging$py.call_function(C:/Program Files/Inductive Automation/Ignition/user-lib/pylib/logging/__init__.py)

at org.python.core.PyTableCode.call(PyTableCode.java:173)

at org.python.core.PyBaseCode.call(PyBaseCode.java:150)

at org.python.core.PyFunction.__call__(PyFunction.java:426)

at org.python.core.PyMethod.__call__(PyMethod.java:141)

at logging$py.handle$82(C:/Program Files/Inductive Automation/Ignition/user-lib/pylib/logging/__init__.py:1280)

at logging$py.call_function(C:/Program Files/Inductive Automation/Ignition/user-lib/pylib/logging/__init__.py)

at org.python.core.PyTableCode.call(PyTableCode.java:173)

at org.python.core.PyBaseCode.call(PyBaseCode.java:150)

at org.python.core.PyFunction.__call__(PyFunction.java:426)

at org.python.core.PyMethod.__call__(PyMethod.java:141)

at logging$py._log$81(C:/Program Files/Inductive Automation/Ignition/user-lib/pylib/logging/__init__.py:1270)

at logging$py.call_function(C:/Program Files/Inductive Automation/Ignition/user-lib/pylib/logging/__init__.py)

at org.python.core.PyTableCode.call(PyTableCode.java:173)

at org.python.core.PyBaseCode.call(PyBaseCode.java:306)

at org.python.core.PyBaseCode.call(PyBaseCode.java:197)

at org.python.core.PyFunction.__call__(PyFunction.java:485)

at org.python.core.PyMethod.instancemethod___call__(PyMethod.java:237)

at org.python.core.PyMethod.__call__(PyMethod.java:228)

at org.python.core.PyMethod.__call__(PyMethod.java:223)

at org.python.core.PyObject._callextra(PyObject.java:589)

at logging$py.info$73(C:/Program Files/Inductive Automation/Ignition/user-lib/pylib/logging/__init__.py:1151)

at logging$py.call_function(C:/Program Files/Inductive Automation/Ignition/user-lib/pylib/logging/__init__.py)

at org.python.core.PyTableCode.call(PyTableCode.java:173)

at org.python.core.PyBaseCode.call(PyBaseCode.java:306)

at org.python.core.PyBaseCode.call(PyBaseCode.java:141)

at org.python.core.PyFunction.__call__(PyFunction.java:426)

at org.python.core.PyMethod.__call__(PyMethod.java:141)

at xxx$py.synchronizeVision$2(C:/Program Files/Inductive Automation/Ignition/user-lib/pylib/xxx.py:213)

at xxx$py.call_function(C:/Program Files/Inductive Automation/Ignition/user-lib/pylib/xxxpy)

at org.python.core.PyTableCode.call(PyTableCode.java:173)

at org.python.core.PyBaseCode.call(PyBaseCode.java:150)

at org.python.core.PyFunction.__call__(PyFunction.java:426)

at org.python.pycode._pyx65.f$0(:19)

at org.python.pycode._pyx65.call_function()

at org.python.core.PyTableCode.call(PyTableCode.java:173)

at org.python.core.PyCode.call(PyCode.java:18)

at org.python.core.Py.runCode(Py.java:1687)

at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:796)

at com.inductiveautomation.ignition.gateway.project.ProjectScriptLifecycle$TrackingProjectScriptManager.runCode(ProjectScriptLifecycle.java:819)

at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:748)

at com.inductiveautomation.ignition.gateway.project.ProjectScriptLifecycle$TrackingProjectScriptManager.runCode(ProjectScriptLifecycle.java:800)

at com.inductiveautomation.ignition.common.script.TimerScriptTask.run(TimerScriptTask.java:90)

at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)

at java.base/java.util.concurrent.FutureTask.runAndReset(Unknown Source)

at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)

at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

at java.base/java.lang.Thread.run(Unknown Source)

Caused by: org.python.core.PyException: java.lang.OutOfMemoryError: java.lang.OutOfMemoryError: Java heap space

... 81 common frames omitted

pturmel · March 14, 2024, 11:03am

I'm surprised that such an experienced hand at Ignition is using pylib for anything that has Ignition-supplied or java-supplied alternatives.

victordcq · March 14, 2024, 11:16am

This is code that was made when i started using igntion 3 years ago, and has not had any problmes untill now.

when im going through the views and testing the big queries i never get more than 30% cpu, but when the issue happended it spiked to 100% very fast...

i have no idea what's the issue as i can not reproduce it consitently...

victordcq · March 18, 2024, 9:54am

Not sure what it was exactly... But things are back to normal with spikes of max 27%

It was either our logging, for which i deleted a bunch of files in the folder we used. There were a ton of them from years ago, so yeah that was no longer needed. Maybe it cleared up a lot of space. I also filtered out a bunch of useless logs that appeared daily cluttering the log files. The vm this is running on isnt the best.

In lights of pturmel comment about threads, I also changed some of the timer scripts that use api calls , their threading to dedicated instead of shared. I had no idea this existed, the timer settings were a bit hidden :o

They also restarted their server (not just the service but the whole pc), maybe that fixed it

So far things seem to be going normal again, i guess we'll see if it happens again in a few years than it was the logger, if not it was the threading.
Or if it somehow happens again sooner then it has not been solved yet...

victordcq · March 20, 2024, 8:11am

well damn, now it got even worse, i couldnt even log in

INFO   | jvm 1    | 2024/03/20 05:36:19 | I [P.InternalDatabase            ] [04:36:19]: Created auto-backup of internal database "config.idb" in 1 seconds 
INFO   | jvm 1    | 2024/03/20 07:40:05 | W [P.WebSocketChannel            ] [06:40:05]: Websocket connection closed unexpectedly. code=1006, reason=Disconnected, codeMeaning=Normal Closure, codeDescription=Reserved. Indicates that a connection was closed abnormally (that is, with no close frame being sent) when a status code is expected.  
INFO   | jvm 1    | 2024/03/20 07:46:20 | I [P.InternalDatabase            ] [06:46:20]: Creating auto-backup of internal database "config.idb"... 
INFO   | jvm 1    | 2024/03/20 07:46:21 | I [P.InternalDatabase            ] [06:46:21]: Created auto-backup of internal database "config.idb" in 1 seconds 
INFO   | jvm 1    | 2024/03/20 08:06:53 | I [p.ClientSession               ] [07:06:53]: WebSocket disconnected from session. session-project=xxxMES
INFO   | jvm 1    | 2024/03/20 08:21:24 | W [ClockDriftDetector            ] [07:21:24]: Clock drift, degraded performance, or pause-the-world detected.
INFO   | jvm 1    | 2024/03/20 08:21:24 | Max allowed deviation=1000ms, actual deviation=2736ms 
INFO   | jvm 1    | 2024/03/20 08:21:57 | W [ClockDriftDetector            ] [07:21:57]: Clock drift, degraded performance, or pause-the-world detected.
INFO   | jvm 1    | 2024/03/20 08:21:57 | Max allowed deviation=1000ms, actual deviation=1079ms 
INFO   | jvm 1    | 2024/03/20 08:22:02 | W [ClockDriftDetector            ] [07:22:02]: Clock drift, degraded performance, or pause-the-world detected.
INFO   | jvm 1    | 2024/03/20 08:22:02 | Max allowed deviation=1000ms, actual deviation=2755ms 
INFO   | jvm 1    | 2024/03/20 08:22:09 | W [ClockDriftDetector            ] [07:22:06]: Clock drift, degraded performance, or pause-the-world detected.
INFO   | jvm 1    | 2024/03/20 08:22:09 | Max allowed deviation=1000ms, actual deviation=1579ms 
INFO   | jvm 1    | 2024/03/20 08:22:16 | W [ClockDriftDetector            ] [07:22:12]: Clock drift, degraded performance, or pause-the-world detected.
INFO   | jvm 1    | 2024/03/20 08:22:16 | Max allowed deviation=1000ms, actual deviation=3521ms 
INFO   | jvm 1    | 2024/03/20 08:22:17 | W [ClockDriftDetector            ] [07:22:17]: Clock drift, degraded performance, or pause-the-world detected.
INFO   | jvm 1    | 2024/03/20 08:22:17 | Max allowed deviation=1000ms, actual deviation=4642ms 
INFO   | jvm 1    | 2024/03/20 08:22:24 | W [ClockDriftDetector            ] [07:22:24]: Clock drift, degraded performance, or pause-the-world detected.
INFO   | jvm 1    | 2024/03/20 08:22:24 | Max allowed deviation=1000ms, actual deviation=5749ms 
INFO   | jvm 1    | 2024/03/20 08:22:26 | E [C.BasicExecutionEngine        ] [07:22:26]: Task gateway performance monitor threw uncaught exception. 
INFO   | jvm 1    | 2024/03/20 08:22:26 | java.lang.OutOfMemoryError: Java heap space
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at java.base/jdk.internal.misc.Unsafe.allocateUninitializedArray(Unknown Source)
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at java.base/java.lang.invoke.StringConcatFactory$MethodHandleInlineCopyStrategy.newArray(Unknown Source)
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at java.base/java.lang.invoke.DirectMethodHandle$Holder.invokeStatic(DirectMethodHandle$Holder)
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at java.base/java.lang.invoke.LambdaForm$MH/0x00000001000eb040.invoke(LambdaForm$MH)
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at java.base/java.lang.invoke.DelegatingMethodHandle$Holder.reinvoke_L(DelegatingMethodHandle$Holder)
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at java.base/java.lang.invoke.Invokers$Holder.linkToTargetMethod(Invokers$Holder)
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at java.management/java.lang.management.ThreadInfo.initialize(Unknown Source)
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at java.management/java.lang.management.ThreadInfo.<init>(Unknown Source)
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at java.management/sun.management.ThreadImpl.getThreadInfo1(Native Method)
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at java.management/sun.management.ThreadImpl.getThreadInfo(Unknown Source)
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at java.management/sun.management.ThreadImpl.getThreadInfo(Unknown Source)
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at com.inductiveautomation.ignition.gateway.util.PerformanceMonitor.updateThreads(PerformanceMonitor.java:261)
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at com.inductiveautomation.ignition.gateway.util.PerformanceMonitor.getCpuUsage(PerformanceMonitor.java:235)
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at com.inductiveautomation.ignition.gateway.IgnitionGateway$PerformanceStatusTagManager.refresh(IgnitionGateway.java:3269)
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at com.inductiveautomation.ignition.gateway.IgnitionGateway.lambda$startupInternal$10(IgnitionGateway.java:1294)
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at com.inductiveautomation.ignition.gateway.IgnitionGateway$$Lambda$3169/0x00000001015b5c40.run(Unknown Source)
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at com.inductiveautomation.ignition.common.execution.impl.BasicExecutionEngine$TrackedTask.run(BasicExecutionEngine.java:587)
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at java.base/java.util.concurrent.FutureTask.runAndReset(Unknown Source)
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
INFO   | jvm 1    | 2024/03/20 08:22:26 | 	at java.base/java.lang.Thread.run(Unknown Source)
STATUS | wrapper  | 2024/03/20 08:22:28 | Pinging the JVM took 7 seconds to respond.
STATUS | wrapper  | 2024/03/20 08:23:27 | Pinging the JVM took 25 seconds to respond.
STATUS | wrapper  | 2024/03/20 08:23:27 | Pinging the JVM took 20 seconds to respond.
STATUS | wrapper  | 2024/03/20 08:23:27 | Pinging the JVM took 15 seconds to respond.
STATUS | wrapper  | 2024/03/20 08:23:27 | Pinging the JVM took 10 seconds to respond.
INFO   | jvm 1    | 2024/03/20 08:23:50 | Exception in thread "Connection evictor" java.lang.OutOfMemoryError: Java heap space
STATUS | wrapper  | 2024/03/20 08:23:50 | Pinging the JVM took 17 seconds to respond.
STATUS | wrapper  | 2024/03/20 08:23:50 | Pinging the JVM took 12 seconds to respond.
STATUS | wrapper  | 2024/03/20 08:23:50 | Pinging the JVM took 7 seconds to respond.
INFO   | jvm 1    | 2024/03/20 08:23:51 | Exception in thread "gateway-storeforward-pipeline[xxx]-engine[PrimarySFEngine]" java.lang.OutOfMemoryError: Java heap space
INFO   | jvm 1    | 2024/03/20 08:23:51 | Exception in thread "AsyncAppender-Worker-SysoutAsync" java.lang.OutOfMemoryError: Java heap space
INFO   | jvm 1    | 2024/03/20 08:23:51 | Exception in thread "gateway-log-monitoring-session-reaper" java.lang.OutOfMemoryError: Java heap space
INFO   | jvm 1    | 2024/03/20 08:23:51 | Exception in thread "gateway-expr-pollingfunc-timer" java.lang.OutOfMemoryError: Java heap space
INFO   | jvm 1    | 2024/03/20 08:23:51 | Exception in thread "tag-group-manager" java.lang.OutOfMemoryError: Java heap space

simpleorm.utils.SException$Jdbc: Opening com.inductiveautomation.ignition.gateway.localdb.CountingDataSource@6d9d2fc7

at simpleorm.sessionjdbc.SSessionJdbc.innerOpen(SSessionJdbc.java:113)

at com.inductiveautomation.ignition.gateway.localdb.persistence.PersistenceSession.initialize(PersistenceSession.java:31)

at com.inductiveautomation.ignition.gateway.localdb.PersistenceInterfaceImpl.getSession(PersistenceInterfaceImpl.java:64)

at com.inductiveautomation.ignition.gateway.localdb.PersistenceInterfaceImpl.getSession(PersistenceInterfaceImpl.java:45)

at com.inductiveautomation.ignition.gateway.authentication.impl.InternalUserSource.getUsers(InternalUserSource.java:392)

at com.inductiveautomation.ignition.gateway.authentication.UserSourceWrapper.doGetUsers(UserSourceWrapper.java:411)

at com.inductiveautomation.ignition.gateway.authentication.UserSourceWrapper$UserCacheImpl.doUpdate(UserSourceWrapper.java:268)

at com.inductiveautomation.ignition.gateway.authentication.UserSourceWrapper$UserCacheImpl.doUpdate(UserSourceWrapper.java:264)

at com.inductiveautomation.ignition.gateway.authentication.AbstractCache$UpdateTask.run(AbstractCache.java:118)

at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)

at java.base/java.util.concurrent.FutureTask.run(Unknown Source)

at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

at java.base/java.lang.Thread.run(Unknown Source)

Caused by: java.sql.SQLException: Connection is locked. Datasource only allows one connection at a time. More information was logged to the gateway console.

at com.inductiveautomation.ignition.gateway.localdb.sqlite.SingleConnectionDatasource.getConnection(SingleConnectionDatasource.java:75)

at com.inductiveautomation.ignition.gateway.localdb.DelegatingDataSource.getConnection(DelegatingDataSource.java:60)

at simpleorm.sessionjdbc.SSessionJdbc.innerOpen(SSessionJdbc.java:111)

... 13 common frames omitted

java.lang.Exception: null

at com.inductiveautomation.ignition.gateway.localdb.PersistenceInterfaceImpl.getSession(PersistenceInterfaceImpl.java:58)

at com.inductiveautomation.ignition.gateway.localdb.PersistenceInterfaceImpl.getSession(PersistenceInterfaceImpl.java:45)

at com.inductiveautomation.ignition.gateway.tags.config.storage.internaljson.InternalJsonStorageManager.saveInternal(InternalJsonStorageManager.java:296)

at com.inductiveautomation.ignition.gateway.tags.config.storage.internaljson.InternalJsonStorageManager$IndependantTagSynchronizationProvider.processChanges(InternalJsonStorageManager.java:528)

at com.inductiveautomation.ignition.gateway.tags.config.storage.internaljson.InternalJsonStorageManager$RedundantTagSynchronizationProvider.processChanges(InternalJsonStorageManager.java:623)

at com.inductiveautomation.ignition.gateway.tags.config.storage.internaljson.InternalJsonStorageManager.save(InternalJsonStorageManager.java:193)

at com.inductiveautomation.ignition.gateway.tags.config.BatchConfigOperation.save(BatchConfigOperation.java:120)

at com.inductiveautomation.ignition.gateway.tags.config.BatchConfigOperation.execute(BatchConfigOperation.java:105)

at com.inductiveautomation.ignition.gateway.tags.evaluation.BatchContextImpl$OpController.run(BatchContextImpl.java:240)

at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

at java.base/java.lang.Thread.run(Unknown Source)

I does usually appear to happen after a config backup...

victordcq · March 20, 2024, 8:43am

i"ll try to update to the latest version i guess

YF129701 · March 20, 2024, 2:14pm

This is probably unrelated to your problem, but how are you running Perspective on 2 GB of memory?! Sometimes a customer will have 8 and it's almost impossible to use...

victordcq · March 20, 2024, 3:37pm

Maybe its not unrelated since im getting memory issues xD But so far it had worked fine so idk.

This project isnt all that big and its mainly using selfmade custom modules for visualisition and api calls to a server that handles most of the logic

victordcq · March 21, 2024, 10:45am

So updating did not help.

Altho we have no memmory issues (just yet, maybe i just caught it earlier this time) the threads are again getting filled up again with what looks like unresolved http threads app//com.inductiveautomation.ignition.common.script.builtin.http.JythonHttpClient.get

Thread [perspective-worker-812] id=20888, (WAITING for java.util.concurrent.CompletableFuture$Signaller@6f0310)
java.base@17.0.9/jdk.internal.misc.Unsafe.park(Native Method)
java.base@17.0.9/java.util.concurrent.locks.LockSupport.park(Unknown Source)
java.base@17.0.9/java.util.concurrent.CompletableFuture$Signaller.block(Unknown Source)
java.base@17.0.9/java.util.concurrent.ForkJoinPool.unmanagedBlock(Unknown Source)
java.base@17.0.9/java.util.concurrent.ForkJoinPool.managedBlock(Unknown Source)
java.base@17.0.9/java.util.concurrent.CompletableFuture.waitingGet(Unknown Source)
java.base@17.0.9/java.util.concurrent.CompletableFuture.get(Unknown Source)
platform/java.net.http@17.0.9/jdk.internal.net.http.HttpClientImpl.send(Unknown Source)
platform/java.net.http@17.0.9/jdk.internal.net.http.HttpClientFacade.send(Unknown Source)
app//com.inductiveautomation.ignition.common.script.builtin.http.JythonHttpClient.send(JythonHttpClient.java:102)
app//com.inductiveautomation.ignition.common.script.builtin.http.JythonHttpClient.get(JythonHttpClient.java:308)
jdk.internal.reflect.GeneratedMethodAccessor56.invoke(Unknown Source)
java.base@17.0.9/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
java.base@17.0.9/java.lang.reflect.Method.invoke(Unknown Source)
app//org.python.core.PyReflectedFunction.__call__(PyReflectedFunction.java:190)
app//org.python.core.PyObject.__call__(PyObject.java:422)
app//org.python.core.PyMethod.instancemethod___call__(PyMethod.java:237)
app//org.python.core.PyMethod.__call__(PyMethod.java:228)
xxx.api.process.reception$py.getReceptions$17(C:/Program Files/Inductive Automation/Ignition/user-lib/pylib/xxx/api/process/reception.py:224)
xxx.api.process.reception$py.call_function(C:/Program Files/Inductive Automation/Ignition/user-lib/pylib/xxx/api/process/reception.py)
app//org.python.core.PyTableCode.call(PyTableCode.java:173)
app//org.python.core.PyBaseCode.call(PyBaseCode.java:306)
app//org.python.core.PyBaseCode.call(PyBaseCode.java:126)
app//org.python.core.PyFunction.__call__(PyFunction.java:416)
app//org.python.core.PyMethod.__call__(PyMethod.java:126)
org.python.pycode._pyx395.runAction$1(:4)
org.python.pycode._pyx395.call_function()
app//org.python.core.PyTableCode.call(PyTableCode.java:173)
app//org.python.core.PyBaseCode.call(PyBaseCode.java:306)
app//org.python.core.PyFunction.function___call__(PyFunction.java:474)
app//org.python.core.PyFunction.__call__(PyFunction.java:469)
app//org.python.core.PyFunction.__call__(PyFunction.java:464)
app//com.inductiveautomation.ignition.common.script.ScriptManager.runFunction(ScriptManager.java:847)
app//com.inductiveautomation.ignition.common.script.ScriptManager.runFunction(ScriptManager.java:829)
app//com.inductiveautomation.ignition.gateway.project.ProjectScriptLifecycle$TrackingProjectScriptManager.runFunction(ProjectScriptLifecycle.java:868)
app//com.inductiveautomation.ignition.common.script.ScriptManager$ScriptFunctionImpl.invoke(ScriptManager.java:1010)
app//com.inductiveautomation.ignition.gateway.project.ProjectScriptLifecycle$AutoRecompilingScriptFunction.invoke(ProjectScriptLifecycle.java:950)
com.inductiveautomation.perspective.gateway.script.ScriptFunctionHelper.invoke(ScriptFunctionHelper.java:161)
com.inductiveautomation.perspective.gateway.script.ScriptFunctionHelper.invoke(ScriptFunctionHelper.java:98)
com.inductiveautomation.perspective.gateway.action.ScriptAction.runAction(ScriptAction.java:80)
com.inductiveautomation.perspective.gateway.model.ActionCollection$ActionSequence$ExecuteActionsTask.lambda$call$0(ActionCollection.java:263)
com.inductiveautomation.perspective.gateway.model.ActionCollection$ActionSequence$ExecuteActionsTask$$Lambda$4241/0x000001d0025b37b8.run(Unknown Source)
com.inductiveautomation.perspective.gateway.api.LoggingContext.mdc(LoggingContext.java:54)
com.inductiveautomation.perspective.gateway.model.ActionCollection$ActionSequence$ExecuteActionsTask.call(ActionCollection.java:252)
com.inductiveautomation.perspective.gateway.model.ActionCollection$ActionSequence$ExecuteActionsTask.call(ActionCollection.java:221)
com.inductiveautomation.perspective.gateway.threading.BlockingTaskQueue$TaskWrapper.run(BlockingTaskQueue.java:154)
java.base@17.0.9/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
java.base@17.0.9/java.util.concurrent.FutureTask.run(Unknown Source)
java.base@17.0.9/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
java.base@17.0.9/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
com.inductiveautomation.perspective.gateway.threading.BlockingWork$BlockingWorkRunnable.run(BlockingWork.java:58)
java.base@17.0.9/java.lang.Thread.run(Unknown Source)

pturmel · March 21, 2024, 11:05am

That can only happen in a few cases:

You have events that are creating their own httpClient instances instead of sharing a per-script top-level instance.
You have long-lived threads holding httpClient instances, and those threads don't kill themselves when their project is edited. (In which case you are also leaking entire jython interpreters per scripting restart.)

victordcq · March 21, 2024, 11:08am

victordcq:

if "client" not in system.util.getGlobals():
        system.util.getGlobals()["client"] = system.net.httpClient()

client = system.util.getGlobals()["client"]

...

client.get(url="%s" %(self.base_url), headers=self.headers)

Its used like this, though there are several separte files. but not that many as i have threads

pturmel · March 21, 2024, 11:13am

No, you should not be putting httpClient instances in getGlobals. Just make one at the top level of each script that needs one.

victordcq · March 21, 2024, 11:15am

so just this?

client = system.net.httpClient()

pturmel · March 21, 2024, 11:15am

Yes.

victordcq · March 21, 2024, 12:57pm

Does not look like this helped
The runnig scripts keep stacking up again, 4 pages already...

pturmel · March 21, 2024, 1:04pm

Then you have something in your system making many threads. That trace is for one of your threads waiting on an API response. I'm going to guess that it is in a Perspective transform.

Kevin.Herron · March 21, 2024, 1:05pm

Controlling the number of client instances doesn't have anything to do with the number of threads/HTTP calls being made.

It looks like you're making HTTP calls from inside a script transform, and from a skim of this thread, making many more HTTP calls than perhaps you realize.