PrintJobHandler with Possible Threading Issue

[JDavis]

We use a custom PrintJobHandler to created new requested tasks for specific documents that are being published. This code has worked fine for many years in 2.6, 3.0, and now 4.0. We are currently on 4.0.30302.1072. We will randomly, it seems, get an error in the PrintJobHandler, which will crash Select. Our code catches all the exceptions and we are able to log exceptions before the crash and there are corresponding events logged to EventViewer. We haven't been able to reproduce this during debugging and users will have it crash, go back into Select to perform the exact same steps and it will work. It happens on many different client machines and different orders and documents being printed.

An overview of what we are doing:

// Getting our order from the print job
order = printJob.Properties["Order"] as IOrder;

// Add a new task to the order
dynamic newRequestedTask = order.CreateNew("RequestedTask");
((dynamic)order).Tasks.Add(newRequestedTask);

We then do a few other things such as set properties on the newly created RequestedTask and possibly add a note to the ReqeustedTask. Performing these tasks in some case will cause the following exception to be thrown:

<?xml version="1.0"?>
<ExceptionWrapper xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema">
<stackTrace> at System.Windows.Forms.BindingSource.get_Count()
at System.Windows.Forms.CurrencyManager.get_Count()
at System.Windows.Forms.BindingSource.ParentCurrencyManager_CurrentItemChanged(Object sender, EventArgs e)
at System.EventHandler.Invoke(Object sender, EventArgs e)
at System.Windows.Forms.CurrencyManager.OnCurrentItemChanged(EventArgs e)
at System.Windows.Forms.CurrencyManager.List_ListChanged(Object sender, ListChangedEventArgs e)
at System.ComponentModel.ListChangedEventHandler.Invoke(Object sender, ListChangedEventArgs e)
at System.Windows.Forms.BindingSource.OnListChanged(ListChangedEventArgs e)
at System.Windows.Forms.BindingSource.InnerList_ListChanged(Object sender, ListChangedEventArgs e)
at System.ComponentModel.ListChangedEventHandler.Invoke(Object sender, ListChangedEventArgs e)
at System.Windows.Forms.BindingSource.OnListChanged(ListChangedEventArgs e)
at System.Windows.Forms.BindingSource.InnerList_ListChanged(Object sender, ListChangedEventArgs e)
at SoftPro.EntityModel.ListChangedEventInstance.Fire()
at SoftPro.EntityModel.EntityTransactionContext.<>c__DisplayClass1.<FireEvents>b__0()
at SoftPro.EntityModel.EntitySynchronizationContext.Invoke(Action action)
at SoftPro.EntityModel.EntityTransactionContext.FireEvents()
at SoftPro.EntityModel.EntityTransactionContext.Scope.Dispose()
at SoftPro.EntityModel.EntityExecutionContext.Dispose(Boolean completed)
at SoftPro.EntityModel.EntityExecutionContext.Scope.Dispose()
at SoftPro.EntityModel.Field`1.set_Value(T value)
at RequestedTask.set_Description(String )
at CallSite.Target(Closure , CallSite , Object , String )
at TG.SoftPro.Select.Task.RequestedTask.CreateRequestedTaskForPrintJobTask(IOrder order, PrintJobTask task)</stackTrace>
<Message>BindingSource cannot be its own data source. Do not set the DataSource and DataMember properties to values that refer back to BindingSource.</Message>
<Source>System.Windows.Forms</Source>
<TargetSite>Int32 get_Count()</TargetSite>
</ExceptionWrapper>

And, in Windows EventLog I've seen the following two logged at the same time:

#1
The connection to the server 'http://service-app-softpro.tghawaii.com:8080/' has been broken. Thread was being aborted.

at System.Threading.Thread.SleepInternal(Int32 millisecondsTimeout)
at System.Threading.Thread.Sleep(Int32 millisecondsTimeout)
at SoftPro.Select.Client.SelectServer.RunHeartbeat()

Call Stack:
at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
at System.Environment.get_StackTrace()
at System.Diagnostics.TraceEventCache.get_Callstack()
at SoftPro.Select.LogTraceListener.OnLog(TraceEventCache eventCache, String message, TraceEventType eventType)
at SoftPro.Select.LogTraceListener.TraceEvent(TraceEventCache eventCache, String source, TraceEventType eventType, Int32 id, String format, Object[] args)
at System.Diagnostics.TraceInternal.TraceEvent(TraceEventType eventType, Int32 id, String format, Object[] args)
at SoftPro.Select.Client.SelectServer.RunHeartbeat()
at System.Threading.ThreadHelper.ThreadStart_Context(Object state)
at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
at System.Threading.ThreadHelper.ThreadStart()

#2
System.NullReferenceException: Object reference not set to an instance of an object.
Stack Trace:
at SoftPro.Select.Runtime.GetService(Type serviceType)
at SoftPro.Select.Shell.Package.GetService(Type serviceType)
at SoftPro.Select.Managers.Manager.GetService(Type serviceType)
at SoftPro.Select.Shell.Package.GetService(Type serviceType)
at SoftPro.Select.Shell.Package.GetService[T]()
at SoftPro.Select.Package.SelectServer_ConnectionStateChanged(Object sender, EventArgs e)
at SoftPro.Select.Client.SelectServer.set_ConnectionState(ConnectionState value)
at SoftPro.Select.Client.SelectServer.Dispose()
at System.ComponentModel.Design.ServiceContainer.Dispose(Boolean disposing)
at SoftPro.Select.Runtime.Dispose(Boolean disposing)
at SoftPro.Select.Runtime.System.IDisposable.Dispose()
at SoftPro.Select.Automation.EnvICE.Start()
XML Log:
<ILExceptionData>
<Point module="Select.exe" classFull="SoftPro.Select.Runtime" methodName="GetService" methodSignature="System.Object GetService(System.Type)" methodToken="0x6000aa5" ILOffset="64" />
<Point module="SoftPro.Select.Shell.dll" classFull="SoftPro.Select.Shell.Package" methodName="GetService" methodSignature="System.Object GetService(System.Type)" methodToken="0x6000850" ILOffset="16" />
<Point module="Select.exe" classFull="SoftPro.Select.Managers.Manager" methodName="GetService" methodSignature="System.Object GetService(System.Type)" methodToken="0x6000376" ILOffset="16" />
<Point module="SoftPro.Select.Shell.dll" classFull="SoftPro.Select.Shell.Package" methodName="GetService" methodSignature="System.Object GetService(System.Type)" methodToken="0x6000850" ILOffset="16" />
<Point module="SoftPro.Select.Shell.dll" classFull="SoftPro.Select.Shell.Package" methodName="GetService" methodSignature="T GetService[T]()" methodToken="0x6000843" ILOffset="0" />
<Point module="SoftPro.Select.dll" classFull="SoftPro.Select.Package" methodName="SelectServer_ConnectionStateChanged" methodSignature="Void SelectServer_ConnectionStateChanged(System.Object, System.EventArgs)" methodToken="0x6000269" ILOffset="13" />
<Point module="SoftPro.Select.Client.dll" classFull="SoftPro.Select.Client.SelectServer" methodName="set_ConnectionState" methodSignature="Void set_ConnectionState(SoftPro.Select.Client.ConnectionState)" methodToken="0x6002db9" ILOffset="24" />
<Point module="SoftPro.Select.Client.dll" classFull="SoftPro.Select.Client.SelectServer" methodName="Dispose" methodSignature="Void Dispose()" methodToken="0x6002dd0" ILOffset="162" />
<Point module="System.dll" classFull="System.ComponentModel.Design.ServiceContainer" methodName="Dispose" methodSignature="Void Dispose(Boolean)" methodToken="0x60037a9" ILOffset="50" />
<Point module="Select.exe" classFull="SoftPro.Select.Runtime" methodName="Dispose" methodSignature="Void Dispose(Boolean)" methodToken="0x6000aa7" ILOffset="17" />
<Point module="Select.exe" classFull="SoftPro.Select.Runtime" methodName="System.IDisposable.Dispose" methodSignature="Void System.IDisposable.Dispose()" methodToken="0x6000aa6" ILOffset="0" />
<Point module="Select.exe" classFull="SoftPro.Select.Automation.EnvICE" methodName="Start" methodSignature="Void Start()" methodToken="0x6000631" ILOffset="277" />
</ILExceptionData>


Call Stack:
at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
at System.Environment.get_StackTrace()
at System.Diagnostics.TraceEventCache.get_Callstack()
at SoftPro.Select.LogTraceListener.OnLog(TraceEventCache eventCache, String message, TraceEventType eventType)
at SoftPro.Select.LogTraceListener.TraceEvent(TraceEventCache eventCache, String source, TraceEventType eventType, Int32 id, String message)
at System.Diagnostics.TraceInternal.TraceEvent(TraceEventType eventType, Int32 id, String format, Object[] args)
at SoftPro.Select.Automation.EnvICE.Start()
at System.Runtime.Remoting.Messaging.Message.Dispatch(Object target)
at System.Runtime.Remoting.Messaging.StackBuilderSink.SyncProcessMessage(IMessage msg)
at System.Runtime.Remoting.Messaging.ServerObjectTerminatorSink.SyncProcessMessage(IMessage reqMsg)
at SoftPro.Select.Shell.SynchronizationContextAspect.SyncProcessMessage(IMessage msg)
at System.Runtime.Remoting.Lifetime.LeaseSink.SyncProcessMessage(IMessage msg)
at System.Runtime.Remoting.Messaging.ServerContextTerminatorSink.SyncProcessMessage(IMessage reqMsg)
at System.Runtime.Remoting.Channels.CrossContextChannel.SyncProcessMessageCallback(Object[] args)
at System.Threading.Thread.CompleteCrossContextCallback(InternalCrossContextDelegate ftnToCall, Object[] args)
at System.Threading.Thread.InternalCrossContextCallback(Context ctx, IntPtr ctxID, Int32 appDomainID, InternalCrossContextDelegate ftnToCall, Object[] args)
at System.Runtime.Remoting.Channels.CrossContextChannel.SyncProcessMessage(IMessage reqMsg)
at System.Runtime.Remoting.Proxies.RemotingProxy.CallProcessMessage(IMessageSink ms, IMessage reqMsg, ArrayWithSize proxySinks, Thread currentThread, Context currentContext, Boolean bSkippingContextChain)
at System.Runtime.Remoting.Proxies.RemotingProxy.InternalInvoke(IMethodCallMessage reqMcmMsg, Boolean useDispatchMessage, Int32 callType)
at System.Runtime.Remoting.Proxies.RemotingProxy.Invoke(IMessage reqMsg)
at System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type)
at SoftPro.Select.Automation.EnvICE.Start()
at SoftPro.Select.Automation.EnvICE.Run(String rootSuffix, Boolean noSplash, Boolean setupMode, Boolean log, Boolean embedding, Boolean allowMultipleInstances, Boolean detectLeaks, Dictionary`2 args, String freeArg)
at SoftPro.Select.Program.Main(String[] args)

