ツナ缶雑記

ぐうたらSEのブログです。主にマイクロソフト系技術を中心に扱います。

ASP.NET Web APIでPOSTリクエストを処理するときスレッドが変わる

.NET Framework

f:id:masatsuna:20200212014211p:plain

.NET Framework ベースの ASP.NET Web API を用いた開発を行っていて、ちょっとよくわからない挙動に出くわしたのでメモ代わりに残しておきます。

環境

何がやりたかったのか

今回のシステムではクライアント側にコンソールアプリケーションを準備し、そこから ASP.NET Web API で作った Web API を呼び出すような構成になっています。 コンソールアプリケーションから Web API のアプリケーションまで、出力する一連のログを並べて確認しやすくなるよう、共通のトレース情報をログに出力するような構成を考えていました。 具体的には、コンソールアプリケーション内で適当な Guid を発行し、その値を Web API のアプリケーションに伝達します。 コンソールアプリケーションも Web API のアプリケーションも、この Guid をログに出力することで、クライアントからサーバーまで、一気通貫でログを確認できるようにしようという魂胆です。

最終的には上記のようなことをやろうと思っていますが、まずは簡単に動作確認をするため、 Web API のアプリケーション内で完結するように、仕組みを作ってみようと思いました。

ログ出力するコード

まずはログ出力を行うコードを書いてみます。 ことを簡単にするため、 System.Diagnostics.Trace を使ってログ出力するコードをを書きました。 一応日時とかのメタデータも出力するようにしています。

using System;
using System.Diagnostics;
using System.Threading;
using System.Web;

namespace HandlerSample.Web
{
    internal class Logger
    {
        public static void WriteLog(string message)
        {
            Trace.WriteLine($"{DateTime.Now.ToString("yyyy/MM/dd HH:mm:ss.fff")} " +
                $"[{HttpContext.Current.Request.HttpMethod}]{HttpContext.Current.Request.Url} " +
                $"{Thread.CurrentThread.ManagedThreadId} " +
                $"{Trace.CorrelationManager.ActivityId} " +
                $"{message}");
        }
    }
}

前述した Guid は、 Trace.CorrelationManager.ActivityId に保存することにしています。

Guid の発行処理を追加する

先ほど作った Logger クラスで使用する Trace.CorrelationManager.ActivityId に、Guid の値を設定する処理を追加します。 将来的にはクライアントから送られてきた値を設定したいのですが、ここではまず動作確認のため、 Global.asax の BeginRequest 内で、新たに Guid を発行して、それを設定するように実装しました。

using System;
using System.Diagnostics;
using System.Web.Http;

namespace HandlerSample.Web
{
    public class WebApiApplication : System.Web.HttpApplication
    {
        protected void Application_Start()
        {
            GlobalConfiguration.Configure(WebApiConfig.Register);
        }

        public override void Init()
        {
            base.Init();
            this.BeginRequest += WebApiApplication_BeginRequest;
            this.EndRequest += WebApiApplication_EndRequest;
        }

        private void WebApiApplication_BeginRequest(object sender, EventArgs e)
        {
            Trace.CorrelationManager.ActivityId = Guid.NewGuid();
            Logger.WriteLog("BeginRequest");
        }

        private void WebApiApplication_EndRequest(object sender, EventArgs e)
        {
            Logger.WriteLog("EndRequest");
        }
    }
}

特に処理上の意味はないのですが、 BeginRequest 、 EndRequest のタイミングでログを出力するようにしています。

API コントローラーを追加する

API コントローラーは、今回適当に作ってあります。 中身の処理はどうでもよくて、HTTP メソッドに対応する処理をそれぞれ作ってあることだけがポイントです。 そして各メソッドのなかで、これまた作成した Logger を用いてログ出力するようにしてあります。

using System.Collections.Generic;
using System.Linq;
using System.Net;
using System.Web.Http;
using HandlerSample.Web.Models;

namespace HandlerSample.Web.Controllers
{
    public class ProductsController : ApiController
    {
        private ProductRepository repository = new ProductRepository();

        // GET: api/Products
        public IEnumerable<Product> Get()
        {
            Logger.WriteLog("Get 呼び出し");
            return this.repository.Products;
        }

