Unhandled exception while building documentation

Topics: Bugs
Apr 21, 2009 at 1:56 PM
System:
Windows XP SP3, Visual Studio 2008 SP1, Sandcastle May 2008, DocProject 1.11.0RC, SandastleStyles May 2008 Patch Rev 2.
Building the documentation from Visual Studio works, but the same from command line, msbuild solution_file.sln yields to unhandled exception:
Unhandled Exception:
Unhandled Exception: System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> System.InvalidOperationException: A call is made on an inactive IBuildEngine interface corresponding to a task that already finished execution.
at Microsoft.Build.Shared.ErrorUtilities.ThrowInvalidOperation(String resourceName, Object[] args)
at Microsoft.Build.BuildEngine.EngineProxy.LogMessageEvent(BuildMessageEventArgs e)
at Microsoft.Build.Utilities.TaskLoggingHelper.LogMessage(MessageImportance importance, String message, Object[] messageArgs)
at Microsoft.Build.Utilities.TaskLoggingHelper.LogMessage(String message, Object[] messageArgs)
at DaveSexton.DocProject.MSBuild.MSBuildTrace.TraceLine(String message)
at DaveSexton.DocProject.BuildContext.<>c__DisplayClass13.<TraceLine>b__12()
--- End of inner exception stack trace ---
at System.RuntimeMethodHandle._InvokeMethodFast(Object target, Object[] arguments, SignatureStruct& sig, MethodAttributes methodAttributes, RuntimeTypeHandle typeOwner)
at System.RuntimeMethodHandle.InvokeMethodFast(Object target, Object[] arguments, Signature sig, MethodAttributes methodAttributes, RuntimeTypeHandle typeOwner)
at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture, Boolean skipVisibilityChecks)
at System.Delegate.DynamicInvokeImpl(Object[] args)
at DaveSexton.DocProject.BuildContext.<>c__DisplayClass2.<InvokeInternal>b__0(Object state)
at System.Threading._ThreadPoolWaitCallback.WaitCallback_Context(Object state)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
at System.Threading._ThreadPoolWaitCallback.PerformWaitCallbackInternal(_ThreadPoolWaitCallback tpWaitCallBack)
at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback(Object state)

Nothing more in Event Viewer. If there is anything else that I can provide let me know.
- Bolek
Coordinator
Apr 23, 2009 at 7:59 AM
Hi Bolek,

It looks like perhaps the TraceLine method is being invoked asynchronously, after the MSBuild process has already completed.

Is the problem reproducible?  If so, could you repro in a small test project and send it to me?  You can contact me here and I'll respond with my direct email address.

One thing you might want to try is to unregister the project's build process component (BPC) just to rule it out as the cause of the issue.  To do that, open the DocProject Properties window for the project and set the Extensibility | Process component type name field to nothing (empty).  Next time you build if you don't see any timestamps between build steps in the trace output then you know the BPC is no longer in use.

- Dave
Apr 23, 2009 at 12:06 PM
               Hi Dave,
    Setting Extensibility | Process component type name field to nothing (empty) didn't help, ie. I still got the exception. Problem is reproductible (at least on my machine) - invoking msbuild on solution file yields to exception, every say second time, which could indicate some problems with asynchronous invokations.
   If there is anything else that I can do, let me know.
          Bolek.
Coordinator
May 9, 2009 at 6:28 AM

Hi Bolek,

Sorry for the delay in responding.  Are you still experiencing this problem?

If so, you could update DocProject's code by catching TargetInvocationException in the MSBuildTrace class's TraceLine method and see if that helps.  You could also try attaching a debugger first to see the source of the error - there might be another way to work around it without having to rebuild the code.

How to Use The Source Code

http://docproject.codeplex.com/Wiki/View.aspx?title=How%20To%20Use%20The%20Source%20Code

- Dave

May 20, 2009 at 10:18 AM

Hi Dave,

Took me some time, since I was busy with different things. Anyway, aforementioned exception is thrown in BuildContext.cs:465, in

                SendOrPostCallback callback = delegate(object state)
                {
                    returnValue = target.DynamicInvoke(arguments);
                };

with message System.InvalidOperationException: A call is made on an inactive IBuildEngine interface corresponding to a task that already finished execution

