Test discovery emits zero length internaltrace log file per project

[barnabas90]

Hi,

The latest nunit test adapter 4.3.0 pollutes the solution dir with empty internaltrace log files during test discovery. Seemingly I get one zero length log file per project in my sln. The previous version doesn't do this. I'm on latest vs 2022.

[OsirisTerje]

@barnabas90 Yes, we are aware. It's an issue in the last version the engine. A fix will be out soon. If you use any of the net core targets the files go to the binary folder, but for net framework it unfortunately goes to the solution root.
In the meanwhile, drop down to 4.2.1 for a few more days.

[barnabas90]

Thank you!

[sandrohanea]

Unfortunately, cannot drop to 4.2.1 because of the issue #987

Workarounds:

1. Manually delete those InternalTrace files.
2. Uninstall dotnet 7 and downgrade to 4,2.1

[OsirisTerje]

@sandrohanea Those files only appear on solution root for net framework <=4.8, for .net core and .net 5,6,7 they comes in the binary folder, where they do no harm. So if #987 is the problem, then you don't have the issue. Assuming of course you don't build test programs for both platforms, but why would you do that?
Also, no need to uninstall dotnet 7 SDK, just set target to 6 or lower

[sandrohanea]

Maybe I have a different issue than #987 then (but looks pretty similar):

1. Using net framework 4.7.2 with NUnit TestAdapter 4.2.1 and VS 2022 Preview (which comes with dotnet 7 preview)
2. Trying to execute the tests from https://github.com/sandrohanea/nunit-repro-issue
3. Receiving the same exception as System.ArgumentException: Unknown framework version 7.0 #987 :
   

Once I installed TestAdapter 4.3.0, the tests are executed but InternalTrace files are generated => this issue started to reproduce.

Even if I downgraded to NuGet package to NUnit Adapter 4.2.1, the InternalTrace files still appear, because it seems 4.3.0 is still used by VS (see test output below) => Workaround 2 is not working:

I managed to re-do all the steps on a clean workstation and the behavior is consistent.

[OsirisTerje]

@sandrohanea You're right, the engine is obviously struggling to enumerate the frameworks and chooses to crash.
I tried using the alpha version of the 4.3 adapter

		<PackageReference Include="NUnit3TestAdapter" Version="4.3.0-alpha-net7.4">

That one has a fixed version of the previous engine, and seems to work as it should. I'll try to get this fixed during the weekend or early next week, but in the meantime you could use the alpha.

PS: Your repro seems to be missing

		  <PackageReference Include="Microsoft.NET.Test.Sdk" Version="17.3.2" />

Assume you have that in some props file... :-)

About downgrading, this is normally the .vs folder that is the problem. Exit vs, deleting that, and restarting vs should do it.

[OsirisTerje]

@CharliePoole I have been debugging this and found the following very interesting stuff:

First, the error for WHERE the logfile ends up is not in the engine, and not really in the adapter either, but I think the adapter can circumvent this.

1. The Engine uses whatever is set as the CurrentDirectory for storing the internal trace log.
2. The Visual Studio/dotnet testhost has different opinions on what is the CurrentDirectory for Net Framework versus the Net Core (NC 2.1 -> Net7).

Stopping the debugger right in the beginning of the RunTests methods:
This is when For Net Core:

And this is for Net Framework

The Engine produces the INternalTracelog (empty ones) when it is first called, which is this code:

where T is ITestFilterService.

So, all that needs to be done is to compensate for the net framework behavior is to set the CurrentDirectory before this code is called.
But, the input has a source parameter that is an enumeration (of assemblies),

This was used earlier, but as far as I can see now, the enumeration has been moved into the MS Testhost, so it seems we always get only one single assembly. I need to check this out to be completely sure.
If this is the case it is easy to change the current directory, but if not it is a bit harder since we then don't know where to place this InternalTracelog.

I haven't checked the Engine source code yet, but I assume you can confirm 1) it stores in the current directory 2) is that the designed choice, or was it intended to go somewhere else, like into current temp folder or something ?

I

[CharliePoole]

I'll re-check the code, but the design is easy to describe...

1. All output files from a run, including the result XML and any logs are intended to go to a WorkDirectory, which is not necessarily the same as the current directory.
2. The WorkDirectory is set when the engine is created by setting the WorkDirectory property.
3. If the property is not set, then the WorkDirectory does default to the current directory.