The only thing I can guess what is happening is that because we are modifying the RequestedTask list on the order, and it happens to be data bound to something, it is causing this exception - but intermittently, and not reproducible when debugging. Does the PrintJobHanlder run on the main thread, or does it run on a background thread?

[JDavis]

Also have seen some other exceptions logged such as:

<?xml version="1.0"?>
<ExceptionWrapper xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema">
<stackTrace> at System.Windows.Forms.CurrencyManager.FindGoodRow()
at System.Windows.Forms.CurrencyManager.CurrencyManager_PushData()
at System.Windows.Forms.CurrencyManager.OnItemChanged(ItemChangedEventArgs e)
at System.Windows.Forms.CurrencyManager.UpdateIsBinding(Boolean raiseItemChangedEvent)
at System.Windows.Forms.CurrencyManager.UpdateIsBinding()
at System.Windows.Forms.CurrencyManager.SuspendBinding()
at System.Windows.Forms.CurrencyManager.FindGoodRow()
at System.Windows.Forms.CurrencyManager.CurrencyManager_PushData()
at System.Windows.Forms.CurrencyManager.OnItemChanged(ItemChangedEventArgs e)
at System.Windows.Forms.CurrencyManager.List_ListChanged(Object sender, ListChangedEventArgs e)
at System.ComponentModel.ListChangedEventHandler.Invoke(Object sender, ListChangedEventArgs e)
at System.Windows.Forms.BindingSource.OnListChanged(ListChangedEventArgs e)
at System.Windows.Forms.BindingSource.InnerList_ListChanged(Object sender, ListChangedEventArgs e)
at System.ComponentModel.ListChangedEventHandler.Invoke(Object sender, ListChangedEventArgs e)
at System.Windows.Forms.BindingSource.OnListChanged(ListChangedEventArgs e)
at System.Windows.Forms.BindingSource.InnerList_ListChanged(Object sender, ListChangedEventArgs e)
at SoftPro.EntityModel.ListChangedEventInstance.Fire()
at SoftPro.EntityModel.EntityTransactionContext.<>c__DisplayClass1.<FireEvents>b__0()
at SoftPro.EntityModel.EntitySynchronizationContext.Invoke(Action action)
at SoftPro.EntityModel.EntityTransactionContext.FireEvents()
at SoftPro.EntityModel.EntityTransactionContext.Scope.Dispose()
at SoftPro.EntityModel.EntityExecutionContext.Dispose(Boolean completed)
at SoftPro.EntityModel.EntityExecutionContext.Scope.Dispose()
at SoftPro.EntityModel.Field`1.set_Value(T value)
at RequestedTask.set_Description(String )
at CallSite.Target(Closure , CallSite , Object , String )
at TG.SoftPro.Select.Task.RequestedTask.CreateRequestedTaskForPrintJobTask(IOrder order, PrintJobTask task)</stackTrace>
<Message>DataBinding cannot find a row in the list that is suitable for all bindings.</Message>
<Source>System.Windows.Forms</Source>
<TargetSite>Void FindGoodRow()</TargetSite>
</ExceptionWrapper>

and

<?xml version="1.0"?>
<ExceptionWrapper xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema">
<stackTrace> at SoftPro.EntityModel.Collections.EntityCollection`2.ValidateAdd(T item)
at SoftPro.EntityModel.Collections.EntityCollection`2.InsertItem(Int32 index, T item)
at SoftPro.EntityModel.Collections.SnapshotCollection`1.Add(T item)
at CallSite.Target(Closure , CallSite , Object , Object )
at System.Dynamic.UpdateDelegates.UpdateAndExecuteVoid2[T0,T1](CallSite site, T0 arg0, T1 arg1)
at TG.SoftPro.Select.Task.RequestedTask.CreateRequestedTaskForPrintJobTask(IOrder order, PrintJobTask task)</stackTrace>
<Message>Cannot access member.</Message>
<Source>SoftPro.EntityModel</Source>
<TargetSite>Void ValidateAdd(T)</TargetSite>
</ExceptionWrapper>

