RAR BadImageReferenceException needs to log the callstack and exception type

[KirillOsenkov]

I'm investigating a build with this warning from RAR:

/Users/builder/azdo/_work/1/s/main/build/tools/MSBuild/bin/Microsoft.Common.CurrentVersion.targets(2143,5): warning MSB3246: Resolved file has a bad image, no metadata, or is otherwise inaccessible.

This exception is thrown in four places:
https://source.dot.net/#Microsoft.Build.Tasks.Core/AssemblyDependency/BadImageReferenceException.cs,cbeccdcba5e80a17,references

It could be a BadImageFormatException, FileNotFoundException, FileLoadException or any other IORelated exception. We throw away the callstack and don't display the type of the underlying exception. We should print the original exception ToString() not just the Message.

[benvillalobos]

@KirillOsenkov are you investigating this currently?

/cc: @Forgind

[KirillOsenkov]

No, this one is up-for-grabs if anyone’s interested

[Forgind]

When you said there were four places that threw the exception, did you mean this? It looks like all the information is saved in an inner exception, so it should be easily accessible when it gets thrown here.

[Forgind]

If so, does #6240 look about how you expected?

[KirillOsenkov]

Yes, perfect.

[KirillOsenkov]

And for completeness, I've found the underlying issue that was causing an AccessDenied exception. Zip on .NET doesn't preserve file permissions, so unpacking the Zip on Mac was creating files with 0 permissions instead of 644:
dotnet/runtime#17912 (comment)

[KirillOsenkov]

Seeing that it was Access Denied and the full ToString() would have certainly helped.

[danmoseley]

This looks a bit ugly to the user though

...warning MSB3246: Resolved file has a bad image, no metadata, or is otherwise inaccessible. System.BadImageFormatException: Assembly file 'C:\git\runtime\artifacts\bin\microsoft.netcore.app.ref\ref\net6.0\System.Security.Cryptography.Encoding.dll' could not be opened -- PE image doesn't contain managed metadata. [...]
...warning MSB3246:    at Microsoft.Build.Shared.AssemblyNameExtension.GetAssemblyNameEx(String path) [...]
...warning MSB3246:    at Microsoft.Build.Tasks.SystemState.GetAssemblyName(String path) [...]
...warning MSB3246:    at Microsoft.Build.Tasks.ReferenceTable.SetPrimaryAssemblyReferenceItem(ITaskItem referenceAssemblyName) [...]

do we want to show these internal frames here?

[KirillOsenkov]

Not sure what’s the best way to truncate them: just keep the first text line from ToString() or take just the message from the innermost exception?

[danmoseley]

I'm not sure what other variations look like or what information you expect the user to get from them? Maybe log the message normally, but reserve ToString (or StackTrace) for the highest verbosity logging? In this case, the dll was corrupted, when I see callstack from my build tool it makes me think there is a bug in it.

[KirillOsenkov]

I agree showing the callstack is unpolished, just curious on how to actually fix this. Because there are nested exceptions so we should probably print the message from each nested exception?

[danmoseley]

For the aggregated message including nested you could concat something like [AggregateException does]?(https://github.com/dotnet/runtime/blob/fc854d9921475366875658180afa495d452451be/src/libraries/System.Private.CoreLib/src/System/AggregateException.cs#L346-L367)
I don't think it's the prettiest, but that's precedent.

For the diagnostic verbosity, you could dump ToSTring() which will include nested info.

[Forgind]

I'm not opposed to trying to make this clearer/simpler, but it seems lower priority than getting the information out, so I removed my assignment.

I'm curious if this could be an opportunity to use the check-verbosity-before-logging idea. Diagnostic --> current behavior. Quiet/minimal --> nothing? Normal --> message from innermost exception?

[danmoseley]

I guess I meant log the error with the messages, and immediately follow with a low importance message event with the ToString(), perhaps.

[danmoseley]

I just hit this a few times building dotnet/runtime. The output folder was "slightly corrupt" I guess. I believe a tool that dumps stack to the console looks like it has a bug. I put up a fix.