Gateway gettting checking user source frequently

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.

  1. 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.

  1. 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.
  2. 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

  1. under what condition is a vision client required to query a user source? (I would like to reduce user source related queries if possible)
  2. why does the user source not count as a connection on the Databases status page?
  3. what causes the log message that mentions ‘Starting up client project monitor.’

Sorry for the long post and I appreciate any insights.

Verify that your database allows the number of concurrent connections you’ve set up. What database, BTW?

Oh, and:

  1. Any client login or use of validateUser().

  2. Don’t know.

  3. New client connection or re-connection.

That’s a good point, I’m not aware of a setting that might control the max concurrent connections I’ll do some reading and see what I can find.

We are using Microsoft sql 2019 (not the express version)

  1. On the vision forms I do have a few buttons that check if the user is a specific level so they can do admin operations at the station. However I’m not sure why it would be checking so frequently since the expression only depends on the user info, which doesn’t change too often.
  2. it’s possible it happens too quickly for the page to see the concurrent connection count change.
  3. If I look through the active vision clients none of them are below a day for uptime. Do you know of a reason for a client to re-connect, other than someone pushing an update?

Thank you

Flaky networks and invasive IT departments come to mind. One of the reasons I avoid deploying Windows in production environments.

I’m doubtful the operating system has anything to do with ignition vision clients querying the user source excessively. The network could be flaky but many of the other systems that are deployed on the floor would also be having issues besides the ignition applications. Their plant IT department are pleasant to work with fortunately.

Also looking at the average query times for the “db_auth” connection the chart for query times seems broken, there will be multiple bars depicting query times with 0.0 ms along the x axis. Also, the longest running queries list range from 50-300 ms in the “db_auth” connection, with a throughput of 30-60 queries per second. I couldn’t find an instance of the log but I remember seeing a timeout error in regards to the user source waiting for connection from the pool. I wonder if it’s possible user authentication has a lower priority when it comes to allocating a connection from the pool.

I did look into max concurrent connections the sql server and it’s been set to 0, which is considered unlimited in the documentation.

Since I don’t seem to get the error any more I’m going to consider the “fix©” being having a dedicated db connection for db user source, unless the issue arises again after adding more clients or I get any more relevant info.

Thanks for the help