MS SQL keeps randomly faulting, gateway disconnecting randomly

bkarabinchak.psi · March 14, 2019, 7:49pm

I am using Ignition 7.9.10 and MS SQL Server 2014.

The connection will work and remain valid for a while, and then randomly fault 4 times in 2 minutes. This seems coupled with my instance being disconnected from the gateway randomly. It’s making it impossible to test a screen on.

In addition to this, I’m unsure if this affects anything, I keep gettting ClockDriftDetector errors despite having just syncing my clock with internet time. It’s not off by much about 20 ms, but it does appear pretty regularly. As does this error - .drivers.TCPDriver[MarkEm_CoLOS_CimJet].T 14Mar2019 15:46:59 Error connecting to 192.168.0.50:1912. Connection timed out: connect.

Any ideas/anything fixable on my end or something I can try?

If this beyond my fixing, what files should I gather to show tech support regarding this?

Kevin.Herron · March 14, 2019, 7:58pm

The clock drift detector only reports deviations > 1000ms... can you post one of the messages?

bkarabinchak.psi · March 15, 2019, 12:39pm

Actually clock drift seems ok now. However, when testing the screen which involces scanning barcodes and looking them up in a database, it will work for a while and then I start getting errors because the DB connect just randomly faults.

Database	15Mar2019 08:22:22	Database connection FAULTED.
org.apache.commons.dbcp.SQLNestedException: Cannot get a connection, pool error Timeout waiting for idle object

at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:104)

at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)

at com.inductiveautomation.ignition.gateway.datasource.DatasourceImpl.getConnectionInternal(DatasourceImpl.java:224)

at com.inductiveautomation.ignition.gateway.datasource.DatasourceManagerImpl.getConnectionImpl(DatasourceManagerImpl.java:150)

at com.inductiveautomation.ignition.gateway.datasource.DatasourceImpl.getConnection(DatasourceImpl.java:219)

at com.inductiveautomation.ignition.gateway.datasource.DatasourceManagerImpl.getConnection(DatasourceManagerImpl.java:133)

at com.inductiveautomation.ignition.gateway.script.GatewayDBUtilities.getConnection(GatewayDBUtilities.java:83)

at com.inductiveautomation.ignition.gateway.servlets.gateway.functions.AbstractDBAction.invoke(AbstractDBAction.java:64)

at com.inductiveautomation.ignition.gateway.servlets.Gateway.doPost(Gateway.java:410)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)

at com.inductiveautomation.ignition.gateway.bootstrap.MapServlet.service(MapServlet.java:85)

at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:837)

at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:583)

at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)

at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)

at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226)

at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1160)

at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:511)

at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)

at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1092)

at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)

at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:52)

at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)

at org.eclipse.jetty.server.Server.handle(Server.java:518)

at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:308)

at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:244)

at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)

at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)

at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)

at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceAndRun(ExecuteProduceConsume.java:246)

at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:156)

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:654)

at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:572)

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

Caused by: java.util.NoSuchElementException: Timeout waiting for idle object

at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:958)

at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:96)




I think this is coupled with my gateway connection getting lost and found again, and my whole popup window resets as though I haven't done scanning yet.  I have yet to make it through 24 barcodes without this happening.  The only other logged error I see is - ...drivers.TCPDriver[MarkEm_CoLOS_CimJet].T	15Mar2019 08:34:00	

It happened just now at 8:33 this morning during testing again and this is the error I see in my wrapper.log - 