So the behavior you are seeing is exactly what I would expect if the WorkDirectory property is not set or if it is set to the value of the current directory.

OTOH, if WorkDirectory is set to an absolute path and that path is not used, I'd call that an engine bug. If it's set to a relative path, then that path is interpreted relative to the current directory, which would lead to the same problem.

In case you wonder, this setting is global to all runners (i.e. all test assemblies) in use by the engine. It therefore cannot be relative to the location of each test assembly. Keep in mind that a set of test assemblies being run may be located anywhere and not necessarily under a common base directory as they are when using the adapter.

I've checked this several times, but I can check again. However, I'm pretty sure that the logs are always stored in the specific directory passed in the WorkDirectory property on creation and can only go into the current directory if the property is not specified or if it is set to a relative path. This is a feature I use all the time myself, in fact.

[OsirisTerje]

From what I can see, I believe that is correct too.
The workdirectory property however is set later in the execution, when the assembly under test has been identified.
The call to get the filterservice happens before the workdirectory is being set. If we always get only one assembly (we did get many back in the old days), then this is not a problem, but if we get many, then I must see if I can move that initialization, since the actual running is per assembly, so if the filterservice is set there it should be fine.

[OsirisTerje]

In case you wonder, this setting is global to all runners (i.e. all test assemblies) in use by the engine. It therefore cannot be relative to the location of each test assembly. Keep in mind that a set of test assemblies being run may be located anywhere and not necessarily under a common base directory as they are when using the adapter.

If we have multiple assemblies, then this calls for setting the workdirectory to something else than the test assembly location. Something to think about, but I need to see first if we got this situation at all with the adapter. For dotnet command line the MS Testhost is calling the adapter once per test assembly. vstest.console can run multiple, and VSTest can run multiple, so I need to check exactly how they do it now. I know things have changed in newer versions of VS, so this means parts of this might break earlier versions of VS.

UPDATE:
Visual Studio runs multiple assemblies through the adapter. The current directory is set to the solution folder. We can't add log files there.
But the filter is set per assembly, and then also the current directory. But the engine is created only once, so should think of where the default current directory should be.
I'll check vstest.console later.
And also VS again with net core, which seems to differ.

[CharliePoole]

I will have to check this, but my memory is that the work directory must be set when the engine is created and may not be changed thereafter. At one time, setting the directory after initialization of the engine threw an exception.

[OsirisTerje]

The workdirectory can be set for the engine, but also for each testpackage. What the difference between these?

Btw, what is the original semantic meaning of Workdirectory?

[OsirisTerje]

And i havent seen any exceptions so far when changing it.

[CharliePoole]

I was away from the engine for two or three years, so stuff may have been changed. I'll examine the code more closely. It may be permissible to change it in the context of the adapter... the console and gui runners couldn't do that because they do logging independent of the running of tests... before, after and between tests!

[CharliePoole]

Do you get a separate runner for each test assembly or a separate engine instance?

[OsirisTerje]

Each test assembly gets its own runner, and share the engine.

[CharliePoole]

I haven't had time to research yet but I suspect that's OK so long as the runner itself (i.e. the adapter) doesn't do any logging through InternalTrace. If it did, having the trace writer re-initialized would cause an issue.

I'll go trace through the code later today and get back to you.

[CharliePoole]

@OsirisTerje I've had a thought!

What is the content and structure of the test package for which you are setting the work directory at the point where you call the engine with it? What properties does it have, what settings, what subpackages? If it has any subpackages, what do they contain?

Asking because version 3 actually has an issue where it allows creating subpackages, which the engine can't handle. A true fix would require changing the api, so it was pushed back to version 4 and various adhoc fixes were applied.

[OsirisTerje]

First, it doesn't have any subpackages. The adapter receives either a set of assemblies, or a set of testcases - which it then groups into a set of assemblies. Each assembly becomes a test package.
The properties that are set are the following, given that they deviate from the default value:

PackageSettings.ShadowCopyFiles
PackageSettings.NumberOfTestWorkers
package.Settings[PackageSettings.LOAD] = prefilters;  // If used
PackageSettings.SynchronousEvents
PackageSettings.DefaultTimeout
PackageSettings.InternalTraceLevel
PackageSettings.BasePath
PackageSettings.PrivateBinPath
PackageSettings.RandomSeed
PackageSettings.TestParametersDictionary  // with test parameters from runsettings
PackageSettings.StopOnError
PackageSettings.SkipNonTestAssemblies
 // Always run one assembly at a time in-process in its own domain
            package.Settings[PackageSettings.ProcessModel] = "InProcess";
PackageSettings.DomainUsage
PackageSettings.DefaultTestNamePattern
PackageSettings.WorkDirectory

The code for this is here:

nunit3-vs-adapter/src/NUnitTestAdapter/NUnitTestAdapter.cs

Line 179 in d0f38dc

protected TestPackage CreateTestPackage(string assemblyName, IGrouping<string, TestCase> testCases)

The package is created with only the assemblyname as a parameter, no other properties are being set.
Immediately after the package is created, a runner is created with that package.

[OsirisTerje]

@barnabas90 @sandrohanea This is work in progress, but would appreciate a test. It should no longer crash, with the existing engine, so empty log files are still produced, but they are in either the temp folder or in the binary.
If this is working as it should now, then I will add a later dev version of the engine tomorrow.

NUnit3TestAdapter.4.3.1-alpha.111.zip

[manfred-brands]

@OsirisTerje I have test the 4.3.1-alpha.111 and it works great and I no longer see an InternalLog file being generated.
Neither in the current directory, nor in the 'bin' folder nor in /tmp

[OsirisTerje]

@manfred-brands That is awesome. I set the InternalTraceLog to Off for the engine, so that is why it probably doesn't appear. That means there is no bug in the engine, so no need to update that further - for that reason. Thanks a lot!

PS: You did look in %temp%/NUnit.Engine.Logs, right ?

[manfred-brands]

PS: You did look in %temp%/NUnit.Engine.Logs, right ?
Yes, empty.

Any ETA for 4.3.1. I get a lot of InternalTrace files.

[OsirisTerje]

Within a few days now.
@CharliePoole is releasing 3.16 of the engine within a few days, and I would like to add that one in too.
If the engine is delayed, 4.3.1 will go out with the current engine, I would say Wednesday latest.

[bdrajer]

Confirming that NUnit3TestAdapter.4.3.1-alpha.111 works in VS 2019 as well. The problem I've seen was even worse since it attempted to create the mentioned internal trace log inside Windows\System32 and was denied by Windows security. And - go figure - it worked perfectly two days ago, I left a failing unit test only to discover I can't even run it anymore. I had also seen it complain in the test output window about failing to compute short-form "targert" framework moniker for project, from previous discussion it seems this could also be relevant (I'm on .Net Framework 4.6)... Didn't do any extensive testing yet but the difference is night and day and I'm keeping alpha.111 until further notice. Thanks!

[CharliePoole]

I wanted to add that the 3.16 release of the engine, which is now out, will stop creating empty log files when the trace setting is "Off" but won't affect where they are created with any other setting. So this will need to be tested as well. The location of the log files under the adapter is completely controlled by the host and the adapter itself. My suggestion is to never allow the location to default to the current directory in this environment, since the host will determine the default setting, possibly differently for different runtime targets.

[OsirisTerje]

And what @CharliePoole says here is what is done in the 4.3.1 version. The location is now explicitly stated for the engine and for each package.

[CharliePoole]

It's also now clear to me from our discussions that the engine code needs some re-thinking. The WorkDirectory property is used in two ways:

1. For the result file created by each test as well as any other test output, possibly created by the user tests examining the TestContext.
2. For trace files created by the runner, the engine, the agent or the framework... yes, up to four of them! The first two of these should not vary during a single execution since the lifetime of the runner and engine may be greater than that of a single test run.

Fortunately, this dual usage has not seemed to be a problem for the adapter up to now, but I can imagine ways it could crop up in the future.

I may consider adding new behavior in 3.16.1 where apparent changes to the destination of the trace output for the engine itself are ignored after the initial setting. Would this present any problem to the adapter?

[OsirisTerje]

I think that would be ok, as long as this affects only trace (and log) files.

[OsirisTerje]

Released here https://www.nuget.org/packages/NUnit3TestAdapter/4.3.1