Diagnosing dependency issues with ASP.NET 5

I answered a question on stackoverflow that started to turn into a brain dump of the debugging techniques we've learnt while building this brand new stack. While everything is still evolving, here's that answer reposted here as a blog post (slightly modified).

Incompatibilities

Right now, living on the bleeding edge will hurt. When things go bad it's easy to throw your hands up and complain (please keep complaining), but with a little help and practice, you'll be diagnosing problems like a pro in no time (and sending pull requests!).

Bare in mind that everything you see here is new. This project system is brand new (written from scratch), the NuGet client is new, the dnx is new and evolving quickly.

Tip #1 Make sure your DNX and packages are on the same version "train"

When things break it's likely because you're running your application on an incompatible dnx. If you ever see method missing of type missing exception or possibly an assembly load failure, chances are you ended up running betaX packages and betaY dnx or vice versa.

Even more specifically, Assembly Neutral Interfaces were removed in beta4 but still exist in beta3 (more on this later) so if you an exception like this:

System.IO.FileNotFoundException: Could not load file or assembly  
'Microsoft.Framework.Runtime.IApplicationEnvironment,
  Version=0.0.0.0, Culture=neutral, PublicKeyToken=null'
or one of its dependencies.  

It's because that type has moved and a package you are referencing is trying to load the ANI still.

We have plans to make it so that packages can mark the minimum dnx that they require to run to make the error message more clear. Also as time goes by, the breaking changes will die down and this issue will fade away...

Dependencies