I'm not sure how to debug it exactly, or what to provide to more.

Regards,

Bolek.

Coordinator
Jun 9, 2009 at 4:48 PM

Hi Bolek,

I couldn't repro, although I didn't try too hard to be honest because I've been so busy on other stuff as well :)

It seems like you've found a concurrency issue.  My only suggestion is to wrap the callback in a try/catch block for now to see if that solves your problem, until I can fix the issue for the next version of DocProject.  For example:

 

- Dave

SendOrPostCallback callback = delegate(object state)
{
  try
  {
    returnValue = target.DynamicInvoke(arguments);
  }
  catch (InvalidOperationException)
  {
    // do nothing
  }
};
Jul 9, 2009 at 8:39 PM

I was having the same issue after integrating Sandcastle/DocProjects into our nightly build via MSBuild script.  Turned out the answer was right in the stack trace.  There are a bunch of Trace methods in the BuildContext.cs file, which do nothing but make an invoke to a member BuildTrace object.  That appears to be anonymous delegate from the stack trace of the OP, and what I was seeing in the build logs.  I wrapped the code inside the anonymous delegates of all the various Trace* methods in BuildContext, and that seems to have done the trick.

Coordinator
Jul 10, 2009 at 3:13 AM

Hi,

Thanks for the feedback.

Could you please be more specific about what changes you made to solve the problem?  I'm not sure what you mean by "I wrapped the code inside the anonymous delegates" and whether it was a thread-safety issue or something else, since I can't reproduce the error.

Thanks,
Dave

Jul 10, 2009 at 4:13 PM
Edited Jul 10, 2009 at 4:21 PM

Sorry for the vagueness.   I wrapped the code inside anonymous methods in a try catch block for each of the Trace* methods in BuildContext.cs, just as you had suggested for the SendOrPostCallback declaration above.  On our build server we have multiple DocSite projects being kicked off in sequence by an msbuild script.  Somewhere around the end of the first DocSite build being completed and the next starting, the exception occurs.  I can only guess that the trace call attempts are from the first run, but I never was able to attach a debugger.  If the exception was thrown from a exiting process, that might explain not being able to attach to it.

Here's a log off of our build server, toward the end of the first DocSite compilation.

2009-07-08 15:32:06,960 [Project - Server Sandcastle:DEBUG]   Step 10 of 12: Execute ChmBuilder
2009-07-08 15:32:06,960 [Project - Server Sandcastle:DEBUG]  
2009-07-08 15:32:06,960 [Project - Server Sandcastle:DEBUG]   C:\Program Files\Sandcastle\ProductionTools\ChmBuilder /html:"C:\ClearCase_Views\Project\Project_src\DocSites\Dept\buildhelp\assembler\Output\html"

/toc:"C:\ClearCase_Views\Project\Project_src\DocSites\Dept\buildhelp\toc.xml" /project:"Dept" /lcid:1033 /metadata+ /out:Help\

