COU-627 - Gives timeout error when transferring content.

Created by Eric Frost 21 Sep 2017, 08:51:18 Updated by James 24 Apr 2018, 17:07:29

Tags: Up For Grabs Gold partner

Subtask of: COU-521

Versions: Umbraco 7.7.6 Courier 3.1.6

Details:

  • The error happens when Courier tries to tranfer the following:
    • The website has a large number of media items (my test has 1,000)
    • Any image (singular) is referenced from within an RTE within an Umbraco content grid control

Files showcasing the issue: https://www.dropbox.com/s/6o7nekpifu22pq3/NoPlugins-LargeMedia-Broken-Snapshot.zip?dl=0

Logs: 2017-09-06 13:47:29,407 [41] ERROR Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 41] There was a problem with extracting database information for the item: CurrentItem is null System.Web.Services.Protocols.SoapException: System.Web.Services.Protocols.SoapException: Server was unable to process request. ---> NHibernate.Exceptions.GenericADOException: could not execute query [ SELECT cmsPropertyData.dataNvarchar, cmsPropertyData.dataNtext, umbracoNode.id, umbracoNode.uniqueID FROM cmsPropertyData INNER JOIN cmsPropertyType ON cmsPropertyType.id = cmsPropertyData.propertytypeid INNER JOIN umbracoNode ON umbracoNode.id = cmsPropertyData.contentNodeId WHERE cmsPropertyType.Alias = (@p0) AND umbracoNode.nodeObjectType = (@p1) AND (cmsPropertyData.dataNvarchar IS NOT NULL OR cmsPropertyData.dataNtext IS NOT NULL) ] Name:alias - Value:umbracoFile Name:nodeObjectType - Value:b796f64c-1f99-4ffb-b886-4bf4bc011a9c [SQL: SELECT cmsPropertyData.dataNvarchar, cmsPropertyData.dataNtext, umbracoNode.id, umbracoNode.uniqueID FROM cmsPropertyData INNER JOIN cmsPropertyType ON cmsPropertyType.id = cmsPropertyData.propertytypeid INNER JOIN umbracoNode ON umbracoNode.id = cmsPropertyData.contentNodeId WHERE cmsPropertyType.Alias = (@p0) AND umbracoNode.nodeObjectType = (@p1) AND (cmsPropertyData.dataNvarchar IS NOT NULL OR cmsPropertyData.dataNtext IS NOT NULL)] ---> 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, Action1 wrapCloseInAction) at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action1 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) 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, TaskCompletionSource1 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.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior) at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader() at NHibernate.AdoNet.AbstractBatcher.ExecuteReader(IDbCommand cmd) at NHibernate.Loader.Loader.GetResultSet(IDbCommand st, Boolean autoDiscoverTypes, Boolean callable, RowSelection selection, ISessionImplementor session) at NHibernate.Loader.Loader.DoQuery(ISessionImplementor session, QueryParameters queryParameters, Boolean returnProxies) at NHibernate.Loader.Loader.DoQueryAndInitializeNonLazyCollections(ISessionImplementor session, QueryParameters queryParameters, Boolean returnProxies) at NHibernate.Loader.Loader.DoList(ISessionImplementor session, QueryParameters queryParameters) --- End of inner exception stack trace --- at NHibernate.Loader.Loader.DoList(ISessionImplementor session, QueryParameters queryParameters) at NHibernate.Loader.Loader.ListIgnoreQueryCache(ISessionImplementor session, QueryParameters queryParameters) at NHibernate.Loader.Loader.List(ISessionImplementor session, QueryParameters queryParameters, ISet1 querySpaces, IType[] resultTypes) at NHibernate.Impl.StatelessSessionImpl.ListCustomQuery(ICustomQuery customQuery, QueryParameters queryParameters, IList results) at NHibernate.Impl.StatelessSessionImpl.List(NativeSQLQuerySpecification spec, QueryParameters queryParameters, IList results) at NHibernate.Impl.SqlQueryImpl.List(IList results) at Umbraco.Courier.Persistence.V6.NHibernate.Helpers.MediaHelper.<>c__DisplayClass2.b__0(Object x) at System.Collections.Concurrent.ConcurrentDictionary2.GetOrAdd(TKey key, Func2 valueFactory) at Umbraco.Courier.Persistence.V6.NHibernate.Helpers.MediaHelper.GetOrCreateMediaPathCache(Func2 sqlQueryFactory) at Umbraco.Courier.Persistence.V6.NHibernate.Helpers.MediaHelper.GetMediaGuidByPath(String mediaPath) at Umbraco.Courier.Persistence.V6.NHibernate.NHibernateProvider.GetUniqueIdFromMediaFile(String filePath) at Umbraco.Courier.DataResolvers.Helpers.ImagesResolver.AddImageDependenciesForValue(String value, Item item) at Umbraco.Courier.DataResolvers.GridCellDataResolvers.CoreCellEditorResolver.HandleRte(Item item, ContentProperty propertyData, GridValueControlModel cell, Boolean packing) at Umbraco.Courier.DataResolvers.GridCellDataResolvers.CoreCellEditorResolver.HandleCoreCellEditors(Item item, ContentProperty propertyData, GridValueControlModel cell, Boolean packing) at Umbraco.Courier.DataResolvers.GridCellDataResolvers.CoreCellEditorResolver.ExtractingCell(Item item, ContentProperty propertyData, GridValueControlModel cell) at Umbraco.Courier.DataResolvers.PropertyDataResolvers.GridCellResolverProvider.ExtractingProperty(Item item, ContentProperty propertyData) at Umbraco.Courier.DataResolvers.PropertyDataResolverProvider.Extracting(Item item) at Umbraco.Courier.Core.ResolutionManager.ExecuteResolver(Item item, ItemEvent e, ItemProvider provider) at Umbraco.Courier.Core.ItemProvider.Extract(Item item) at Umbraco.Courier.RepositoryProviders.Local.ExtractItem(Item item, Boolean overwrite) at Umbraco.Courier.RepositoryProviders.Webservices.Repository.ExtractItems(String sessionKey, SerializedItemWrapper[] items, Boolean overWrite) --- End of inner exception stack trace --- at System.Web.Services.Protocols.SoapHttpClientProtocol.ReadResponse(SoapClientMessage message, WebResponse response, Stream responseStream, Boolean asyncCall) at System.Web.Services.Protocols.SoapHttpClientProtocol.EndInvoke(IAsyncResult asyncResult) at Umbraco.Courier.RepositoryProviders.WebServiceProvider.RepositoryWebservice.EndExtractItems(IAsyncResult asyncResult) at Umbraco.Courier.RepositoryProviders.CourierWebserviceRepositoryProvider.ExtractItems(Item[] items, Boolean overWrite) at Umbraco.Courier.Core.Extraction.RevisionExtraction.ExtractItems(List1 nodes) at Umbraco.Courier.Core.Extraction.RevisionExtraction.ExtractReadyRevisionBatch() at Umbraco.Courier.Core.Extraction.RevisionExtraction.ExtractReadyRevisionBatch() at Umbraco.Courier.Core.Extraction.RevisionExtraction.ExtractReadyRevisionBatch() at Umbraco.Courier.Core.Extraction.RevisionExtraction.Extract() 2017-09-06 13:47:29,412 [41] DEBUG Umbraco.Courier.Persistence.V6.NHibernate.NHibernateProvider - [Thread 41] Closing session, UseGlobalSession: False, key: 5460a37d-3c6d-4134-a389-279ec55299d6

