Sign in Register
Copied to clipboard

Flag this post as spam?

This post will be reported to the moderators as potential spam to be looked at


  • Carl Bussema 38 posts 140 karma points
    Jan 19, 2016 @ 19:02
    Carl Bussema
    0

    Courier breaks with NHibernate Exception

    U 7.3.4 C 2.51.4-nightly280

    Sometimes courier fails; this sadly seems to be a fact of life. Courier also does not like large content trees; this seems to be a frequent cause of failure, unfortunately sometimes A) it is necessary to transfer these large trees because you are reorganizing folders with lots of children (e.g., into subfolders) and B) it is impossible to tell up front whether the tree is too big for Courier.

    So OK, courier fails and crashes with a random exception. In this case it's the NHibernate CheckNotZombied function throwing a TransactionException. I tried restarting the App Pool on the staging (source) environment and now if I try to courier something I get

    Tried opening session with id: {some guid} - There is already an active session with id: {other guid} and there can only be one at Umbraco.Courier.Persistence.V6.NHibernate.NHibernateGlobalSessionManager.set_CurrentSessionId(String value) at ...

    So I looked in the troubleshooting steps and it says "clear the courier cache in AppData/Courier/cache" but this folder doesn't actually exist in either Staging or Production. In production all that the AppData\courier folder has is "revisions" which has _{guid that doesn't match either of the above two} _backup

    Restarting the production server app pool is not an acceptable answer; because it would cause downtime while the app pool warms back up and we rely heavily on output caching which would all be destroyed (rebuilt fairly quickly but can be somewhat painful for the first few minutes).

    What is the correct way to get courier to release its hold so that we can again transfer content?

    Copy Link
  • Dennis Aaen 4500 posts 18255 karma points admin hq c-trib
    Jan 20, 2016 @ 09:00
    Dennis Aaen
    0

    Hi Carl,

    We have created a issue in our issue tracker. http://issues.umbraco.org/issue/COU-273

    So we are looking into solve the issue that you are experience.

    /Dennis

    Copy Link
  • Claus Jensen 49 posts 157 karma points hq
    Feb 02, 2016 @ 09:43
    Claus Jensen
    0

    Hi Carl,

    I'm looking into this issue and have so far successfully decreased the timeout for a session to be much lower than what it was previously. When you hit an exception, the session will now time out after only 120 seconds of being untouched - so no need to refresh the app pool when it happens.

    Untouched, however means you can not retry a deploy within these two minutes - if you do, sliding expiration in the session manager will refresh your session, meaning it will reset the timeout timer to the 120 seconds again (which is most likely why you would think it would never be released in the current code - it actually did happen if it was untouched for 10 minutes).

    I would however very much like to actually just close the session whenever we hit those exceptions, so we don't run into this issue. That however requires a little more information on when/where you are getting these exceptions - best of all if you can give me a consistent way to reproduce it happening (otherwise a stacktrace, and/or logs would be great).

    I'm going through the code to see if there's any obvious cases where we're not closing the session, but any pointers would be appreciated - that way we can also ensure that your deployments should hopefully work better in the future! ;)

    You can add log files and other info to the issue at our issue tracker here: http://issues.umbraco.org/issue/COU-273

    Best regards, Claus

    Copy Link
  • Carl Bussema 38 posts 140 karma points
    Feb 08, 2016 @ 15:28
    Carl Bussema
    0

    So now I'm getting Courier to break with no error visible; it goes through finding the changes, you can hit deploy, and then you just see a white panel, nothing else. The log on the SOURCE server (v 2.51.5) shows that a .SingleOrDefault() is causing the exception when .GetById() is returning more than one item (why GetById() is returning more than one item, I don't know). But it's definitely confused; if I look on the target server, I see two copies of the item in the tree view. If I try to click on the second, I get taken to the first instead. 

    2016-02-08 11:17:35,078 [166] DEBUG Umbraco.Courier.Core.EventManager - [Thread 209] Unloading (count: 0)
