I have a vision project I’ve been working on for the past several months and we have 141 active vision clients attached to our gateway (and we are adding more soon).
Our system utilizes the customers database as a user store. It’s not for security it’s only used so the customer can continue to utilize their existing employee table and keep their username/badge#/user levels combination in one location.
I’ve been running into an issue were many or possibly all vision clients get an error where they cant login. Looking at the gateway logs during the time of the errors there are 2 types of errors.
- Level:Warning, Logger:Login, Message: Error attempting client login.
java.lang.Exception: SQL exception during authentication
at com.inductiveautomation.ignition.gateway.authentication.impl.DatabaseExpertUserSource.authenticateUsernamePassword(DatabaseExpertUserSource.java:172)
at com.inductiveautomation.ignition.gateway.authentication.impl.DatabaseExpertUserSource.authenticate(DatabaseExpertUserSource.java:276)
at com.inductiveautomation.ignition.gateway.authentication.UserSourceWrapper.authenticate(UserSourceWrapper.java:499)
at com.inductiveautomation.ignition.gateway.servlets.gateway.functions.Login.client(Login.java:368)
at jdk.internal.reflect.GeneratedMethodAccessor42.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.base/java.lang.reflect.Method.invoke(Unknown Source)
at com.inductiveautomation.ignition.gateway.servlets.gateway.AbstractGatewayFunction.invoke(AbstractGatewayFunction.java:225)
at com.inductiveautomation.ignition.gateway.servlets.Gateway.doPost(Gateway.java:405)
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:86)
at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1391)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:760)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:590)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1607)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1297)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1577)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1212)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
at org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:322)
at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:59)
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
at org.eclipse.jetty.server.Server.handle(Server.java:500)
at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)
at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:270)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
at java.base/java.lang.Thread.run(Unknown Source)
Caused by: com.inductiveautomation.ignition.gateway.datasource.FaultedDatabaseConnectionException: The database connection 'db source name' is FAULTED. See Gateway Status for details.
at com.inductiveautomation.ignition.gateway.datasource.DatasourceManagerImpl.getConnectionImpl(DatasourceManagerImpl.java:201)
at com.inductiveautomation.ignition.gateway.datasource.DatasourceImpl.getConnection(DatasourceImpl.java:243)
at com.inductiveautomation.ignition.gateway.datasource.DatasourceManagerImpl.getConnection(DatasourceManagerImpl.java:130)
at com.inductiveautomation.ignition.gateway.authentication.impl.DatabaseExpertUserSource.getConnection(DatabaseExpertUserSource.java:589)
at com.inductiveautomation.ignition.gateway.authentication.impl.DatabaseExpertUserSource.authenticateUsernamePassword(DatabaseExpertUserSource.java:167)
... 43 common frames omitted
2.Level:Error, Logger:DB_ManualMode, Message: [profileName=‘user source name’] SQL exception during authentication
com.inductiveautomation.ignition.gateway.datasource.FaultedDatabaseConnectionException: The database connection 'db source name' is FAULTED. See Gateway Status for details.
at com.inductiveautomation.ignition.gateway.datasource.DatasourceManagerImpl.getConnectionImpl(DatasourceManagerImpl.java:201)
at com.inductiveautomation.ignition.gateway.datasource.DatasourceImpl.getConnection(DatasourceImpl.java:243)
at com.inductiveautomation.ignition.gateway.datasource.DatasourceManagerImpl.getConnection(DatasourceManagerImpl.java:130)
at com.inductiveautomation.ignition.gateway.authentication.impl.DatabaseExpertUserSource.getConnection(DatabaseExpertUserSource.java:589)
at com.inductiveautomation.ignition.gateway.authentication.impl.DatabaseExpertUserSource.authenticateUsernamePassword(DatabaseExpertUserSource.java:167)
at com.inductiveautomation.ignition.gateway.authentication.impl.DatabaseExpertUserSource.authenticate(DatabaseExpertUserSource.java:276)
at com.inductiveautomation.ignition.gateway.authentication.UserSourceWrapper.authenticate(UserSourceWrapper.java:499)
at com.inductiveautomation.ignition.gateway.servlets.gateway.functions.Login.client(Login.java:368)
at jdk.internal.reflect.GeneratedMethodAccessor42.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.base/java.lang.reflect.Method.invoke(Unknown Source)
at com.inductiveautomation.ignition.gateway.servlets.gateway.AbstractGatewayFunction.invoke(AbstractGatewayFunction.java:225)
at com.inductiveautomation.ignition.gateway.servlets.Gateway.doPost(Gateway.java:405)
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:86)
at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1391)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:760)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:590)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1607)
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1297)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1577)
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1212)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
at org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:322)
at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:59)
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
at org.eclipse.jetty.server.Server.handle(Server.java:500)
at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)
at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:270)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
at java.base/java.lang.Thread.run(Unknown Source)
This made me believe I was overloading the sql connection in someway since I was for brief moments reaching 8/8 connections. I raised the connections to 25 to see what would happen. The issue was still not fixed so I created a second database connection with all of the same properties except the name of the connection I added ‘_UserAuth’. This seems to have fixed the issue for now however I noticed a few strange things.
- my Total Throughput for database queries has been in the 30-70 queries/sec range. However now that the user authentication is contained to the ‘_UserAuth’ connection almost all the query throughput moved to the ‘_UserAuth’ connection. I verified that the rest of my project is not defaulting to this connection. Also the connections being utilized never changes from zero.
- Since before these login errors I’ve had my logs spammed with the following message
Starting up client project monitor. project={vision project name} scope=4
. I’m curious if anyone knows why this message appears. If I hover over the magnifying glass it will list details like session id, ip address, and user name.
TLDR;
I have many vision clients 140+ and they will get an authentication error intermittently (once a day sometimes?). I believe that many of the vision clients are excessively checking for user information causing timeout exceptions to occur when waiting for a connection out of the pool. It might have something to do with user sources not counting as a connection in the connection pool.
I do have some code that automatically logs users in/out from an outside system but this code is only called if the clock number is changed. So I technically shouldn’t have too much python code doing user auth operations.
Here are my questions
- under what condition is a vision client required to query a user source? (I would like to reduce user source related queries if possible)
- why does the user source not count as a connection on the Databases status page?
- what causes the log message that mentions ‘Starting up client project monitor.’
Sorry for the long post and I appreciate any insights.