6 Attachments

Download Courier.v3.1.7-cou-627.zip

Download Courier.v3.1.7-cou-627.HotFix.zip

Download CourierTraceLog.txt

Download Courier.v3.1.6-cou-627-v2.HotFix.zip

Comments

Gareth Evans 21 Sep 2017, 20:52:30

Eric has loaded this issue on my behalf following a support enquiry. I can provide any further detail required.


Gareth Evans 21 Sep 2017, 20:53:45

The query that is timing out executes in under a second when you run it manually against the database.


Gareth Evans 09 Oct 2017, 20:46:41

I have just re-tested this with the latest nightly (493, Courier.v3.1.5-nightly493.HotFix.zip) and unfortunately am still encountering the same issue. The transfer of the node containing a media inside an RTE inside a grid fails. It gets to the deploy of media, as shown, then results in a timeout error. I think this is likely due to the refactoring/changes in http://issues.umbraco.org/issue/COU-608 (refactoring of media data fetch so it is one big pre-cached query) and possibly also http://issues.umbraco.org/issue/COU-582 (where media in RTE+grids support was added)


Gareth Evans 22 Nov 2017, 04:04:32

Retested in 3.1.6 and can confirm same fault still occurs. Stack trace and query is the same.


Gareth Evans 22 Nov 2017, 20:28:38

