Communications with a large number of recipients time out and don't send.

[tikool17]

Description

Communication Timeout error in the exception log for communications that have a large number of recipients.

Example https://staff.freechapel.org/communications/295239
Recipients: 18425
This is an email bulk communication using the "Default" template.
Navigating from Editor to Confirmation screen takes 26 seconds.

Actual Behavior

Depending on how the communication is being sent one of two errors are logged.

Sent by the Send Communications Job

One or more exceptions occurred sending communications... Exception occurred sending communication ID:311187: 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 Rock.Jobs.SendCommunications.Execute() in \Rock\Jobs\SendCommunications.cs:line 189
   at Rock.Jobs.RockJob.ExecuteInternal(IJobExecutionContext context) in \Rock\Jobs\RockJob.cs:line 162
   at Quartz.Core.JobRunShell.Run()

Sent by the Bus

A ConsumeFault occurred in the Rock.Tasks.ProcessSendCommunication. Original Message: Rock.Tasks.ProcessSendCommunication+Message.
Exception: System.Data.Entity.Core.EntityCommandExecutionException: An error occurred while executing the command definition.
See the inner exception for details. 
System.Data.SqlClient.SqlException: Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
System.ComponentModel.Win32Exception: The wait operation timed out --- End of inner exception stack trace ---
 at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
 at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
 at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
 at System.Data.SqlClient.SqlDataReader.TryConsumeMetaData()
 at System.Data.SqlClient.SqlDataReader.get_MetaData()
 at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted)
 at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest)
 at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)
 at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
 at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
 at System.Data.Entity.Infrastructure.Interception.InternalDispatcher`1.Dispatch[TTarget,TInterceptionContext,TResult](TTarget target, Func`3 operation, TInterceptionContext interceptionContext, Action`3 executing, Action`3 executed)
 at System.Data.Entity.Infrastructure.Interception.DbCommandDispatcher.Reader(DbCommand command, DbCommandInterceptionContext interceptionContext)
 at System.Data.Entity.Core.EntityClient.Internal.EntityCommandDefinition.ExecuteStoreCommands(EntityCommand entityCommand, CommandBehavior behavior) --- End of inner exception stack trace ---
 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__DisplayClass41_0.<GetResults>b__0()
 at System.Data.Entity.SqlServer.DefaultSqlExecutionStrategy.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__31_0()
 at System.Data.Entity.Internal.LazyEnumerator`1.MoveNext()
 at System.Collections.Generic.List`1..ctor(IEnumerable`1 collection)
 at System.Linq.Enumerable.ToList[TSource](IEnumerable`1 source)
 at Rock.Model.Communication.RefreshCommunicationRecipientList(RockContext rockContext) in \Rock\Model\Communication\Communication\Communication.Logic.cs:line 350
 at Rock.Model.Communication.<SendAsync>d__21.MoveNext() in \Rock\Model\Communication\Communication\Communication.Logic.cs:line 532 --- End of stack trace from previous location where exception was thrown ---
 at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
 at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
 at Rock.Utility.AsyncHelper.RunSync(Func`1 func) in \Rock\Utility\AsyncHelper.cs:line 74
 at Rock.Tasks.ProcessSendCommunication.Execute(Message message) in \Rock\Tasks\ProcessSendCommunication.cs:line 37
 at Rock.Bus.Consumer.RockConsumer`2.Consume(ConsumeContext`1 context) in \Rock\Bus\Consumer\RockConsumer.cs:line 87
 at MassTransit.Pipeline.ConsumerFactories.DelegateConsumerFactory`1.<Send>d__2`1.MoveNext() --- End of stack trace from previous location where exception was thrown ---
 at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
 at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
 at MassTransit.Pipeline.Filters.ConsumerMessageFilter`2.<GreenPipes-IFilter<MassTransit-ConsumeContext<TMessage>>-Send>d__4.MoveNext()

It appears the timeout occurs while checking to see if all of the communication members are in the recipient list here: https://github.com/SparkDevNetwork/Rock/blob/33b0d328a3b7835613afeede9af57b206f6125f3/Rock/Model/Communication/Communication/Communication.Logic.cs#L350https://github.com/SparkDevNetwork/Rock/blob/33b0d328a3b7835613afeede9af57b206f6125f3/Rock/Model/Communication/Communication/Communication.Logic.cs#L350

Expected Behavior

The communication is sent successfully.

Steps to Reproduce

-Create a communication with a large number of recipients.

Issue Confirmation

• Perform a search on the Github Issues to see if your bug or enhancement is already reported.
• Try to reproduce the problem on a fresh install or on the demo site.

Rock Version

16

Client Culture Setting

en-US

[chead4]

@tikool17 Rock is all about community. If possible, please include your name in your GitHub account.

[jasonhendee]

Hey @tikool17, thanks for reporting. Are you able to consistently reproduce this issue? We've spent a bit of time attempting to reproduce while sending to 100k+ recipients, without success thus far. Are there any additional "Steps to Reproduce" you can provide?

[tikool17]

@jasonhendee thanks for looking into this. I don't have definite steps to reproduce other than a large number of recepients. But if it helps we do use Communication lists, segments and prevent duplicates often. See below on some typical segment setup which I could see that would add some extra strain on the system to process.

[jasonhendee]

Thanks, @tikool17; this is very helpful.

If you were to send the above communication, would it fail every time? Or does it seem to be hit-or-miss?

[jasonhendee]

@tikool17, we've addressed this issue as follows:

1. We identified and improved several areas within the Communication Entry Wizard block and the general Communication send processes themselves where performance improvements could be made. We hope you'll notice that creating new communications within the wizard feels snappier moving forward.
2. We added new Observability hooks to several key areas within the Communication Entry Wizard block and general Communication send processes that will help us track down and dig further into remaining performance bottlenecks that might yet reveal themselves.

Furthermore, we have plans to rewrite the Communication Entry Wizard block in Obsidian soon, so we're hesitant to spend too much more time addressing some of the known super edge case performance issues that still exist within the legacy version of this block.

Please feel free to reopen this issue if you find the original issues still present themselves within your environment after updating to Rock v16.2.