结构化日志，为什么Log($"...")是一个陷阱

一个看起来无害的写法

日志，是开发最后的防线，它是你扯皮的利器，接口到底有没有调用？有没有超时？性能怎么样？有没有执行完？有没有异常？
这些都需要日志来证明作为开发的你，这个锅是不是要你来背。

我们在写日志的时候，我相信大多数老.NET er都写过这两种形式之一

// 写法 A：消息模板
_logger.LogInformation("Order {OrderId} shipped to {City}", orderId, city);

// 写法 B：字符串插值,绝大多数人在刚入行时，都用这个写法
_logger.LogInformation($"Order {orderId} shipped to {city}");

这两者，你当作普通文本(AddSimpleConsole)来看是没有任何区别的，甚至写法B更符合人的直觉。

但如果把输出格式换成Json(AddJsonConsole)，那输出差异就非常之大了

{
  "EventId": 0,
  "LogLevel": "Information",
  "Category": "LogDemo.Controllers.DiagnosticsController",
  "Message": "Order 12345 shipped to Shanghai",
  "State": {
    "OrderId": 12345, -- 类型强类型
    "City": "Shanghai", -- 清晰好理解
    "{OriginalFormat}": "Order {OrderId} shipped to {City}"
  }
}

{
  "EventId": 0,
  "LogLevel": "Information",
  "Category": "LogDemo.Controllers.DiagnosticsController",
  "Message": "Order 12345 shipped to Shanghai",
  "State": {
    "{OriginalFormat}": "Order 12345 shipped to Shanghai"
  }
}

可以看到，主要差异集中在State中，消息模板中的Order是一个清晰可辩别的int类型，City也是一个独立的字符串，这意味着任一支持结构化的的产品(Seq,Elasticsearch,Application Insights)都可以直接对OrderId,City等结构对象做类似SQL的查询
而字符串插值就难受了，就是一串字符串，只能全文搜索，如果要提取关键信息，只能靠正则表达式，不准且低效。

踩坑经验：AWS的data lake按照扫描多少行收费，一个低效的正则能干掉很多费用

编译器也在提醒你

.NET内置的Roslyn分析器也在提醒你，你不应该用字符串插值当作日志消息。

https://learn.microsoft.com/zh-cn/dotnet/fundamentals/code-analysis/quality-rules/ca2254

为什么要较真？

有人可能会问，我就是一个单体系统，每天就那么点日志，不用也没啥影响吧？
从个人实际的角度出发，确实是没什么必要。
但从工程化的角度来看，这是我们必须要遵循的规范，因为项目工程化虽然会降低天才程序员的上限，但会提高垃圾程序员的下限。
如果在项目中不遵循消息模板来记日志，随着时间的堆叠，代码的腐化，在如下地方会逐渐放大

1. 检索成本高，不利于分析
   熟悉数据库的小伙伴都知道，查数据只需要知道表结构，你就能非常优雅的通过Select/Where/Group/Having等关键字来编排自己想要的结果。
   但如果是日志是一个纯文本，那就只能依靠全文搜索 or 正则来猜测结构，而结构化字段则可以按OrderId=xxxx,City=xxxxx提供精准的匹配关系。

2. 无法接入链路跟踪体系
   在微服务架构中，链路跟踪是非常重要的一环，如果没有TraceId，SpanId,ElapsedMs,StatusCode这些关键信息，就无法将各个微服务之间的运作情况给串联起来，导致只能靠时间戳去猜，这无疑是一场耗时巨大的灾难。

一个最佳实践：ex.Message不要写入日志，异常必须作为独立参数传入！！！

在我的职业生涯中，我见过太多这种错误的写法

// 反例：异常信息被拍扁成字符串，堆栈/异常类型全部丢失
logger.LogError("Create order failed: {ExceptionMessage}", ex.Message);

// 正确写法：异常对象独立传入，堆栈、内部异常、异常类型都保留在结构化字段里
logger.LogError(ex, "Create order failed.");

有人会问，这里就是用的消息模板呀，这有什么问题？
让我们眼见为实，空指针异常/未将对象引用到对象的实例，这两句话相信大家都不陌生，当我们拿着Value cannot be null 去日志中搜索时，我相信你会懵逼，系统中会充斥着大量的这种错误，但你就是定位不到问题发生在哪，因为你丢失了最终的堆栈信息，你压根就不知道到底是哪一个参数为空。
道理也很简单，这里错误的使用ex.Message导致消息模板失效，只有独立传入ex才能让日志系统拿到完整的异常对象。

{
  "EventId": 0,
  "LogLevel": "Error",
  "Category": "LogDemo.Controllers.DiagnosticsController",
  "Message": "Create order failed: Value cannot be null. (Parameter \u0027source\u0027)",
  "State": {
    "ExceptionMessage": "Value cannot be null. (Parameter \u0027source\u0027)",
    "{OriginalFormat}": "Create order failed: {ExceptionMessage}"
  }
}
{
  "EventId": 0,
  "LogLevel": "Error",
  "Category": "LogDemo.Controllers.DiagnosticsController",
  "Message": "Create order failed",
  // 只有完整的异常信息才方便定位问题
  "Exception": "System.ArgumentNullException: Value cannot be null. (Parameter \u0027source\u0027)\r\n   at System.Linq.ThrowHelper.ThrowArgumentNullException(ExceptionArgument argument)\r\n   at System.Linq.Enumerable.TryGetFirst[TSource](IEnumerable\u00601 source, Boolean\u0026 found)\r\n   at System.Linq.Enumerable.First[TSource](IEnumerable\u00601 source)\r\n   at LogDemo.Controllers.DiagnosticsController.Test(String name) in C:\\Users\\simpletruss\\source\\repos\\LogDemo\\LogDemo\\Controllers\\DiagnosticsController.cs:line 41",
  "State": {
    "{OriginalFormat}": "Create order failed"
  }
}

总结

结构化日志的本质是，日志字段能否如同数据库字段那样被系统单独理解。将一个未来的隐性坑提前解决也是项目工程化的思想体现。