4

Good Morning.

I was been working in a "Workflow/Event System" Component few month ago and it was working as it should. this week i deployed everything to a new box and I start getting an estrange behavior.

So, let me give You some context, the specific code in the event system I've been taking about is waiting for the success publication of the content. It should Get all activities in the workflow that were suspended (the activity is suspended while the publication process is taking place) using an specific ResumeBookmark ('Wait until publication completed').

UPDATE: 07/22/14 it turns out to be a logging problem when using Log4Net (see Answer)

By the way, I am using Tridion 2013 GA.

Event Subscription :

enter image description here

Execution (only executes for WaitingForPublish event):

private void PublishOnTransactionSaveFinished(PublishTransaction publishTransaction, SaveEventArgs args, EventPhases phase)

It is weird because two days ago it was working fine in my local box, all events were being Caught. here some of them

2014-07-15 20:52:05,087 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - WaitingForDeployment
2014-07-15 20:52:07,882 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - Deploying
2014-07-15 20:52:14,673 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - CommittingDeployment
2014-07-15 20:52:19,868 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - Success
2014-07-15 20:53:30,571 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - InProgress
2014-07-15 20:53:33,111 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - Resolving
2014-07-15 20:53:39,891 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - Rendering
2014-07-15 20:53:50,336 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - Rendering
2014-07-15 20:53:50,384 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - ReadyForTransport
2014-07-15 20:53:50,624 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - ReadyForTransport
2014-07-15 20:53:52,117 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - WaitingForDeployment
2014-07-15 20:53:56,036 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - Deploying
2014-07-15 20:53:59,813 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - CommittingDeployment
2014-07-15 20:54:00,279 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - CommittingDeployment
2014-07-15 20:54:05,193 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - Success
2014-07-15 20:55:22,659 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - Undoing
2014-07-15 20:55:24,630 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - Undoing
2014-07-15 20:55:24,910 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - Undoing
2014-07-15 20:55:32,699 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - Undoing
2014-07-15 20:55:36,586 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - Undoing
2014-07-15 20:55:41,778 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - Undoing
2014-07-15 20:55:46,556 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - Undone

This is the log i am getting now, even in my local box :

2014-07-17 06:53:25,580 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - 
2014-07-17 06:53:25,708 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - -----------------------------------------------------------
2014-07-17 07:47:24,455 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - WaitingForPublish
2014-07-17 07:50:25,701 DEBUG Project.Workflow.EventSystem.EventsManager T2013RC1 - WaitingForPublish

I already read a question that is very similar to mine :

Tridion published Item state not returning properly in Event System

I restarted everything but no luck so far.

Thank You!.

Improve this question
1
  • That's very odd. Are you sure this is the only publisher on this environment? Maybe another machine is picking up the work?
    – Nuno Linhares ♦
    Commented Jul 17, 2014 at 14:19

1 Answer 1

Reset to default
5

After doing some research, and with Eric Huiza's help, we realized it was a logging problem when using Log4Net in a Event System / Workflow Context.

so, The problem was that there was more than 1 process trying to write the logs. When the workflow started the publication procedure, it was the TcmServiceHost the one that acually started the publication (WaitingForPublish event), so the TcmServiceHost took ownership of the log file and locked it, so any other can write in this file.

After the publication was started, there was another process that got into the scene, it was the TcmPublisher itself. it was the responsible of complete the publication procedure (execute the others publication phases).

Here is the log after solving the problem :

2014-07-18 06:05:33,601 DEBUG Project.Workflow.ES.EventsMgr TRAIN1 - -----------------------------------------------------------
2014-07-18 06:08:55,392 DEBUG Project.Workflow.ES.EventsMgr TRAIN1 - [TcmServiceHost : NT AUTHORITY\NETWORK SERVICE] ::: asp.net.Draft : WaitingForPublish
2014-07-18 06:08:57,670 DEBUG Project.Workflow.ES.EventsMgr TRAIN1 - -----------------------------------------------------------
2014-07-18 06:08:58,147 DEBUG Project.Workflow.ES.EventsMgr TRAIN1 - [TcmPublisher : NT AUTHORITY\SYSTEM] ::: asp.net.Draft : InProgress
2014-07-18 06:08:58,389 DEBUG Project.Workflow.ES.EventsMgr TRAIN1 - [TcmPublisher : NT AUTHORITY\SYSTEM] ::: asp.net.Draft : Resolving
2014-07-18 06:08:58,709 DEBUG Project.Workflow.ES.EventsMgr TRAIN1 - [TcmPublisher : NT AUTHORITY\SYSTEM] ::: asp.net.Draft : Rendering
2014-07-18 06:09:00,910 DEBUG Project.Workflow.ES.EventsMgr TRAIN1 - [TcmPublisher : NT AUTHORITY\SYSTEM] ::: asp.net.Draft : Rendering
2014-07-18 06:09:00,915 DEBUG Project.Workflow.ES.EventsMgr TRAIN1 - [TcmPublisher : NT AUTHORITY\SYSTEM] ::: asp.net.Draft : ReadyForTransport
2014-07-18 06:09:00,981 DEBUG Project.Workflow.ES.EventsMgr TRAIN1 - [TcmPublisher : NT AUTHORITY\SYSTEM] ::: asp.net.Draft : ReadyForTransport
2014-07-18 06:09:01,636 DEBUG Project.Workflow.ES.EventsMgr TRAIN1 - [TcmPublisher : NT AUTHORITY\SYSTEM] ::: asp.net.Draft : WaitingForDeployment
2014-07-18 06:09:03,756 DEBUG Project.Workflow.ES.EventsMgr TRAIN1 - [TcmPublisher : NT AUTHORITY\SYSTEM] ::: asp.net.Draft : Deploying
2014-07-18 06:09:08,816 DEBUG Project.Workflow.ES.EventsMgr TRAIN1 - [TcmPublisher : NT AUTHORITY\SYSTEM] ::: asp.net.Draft : CommittingDeployment
2014-07-18 06:09:15,962 DEBUG Project.Workflow.ES.EventsMgr TRAIN1 - [TcmPublisher : NT AUTHORITY\SYSTEM] ::: asp.net.Draft : Success

When TcmPublisher was trying to write the logs in the same file, log4Net didn't allow it, because TcmServiceHost had already locked the log fie, and it was due to the locking model of the appender. The default value is exclusiveLock, so we need to change it to the MinimalLock, We achive it using this line :

<lockingModel type="log4net.Appender.FileAppender+MinimalLock" />

Here is an example

  <log4net debug="true">
    <appender name="RollingLogFileAppender" type="log4net.Appender.RollingFileAppender">
      <file value="D:\Logs\EventSystem\workflow.eventSystem.txt" />
      <datePattern value="MM.dd.yyyy'_'HH'.txt'" />
      <staticLogFileName value="false" />
      <appendToFile value="true" />
      <rollingStyle value="Size" />
      <maxSizeRollBackups value="10" />
      <maximumFileSize value="2MB" />
      <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date %-5level %logger ${COMPUTERNAME} - %message%newline" />
      </layout>
    </appender>
    <root>
      <level value="DEBUG" />
      <appender-ref ref="RollingLogFileAppender" />
    </root>
  </log4net>

It took this information from this article

Thank You.

Improve this answer

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.