InternalTrace.Initialize fails with Nullref exception

[OsirisTerje]

When testing the 4.3.1 NUnit3Testadapter I'm experiencing crashes in the InternalTrace.Initialize, which raises a nullref exception.

The stacktrace and messages are

SendMessage: Current directory: D:\repos\NUnit\nunit3-vs-adapter\src\NUnitTestAdapterTests\bin\Debug\netcoreapp3.1
SendMessage:    Exception thrown executing tests in D:\repos\NUnit\nunit3-vs-adapter\src\NUnitTestAdapterTests\bin\Debug\netcoreapp3.1\mock-assembly.dll
SendMessage: NUnit.Engine.NUnitEngineException: An exception occurred in the driver while loading tests.
 ---> System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation.
 ---> System.NullReferenceException: Object reference not set to an instance of an object.
   at NUnit.Framework.Internal.InternalTrace.Initialize(String logName, InternalTraceLevel level)
   at NUnit.Framework.Api.FrameworkController.Initialize(String assemblyNameOrPath, IDictionary settings)
   at NUnit.Framework.Api.FrameworkController..ctor(String assemblyNameOrPath, String idPrefix, IDictionary settings)
   at NUnit.Framework.Api.FrameworkController..ctor(Assembly assembly, String idPrefix, IDictionary settings)
   --- End of inner exception stack trace ---
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor, Boolean wrapExceptions)
   at System.Reflection.RuntimeConstructorInfo.Invoke(BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)
   at System.RuntimeType.CreateInstanceImpl(BindingFlags bindingAttr, Binder binder, Object[] args, CultureInfo culture)
   at System.Activator.CreateInstance(Type type, BindingFlags bindingAttr, Binder binder, Object[] args, CultureInfo culture, Object[] activationAttributes)
   at System.Activator.CreateInstance(Type type, Object[] args)
   at NUnit.Engine.Drivers.NUnitNetStandardDriver.CreateObject(String typeName, Object[] args)
   at NUnit.Engine.Drivers.NUnitNetStandardDriver.Load(String testAssembly, IDictionary`2 settings)
   at NUnit.Engine.Runners.DirectTestRunner.LoadDriver(IFrameworkDriver driver, String testFile, TestPackage subPackage)
   --- End of inner exception stack trace ---
   at NUnit.Engine.Runners.DirectTestRunner.LoadDriver(IFrameworkDriver driver, String testFile, TestPackage subPackage)
   at NUnit.Engine.Runners.DirectTestRunner.LoadPackage()
   at NUnit.Engine.Runners.DirectTestRunner.EnsurePackageIsLoaded()
   at NUnit.Engine.Runners.DirectTestRunner.Explore(TestFilter filter)
   at NUnit.Engine.Runners.MasterTestRunner.Explore(TestFilter filter)
   at NUnit.VisualStudio.TestAdapter.NUnitEngine.NUnitEngineAdapter.Explore(TestFilter filter) in d:\repos\NUnit\nunit3-vs-adapter\src\NUnitTestAdapter\NUnitEngine\NUnitEngineAdapter.cs:line 98
   at NUnit.VisualStudio.TestAdapter.NUnit3TestExecutor.RunAssembly(String assemblyPath, IGrouping`2 testCases, TestFilter filter) in d:\repos\NUnit\nunit3-vs-adapter\src\NUnitTestAdapter\NUnit3TestExecutor.cs:line 286
