编写日志的正确姿势

Posted 2020-11-17 xiandnc

一般来说，对于何时写日志并没有明确的限制和约束，只要你觉得记录的日志是有价值的，对跟踪bug是有帮助的，你就可以去添加日志。当然一些敏感信息除外，比如你正在开发一套支付系统，不要把客户的卡号和密码等信息记录在日志中，因为日志并不会被刻意保护，有可能被其他的用户群体收集到。
另外不要担心大量的日志会对服务器造成压力，一般来说在产品环境都会采用消息队列配合搜索引擎的方式存储日志，通过定义准确的日志级别也会减少生产环境的日志数量。

一、如何记录日志

以log4net为例，在想要添加日志的任何地方使用下列的方法添加日志：

private readonly ILog log = log4net.LogManager.GetLogger(typeof(T));
log.Info("message");

二、选择准确的日志级别

一般来说日志组件都会有Debug,Info,Warn,Error,Fatal五种日志级别，其中Fatal用来处理Unhandled exception，因此对开发者而言在开发过程中只有四种可用的日志级别：

• Debug 用来记录一些用于有利于调试程序的信息和系统状态，一般来说这种级别的日志只会出现在开发环境
• Info 跟Debug类似，区别在于这种级别的日志可以上生产环境
• Warn 警告类日志，比如第三方请求返回了失败的信息，但是开发者知道如何处理这种信息, 不会造成系统奔溃
• Error 一般可以用来记录一些异常信息，比如配置文件丢失等

三、选择真确的方法重载

以log.Error()举例：

• 使用log.Error(string message)的时机

  if (string.IsNullOrEmpty(userName))
  {
  var message = "user name is empty";
  logger.Error(message);
  
   throw new UserNameEmptryException();
  }

  上面的使用方式是显而易见的，业务代码发现用户名为空，记录日志同时抛出异常，上面的场景不能使用下面的方式记录日志：

  logger.Error(new Exception(message));

  选择错误的重载会导致日志调用堆栈丢失，日志变得不再完整，最终会在查找日志的时候浪费时间。

• 使用log.Error(Exeception exception)的时机

在捕获到异常的时候使用此重载：

try
{
    var response = AlipayHandler.Pay();
}
catch (AlipayRequestException e)
{
    logger.Error(e);
    throw;
}

• 使用log.Error(string message, Exception exception)的时机

上面的场景也符合这个重载，区别在于你不但想记录异常信息，还想添加自定义的信息。

四、设计全局的Unhandler exception handler

一般来说使用不同的框架，添加Unhandler exception handler的方式也不同。

• 对于ASP.NET MVC 项目，标准的方式是创建自定义ExceptionFilter:

  public class UnhandledExceptionFilterAttribute : ActionFilterAttribute
  {
  public override void OnActionExecuting(ActionExecutingContext filterContext)
  {
      var logger = LoggerFactory.GetLogger(typeof(UnhandledExceptionFilterAttribute));
      var exception = filterContext.Exception;
      logger.Fatal("Unhandled exception", exception);
      base.OnActionExecuting(filterContext);
  }
  }

• 对于Winform则需要用另一种方式:

  AppDomain.CurrentDomain.UnhandledException += 
                      (sender, e) =>
                      {
                          logger.Fatal("Unhandled exception", exception);;
                      };

• 对于asp.net core可以使用NLog来记录unhandled exception。

总之，开发不同类型的应用程序都有相对应的方法来处理unhandled exception，使用时搜索最佳实践即可。

五、错误的日志记录方式

private void RequestAlipay()
{
    try
    {
        var response = httpClient.Request(url);
    }
    catch (Exception e)
    {
        logger.Error(e);
    }
}

上面记录日志的方式犯了两个错误：

1. 不要捕获通用的异常, 记住：只捕获你知道如何处理的异常，如果你不知道如何处理他，请不要捕获他。Why catch(Exception)/empty catch is bad
   在上面的场景中，你可能会担心由于网络原因或者请求不合理等原因会导致整个请求失败，你想在此时记录日志，因此你的意图是处理HttpRequestException而不是Exception。因此正确的写法如下：

private void RequestAlipay()
{
    try
    {
        var response = httpClient.Request(url);
    }
    catch (HttpRequestException e)
    {
        logger.Error(e);
    }
}

你并不知道如何处理其他类型的异常，因此你不应该捕获其他类型的异常。

1. 上面的Try...Catch会吞掉异常并吞掉bug，同时还有可能会将本应该在开发阶段就能发现的问题推迟到了产品环境。
   一般来说你之所以要捕获异常是应为你知道如何处理该异常同时还知道一个恢复的方案Swallowing exceptions is hazardous to your health
   这段代码的意图是向第三方请求资源，如果真的由于某些原因导致请求失败，只写日志是不够的，你的应用程序还是可能会由此崩掉。但是开发人员想要查到事情的真相不再容易，因为你静悄悄的吞掉了这个异常，看起来好像什么事情都没有发生一样。如果在此时你并不知道如何处理这种异常，你应该把异常抛出去，让上层调用者做决定。

private void RequestAlipay()
{
    try
    {
        var response = httpClient.Request(url);
    }
    catch (HttpRequestException e)
    {
        logger.Error(e);
        throw;
    }
}

注意: 不要通过下面的方式抛出异常，因为这样会丢掉调用堆栈Why catch and rethrow an exception in C#?

throw ex;

六、一个正确记录日志的例子

比如在一个ProductSellingService中：

public void Sell(string itemId)
{
    Product product;
    try
    {
        car = GetProducts().Single(x => x.ItemId.Contains(itemId));
    }
    catch (InvalidOperationException)
    {
        log.Error($"product {itemId} has been sold out.")
        throw new ProductsHasBeenSoldOutException();
    }
}

当用户要购买的产品已经不存在时，除了记录一条日志，还会抛出一个ProductsHasBeenSoldOutException异常。因为作为ProductSellingService并不知道如何处理这种异常，所以需要上层的调用者做决策。
在ProductSellingController中使用了ProductSellingService:

try
{
    ProductSellingService.Sell(id);
    var response = Request.CreateResponse(HttpStatusCode.OK, "successful");
}
catch (ProductsHasBeenSoldOutException e)
{
    var response = Request.CreateResponse(HttpStatusCode.NotFound, 
"product is been sold out");
    return response;
}

ProductSellingController知道如何处理ProductsHasBeenSoldOutException，最终返回给用户一个错误消息。

准确的使用日志可以方便bug追踪，数据分析，达到事半功倍的效果，相反，错误的日志使用方式只会让开发者在调查原因的过程中浪费时间，降低效率。本文将重点描述日志的代码设计部分，在正式环境还要考虑如何通过消息队列和搜索引擎存储海量日志，以及日志监控等解决方案的设计，敬请期待后续文章。