[BobRichards]

Please submit a representative block of code and it's stack trace so we can look into the problem. Thanks.

[JDavis]

This is the method that is called in our PrintJobHandler. PrintJobTask is one of our objects to set up the defaults on the Order.RequestedTask. All exceptions shown above are what we have logged.

Code: Select all

public static Guid CreateRequestedTaskForPrintJobTask(IOrder order, PrintJobTask task)
        {
            Guid taskId = Guid.Empty;
            
            try
            {
                dynamic newRequestedTask = order.CreateNew("RequestedTask");
                ((dynamic)order).Tasks.Add(newRequestedTask);

                if (newRequestedTask != null)
                {
                    newRequestedTask.Description = task.TaskDescription;

                    switch (task.Status)
                    {
                        case "Required":
                            newRequestedTask.Status = SPOrders.TaskStatusType.Required;
                            break;
                        case "Received":
                            newRequestedTask.Status = SPOrders.TaskStatusType.Received;
                            break;
                        case "Requested":
                            newRequestedTask.Status = SPOrders.TaskStatusType.Required;
                            break;
                        case "Completed":
                            newRequestedTask.Status = SPOrders.TaskStatusType.Completed;
                            break;
                        default:
                            newRequestedTask.Status = SPOrders.TaskStatusType.None;
                            break;
                    }

                    DateTime requestedDate = DateTime.Today.AddDays(task.Days);
                    newRequestedTask.RequestDueDate = requestedDate;
                    newRequestedTask.Occurs = task.PostClosing == true ? TaskOccurs.PostClosing : TaskOccurs.PreClosing;

                    string taskNote = task.TaskNote ?? string.Empty;
                    if (taskNote.Length > 0)
                    {
                        dynamic checklistTaskNote = order.CreateNew("Note");
                        checklistTaskNote.IncludeInGeneralOrderNotes = false;
                        newRequestedTask.Notes.Add(checklistTaskNote);

                        if (checklistTaskNote != null)
                        {
                            checklistTaskNote.Text = task.TaskNote;
                        }
                    }

                    newRequestedTask.AssignedTo = null;
                    taskId = newRequestedTask.Guid;
                }
            }
            catch (Exception ex)
            {
                LoggingClient.LogEvent(EventTypes.Error, "SoftPro", String.Format("Order {0} : {1}", order["Number"] ?? string.Empty, ex.Message), String.Format("{0} - {1}", "TG.SoftPro.PrintProcessor.PrintJobTaskProcessor", "CreateRequestedTask"), ex);
            }

            return taskId;
        }

