umbraco / Umbraco.Workflow.Issues

Public issue tracker for Umbraco Workflow
1 stars 0 forks source link

Page is published through workflow, but workflow is not completed #85

Closed bruceanewton closed 1 month ago

bruceanewton commented 1 month ago

We are still in the process of converting our Umbraco V8 site to V13, and have come across an issue with workflows whereby we are able to 'Request publish' for a page, 'Approve' the publish request, which publishes the page, but does not complete the workflow (it still shows as 'Pending approval' in the page workflow history), which leads to issues when attempting to make further changes to the page at a later date.

Reproduction

Specifics

Umbraco version: 13.5.1 Umbraco.Workflow version: 13.2.1 Chrome browser version 122.0.6261.129, site running under IIS on Windows 10 (although the same issues occur when running directly from the Visual Studio IDE)

Steps to reproduce

I'll detail the steps taken to reproduce the issue below.

Note that I've spent hours trying to reproduce this issue on a vanilla Umbraco 13 site, but without success. Hence, I'm wondering whether it's similar to the error that I reported and you resolved a while ago https://github.com/umbraco/Umbraco.Workflow.Issues/issues/79, which I also couldn't reproduce on a small site.

It seems similar to that issue, because if I turn off the workflow 'Send notifications' setting, then this issue appears to go away.

Steps:

image

image

image

image

image

At the point of the page approval, a number of messages are raised in the Umbraco trace log:

[ {"@t":"2024-10-17T05:00:19.5441194Z","@mt":"Workflow completed for node {Id}, page has been {Action}","@tr":"786f13d8abee21f54dbcae439a074e78","@sp":"9dc4005199b28b0b","Id":103161,"Action":"published","SourceContext":"Umbraco.Workflow.Core.Processes.WorkflowInstanceCompletionManager","ActionId":"555fd5ad-88ec-4174-8bb7-44f9b1e93b7e","ActionName":"Umbraco.Workflow.Web.Controllers.ActionsController.Approve (Umbraco.Workflow.Web)","RequestId":"800000e8-0009-ec00-b63f-84710c7967bb","RequestPath":"/umbraco/backoffice/workflow/actions/approve","ProcessId":89792,"ProcessName":"w3wp","ThreadId":83,"ApplicationId":"6b5d00dc72ce5284e0f562842f9308a3cff85b97","MachineName":"65CP373","Log4NetLevel":"INFO ","HttpRequestId":"6b4c7748-2845-47b1-a368-6cdeb0d5107d","HttpRequestNumber":29,"HttpSessionId":"120037cf-6064-c2f5-c04a-3977ca25ad7e"}, {"@t":"2024-10-17T05:00:19.5449862Z","@mt":"Exception ({InstanceId}).","@l":"Error","@x":"System.InvalidOperationException: There is already an open DataReader associated with this Connection which must be closed first.\r\n at Microsoft.Data.SqlClient.SqlCommand.ValidateCommand(Boolean isAsync, String method)\r\n at Microsoft.Data.SqlClient.SqlCommand.ExecuteNonQuery()\r\n at Umbraco.Cms.Infrastructure.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func1 func)\r\n at System.Data.Common.DbCommand.ExecuteNonQueryAsync(CancellationToken cancellationToken)\r\n--- End of stack trace from previous location ---\r\n at NPoco.Database.ExecutionHookAsync[T](Func1 action)\r\n at NPoco.Database.ExecuteNonQueryHelperAsync(DbCommand cmd)\r\n at NPoco.Database.ExecuteAsync(Sql Sql)","@tr":"786f13d8abee21f54dbcae439a074e78","@sp":"9dc4005199b28b0b","InstanceId":"f31a0ba1","SourceContext":"Umbraco.Cms.Infrastructure.Persistence.UmbracoDatabase","ActionId":"555fd5ad-88ec-4174-8bb7-44f9b1e93b7e","ActionName":"Umbraco.Workflow.Web.Controllers.ActionsController.Approve (Umbraco.Workflow.Web)","RequestId":"800000e8-0009-ec00-b63f-84710c7967bb","RequestPath":"/umbraco/backoffice/workflow/actions/approve","ProcessId":89792,"ProcessName":"w3wp","ThreadId":83,"ApplicationId":"6b5d00dc72ce5284e0f562842f9308a3cff85b97","MachineName":"65CP373","Log4NetLevel":"ERROR","HttpRequestId":"6b4c7748-2845-47b1-a368-6cdeb0d5107d","HttpRequestNumber":29,"HttpSessionId":"120037cf-6064-c2f5-c04a-3977ca25ad7e"}, {"@t":"2024-10-17T05:00:19.5534201Z","@mt":"Exception ({InstanceId}).","@l":"Error","@x":"System.InvalidOperationException: There is already an open DataReader associated with this Connection which must be closed first.\r\n at Microsoft.Data.SqlClient.SqlCommand.ValidateCommand(Boolean isAsync, String method)\r\n at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, TaskCompletionSource1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry, String method)\r\n at Microsoft.Data.SqlClient.SqlCommand.ExecuteScalar()\r\n at Umbraco.Cms.Infrastructure.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func1 func)\r\n at NPoco.Database.ExecuteScalarHelper(DbCommand cmd)\r\n at NPoco.Database.InsertAsyncImp[T](PocoData pocoData, String tableName, String primaryKeyName, Boolean autoIncrement, T poco, Boolean sync)","@tr":"786f13d8abee21f54dbcae439a074e78","@sp":"9dc4005199b28b0b","InstanceId":"f31a0ba1","SourceContext":"Umbraco.Cms.Infrastructure.Persistence.UmbracoDatabase","RequestId":"800000e8-0009-ec00-b63f-84710c7967bb","RequestPath":"/umbraco/backoffice/workflow/actions/approve","ProcessId":89792,"ProcessName":"w3wp","ThreadId":83,"ApplicationId":"6b5d00dc72ce5284e0f562842f9308a3cff85b97","MachineName":"65CP373","Log4NetLevel":"ERROR","HttpRequestId":"6b4c7748-2845-47b1-a368-6cdeb0d5107d","HttpRequestNumber":29,"HttpSessionId":"0"}, {"@t":"2024-10-17T05:00:19.5583878Z","@mt":"An unhandled exception has occurred while executing the request.","@l":"Error","@x":"System.InvalidOperationException: There is already an open DataReader associated with this Connection which must be closed first.\r\n at Microsoft.Data.SqlClient.SqlCommand.ValidateCommand(Boolean isAsync, String method)\r\n at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, TaskCompletionSource1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry, String method)\r\n at Microsoft.Data.SqlClient.SqlCommand.ExecuteScalar()\r\n at Umbraco.Cms.Infrastructure.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func1 func)\r\n at NPoco.Database.ExecuteScalarHelper(DbCommand cmd)\r\n at NPoco.Database.InsertAsyncImp[T](PocoData pocoData, String tableName, String primaryKeyName, Boolean autoIncrement, T poco, Boolean sync)\r\n at NPoco.Database.Insert[T](String tableName, String primaryKeyName, Boolean autoIncrement, T poco)\r\n at NPoco.Database.Insert[T](T poco)\r\n at Umbraco.Cms.Infrastructure.Persistence.Repositories.Implement.CacheInstructionRepository.Add(CacheInstruction cacheInstruction)\r\n at Umbraco.Cms.Infrastructure.Services.CacheInstructionService.DeliverInstructionsInBatches(IEnumerable1 instructions, String localIdentity)\r\n at Umbraco.Cms.Infrastructure.Sync.BatchedDatabaseServerMessenger.SendMessages()\r\n at Umbraco.Cms.Core.Events.INotificationHandler1.Handle(IEnumerable1 notifications)\r\n at Umbraco.Cms.Core.Events.EventAggregator.PublishCore[TNotification](IEnumerable1 allHandlers, IEnumerable1 notifications)\r\n at Umbraco.Cms.Core.Events.NotificationHandlerWrapperImpl1.Handle[TNotification,TNotificationHandler](IEnumerable1 notifications, ServiceFactory serviceFactory, Action2 publish)\r\n at Umbraco.Cms.Core.Events.EventAggregator.PublishNotifications[TNotification,TNotificationHandler](IEnumerable1 notifications)\r\n at Umbraco.Cms.Core.Events.EventAggregator.PublishAsync[TNotification,TNotificationHandler](IEnumerable1 notifications, CancellationToken cancellationToken)\r\n at Umbraco.Cms.Core.Events.EventAggregator.PublishAsync[TNotification](TNotification notification, CancellationToken cancellationToken)\r\n at Umbraco.Cms.Web.Common.Middleware.UmbracoRequestMiddleware.InvokeAsync(HttpContext context, RequestDelegate next)\r\n at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.InterfaceMiddlewareBinder.<>cDisplayClass2_0.<b0>d.MoveNext()\r\n--- End of stack trace from previous location ---\r\n at Umbraco.Cms.Web.Common.Middleware.PreviewAuthenticationMiddleware.InvokeAsync(HttpContext context, RequestDelegate next)\r\n at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.InterfaceMiddlewareBinder.<>cDisplayClass2_0.<b0>d.MoveNext()\r\n--- End of stack trace from previous location ---\r\n at Umbraco.Cms.Web.Common.Middleware.UmbracoRequestLoggingMiddleware.InvokeAsync(HttpContext context, RequestDelegate next)\r\n at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.InterfaceMiddlewareBinder.<>cDisplayClass2_0.<b0>d.MoveNext()\r\n--- End of stack trace from previous location ---\r\n at SixLabors.ImageSharp.Web.Middleware.ImageSharpMiddleware.Invoke(HttpContext httpContext, Boolean retry)\r\n at Umbraco.Forms.Web.HttpModules.ProtectFormUploadRequestsMiddleware.InvokeAsync(HttpContext context, RequestDelegate next)\r\n at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.InterfaceMiddlewareBinder.<>cDisplayClass2_0.<b0>d.MoveNext()\r\n--- End of stack trace from previous location ---\r\n at Usc.Infrastructure.BackOfficeProtectorMiddleware.Invoke(HttpContext context) in D:\Git\CorporateWebsiteV13\Usc.Infrastructure\BackOfficeProtectorMiddleware.cs:line 37\r\n at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddlewareImpl.Invoke(HttpContext context)","@tr":"786f13d8abee21f54dbcae439a074e78","@sp":"9dc4005199b28b0b","EventId":{"Id":1,"Name":"UnhandledException"},"SourceContext":"Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware","RequestId":"800000e8-0009-ec00-b63f-84710c7967bb","RequestPath":"/umbraco/backoffice/workflow/actions/approve","ProcessId":89792,"ProcessName":"w3wp","ThreadId":83,"ApplicationId":"6b5d00dc72ce5284e0f562842f9308a3cff85b97","MachineName":"65CP373","Log4NetLevel":"ERROR"}, {"@t":"2024-10-17T05:00:19.5741840Z","@mt":"The response has already started, the error page middleware will not be executed.","@l":"Warning","@tr":"786f13d8abee21f54dbcae439a074e78","@sp":"9dc4005199b28b0b","EventId":{"Id":2,"Name":"ResponseStarted"},"SourceContext":"Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware","RequestId":"800000e8-0009-ec00-b63f-84710c7967bb","RequestPath":"/umbraco/backoffice/workflow/actions/approve","ProcessId":89792,"ProcessName":"w3wp","ThreadId":83,"ApplicationId":"6b5d00dc72ce5284e0f562842f9308a3cff85b97","MachineName":"65CP373","Log4NetLevel":"WARN "}, {"@t":"2024-10-17T05:00:19.5753341Z","@mt":"Connection ID \"{ConnectionId}\", Request ID \"{TraceIdentifier}\": An unhandled exception was thrown by the application.","@l":"Error","@x":"System.InvalidOperationException: There is already an open DataReader associated with this Connection which must be closed first.\r\n at Microsoft.Data.SqlClient.SqlCommand.ValidateCommand(Boolean isAsync, String method)\r\n at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, TaskCompletionSource1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry, String method)\r\n at Microsoft.Data.SqlClient.SqlCommand.ExecuteScalar()\r\n at Umbraco.Cms.Infrastructure.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func1 func)\r\n at NPoco.Database.ExecuteScalarHelper(DbCommand cmd)\r\n at NPoco.Database.InsertAsyncImp[T](PocoData pocoData, String tableName, String primaryKeyName, Boolean autoIncrement, T poco, Boolean sync)\r\n at NPoco.Database.Insert[T](String tableName, String primaryKeyName, Boolean autoIncrement, T poco)\r\n at NPoco.Database.Insert[T](T poco)\r\n at Umbraco.Cms.Infrastructure.Persistence.Repositories.Implement.CacheInstructionRepository.Add(CacheInstruction cacheInstruction)\r\n at Umbraco.Cms.Infrastructure.Services.CacheInstructionService.DeliverInstructionsInBatches(IEnumerable1 instructions, String localIdentity)\r\n at Umbraco.Cms.Infrastructure.Sync.BatchedDatabaseServerMessenger.SendMessages()\r\n at Umbraco.Cms.Core.Events.INotificationHandler1.Handle(IEnumerable1 notifications)\r\n at Umbraco.Cms.Core.Events.EventAggregator.PublishCore[TNotification](IEnumerable1 allHandlers, IEnumerable1 notifications)\r\n at Umbraco.Cms.Core.Events.NotificationHandlerWrapperImpl1.Handle[TNotification,TNotificationHandler](IEnumerable1 notifications, ServiceFactory serviceFactory, Action2 publish)\r\n at Umbraco.Cms.Core.Events.EventAggregator.PublishNotifications[TNotification,TNotificationHandler](IEnumerable1 notifications)\r\n at Umbraco.Cms.Core.Events.EventAggregator.PublishAsync[TNotification,TNotificationHandler](IEnumerable1 notifications, CancellationToken cancellationToken)\r\n at Umbraco.Cms.Core.Events.EventAggregator.PublishAsync[TNotification](TNotification notification, CancellationToken cancellationToken)\r\n at Umbraco.Cms.Web.Common.Middleware.UmbracoRequestMiddleware.InvokeAsync(HttpContext context, RequestDelegate next)\r\n at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.InterfaceMiddlewareBinder.<>cDisplayClass2_0.<b0>d.MoveNext()\r\n--- End of stack trace from previous location ---\r\n at Umbraco.Cms.Web.Common.Middleware.PreviewAuthenticationMiddleware.InvokeAsync(HttpContext context, RequestDelegate next)\r\n at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.InterfaceMiddlewareBinder.<>cDisplayClass2_0.<b0>d.MoveNext()\r\n--- End of stack trace from previous location ---\r\n at Umbraco.Cms.Web.Common.Middleware.UmbracoRequestLoggingMiddleware.InvokeAsync(HttpContext context, RequestDelegate next)\r\n at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.InterfaceMiddlewareBinder.<>cDisplayClass2_0.<b0>d.MoveNext()\r\n--- End of stack trace from previous location ---\r\n at SixLabors.ImageSharp.Web.Middleware.ImageSharpMiddleware.Invoke(HttpContext httpContext, Boolean retry)\r\n at Umbraco.Forms.Web.HttpModules.ProtectFormUploadRequestsMiddleware.InvokeAsync(HttpContext context, RequestDelegate next)\r\n at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.InterfaceMiddlewareBinder.<>cDisplayClass2_0.<b0>d.MoveNext()\r\n--- End of stack trace from previous location ---\r\n at Usc.Infrastructure.BackOfficeProtectorMiddleware.Invoke(HttpContext context) in D:\Git\CorporateWebsiteV13\Usc.Infrastructure\BackOfficeProtectorMiddleware.cs:line 37\r\n at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddlewareImpl.Invoke(HttpContext context)\r\n at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddlewareImpl.Invoke(HttpContext context)\r\n at Microsoft.AspNetCore.Server.IIS.Core.IISHttpContextOfT`1.ProcessRequestAsync()","@tr":"786f13d8abee21f54dbcae439a074e78","@sp":"9dc4005199b28b0b","ConnectionId":"17005592233216311527","TraceIdentifier":"800000e8-0009-ec00-b63f-84710c7967bb","EventId":{"Id":2,"Name":"ApplicationError"},"SourceContext":"Microsoft.AspNetCore.Server.IIS.Core.IISHttpServer","RequestId":"800000e8-0009-ec00-b63f-84710c7967bb","RequestPath":"/umbraco/backoffice/workflow/actions/approve","ProcessId":89792,"ProcessName":"w3wp","ThreadId":83,"ApplicationId":"6b5d00dc72ce5284e0f562842f9308a3cff85b97","MachineName":"65CP373","Log4NetLevel":"ERROR"} ]

Expected result

The page is published and the workflow status set to Approved when the workflow is approved.

Actual result

As above

Thanks, Bruce


This item has been added to our backlog AB#45084

nathanwoulfe commented 1 month ago

Hey Bruce, this sounds very much related to #79.

I think I need to have a look at how we manage emailing, and move that logic off to a scheduled task. That way, rather than sending the notifications as part of initiating/processing a workflow process, I'll write to a queue, then pull items from that queue in the hosted service. It's probably more efficient too to send batches of emails every n minutes, rather than sporadically as workflows are actioned.

I have a release scheduled for next Wednesday, will look at this one tomorrow and should be able to include it, assuming all goes well

nathanwoulfe commented 1 month ago

Latest minors include this change - looks to have resolved the problem (at least, I was able to reproduce the bug on a large site, then no longer after adding the email queue).

bruceanewton commented 1 month ago

Thanks Nathan, much appreciated. Bruce