Working with SqlAzureExecutionStrategy

One of my favorite features of Entity Framework 6 was the SqlAzureExecutionStrategy. At least I thought this. I wanted to use it also in my company’s network since we get periodically timeouts connecting to a SQL Server instance (SQL Server 2008 in this case). So I thought, perfect, the SqlAzureExecutionStrategy is the solution to my problem. However, it didn’t work. So I had to investigate...

My approach was to write a sample program starting two tasks:

• Task 1 should open a transaction, update a database row and then wait for some time (without committing or rolling back the transaction)
• Task 2 should try to modify the same database row during Task 1’s wait time

Without any further preparation, this approach raised an exception in Task 2:

System.Data.SqlClient.SqlException (0x80131904): Timeout expired.  The timeout period elapsed prior to completion of the operation or the server is not responding. ---> System.ComponentModel.Win32Exception (0x80004005): The wait operation timed out

Next I added my own implementation of DbConfiguration, which simply configured the execution strategy:

public class MyDbConfiguration : DbConfiguration
{
  public MyDbConfiguration()
  {
    this.SetExecutionStrategy("System.Data.SqlClient", () => new SqlAzureExecutionStrategy()); 
  }
}

Unfortunately, this approach did not work since the "retrying execution strategies" do not support user-initiated transactions (see Limitations with Retrying Execution Strategies (EF6 onwards)). To my rescue, the mentioned article describes also a workaround which prevents the usage of the SqlAzureExecutionStrategy together with the transaction:

public class MyDbConfiguration : DbConfiguration
{
  public MyDbConfiguration()
  {
    this.SetExecutionStrategy("System.Data.SqlClient", () => SuspendExecutionStrategy
      ? (IDbExecutionStrategy)new DefaultExecutionStrategy()
      : new SqlAzureExecutionStrategy()); 
  }
  public static bool SuspendExecutionStrategy
  {
    get { return (bool?)CallContext.LogicalGetData("SuspendExecutionStrategy") ?? false; }
    set { CallContext.LogicalSetData("SuspendExecutionStrategy", value); }
  }
}

Now the program was running again, but I still got the SqlException with the timeout. Therefore I now added some database logging, another great feature of Entity Framework 6 (see Logging and Intercepting Database Operations). The log was interesting, since it provided some additional insights. But with my special problem, it was not really useful.

10:49:56,117 Task 1: UPDATE [dbo].[T_Message] SET [LastUpdate] = @0 WHERE ([Messageid] = @1)
10:49:56,119 Task 1: -- @0: '3/5/2014 10:49:56 AM' (Type = DateTime2)
10:49:56,119 Task 1: -- @1: '3621840d-724e-4a62-b22a-accb215dfb1b' (Type = Guid)
10:49:56,120 Task 1: -- Executing at 3/5/2014 10:49:56 AM +01:00
10:49:56,130 Task 1: -- Completed in 6 ms with result: 1
10:49:56,430 Task 2: UPDATE [dbo].[T_Message] SET [LastUpdate] = @0 WHERE ([Messageid] = @1)
10:49:56,431 Task 2: -- @0: '3/5/2014 10:49:56 AM' (Type = DateTime2)
10:49:56,431 Task 2: -- @1: '3621840d-724e-4a62-b22a-accb215dfb1b' (Type = Guid)
10:49:56,431 Task 2: -- Executing at 3/5/2014 10:49:56 AM +01:00
10:50:01,557 Task 2: -- Failed in 5124 ms with error: Timeout expired.  The timeout period elapsed pr...
10:50:01,732 Task 2: update failed
System.Data.Entity.Infrastructure.DbUpdateException: An error occurred while updating the entries. See the inner exception for details. ---> System.Data.Entity.Core.UpdateException: An error occurred while updating the entries. See the inner exception for details. ---> System.Data.SqlClient.SqlException: Timeout expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
The statement has been terminated. ---> System.ComponentModel.Win32Exception: The wait operation timed out

