Skip to content
This repository has been archived by the owner on Nov 15, 2021. It is now read-only.

Random access violations with VS2015 compiler and OpenCover 4.6.166 / 4.5.3723 #329

Closed
Sam13 opened this issue Jul 27, 2015 · 83 comments
Closed

Comments

@Sam13
Copy link
Contributor

Sam13 commented Jul 27, 2015

I upgraded recently from VS2010 .NET 4.0 / OpenCover 4.5.3522 to
VS2015 .NET 4.0 (uses .NET 4.5 compiler to generate .NET 4.0) / OpenCover 4.5.3723 / 4.6.166

When running my unit tests compiled with VS2010 and OpenCover 4.5.3522 they work fine.
When running my unit tests compiled with VS2015 without OpenCover they work fine.

When running with OC 4.6.166 or 4.5.3723 they crash randomly.
I cannot use a version < 4.5.3723 because of #319 .

Mostly there is an AccessVioloationException

Unhandled Exception: System.AccessViolationException: Attempted to read or write protected memory. This is often an indication that other memory is corrupt.
at System.CannotUnloadAppDomainException.VisitedCritical(Int32 )
at System.CannotUnloadAppDomainException.SafeVisited(Int32 )
(anonymized)

or sometimes an ArgumentOutOfRangeException:

Unhandled Exception: System.ArgumentOutOfRangeException: Index was out of range. Must be non-negative and less than the size of the collection.
[asyncexec] Parameter name: startIndex
[asyncexec]    at System.ThrowHelper.ThrowArgumentOutOfRangeException(ExceptionArgument argument, ExceptionResource resource)
[asyncexec]    at System.BitConverter.ToUInt32(Byte[] value, Int32 startIndex)
[asyncexec]    at OpenCover.Framework.Persistance.BasePersistance.SaveVisitData(Byte[] data) in c:\projects\opencover\main\OpenCover.Framework\Persistance\BasePersistance.cs:line 494
[asyncexec]    at OpenCover.Framework.Manager.ProfilerManager.<>c__DisplayClass7.<SaveVisitData>b__6(Object state) in c:\projects\opencover\main\OpenCover.Framework\Manager\ProfilerManager.cs:line 157
[asyncexec]    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
[asyncexec]    at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
[asyncexec]    at System.Threading.QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem()
[asyncexec]    at System.Threading.ThreadPoolWorkQueue.Dispatch()
@sawilde
Copy link
Member

sawilde commented Jul 27, 2015

looks like it is related to this pull request #330 - do you have a code sample so I can investigate the latter issue further?

@Sam13
Copy link
Contributor Author

Sam13 commented Jul 28, 2015

Unfortunately I can provide a sample to reproduce because the crashes occur more or less randomly.
I also noticed that version 4.5.3723 is not running smoothly, at least in my environment...

I've built the fix version from #330 myself and will run it in my environment to see if this fixes the crashes...

@Sam13
Copy link
Contributor Author

Sam13 commented Jul 28, 2015

urasandesu@d1f07d4 does not fix my problem, still access violations.

I can offer to run an instrumented build on my environment which collects hopefully helpful informations about the problem...

@sawilde
Copy link
Member

sawilde commented Jul 30, 2015

@Sam13 - thanks for the offer but I tend to tweak the instrumentation based on the issue - otherwise it's too hard to wade through all the data - hence why a reproducible sample is much easier

@Sam13
Copy link
Contributor Author

Sam13 commented Aug 3, 2015

@sawilde Did you try to run the OpenCover over something compiled with VS2015?

I tried again to find some repeatable behavior but without success. I tried to isolate a failing test assembly (normally run OpenCover over nunit-console with 33 different assemblies). When I run only over an assembly that might have caused the crash it did not crash anymore...

The only thing I got might not be very helpful

Application: nunit-agent-x86.exe
Framework Version: v4.0.30319
Description: The process was terminated due to an unhandled exception.
Exception Info: System.AccessViolationException
Stack:
   at System.AppDomain.SetupDomain(Boolean, System.String, System.String, System.String[], System.String[])

Since I'm not very familiar with unmanaged code can you give me some advice how to lookup for something that might help you?

@bunnu
Copy link

bunnu commented Aug 6, 2015

Same issue here:

Ausnahmefehler: System.ArgumentOutOfRangeException: Der Index lag auáerhalb des Bereichs. Er muss nicht negativ und kleiner als die Auflistung sein.
Parametername: startIndex
   bei System.ThrowHelper.ThrowArgumentOutOfRangeException(ExceptionArgument argument, ExceptionResource resource)
   bei System.BitConverter.ToUInt32(Byte[] value, Int32 startIndex)
   bei OpenCover.Framework.Persistance.BasePersistance.SaveVisitData(Byte[] data) in c:\projects\opencover\main\OpenCover.Framework\Persistance\BasePersistance.cs:Zeile 494.
   bei OpenCover.Framework.Manager.ProfilerManager.<>c__DisplayClass7.<SaveVisitData>b__6(Object state) in c:\projects\opencover\main\OpenCover.Framework\Manager\ProfilerManager.cs:Zeile 157.
   bei System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   bei System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   bei System.Threading.QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem()
   bei System.Threading.ThreadPoolWorkQueue.Dispatch()

I'm using VS 2015 / Microsoft Build Tools 2015 and nunit. The problem appears randomly.

@Sam13
Copy link
Contributor Author

Sam13 commented Aug 10, 2015

Version 15c47b8 still crashes

Application: nunit-agent-x86.exe
Framework Version: v4.0.30319
Description: The process was terminated due to an unhandled exception.
Exception Info: System.AccessViolationException
Stack:
at System.AppDomain.SetupDomain(Boolean, System.String, System.String, System.String[], System.String[])

@sawilde
Copy link
Member

sawilde commented Aug 10, 2015

It seems odd that this is happening in System.AppDomain.SetupDomain, what filters are you using? I tend to ignore System as it is not user code.

A repeatable example would be really useful right now.

@Sam13
Copy link
Contributor Author

Sam13 commented Aug 10, 2015

I set the filter like that:

-filter:"+[AppAssembly1]*  +[AppAssembly2]*  -[AppAssembly2]AppNamespace2.UserControl* -[AppAssembly2]AppNamespace2.Properties.* +[AppAssembly3]* +[AppAssembly4]* -[log4net*]* -[*nunit*]* -[msvcm*]* -[Rhino.Mocks*]* -[NLog*]* -[*UnitTest]*" -excludebyattribute:System.Diagnostics.CodeAnalysis.ExcludeFromCodeCoverageAttribute

I totally agree a sample would be nice, but I can't provide one.
As @bunnu stated the exceptions appear to be randomly, I have about 35 unit test assemblies with total over 10000 unit tests. Since I'm not familiar with unmanaged code / access violation debugging I did not even manage to determine the name of the failing tests so far :-(

@bunnu
Copy link

bunnu commented Aug 10, 2015

Unfortunately I don't have an repeatable example. The exception occurs randomly at different tests. Sometimes the error appears 1-2 times a day. Sometimes it takes a few days until it happens again.
I'll try to setup a simple unit-Test Solution and run it endless until the exception hopefully occurs. If so, I will provide you the code.

@sawilde
Copy link
Member

sawilde commented Aug 10, 2015

@Sam13 - It's not something I have seen myself so I don't know if it is OpenCover causing NUnit to crash or NUnit just crashing; especially in the case of the crash in SetupDomain as OpenCover would not touch that method as it is not in the filters and you probably don't have a PDB for it either. Do you see an entry in the XML file for that method?

@bunnu - Have you tried the latest build? https://ci.appveyor.com/project/sawilde/opencover/build/4.6.177/artifacts

@Sam13
Copy link
Contributor Author

Sam13 commented Aug 11, 2015

@sawilde
This must be OpenCover. The unit tests without OpenCover run stable on all our build servers and developer machines.
As far as I know in case of an access violation the stack trace might not be the cause for the exception, this is when it is detected. So memory corruption can happen somewhere else, as long as nobody is accessing it all runs fine...

Now I'll try the latest build. Yesterday I run a self compiled debug build of 15c47b8 and there a debug assertion was shown of OpenCover.Profiler.dll. I had no luck debugging it. Will try again if latest version still fails...
@bunnu Maybe you can also try to run a debug build?

@sawilde
Copy link
Member

sawilde commented Aug 11, 2015

