Diagnosing Marshaling Errors using Interop Logging
In a previous post I described how the Loader Log can be used to help diagnose problems such as assembly load failures, version mismatches and so on (https://blogs.msdn.com/stevenpr/archive/2005/02/28/381744.aspx ). Another critical element of our new diagnostics feature set in Whidbey is Interop Logging.
Interop logging was added in response to the huge number of questions and support calls we’ve seen over the last few years related to PInvoke. If you’ve used PInvoke to call a native function from your managed application, you’ve likely seen how easy it is to get the managed definition of your native function incorrect, leading the marshaling errors at runtime. In fact, the difficulty in matching native and managed definitions is a significant enough issue that an entire site now exists to help you get this right. Check out www.pinvoke.net for the managed definitions of many of the Win32 APIs. Help with both WindowsCE and “desktop” definitions is available.
In this post, I’ll show you how our new Interop logging feature makes it much easier to diagnose errors encountered when using PInvoke or COM interop to call native code from your .Net Compact Framework application. In many ways, Interop logging is the Compact Framework’s equivalent to the Interop Customer Debug Probe (aka Managed Debug Assistant) offered by the full .Net Framework (https://blogs.msdn.com/adam_nathan/archive/2003/05/13/56680.aspx ).
Enabling the Interop Log
Interop logging is enabled and configured by setting a series of registry keys. At a minimum, you must set two keys: one to enable the CLR’s overall logging feature and one to specifically enable interop logging.
To enable CLR logging, set the following DWORD value to 1:
HKLM\Software\Microsoft\.NETCompactFramework\Diagnostics\Logging\Enabled
To specifically enable interop logging, the following DWORD value must be set to 1:
HKLM\Software\Microsoft\.NETCompactFramework\Diagnostics\Logging\Interop\Enabled
When these two keys are set, the CLR will create a file named netcf_Interop.log in the same directory as your application.
There are a few other values you can set to customize how the log file is named and how eagerly it is written to. If you saw my earlier post on Loader logging, these values should look familiar as they apply to all logging done by the Compact Framework. These values (all DWORDs) are:
· HKLM\Software\Microsoft\.NETCompactFramework\Diagnostics\Logging\UseApp
The UseApp value causes the name of the application to be included in the name of the log file. For example, if I’m running an application called BankClient.exe, setting the UseApp value to 1 will cause the log file to be named netcf_BankClient_Interop.log. The UseApp value is useful if you enable logging and have several applications installed in the same directory.
· HKLM\Software\Microsoft\.NETCompactFramework\Diagnostics\Logging\UsePid
The UsePid value causes the process’s ID to be included in the name of the log file. As with UseApp, the UsePid value is useful if you enable logging and have several applications installed in the same directory.
· HKLM\Software\Microsoft\.NETCompactFramework\Diagnostics\Logging\Flush
Setting the Flush value to 1 will cause the CLR to write log events to the log file as they occur instead of buffering them up. Flushing eagerly negatively affects performance, but it can be useful in case you’re not getting the data you need in the log file because of application crashes or other errors.
What’s in the Interop Log?
The Interop log contains two primary pieces of information:
· The managed and native function signatures for all calls that cross an interop boundary. That is, both calls from managed code to native code and calls from native back into managed.
· Errors returned to native callers from managed code. This category of logging is particularly useful when diagnosing errors you get when calling a managed object from native code using Com Interop.
In addition to these two general categories of information, the Interop log also contains data about scenarios the Compact Framework doesn’t support which would otherwise be very hard to diagnose. For example, interfaces implemented in managed code cannot be called from Com if the interface contains any generic methods. Trying to call methods on such an interface will generate error text in the Interop log.
The Interop log contains three lines for every call that uses either Pinvoke or Com Interop. Here’s an example:
[pinvokeimpl][preservesig]
int Sample.Form1:: NativeFunction (int , string);
int (I4_VAL) NativeFunction (int (I4_VAL) , WCHAR * (STRING_LPWSTR) );
The first line is a set of flags that describes the call. In the example above, the [pinvokeimpl] flag indicates that this call is a PInvoke. A value of [delegate] indicates a call from native code to managed code through a delegate that was marshaled to native code as a pointer to a function. The absence of a value altogether signifies a call through Com Interop.
The second line is the managed definition of the native function being called. In this case, you can see that the native function was declared in managed code as taking two parameters, an int and a string, and returning an int.
The third line is the native definition of the function as understood by the Compact Framework. In this case, we can see that the managed string argument is being marshaled to native code as a pointer to a Unicode string, for example.
For calls that include error information, the text describing the error, including the error value is written either just before or just after the call information.
Diagnosing Marshaling Errors
The native function signature (the 3rd line from our description above) is the most useful when diagnosing marshaling errors that occur when you are calling native code either through PInvoke or Com Interop. The Compact Framework does not have intrinsic knowledge of the native function you are calling – it simply takes the managed definition you’ve provided and creates an equivalent native signature. If this signature doesn’t match the actual signature of the targeted native function, a marshaling error will occur. These errors are fixed by changing your managed definition to match the actual native function signature.
Here’s an example. Let’s assume we’re using PInvoke to call a native function with the following signature (in C):
int NativeFunction(long value);
In managed code, we declare NativeFunction as follows:
[DllImport("Sample.dll")]
static extern int NativeFunction(long value);
Calling NativeFunction from managed code, gives us the following entries in the Interop log:
[pinvokeimpl][preservesig]
int Sample.Form1:: NativeFunction (long);
int (I4_VAL) NativeFunction (INT64 (I8_VAL) );
Can you see the marshaling error? The C definition of NativeFunction takes a single long as a parameter. Variables of type long is C/C++ are 32 bits (I’m on x86). However, the long type in C# is 64 bits. By looking at the 3rd line of our Interop log, we can see that the .Net Compact Framework is marshaling the long parameter as a 64 bit value, when the native function is expecting only a 32 bit value. In this case, an extra 4 bytes will be pushed on the stack as the call is made.
Fixing this problem involves defining the parameter to NativeFunction as an int in managed code like so:
[DllImport("Sample.dll")]
static extern int NativeFunction(int value);
Now everything lines up at call time according to the interop log:
[pinvokeimpl][preservesig]
int Sample.Form1:: NativeFunction (long);
int (I4_VAL) NativeFunction (int (I4_VAL) );
Even with this simple example it’s easy to see how easy it is to make mistakes when writing the managed definitions of unmanaged functions. These problems are easier to diagnose now that the interop log tells you exactly how the data is being marshaled.
COM Error Information
As described, the other major purpose of the Interop log is to help diagnose errors returned from calls made through COM interop. This is particularly useful when calling from native code into managed code mostly because the Compact Framework implements several COM interfaces on your object’s behalf.
The following log entries show the result of a failed called to QueryInterface on a managed object. As you can see, the log includes the GUID of the interface that the Compact Framework couldn’t return.
[no flags]
void BankObjectsLib.IAccount::Withdraw(BankObjectsLib.IAccount , int );
HRESULT Withdraw(IAccount *(INTF_VAL) this, int (I4_VAL) );
ERROR: CCW IUnknown::QueryInterface Error: 0x80004002 {06FAF1B7-66B8-4FFC-9396-A0FD3C01E75C}
This case is perhaps oversimplified if you own the native code that is making the call. In that case, you presumably know which interface you are querying for can just check the HRESULT in code. However, this logging really pays off in situations where you are using a COM object or ActiveX control that you don’t own. In scenarios like this, it’s not uncommon to find the object querying for interfaces or using other COM features that you didn’t expect.
Logging information about COM errors also helps you in case you attempt to use a feature that the Compact Framework doesn’t support. For example, we don’t support the ability to get type information by calling IDispatch::GetTypeInfo. Attempts to use GetTypeInfo will be clearly displayed in the Interop log. By the way, I’m currently gathering a list of all such unsupported features and hope to post it soon.
Comment or email with questions as always. Thanks,
Steven
This posting is provided "AS IS" with no warranties, and confers no rights.