Dependencies you put into project.json are top level only (this is unlike packages.config where the entire package closure is expanded directly). Versions are also always minimums (it's just like a NuGet package). This means that when you specify Foo 1.0.0-beta4 you're really specifying Foo >= 1.0.0-beta4. This means if you ask for MVC 0.0.1 and the minimum versions on your configured feeds is MVC 3.0.0, you'll get that one. We also NEVER float your version unless you specify it. If you ask for 1.0.0 and it exists, you will get 1.0.0 even if newer versions exist. Specifying empty versions is ALWAYS bad and will be disallowed in later builds.

There's a new feature we're introducing to nuget called floating versions. Today it only works on the prerelease tag, but in the next version of NuGet it'll work on more parts of the version. This is similar to npm and gem syntax for specifying version ranges in the package specification file.

1.0.0-* - Means give me the HIGHEST version matching the prefix (according to semantic versioning rules) OR if there is no version matching that prefix, use normal behavior and get me the LOWEST version >= the specified version. If you're interested, you can see the new logic in the lastest NuGet.Versioning packages.

When you run restore in the latest builds, it will write out a file called project.lock.json. This file will have the transitive closure of dependencies for all target frameworks defined in project.json.

project.lock.json

It has 3 purposes:

Think of it as a packages folder per project. In NuGet today, you get a solution level packages folder. That tells the project (via hint paths) what set of packages it can use for compilation and running. The project.lock.json file is effectively the same thing, it's a "per project packages folder", since we don't copy anything local in the new project system (your bin folder is empty), it's a way to scope the list of packages in %userprofile%\.dnx\packages so that projects don't just run based on the global set of packages, but the ones that are relevant to that project.

On top of that, it also stores the list of files and relevant content for compilation and runtime so that the runtime only has to read a single file instead of N nuspec files at startup time. This actually cut the startup time in 1/2 on azure websites.

The third function of the lock file is when you choose to check it into source control. If you run kpm restore --lock it will set the "locked": true property in the file. When you actually lock the lock file (hence the name), kpm restore no longer does dependency resolution. It will just download the files listed in the lock file. This way it acts more like a packages.config.

Diagnosing Failures

When you get a build or runtime failure you can do the following:

Take a look at the resolved dependencies using kpm list. This will show you the resolved versions of packages referenced by your project and what dependency pulled it in.

Actual kpm list output:

Listing dependencies for ClassLibrary39 (C:\Users\davifowl\Documents\Visual Studio 14\Projects\ClassLibrary39\src\ClassLibrary39\project.json)

[Target framework DNX,Version=v4.5.1 (dnx451)]

 framework/Microsoft.CSharp 4.0.0.0
    -> ClassLibrary39 1.0.0
 framework/mscorlib 4.0.0.0
    -> ClassLibrary39 1.0.0
 framework/System 4.0.0.0
    -> ClassLibrary39 1.0.0
 framework/System.Core 4.0.0.0
    -> ClassLibrary39 1.0.0
*Newtonsoft.Json 6.0.1
    -> ClassLibrary39 1.0.0

[Target framework DNXCore,Version=v5.0 (dnxcore50)]

*Newtonsoft.Json 6.0.1
    -> ClassLibrary39 1.0.0
 System.Runtime 4.0.20-beta-22709
    -> ClassLibrary39 1.0.0

* means direct dependency.

If you have a working visual studio (which breaks with DNX right now), you can look at the references node. It has the same data represented visually:

References node

Let's look at what a dependency failure looks like:

Here's the project.json

{
    "version": "1.0.0-*",
    "dependencies": {
        "Newtonsoft.Json": "8.0.0"
    },

    "frameworks" : {
        "dnx451" : { 
            "dependencies": {
            }
        },
        "dnxcore50" : { 
            "dependencies": {
                "System.Runtime": "4.0.20-beta-22709"
            }
        }
    }
}

Newtonsoft.Json 8.0.0 doesn't exist. So running kpm restore shows the following:

enter image description here

When diagnosing when restore might have failed, look at the HTTP requests made, they tell you what configured package sources kpm looked in. Notice in the above image, there is a CACHE request. This is the built in caching based on the type of resource (nupkg or nuspec) and has a configurable TTL (look at kpm restore --help). If you want to force kpm to hit the remote NuGet sources, use the --no-cache flag:

KPM restore --no-cache

These errors also show up in Visual Studio in the package manager log output window:

enter image description here

Read more about NuGet.config here to learn about how packages sources work and how they affect your application.

When dependencies are unresolved, running the application will give you this:

> dnx . run
System.InvalidOperationException: Failed to resolve the following dependencies for target framework 'DNX,Version=v4.5.1':
   Newtonsoft.Json 8.0.0

Searched Locations:
  C:\Users\davifowl\Documents\Visual Studio 14\Projects\ClassLibrary39\src\{name}\project.json
  C:\Users\davifowl\Documents\Visual Studio 14\Projects\ClassLibrary39\test\{name}\project.json
  C:\Users\davifowl\.dnx\packages\{name}\{version}\{name}.nuspec
  C:\Program Files (x86)\Reference Assemblies\Microsoft\Framework\.NETFramework\v4.5.1\{name}.dll
  C:\Program Files (x86)\Reference Assemblies\Microsoft\Framework\.NETFramework\v4.5.1\Facades\{name}.dll
  C:\WINDOWS\Microsoft.NET\assembly\GAC_32\{name}\{version}\{name}.dll
  C:\WINDOWS\Microsoft.NET\assembly\GAC_64\{name}\{version}\{name}.dll
  C:\WINDOWS\Microsoft.NET\assembly\GAC_MSIL\{name}\{version}\{name}.dll

Try running 'kpm restore'.

   at Microsoft.Framework.Runtime.DefaultHost.GetEntryPoint(String applicationName)
   at Microsoft.Framework.ApplicationHost.Program.ExecuteMain(DefaultHost host, String applicationName, String[] args)
   at Microsoft.Framework.ApplicationHost.Program.Main(String[] args)

The runtime basically tries to validate that the entire dependency graph is resolved before attempting to run. If it suggests running kpm restore it's because it can't find the dependencies listed.

Another reason why you might get this error is if you're running the wrong dnx flavor. If your application only specifies dnx451 and you try to run the dnx-coreclr, you might see a similar problem. Pay close attention to the target framework in the error message:

For running:

dnx4x - runs on dnx-clr-{etc}
dnxcore50 - runs on dnx-coreclr-{etc}

When you're trying to run, you should remember that mental mapping from clr to target framework defined in your project.json.

This also shows up in Visual Studio under the references node:
Unresolved dependencies

The nodes marked as yellow are unresolved.

These also show up in the error list:

Error list unresolved dependencies

Building

These errors also show up when building. When building from the command line, the output is very verbose and can be extremely useful when diagnosing problems:

> kpm build

Building ClassLibrary39 for DNX,Version=v4.5.1
  Using Project dependency ClassLibrary39 1.0.0
    Source: C:\Users\davifowl\Documents\Visual Studio 14\Projects\ClassLibrary39\src\ClassLibrary39\project.json

  Using Assembly dependency framework/mscorlib 4.0.0.0
    Source: C:\Program Files (x86)\Reference Assemblies\Microsoft\Framework\.NETFramework\v4.5.1\mscorlib.dll

  Using Assembly dependency framework/System 4.0.0.0
    Source: C:\Program Files (x86)\Reference Assemblies\Microsoft\Framework\.NETFramework\v4.5.1\System.dll

  Using Assembly dependency framework/System.Core 4.0.0.0
    Source: C:\Program Files (x86)\Reference Assemblies\Microsoft\Framework\.NETFramework\v4.5.1\System.Core.dll

  Using Assembly dependency framework/Microsoft.CSharp 4.0.0.0
    Source: C:\Program Files (x86)\Reference Assemblies\Microsoft\Framework\.NETFramework\v4.5.1\Microsoft.CSharp.dll


Building ClassLibrary39 for DNXCore,Version=v5.0
  Using Project dependency ClassLibrary39 1.0.0
    Source: C:\Users\davifowl\Documents\Visual Studio 14\Projects\ClassLibrary39\src\ClassLibrary39\project.json

  Using Package dependency System.Console 4.0.0-beta-22709
    Source: C:\Users\davifowl\.dnx\packages\System.Console\4.0.0-beta-22709
    File: lib\contract\System.Console.dll

  Using Package dependency System.IO 4.0.10-beta-22231
    Source: C:\Users\davifowl\.dnx\packages\System.IO\4.0.10-beta-22231
    File: lib\contract\System.IO.dll

  Using Package dependency System.Runtime 4.0.20-beta-22231
    Source: C:\Users\davifowl\.dnx\packages\System.Runtime\4.0.20-beta-22231
    File: lib\contract\System.Runtime.dll

  Using Package dependency System.Text.Encoding 4.0.10-beta-22231
    Source: C:\Users\davifowl\.dnx\packages\System.Text.Encoding\4.0.10-beta-22231
    File: lib\contract\System.Text.Encoding.dll

  Using Package dependency System.Threading.Tasks 4.0.10-beta-22231
    Source: C:\Users\davifowl\.dnx\packages\System.Threading.Tasks\4.0.10-beta-22231
    File: lib\contract\System.Threading.Tasks.dll

The output shows all of the assemblies passed into the compiler from packages and project references. When you start getting build failures, it's useful to look here to make sure that the package you are using actually works on that target platform.

Here's an example of a package that doesn't work on dnxcore50:

{
    "version": "1.0.0-*",
    "dependencies": {
        "Microsoft.Owin.Host.SystemWeb": "3.0.0"
    },

    "frameworks": {
        "dnx451": {
            "dependencies": {
            }
        },
        "dnxcore50": {
            "dependencies": {
                "System.Console": "4.0.0-beta-22709"
            }
        }
    }
}

Microsoft.Owin.Host.SystemWeb version 3.0.0 does not have any assemblies that run on dnxcore50 (take a look at the unzipped package's lib folder). When we run kpm build:

Missing assemblies on dnxcore50

Notice it says using Package Microsoft.Owin.Host.SystemWeb but there is not File:. This could be the reason for a build failure.

Building in Visual Studio

One thing I didn't mention was the fact that building in visual studio uses a different code path completely. Within visual studio, there is a process that runs called the Design Time Host. It's an instance of the DNX that Visual Studio and Omnisharp use to drive intellisense and diagnostics for project.json based projects. In theory, the command line and Visual Studio should act the same, but things have bugs so let's dive into how you can get more data from the project system when things go wrong.

The magic environment variable you need to set to see everything in Visual Studio, is the same as the runtime switch set DNX_TRACE=1 or KRE_TRACE=1 if you're running on CTP6. Set that in the command line and launch Visual Studio, open up an ASP.NET class library, go to the output window and look for the dnx.exe log (klr.exe log on CTP6):

Here's an example of what it dumps out (truncated):

Information: [ApplicationContext]: OnTransmit(References)  
Information: [ProcessingQueue]: Send((11e4cd605fbb487dbb4b63650494e550, References, 1) -> {  
  "Framework": {
    "FrameworkName": "DNXCore,Version=v5.0",
    "FriendlyName": "DNX Core 5.0",
    "ShortName": "dnxcore50",
    "RedistListPath": null
  },
  "ProjectReferences": [],
  "FileReferences": [
    "C:\\Users\\davifowl\\.dnx\\packages\\System.Console\\4.0.0-beta-22709\\lib\\contract\\System.Console.dll",
    "C:\\Users\\davifowl\\.dnx\\packages\\System.IO\\4.0.10-beta-22231\\lib\\contract\\System.IO.dll",
    "C:\\Users\\davifowl\\.dnx\\packages\\System.Runtime\\4.0.20-beta-22231\\lib\\contract\\System.Runtime.dll",
    "C:\\Users\\davifowl\\.dnx\\packages\\System.Text.Encoding\\4.0.10-beta-22231\\lib\\contract\\System.Text.Encoding.dll",
    "C:\\Users\\davifowl\\.dnx\\packages\\System.Threading.Tasks\\4.0.10-beta-22231\\lib\\contract\\System.Threading.Tasks.dll"
  ],
  "RawReferences": {}
})
Information: [ApplicationContext]: OnTransmit(Sources)  
Information: [ProcessingQueue]: Send((11e4cd605fbb487dbb4b63650494e550, Sources, 1) -> {  
  "Framework": {
    "FrameworkName": "DNXCore,Version=v5.0",
    "FriendlyName": "DNX Core 5.0",
    "ShortName": "dnxcore50",
    "RedistListPath": null
  },
  "Files": [
    "C:\\Users\\davifowl\\documents\\visual studio 14\\Projects\\ClassLibrary39\\src\\ClassLibrary39\\Class1.cs"
  ],
  "GeneratedFiles": null
})

This is the resolved references and the source files for the project.json file. When you build in VS, you can see actually see the MSBuild task, call out to the out of process dnx.exe asking it for errors and warnings:

To disable this build (which you may want to do just to verify that the issue isn't Design time host specific), go to the property pages build page and select Produce Outputs on build:

Now build should show the same output as the command line:

Happy Debugging!

comments powered by Disqus