/config:"C:\ClearCase_Views\Project\Project_src\DocSites\Dept\Help\Settings\Projects\help1x.config"
2009-07-08 15:32:06,960 [Project - Server Sandcastle:DEBUG]  
2009-07-08 15:32:08,757 [Project - Server Sandcastle:DEBUG]   ChmBuilder (v2.4.10520.1)
2009-07-08 15:32:08,757 [Project - Server Sandcastle:DEBUG]   Copyright c MS 2007
2009-07-08 15:42:03,539 [Project - Server Sandcastle:DEBUG]   Processed 16703 files.
2009-07-08 15:42:05,367 [Project - Server Sandcastle:DEBUG]  
2009-07-08 15:42:05,367 [Project - Server Sandcastle:DEBUG]   Step 10 Time Elapsed: 00:09:58.4062500
2009-07-08 15:42:05,367 [Project - Server Sandcastle:DEBUG]  
2009-07-08 15:42:05,367 [Project - Server Sandcastle:DEBUG]   Step 11 of 12: Execute DBCSFix
2009-07-08 15:42:05,476 [Project - Server Sandcastle:DEBUG]  
2009-07-08 15:42:05,476 [Project - Server Sandcastle:DEBUG]   C:\Program Files\Sandcastle\ProductionTools\DBCSFix /d:"Help\Html" /l:1033
2009-07-08 15:42:05,492 [Project - Server Sandcastle:DEBUG]  
2009-07-08 15:42:05,929 [Project - Server Sandcastle:DEBUG]   DBCSFix (v2.4.10520.1)
2009-07-08 15:42:05,929 [Project - Server Sandcastle:DEBUG]   Copyright c  2007
2009-07-08 15:42:05,929 [Project - Server Sandcastle:DEBUG]   Converting unsupported high-order characters to 7-bit ASCII equivalents.
2009-07-08 15:42:05,976 [Project - Server Sandcastle:DEBUG]   EncodingName: Windows-1252
2009-07-08 15:42:06,195 [Project - Server Sandcastle:DEBUG]  
2009-07-08 15:42:06,195 [Project - Server Sandcastle:DEBUG]   Step 11 Time Elapsed: 00:00:00.8281250
2009-07-08 15:42:06,195 [Project - Server Sandcastle:DEBUG]  
2009-07-08 15:42:06,195 [Project - Server Sandcastle:DEBUG]   Step 12 of 12: Compile Help 1.x
2009-07-08 15:42:06,195 [Project - Server Sandcastle:DEBUG]  
2009-07-08 15:42:06,195 [Project - Server Sandcastle:DEBUG]   C:\Program Files\Html Help Workshop\hhc.exe "C:\ClearCase_Views\Project\Project_src\DocSites\Dept\Help\Dept.hhp"
2009-07-08 15:42:06,195 [Project - Server Sandcastle:DEBUG]  
2009-07-08 15:48:09,507 [Project - Server Sandcastle:DEBUG]   Microsoft HTML Help Compiler 4.74.8702
2009-07-08 15:48:09,507 [Project - Server Sandcastle:DEBUG]   Compiling c:\ClearCase_Views\Project\Project_src\DocSites\Dept\Help\Dept.chm
2009-07-08 15:48:09,507 [Project - Server Sandcastle:DEBUG]   HHC4003: Warning: The following option line does not contain an '=' character separating the option and its value: n++[OPTIONS].
2009-07-08 15:48:09,507 [Project - Server Sandcastle:DEBUG]   Compile time: 6 minutes, 1 second
2009-07-08 15:48:09,523 [Project - Server Sandcastle:DEBUG]   16,703 Topics
2009-07-08 15:48:09,523 [Project - Server Sandcastle:DEBUG]   157,806 Local links
2009-07-08 15:48:09,523 [Project - Server Sandcastle:DEBUG]   114,560 Internet links
2009-07-08 15:48:09,523 [Project - Server Sandcastle:DEBUG]   0 Graphics
2009-07-08 15:48:09,523 [Project - Server Sandcastle:DEBUG]   Created c:\ClearCase_Views\Project\Project_src\DocSites\Dept\Help\Dept.chm, 20,506,334 bytes
2009-07-08 15:48:09,523 [Project - Server Sandcastle:DEBUG]   Compression decreased file by 182,177,338 bytes.
2009-07-08 15:48:09,648 [Project - Server Sandcastle:DEBUG]  
2009-07-08 15:48:09,648 [Project - Server Sandcastle:DEBUG]   Step 12 Time Elapsed: 00:06:03.4531250
2009-07-08 15:48:09,648 [Project - Server Sandcastle:DEBUG]  
2009-07-08 15:48:09,648 [Project - Server Sandcastle:DEBUG]   Build step execution complete.
2009-07-08 15:48:09,648 [Project - Server Sandcastle:DEBUG]  
2009-07-08 15:48:09,648 [Project - Server Sandcastle:DEBUG]   Building DocSite files...
2009-07-08 15:48:09,679 [Project - Server Sandcastle:DEBUG]  
2009-07-08 15:48:09,867 [Project - Server Sandcastle:DEBUG]   Creating DocSite TOC: C:\ClearCase_Views\Project\Project_src\DocSites\Dept\App_Data\DocSiteContents.xml
2009-07-08 15:48:13,429 [Project - Server Sandcastle:DEBUG]   Creating DocSite index: C:\ClearCase_Views\Project\Project_src\DocSites\Dept\App_Data\DocSiteIndex.xml
2009-07-08 15:48:13,492 [Project - Server Sandcastle:DEBUG]  
2009-07-08 15:48:13,492 [Project - Server Sandcastle:DEBUG]   Verifying output...
2009-07-08 15:48:13,492 [Project - Server Sandcastle:DEBUG]   Done.
2009-07-08 15:48:13,507 [Project - Server Sandcastle:DEBUG]  
2009-07-08 15:48:13,507 [Project - Server Sandcastle:DEBUG]   Total Time Elapsed: 00:38:02.9375000
2009-07-08 15:48:13,507 [Project - Server Sandcastle:DEBUG] Done Building Project "C:\ClearCase_Views\Project\Project_src\DocSites\Dept\Dept.csproj" (default targets).
2009-07-08 15:48:13,539 [Project - Server Sandcastle:DEBUG] Project "C:\ClearCase_Views\Project\Project_build\BuildScripts\DocSites\MakeDocSites.proj" (1) is building

