PublishTransaction save event not recording all publish states

Question

We are implementing an Event System to record the publish transaction information to a log file and a custom database. When a single page is published all the states it goes through are being captured in the log file; however, when multiple pages are published not all transactions are being captured.

We are subscribing to the PublishTransaction event.

EventSystem.Subscribe<PublishTransaction, SaveEventArgs>(HandleForPublishTransactionSaved, EventPhases.TransactionCommitted);

The event handler captures the transaction details and logs that to a file.

public void HandleForPublishTransactionSaved(PublishTransaction transaction, SaveEventArgs args, EventPhases phase)
{    
      foreach (IdentifiableObject id in transaction.Items)
      {
           // publishTransaction = transaction.Title + transaction.State.ToString() + ..

           if (!File.Exists(filePath))
           {
                 using (StreamWriter sw = File.CreateText(filePath))
                 {
                      sw.WriteLine(publishTransaction.ToString());
                 }
           }

           using (StreamWriter sw = File.AppendText(filePath))
           {
                 sw.WriteLine(publishTransaction.ToString());
           }
      }
 }

The log file when a single page is published:

tcm:0-3582408-66560, Page title, tcm:194-35857-64, WaitingForPublish, 7/18/2017 11:00:12 PM
tcm:0-3582408-66560, Page title, tcm:194-35857-64, InProgress, 7/18/2017 11:00:14 PM
tcm:0-3582408-66560, Page title, tcm:194-35857-64, Resolving, 7/18/2017 11:00:14 PM
tcm:0-3582408-66560, Page title, tcm:194-35857-64, Rendering, 7/18/2017 11:00:14 PM
tcm:0-3582408-66560, Page title, tcm:194-35857-64, Failed, 7/18/2017 11:00:34 PM
tcm:0-3582408-66560, Page title, tcm:194-35857-64, Failed, 7/18/2017 11:00:34 PM

When more than one page are published the logs were not consistent. Several states didn't get recorded for one or more pages. We also tried to log just to the Event Viewer and the results were similar. Tried adding locks to the event handler and that didn't help either.

Is there a way I could prevent this random behavior? Any help would be greatly appreciated!

Answer 1

I think Raimond's comment is spot on, when creating an event handler, you have to be aware that this can be called by multiple threads and simply trying to write to a file without proper locking will cause issues.

Why not use the event log to ensure you won't have threading issues?

See https://github.com/bkoopman/sdl-tridion-world/blob/master/ECL%20Stub%20Component%20Event%20Handler/trunk/ECL%20Stub%20Component%20Event%20Handler/EventHandler.cs for an example of how to use the Tridion.Logging.Logger class. I'll post some snippets of the event handler here as an example:

...
using Tridion.ContentManager.Extensibility;
using Tridion.ContentManager.Extensibility.Events;
using Tridion.Logging;

namespace Example
{
    [TcmExtension("ExampleEventHandlerExtension")]
    public class EventHandler : TcmExtension
    {
        public EventHandler()
        {
            EventSystem.Subscribe<PublishTransaction, SaveEventArgs>(HandleForPublishTransactionSaved, EventPhases.TransactionCommitted);
        }

        public static void HandleForPublishTransactionSaved(PublishTransaction subject, SaveEventArgs args, EventPhases phase)
        {
            string message = string.Format("Publish Transaction URI: {0}, Number of items {1}", subject.Id, subject.Items.Count());
            Logger.Write(message, "ExampleEventHandlerExtension", LoggingCategory.General, TraceEventType.Information);
        }
    }
}

Answer 2

We were able to narrow down the issue to the fact that not all publishing happens in a single server. The templating logs that normally gets logged in Event Viewer when a single page is published is not happening when more than one page is published. The load balancers were the reason for this issue and we had to deploy the Event System on all servers.