Then I had a look at the source code of SqlAzureExecutionStrategy. Its implementation consists of mainly one method:

protected override bool ShouldRetryOn(Exception exception)
{
  return SqlAzureRetriableExceptionDetector.ShouldRetryOn(exception);
}

Since the method is protected, I decided to implement my own strategy derived from SqlAzureExecutionStrategy. In the first step, I simply implemented my own ShouldRetryOn method, which I used for setting a breakpoint. I found out that the method was called with the SqlException, but SqlAzureExecutionStrategy's implementation returned false.

SqlAzureExecutionStrategy delegates the check of the exception to SqlAzureRetriableExceptionDetector. As you can see in the source code, it returns true for TimeoutException and for SqlException with a specific SqlError. However, "my" SqlException has a SqlError with Number == -2, for which false is returned.

Now I added some real logic to my strategy:

protected override bool ShouldRetryOn(Exception exception)
{
  bool shouldRetry = false;

  SqlException sqlException = exception as SqlException;
  if (sqlException != null)
  {
    foreach (SqlError error in sqlException.Errors)
    {
      if (error.Number == -2)
        shouldRetry = true;
    }
  }

  shouldRetry = shouldRetry || base.ShouldRetryOn(exception);

  Logger.WriteLog("ShouldRetryOn: " + shouldRetry);
  return shouldRetry;
}

With this implementation I had two benefits:

• The connection attempt was retried also in my deadlock scenario.
  
• I got a log entry for every retry.
  

Now I got a "beautiful" trace of my retry activities. And also an explicit exception, when the problem couldn’t be solved by simply retrying it:

10:56:15,805 Task 1: UPDATE [dbo].[T_Message] SET [LastUpdate] = @0 WHERE ([Messageid] = @1)
10:56:15,807 Task 1: -- @0: '3/5/2014 10:56:15 AM' (Type = DateTime2)
10:56:15,808 Task 1: -- @1: '4e3554be-1e13-461b-af12-848575317beb' (Type = Guid)
10:56:15,808 Task 1: -- Executing at 3/5/2014 10:56:15 AM +01:00
10:56:15,816 Task 1: -- Completed in 5 ms with result: 1
10:56:15,823 Task 2: UPDATE [dbo].[T_Message] SET [LastUpdate] = @0 WHERE ([Messageid] = @1)
10:56:15,824 Task 2: -- @0: '3/5/2014 10:56:15 AM' (Type = DateTime2)
10:56:15,824 Task 2: -- @1: '4e3554be-1e13-461b-af12-848575317beb' (Type = Guid)
10:56:15,824 Task 2: -- Executing at 3/5/2014 10:56:15 AM +01:00
10:56:20,949 Task 2: -- Failed in 5123 ms with error: Timeout expired.  The timeout period elapsed pr...
10:56:21,046 MyExecutionStrategy: retrying
10:56:21,051 Task 2: UPDATE [dbo].[T_Message] SET [LastUpdate] = @0 WHERE ([Messageid] = @1)
10:56:21,051 Task 2: -- @0: '3/5/2014 10:56:15 AM' (Type = DateTime2)
10:56:21,052 Task 2: -- @1: '4e3554be-1e13-461b-af12-848575317beb' (Type = Guid)
10:56:21,052 Task 2: -- Executing at 3/5/2014 10:56:21 AM +01:00
10:56:26,137 Task 2: -- Failed in 5083 ms with error: Timeout expired.  The timeout period elapsed pr...
10:56:26,219 MyExecutionStrategy: retrying
10:56:27,241 Task 2: UPDATE [dbo].[T_Message] SET [LastUpdate] = @0 WHERE ([Messageid] = @1)
10:56:27,241 Task 2: -- @0: '3/5/2014 10:56:15 AM' (Type = DateTime2)
10:56:27,242 Task 2: -- @1: '4e3554be-1e13-461b-af12-848575317beb' (Type = Guid)
10:56:27,242 Task 2: -- Executing at 3/5/2014 10:56:27 AM +01:00
10:56:32,323 Task 2: -- Failed in 5080 ms with error: Timeout expired.  The timeout period elapsed pr...
10:56:32,404 MyExecutionStrategy: retrying
10:56:35,653 Task 2: UPDATE [dbo].[T_Message] SET [LastUpdate] = @0 WHERE ([Messageid] = @1)
10:56:35,653 Task 2: -- @0: '3/5/2014 10:56:15 AM' (Type = DateTime2)
10:56:35,653 Task 2: -- @1: '4e3554be-1e13-461b-af12-848575317beb' (Type = Guid)
10:56:35,654 Task 2: -- Executing at 3/5/2014 10:56:35 AM +01:00
10:56:40,737 Task 2: -- Failed in 5083 ms with error: Timeout expired.  The timeout period elapsed pr...
10:56:40,822 MyExecutionStrategy: retrying
10:56:47,901 Task 2: UPDATE [dbo].[T_Message] SET [LastUpdate] = @0 WHERE ([Messageid] = @1)
10:56:47,901 Task 2: -- @0: '3/5/2014 10:56:15 AM' (Type = DateTime2)
10:56:47,901 Task 2: -- @1: '4e3554be-1e13-461b-af12-848575317beb' (Type = Guid)
10:56:47,902 Task 2: -- Executing at 3/5/2014 10:56:47 AM +01:00
10:56:52,982 Task 2: -- Failed in 5080 ms with error: Timeout expired.  The timeout period elapsed pr...
10:56:53,066 MyExecutionStrategy: retrying
10:57:08,527 Task 2: UPDATE [dbo].[T_Message] SET [LastUpdate] = @0 WHERE ([Messageid] = @1)
10:57:08,529 Task 2: -- @0: '3/5/2014 10:56:15 AM' (Type = DateTime2)
10:57:08,530 Task 2: -- @1: '4e3554be-1e13-461b-af12-848575317beb' (Type = Guid)
10:57:08,531 Task 2: -- Executing at 3/5/2014 10:57:08 AM +01:00
10:57:13,615 Task 2: -- Failed in 5082 ms with error: Timeout expired.  The timeout period elapsed pr...
10:57:13,699 MyExecutionStrategy: retrying
10:57:13,745 Task 2: update failed
System.Data.Entity.Infrastructure.RetryLimitExceededException: Maximum number of retries (5) exceeded while executing database operations with 'MyExecutionStrategy'. See inner exception for the most recent failure. ---> System.Data.Entity.Core.UpdateException: An error occurred while updating the entries. See the inner exception for details. ---> System.Data.SqlClient.SqlException: Timeout expired.  The timeout period elapsed prior to completion of the operation or the server
is not responding.
The statement has been terminated. ---> System.ComponentModel.Win32Exception: The wait operation timed out

As you can see, the System.Data.Entity.Infrastructure.DbUpdateException was changed now into a System.Data.Entity.Infrastructure.RetryLimitExceededException. The inner System.Data.Entity.Core.UpdateException remains the same.

My final issue was that I did misunderstand the optional parameters of SqlAzureExecutionStrategy: maxRetryCount is simply the maximum number of retries. But with maxDelay it is more complicated. The delay between the retries is connected to retry number and the power of 2. This results in the following delay intervals (ignoring some minor random stuff):
0, 1, 3, 7, 15, 31, 63, ... (seconds)
You can see the delay also in the trace above: the timespan between "MyExecutionStrategy: retrying" and "Task 2: UPDATE ...".

maxDelay does not set the duration of the complete operation (from first try until last retry). This was my expectation. Instead it limits only the delay between two retries. With a maxDelay of 5, we get par example:
0, 1, 3, 5, 5, 5, 5, ...