@Sam13 - I am not sure what to do next - I can't fix something if I can't repeat it as i don't know if I am fixing the right thing. If you can supply a repeatable sample that would be great owever I don't know what your code does so I don't know if this is feasible.

@Sam13
Copy link
Contributor Author

Sam13 commented Aug 11, 2015

@sawilde As already state earlier, the debug build of 15c47b8 produces sometimes an assertion when running over my tests.
I finally managed to get more informations:

ocdebug

It seems that something with m_visitmap is wrong.
Assertion is _DEBUG_ERROR("list erase iterator outside range");

Let me know if you need more informations? I can also run an instrumented build...

@sawilde
Copy link
Member

sawilde commented Aug 11, 2015

It seems that something with m_visitmap is wrong.

hmm it might be a race condition that I was not expecting...

sawilde added a commit that referenced this issue Aug 12, 2015
#329 add critical section block around use of m_visitmap during Shutdown (can we get a ThreadDestroyed during Shutdown?)
@Sam13
Copy link
Contributor Author

Sam13 commented Aug 12, 2015

Still access violation with OC 4.6.183.
I managed it to get some WinDbg informations about the crash. I also have an unmanaged callstack which is better than System.AppDomain.SetupDomain I provided before...

0:000> k
ChildEBP RetAddr  
0036e730 6b9804df OpenCover_Profiler!<lambda_dc634b13574e7310065c8c22211f296e>::operator()+0x6b [c:\projects\opencover\main\opencover.profiler\profilercommunication.cpp @ 234]
0036e7a8 6b982b05 OpenCover_Profiler!ProfilerCommunication::RequestInformation<<lambda_1f392c229d59fdc248147a591270c623>,<lambda_dc634b13574e7310065c8c22211f296e> >+0xff [c:\projects\opencover\main\opencover.profiler\profilercommunication.cpp @ 399]
0036e7fc 6b982a7c OpenCover_Profiler!ProfilerCommunication::GetSequencePoints+0x65 [c:\projects\opencover\main\opencover.profiler\profilercommunication.cpp @ 242]
0036e81c 6b9748d6 OpenCover_Profiler!ProfilerCommunication::GetPoints+0x2c [c:\projects\opencover\main\opencover.profiler\profilercommunication.cpp @ 211]
0036e8dc 6b4b6f76 OpenCover_Profiler!CCodeCoverage::JITCompilationStarted+0x136 [c:\projects\opencover\main\opencover.profiler\codecoverage.cpp @ 275]
0036e914 6b525814 clr!EEToProfInterfaceImpl::JITCompilationStarted+0x53
0036e9f8 6b23894d clr!MethodDesc::MakeJitWorker+0x2dd
0036ea70 6b2274a3 clr!MethodDesc::DoPrestub+0x5fc
0036eae8 6b2117f5 clr!PreStubWorker+0xe2
0036eb88 6b211366 clr!ThePreStub+0x11
0036eba4 6b212f47 clr!CallDescrWorkerInternal+0x34
0036ebf8 6b219d0a clr!CallDescrWorkerWithHandler+0x6b
0036ec7c 6b30317b clr!MethodDescCallSite::CallTargetWorker+0x158
0036ed70 6b30338b clr!AppDomain::InitializeDomainContext+0x1ee
0036f204 6b31ef8a clr!SystemDomain::InitializeDefaultDomain+0x284
0036f708 6b31f419 clr!SystemDomain::ExecuteMainMethod+0x1d3
0036f760 6b31eb9a clr!ExecuteEXE+0x4c
0036f7a0 6b31af45 clr!_CorExeMainInternal+0xdc
0036f7dc 7384cc2f clr!_CorExeMain+0x4d
0036f818 73a77f16 mscoreei!_CorExeMain+0x10a
0036f828 73a74de3 MSCOREE!ShellShim__CorExeMain+0x99
0036f830 750b337a MSCOREE!_CorExeMain_Exported+0x8
0036f83c 771592e2 KERNEL32!BaseThreadInitThunk+0xe
0036f87c 771592b5 ntdll!__RtlUserThreadStart+0x70
0036f894 00000000 ntdll!_RtlUserThreadStart+0x1b

0:000> !analyze -v
*******************************************************************************
*                                                                             *
*                        Exception Analysis                                   *
*                                                                             *
*******************************************************************************

*** WARNING: Unable to verify checksum for image00d80000
*** ERROR: Module load completed but symbols could not be loaded for image00d80000

FAULTING_IP: 
OpenCover_Profiler!<lambda_dc634b13574e7310065c8c22211f296e>::operator()+6b [c:\projects\opencover\main\opencover.profiler\profilercommunication.cpp @ 234]
6b98239b 8b07            mov     eax,dword ptr [edi]

EXCEPTION_RECORD:  ffffffff -- (.exr 0xffffffffffffffff)
ExceptionAddress: 6b98239b (OpenCover_Profiler!<lambda_dc634b13574e7310065c8c22211f296e>::operator()+0x0000006b)
   ExceptionCode: c0000005 (Access violation)
  ExceptionFlags: 00000000
NumberParameters: 2
   Parameter[0]: 00000000
   Parameter[1]: 003af000
Attempt to read from address 003af000

FAULTING_THREAD:  00000724

DEFAULT_BUCKET_ID:  WRONG_SYMBOLS

PROCESS_NAME:  image00d80000

ERROR_CODE: (NTSTATUS) 0xc0000005 - The instruction at 0x%08lx referenced memory at 0x%08lx. The memory could not be %s.

EXCEPTION_CODE: (NTSTATUS) 0xc0000005 - The instruction at 0x%08lx referenced memory at 0x%08lx. The memory could not be %s.

EXCEPTION_PARAMETER1:  00000000

EXCEPTION_PARAMETER2:  003af000

READ_ADDRESS:  003af000 

FOLLOWUP_IP: 
OpenCover_Profiler!<lambda_dc634b13574e7310065c8c22211f296e>::operator()+6b [c:\projects\opencover\main\opencover.profiler\profilercommunication.cpp @ 234]
6b98239b 8b07            mov     eax,dword ptr [edi]

NTGLOBALFLAG:  400

APPLICATION_VERIFIER_FLAGS:  0

APP:  image00d80000

MANAGED_STACK: 
(TransitionMU)
0036EB14 058A008E mscorlib_4b40000!System.AppDomain.SetupDomain(Boolean, System.String, System.String, System.String[], System.String[])+0x46
(TransitionUM)

MANAGED_STACK_COMMAND:  _EFN_StackTrace

PRIMARY_PROBLEM_CLASS:  WRONG_SYMBOLS

BUGCHECK_STR:  APPLICATION_FAULT_WRONG_SYMBOLS

LAST_CONTROL_TRANSFER:  from 6b9804df to 6b98239b

STACK_TEXT:  
0036e730 6b9804df 99f5802e 006f8ee4 0036e84c OpenCover_Profiler!<lambda_dc634b13574e7310065c8c22211f296e>::operator()+0x6b
0036e7a8 6b982b05 006f8ee4 06006ebf 00782b00 OpenCover_Profiler!ProfilerCommunication::RequestInformation<<lambda_1f392c229d59fdc248147a591270c623>,<lambda_dc634b13574e7310065c8c22211f296e> >+0xff
0036e7fc 6b982a7c 06006ebf 00782b00 00744ee0 OpenCover_Profiler!ProfilerCommunication::GetSequencePoints+0x65
0036e81c 6b9748d6 06006ebf 00782b00 00744ee0 OpenCover_Profiler!ProfilerCommunication::GetPoints+0x2c
0036e8dc 6b4b6f76 006f8eb0 004b4278 00000001 OpenCover_Profiler!CCodeCoverage::JITCompilationStarted+0x136
0036e914 6b525814 004b4278 006f8e18 990aaac2 clr!EEToProfInterfaceImpl::JITCompilationStarted+0x53
0036e9f8 6b23894d 00745368 00000000 00000001 clr!MethodDesc::MakeJitWorker+0x2dd
0036ea70 6b2274a3 00000000 990aa9d2 0036eb7c clr!MethodDesc::DoPrestub+0x5fc
0036eae8 6b2117f5 0036eaa8 004b4278 00000000 clr!PreStubWorker+0xe2
0036eb88 6b211366 00000000 00000000 026412d4 clr!ThePreStub+0x11
0036eba4 6b212f47 0036ec50 0036ebe8 6b33ccc4 clr!CallDescrWorkerInternal+0x34
0036ebf8 6b219d0a 00000000 02641388 0036ec2c clr!CallDescrWorkerWithHandler+0x6b
0036ec7c 6b30317b 0036ed38 0036efe8 006c12d0 clr!MethodDescCallSite::CallTargetWorker+0x158
0036ed70 6b30338b 00000000 0036efe8 0036edd8 clr!AppDomain::InitializeDomainContext+0x1ee
0036f204 6b31ef8a 990ab12a 00d80000 00000000 clr!SystemDomain::InitializeDefaultDomain+0x284
0036f708 6b31f419 990ab45a 00000000 00000000 clr!SystemDomain::ExecuteMainMethod+0x1d3
0036f760 6b31eb9a 990ab49a 00000000 00000000 clr!ExecuteEXE+0x4c
0036f7a0 6b31af45 990ab4e6 00000000 00000000 clr!_CorExeMainInternal+0xdc
0036f7dc 7384cc2f 990b3630 00000000 750b1222 clr!_CorExeMain+0x4d
0036f818 73a77f16 00000000 73840000 0036f83c mscoreei!_CorExeMain+0x10a
0036f828 73a74de3 00000000 750b337a 7efde000 MSCOREE!ShellShim__CorExeMain+0x99
0036f830 750b337a 7efde000 0036f87c 771592e2 MSCOREE!_CorExeMain_Exported+0x8
0036f83c 771592e2 7efde000 1bc9b8b9 00000000 KERNEL32!BaseThreadInitThunk+0xe
0036f87c 771592b5 73a74ddb 7efde000 00000000 ntdll!__RtlUserThreadStart+0x70
0036f894 00000000 73a74ddb 7efde000 00000000 ntdll!_RtlUserThreadStart+0x1b