        // GET: api/Products/5
        public Product Get(int id)
        {
            Logger.WriteLog("Get 呼び出し");
            var product = this.repository.Products.FirstOrDefault(p => p.Id == id);
            if (product == null)
            {
                throw new HttpResponseException(HttpStatusCode.NotFound);
            }

            return product;
        }

        // POST: api/Products
        public void Post([FromBody]Product newProduct)
        {
            Logger.WriteLog("Post 呼び出し");
            if (this.repository.Products.Any(p => p.Id == newProduct.Id))
            {
                throw new HttpResponseException(HttpStatusCode.BadRequest);
            }

            this.repository.Products.Add(newProduct);
        }
    }
}

Restlet Client で呼び出してみる

上記の ASP.NET Web API アプリケーションを Visual Studio から実行して、 Restlet Client などのツールで呼び出してみます。

f:id:masatsuna:20200211010005p:plain
GET リクエストの送信

このような形で GET リクエストを送ると、ちゃんと以下のようなレスポンスが返ってきます。

{
    "Id": 1,
    "Name": "書籍2"
}

ログも以下のようにちゃんと出ています。

2020/02/11 00:59:24.389 [GET]https://localhost:44367/api/products/1 25 8e656e70-4da1-4069-b619-82ffb8e0a4e4 BeginRequest
2020/02/11 00:59:24.391 [GET]https://localhost:44367/api/products/1 25 8e656e70-4da1-4069-b619-82ffb8e0a4e4 Get 呼び出し
2020/02/11 00:59:24.392 [GET]https://localhost:44367/api/products/1 25 8e656e70-4da1-4069-b619-82ffb8e0a4e4 EndRequest

ついでに POST リクエストのケースも試しておきます。 以下の json を POST で送り付けてみます。

{
"Id": 4,
"Name": "書籍5"
}

f:id:masatsuna:20200211010413p:plain
POST リクエストの送信

こちらも問題なく送信でき、ログにも記録が残されています。

2020/02/11 01:05:07.112 [POST]https://localhost:44367/api/products/1 33 ae074c8a-e1bf-4d57-9d52-010eace67f12 BeginRequest
2020/02/11 01:05:07.112 [POST]https://localhost:44367/api/products/1 33 ae074c8a-e1bf-4d57-9d52-010eace67f12 Post 呼び出し
2020/02/11 01:05:07.113 [POST]https://localhost:44367/api/products/1 33 ae074c8a-e1bf-4d57-9d52-010eace67f12 EndRequest

コンソールアプリケーションを作成して Web API を呼び出す

これまた超適当に作成した Web API を呼び出します。 特に意味はないですが、 HTTP GET で全データを取得してから、HTTP POST のリクエストを実行しています。

using System;
using System.Net.Http;
using System.Text;
using System.Threading.Tasks;

namespace HandlerSample.ConsoleApp
{
    class Program
    {
        private static readonly HttpClient client = new HttpClient();

        static void Main(string[] args)
        {
            InternalMainAsync().Wait();
        }

        private static async Task InternalMainAsync()
        {
            var url = "https://localhost:44367/api/products/";

            var getResponse = await client.GetAsync(url);
            var getResponseBody = await getResponse.Content.ReadAsStringAsync();
            Console.WriteLine(getResponseBody);

            var content1 = new StringContent("{\"Id\": 4,\"Name\": \"書籍5\"}", Encoding.UTF8, "application/json");
            var response1 = await client.PostAsync(url, content1);
            Console.WriteLine(response1.StatusCode);
        }
    }
}

その結果、ログには以下のように残されていました。

2020/02/12 00:33:47.797 [GET]https://localhost:44367/api/products/ 89 54d54c6d-66a4-421f-96b9-1f99422e5548 BeginRequest
2020/02/12 00:33:47.838 [GET]https://localhost:44367/api/products/ 89 54d54c6d-66a4-421f-96b9-1f99422e5548 Get 呼び出し
2020/02/12 00:33:47.941 [GET]https://localhost:44367/api/products/ 89 54d54c6d-66a4-421f-96b9-1f99422e5548 EndRequest
2020/02/12 00:33:47.943 [POST]https://localhost:44367/api/products/ 74 fe141f94-f8e5-4b26-be8b-69ca171c49ca BeginRequest
2020/02/12 00:33:47.997 [POST]https://localhost:44367/api/products/ 81 00000000-0000-0000-0000-000000000000 Post 呼び出し
2020/02/12 00:33:47.997 [POST]https://localhost:44367/api/products/ 81 00000000-0000-0000-0000-000000000000 EndRequest