"C:\ClearCase_Views\Project\Project_src\DocSites\Dept.Project.Database\Dept.Project.Database.csproj" (3:2) on node 0 (default targets).
2009-07-08 15:48:13,539 [Project - Server Sandcastle:DEBUG]   Processing 0 EDMX files.
2009-07-08 15:48:13,539 [Project - Server Sandcastle:DEBUG]   Finished processing 0 EDMX files.
2009-07-08 15:48:13,539 [Project - Server Sandcastle:DEBUG] PrepareForBuild:
2009-07-08 15:48:13,539 [Project - Server Sandcastle:DEBUG]   Creating directory "bin\".
2009-07-08 15:48:14,757 [Project - Server Sandcastle:DEBUG] Unhandled Exception: System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. --->

System.InvalidOperationException: A call is made on an inactive IBuildEngine interface corresponding to a task that already finished execution.
2009-07-08 15:48:14,757 [Project - Server Sandcastle:DEBUG]    at Microsoft.Build.Shared.ErrorUtilities.ThrowInvalidOperation(String resourceName, Object[] args)
2009-07-08 15:48:14,757 [Project - Server Sandcastle:DEBUG]    at Microsoft.Build.BuildEngine.EngineProxy.LogMessageEvent(BuildMessageEventArgs e)
2009-07-08 15:48:14,757 [Project - Server Sandcastle:DEBUG]    at Microsoft.Build.Utilities.TaskLoggingHelper.LogMessage(MessageImportance importance, String message, Object[] messageArgs)
2009-07-08 15:48:14,757 [Project - Server Sandcastle:DEBUG]    at Microsoft.Build.Utilities.TaskLoggingHelper.LogMessage(String message, Object[] messageArgs)
2009-07-08 15:48:14,757 [Project - Server Sandcastle:DEBUG]    at DaveSexton.DocProject.MSBuild.MSBuildTrace.TraceLine(String message)
2009-07-08 15:48:14,757 [Project - Server Sandcastle:DEBUG]    at DaveSexton.DocProject.BuildContext.<>c__DisplayClass13.<TraceLine>b__12()
2009-07-08 15:48:14,757 [Project - Server Sandcastle:DEBUG]    --- End of inner exception stack trace ---
2009-07-08 15:48:14,757 [Project - Server Sandcastle:DEBUG]    at System.RuntimeMethodHandle._InvokeMethodFast(Object target, Object[] arguments, SignatureStruct& sig, MethodAttributes methodAttributes, RuntimeTypeHandle typeOwner)
2009-07-08 15:48:14,757 [Project - Server Sandcastle:DEBUG]    at System.RuntimeMethodHandle.InvokeMethodFast(Object target, Object[] arguments, Signature sig, MethodAttributes methodAttributes, RuntimeTypeHandle typeOwner)
2009-07-08 15:48:14,757 [Project - Server Sandcastle:DEBUG]    at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture, Boolean skipVisibilityChecks)
2009-07-08 15:48:14,757 [Project - Server Sandcastle:DEBUG]    at System.Delegate.DynamicInvokeImpl(Object[] args)
2009-07-08 15:48:14,757 [Project - Server Sandcastle:DEBUG]    at DaveSexton.DocProject.BuildContext.<>c__DisplayClass2.<InvokeInternal>b__0(Object state)
2009-07-08 15:48:14,757 [Project - Server Sandcastle:DEBUG]    at System.Threading._ThreadPoolWaitCallback.WaitCallback_Context(Object state)
2009-07-08 15:48:14,757 [Project - Server Sandcastle:DEBUG]    at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
2009-07-08 15:48:14,757 [Project - Server Sandcastle:DEBUG]    at System.Threading._ThreadPoolWaitCallback.PerformWaitCallbackInternal(_ThreadPoolWaitCallback tpWaitCallBack)
2009-07-08 15:48:14,757 [Project - Server Sandcastle:DEBUG]    at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback(Object state)
2009-07-08 15:48:15,398 [Project - Server Sandcastle:DEBUG] Unhandled Exception: System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> System.InvalidOperationException: A call is made on an inactive IBuildEngine interface corresponding to a task that already finished execution.
2009-07-08 15:48:15,398 [Project - Server Sandcastle:DEBUG]    at Microsoft.Build.Shared.ErrorUtilities.ThrowInvalidOperation(String resourceName, Object[] args)
2009-07-08 15:48:15,398 [Project - Server Sandcastle:DEBUG]    at Microsoft.Build.BuildEngine.EngineProxy.LogMessageEvent(BuildMessageEventArgs e)
2009-07-08 15:48:15,398 [Project - Server Sandcastle:DEBUG]    at Microsoft.Build.Utilities.TaskLoggingHelper.LogMessage(MessageImportance importance, String message, Object[] messageArgs)
2009-07-08 15:48:15,398 [Project - Server Sandcastle:DEBUG]    at Microsoft.Build.Utilities.TaskLoggingHelper.LogMessage(String message, Object[] messageArgs)
2009-07-08 15:48:15,398 [Project - Server Sandcastle:DEBUG]    at DaveSexton.DocProject.MSBuild.MSBuildTrace.TraceLine(String message)
2009-07-08 15:48:15,398 [Project - Server Sandcastle:DEBUG]    at DaveSexton.DocProject.BuildContext.<>c__DisplayClass13.<TraceLine>b__12()
2009-07-08 15:48:15,398 [Project - Server Sandcastle:DEBUG]    --- End of inner exception stack trace ---
2009-07-08 15:48:15,398 [Project - Server Sandcastle:DEBUG]    at System.RuntimeMethodHandle._InvokeMethodFast(Object target, Object[] arguments, SignatureStruct& sig, MethodAttributes methodAttributes, RuntimeTypeHandle typeOwner)
2009-07-08 15:48:15,398 [Project - Server Sandcastle:DEBUG]    at System.RuntimeMethodHandle.InvokeMethodFast(Object target, Object[] arguments, Signature sig, MethodAttributes methodAttributes, RuntimeTypeHandle typeOwner)
2009-07-08 15:48:15,398 [Project - Server Sandcastle:DEBUG]    at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture, Boolean skipVisibilityChecks)
2009-07-08 15:48:15,398 [Project - Server Sandcastle:DEBUG]    at System.Delegate.DynamicInvokeImpl(Object[] args)
2009-07-08 15:48:15,398 [Project - Server Sandcastle:DEBUG]    at DaveSexton.DocProject.BuildContext.<>c__DisplayClass2.<InvokeInternal>b__0(Object state)
2009-07-08 15:48:15,398 [Project - Server Sandcastle:DEBUG]    at System.Threading._ThreadPoolWaitCallback.WaitCallback_Context(Object state)
2009-07-08 15:48:15,398 [Project - Server Sandcastle:DEBUG]    at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
2009-07-08 15:48:15,398 [Project - Server Sandcastle:DEBUG]    at System.Threading._ThreadPoolWaitCallback.PerformWaitCallbackInternal(_ThreadPoolWaitCallback tpWaitCallBack)
2009-07-08 15:48:15,398 [Project - Server Sandcastle:DEBUG]    at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback(Object state)

Coordinator
Jul 15, 2009 at 12:16 PM
This discussion has been copied to a work item. Click here to go to the work item and continue the discussion.
Coordinator
Jul 15, 2009 at 12:18 PM

Thanks for the additional information.  I'll take a look for the next release.

- Dave