.NET Framework ベースの ASP.NET Web API を用いた開発を行っていて、ちょっとよくわからない挙動に出くわしたのでメモ代わりに残しておきます。
- 環境
- 何がやりたかったのか
- ログ出力するコード
- Guid の発行処理を追加する
- API コントローラーを追加する
- Restlet Client で呼び出してみる
- コンソールアプリケーションを作成して Web API を呼び出す
- Guid の保存場所を変える
環境
- .NET Framework 4.8
- ASP.NET Web API 5.2.7
何がやりたかったのか
今回のシステムではクライアント側にコンソールアプリケーションを準備し、そこから 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 などのツールで呼び出してみます。
このような形で 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" }
こちらも問題なく送信でき、ログにも記録が残されています。
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とかを調べてみると、詳しい人がいろいろ教えてくれるはず。
