Using NETCF Loader Logs to solve start issues

I hope you folks all had a great Christmas. While digging out of email today, I was going through my list of blog ideas to find a tip I could quickly share…and ran across...

NETCF Loader logs. Ah!, good one!

If you write and distribute a managed application, I highly recommend you enable some of the NETCF logs to learn more about what is going on with your app. You might find some surprises. NETCF now supports Finalizer, Interop, Loader, Networking, Trace logging, and more. Loader logs can be an eye opener. I often hear people complain about startup time with managed apps. The NETCF runtime really is a pretty amazing little beast and does a great job at many things. It can also do a good job of hiding some of the reasons your app may be slower than necessary when starting up. Good code design is part of it, but component dependencies can also throw you for a loop. Let’s also take that one step farther and talk about the scenario where a NETCF app completely fails to start. That’s certainly not the norm, but it does happen on occasion. Why? That’s a very good question and unless you look at a Loader log, you will probably run in circles.

I recently helped an ISV with one of these issues I thought would make a good example. They built an app on NETCF 1.x and found that it was failing on new WM6 devices. After selecting the application icon, they would see several seconds of a wait cursor and then… nothing. Since the new device was a WM6 unit (with NETCF 2.x in ROM), they suspected the problem was a backward compatibility issues running their NETCF 1.x app on NETCF 2.x. NETCF has a great back-compat story, so I had my doubts about that theory. We tried using a config file to force compatibility against v1 and it still failed. Hmmm… something else going on here. I decided to use a Loader log to see what was going on.

I enabled Loader logging on the emulator so I could get a trace of what was failing when we start. To do this, you just create a few registry keys using Remote Registry Editor on the device or emulator:

https://msdn.microsoft.com/en-us/library/ms229650.aspx

Then I simply started the app again, let it fail, and examined the loader log from the emulator.

…

========================================

Process [\Program Files\SomeApp\SomeApp.exe]

ProcessID [0x16f8a3c2]

Date [2008/09/17] (yyyy/mm/dd)

Time [19:04:43] (hh:mm:ss)

NETCF [2.0.6129.00]

Platform [Windows CE v5.2.318 (PocketPC) WinCE5ARMV4I release V2\SP1 ARMV4I IJITv2]

========================================

…

Redirecting [System.Windows.Forms, Version=1.0.5000.0, Culture=neutral, PublicKeyToken=969DB8053D3322AC] to [System.Windows.Forms, Version=2.0.0.0, Culture=neutral, PublicKeyToken=969DB8053D3322AC]

Loading module [\windows\GAC_System.Windows.Forms_v2_0_0_0_cneutral_1.dll]

Loaded [System.Windows.Forms, Version=2.0.0.0, Culture=neutral, PublicKeyToken=969DB8053D3322AC] from [\windows\GAC_System.Windows.Forms_v2_0_0_0_cneutral_1.dll]

…

Loaded [EdtFtpNet, Version=1.0.1.1, Culture=neutral, PublicKeyToken=null] from [\Program Files\SomeApp\3rdParty.dll]

Loading module [\Program Files\SomeApp\System.dll]

Attempt to load [\Program Files\SomeApp\System.dll] has failed (err 0x80001000).

Loading module [\Program Files\SomeApp\System.exe]

Attempt to load [\Program Files\SomeApp\System.exe] has failed (err 0x80001000).

Loading module [\Program Files\SomeApp\System.dll]

Attempt to load [\Program Files\SomeApp\System.dll] has failed (err 0x80001000).

Loading module [\Program Files\SomeApp\System.exe]

Attempt to load [\Program Files\SomeApp\System.exe] has failed (err 0x80001000).

Failed to load [System, Version=1.0.5000.0, Culture=neutral, PublicKeyToken=B77A5C561934E089]

(this occurs over and over again which is the lengthy hourglass)

B77A5C561934E089 is the token to the desktop assembly of System.dll…not the NETCF version. When I ran ILDASM.EXE, pulled in 3rdParty.dll, clicked on the manifest I found:

.assembly extern mscorlib

{

  .publickeytoken = (B7 7A 5C 56 19 34 E0 89 ) // .z\V.4..

  .ver 1:0:5000:0

}

.assembly extern System

{

  .publickeytoken = (B7 7A 5C 56 19 34 E0 89 ) // .z\V.4..

  .ver 1:0:5000:0

}

What happened? Somehow, they managed to add a reference to the desktop versions of the .NET runtime into their application. In almost every case where I have seen a NETCF app fail to start, it's usually a dependency on a assembly that is not present on the device. Some of the earlier version of NETCF were pretty forgiving about this (would ignore them)... the later versions will stop the load and terminate on bad assembly references. If you use a loader file, you can see the debug output of the load process and identify any problems like this.

Once they removed the desktop assembly references, the app worked just fine. Loader logs are great for giving you granular details about what NETCF is doing during the launch process which can be very helpful with issues like this.

Cheers,

Reed