FAULTING_SOURCE_LINE:  c:\projects\opencover\main\opencover.profiler\profilercommunication.cpp

FAULTING_SOURCE_FILE:  c:\projects\opencover\main\opencover.profiler\profilercommunication.cpp

FAULTING_SOURCE_LINE_NUMBER:  234

SYMBOL_STACK_INDEX:  0

SYMBOL_NAME:  opencover_profiler!<lambda_dc634b13574e7310065c8c22211f296e>::operator+6b

FOLLOWUP_NAME:  MachineOwner

MODULE_NAME: OpenCover_Profiler

IMAGE_NAME:  OpenCover.Profiler.dll

DEBUG_FLR_IMAGE_TIMESTAMP:  55cb3e31

STACK_COMMAND:  ~0s ; kb

FAILURE_BUCKET_ID:  WRONG_SYMBOLS_c0000005_OpenCover.Profiler.dll!_lambda_dc634b13574e7310065c8c22211f296e_::operator

BUCKET_ID:  APPLICATION_FAULT_WRONG_SYMBOLS_opencover_profiler!_lambda_dc634b13574e7310065c8c22211f296e_::operator+6b

WATSON_STAGEONE_URL:  http://watson.microsoft.com/StageOne/image00d80000/2_6_4_14350/5490f7cb/OpenCover_Profiler_dll/4_6_183_0/55cb3e31/c0000005/0001239b.htm?Retriage=1

Followup: MachineOwner
---------