In the last trace, you can see the decreased maxDelay. And also the final success, since here Task 1 rolls back after 50 seconds:

11:06:39,953 Task 1: UPDATE [dbo].[T_Message] SET [LastUpdate] = @0 WHERE ([Messageid] = @1)
11:06:39,955 Task 1: -- @0: '3/5/2014 11:06:39 AM' (Type = DateTime2)
11:06:39,955 Task 1: -- @1: 'c5da0be6-a4a8-4018-9c8f-c1062aa9a958' (Type = Guid)
11:06:39,955 Task 1: -- Executing at 3/5/2014 11:06:39 AM +01:00
11:06:39,964 Task 1: -- Completed in 4 ms with result: 1
11:06:39,971 Task 2: UPDATE [dbo].[T_Message] SET [LastUpdate] = @0 WHERE ([Messageid] = @1)
11:06:39,971 Task 2: -- @0: '3/5/2014 11:06:39 AM' (Type = DateTime2)
11:06:39,972 Task 2: -- @1: 'c5da0be6-a4a8-4018-9c8f-c1062aa9a958' (Type = Guid)
11:06:39,972 Task 2: -- Executing at 3/5/2014 11:06:39 AM +01:00
11:06:45,097 Task 2: -- Failed in 5123 ms with error: Timeout expired.  The timeout period elapsed pr...
11:06:45,193 MyExecutionStrategy: retrying
11:06:45,199 Task 2: UPDATE [dbo].[T_Message] SET [LastUpdate] = @0 WHERE ([Messageid] = @1)
11:06:45,199 Task 2: -- @0: '3/5/2014 11:06:39 AM' (Type = DateTime2)
11:06:45,199 Task 2: -- @1: 'c5da0be6-a4a8-4018-9c8f-c1062aa9a958' (Type = Guid)
11:06:45,200 Task 2: -- Executing at 3/5/2014 11:06:45 AM +01:00
11:06:50,283 Task 2: -- Failed in 5082 ms with error: Timeout expired.  The timeout period elapsed pr...
11:06:50,368 MyExecutionStrategy: retrying
11:06:51,427 Task 2: UPDATE [dbo].[T_Message] SET [LastUpdate] = @0 WHERE ([Messageid] = @1)
11:06:51,427 Task 2: -- @0: '3/5/2014 11:06:39 AM' (Type = DateTime2)
11:06:51,427 Task 2: -- @1: 'c5da0be6-a4a8-4018-9c8f-c1062aa9a958' (Type = Guid)
11:06:51,428 Task 2: -- Executing at 3/5/2014 11:06:51 AM +01:00
11:06:56,510 Task 2: -- Failed in 5080 ms with error: Timeout expired.  The timeout period elapsed pr...
11:06:56,593 MyExecutionStrategy: retrying
11:06:59,686 Task 2: UPDATE [dbo].[T_Message] SET [LastUpdate] = @0 WHERE ([Messageid] = @1)
11:06:59,687 Task 2: -- @0: '3/5/2014 11:06:39 AM' (Type = DateTime2)
11:06:59,687 Task 2: -- @1: 'c5da0be6-a4a8-4018-9c8f-c1062aa9a958' (Type = Guid)
11:06:59,687 Task 2: -- Executing at 3/5/2014 11:06:59 AM +01:00
11:07:04,772 Task 2: -- Failed in 5083 ms with error: Timeout expired.  The timeout period elapsed pr...
11:07:04,853 MyExecutionStrategy: retrying
11:07:09,858 Task 2: UPDATE [dbo].[T_Message] SET [LastUpdate] = @0 WHERE ([Messageid] = @1)
11:07:09,858 Task 2: -- @0: '3/5/2014 11:06:39 AM' (Type = DateTime2)
11:07:09,859 Task 2: -- @1: 'c5da0be6-a4a8-4018-9c8f-c1062aa9a958' (Type = Guid)
11:07:09,859 Task 2: -- Executing at 3/5/2014 11:07:09 AM +01:00
11:07:14,939 Task 2: -- Failed in 5079 ms with error: Timeout expired.  The timeout period elapsed pr...
11:07:15,023 MyExecutionStrategy: retrying
11:07:20,028 Task 2: UPDATE [dbo].[T_Message] SET [LastUpdate] = @0 WHERE ([Messageid] = @1)
11:07:20,029 Task 2: -- @0: '3/5/2014 11:06:39 AM' (Type = DateTime2)
11:07:20,030 Task 2: -- @1: 'c5da0be6-a4a8-4018-9c8f-c1062aa9a958' (Type = Guid)
11:07:20,031 Task 2: -- Executing at 3/5/2014 11:07:20 AM +01:00
11:07:25,113 Task 2: -- Failed in 5080 ms with error: Timeout expired.  The timeout period elapsed pr...
11:07:25,196 MyExecutionStrategy: retrying
11:07:29,968 Task 1: rolling back
11:07:29,975 Task 1: rolled back
11:07:30,201 Task 2: UPDATE [dbo].[T_Message] SET [LastUpdate] = @0 WHERE ([Messageid] = @1)
11:07:30,202 Task 2: -- @0: '3/5/2014 11:06:39 AM' (Type = DateTime2)
11:07:30,204 Task 2: -- @1: 'c5da0be6-a4a8-4018-9c8f-c1062aa9a958' (Type = Guid)
11:07:30,204 Task 2: -- Executing at 3/5/2014 11:07:30 AM +01:00
11:07:30,208 Task 2: -- Completed in 2 ms with result: 1