INFO   | jvm 1    | 2019/03/15 08:33:04 | E [TagChangeScriptExecutor       ] [12:33:04]: Error executing tag change script: AntiDiversion/Engine: Data Read on Data Change 
INFO   | jvm 1    | 2019/03/15 08:33:04 | com.inductiveautomation.ignition.common.script.JythonExecException: Traceback (most recent call last):
INFO   | jvm 1    | 2019/03/15 08:33:04 |   File "<TagChangeScript:AntiDiversion/Engine: Data Read on Data Change>", line 19, in <module>
INFO   | jvm 1    | 2019/03/15 08:33:04 |   File "<module:project.scanner>", line 17, in read
INFO   | jvm 1    | 2019/03/15 08:33:04 |   File "<module:project.scanner>", line 71, in parseCode
INFO   | jvm 1    | 2019/03/15 08:33:04 | IndexError: index out of range: -3
INFO   | jvm 1    | 2019/03/15 08:33:04 | 
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at org.python.core.Py.IndexError(Py.java:250)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at org.python.core.SequenceIndexDelegate.checkIdxAndGetItem(SequenceIndexDelegate.java:63)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at org.python.core.PySequence.seq___getitem__(PySequence.java:305)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at org.python.core.PySequence.__getitem__(PySequence.java:301)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at org.python.pycode._pyx18.parseCode$3(<module:project.scanner>:89)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at org.python.pycode._pyx18.call_function(<module:project.scanner>)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at org.python.core.PyTableCode.call(PyTableCode.java:165)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at org.python.core.PyBaseCode.call(PyBaseCode.java:134)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at org.python.core.PyFunction.__call__(PyFunction.java:317)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at org.python.pycode._pyx18.read$1(<module:project.scanner>:24)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at org.python.pycode._pyx18.call_function(<module:project.scanner>)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at org.python.core.PyTableCode.call(PyTableCode.java:165)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at org.python.core.PyBaseCode.call(PyBaseCode.java:134)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at org.python.core.PyFunction.__call__(PyFunction.java:317)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at org.python.pycode._pyx4.f$0(<TagChangeScript:AntiDiversion/Engine: Data Read on Data Change>:19)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at org.python.pycode._pyx4.call_function(<TagChangeScript:AntiDiversion/Engine: Data Read on Data Change>)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at org.python.core.PyTableCode.call(PyTableCode.java:165)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at org.python.core.PyCode.call(PyCode.java:18)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at org.python.core.Py.runCode(Py.java:1275)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:657)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:616)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at com.inductiveautomation.ignition.common.script.TagChangeScriptExecutor$TagChangeExecutionCallback.execute(TagChangeScriptExecutor.java:187)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at com.inductiveautomation.ignition.common.script.TagChangeScriptExecutor$TagChangeExecutionCallback.execute(TagChangeScriptExecutor.java:134)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at com.inductiveautomation.ignition.common.util.SerialExecutionQueue$PollAndExecute.run(SerialExecutionQueue.java:99)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at java.util.concurrent.FutureTask.run(Unknown Source)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	at java.lang.Thread.run(Unknown Source)
INFO   | jvm 1    | 2019/03/15 08:33:04 | Caused by: org.python.core.PyException: Traceback (most recent call last):
INFO   | jvm 1    | 2019/03/15 08:33:04 |   File "<TagChangeScript:AntiDiversion/Engine: Data Read on Data Change>", line 19, in <module>
INFO   | jvm 1    | 2019/03/15 08:33:04 |   File "<module:project.scanner>", line 17, in read
INFO   | jvm 1    | 2019/03/15 08:33:04 |   File "<module:project.scanner>", line 71, in parseCode
INFO   | jvm 1    | 2019/03/15 08:33:04 | IndexError: index out of range: -3
INFO   | jvm 1    | 2019/03/15 08:33:04 | 
INFO   | jvm 1    | 2019/03/15 08:33:04 | 	... 29 common frames omitted
INFO   | jvm 1    | 2019/03/15 08:33:07 | (Step 2a) Executing Read.
INFO   | jvm 1    | 2019/03/15 08:33:07 | I [dev logger                    ] [12:33:07]: 3 >> (Step 3) Read Data. Data From PLC = [2I] 
INFO   | jvm 1    | 2019/03/15 08:33:07 | E [TagChangeScriptExecutor       ] [12:33:07]: Error executing tag change script: AntiDiversion/Engine: Data Read on Data Change 
INFO   | jvm 1    | 2019/03/15 08:33:07 | com.inductiveautomation.ignition.common.script.JythonExecException: Traceback (most recent call last):
INFO   | jvm 1    | 2019/03/15 08:33:07 |   File "<TagChangeScript:AntiDiversion/Engine: Data Read on Data Change>", line 19, in <module>
INFO   | jvm 1    | 2019/03/15 08:33:07 |   File "<module:project.scanner>", line 17, in read
INFO   | jvm 1    | 2019/03/15 08:33:07 |   File "<module:project.scanner>", line 71, in parseCode
INFO   | jvm 1    | 2019/03/15 08:33:07 | IndexError: index out of range: -3
INFO   | jvm 1    | 2019/03/15 08:33:07 | 
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at org.python.core.Py.IndexError(Py.java:250)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at org.python.core.SequenceIndexDelegate.checkIdxAndGetItem(SequenceIndexDelegate.java:63)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at org.python.core.PySequence.seq___getitem__(PySequence.java:305)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at org.python.core.PySequence.__getitem__(PySequence.java:301)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at org.python.pycode._pyx18.parseCode$3(<module:project.scanner>:89)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at org.python.pycode._pyx18.call_function(<module:project.scanner>)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at org.python.core.PyTableCode.call(PyTableCode.java:165)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at org.python.core.PyBaseCode.call(PyBaseCode.java:134)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at org.python.core.PyFunction.__call__(PyFunction.java:317)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at org.python.pycode._pyx18.read$1(<module:project.scanner>:24)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at org.python.pycode._pyx18.call_function(<module:project.scanner>)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at org.python.core.PyTableCode.call(PyTableCode.java:165)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at org.python.core.PyBaseCode.call(PyBaseCode.java:134)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at org.python.core.PyFunction.__call__(PyFunction.java:317)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at org.python.pycode._pyx4.f$0(<TagChangeScript:AntiDiversion/Engine: Data Read on Data Change>:19)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at org.python.pycode._pyx4.call_function(<TagChangeScript:AntiDiversion/Engine: Data Read on Data Change>)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at org.python.core.PyTableCode.call(PyTableCode.java:165)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at org.python.core.PyCode.call(PyCode.java:18)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at org.python.core.Py.runCode(Py.java:1275)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:657)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:616)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at com.inductiveautomation.ignition.common.script.TagChangeScriptExecutor$TagChangeExecutionCallback.execute(TagChangeScriptExecutor.java:187)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at com.inductiveautomation.ignition.common.script.TagChangeScriptExecutor$TagChangeExecutionCallback.execute(TagChangeScriptExecutor.java:134)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at com.inductiveautomation.ignition.common.util.SerialExecutionQueue$PollAndExecute.run(SerialExecutionQueue.java:99)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at java.util.concurrent.FutureTask.run(Unknown Source)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	at java.lang.Thread.run(Unknown Source)
INFO   | jvm 1    | 2019/03/15 08:33:07 | Caused by: org.python.core.PyException: Traceback (most recent call last):
INFO   | jvm 1    | 2019/03/15 08:33:07 |   File "<TagChangeScript:AntiDiversion/Engine: Data Read on Data Change>", line 19, in <module>
INFO   | jvm 1    | 2019/03/15 08:33:07 |   File "<module:project.scanner>", line 17, in read
INFO   | jvm 1    | 2019/03/15 08:33:07 |   File "<module:project.scanner>", line 71, in parseCode
INFO   | jvm 1    | 2019/03/15 08:33:07 | IndexError: index out of range: -3
INFO   | jvm 1    | 2019/03/15 08:33:07 | 
INFO   | jvm 1    | 2019/03/15 08:33:07 | 	... 29 common frames omitted
INFO   | jvm 1    | 2019/03/15 08:33:09 | (Step 2a) Executing Read.
INFO   | jvm 1    | 2019/03/15 08:33:09 | I [dev logger                    ] [12:33:09]: 3 >> (Step 3) Read Data. Data From PLC = [3I] 
INFO   | jvm 1    | 2019/03/15 08:33:09 | E [TagChangeScriptExecutor       ] [12:33:09]: Error executing tag change script: AntiDiversion/Engine: Data Read on Data Change 
INFO   | jvm 1    | 2019/03/15 08:33:09 | com.inductiveautomation.ignition.common.script.JythonExecException: Traceback (most recent call last):
INFO   | jvm 1    | 2019/03/15 08:33:09 |   File "<TagChangeScript:AntiDiversion/Engine: Data Read on Data Change>", line 19, in <module>
INFO   | jvm 1    | 2019/03/15 08:33:09 |   File "<module:project.scanner>", line 17, in read
INFO   | jvm 1    | 2019/03/15 08:33:09 |   File "<module:project.scanner>", line 71, in parseCode
INFO   | jvm 1    | 2019/03/15 08:33:09 | IndexError: index out of range: -3
INFO   | jvm 1    | 2019/03/15 08:33:09 | 
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at org.python.core.Py.IndexError(Py.java:250)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at org.python.core.SequenceIndexDelegate.checkIdxAndGetItem(SequenceIndexDelegate.java:63)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at org.python.core.PySequence.seq___getitem__(PySequence.java:305)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at org.python.core.PySequence.__getitem__(PySequence.java:301)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at org.python.pycode._pyx18.parseCode$3(<module:project.scanner>:89)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at org.python.pycode._pyx18.call_function(<module:project.scanner>)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at org.python.core.PyTableCode.call(PyTableCode.java:165)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at org.python.core.PyBaseCode.call(PyBaseCode.java:134)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at org.python.core.PyFunction.__call__(PyFunction.java:317)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at org.python.pycode._pyx18.read$1(<module:project.scanner>:24)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at org.python.pycode._pyx18.call_function(<module:project.scanner>)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at org.python.core.PyTableCode.call(PyTableCode.java:165)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at org.python.core.PyBaseCode.call(PyBaseCode.java:134)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at org.python.core.PyFunction.__call__(PyFunction.java:317)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at org.python.pycode._pyx4.f$0(<TagChangeScript:AntiDiversion/Engine: Data Read on Data Change>:19)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at org.python.pycode._pyx4.call_function(<TagChangeScript:AntiDiversion/Engine: Data Read on Data Change>)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at org.python.core.PyTableCode.call(PyTableCode.java:165)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at org.python.core.PyCode.call(PyCode.java:18)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at org.python.core.Py.runCode(Py.java:1275)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:657)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:616)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at com.inductiveautomation.ignition.common.script.TagChangeScriptExecutor$TagChangeExecutionCallback.execute(TagChangeScriptExecutor.java:187)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at com.inductiveautomation.ignition.common.script.TagChangeScriptExecutor$TagChangeExecutionCallback.execute(TagChangeScriptExecutor.java:134)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at com.inductiveautomation.ignition.common.util.SerialExecutionQueue$PollAndExecute.run(SerialExecutionQueue.java:99)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at java.util.concurrent.FutureTask.run(Unknown Source)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	at java.lang.Thread.run(Unknown Source)
INFO   | jvm 1    | 2019/03/15 08:33:09 | Caused by: org.python.core.PyException: Traceback (most recent call last):
INFO   | jvm 1    | 2019/03/15 08:33:09 |   File "<TagChangeScript:AntiDiversion/Engine: Data Read on Data Change>", line 19, in <module>
INFO   | jvm 1    | 2019/03/15 08:33:09 |   File "<module:project.scanner>", line 17, in read
INFO   | jvm 1    | 2019/03/15 08:33:09 |   File "<module:project.scanner>", line 71, in parseCode
INFO   | jvm 1    | 2019/03/15 08:33:09 | IndexError: index out of range: -3
INFO   | jvm 1    | 2019/03/15 08:33:09 | 
INFO   | jvm 1    | 2019/03/15 08:33:09 | 	... 29 common frames omitted
INFO   | jvm 1    | 2019/03/15 08:33:09 | I [P.InternalDatabase            ] [12:33:09]: Creating auto-backup of internal database "config.idb"... 
INFO   | jvm 1    | 2019/03/15 08:33:11 | I [P.InternalDatabase            ] [12:33:11]: Created auto-backup of internal database "config.idb" in 1 seconds 
INFO   | jvm 1    | 2019/03/15 08:33:13 | (Step 2a) Executing Read.
INFO   | jvm 1    | 2019/03/15 08:33:13 | I [dev logger                    ] [12:33:13]: 3 >> (Step 3) Read Data. Data From PLC = [4I] 
INFO   | jvm 1    | 2019/03/15 08:33:13 | E [TagChangeScriptExecutor       ] [12:33:13]: Error executing tag change script: AntiDiversion/Engine: Data Read on Data Change 
INFO   | jvm 1    | 2019/03/15 08:33:13 | com.inductiveautomation.ignition.common.script.JythonExecException: Traceback (most recent call last):
INFO   | jvm 1    | 2019/03/15 08:33:13 |   File "<TagChangeScript:AntiDiversion/Engine: Data Read on Data Change>", line 19, in <module>
INFO   | jvm 1    | 2019/03/15 08:33:13 |   File "<module:project.scanner>", line 17, in read
INFO   | jvm 1    | 2019/03/15 08:33:13 |   File "<module:project.scanner>", line 71, in parseCode
INFO   | jvm 1    | 2019/03/15 08:33:13 | IndexError: index out of range: -3
INFO   | jvm 1    | 2019/03/15 08:33:13 | 
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at org.python.core.Py.IndexError(Py.java:250)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at org.python.core.SequenceIndexDelegate.checkIdxAndGetItem(SequenceIndexDelegate.java:63)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at org.python.core.PySequence.seq___getitem__(PySequence.java:305)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at org.python.core.PySequence.__getitem__(PySequence.java:301)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at org.python.pycode._pyx18.parseCode$3(<module:project.scanner>:89)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at org.python.pycode._pyx18.call_function(<module:project.scanner>)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at org.python.core.PyTableCode.call(PyTableCode.java:165)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at org.python.core.PyBaseCode.call(PyBaseCode.java:134)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at org.python.core.PyFunction.__call__(PyFunction.java:317)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at org.python.pycode._pyx18.read$1(<module:project.scanner>:24)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at org.python.pycode._pyx18.call_function(<module:project.scanner>)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at org.python.core.PyTableCode.call(PyTableCode.java:165)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at org.python.core.PyBaseCode.call(PyBaseCode.java:134)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at org.python.core.PyFunction.__call__(PyFunction.java:317)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at org.python.pycode._pyx4.f$0(<TagChangeScript:AntiDiversion/Engine: Data Read on Data Change>:19)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at org.python.pycode._pyx4.call_function(<TagChangeScript:AntiDiversion/Engine: Data Read on Data Change>)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at org.python.core.PyTableCode.call(PyTableCode.java:165)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at org.python.core.PyCode.call(PyCode.java:18)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at org.python.core.Py.runCode(Py.java:1275)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:657)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at com.inductiveautomation.ignition.common.script.ScriptManager.runCode(ScriptManager.java:616)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at com.inductiveautomation.ignition.common.script.TagChangeScriptExecutor$TagChangeExecutionCallback.execute(TagChangeScriptExecutor.java:187)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at com.inductiveautomation.ignition.common.script.TagChangeScriptExecutor$TagChangeExecutionCallback.execute(TagChangeScriptExecutor.java:134)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at com.inductiveautomation.ignition.common.util.SerialExecutionQueue$PollAndExecute.run(SerialExecutionQueue.java:99)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at java.util.concurrent.FutureTask.run(Unknown Source)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	at java.lang.Thread.run(Unknown Source)
INFO   | jvm 1    | 2019/03/15 08:33:13 | Caused by: org.python.core.PyException: Traceback (most recent call last):
INFO   | jvm 1    | 2019/03/15 08:33:13 |   File "<TagChangeScript:AntiDiversion/Engine: Data Read on Data Change>", line 19, in <module>
INFO   | jvm 1    | 2019/03/15 08:33:13 |   File "<module:project.scanner>", line 17, in read
INFO   | jvm 1    | 2019/03/15 08:33:13 |   File "<module:project.scanner>", line 71, in parseCode
INFO   | jvm 1    | 2019/03/15 08:33:13 | IndexError: index out of range: -3
INFO   | jvm 1    | 2019/03/15 08:33:13 | 
INFO   | jvm 1    | 2019/03/15 08:33:13 | 	... 29 common frames omitted