SendMessage:    at NUnit.Engine.Runners.DirectTestRunner.LoadDriver(IFrameworkDriver driver, String testFile, TestPackage subPackage)
   at NUnit.Engine.Runners.DirectTestRunner.LoadPackage()
   at NUnit.Engine.Runners.DirectTestRunner.EnsurePackageIsLoaded()
   at NUnit.Engine.Runners.DirectTestRunner.Explore(TestFilter filter)
   at NUnit.Engine.Runners.MasterTestRunner.Explore(TestFilter filter)
   at NUnit.VisualStudio.TestAdapter.NUnitEngine.NUnitEngineAdapter.Explore(TestFilter filter) in d:\repos\NUnit\nunit3-vs-adapter\src\NUnitTestAdapter\NUnitEngine\NUnitEngineAdapter.cs:line 98
   at NUnit.VisualStudio.TestAdapter.NUnit3TestExecutor.RunAssembly(String assemblyPath, IGrouping`2 testCases, TestFilter filter) in d:\repos\NUnit\nunit3-vs-adapter\src\NUnitTestAdapter\NUnit3TestExecutor.cs:line 286
SendMessage: NUnit Adapter 4.3.1.0: Test execution complete

This does not happen during normal runs, but when running some of the tests in the adapter,

The code for this {in the adapter repo] is currently in the Fixtmppath branch.

Looking at the NUnit code for the InternalTrace.Initialize method, I can't see that much that can go wrong, but line

nunit/src/NUnitFramework/framework/Internal/Logging/InternalTrace.cs

Line 54 in 92180f1

traceWriter.WriteLine("InternalTrace: Ignoring attempted re-initialization at level {0}", level);

could raise this. The property Initialized is actually a check for the traceWriter != null, but as these are independent they could [theoretically] deviate. I might be missing something here, but anyway, it crashes in this method.

[CharliePoole]

Yes, I think I can see what's happening...

1. Initialize is called with level Off.
2. Tracewriter is left null but Initialized is set to true.
3. Initialize is called a second time, with any level specified.
4. The else clause is executed with a null TraceWriter.

So we changed to allow re-initialization at a different level while the framework is still trying to protect itself against re-initialization. This didn't show up as a problem until we implemented the further change of lazily creating the TraceWriter.

We can't do both things... lazy creation and using the null value as an indicator of creation.

[stevenaw]

Nice find!
Based on the existing code, I assume the desired behavior here is that this can be called multiple times, and the internal tracer should only be created the first time a level other that "Off" is specified?

In other words, the level can be changed from "Off" -> "something", but not from "something" -> "Off"?

[CharliePoole]

No, initialization should only be called once and the data provided saved. If the level is changed on the fly, it is done by setting the property. The file should be created either on first write or when the level is set to something other than off. I have wrote code for this for this which may only be in the engine's copy of InternalTrace - I'll have to check.

[OsirisTerje]

So as a minimum the code should be changed like:

It has to be done in both methods though.

But, the Initialized property is only stating that the traceWriter is null or not, so why are they independent? That's the underlying reason for this crash. If the property is needed (which I assume it is), why not let it just be like:

 public static bool Initialized  => traceWriter != null;

Would be less code to write too.

[CharliePoole]

I feel like it's somewhat more complicated than just that fix. I feel I should look into this a bit more deeply and make some suggestions to the framework team... maybe even a PR. I have a few other things to fix first. :-)

But the framework code, though flawed, is intended to avoid multiple calls to InternalTrace.Initialize. That seems to be the heart of the matter. How is the adapter directly or indirectly calling this more than once for the same assembly?

UPDATE - I see this is a framework issue now. Apparently transfered. Very confusing. :-)

[OsirisTerje]

I raised this issue here in the NUnit repo, it has never been elsewhere. And did so because the stack trace pointed to this method.

The underlying reason for calling it multiple times comes from how the tests are run inside the adapter test project. It uses the adapter code at the same time as it tests it. It has been like this for ~8 years now, so it must be the latest change we did there to set the InternalTraceLevel for the engine that triggers this. But the change I have suggested here is doing the same as before, just in a more safe manner.

Awesome if you can have a deeper look and see if there is something more to this. But the code should not be as it was in any case.

[CharliePoole]

My mistake then. I saw your name and made that assumption. My comments have therefore been aimed at the adapter not the framework up to now. Possibly confusing to everyone I guess.

I disagree that your statement that the change you propose does the same as before.

Original behavior: Log an error if InitializeTrace is called more than once.
New behavior: Log an error if InitializeTrace is called more than once unless all earlier calls used a level of Off.

Of course it's up to @rprouse and the @nunit/framework-team to decide which behavior they want.

If they want the original behavior then simply using traceWriter?.WriteLine would prevent the error. That, however, leads to the question "How will the caller ever learn that the call was invalid.?" Maybe I should have just thrown an exception in the first place. :-)

(I acknowledge of course that throwing would be a breaking change, so we can't do it now.)

[OsirisTerje]

I agree the change does change the behavior as you state there.

Protecting the call to Writeline is an option, but why is it that the call can't be set to Off first (like we do in the adapter for the engine (I have not checked if that call is propagated down here) and then set for each package (I assume that those calls are the ones that are actually propagated down here). Using Off first makes it possible to first set it as a default value, then a bit later set it to the actually wanted level. When looking from the adapter's "point of view" that makes more sense to me, but then I am ignoring other possible ways this would be used, unknown to me.

On the other hand, this might be an "adapter test only" issue. And the tests in question comes from way back. @jnm2 added acceptance tests to the adapter a while back, and those are isolated, and running in their own process. All of those are working. These tests (loading and using the Mockassembly) are kind of early versions of that, and should possibly be run in isolation too. I don't think the adapter is able to run anything else in this manner though.
The code should be fixed anyway since it is not robust, but either of the ways would work.

Btw, throwing an exception would effectively stop any way of that kind of testing.

And, I am currently trying to release the 4.3.1 hotfix, but I do have a bunch of failing tests. I suspect that they are caused by this, but I haven't gone through them all. I am reluctant to release anything with failing tests.

UPDATE:
I can release a beta though, but a beta for a hotfix feels a bit off.

[CharliePoole]

I think your adapter tests are proof that the original concept (mine btw) of ignoring and logging subsequent initialization was a mistake. If an error had been thrown eight years ago, you would have tested in a more isolated way. I think both I and others were more casual about ignoring errors than we like to be today. Of course, the point of the log is that you should know about this problem because something may change in the future... as it now has.

The basic problem is that the Initialize method sets up two things: the file to which writing will be done and the trace level. In the change that led to the "empty file error" the intent was that the level might change, but not the file. In principal, the caller has no way to know whether that file has been written to. So really, an entire (breaking) restructuring of what trace does would be the cleanest approach. All of what we are seeing here is really an attempt to do the same thing without breaking anything.

In agree that your change would be the most expedient and it does bring the framework InternalTrace closer to the other copies. I'm thinking that we should eventually review each copy for consistency. (I can't quite remember how many there are, but more than one for sure)

[CharliePoole]

@OsirisTerje I forgot to mention...

The initial setting to Off should be happening internally, without any call on your part. That's why, for example, most runners don't include the Off setting in their packages. I'm not sure if this is happening in all instances of InternalTrace however.

In the case of the framework, the correct behavior occurs without actually changing the value from Default to Off by use of the > comparison.

[OsirisTerje]

@CharliePoole I set this to Off for the engine, and I don't think it would work without that. Can recheck of course.

[CharliePoole]

You could be right. I often advise users of the console runner to just use the defaults unless they have some need to change them. Generally, for users, that's the best to do because as soon as you start specifying options you can run into problems.

But when calling the engine programmatically, that may not be the best way.