0:000> !dumpstack
OS Thread Id: 0x724 (0)
Current frame: OpenCover_Profiler!<lambda_dc634b13574e7310065c8c22211f296e>::operator()+0x6b
ChildEBP RetAddr  Caller, Callee
0036e730 6b9804df OpenCover_Profiler!ProfilerCommunication::RequestInformation<<lambda_1f392c229d59fdc248147a591270c623>,<lambda_dc634b13574e7310065c8c22211f296e> >+0xff, calling OpenCover_Profiler!<lambda_dc634b13574e7310065c8c22211f296e>::operator()
0036e75c 6b97730d OpenCover_Profiler!std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> >::_Copy+0x8d, calling OpenCover_Profiler!operator new
0036e7a8 6b982b05 OpenCover_Profiler!ProfilerCommunication::GetSequencePoints+0x65, calling OpenCover_Profiler!ProfilerCommunication::RequestInformation<<lambda_1f392c229d59fdc248147a591270c623>,<lambda_dc634b13574e7310065c8c22211f296e> >
0036e7fc 6b982a7c OpenCover_Profiler!ProfilerCommunication::GetPoints+0x2c, calling OpenCover_Profiler!ProfilerCommunication::GetSequencePoints
0036e81c 6b9748d6 OpenCover_Profiler!CCodeCoverage::JITCompilationStarted+0x136, calling OpenCover_Profiler!ProfilerCommunication::GetPoints
0036e87c 771547b7 ntdll!RtlInterlockedPushEntrySList+0x10, calling ntdll!InterlockedPushEntrySList
0036e884 77154763 ntdll!RtlpFreeDebugInfo+0x4b, calling ntdll!RtlInterlockedPushEntrySList
0036e894 6b2128b0 clr!CrstBase::Enter+0x156, calling ntdll!RtlTryEnterCriticalSection
0036e8ac 6b21280f clr!CrstBase::Leave+0x31, calling ntdll!RtlLeaveCriticalSection
0036e8bc 6b22e9b4 clr!DeadlockAwareLock::TryBeginEnterLock+0x56, calling clr!_EH_epilog3
0036e8dc 6b4b6f76 clr!EEToProfInterfaceImpl::JITCompilationStarted+0x53
0036e914 6b525814 clr!MethodDesc::MakeJitWorker+0x2dd, calling clr!EEToProfInterfaceImpl::JITCompilationStarted
0036e93c 7714e3cc ntdll!RtlpLowFragHeapAllocFromContext+0xaec, calling ntdll!_SEH_epilog4
0036e940 7714e132 ntdll!RtlAllocateHeap+0x206, calling ntdll!RtlpLowFragHeapAllocFromContext
0036e9f8 6b23894d clr!MethodDesc::DoPrestub+0x5fc, calling clr!MethodDesc::MakeJitWorker
0036ea5c 6b227460 clr!PreStubWorker+0x86, calling clr!ETWTraceStartup::ETWTraceStartup
0036ea70 6b2274a3 clr!PreStubWorker+0xe2, calling clr!MethodDesc::DoPrestub
0036eae8 6b2117f5 clr!ThePreStub+0x11, calling clr!PreStubWorker
0036eb0c 058a008e (MethodDesc 004b3598 +0x46 System.AppDomain.SetupDomain(Boolean, System.String, System.String, System.String[], System.String[])), calling 004a6139
0036eb88 6b211366 clr!CallDescrWorkerInternal+0x34
0036eba4 6b212f47 clr!CallDescrWorkerWithHandler+0x6b, calling clr!CallDescrWorkerInternal
0036ebb8 6b212f00 clr!CallDescrWorkerWithHandler+0x20, calling clr!_alloca_probe
0036ebcc 6b349abf clr!MetaSig::SkipArg+0x25, calling clr!SigParser::SkipExactlyOne
0036ebf8 6b219d0a clr!MethodDescCallSite::CallTargetWorker+0x158, calling clr!CallDescrWorkerWithHandler
0036ec08 6b22566c clr!SigParser::SkipExactlyOne+0xa4, calling clr!SigParser::SkipExactlyOne
0036ec30 6b219c9b clr!MethodDescCallSite::CallTargetWorker+0x72, calling clr!_alloca_probe_16
0036ec60 6b219f1a clr!MethodDescCallSite::MethodDescCallSite+0x4d, calling clr!ArgIteratorTemplate<ArgIteratorBase>::ForceSigWalk
0036ec7c 6b30317b clr!AppDomain::InitializeDomainContext+0x1ee, calling clr!MethodDescCallSite::CallTargetWorker
0036ed64 6b374ce2 clr!AppDomain::InitializeSorting+0x12d, calling clr!RunningOnWin8
0036ed70 6b30338b clr!SystemDomain::InitializeDefaultDomain+0x284, calling clr!AppDomain::InitializeDomainContext
0036eef4 74a812e7 CRYPTBASE!AesCtr_safe+0x26, calling CRYPTBASE!AesCtrRng_Generate
0036ef10 74a81489 CRYPTBASE!AesCtr_safe_unlock+0x1c, calling ntdll!RtlLeaveCriticalSection
0036ef1c 74a81454 CRYPTBASE!RandomFillBuffer+0xb9, calling CRYPTBASE!AesCtr_safe_unlock
0036ef30 74a81464 CRYPTBASE!RandomFillBuffer+0xc9, calling CRYPTBASE!__security_check_cookie
0036ef7c 74a81376 CRYPTBASE!SlavePrng+0x30, calling CRYPTBASE!RandomFillBuffer
0036ef94 74a81343 CRYPTBASE!NewGenRandomEx+0x1b, calling CRYPTBASE!SlavePrng
0036efb0 75bb0880 RPCRT4!rc4_safe+0x38, calling ntdll!RtlLeaveCriticalSection
0036efc8 75bb0831 RPCRT4!GenerateRandomNumber+0x8f, calling RPCRT4!rc4_safe
0036efe0 75bb083f RPCRT4!GenerateRandomNumber+0x9d, calling RPCRT4!__security_check_cookie
0036f0f8 6b21ad4d clr!StgPoolReadOnly::GetString+0x15
0036f110 6b231a44 clr!CMiniMdTemplate<CMiniMd>::getNameOfTypeRef+0x3a, calling clr!StgPoolReadOnly::GetString
0036f124 6b34ca52 clr!CMiniMdTemplate<CMiniMd>::CommonGetNameOfCustomAttribute+0x13e, calling clr!CMiniMdTemplate<CMiniMd>::getNameOfTypeRef
0036f144 6b234012 clr!CMiniMdTemplate<CMiniMd>::CompareCustomAttribute+0x90, calling MSVCR120_CLR0400!strncmp
0036f170 6b23403b clr!CMiniMd::CommonGetCustomAttributeByNameEx+0x37, calling clr!CMiniMdTemplate<CMiniMd>::CompareCustomAttribute
0036f194 6b23cc9a clr!IMetaModelCommon::CommonGetCustomAttributeByName+0x16
0036f1b0 6b23ccb8 clr!MDInternalRO::GetCustomAttributeByName+0x1a
0036f1c8 6b31b264 clr!SystemDomain::SetGlobalSharePolicyUsingAttribute+0x1e
0036f204 6b31ef8a clr!SystemDomain::ExecuteMainMethod+0x1d3, calling clr!SystemDomain::InitializeDefaultDomain
0036f228 6b23c0db clr!MethodTable::DoFullyLoad+0xa55, calling clr!_EH_epilog3
0036f280 6b21ad4d clr!StgPoolReadOnly::GetString+0x15
0036f2e4 6b223282 clr!EEClassHashTable::ConstructKeyFromData+0x192, calling clr!__security_check_cookie
0036f2f0 7714e3cc ntdll!RtlpLowFragHeapAllocFromContext+0xaec, calling ntdll!_SEH_epilog4
0036f308 6b23c0db clr!MethodTable::DoFullyLoad+0xa55, calling clr!_EH_epilog3
0036f378 7714e3cc ntdll!RtlpLowFragHeapAllocFromContext+0xaec, calling ntdll!_SEH_epilog4
0036f37c 7714e132 ntdll!RtlAllocateHeap+0x206, calling ntdll!RtlpLowFragHeapAllocFromContext
0036f3a4 6b23be31 clr!ClassLoader::LoadTypeHandleForTypeKey+0xbc, calling clr!_EH_epilog3
0036f3a8 6b23c88d clr!ClassLoader::LoadTypeDefThrowing+0x2cc, calling clr!ClassLoader::LoadTypeHandleForTypeKey
0036f3b8 6b218ec5 clr!_EH_epilog3_GS+0xa, calling clr!__security_check_cookie
0036f3bc 6b22f7ca clr!ClassLoader::LoadTypeDefThrowing+0x319, calling clr!_EH_epilog3_GS
0036f3d0 6b218546 clr!ClrFlsSetValue+0xc, calling clr!ClrFlsGetBlock
0036f3dc 6b21d6c3 clr!IncCantAllocCount+0x82, calling clr!ClrFlsSetValue
0036f3f4 6b3a6eeb clr!StgBlobPool::GetBlob+0x4e, calling clr!MetaData::DataBlob::PeekCompressedU
0036f40c 6b3a6f51 clr!CMiniMdTemplate<CMiniMdRW>::getSignatureOfMethod+0x42
0036f420 7714e063 ntdll!RtlFreeHeap+0x105, calling ntdll!RtlpLowFragHeapFree
0036f438 750b14bd KERNEL32!HeapFree+0x14, calling ntdll!RtlFreeHeap
0036f44c 6b3547d0 clr!EEHeapFree+0x31, calling KERNEL32!HeapFree
0036f464 6b3547f5 clr!EEHeapFreeInProcessHeap+0x2f, calling clr!EEHeapFree
0036f470 6b35480d clr!operator delete+0x14, calling clr!EEHeapFreeInProcessHeap
0036f480 6b231ed4 clr!MethodTable::MethodDataObject::`vector deleting destructor'+0x2a, calling clr!operator delete
0036f484 6b231edc clr!MethodTable::MethodDataObject::`vector deleting destructor'+0x32, calling clr!_EH_epilog3
0036f4a8 6b231edc clr!MethodTable::MethodDataObject::`vector deleting destructor'+0x32, calling clr!_EH_epilog3
0036f4ac 6b231ea5 clr!MethodTable::MethodData::Release+0x16
0036f4b8 6b232003 clr!MemberLoader::FindMethod+0x18f, calling clr!_EH_epilog3
0036f510 6b232003 clr!MemberLoader::FindMethod+0x18f, calling clr!_EH_epilog3
0036f514 6b2881da clr!MscorlibBinder::LookupMethodLocal+0x65, calling clr!MemberLoader::FindMethod
0036f54c 6b2881fb clr!MscorlibBinder::LookupMethod+0xb, calling clr!MscorlibBinder::LookupMethodLocal
0036f55c 6b30458b clr!EEStartupHelper+0xb08, calling clr!_EH_epilog3
0036f5d4 7395d3dd MSVCR120_CLR0400!__crtFlsGetValue+0x3d, calling MSVCR120_CLR0400!__security_check_cookie
0036f608 771538ca ntdll!RtlpFreeHeap+0xb7a, calling ntdll!_SEH_epilog4
0036f60c 771534c2 ntdll!RtlFreeHeap+0x142, calling ntdll!RtlpFreeHeap
0036f650 6b310cd7 clr!REGUTIL::InitOptionalConfigCache+0x25a, calling clr!__security_check_cookie
0036f6b0 6b3a1193 clr!ThreadWillCreateGuardPage+0x17, calling KERNEL32!GetSystemInfoStub
0036f6d0 6b30458b clr!EEStartupHelper+0xb08, calling clr!_EH_epilog3
0036f6d4 6b30301e clr!EEStartup+0xb8, calling clr!_SEH_epilog4
0036f708 6b31f419 clr!ExecuteEXE+0x4c, calling clr!SystemDomain::ExecuteMainMethod
0036f760 6b31eb9a clr!_CorExeMainInternal+0xdc, calling clr!ExecuteEXE
0036f784 7384ebba mscoreei!CLRMetaHostPolicyImpl::`vector deleting destructor'+0x2c, calling mscoreei!_EH_epilog3
0036f7a0 6b31af45 clr!_CorExeMain+0x4d, calling clr!_CorExeMainInternal
0036f7dc 7384cc2f mscoreei!_CorExeMain+0x10a
0036f818 73a77f16 MSCOREE!ShellShim__CorExeMain+0x99
0036f828 73a74de3 MSCOREE!_CorExeMain_Exported+0x8, calling MSCOREE!ShellShim__CorExeMain
0036f830 750b337a KERNEL32!BaseThreadInitThunk+0xe
0036f83c 771592e2 ntdll!__RtlUserThreadStart+0x70
0036f87c 771592b5 ntdll!_RtlUserThreadStart+0x1b, calling ntdll!__RtlUserThreadStart

@sawilde
Copy link
Member

sawilde commented Aug 12, 2015

Thanks that is awesome - it seems to be having an issue processing the results from the host

What I suspect is that the host is not populating the array before returning to the client - unusual.

I've added extra diagnostics around this area.

NOTE: can you provide extra details on how you used WinDbg in this scenario; perhaps I can build a special diagnostics package and instructions that I can provide to people with similar issues.

sawilde added a commit that referenced this issue Aug 12, 2015
@Sam13
Copy link
Contributor Author

Sam13 commented Aug 13, 2015

How can I receive the extra log messages?
As far as I've seen in the code you are writing to Console and DebugOutput. I've run the latest binaries but recevied no output...