ronaldny · October 30, 2020, 4:22pm

Similar problem here,
the MS SQL connection randomly faults. Anyone with a solution???

JordanCClark · October 30, 2020, 9:19pm

From this line:

Cannot get a connection, pool error Timeout waiting for idle object

This exception is stating that the pool manager cannot produce a viable connection to a waiting requester and the maxWait has passed therefore triggering a timeout. Usually the issue falls into two broad categories:

The DB is down or unreachable. This could be because you forgot to start it, or it crashed, or the network between you and the DB has stopped working.
The connection pool is out of connections. This could be due to high demand, or it could be an indication of a connection leak where connections are never returned to the pool and eventually you exceed the max connections limit.

JordanCClark · October 30, 2020, 9:20pm

Are you getting the same type of error in the log?

mmurphy · April 8, 2021, 8:28pm

Hi guys,

One of my Vision clients is acting up in a similar way. I have the Ignition gateway and MSSQL running on the same machine. There is a database connection that I use to historize tags. The setup has been working for about a year and suddenly, starting yesterday morning, the database connection is faulting out sporadically and frequently. It remains faulted for a few seconds and then fixes itself. Not sure what to look for to troubleshoot.

The diagnostic log looks something like this:

If you open up one of the instances it looks like this:

I was able to copy the following from the database tab on the gateway as the error was happening:

The setup is running Ignition v8.0.10 and MSSQL 2017. Any help would be greatly appreciated!!

smcfarlane · February 9, 2023, 1:35am

Having a similar issue as above, including read timeouts and the following historical queries are reporting they they are taking 1-2 minutes to execute. The gateway is frequently disconnecting from the designer and doing anything with the SQL server through SSMS is incredibly slow. It seems like the SQL server is being overloaded but there aren't that many historized tags. About 850, but many of those are Booleans with a deadband.

Also seeing the clock drift issue

pturmel · February 9, 2023, 2:30am

You probably should start a new topic, with full information on your setup. Including whether your DB and GW share a machine.