EasyMorph Server 5.1.2 Logging Error

ThisThatTheOther · February 18, 2022, 8:38pm

My team was encountering a problem with the Snowflake Connector that caused EasyMorph Server 5.1.1 to stop unexpectedly. When we upgraded to EasyMorph 5.1.2, in hope that this problem may have been corrected, we found a different log message that I believe may be a separate issue. When EasyMorph Server 5.1.2 quit unexpectedly (presumably from the Snowflake Connector problem) we found this error in EasyMorphServer.log and EasyMorphServerDebug.log:

Could not load file or assembly ‘log4net, Version=2.0.8.0, Culture=neutral, PublicKeyToken=669e0ddf0bb1aa2a’ or one of its dependencies. The located assembly’s manifest definition does not match the assembly reference. (Exception from HRESULT: 0x80131040)

Admittedly, I know little about how these assemblies are configured, but I did notice that log4net is referenced in EasyMorph Server 5.1.1’s Morph.Server.WebConsole.deps.json and it is not referenced in EasyMorph Server 5.1.2’s version of that same file.

The error message we expected to find in the log for the Snowflake Connector problem always look like the following:

02/17/2022 11:00:04 PM 002264 ERROR 02/17/2022 11:00:04 PM 002265 ERROR 02/17/2022 11:00:04 PM 002266 ERROR 02/17/2022 11:00:04 PM 002267 ERROR 02/17/2022 11:00:04 PM 002268 ERROR 02/17/2022 11:00:04 PM 002269 ERROR 02/17/2022 11:00:04 PM 002270 ERROR 02/17/2022 11:00:04 PM 002271 ERROR 02/17/2022 11:00:04 PM 002272 ERROR 02/17/2022 11:00:04 PM 002273 ERROR 02/17/2022 11:00:04 PM 002274 ERROR 02/17/2022 11:00:04 PM 002275 ERROR 02/17/2022 11:00:04 PM 002276 ERROR 02/17/2022 11:00:04 PM 002277 ERROR 02/17/2022 11:00:04 PM 002278 ERROR 02/17/2022 11:00:04 PM 002279 ERROR 02/17/2022 11:00:04 PM 002280 ERROR 02/17/2022 11:00:04 PM 002281 ERROR 02/17/2022 11:00:04 PM 002282 ERROR 02/17/2022 11:00:04 PM 002283 ERROR 02/17/2022 11:00:04 PM 002284 ERROR 02/17/2022 11:00:04 PM 002285 ERROR 02/17/2022 11:00:04 PM 002286 ERROR 02/17/2022 11:00:04 PM 002287 ERROR 02/17/2022 11:00:04 PM 002288 ERROR 02/17/2022 11:00:04 PM 002289 ERROR 02/17/2022 11:00:04 PM 002290 ERROR 02/17/2022 11:00:04 PM 002291 ERROR 02/17/2022 11:00:04 PM 002292 ERROR 02/17/2022 11:00:04 PM 002293 ERROR 02/17/2022 11:00:04 PM 002294 ERROR 02/17/2022 11:00:04 PM 002295 ERROR 02/17/2022 11:00:04 PM 002296 ERROR 02/17/2022 11:00:04 PM 002297 ERROR 02/17/2022 11:00:04 PM 002298 ERROR 02/17/2022 11:00:04 PM 002299 ERROR 02/17/2022 11:00:04 PM 002300 ERROR 02/17/2022 11:00:04 PM 002301 ERROR Unhandled exception System.AggregateException: One or more errors occurred. —> System.AggregateException: One or more errors occurred. —> Snowflake.Data.Client.SnowflakeDbException: Your session has expired. Please login again.
at Snowflake.Data.Core.SFStatement.Cancel()
at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
at System.Threading.CancellationCallbackInfo.ExecuteCallback()
at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException)
— End of inner exception stack trace —
at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException)
at System.Threading.CancellationTokenSource.NotifyCancellation(Boolean throwOnFirstException)
at System.Threading.CancellationTokenSource.LinkedTokenCancelDelegate(Object source)
at System.Threading.CancellationCallbackInfo.ExecuteCallback()
at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException)
— End of inner exception stack trace —
at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException)
at System.Threading.CancellationTokenSource.NotifyCancellation(Boolean throwOnFirstException)
at System.Threading.CancellationTokenSource.TimerCallbackLogic(Object obj)
at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
at System.Threading.TimerQueueTimer.CallCallback()
at System.Threading.TimerQueueTimer.Fire()
at System.Threading.TimerQueue.FireNextTimers()
—> (Inner Exception #0) System.AggregateException: One or more errors occurred. —> Snowflake.Data.Client.SnowflakeDbException: Your session has expired. Please login again.
at Snowflake.Data.Core.SFStatement.Cancel()
at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
at System.Threading.CancellationCallbackInfo.ExecuteCallback()
at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException)
— End of inner exception stack trace —
at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException)
at System.Threading.CancellationTokenSource.NotifyCancellation(Boolean throwOnFirstException)
at System.Threading.CancellationTokenSource.LinkedTokenCancelDelegate(Object source)
at System.Threading.CancellationCallbackInfo.ExecuteCallback()
at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException)
—> (Inner Exception #0) Error: Your session has expired. Please login again. SqlState: , VendorCode: 390112, QueryId: <—
<—

To be clear, I believe there are 2 problems here:

logging issue in EasyMorph Server 5.1.2
Snowflake Connector issue affecting EasyMorph Server 5.1.1 and 5.1.2 (and possibly others)

I believe the Snowflake Connector issue may be due to multiple tables in a single Morph connecting to Snowflake at same time. But, we are still doing research to narrow down the exact cause.

dgudkov · February 18, 2022, 11:16pm

Hi Greg,

we’re investigating the issue. I’ll keep you posted.

Meanwhile, here are a few suggestions on how to stabilize the workflow:

Use the Synchronize action, to avoid simultaneous interaction with the Snowflake in independent tables in EasyMorph. EasyMorph may execute actions in independent tables in parallel. The Synchronize action allows defining an order of execution.
Use an ODBC driver instead of the built-in Snowflake driver.

dgudkov · February 22, 2022, 10:24am

@ThisThatTheOther, the problem has been fixed. Please update your EasyMorph Server to the most recent version from our website.

ThisThatTheOther · February 22, 2022, 5:33pm

I have installed. I will post again in couple days letting you know if everything is working. The Snowflake token expiration only happens once daily and even then we were not always guaranteed to get a failure. I don’t have any great way to test if something that causes the service to quit unexpectedly is able to log properly, but I did find the log4net entries in the assembly dependency in the new version. Thanks!

ThisThatTheOther · February 26, 2022, 4:52pm

I have had no failures since the new install. The Snowflake Connectors are running in parallel without issue. Thanks for the fast response!

ThisThatTheOther · March 7, 2022, 4:00pm

The new build of EasyMorph Server 5.1.2 corrected the logging issue we encountered, but the problem described above with concurrent Snowflake Connector connections persists.

andrew.rybka · March 7, 2022, 9:06pm

Hi Greg,

Can you please post the error message that you are getting in the new build of EasyMorph Server 5.1.2?

ThisThatTheOther · March 7, 2022, 9:29pm

03/06/2022 11:00:14 PM 004028 ERROR     Unhandled exception System.AggregateException: One or more errors occurred. ---> System.AggregateException: One or more errors occurred. ---> Snowflake.Data.Client.SnowflakeDbException: Your session has expired. Please login again.
03/06/2022 11:00:14 PM 004029 ERROR        at Snowflake.Data.Core.SFStatement.Cancel()
03/06/2022 11:00:14 PM 004030 ERROR        at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
03/06/2022 11:00:14 PM 004031 ERROR        at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
03/06/2022 11:00:14 PM 004032 ERROR        at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
03/06/2022 11:00:14 PM 004033 ERROR        at System.Threading.CancellationCallbackInfo.ExecuteCallback()
03/06/2022 11:00:14 PM 004034 ERROR        at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException)
03/06/2022 11:00:14 PM 004035 ERROR        --- End of inner exception stack trace ---
03/06/2022 11:00:14 PM 004036 ERROR        at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException)
03/06/2022 11:00:14 PM 004037 ERROR        at System.Threading.CancellationTokenSource.NotifyCancellation(Boolean throwOnFirstException)
03/06/2022 11:00:14 PM 004038 ERROR        at System.Threading.CancellationTokenSource.LinkedTokenCancelDelegate(Object source)
03/06/2022 11:00:14 PM 004039 ERROR        at System.Threading.CancellationCallbackInfo.ExecuteCallback()
03/06/2022 11:00:14 PM 004040 ERROR        at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException)
03/06/2022 11:00:14 PM 004041 ERROR        --- End of inner exception stack trace ---
03/06/2022 11:00:14 PM 004042 ERROR        at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException)
03/06/2022 11:00:14 PM 004043 ERROR        at System.Threading.CancellationTokenSource.NotifyCancellation(Boolean throwOnFirstException)
03/06/2022 11:00:14 PM 004044 ERROR        at System.Threading.CancellationTokenSource.TimerCallbackLogic(Object obj)
03/06/2022 11:00:14 PM 004045 ERROR        at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
03/06/2022 11:00:14 PM 004046 ERROR        at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
03/06/2022 11:00:14 PM 004047 ERROR        at System.Threading.TimerQueueTimer.CallCallback()
03/06/2022 11:00:14 PM 004048 ERROR        at System.Threading.TimerQueueTimer.Fire()
03/06/2022 11:00:14 PM 004049 ERROR        at System.Threading.QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem()
03/06/2022 11:00:14 PM 004050 ERROR        at System.Threading.ThreadPoolWorkQueue.Dispatch()
03/06/2022 11:00:14 PM 004051 ERROR     ---> (Inner Exception #0) System.AggregateException: One or more errors occurred. ---> Snowflake.Data.Client.SnowflakeDbException: Your session has expired. Please login again.
03/06/2022 11:00:14 PM 004052 ERROR        at Snowflake.Data.Core.SFStatement.Cancel()
03/06/2022 11:00:14 PM 004053 ERROR        at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
03/06/2022 11:00:14 PM 004054 ERROR        at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
03/06/2022 11:00:14 PM 004055 ERROR        at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
03/06/2022 11:00:14 PM 004056 ERROR        at System.Threading.CancellationCallbackInfo.ExecuteCallback()
03/06/2022 11:00:14 PM 004057 ERROR        at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException)
03/06/2022 11:00:14 PM 004058 ERROR        --- End of inner exception stack trace ---
03/06/2022 11:00:14 PM 004059 ERROR        at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException)
03/06/2022 11:00:14 PM 004060 ERROR        at System.Threading.CancellationTokenSource.NotifyCancellation(Boolean throwOnFirstException)
03/06/2022 11:00:14 PM 004061 ERROR        at System.Threading.CancellationTokenSource.LinkedTokenCancelDelegate(Object source)
03/06/2022 11:00:14 PM 004062 ERROR        at System.Threading.CancellationCallbackInfo.ExecuteCallback()
03/06/2022 11:00:14 PM 004063 ERROR        at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException)
03/06/2022 11:00:14 PM 004064 ERROR     ---> (Inner Exception #0) Error: Your session has expired. Please login again. SqlState: , VendorCode: 390112, QueryId: <---
03/06/2022 11:00:14 PM 004065 ERROR     <---
03/06/2022 11:00:14 PM 004066 ERROR

andrew.rybka · March 8, 2022, 7:41pm

Greg, thank you for the logs.

How much time does it take for the projects that interact with Snowflake to complete when they are executed one by one?

ThisThatTheOther · March 8, 2022, 8:53pm

A few seconds to a few minutes, depending on the work taking place. We have several Tasks that access Snowflake scheduled at the same time. Due to the number of Tasks and their run frequency, it is not practical to skew their start times using the scheduler. Each Task runs a Morph with one or several Tables concurrently accessing Snowflake and other databases. We have a workaround in place that single threads a single dummy query to Snowflake before all the other Tasks begin their work. The idea here is that the token refresh can happen in insolation when it is needed. We have not encountered this fault with the workaround in place. From my anecdotal experience, this fault occurs when multiple accesses to Snowflake take place simultaneously when the token is expired or as it is expiring.

andrew.rybka · March 9, 2022, 9:08am

Greg, a few more questions:

How often are those tasks executed?
How often does this error happen?

ThisThatTheOther · March 9, 2022, 1:44pm

There are 4 Tasks -
task1 has 2 concurrent connections to Snowflake, runs every 10 minutes
task2 has 6 concurrent connections to Snowflake, runs every 20 minutes
task3 has 1 connection to Snowflake, runs every 15 minutes
task4 has 1 connection to Snowflake, runs every 15 minutes

All 4 of these tasks run at the hour. The fault is intermittent. If it occurs, it is at the same time each day.

andrew.rybka · March 10, 2022, 11:49am

Hi Greg,

Thank you for the answers.

I was able to replicate a similar error on my side. And it seems that both errors are caused by Snowflake Connector for .NET that is used internally by EasyMorph’s native Snowflake connector.

I would suggest using the ODBC connector instead of the native one or sticking with the workaround that you described earlier.