FInally, I was even more enthusiatstic with SqlAzureExecutionStrategy than before. And I hope, you are, too.

log4javascript and ASP.NET Web Api

log4javascript is a nice logging framework for JavaScript. With it you can log to the browser console (if supported by the browser), but also to an own window and even to the server via AJAX calls. For the latter, you need also something on the server which can handle the AJAX requests. Here I wanted to use ASP.NET Web Api. Since I didn’t find any documentation on this specific topic, I want to share my experiences here.

In general, the whole stuff is quite easy. On the client side you have to define the AjaxAppender:

var ajaxAppender = new log4javascript.AjaxAppender(serverUrl);
ajaxAppender.setLayout(new log4javascript.JsonLayout());
ajaxAppender.addHeader("Content-Type", "application/json; charset=utf-8");

I thought, with Web Api JSON would be the most natural data format. The more tricky line is the last one. Without it, the Content-Type header has the value application/x-www-form-urlencoded. This causes Web Api to use the JQueryMvcFormUrlEncodedFormatter. Unfortunately, this formatter cannot handle the JSON formatted data.
After specifying the correct content type, Web Api uses the JsonMediaTypeFormatter. And everything is fine.

On the server side, I first had to define the structure of the log data:

public struct LogEntry
{
  public string Logger;
  public long Timestamp;
  public string Level;
  public string Url;
  public string Message;
}

Since log4javascript can send more than one log entry in one AJAX call, my logging method gets an array of LogEntry instances. Additionally I needed to convert the timestamp value, since log4javascript sends it in milliseconds since 01-Jan-1970:

public void Write(LogEntry[] data)
{
  if (data != null)
  {
    foreach (LogEntry entry in data)
    {
      DateTime timestampUtc = new DateTime(1970, 1, 1, 0, 0, 0, DateTimeKind.Utc).AddMilliseconds(entry.Timestamp);
      DateTime timestampLocal = timestampUtc.ToLocalTime();
      ...
    }
  }
}

That’s it!

Registration-Free COM with ActiveX Controls

In my current project, I have beside other things, a form with an ActiveX control on it. Additionally, I am using registration free COM, meaning that the COM information is stored in a manifest file instead of the registry.

Everything worked fine, until I tried to create the form a second time. Also this worked without problems, but not in the Visual Studio debugger. Here I got the strange exception:

System.NotSupportedException: Unable to get the window handle for the 'xxx' control. Windowless ActiveX controls are not supported.
at System.Windows.Forms.AxHost.EnsureWindowPresent()
at System.Windows.Forms.AxHost.InPlaceActivate()
at System.Windows.Forms.AxHost.TransitionUpTo(Int32 state)
at System.Windows.Forms.AxHost.CreateHandle()
at System.Windows.Forms.Control.CreateControl(Boolean fIgnoreVisible)
at System.Windows.Forms.Control.CreateControl(Boolean fIgnoreVisible)
at System.Windows.Forms.AxHost.EndInit()

After hours of thinking, debugging, code stripping and so on (to be honest, mainly from a colleague of me), we found the solution: the used manifest was not complete. The manifest was created using mt.exe with the typelib of the control. This manifest looked like

<file name="..." hashalg="SHA1">
  <comClass clsid="..." tlbid="..." description="..." />
  <typelib tlbid="..." version="..." helpdir="" />
</file>

When we compared this with the entries in the registry, we saw in the registry much more things. And also in the assembly manifest documentation are more attributes mentioned. Therefore we tried to add as much attributes to the manifest as possible (even if we did not understand every bit completely). And viola, now the error was gone!

In total, we added 4 attributes (in our case):

<file name="..." hashalg="SHA1">
  <comClass clsid="..." tlbid="..." description="..." threadingModel="..." progid="..." miscStatus="..." />
  <typelib tlbid="..." version="..." helpdir="" flags="..." />
</file>

I hope this could help, if you have a similar issue.

AppDomains and user.config

Previously I had a problem with an application using different AppDomains. In one AppDomain I wrote some settings to an user.config file. And then I got in another AppDomain the following exception:
System.Configuration.ConfigurationErrorsException: Configuration system failed to initialize
---> System.Configuration.ConfigurationErrorsException: Unrecognized configuration section userSettings. (C:\Users\uuuuuuuu\AppData\Local\cccccc\aaaaaaaaaaaaaa_Url_4v0elz3yo0gytsdhg5vusobffefqs0so\1.0.0.0\user.config line 3)

This was very strange since in this AppDomain I even didn’t use any user.config. After some hours of investigation, I found the problem. The user.config file will be written to

<Profile Directory>\<Company Name>\<App Domain>_<Evidence Type>_<Evidence Hash>\<Version>\user.config

• <Profile Directory>: %APPDATA% or %LOCALAPPDATA%
• <Company Name>: value of AssemblyCompanyAttribute, trimmed to 25 characters, invalid characters replaced by '_'
• <App Domain>: friendly name of the current AppDomain, trimmed to 25 characters, invalid characters replaced by '_'
• <Evidence Type> and <Evidence Hash>: some magic from AppDomain’s evidence
• <Version>: value of AssemblyVersionAttribute

In my case, all these properties had the same value. Therefore the whole stuff got mixed up: 

• company name: ok this is by purpose the same
• version: I generated the version from the build number for all assemblies, but also this is not so uncommon
• evidence: I created the new AppDomains with
  AppDomain.CreateDomain(appDomainName, null, appDomainSetup);
  The second parameter is the evidence for the new AppDomain. If it is null, the evidence from the current AppDomain will be taken. Also understandable.
• App domain: this was the sticky point. I used for the AppDomain’s name the full name of the main assembly. Since I used a pattern like Company.Application.Subsystem..., this name was simply too long. The first 25 characters were all the same...

So the solution was quite easy: I just had to change the AppDomain’s name. But the trail to the solution took its time. Maybe this blog can accelerate your search a little bit.

BTW: Finally I checked the source code of System.Configuration.ClientConfigPaths.cs. This helped me a lot to understand the problem.

Problems with WSDL of WCF web services behind load balancer