2016-02-08 11:17:35,184 [166] DEBUG Umbraco.Courier.Core.EventManager - [Thread 209] Unloading (count: 0)
2016-02-08 11:17:35,185 [166] INFO  Umbraco.Courier.Core.TaskManager - [Thread 209] Added ExtractionTask behind queue of : 0
2016-02-08 11:17:35,185 [166] INFO  Umbraco.Courier.Core.BackgroundTaskRunner - [Thread 209]  Task added Umbraco.Courier.Core.Tasks.ExtractionTask
2016-02-08 11:17:35,185 [166] INFO  Umbraco.Courier.Core.TaskManager - [Thread 94] Starting ExtractionTask with id: dade663f-dd8d-45ac-ba7f-f0cc53cd5635
2016-02-08 11:17:35,185 [166] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 94] Running PopulateGraph
2016-02-08 11:17:35,271 [166] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 94] Finished PopulateGraph (took 86ms)
2016-02-08 11:17:35,271 [166] DEBUG Umbraco.Courier.Core.EventManager - [Thread 94] Adding event DeleteContentAndMedia To Queue: DeploymentComplete for session: 66a6c2b3-bd23-4e08-8b6c-3cc4b7a263b9
2016-02-08 11:17:35,271 [166] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 94] Starting extraction
2016-02-08 11:17:35,271 [166] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 94] Opens database session
2016-02-08 11:17:35,271 [166] DEBUG Umbraco.Courier.RepositoryProviders.CourierWebserviceRepositoryProvider - [Thread 94] Opening session to http://localhost:33333/
2016-02-08 11:17:35,358 [166] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 94] Transfering pre-extraction files
2016-02-08 11:17:35,367 [166] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 94] Running ExtractReadyRevisionBatch
2016-02-08 11:17:35,367 [166] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 94] Extracting batch of 1 items
2016-02-08 11:17:35,367 [166] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 94] Extracting: Home - Umbraco.Courier.Core.DependencyGraph+GraphNode
2016-02-08 11:17:36,586 [166] WARN  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 94] Finished ExtractItem (took 1215ms)
2016-02-08 11:17:36,587 [166] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 94] Finished ExtractReadyRevisionBatch (took 1220ms)
2016-02-08 11:17:36,587 [166] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 94] Completed extraction queue
2016-02-08 11:17:36,647 [166] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 94] Post processing
2016-02-08 11:17:36,647 [166] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 94] Post processing 0 items
2016-02-08 11:17:36,647 [166] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 94] Finished PostProcessing (took 0ms)
2016-02-08 11:17:36,669 [166] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 94] Completed post processing
2016-02-08 11:17:36,669 [166] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 94] Committing to database
2016-02-08 11:17:36,840 [166] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 94] Transfering post-extract resources
2016-02-08 11:17:36,840 [166] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 94] Completing database transaction
2016-02-08 11:17:42,200 [166] DEBUG Umbraco.Courier.RepositoryProviders.Local - [Thread 94] Disposing: True
2016-02-08 11:17:42,200 [166] WARN  Umbraco.Courier.RepositoryProviders.Local - [Thread 94] Closing session called but there is no session open: 66a6c2b3-bd23-4e08-8b6c-3cc4b7a263b9
2016-02-08 11:17:42,494 [166] DEBUG Umbraco.Courier.Core.EventManager - [Thread 94] Unloading (count: 1)
2016-02-08 11:17:42,498 [166] ERROR Umbraco.Courier.Core.TaskManager - [Thread 94] Error ExtractionTask with id: dade663f-dd8d-45ac-ba7f-f0cc53cd5635
System.Web.Services.Protocols.SoapException: System.Web.Services.Protocols.SoapException: Server was unable to process request. ---> System.InvalidOperationException: Sequence contains more than one element
   at System.Linq.Enumerable.SingleOrDefault[TSource](IEnumerable`1 source)
   at Umbraco.Core.Services.ContentService.GetById(Guid key)
   at Umbraco.Courier.DataResolvers.ItemEventProviders.PublishDocument.Execute(ItemIdentifier itemId, SerializableDictionary`2 parameters)
   at Umbraco.Courier.Core.EventManager.ExecuteLocalEvent(String eventAlias, ItemIdentifier itemId, Dictionary`2 parameters, ExecutionContext context)
   at Umbraco.Courier.Core.EventManager.ExecuteLocalQueue(String sessionKey, String queueAlias, ExecutionContext context)
   at Umbraco.Courier.RepositoryProviders.Local.ExecuteQueue(String queueItems)
   at Umbraco.Courier.RepositoryProviders.Webservices.Repository.ExecuteQueue(String sessionKey, String queueAlias, String user, String pass)
   --- 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.Invoke(String methodName, Object[] parameters)
   at Umbraco.Courier.RepositoryProviders.WebServiceProvider.RepositoryWebservice.ExecuteQueue(String sessionKey, String queueAlias, String user, String pass)
   at Umbraco.Courier.RepositoryProviders.CourierWebserviceRepositoryProvider.ExecuteQueue(String queueAlias)
   at Umbraco.Courier.Core.Extraction.RevisionExtraction.CompleteDatabaseTransaction()
   at Umbraco.Courier.Core.Extraction.RevisionExtraction.Extract()
   at Umbraco.Courier.Core.Tasks.ExtractionTask.Run()
   at Umbraco.Courier.Core.BackgroundTaskRunner`1.ConsumeTaskInternal(T task)
2016-02-08 11:17:42,538 [166] ERROR Umbraco.Courier.Core.BackgroundTaskRunner - [Thread 94] An error occurred consuming task
System.Web.Services.Protocols.SoapException: System.Web.Services.Protocols.SoapException: Server was unable to process request. ---> System.InvalidOperationException: Sequence contains more than one element
   at System.Linq.Enumerable.SingleOrDefault[TSource](IEnumerable`1 source)
   at Umbraco.Core.Services.ContentService.GetById(Guid key)
   at Umbraco.Courier.DataResolvers.ItemEventProviders.PublishDocument.Execute(ItemIdentifier itemId, SerializableDictionary`2 parameters)
   at Umbraco.Courier.Core.EventManager.ExecuteLocalEvent(String eventAlias, ItemIdentifier itemId, Dictionary`2 parameters, ExecutionContext context)
   at Umbraco.Courier.Core.EventManager.ExecuteLocalQueue(String sessionKey, String queueAlias, ExecutionContext context)
   at Umbraco.Courier.RepositoryProviders.Local.ExecuteQueue(String queueItems)
   at Umbraco.Courier.RepositoryProviders.Webservices.Repository.ExecuteQueue(String sessionKey, String queueAlias, String user, String pass)
   --- 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.Invoke(String methodName, Object[] parameters)
   at Umbraco.Courier.RepositoryProviders.WebServiceProvider.RepositoryWebservice.ExecuteQueue(String sessionKey, String queueAlias, String user, String pass)
   at Umbraco.Courier.RepositoryProviders.CourierWebserviceRepositoryProvider.ExecuteQueue(String queueAlias)
   at Umbraco.Courier.Core.Extraction.RevisionExtraction.CompleteDatabaseTransaction()
   at Umbraco.Courier.Core.Extraction.RevisionExtraction.Extract()
   at Umbraco.Courier.Core.Tasks.ExtractionTask.Run()
   at Umbraco.Courier.Core.BackgroundTaskRunner`1.ConsumeTaskInternal(T task)

    DESTINATION LOG

    2016-02-08 11:17:35,341 [135] DEBUG Umbraco.Courier.RepositoryProviders.Local - [Thread 340] Opening session: 66a6c2b3-bd23-4e08-8b6c-3cc4b7a263b9
2016-02-08 11:17:36,575 [135] DEBUG Umbraco.Courier.Core.EventManager - [Thread 263] Adding event ClearInternalDataCache To Queue: ExtractionComplete for session: 66a6c2b3-bd23-4e08-8b6c-3cc4b7a263b9
2016-02-08 11:17:36,575 [135] DEBUG Umbraco.Courier.Core.EventManager - [Thread 263] Adding event PublishDocument To Queue: DBTransactionComplete for session: 66a6c2b3-bd23-4e08-8b6c-3cc4b7a263b9
2016-02-08 11:17:36,575 [135] DEBUG Umbraco.Courier.Core.EventManager - [Thread 263] Adding event RefreshCache To Queue: DeploymentComplete for session: 66a6c2b3-bd23-4e08-8b6c-3cc4b7a263b9
2016-02-08 11:17:36,575 [135] DEBUG Umbraco.Courier.Core.EventManager - [Thread 263] Adding event UpdateLuceneIndexes To Queue: DeploymentComplete for session: 66a6c2b3-bd23-4e08-8b6c-3cc4b7a263b9
2016-02-08 11:17:36,575 [135] WARN  Umbraco.Courier.Core.ItemProvider - [Thread 263] Finished HandleExtract for provider: Documents (took 1180ms)
2016-02-08 11:17:36,643 [135] INFO  Umbraco.Courier.Core.EventManager - [Thread 340] Start processing local queue: 66a6c2b3-bd23-4e08-8b6c-3cc4b7a263b9, alias: ExtractionComplete, count: 1
2016-02-08 11:17:36,644 [135] DEBUG Umbraco.Courier.Core.EventManager - [Thread 340] Start executing local event: [NULL], alias: ClearInternalDataCache
2016-02-08 11:17:36,644 [135] DEBUG Umbraco.Courier.Core.EventManager - [Thread 340] Finished executing local event: [NULL], alias: ClearInternalDataCache (took 0ms)
2016-02-08 11:17:36,644 [135] INFO  Umbraco.Courier.Core.EventManager - [Thread 340] Finished processing local queue: 66a6c2b3-bd23-4e08-8b6c-3cc4b7a263b9, alias: ExtractionComplete, count: 1 (took 1ms)
2016-02-08 11:17:36,667 [135] INFO  Umbraco.Courier.Core.EventManager - [Thread 263] Start processing local queue: 66a6c2b3-bd23-4e08-8b6c-3cc4b7a263b9, alias: PostProcessingComplete, count: 0
2016-02-08 11:17:36,667 [135] INFO  Umbraco.Courier.Core.EventManager - [Thread 263] Finished processing local queue: 66a6c2b3-bd23-4e08-8b6c-3cc4b7a263b9, alias: PostProcessingComplete, count: 0 (took 0ms)
2016-02-08 11:17:36,690 [135] DEBUG Umbraco.Courier.RepositoryProviders.Local - [Thread 340] Committing session: 66a6c2b3-bd23-4e08-8b6c-3cc4b7a263b9
2016-02-08 11:17:36,690 [135] DEBUG Umbraco.Courier.Persistence.V6.NHibernate.NHibernateProvider - [Thread 340] Committing transaction, UseGlobalSession: True, key: 66a6c2b3-bd23-4e08-8b6c-3cc4b7a263b9
2016-02-08 11:17:36,833 [135] DEBUG Umbraco.Courier.RepositoryProviders.Local - [Thread 340] Committed session: 66a6c2b3-bd23-4e08-8b6c-3cc4b7a263b9
2016-02-08 11:17:36,864 [135] INFO  Umbraco.Courier.Core.EventManager - [Thread 263] Start processing local queue: 66a6c2b3-bd23-4e08-8b6c-3cc4b7a263b9, alias: DBTransactionComplete, count: 1
2016-02-08 11:17:36,864 [135] DEBUG Umbraco.Courier.Core.EventManager - [Thread 263] Start executing local event: 428c901a-1260-4066-b823-2060fbd91295, alias: PublishDocument
2016-02-08 11:17:42,089 [135] WARN  Umbraco.Courier.Core.EventManager - [Thread 263] Finished executing local event: 428c901a-1260-4066-b823-2060fbd91295, alias: PublishDocument (took 5224ms)
2016-02-08 11:17:42,090 [135] INFO  Umbraco.Courier.Core.EventManager - [Thread 263] Finished processing local queue: 66a6c2b3-bd23-4e08-8b6c-3cc4b7a263b9, alias: DBTransactionComplete, count: 1 (took 5224ms)
2016-02-08 11:17:42,492 [135] DEBUG Umbraco.Courier.RepositoryProviders.Local - [Thread 263] Closing session: 66a6c2b3-bd23-4e08-8b6c-3cc4b7a263b9
2016-02-08 11:17:42,492 [135] DEBUG Umbraco.Courier.Persistence.V6.NHibernate.NHibernateProvider - [Thread 263] Closing session, UseGlobalSession: True, key: 66a6c2b3-bd23-4e08-8b6c-3cc4b7a263b9
2016-02-08 11:17:42,492 [135] DEBUG Umbraco.Courier.Core.EventManager - [Thread 263] Unloading (count: 3)
2016-02-08 11:17:42,492 [135] DEBUG Umbraco.Courier.RepositoryProviders.Local - [Thread 263] Disposing: True
2016-02-08 11:17:42,492 [135] DEBUG Umbraco.Courier.RepositoryProviders.Local - [Thread 263] Closing session: 66a6c2b3-bd23-4e08-8b6c-3cc4b7a263b9
2016-02-08 11:17:42,492 [135] DEBUG Umbraco.Courier.Persistence.V6.NHibernate.NHibernateProvider - [Thread 263] Closing session, UseGlobalSession: True, key: 66a6c2b3-bd23-4e08-8b6c-3cc4b7a263b9

    So where's this duplicate node? This returns two rows. Seems like there really ought to only be ONE newest, so maybe that's the problem. 

    SELECT TOP 1000 [nodeId]
      ,[published]
      ,[documentUser]
      ,[versionId]
      ,[text]
      ,[releaseDate]
      ,[expireDate]
      ,[updateDate]
      ,[templateId]
      ,[newest]
  FROM [dbo].[cmsDocument]
  where nodeid = 1839 and newest = 1

nodeId  published   documentUser    versionId   text    releaseDate expireDate  updateDate  templateId  newest
1839    1   0   E3DB5458-239B-46C1-865E-35FA28029396    Home    NULL    NULL    2016-02-08 11:06:49.000 1377    1
1839    0   2   442504E2-7395-4D6E-B3F0-5F3FF2F2C921    Home    NULL    NULL    2016-02-08 15:09:15.910 1377    1

    Checking the UmbracoNode table, everything looks good.

    SELECT TOP 1000 [id]
      ,[trashed]
      ,[parentID]
      ,[nodeUser]
      ,[level]
      ,[path]
      ,[sortOrder]
      ,[uniqueID]
      ,[text]
      ,[nodeObjectType]
      ,[createDate]
  FROM [dbo].[umbracoNode]
  where uniqueid = '428c901a-1260-4066-b823-2060fbd91295'

id  trashed parentID    nodeUser    level   path    sortOrder   uniqueID    text    nodeObjectType  createDate
1839    0   1785    0   2   -1,1785,1839    0   428C901A-1260-4066-B823-2060FBD91295    Home    C66BA18E-EAF3-4CFF-8A22-41B16D66A972    2014-09-25 16:52:36.000
    Copy Link
  • Carl Bussema 38 posts 140 karma points
    Feb 08, 2016 @ 19:56
    Carl Bussema
    0

    So this happened again this afternoon.

    SOURCE

    2016-02-08 19:12:06,623 [14] INFO  Umbraco.Courier.Core.TaskManager - [Thread 77] Starting ExtractionTask with id: 037d45c7-081c-4322-ac1b-b0bce5c8edcd
2016-02-08 19:12:06,623 [14] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 77] Running PopulateGraph
2016-02-08 19:12:06,654 [14] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 77] Finished PopulateGraph (took 39ms)
2016-02-08 19:12:06,654 [14] DEBUG Umbraco.Courier.Core.EventManager - [Thread 77] Adding event DeleteContentAndMedia To Queue: DeploymentComplete for session: f808b779-4770-4d58-aac5-de8232c73d3d
2016-02-08 19:12:06,654 [14] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 77] Starting extraction
2016-02-08 19:12:06,654 [14] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 77] Opens database session
2016-02-08 19:12:06,654 [14] DEBUG Umbraco.Courier.RepositoryProviders.CourierWebserviceRepositoryProvider - [Thread 77] Opening session to URL-REMOVED
2016-02-08 19:12:06,670 [14] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 77] Transfering pre-extraction files
2016-02-08 19:12:06,670 [14] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 77] Running ExtractReadyRevisionBatch
2016-02-08 19:12:06,670 [14] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 77] Extracting batch of 1 items
2016-02-08 19:12:06,670 [14] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 77] Extracting: About Us - Umbraco.Courier.Core.DependencyGraph+GraphNode
2016-02-08 19:12:09,596 [14] WARN  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 77] Finished ExtractItem (took 2931ms)
2016-02-08 19:12:09,596 [14] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 77] Extracting batch of 1 items
2016-02-08 19:12:09,596 [14] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 77] Extracting: Document About Us Property Data - Umbraco.Courier.Core.DependencyGraph+GraphNode
2016-02-08 19:12:10,364 [14] WARN  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 77] Finished ExtractItem (took 764ms)
2016-02-08 19:12:10,364 [14] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 77] Finished ExtractReadyRevisionBatch (took 3696ms)
2016-02-08 19:12:10,364 [14] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 77] Completed extraction queue
2016-02-08 19:12:10,380 [14] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 77] Post processing
2016-02-08 19:12:10,380 [14] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 77] Post processing 0 items
2016-02-08 19:12:10,380 [14] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 77] Finished PostProcessing (took 0ms)
2016-02-08 19:12:10,396 [14] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 77] Completed post processing
2016-02-08 19:12:10,396 [14] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 77] Committing to database
2016-02-08 19:12:10,411 [14] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 77] Transfering post-extract resources
2016-02-08 19:12:10,411 [14] INFO  Umbraco.Courier.Core.Extraction.RevisionExtraction - [Thread 77] Completing database transaction
2016-02-08 19:12:20,098 [14] DEBUG Umbraco.Courier.RepositoryProviders.Local - [Thread 77] Disposing: True
2016-02-08 19:12:20,098 [14] WARN  Umbraco.Courier.RepositoryProviders.Local - [Thread 77] Closing session called but there is no session open: f808b779-4770-4d58-aac5-de8232c73d3d
2016-02-08 19:12:20,130 [14] DEBUG Umbraco.Courier.Core.EventManager - [Thread 77] Unloading (count: 1)
2016-02-08 19:12:20,130 [14] ERROR Umbraco.Courier.Core.TaskManager - [Thread 77] Error ExtractionTask with id: 037d45c7-081c-4322-ac1b-b0bce5c8edcd
System.Web.Services.Protocols.SoapException: System.Web.Services.Protocols.SoapException: Server was unable to process request. ---> System.InvalidOperationException: Sequence contains more than one element
   at System.Linq.Enumerable.SingleOrDefault[TSource](IEnumerable`1 source)
   at Umbraco.Core.Services.ContentService.GetById(Guid key)
   at Umbraco.Courier.DataResolvers.ItemEventProviders.PublishDocument.Execute(ItemIdentifier itemId, SerializableDictionary`2 parameters)
   at Umbraco.Courier.Core.EventManager.ExecuteLocalEvent(String eventAlias, ItemIdentifier itemId, Dictionary`2 parameters, ExecutionContext context)
   at Umbraco.Courier.Core.EventManager.ExecuteLocalQueue(String sessionKey, String queueAlias, ExecutionContext context)
   at Umbraco.Courier.RepositoryProviders.Local.ExecuteQueue(String queueItems)
   at Umbraco.Courier.RepositoryProviders.Webservices.Repository.ExecuteQueue(String sessionKey, String queueAlias, String user, String pass)
   --- End of inner exception stack trace ---
   at System.Web.Services.Protocols.SoapHttpClientProtocol.ReadResponse(SoapClientMessage message, WebResponse response, Stream responseStream, Boolean asyncCall)

    What I do notice is that in the Destination log, there's a lot of duplicate lines

    2016-02-08 19:11:33,534 [124] DEBUG Umbraco.Courier.RepositoryProviders.Local - [Thread 165] Opening session: 8548cf39-5c91-4f74-acf7-8991f6959737
2016-02-08 19:11:42,816 [124] WARN  Umbraco.Courier.Core.ResolutionManager - [Thread 165] Finished executing resolver: Document About Us Property Data For provider: PropertyData (took 3314ms)
2016-02-08 19:11:43,944 [124] WARN  Umbraco.Courier.Core.ResolutionManager - [Thread 165] Finished executing resolver: Document About Us Property Data For provider: PropertyData (took 1133ms)
2016-02-08 19:11:44,816 [124] DEBUG Umbraco.Courier.DataResolvers.ItemDataResolvers.MediaPickers - [Thread 79] logging media picker packaging Document us Property Data 
2016-02-08 19:11:44,816 [124] DEBUG Umbraco.Courier.DataResolvers.ItemDataResolvers.MediaPickers - [Thread 79] Adding media picker data from: 1219 
2016-02-08 19:11:44,816 [124] DEBUG Umbraco.Courier.DataResolvers.ItemDataResolvers.MediaPickers - [Thread 79] logging media picker packaging Document us Property Data 
2016-02-08 19:11:44,816 [124] DEBUG Umbraco.Courier.DataResolvers.ItemDataResolvers.MediaPickers - [Thread 79] Adding media picker data from: 1219 
2016-02-08 19:11:47,349 [124] DEBUG Umbraco.Courier.DataResolvers.ItemDataResolvers.MediaPickers - [Thread 73] logging media picker packaging Document Home Property Data 
2016-02-08 19:11:47,349 [124] DEBUG Umbraco.Courier.DataResolvers.ItemDataResolvers.MediaPickers - [Thread 73] Adding media picker data from: 19197,19583,19588,19589 
2016-02-08 19:11:47,380 [124] DEBUG Umbraco.Courier.DataResolvers.ItemDataResolvers.MediaPickers - [Thread 73] logging media picker packaging Document Home Property Data 
2016-02-08 19:11:47,380 [124] DEBUG Umbraco.Courier.DataResolvers.ItemDataResolvers.MediaPickers - [Thread 73] Adding media picker data from: 19197,19583,19588,19589 
2016-02-08 19:11:59,077 [124] WARN  Umbraco.Courier.Core.ResolutionManager - [Thread 165] Finished executing resolver: Document Solo History Property Data For provider: PropertyData (took 3261ms)
2016-02-08 19:12:00,830 [124] DEBUG Umbraco.Courier.DataResolvers.ItemDataResolvers.MediaPickers - [Thread 14] logging media picker packaging Document Dart History Property Data 
2016-02-08 19:12:00,830 [124] DEBUG Umbraco.Courier.DataResolvers.ItemDataResolvers.MediaPickers - [Thread 14] Adding media picker data from: 1283 
2016-02-08 19:12:00,830 [124] DEBUG Umbraco.Courier.DataResolvers.ItemDataResolvers.MediaPickers - [Thread 14] logging media picker packaging Document Dart History Property Data 
2016-02-08 19:12:00,830 [124] DEBUG Umbraco.Courier.DataResolvers.ItemDataResolvers.MediaPickers - [Thread 14] Adding media picker data from: 1283 
2016-02-08 19:12:01,942 [124] DEBUG Umbraco.Courier.RepositoryProviders.Local - [Thread 25] Closing session: 8548cf39-5c91-4f74-acf7-8991f6959737

    It's like Courier is somehow creating a duplicate node instead of synching the changes to the correct node, then getting confused when there are two nodes with the same ID. I asked my user and he said he changed the "About Us" page, synched it, changed a different page, synched it, then went back and changed "About Us" again and that time when it went to deploy changes it triggered the blank white screen error.

    Copy Link
  • Claus Jensen 49 posts 157 karma points hq
    Apr 13, 2016 @ 15:11
    Claus Jensen
    0

    Hi Carl

    What you're seeing is that a content item can end up having two versions both marked as 'newest' in the database (as you also mention). This however just shows up in the code and in logs, looking like the content item being a duplicate even though it is actually just corrupt data causing Courier to think that.

    It is a bug we discovered recently and it is fixed in the next version of Courier (and is already fixed in the latest nightlies).

    I can refer you to this issue on our tracker: http://issues.umbraco.org/issue/COU-307

    Best, Claus

    Copy Link
Please Sign in or register to post replies

Write your reply to:

Draft