Here are the steps I've done to use WinDbg:

  • Copy OpenCover PDBs to working directory
  • Use gflags (use corresponding platform executable) to configure NUnit agent to break on exception
    image2015-8-13 12 55 19
  • Run coverage and wait for WinDbg breakpoint
    • Load CLR support: .loadby sos clr
    • Show callstacks:
      k (unmanaged) or !dumpstack (mixed)
    • Show exception details: !analyze -v

@sawilde
Copy link
Member

sawilde commented Aug 13, 2015

You probably see the extra messages if you use DebugView (part of sysinternals)

@Sam13
Copy link
Contributor Author

Sam13 commented Aug 13, 2015

I'm already using DebugView and also did http://stackoverflow.com/questions/12494300/no-output-from-debugview/12800603#12800603 but still not messages from OpenCover when access violation happens. I'm using binaries of version 4.6.184 from app veyor.
Also no messages directly in WinDbg...

@sawilde
Copy link
Member

sawilde commented Aug 13, 2015

None at all? That is odd as even release build pumps out a few messages especially during profiler start/stop.

sawilde added a commit that referenced this issue Aug 13, 2015
@Sam13
Copy link
Contributor Author

Sam13 commented Aug 14, 2015

Now I do get it, I've created a pull request which writes all output to the debug output with a prefix: #341.

It seems not much of your added tracing is printed when the exception happens (see end of trace):

Here is the debug output of the whole coverage process when the access violation happens:

00000001    0.00000000  [6692] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00000002    0.00007152  [6692] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-console-x86.exe  
00000003    0.00012990  [6692] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00000004    0.00018941  [6692] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00000005    0.00028523  [6692] OpenCover: Initialised mutexes   
00000006    0.00036820  [6692] OpenCover: Initialised communication interface   
00000007    2.07438087  [6692] OpenCover: Re-initialised communication interface    
00000008    2.07460427  [6692] OpenCover: Initialised results interface 
00000009    2.07476258  [6692] OpenCover: ::Initialize - Done!  
00000010    2.09082079  [6692] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00000011    2.10180473  [6692] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00000014    4.88152456  [8180] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00000015    4.88159943  [8180] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00000016    4.88190413  [8180] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00000017    4.88226414  [8180] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00000018    4.88280821  [8180] OpenCover: Initialised mutexes   
00000019    4.88339853  [8180] OpenCover: Initialised communication interface   
00000020    5.24020386  [8180] OpenCover: Re-initialised communication interface    
00000021    5.24052858  [8180] OpenCover: Initialised results interface 
00000022    5.24084711  [8180] OpenCover: ::Initialize - Done!  
00000023    5.27929449  [8180] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00000024    5.30460835  [8180] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00000025    11.24248219 [7472] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00000026    11.24251270 [7472] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00000027    11.24255657 [7472] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00000028    11.24260426 [7472] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00000029    11.24268436 [7472] OpenCover: Initialised mutexes   
00000030    11.24275112 [7472] OpenCover: Initialised communication interface   
00000031    11.24324894 [7472] OpenCover: Re-initialised communication interface    
00000032    11.24330807 [7472] OpenCover: Initialised results interface 
00000033    11.24336529 [7472] OpenCover: ::Initialize - Done!  
00000034    11.47317028 [7472] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00000035    11.48672581 [7472] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00000047    26.64159966 [5016] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00000048    26.64223099 [5016] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00000049    26.64229393 [5016] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00000050    26.64236069 [5016] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00000051    26.64245224 [5016] OpenCover: Initialised mutexes   
00000052    26.64258575 [5016] OpenCover: Initialised communication interface   
00000053    26.64322090 [5016] OpenCover: Re-initialised communication interface    
00000054    26.64331436 [5016] OpenCover: Initialised results interface 
00000055    26.64339828 [5016] OpenCover: ::Initialize - Done!  
00000056    26.66187286 [5016] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00000057    26.67707634 [5016] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00000058    28.94972038 [6328] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00000059    28.94979286 [6328] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00000060    28.94985390 [6328] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00000061    28.94992065 [6328] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00000062    28.95001221 [6328] OpenCover: Initialised mutexes   
00000063    28.95009804 [6328] OpenCover: Initialised communication interface   
00000064    32.90320969 [6328] OpenCover: Re-initialised communication interface    
00000065    32.90330505 [6328] OpenCover: Initialised results interface 
00000066    32.90342712 [6328] OpenCover: ::Initialize - Done!  
00000067    32.96213150 [6328] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00000068    33.02261734 [6328] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00000069    36.35596085 [7896] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00000070    36.35600281 [7896] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00000071    36.35604477 [7896] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00000072    36.35609436 [7896] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00000073    36.35617828 [7896] OpenCover: Initialised mutexes   
00000074    36.35625076 [7896] OpenCover: Initialised communication interface   
00000075    40.40711594 [7896] OpenCover: Re-initialised communication interface    
00000076    40.41128540 [7896] OpenCover: Initialised results interface 
00000077    40.41130829 [7896] OpenCover: ::Initialize - Done!  
00000078    40.43939209 [7896] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00000079    40.45316315 [7896] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00000089    43.66004562 [5356] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00000090    43.66011810 [5356] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00000091    43.66018295 [5356] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00000092    43.66024399 [5356] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00000093    43.66033936 [5356] OpenCover: Initialised mutexes   
00000094    43.66042328 [5356] OpenCover: Initialised communication interface   
00001229    44.40044022 [5356] OpenCover: Re-initialised communication interface    
00001230    44.40053940 [5356] OpenCover: Initialised results interface 
00001231    44.40062714 [5356] OpenCover: ::Initialize - Done!  
00001232    44.41890717 [5356] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001233    44.43266678 [5356] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001234    46.18522263 [5916] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001235    46.18525696 [5916] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001236    46.18529892 [5916] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001237    46.18534851 [5916] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001238    46.18541718 [5916] OpenCover: Initialised mutexes   
00001239    46.18548203 [5916] OpenCover: Initialised communication interface   
00001240    46.40077972 [5916] OpenCover: Re-initialised communication interface    
00001241    46.40083313 [5916] OpenCover: Initialised results interface 
00001242    46.40091324 [5916] OpenCover: ::Initialize - Done!  
00001243    46.42034531 [5916] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001244    46.43792725 [5916] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001245    48.08220673 [4612] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001246    48.08227921 [4612] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001247    48.08234024 [4612] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001248    48.08240509 [4612] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001249    48.08253479 [4612] OpenCover: Initialised mutexes   
00001250    48.08262634 [4612] OpenCover: Initialised communication interface   
00001251    48.40065384 [4612] OpenCover: Re-initialised communication interface    
00001252    48.40075302 [4612] OpenCover: Initialised results interface 
00001253    48.40084076 [4612] OpenCover: ::Initialize - Done!  
00001254    48.41994476 [4612] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001255    48.43471527 [4612] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001256    50.61579132 [3728] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001257    50.61582565 [3728] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001258    50.61587143 [3728] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001259    50.61591721 [3728] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001260    50.61599350 [3728] OpenCover: Initialised mutexes   
00001261    50.61605453 [3728] OpenCover: Initialised communication interface   
00001262    50.89951324 [3728] OpenCover: Re-initialised communication interface    
00001263    50.89956665 [3728] OpenCover: Initialised results interface 
00001264    50.89963150 [3728] OpenCover: ::Initialize - Done!  
00001265    50.91905594 [3728] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001266    50.93240356 [3728] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001267    52.99543381 [7116] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001268    52.99550247 [7116] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001269    52.99558640 [7116] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001270    52.99565887 [7116] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001271    52.99575043 [7116] OpenCover: Initialised mutexes   
00001272    52.99583817 [7116] OpenCover: Initialised communication interface   
00001273    54.89955139 [7116] OpenCover: Re-initialised communication interface    
00001274    54.89965057 [7116] OpenCover: Initialised results interface 
00001275    54.89973450 [7116] OpenCover: ::Initialize - Done!  
00001276    54.91857910 [7116] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001277    54.93335342 [7116] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001278    57.96984100 [5560] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001279    57.96987152 [5560] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001280    57.96991348 [5560] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001281    57.96995926 [5560] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001282    57.97003555 [5560] OpenCover: Initialised mutexes   
00001283    57.97010803 [5560] OpenCover: Initialised communication interface   
00001284    59.40248108 [5560] OpenCover: Re-initialised communication interface    
00001285    59.40253448 [5560] OpenCover: Initialised results interface 
00001286    59.40260315 [5560] OpenCover: ::Initialize - Done!  
00001287    59.42695999 [5560] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001288    59.44536209 [5560] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001289    62.89416885 [7012] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001290    62.89424133 [7012] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001291    62.89430237 [7012] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001292    62.89437103 [7012] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001293    62.89445877 [7012] OpenCover: Initialised mutexes   
00001294    62.89455032 [7012] OpenCover: Initialised communication interface   
00001295    63.40108109 [7012] OpenCover: Re-initialised communication interface    
00001296    63.40118027 [7012] OpenCover: Initialised results interface 
00001297    63.40126038 [7012] OpenCover: ::Initialize - Done!  
00001298    63.42193222 [7012] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001299    63.43588257 [7012] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001300    65.39746857 [5824] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001301    65.39752960 [5824] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001302    65.39759064 [5824] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001303    65.39766693 [5824] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001304    65.39776611 [5824] OpenCover: Initialised mutexes   
00001305    65.39783478 [5824] OpenCover: Initialised communication interface   
00001306    65.89955902 [5824] OpenCover: Re-initialised communication interface    
00001307    65.89962006 [5824] OpenCover: Initialised results interface 
00001308    65.89968872 [5824] OpenCover: ::Initialize - Done!  
00001309    65.92477417 [5824] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001310    65.93830872 [5824] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001311    67.69301605 [5844] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001312    67.69312286 [5844] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001313    67.69321442 [5844] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001314    67.69332123 [5844] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001315    67.69345856 [5844] OpenCover: Initialised mutexes   
00001316    67.69358063 [5844] OpenCover: Initialised communication interface   
00001317    68.40066528 [5844] OpenCover: Re-initialised communication interface    
00001318    68.40077209 [5844] OpenCover: Initialised results interface 
00001319    68.40087128 [5844] OpenCover: ::Initialize - Done!  
00001320    68.41878510 [5844] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001321    68.43901062 [5844] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001322    71.72624207 [7188] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001323    71.72627258 [7188] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001324    71.72631073 [7188] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001325    71.72636414 [7188] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001326    71.72644043 [7188] OpenCover: Initialised mutexes   
00001327    71.72650909 [7188] OpenCover: Initialised communication interface   
00001328    72.40111542 [7188] OpenCover: Re-initialised communication interface    
00001329    72.40116882 [7188] OpenCover: Initialised results interface 
00001330    72.40122223 [7188] OpenCover: ::Initialize - Done!  
00001331    72.42338562 [7188] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001332    72.43643951 [7188] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001333    75.92889404 [4116] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001334    75.92896271 [4116] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001335    75.92902374 [4116] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001336    75.92908478 [4116] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001337    75.92920685 [4116] OpenCover: Initialised mutexes   
00001338    75.92928314 [4116] OpenCover: Initialised communication interface   
00001339    85.94459534 [4116] OpenCover: ProfilerCommunication::RequestInformation(...) => Communication (Chat channel - AllocateBuffer) with host has failed (0x102, 10000)   
00001340    85.94470978 [4116] OpenCover:     ::Initialize => Failed to initialise the profiler communications -> GetLastError() => 183 
00001341    86.66264343 [2408] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001342    86.66268158 [2408] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001343    86.66271210 [2408] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001344    86.66275787 [2408] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001345    86.66283417 [2408] OpenCover: Initialised mutexes   
00001346    86.66290283 [2408] OpenCover: Initialised communication interface   
00001347    90.89962769 [2408] OpenCover: Re-initialised communication interface    
00001348    90.89974976 [2408] OpenCover: Initialised results interface 
00001349    90.89984131 [2408] OpenCover: ::Initialize - Done!  
00001350    90.92893219 [2408] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001351    90.94592285 [2408] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001352    93.61556244 [6544] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001353    93.61565399 [6544] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001354    93.61573029 [6544] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001355    93.61580658 [6544] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001356    93.61589050 [6544] OpenCover: Initialised mutexes   
00001357    93.61597443 [6544] OpenCover: Initialised communication interface   
00001358    93.61608124 [6544] OpenCover: ::Initialize - Done!  
00001359    93.67753601 [6544] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001360    93.69159698 [6544] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001361    124.69689178    [7068] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001362    124.69708252    [7068] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001363    124.70328522    [7068] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001364    124.71047211    [7068] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001365    124.71058655    [7068] OpenCover: Initialised mutexes   
00001366    124.71067810    [7068] OpenCover: Initialised communication interface   
00001367    124.73320770    [7068] OpenCover: Re-initialised communication interface    
00001368    124.73332977    [7068] OpenCover: Initialised results interface 
00001369    124.73341370    [7068] OpenCover: ::Initialize - Done!  
00001370    124.90754700    [7068] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001371    124.92201996    [7068] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001372    128.51898193    [6648] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001373    128.51902771    [6648] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001374    128.51907349    [6648] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001375    128.51911926    [6648] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001376    128.51919556    [6648] OpenCover: Initialised mutexes   
00001377    128.51925659    [6648] OpenCover: Initialised communication interface   
00001378    138.61117554    [6648] OpenCover: ProfilerCommunication::RequestInformation(...) => Communication (Chat channel - AllocateBuffer) with host has failed (0x102, 10000)   
00001379    138.61122131    [6648] OpenCover:     ::Initialize => Failed to initialise the profiler communications -> GetLastError() => 183 
00001380    140.12501526    [7592] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001381    140.12503052    [7592] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001382    140.12507629    [7592] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001383    140.12512207    [7592] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001384    140.12519836    [7592] OpenCover: Initialised mutexes   
00001385    140.12525940    [7592] OpenCover: Initialised communication interface   
00001386    144.91513062    [7592] OpenCover: Re-initialised communication interface    
00001387    144.91702271    [7592] OpenCover: Initialised results interface 
00001388    144.91717529    [7592] OpenCover: ::Initialize - Done!  
00001389    144.94767761    [7592] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001390    144.96093750    [7592] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001391    149.40888977    [5528] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001392    149.40896606    [5528] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001393    149.40901184    [5528] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001394    149.40908813    [5528] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001395    149.40919495    [5528] OpenCover: Initialised mutexes   
00001396    149.40928650    [5528] OpenCover: Initialised communication interface   
00001397    149.40939331    [5528] OpenCover: ::Initialize - Done!  
00001398    149.43132019    [5528] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001399    149.45088196    [5528] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001400    159.48426819    [5528] OpenCover: ProfilerCommunication::RequestInformation(...) => Communication (Chat channel - GetSequencePoints) with host has failed (0x102, 10000)    
00001401    184.41227722    [6164] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001402    184.41235352    [6164] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001403    184.41241455    [6164] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001404    184.41246033    [6164] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001405    184.41258240    [6164] OpenCover: Initialised mutexes   
00001406    184.41267395    [6164] OpenCover: Initialised communication interface   
00001407    184.41276550    [6164] OpenCover: ::Initialize - Done!  
00001408    184.64167786    [6164] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001409    184.65533447    [6164] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001410    215.79061890    [2588] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001411    215.79069519    [2588] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001412    215.79075623    [2588] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001413    215.79080200    [2588] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001414    215.79089355    [2588] OpenCover: Initialised mutexes   
00001415    215.79098511    [2588] OpenCover: Initialised communication interface   
00001416    215.79107666    [2588] OpenCover: ::Initialize - Done!  
00001417    216.03587341    [2588] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001418    216.03598022    [2588] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001419    253.30570984    [7600] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001420    253.30577087    [7600] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001421    253.30584717    [7600] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001422    253.30593872    [7600] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001423    253.30604553    [7600] OpenCover: Initialised mutexes   
00001424    253.30615234    [7600] OpenCover: Initialised communication interface   
00001425    253.30627441    [7600] OpenCover: ::Initialize - Done!  
00001426    253.33081055    [7600] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001427    253.34721375    [7600] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001428    283.71768188    [7732] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001429    283.71774292    [7732] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001430    283.71780396    [7732] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001431    283.71789551    [7732] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001432    283.71798706    [7732] OpenCover: Initialised mutexes   
00001433    283.71807861    [7732] OpenCover: Initialised communication interface   
00001434    283.71820068    [7732] OpenCover: ::Initialize - Done!  
00001435    283.73825073    [7732] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001436    283.75244141    [7732] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001437    285.91629028    [6804] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001438    285.91632080    [6804] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001439    285.91635132    [6804] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001440    285.91641235    [6804] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001441    285.91650391    [6804] OpenCover: Initialised mutexes   
00001442    285.91656494    [6804] OpenCover: Initialised communication interface   
00001443    286.95025635    [6804] OpenCover: Re-initialised communication interface    
00001444    286.95031738    [6804] OpenCover: Initialised results interface 
00001445    286.95037842    [6804] OpenCover: ::Initialize - Done!  
00001446    286.97302246    [6804] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001447    286.98852539    [6804] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001448    289.87408447    [4004] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001449    289.87414551    [4004] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001450    289.87420654    [4004] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001451    289.87426758    [4004] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001452    289.87438965    [4004] OpenCover: Initialised mutexes   
00001453    289.87448120    [4004] OpenCover: Initialised communication interface   
00001454    290.14260864    [4004] OpenCover: Re-initialised communication interface    
00001455    290.14270020    [4004] OpenCover: Initialised results interface 
00001456    290.14279175    [4004] OpenCover: ::Initialize - Done!  
00001457    290.15881348    [4004] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001458    290.17251587    [4004] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001459    293.91738892    [3744] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001460    293.91741943    [3744] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001461    293.91748047    [3744] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001462    293.91751099    [3744] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001463    293.91760254    [3744] OpenCover: Initialised mutexes   
00001464    293.91769409    [3744] OpenCover: Initialised communication interface   
00001465    294.39843750    [3744] OpenCover: Re-initialised communication interface    
00001466    294.39849854    [3744] OpenCover: Initialised results interface 
00001467    294.39855957    [3744] OpenCover: ::Initialize - Done!  
00001468    294.41824341    [3744] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001469    294.43133545    [3744] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001470    296.46185303    [3796] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001471    296.46188354    [3796] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001472    296.46191406    [3796] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001473    296.46197510    [3796] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001474    296.46203613    [3796] OpenCover: Initialised mutexes   
00001475    296.46209717    [3796] OpenCover: Initialised communication interface   
00001476    298.40103149    [3796] OpenCover: Re-initialised communication interface    
00001477    298.40109253    [3796] OpenCover: Initialised results interface 
00001478    298.40115356    [3796] OpenCover: ::Initialize - Done!  
00001479    298.42117310    [3796] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001480    298.43438721    [3796] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001481    305.86614990    [1140] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001482    305.86624146    [1140] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001483    305.86630249    [1140] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001484    305.86636353    [1140] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001485    305.86645508    [1140] OpenCover: Initialised mutexes   
00001486    305.86654663    [1140] OpenCover: Initialised communication interface   
00001487    306.40087891    [1140] OpenCover: Re-initialised communication interface    
00001488    306.40097046    [1140] OpenCover: Initialised results interface 
00001489    306.40103149    [1140] OpenCover: ::Initialize - Done!  
00001490    306.42303467    [1140] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001491    306.43859863    [1140] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001492    308.35632324    [4828] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001493    308.35635376    [4828] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001494    308.35641479    [4828] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001495    308.35644531    [4828] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001496    308.35650635    [4828] OpenCover: Initialised mutexes   
00001497    308.35656738    [4828] OpenCover: Initialised communication interface   
00001498    308.89950562    [4828] OpenCover: Re-initialised communication interface    
00001499    308.89956665    [4828] OpenCover: Initialised results interface 
00001500    308.89965820    [4828] OpenCover: ::Initialize - Done!  
00001501    308.92477417    [4828] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001502    308.93850708    [4828] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001503    310.66571045    [6476] OpenCover:     ::Initialize(...) => CLSID == {1542C21D-80C3-45E6-A56C-A9C1E4BEB7B8}  
00001504    310.66577148    [6476] OpenCover:     ::Initialize(...) => EXE = D:\vendor\nunit\bin\nunit-agent-x86.exe    
00001505    310.66583252    [6476] OpenCover:     ::Initialize(...) => PROFILER = D:\vendor\opencover\bin\x86\OpenCover.Profiler.dll    
00001506    310.66592407    [6476] OpenCover:     ::Initialize(...) => key = 719B4EDF   
00001507    310.66598511    [6476] OpenCover: Initialised mutexes   
00001508    310.66610718    [6476] OpenCover: Initialised communication interface   
00001509    311.39978027    [6476] OpenCover: Re-initialised communication interface    
00001510    311.39987183    [6476] OpenCover: Initialised results interface 
00001511    311.40008545    [6476] OpenCover: ::Initialize - Done!  
00001512    311.42019653    [6476] OpenCover: ::ModuleLoadFinished(...) => Adding methods to mscorlib...    
00001513    311.43447876    [6476] OpenCover: ::ModuleLoadFinished(...) => Added methods to mscorlib    
00001514    321.77377319    [8180] OpenCover: ::Shutdown - Nothing left to do but return S_OK(D:\vendor\nunit\bin\nunit-agent-x86.exe)  
00001515    321.79974365    [7472] OpenCover: ::Shutdown - Nothing left to do but return S_OK(D:\vendor\nunit\bin\nunit-agent-x86.exe)  
00001516    321.84606934    [5016] OpenCover: ::Shutdown - Nothing left to do but return S_OK(D:\vendor\nunit\bin\nunit-agent-x86.exe)  
00001517    321.97097778    [6328] OpenCover: ::Shutdown - Nothing left to do but return S_OK(D:\vendor\nunit\bin\nunit-agent-x86.exe)  
00001518    322.01553345    [7896] OpenCover: ::Shutdown - Nothing left to do but return S_OK(D:\vendor\nunit\bin\nunit-agent-x86.exe)  
00001519    322.09249878    [5356] OpenCover: ::Shutdown - Nothing left to do but return S_OK(D:\vendor\nunit\bin\nunit-agent-x86.exe)  
00001520    322.17178345    [5916] OpenCover: ::Shutdown - Nothing left to do but return S_OK(D:\vendor\nunit\bin\nunit-agent-x86.exe)  
00001521    322.20004272    [4612] OpenCover: ::Shutdown - Nothing left to do but return S_OK(D:\vendor\nunit\bin\nunit-agent-x86.exe)  
00001522    322.28143311    [3728] OpenCover: ::Shutdown - Nothing left to do but return S_OK(D:\vendor\nunit\bin\nunit-agent-x86.exe)  
00001523    322.34762573    [7116] OpenCover: ::Shutdown - Nothing left to do but return S_OK(D:\vendor\nunit\bin\nunit-agent-x86.exe)  
00001526    322.44729614    [5560] OpenCover: ::Shutdown - Nothing left to do but return S_OK(D:\vendor\nunit\bin\nunit-agent-x86.exe)  
00001527    322.52667236    [7012] OpenCover: ::Shutdown - Nothing left to do but return S_OK(D:\vendor\nunit\bin\nunit-agent-x86.exe)  
00001528    322.60330200    [5824] OpenCover: ::Shutdown - Nothing left to do but return S_OK(D:\vendor\nunit\bin\nunit-agent-x86.exe)  
00001529    322.71142578    [5844] OpenCover: ::Shutdown - Nothing left to do but return S_OK(D:\vendor\nunit\bin\nunit-agent-x86.exe)  
00001530    322.75656128    [7188] OpenCover: ::Shutdown - Nothing left to do but return S_OK(D:\vendor\nunit\bin\nunit-agent-x86.exe)  
00001531    322.83914185    [2408] OpenCover: ::Shutdown - Nothing left to do but return S_OK(D:\vendor\nunit\bin\nunit-agent-x86.exe)  
00001532    322.92138672    [7068] OpenCover: ::Shutdown - Nothing left to do but return S_OK(D:\vendor\nunit\bin\nunit-agent-x86.exe)  
00001533    323.02001953    [7592] OpenCover: ::Shutdown - Nothing left to do but return S_OK(D:\vendor\nunit\bin\nunit-agent-x86.exe)  
00001534    325.05236816    [6692] OpenCover: ::Shutdown - Nothing left to do but return S_OK(D:\vendor\nunit\bin\nunit-console-x86.exe)    
00001535    335.78976440    [3744] OpenCover: ProfilerCommunication::SendVisitPoints() => Communication (Results channel) with host has failed (0x102, 10000)   
00001536    336.00888062    [4004] OpenCover: ProfilerCommunication::SendVisitPoints() => Communication (Results channel) with host has failed (0x102, 10000)   
00001537    337.35220337    [6476] OpenCover: ProfilerCommunication::SendVisitPoints() => Communication (Results channel) with host has failed (0x102, 10000)   
00001538    344.21649170    [3796] OpenCover: ProfilerCommunication::SendVisitPoints() => Communication (Results channel) with host has failed (0x102, 10000)   
00001539    350.13623047    [4828] OpenCover: ProfilerCommunication::SendVisitPoints() => Communication (Results channel) with host has failed (0x102, 10000)   
00001540    352.63824463    [1140] OpenCover: ProfilerCommunication::SendVisitPoints() => Communication (Results channel) with host has failed (0x102, 10000)   
00001541    353.13827515    [6804] OpenCover: ProfilerCommunication::SendVisitPoints() => Communication (Results channel) with host has failed (0x102, 10000)   