Retested after upgrading to Umbraco 7.7.6 (with both Courier 3.1.5 and 3.1.6) and can still reproduce.

2017-11-23 09:22:40,028 [128] INFO Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 128] Running ExtractReadyRevisionBatch 2017-11-23 09:22:40,028 [128] INFO Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 128] Extracting batch of 1 items 2017-11-23 09:22:40,076 [128] INFO Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 128] Extracting batch of 1 items 2017-11-23 09:22:40,100 [128] INFO Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 128] Extracting batch of 1 items 2017-11-23 09:22:40,210 [128] INFO Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 128] Extracting batch of 1 items 2017-11-23 09:23:10,250 [128] INFO Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 128] Finished ExtractReadyRevisionBatch (took 30222ms) 2017-11-23 09:23:10,251 [128] INFO Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 128] Rolling back changes due to errors 2017-11-23 09:23:10,273 [128] ERROR Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 128] There was a problem with extracting database information for the item: CurrentItem is null

Followed by 4x query failure: System.Web.Services.Protocols.SoapException: System.Web.Services.Protocols.SoapException: Server was unable to process request. ---> NHibernate.Exceptions.GenericADOException: could not execute query 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

Raw query in SQL

declare @p0 nvarchar(255) select @p0 = 'umbracoFile' declare @p1 uniqueidentifier select @p1 = 'b796f64c-1f99-4ffb-b886-4bf4bc011a9c' SELECT cmsPropertyData.dataNvarchar, cmsPropertyData.dataNtext, umbracoNode.id, umbracoNode.uniqueID FROM cmsPropertyData INNER JOIN cmsPropertyType ON cmsPropertyType.id = cmsPropertyData.propertytypeid INNER JOIN umbracoNode ON umbracoNode.id = cmsPropertyData.contentNodeId WHERE cmsPropertyType.Alias = (@p0) AND umbracoNode.nodeObjectType = (@p1) AND (cmsPropertyData.dataNvarchar IS NOT NULL OR cmsPropertyData.dataNtext IS NOT NULL)

SSMS actual execution plan suggests index: CREATE NONCLUSTERED INDEX UX_UmbracoNode_NodeObjectType ON [dbo].[umbracoNode] ([nodeObjectType]) INCLUDE ([id],[uniqueID]) GO

But has no effect, query still times out when run through courier. The query in question returns 2043 rows on left side, and 220 rows on right side (around 1000 nodes of media was imported to left) and returns in SSMS in less than 100ms.


Greg Vincent 01 Dec 2017, 14:49:17

I am experiencing the same issue. I have a staging site running on a dedicated AWS server. The server is in an ELB pool, but we are not using Umbraco's flexible load balancer configuration since we only have one staging site/server. Our production site/server mirrors the staging server setup on a separate AWS server.

The sites are running Umbraco 7.5.11 with courier 3.1.6. When we attempt to courier transfer a content page containing an RTE with an embedded media image, we receive the following error;