If you have a WCF web service, you can get its WSDL by appending ?wsdl to the URL:

http://server/web/Service.svc?wsdl

Typically, the generated WSDL is not complete. The types are loaded separately from the server:

<xsd:import schemaLocation="http://server/web/Service.svc?xsd=xsd0" />

For the type import, the current machine is used. Normally this isn't a problem. But if you use a load balancer, you end up with the following requests:

http://loadbalancer/web/Service.svc?wsdl

<xsd:import schemaLocation="http://node1/web/Service.svc?xsd=xsd0" />

This will not work, when node1 is not accessible directly.
Fortunately, you can force WCF to use the Loadbalancer also in the WSDL. You only have to add one line to the serviceBehavior in the Web.config:

<behaviors>
<serviceBehaviors>
<behavior name="MyBehavior">
<useRequestHeadersForMetadataAddress />
...
</behavior>
</serviceBehaviors>
</behaviors>

.net programs on 32 and/or 64 bit machines

Generally, a .net program can run on a 32 bit machine as well as on a 64 bit machine. But sometimes it is necessary to run the program also on a 64 bit machine in 32 bit mode, the so-called WoW64.

WoW64 stands for "Windows on 64-bit Windows", and it contains all the 32-bit binary files required for compatibility, which run on top of the 64 bit Windows. So, yeah, it looks like a double copy of everything in System32 (which despite the directory name, are actually 64-bit binaries).

You will need WoW64 par example, if you want to call 32 bit ActiveX components. Visual Studio provides for this purpose the so-called platform target:

• x86
  32 bit application, runs either on Win32 or on Win64 in WoW64
• x64
  64 bit application, runs only on Win64 (not in WoW64)
• Any CPU
  runs on Win32 as 32 bit application and on Win64 as 64 bit application

This info will be stored in the PE header. At application startup, Windows checks the settings and starts the application in the appropriate mode (or not). If you want to check later, for which platform the application was built, you can use the corflags tool in Visual Studio Command Prompt:

> corflags MyApp.exe
Microsoft (R) .NET Framework CorFlags Conversion Tool.  Version  4.0.30319.1
Copyright (c) Microsoft Corporation.  All rights reserved.

Version   : v4.0.30319
CLR Header: 2.5
PE        : PE32
CorFlags  : 11
ILONLY    : 1
32BIT     : 1
Signed    : 1

The interesting parts are PE and 32BIT. The values are a little bit strange and hard to remember:

Platform target	PE	32BIT
x86	PE32	1
x64	PE32+	0
Any CPU	PE32	0

References

• CorFlags.exe (CorFlags Conversion Tool)
• Sorting Out the Confusion: 32- vs. 64-Bit, CLR vs. Native, C# vs. C++

Problem with asynchronous HttpClient methods

Recently, I wrote a client application which should send some log messages to a server. Since it was only for statistics, the log didn’t have the highest requirements on reliability. Additionally, it shouldn’t block my application. Therefore I decided to send the message asynchronously, and in case of an error only to write something to the local log file. I came up with