@sawilde
Copy link
Member

sawilde commented Aug 14, 2015

Okay that looks odd it seems the nunit-console is starting over 34 agents but only closing 18 before it shuts itself down.

OpenCover is tracking the nunit-console and starts closing when it shuts down.

I also note that one of the buffer allocations failed due to a timeout > 10s; the SendVisitPoints at th end are also failing due to timeouts but is probably due to the fact that opencover has started shutting down.

How are you running nunit to launch so many agents?

@ddur
Copy link
Contributor

ddur commented Jan 11, 2016

We have very recent changes thanks to Coverity.

@Sam13
You can install and try OpenCover from latest merged build

@Sam13
Copy link
Contributor Author

Sam13 commented Jan 11, 2016

@ddur Thanks, I tried but build 365 doesn't seem to work either. Same output in DebugView.
My filters are like the following:

"D:\Trunk\packages\OpenCover.4.6.365\tools\OpenCover.Console.exe" -targetargs:" "Assembly1UnitTest.dll" "Assembly2UnitTest.dll" "Assembly3UnitTest.dll" /framework=4.0 /process=Multiple /xml="D:\Trunk\UnitTests2_Debug_x64.TestResult.xml" /labels /out:"D:\Trunk\UnitTests2_Debug_x64.TestResult.log"" -target:"D:\Trunk\packages\NUnit.Runners.2.6.4\tools\nunit-console.exe" -targetdir:"D:\Trunk\bin\x64\Debug" -output:"D:\Trunk\UnitTests2_Debug_x64.CoverageResult.xml" -filter:"+[Assembly1]*  +[Assembly2]* +[Assembly3]* -[Assembly2]Namespace1.UserControl* -[Assembly2]Namespace1.Properties.* -[log4net*]* -[*nunit*]* -[msvcm*]* -[Rhino.Mocks*]* -[NLog*]* -[*UnitTest]*" -excludebyattribute:System.Diagnostics.CodeAnalysis.ExcludeFromCodeCoverageAttribute -log:Error -returntargetcode -threshold:100