Server was unable to process request. ---> could not execute query [ SELECT cmsPropertyData.dataNvarchar, cmsPropertyData.dataNtext, umbracoNode.id, umbracoNode.uniqueID FROM cmsPropertyData INNER JOIN cmsPropertyType ON cmsPropertyType.id = cmsPropertyData.propertytypeid INNER JOIN umbracoNode ON umbracoNode.id = cmsPropertyData.contentNodeId WHERE cmsPropertyType.Alias = (@p0) AND umbracoNode.id IN (SELECT umbracoNode.id FROM umbracoNode INNER JOIN cmsContent ON cmsContent.nodeId = umbracoNode.id INNER JOIN cmsContentType ON cmsContentType.nodeId = cmsContent.contentType INNER JOIN cmsPropertyType ON cmsPropertyType.contentTypeId = cmsContentType.nodeId WHERE cmsPropertyType.Alias = (@p0) AND umbracoNode.nodeObjectType = (@p2)) AND (cmsPropertyData.dataNvarchar IS NOT NULL OR cmsPropertyData.dataNtext IS NOT NULL) ] Name:alias - Value:umbracoFile Name:nodeObjectType - Value:b796f64c-1f99-4ffb-b886-4bf4bc011a9c [SQL: SELECT cmsPropertyData.dataNvarchar, cmsPropertyData.dataNtext, umbracoNode.id, umbracoNode.uniqueID FROM cmsPropertyData INNER JOIN cmsPropertyType ON cmsPropertyType.id = cmsPropertyData.propertytypeid INNER JOIN umbracoNode ON umbracoNode.id = cmsPropertyData.contentNodeId WHERE cmsPropertyType.Alias = (@p0) AND umbracoNode.id IN (SELECT umbracoNode.id FROM umbracoNode INNER JOIN cmsContent ON cmsContent.nodeId = umbracoNode.id INNER JOIN cmsContentType ON cmsContentType.nodeId = cmsContent.contentType INNER JOIN cmsPropertyType ON cmsPropertyType.contentTypeId = cmsContentType.nodeId WHERE cmsPropertyType.Alias = (@p0) AND umbracoNode.nodeObjectType = (@p2)) AND (cmsPropertyData.dataNvarchar IS NOT NULL OR cmsPropertyData.dataNtext IS NOT NULL)] ---> Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding. ---> The wait operation timed out

Executing this query in SQL takes less than 4 seconds and returns thousands of results. The SQL execution suggests that the query is not timing out.

During debugging we found that the issue is caused when a new image is added to the media library, but not transferred to the destination server before attempting to transfer the content page containing the RTE and embedded media image.

As a work around we are currently creating and transferring the content page without the embedded media image. We then create a new media image in the media library and transfer it to the destination server. Once the media item is transferred we update the content page with the embedded media image and transfer it again to the destination.

I found a post on our.umbraco.org where someone asked why images embedded in the RTE are not transferring. The question was posted with regards to courier 7.52.3, but the ultimate fix was to create a custom data resolver to transfer the embedded media item. The post can be found at

https://our.umbraco.org/forum/umbraco-courier/76273-help-courier-publishing-image-within-a-rich-text-editor-maybe-simple-for-someone-who-knows

Do we need to create a custom data resolver to overcome this issue?


Gareth Evans 04 Dec 2017, 20:38:40

@gvincent my understanding from reading the stack trace and my own observation on the problem plus other tickets is that built in support was added to courier so there is no need to for a custom data resolver. The data resolver determines what items need to be transferred and this issue occurs at the time of extraction/transfer - after the items to be transferred have been resolved. I also found the query executed quickly, I think this may ultimately be a transaction/locking issue but I can't debug it myself, nor can we step through the courier code to find a fix. Your workaround seems fine but for us our client is doing the transfer themselves so we've had to put this project on hold until we get a resolution.


Mikkel Holck Madsen 05 Dec 2017, 22:47:31

Hi @agrath I've attached a local build of Courier - It should is reverting some stuff related to the session mechanisme used, when resolving the images in the rte.

For some reason when transfering a rte that has images in it, it will try to open a new session, while an existing session to the database is already running - the new session will never be allowed access to the finalize its query, because of the clash with the first session - and therefore it ends in a timeout.