[John Morris]

Can you verify that you're not manipulating the order from a background thread? Since the order is data-bound to the UI main thread, any changes made to it will probably cause GUI changes. If the order is being modified from a thread other than the main GUI thread, this can cause issues.

I would recommend logging the thread ID of the main thread as well as the thread id of the thread you're print handler is on. If they are different, then that is most likely the root cause.

Modifying the order from a print pipeline handler isn't something we've designed the system to handle, so your mileage may vary.

[JDavis]

We simply call that method from the PrintJobHandler.OnProcess method, passing in the IOrder that is on the IPrintJob. We do not start up any new threads - does Select itself start up the PrintJobHandlers on separate threads?

[JDavis]

And I guess my next question would be, if it is indeed on another thread, how can we make the change to the order back on the UI context if it is not being passed into the PrintJobHanlder?

[John Morris]

Yes, Select uses background threads during the printing process.

You could try doing your task work in a method invoked via a IShell::BeginInvoke call.

During your print pipeline handler, you would IShell::BeginInvoke() passing a delegate to your method that can add the task data. That places the method call into the GUI message pump queue for executing as soon as the GUI thread is freed up, but won't block your print pipeline from moving forward. If it did, that would be a GUI deadlock.

[JDavis]

Thanks, I'll give that a try, I knew BeginInvoke was needed, but didn't know on what object to get it from.

[JDavis]

We used the following in our print job handler to call the method that adds requested tasks to the order. We are still getting the same kinds of errors. Was this the method that you suggested John?

Code: Select all

GetService<IShell>().BeginInvoke((MethodInvoker)delegate
                                {
                                    CreateOrderTask(order, itemToPrint);
                                }, null);