Basically I exclude everything and include the production assemblies with

+[Assembly2]*

this always worked so far...

@ddur
Copy link
Contributor

ddur commented Jan 11, 2016

@Sam13
Can you try one run without exclusion filters?

BTW,

  1. did you try to run NUnit with /domain=Single or None?
  2. did you try to compile tests with VS2013?
  3. are you running anything via Net Remoting or WCF?

@sawilde
Copy link
Member

sawilde commented Jan 11, 2016

it seems to be the -[*nunit*]* switch - I have a repeat and a test

@sawilde
Copy link
Member

sawilde commented Jan 11, 2016

@ddur
Copy link
Contributor

ddur commented Jan 12, 2016

@sawilde
I usually use only inclusion filters.
Suggestion for running without exclusion filters is because there are so many.
"Potential fix" is present in very recent builds only, not in any release used here.
Thanks for finding it before release

@ddur ddur mentioned this issue Jan 12, 2016
ddur added a commit that referenced this issue Jan 12, 2016
#329 More process-filter test-specs.
#449 Include AdminOnly tests on AppVeyor build
@sawilde
Copy link
Member

sawilde commented Jan 13, 2016

@Sam13
Copy link
Contributor Author

Sam13 commented Jan 13, 2016

Filtering now works, but nunit-agent occasionally crashes.
Unfotunately at the moment I have no time to dig into that further, since I have about 30 unit test assemblies which take about 30 minutes to run each try...

@sawilde
Copy link
Member

sawilde commented Jan 14, 2016

but nunit-agent occasionally crashes.

damn!

@ddur
Copy link
Contributor

ddur commented Jan 14, 2016

Never had any similar problems with OpenCover.
My test run one by one, so there is obvious and simple solution for this problem.
Since project under test is obviously commercial and we cannot reproduce, since problem has low priority to the user, user is to busy to run it overnight, I propose to close this issue.

BTW, I experienced collision crash while accessing same assembly while running number of "doogfood-release" tests in parallel.

@Sam13
Copy link
Contributor Author

Sam13 commented Jan 14, 2016

I'm planning to migrate to .NET 4.6.1 and NUnit 3 soon. Once done I'll try to reenable OpenCover coverage, maybe this fixes the occasional crashes as well...

@sawilde
Copy link
Member

sawilde commented Feb 1, 2016

@sawilde
Copy link
Member

sawilde commented Feb 8, 2016

@Sam13
Copy link
Contributor Author

Sam13 commented Feb 9, 2016

In meantime I migrated to .NET 4.6.1 and NUnit 3. I was only able to do a few tests with 4.6.515-rc. That's why I did not report anything so far.
The good news is that no crash occured so far ;-)

@sawilde
Copy link
Member

sawilde commented Feb 9, 2016

:) - let us know how you progress - we'll check back in a week or so.

@Sam13
Copy link
Contributor Author

Sam13 commented Feb 12, 2016

So far no crashes but NUnit3 seems to wait forever. The unit tests run successfully without OpenCover. I'm using OC 4.6.519 and NUnit 3.0.1. Any ideas how to dig into that further? As far as I can see no test assembly is still active, it's just the framework waiting for something...
nunithang

@sawilde
Copy link
Member

sawilde commented Feb 12, 2016

I assume you are still running them in parallel?

If you run DebugView then you might see what OpenCover is up to during this time - it does wait for the host process to shutdown so you could use the process exclusion to not not instrument the nunit console app; you will need to hook into the agents though). That way we can determine if the profiler itself is causing issues.

@Sam13
Copy link
Contributor Author

Sam13 commented Feb 15, 2016

Yes I'm using the parallelization algorithms inside NUnit3, that is supported, isn't it?

Ok I'll try and get back as soon as I have some results...

@sawilde
Copy link
Member

sawilde commented Feb 15, 2016

Yes I'm using the parallelization algorithms inside NUnit3, that is supported, isn't it?

As much as it can be, but you may not get the performance benefits of parallelization due to internal locks within the profiler.

@Sam13
Copy link
Contributor Author

Sam13 commented Feb 17, 2016

Ok, I'll also do some tests with disabled parallelization...

@sawilde
Copy link
Member

sawilde commented Feb 17, 2016

We also added a -safemode switch the default is on but you may get turn it off to switch to thread based buffers - these seem to be causing your problems (based on what we have fixed so far) but others are not experiencing the same issues as you now when using this feature.

@Sam13
Copy link
Contributor Author

Sam13 commented Feb 23, 2016

Finally, I found some time to play around with version 4.6.519.
In meantime I updated my codebase to .NET 4.6.1 / NUnit 3.
With that constellation I did not have any exceptions so far, so I was able to reenable OpenCover in my build.
I also digged into the "wait forever" problem and found out that a threshold value of 100 seems to help.
Also tested both options for safe mode but did not have big impact on test execution time...
So I'll leave it OFF, or what's the suggested value there?

@sawilde
Copy link
Member

sawilde commented Feb 23, 2016

So I'll leave it OFF, or what's the suggested value there?

the default is -safemode:on as I think that is probably the best for most tests. Only tests with high degrees of parallelism within the test (i.e. the .NET core guys testing their threading libraries) will benefit from -safemode:off. It really was a test feature and should not have gone mainstream so soon (hence why I now reverted it and placed it as a feature switch) but the knock affect for a few users was high.

Thanks for persevering - if we ever meet I owe you a beer or two - 🍻

Are we good to close?

@Sam13
Copy link
Contributor Author

Sam13 commented Feb 24, 2016

Yes I think so, no crashes so far... Can be closed from my side. Thanks for your support.
I heard you have some good beers down under 🍺 👍

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

5 participants