static void LogMessage(string message)
{
  Uri baseAddress = new Uri("http://localhost/");
  string requestUri = "uri";

  using (HttpClient client = new HttpClient { BaseAddress = baseAddress })
  {
    client.PostAsJsonAsync(requestUri, message, cancellationToken).ContinueWith(task =>
      {
        if (task.IsFaulted)
          Console.WriteLine(“Failed: “ + task.Exception);
        else if (task.IsCanceled)
          Console.WriteLine ("Canceled");
        else
        {
          HttpResponseMessage response = task.Result;
          if (response.IsSuccessStatusCode)
            Console.WriteLine("Succeeded");
          else
            response.Content.ReadAsStringAsync().ContinueWith(task2 => Console.WriteLine(“Failed with status " + response.StatusCode));
        }
      });
  }
}

This code should send the message asynchronously (PostAsJsonAsync). And afterwards it should check, if the sending was successfully or not (ContinueWith). My expectation was to see an error, since there is nothing is listening on the specified address. But I didn’t see anything. Moreover, it even didn’t send any requests. Even for my requirements, this was not enough.

After some research, I added trace switches to my config file:

<system.diagnostics>
  <switches>
    <add name="System.Net" value="Verbose"/>
    <add name="System.Net.Http" value="Verbose"/>
    <add name="System.Net.HttpListener" value="Verbose"/>
    <add name="System.Net.Sockets" value="Verbose"/>
    <add name="System.Net.Cache" value="Verbose"/>
  </switches>
</system.diagnostics>

With it, one of the last lines of my debug output was

System.Net Error: 0 : [0864] Exception in HttpWebRequest#54246671:: - The request was aborted: The request was canceled..

This led me to the evil: it was the disposing of HttpClient too early. At the end of the using block the client will be disposed. But at this time, the message has not been sent. This happens, since I do something asynchronous inside the using block without waiting for its end.

The solution to this problem is to reverse the order of using and asynchronous: if I start the using in an asynchronous way, everything is fine:

static void LogMessage(string message)
{
  Uri baseAddress = new Uri("http://localhost/");
  string requestUri = "uri";

  new TaskFactory().StartNew(() =>
    {
      using (HttpClient client = new HttpClient { BaseAddress = baseAddress })
      {
        Console.WriteLine("Sending message");
        HttpResponseMessage response = client.PostAsJsonAsync(requestUri, message).Result;

        Console.WriteLine("Evaluating response");
        if (response.IsSuccessStatusCode)
          Console.WriteLine("Succeeded");
        else
          Console.WriteLine("Failed with status " + response.StatusCode);
      }
    });
}

Here I start a new task, which does inside the using / Dispose stuff. And the task is finished only after the Dispose.

This took me to the next stage: what about the async / await pattern from .net 4.5? The implementation is quite similar to the one above - the main difference is that the method now has to return a Task.

static async Task LogMessage (string message)
{
  Uri baseAddress = new Uri("http://localhost/");
  string requestUri = "uri";

  using (HttpClient client = new HttpClient { BaseAddress = baseAddress })
  {
    Console.WriteLine("Sending message");
    HttpResponseMessage response = await client.PostAsJsonAsync(requestUri, message);

    Console.WriteLine("Evaluating response");
    if (response.IsSuccessStatusCode)
      Console.WriteLine("Succeeded");
    else
      Console.WriteLine("Failed with status " + response.StatusCode);
  }
}

Also this implementation starts a new thread for the response message handling. But it does it only if really needed. And it does it as late as possible.

A little more sophisticated logging shows some details (the 2nd column is the thread number). The implementation with an explicit Task calls LogMessage on the main thread 9. Afterwards in continues immediately on the same thread. Approx. 20 ms later the new thread 12 starts with the HTTP handling:

21:28:42.524    9       CallMethod      Calling LogMessageWithTask
21:28:42.526    9       CallMethod      Continuing after LogMessageWithTask
21:28:42.545    12      LogMessageWithTask      Sending message
21:28:45.682    12      LogMessageWithTask      Evaluating response
21:28:45.682    12      LogMessageWithTask      Failed with status NotFound

With async / await it is a little bit different: also the request will be sent on the main thread. The response handling will be done later also in a second thread:

21:28:51.638    9       CallMethod      Calling LogMessageAsyncAwait
21:28:51.666    9       LogMessageAsyncAwait    Sending message
21:28:51.701    9       CallMethod      Continuing after LogMessageAsyncAwait
21:28:52.144    16      LogMessageAsyncAwait    Evaluating response
21:28:52.144    16      LogMessageAsyncAwait    Failed with status NotFound

However, the coding is more precise. And the request will be sent without the delay for creating the new Task.

---

You can find the source code at GitHub: https://github.com/Ritzlgrmft/HttpClientDispose.