注目してほしいのは POST のリクエストにおいて、 BeginRequest が実行されているスレッドと、ApiController が実行されているスレッドが異なることです。 その結果、BeginRequest で設定した Trace.CorrelationManager.ActivityId が取得できなくなっており、ログには Guid の規定値が出力されています。

この挙動、Restlet Clientから POST リクエストを投げた時と異なります。 またコンソールアプリケーションから実行するときも、 Web サーバー起動直後に POST リクエストを送ったときは、このような挙動にならないことが確認できています。 また GET リクエストの時は、処理の途中でスレッドが変わらないのです。

何かこの辺の情報をお持ちの方は Twitter で教えてください。

Guid の保存場所を変える

Guid の値をログに埋め込むことで、一連の処理を一気通貫で見れるようになることが目的でした。 しかし、前述の通りスレッドが変わってしまうことで Guid の値が規定値に戻ってしまっており、もともとの要求が満たせていません。 ということで、 Guid の値を別の場所に保存することで、この問題に対処してみます。

Guid の保存場所として今回使用したのは、 HttpContext.Items プロパティです。 このプロパティは、たとえスレッドが変わろうとも、値をうまいこと引き継いでくれるようになっています*1。 もともと Global.asax に実装していた処理と、 Logger の処理をこれに合わせて書き換えてみます。

Global.asax

private void WebApiApplication_BeginRequest(object sender, EventArgs e)
{
    HttpContext.Current.Items.Add("ActivityId", Guid.NewGuid());
    Logger.WriteLog("BeginRequest");
}

Logger

public static void WriteLog(string message)
{
    Trace.WriteLine($"{DateTime.Now.ToString("yyyy/MM/dd HH:mm:ss.fff")} " +
        $"[{HttpContext.Current.Request.HttpMethod}]{HttpContext.Current.Request.Url} " +
        $"{Thread.CurrentThread.ManagedThreadId} " +
        $"{HttpContext.Current.Items["ActivityId"]} " +
        $"{message}");
}

こうすることで、無事に Guid の値が出力されるようになります。

2020/02/12 00:50:37.835 [GET]https://localhost:44367/api/products/ 45 4a33b4e8-7956-4fb4-b59e-5d07e8a66c45 BeginRequest
2020/02/12 00:50:37.836 [GET]https://localhost:44367/api/products/ 45 4a33b4e8-7956-4fb4-b59e-5d07e8a66c45 Get 呼び出し
2020/02/12 00:50:37.878 [GET]https://localhost:44367/api/products/ 45 4a33b4e8-7956-4fb4-b59e-5d07e8a66c45 EndRequest
2020/02/12 00:50:37.880 [POST]https://localhost:44367/api/products/ 76 0e14ae64-6644-402d-bde1-eb06f0fefd39 BeginRequest
2020/02/12 00:50:37.882 [POST]https://localhost:44367/api/products/ 48 0e14ae64-6644-402d-bde1-eb06f0fefd39 Post 呼び出し
2020/02/12 00:50:37.899 [POST]https://localhost:44367/api/products/ 48 0e14ae64-6644-402d-bde1-eb06f0fefd39 EndRequest

POST リクエストのログは、スレッド ID が途中で変わっていることを確認できます。 しかし、 Guid の値はちゃんと引き継がれ、ログに出力できています。

2020/2/20 追記

この現象を追加調査をしてみたところ、 .NET Framework のクライアントから HTTP リクエストを送る際、 HTTP 100 Continue を挟んでから Body を送っていることがわかりました。 ただ HTTP 100 を挟むかどうかはケースバイケースのようで、その真因にまでは迫れていません。

*1:詳しくはここで解説しません。SynchronizationContextとかを調べてみると、詳しい人がいろいろ教えてくれるはず。