SmartConnector recovery after DB connection lost

[MaximeLaudren]

Hi,

I had an issue at a customer site (Hotel).

Context:

SC and SQL server runs on 2 distinct machine.

SC have 2 processor running to integrate with 2 3rd party system in EBO (Kaba and Micros).

Issue:

For some reason the smartconnector service lost the connectivity with the SQL server.

Maybe it was just a timeout due to high network latency, or SQL server connectivity issue. We don't know.

This happened shortly before the processors were supposed to run.

Result is that the license verification failed for all processors and stopped the execution.

When the connectivity was restored , the SC did not try to recover/recheck the licenses, as far as we can tell from the logs.

Only a manual restart of the smartconnector service through the windows service windows trigger a license check and everything went back online.

Here is the interesting log section, I can provide more logs if needed:

2021-06-07 07:14:57.7384,Error,Service,<no principal>,An error occurred while executing the command definition. See the inner exception for details.

Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.

The wait operation timed out

   at System.Data.Entity.Core.EntityClient.Internal.EntityCommandDefinition.ExecuteStoreCommands(EntityCommand entityCommand, CommandBehavior behavior)

   at System.Data.Entity.Core.Objects.Internal.ObjectQueryExecutionPlan.Execute[TResultType](ObjectContext context, ObjectParameterCollection parameterValues)

   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.Infrastructure.DbExecutionStrategy.Execute[TResult](Func`1 operation)

   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.FirstOrDefault[TSource](IEnumerable`1 source)

   at Mongoose.Service.Licensing.AntiRollbackDateTime.get_UtcNow()

,["Current WindowsIdentity is NT AUTHORITY\\SYSTEM"],

2021-06-07 07:14:57.7384,Trace,Service,<no principal>,Validating framework license,

2021-06-07 07:15:32.7604,Error,Service,<no principal>,An error occurred while executing the command definition. See the inner exception for details.

Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.

The wait operation timed out

   at System.Data.Entity.Core.EntityClient.Internal.EntityCommandDefinition.ExecuteStoreCommands(EntityCommand entityCommand, CommandBehavior behavior)

   at System.Data.Entity.Core.Objects.Internal.ObjectQueryExecutionPlan.Execute[TResultType](ObjectContext context, ObjectParameterCollection parameterValues)

   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.Infrastructure.DbExecutionStrategy.Execute[TResult](Func`1 operation)

   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.FirstOrDefault[TSource](IEnumerable`1 source)

   at Mongoose.Service.Mongoose.HasValidFrameworkLicense()

,[],

2021-06-07 07:15:32.7634,Debug,WorkerManager,<no principal>,Stopping Processors,

2021-06-07 07:15:32.8374,Debug,WorkerManager,<no principal>,Stopping EWS Servers,

2021-06-07 07:15:32.8994,Debug,WorkerManager,<no principal>,Stopping Endpoints,

2021-06-07 07:15:32.9394,Debug,Database,<no principal>,EwsServerRequestChanged,Could not convert Mongoose.Service.Notifications.EntityChangeEventArgs`1[Mongoose.Ews.Server.Data.EwsServerRequest] to JSON,

2021-06-07 07:15:32.9484,Status,Service,<no principal>,Stopping EWS Server http://localhost:51200/EcoStruxure/DataExchange,

2021-06-07 07:15:33.9400,Debug,Processor,<no principal>,Sent: _LE|DA210607|TI071532|_,

2021-06-07 07:15:33.9400,Debug,Processor,<no principal>,Processor Micros Interface Processor Execute completed,

2021-06-07 07:15:33.9400,Debug,WorkerThread,<no principal>,Micros Interface Processor,Execute (end),2021-06-02T01:08:32,ET=418021821 mSec,

2021-06-07 07:15:33.9400,Info,WorkerThread,<no principal>,Micros Interface Processor,Ended successfully,

2021-06-07 07:15:33.9501,Info,WorkerThread,<no principal>,Micros Interface Processor,Next run will be at next SmartConnector startup,

2021-06-07 07:15:33.9691,Trace,Service,<no principal>,Validating framework license,

2021-06-07 07:15:34.0890,Info,WorkerThread,<no principal>,Micros Server Manager Processor,Started,

2021-06-07 07:15:34.0890,Debug,WorkerThread,<no principal>,Micros Server Manager Processor,InstantiateProcessor,ET=4 mSec,

2021-06-07 07:15:34.0890,Debug,WorkerThread,<no principal>,Micros Server Manager Processor,Execute (start),2021-06-06T21:15:34,

2021-06-07 07:15:34.0890,Debug,Processor,<no principal>,Processor Micros Server Manager Processor Execute started,

2021-06-07 07:15:34.3110,Debug,Processor,<no principal>,Processor Micros Server Manager Processor Execute completed,

2021-06-07 07:15:34.3110,Debug,WorkerThread,<no principal>,Micros Server Manager Processor,Execute (end),2021-06-06T21:15:34,ET=222 mSec,

2021-06-07 07:15:34.3110,Info,WorkerThread,<no principal>,Micros Server Manager Processor,Ended successfully,

2021-06-07 07:15:34.3110,Info,WorkerThread,<no principal>,Micros Server Manager Processor,Next run will be at 2021-06-06T21:16:00,

2021-06-07 07:15:34.3250,Trace,Service,<no principal>,Validating framework license,

2021-06-07 07:15:34.5070,Debug,Processor,<no principal>,Processor Kaba Door Lock Server Connector Execute completed,

2021-06-07 07:15:34.5070,Debug,WorkerThread,<no principal>,Kaba Door Lock Server Connector,Execute (end),2021-06-02T01:15:12,ET=417621684 mSec,

2021-06-07 07:15:34.5070,Info,WorkerThread,<no principal>,Kaba Door Lock Server Connector,Ended successfully,

2021-06-07 07:15:34.5110,Info,WorkerThread,<no principal>,Kaba Door Lock Server Connector,Next run will be at ,

2021-06-07 07:15:34.5110,Trace,Service,<no principal>,Validating framework license,

2021-06-07 07:15:35.4764,Status,Service,<no principal>,Stopping EWS Server http://localhost:8093/EcoStruxure/DataExchange,

[ardak]

Hi!

Could you please share the logs, and point out at which time the problems started occurring? 

According to the logs you've shared there are some timeouts as you say but the processors start right up again, or am I missing something?

BR

Armend

[MaximeLaudren]

Hello Armend,

One of the processor was not able to restart, and the other one, even if in the log it appear to be running, from the UI both where stopped.

I will provide you the whole log and screenshot by email, but the interesting part is the one I have put in the first post.