the fix provided is not a finalized solution, as the it in reality reverts some other fixes, that will ensure better database session management and transactions. It should however help you with the issue you are seeing, and should just be able to be implemented. The real fix will be in Courier 3.1.7, and might just be this current one.

Could you please give it a go, and test weather it fixes the current issue?


Mikkel Holck Madsen 05 Dec 2017, 22:48:14

Btw. i tested it in the attached solutions and works as expected there - items can be transfered without any issues


Mikkel Holck Madsen 05 Dec 2017, 22:49:43

the hotfix package - containing the dlls needed - should be sufficient to copy the Umbraco.Courier.DataResolvers.dll file


Gareth Evans 07 Dec 2017, 01:42:22

Hi @mikkelhm It sounds like you're on the right track but I've just tested with your hotfix (dropped bin folder contents into my left & right test site) and i'm still getting a very similar crash. I've attached a courier trace log from the left/source side.


Mikkel Holck Madsen 08 Dec 2017, 11:08:51

@agrath I see the issue as well - I have no idea about what went wrong - I was 100% sure everything was working. We will try to get a fix done early next week, that can prevent this from happening. We need to dive a bit deeper into the source to find a proper solution.


Mikkel Holck Madsen 13 Dec 2017, 12:49:51

@agrath Finally managed to find what happened in the last fix, and how to do a workarround. Ill attach a new build that I would love for you to test. I've tested in the Left/Right sites and seems to be working as expected.

We were looking at the right thing, but my fix last week was poorly executed - Seems that if I had successfully deployed form one environment to the next one once, it worked on subsequent attempts, which was why I thought it was fixed.

So this new fix is to reuse the current session, in stead of trying to create its own. From my tests it works as expected, but I would really love some input on it, before we merge it into the main Courier branch.

The files changed from the original Courier 3.1.6 code is only the Umbraco.Courier.Persistence.V7.NHibernate.dll - but if you have already applied the fix i gave last week, you should revert the Umbraco.Courier.DataResolvers.dll, as the change that was included in that dll wasnt nessecary after all.


Gareth Evans 14 Dec 2017, 19:42:36

@mikkelhm

I can confirm that this patch is working on my left/right test sites. Thank you so much, we were in a bit of a bind with this not working having sold the solution to our client.

I replaced all courier files with the ones from the 3.1.6 release then applied the patch/hotfix you supplied. Our next (internal) step will be to set this up on our client's site and test it there, however this will not be until early 2018 now.

Please let me know if you need anything else?


Shannon Deminick 20 Dec 2017, 04:58:57

A fix has been pulled in, a new version of Courier will be due out next week.


Davy Meybos 16 Feb 2018, 14:35:39

Experiencing the same issue as described above.

@mikkelhm : is it safe to use your fix for pushing content towards a production environment or should we wait for Courier 3.1.7?


Chris Van Oort 23 Feb 2018, 19:02:19

Also experiencing the same issue as above on Umbraco 7.8.1; I rolled out @mikkelhm fix to staging and production in lieu of Courier 3.1.7's release.


Mikkel Holck Madsen 26 Feb 2018, 08:07:12

Sorry guys, we never did release the 3.1.7 version - We've put it back on the priority list, and it will be released soon - untill then, the fix provided in this thread is still the valid one.


James 24 Apr 2018, 17:07:29

Just adding that we are also experiencing this on our staging/production sites (Umbraco 7.10.3 / Courier 3.1.6). Huge thanks to @mikkelhm for the hotfix, just replacing the Umbraco.Courier.Persistence.V7.NHibernate.dll did the trick. Eagerly awaiting 3.1.7 come out!


Priority: Critical

Type: Bug

State: Fixed

Assignee:

Difficulty:

Category:

Backwards Compatible: True

Fix Submitted:

Affected versions: 3.1.6

Due in version: 3.1.7

Sprint: Sprint 74

Story Points: 3

Cycle: 6