Intermittent Failure to Connect with SSL Client Certificate - Unable to Sign the Data
Posted: Fri 19 Oct 2018 14:29
We've been tracking an issue for the last few months related to a very infrequent error:
By my tests, this happens about once per 2 million queries on our test systems which have 2 cores, but once per 300,000 on my local machine where I have 4 cores. My coworker who has a newer machine than mine and 8 logical processors also sees it roughly once per 300,000 queries.
It happens disproportionately frequently when our services first start up (Often within the first 500 connections either locally or on our systems), but otherwise can be difficult to reproduce.
The error is seen in our live systems, but we don't have enough data to draw any meaningful conclusion from it.
Our current connection string looks like this:
Thus far, I've tried increasing/decreasing Connection Lifetime, Pool Size, and I've tried turning Pooling off entirely. Some of these have effected the frequency with which I see the error, but the above connection string causes it to happen least frequently (at least as far as I have been able to tell. The issue occurs so infrequently that it can be hard to know for sure).
I've also investigated whether or not the use of "using" statements in the code will increase or decrease the rate. The issue seems to appear equally with or without "using" statements.
Additionally, I have the following code which I'm using to perform tests in a reasonable amount of time. With this code, my local machine can perform about 10,000 queries per minute.
Additional System Info:
Database Server is running PostgreSQL 9.4 on CentOS.
Web Apps are 64-bit running on IIS 8.5 on our test servers, 32-bit running on IIS 8.0 locally.
dotConnect for PostgreSQL Professional 7.9.912.0
Code: Select all
System.Data.Entity.Core.EntityException: The underlying provider failed on Open. ---> Devart.Data.PostgreSql.PgSqlException: Unable to sign the data. ---> System.Security.Cryptography.CryptographicException: Unable to sign the data.
at Devart.Security.SSL.s.b(IAsyncResult A_0)
at Devart.Security.SSL.af.b(Byte[] A_0, Int32 A_1, Int32 A_2)
at Devart.Common.l.e(Byte[] A_0, Int32 A_1, Int32 A_2)
--- End of inner exception stack trace ---
at Devart.Data.PostgreSql.h.x()
at Devart.Data.PostgreSql.h..ctor(PgSqlConnectionOptions A_0)
at Devart.Data.PostgreSql.ah.a(au A_0, Object A_1, DbConnectionBase A_2)
at Devart.Common.DbConnectionFactory.a(DbConnectionPool A_0, au A_1, DbConnectionBase A_2)
at Devart.Common.DbConnectionPool.a(DbConnectionBase A_0)
at Devart.Common.DbConnectionPool.GetObject(DbConnectionBase owningConnection)
at Devart.Common.DbConnectionPool.GetObject(DbConnectionBase owningConnection)
at Devart.Common.DbConnectionPool.GetObject(DbConnectionBase owningConnection)
at Devart.Common.DbConnectionFactory.b(DbConnectionBase A_0)
at Devart.Common.DbConnectionClosed.Open(DbConnectionBase outerConnection)
at Devart.Common.DbConnectionBase.Open()
at Devart.Data.PostgreSql.PgSqlConnection.Open()
at System.Data.Entity.Infrastructure.Interception.InternalDispatcher`1.Dispatch[TTarget,TInterceptionContext](TTarget target, Action`2 operation, TInterceptionContext interceptionContext, Action`3 executing, Action`3 executed)
at System.Data.Entity.Infrastructure.Interception.DbConnectionDispatcher.Open(DbConnection connection, DbInterceptionContext interceptionContext)
at System.Data.Entity.Core.EntityClient.EntityConnection.Open()
--- End of inner exception stack trace ---
at System.Data.Entity.Core.EntityClient.EntityConnection.Open()
at System.Data.Entity.Core.Objects.ObjectContext.EnsureConnection(Boolean shouldMonitorTransactions)
at System.Data.Entity.Core.Objects.ObjectContext.ExecuteInTransaction[T](Func`1 func, IDbExecutionStrategy executionStrategy, Boolean startLocalTransaction, Boolean releaseConnectionOnSuccess)
at System.Data.Entity.Core.Objects.ObjectQuery`1.<>c__DisplayClass7.<GetResults>b__5()
at System.Data.Entity.Core.Objects.ObjectQuery`1.GetResults(Nullable`1 forMergeOption)
at System.Data.Entity.Core.Objects.ObjectQuery`1.<System.Collections.Generic.IEnumerable<T>.GetEnumerator>b__0()
at System.Data.Entity.Internal.LazyEnumerator`1.MoveNext()
at System.Linq.Enumerable.First[TSource](IEnumerable`1 source)
at System.Linq.Queryable.First[TSource](IQueryable`1 source)
It happens disproportionately frequently when our services first start up (Often within the first 500 connections either locally or on our systems), but otherwise can be difficult to reproduce.
The error is seen in our live systems, but we don't have enough data to draw any meaningful conclusion from it.
Our current connection string looks like this:
Code: Select all
<add name="DBEntities" connectionString="metadata=res://*/DB.csdl|res://*/DB.ssdl|res://*/DB.msl;provider=Devart.Data.PostgreSql;provider connection string="User Id=user;SslMode=require;Ssl Key=C:/Certificates/postgresql.key;Ssl Cert=C:/Certificates/postgresql.crt;Host=hostname;Database=DB;Persist Security Info=True;Pooling=True;Connection Lifetime=60;Min Pool Size=1;Max Pool Size=1500;Schema=dbo"" providerName="System.Data.EntityClient" />
I've also investigated whether or not the use of "using" statements in the code will increase or decrease the rate. The issue seems to appear equally with or without "using" statements.
Additionally, I have the following code which I'm using to perform tests in a reasonable amount of time. With this code, my local machine can perform about 10,000 queries per minute.
Code: Select all
private void FindCrypto() {
if (ToggleHammer())
{
for (var i = 0; i < 50; i++)
{
var i1 = i;
Log.InfoFormat("Order start of db hammer {0}", i1);
Task.Factory.StartNew(() => DbHammer(i1, false));
Task.Factory.StartNew(() => DbHammer(i1, true));
}
}
}
private bool ToggleHammer()
{
dbHammerEngaged = !dbHammerEngaged;
Log.WarnFormat("DB Hammer {0} Engaged!", dbHammerEngaged ? "IS" : "IS NOT");
if (dbHammerEngaged)
{
// Reset Hammer Counter
Interlocked.Exchange(ref dbHammerAttempts, 0L)
}
return dbHammerEngaged;
}
private void DbHammer(int threadId, bool useUsing)
{
var tName = String.Format("${0}${1}", threadId, useUsing ? 'U' : 'N');
Log.InfoFormat("DbHammer {0} Initializing...", tName);
int timer = 0;
var r = new Random();
var minHammer = 0;
var maxHammer = 0;
IQueryable<TesData> td = null;
while (dbHammerEngaged)
{
try
{
while (dbHammerEngaged)
{
if (useUsing)
{
using (var repo = _ninjaFactory.GetRepository())
{
td = repo.GetAll<TestData>();
timer = r.Next(minHammer, maxHammer);
System.Threading.Thread.Sleep(timer);
Interlocked.Increment(ref dbHammerAttempts);
var blah = td.First();
}
}
else
{
var repo = _ninjaFactory.GetRepository();
td = repo.GetAll<TestData>();
System.Threading.Thread.Sleep(timer);
Interlocked.Increment(ref dbHammerAttempts);
var blah = td.First();
}
if (dbHammerAttempts % 10000 == 0)
{
Log.InfoFormat("Db Hammered {0} times.", dbHammerAttempts);
}
}
}
catch (Exception e)
{
Log.Error(string.Format("Error detected on thread {0} after waiting {1} ms = {2} attempts", tName, timer, dbHammerAttempts), e);
Interlocked.Exchange(ref dbHammerAttempts, 0L);
}
}
Database Server is running PostgreSQL 9.4 on CentOS.
Web Apps are 64-bit running on IIS 8.5 on our test servers, 32-bit running on IIS 8.0 locally.
dotConnect for PostgreSQL Professional 7.9.912.0