调试不烂时:美丽的错误

异常每天都在发生:系统越大(且分布越分散),发生故障的机会就越大。

当我们理想化架构时,我们中的大多数人都已经吸取了教训,它们以灾难性的停机时间的形式使我们陷入困境,这可以避免,方法可能只是增加所需的超时时间,或者牢记一些分布式系统的最佳实践:现在是更好的架构师,他们了解失败是一种选择 ,我们必须构建能够容纳失败的弹性系统,并努力减轻其影响。

但是,有一件事是,我们大多数人(包括我)仍然在吸吮: 抛出漂亮的错误

我们拥有完善的基础架构来记录信息并监控我们的系统,从理论上讲,所有这些工作都得到了照顾。 然后是灾难到来的一天,灾难以一种讨厌的错误的形式来袭,我们被迫试图了解我们的软件正在发生什么。

修复错误后,您发现自己说过多少次“ 尽管我们还要添加更多日志 ”? 如果您像以前一样沮丧,建议您继续阅读。

日志记录应对应用程序透明

stdout / stderr大部分时间都可以正常工作,这就是您的应用程序应登录的情况(在99%的情况下):日志记录通常是基础结构的一部分,而不是单个应用程序,因此实际上没有理由让该应用程序了解特定的伐木运输。

大多数日志库开箱即用都支持std*** ,因此,您可以在更高级别上将这些日志收集在一个地方,而不必在决定切换到新日志收集器时更改一百个应用程序(即, SumoLogic,ELK,Graylog)。

使应用程序不知道谁在接收日志,这是集中日志记录的最佳方式,并确保您不会被一种解决方案所困扰,除非您更改体系结构中的每个应用程序。

不太多,也不太少

没有人喜欢摄取(并支付)千兆字节的无用日志,尤其是当您尝试调试且监视控制台中弹出的所有内容是:

  3月17日17:53:35 app收到订单#123的请求 
3月17日17:53:35 app打开mysql连接
3月17日17:53:35应用程序#123的订单无法放置
3月17日17:53:35 app订单#123出现问题
3月17日17:53:35应用程序关闭mysql连接(超时)
3月17日17:53:35应用程序保存命令#123时出错:第111行的mysql.go连接超时
3月17日17:53:35应用无法下订单#123,以错误代码响应客户
3月17日17:53:35应用将代码500发送给客户,订单号为123

因此,在8条消息中,我们只关心其中的1或2条消息,实际错误( connection timed out ),也许还有传入的请求消息(上面的第一个消息):除了混乱之外,这些消息中的大多数不会真正添加任何东西,而您只剩下您最终不得不过滤掉的日志。

更好的策略可能是记录该错误并提供一些其他信息,以防读者想了解有关该错误的更多信息:

  3月17日17:53:35应用程序保存命令#123时出错:在mysql.go的第111行,连接超时{ 
超时:10000,
httpStatus:500,
orderParams:...
}

这应该有助于使日志尽可能多地提供信息,但是这会使您面临麻烦,因为您仅在发生错误的情况下进行日志记录。 假设您的应用程序是HTTP服务器,强烈建议您记录该请求(非常高级,不需要很多细节),以便您知道该应用程序已被点击:

  3月17日17:53:35应用POST /订单 
3月17日17:53:35应用程序保存命令#123时出错:在mysql.go的第111行,连接超时{
超时:10000,
httpStatus:500,
orderParams:...
}

否则,当一堆请求最终引发500错误并且您在控制台中看不到日志时,您将无法判断问题出在应用程序前面的负载均衡器是否拒绝了某些请求,或者什么。 高级别添加便宜的日志,这样就可以在出现问题时不必做很多假设,以便在日志中看到以下内容:

  3月17日17:53:35服务器从端口8080启动... 

您知道该应用可能根本没有收到流量。

按标识符聚类

能够标记日志是一个好主意,以便以后可以对它们进行群集,尤其是在您具有多层体系结构的情况下:例如,Amazon启动了X-Ray以在这些确切场景中提供帮助。

为每个到达负载均衡器的请求分配一个请求ID,并将该ID转发到体系结构的内部级别:这将帮助您为错误提供更多的上下文。

例如,您可能最终看到通过负载均衡器并通过特定查询字符串参数命中服务A的请求最终并未到达服务B,因此您现在可以集中精力了解为什么服务A会保留所有具有该特定参数的请求。

什么地方出了错?

通常,了解到底出了什么问题,或者我们期望什么样的参数通常是有帮助的:在大多数情况下,这是能够在日志中包括引起错误的特定参数的问题,因为没有什么比记录泛型更为糟糕的了。 invalid parameters错误,让下一个待命的家伙试图找出导致错误的确切原因。

就像这样简单:

  app.post('/ users',(req,res){ 
让用户= req.params
  db.findUser(用户).catch(错误=> { 
console.log(“创建新用户时出错”,{err,params})
})
})

可以帮助您了解故障的根本原因。

请记住,将外部参数嵌入到日志中时必须非常小心,因为您可能最终会记录敏感信息,例如数据库凭证或信用卡号 :请查看特定记录器的文档以查看其是否支持编辑信息,否则,您将不得不手动“隐藏”这些值。

我该如何解决?

优质日志的另一个非常重要的方面是能够将补救步骤包括在日志本身中,因此一旦发生故障,我们就可以立即进行故障排除。

听起来似乎很容易,但将它们包括在内并不总是可行的:例如,当客户将错误的参数发送给服务时,很容易找出根本原因,但是要弄清楚需要做什么却并不容易。纠正错误。

是否有将参数名称从userId更改为user_id的部署? 客户端是否由于更新而中断? 是在“我们”一方还是“他们”一方? 在不进行进一步深入研究的情况下,无法采取任何明确的行动,因此最好避免使用模糊,无益的补救措施,例如“ 联系客户,因为他们似乎正在搞砸 ”,因为这可能会导致您转向方向错误。

断路器启动时的补救步骤示例:

  GET api.example.com-如果您认为这会阻止断路器连接 
如果出现错误,您可以使用我们的以下命令手动断开电路
内联网:
  curl -X POST -d“ state = open” https://frontend.example.com/_breakers/api.namshi.com 

在大多数情况下,断路器会出于有效原因将电路闭合; 只要不是这种情况,您就可以在自己面前找到解决方案。

值得注意的是,与任何形式的文档一样,补救步骤可能会很快过时:我的建议是不要太过兴奋,以避免用每3个月更改一次的指令来滥发代码库。

提供有用的信息

如今,大多数可用的记录器都允许您指定某种上下文来围绕您的日志消息:例如,当发生与MySQL的超时连接时,很高兴了解您的连接池在当时的状况以及其他情况。超时本身之类的信息。

  pool.getConnection({timeout}) 
。然后(...)
.catch(err => {
logger.error(err,{
暂停,
池:pool.getState(),
})
})

像往常一样,没有火箭科学。

收集当机

最后但并非最不重要的一点是,对于您中的许多人来说可能听起来很愚蠢: 收集崩溃报告

在某些听起来不那么琐碎的语言中(例如,PHP的致命错误直到PHP 7才被发现),因此您可能需要研究其他一些较低级别的解决方案,这些解决方案可以在用户区代码拦截和记录崩溃没法子。

尽管NewRelic在某些情况下(例如AWS上的容器或t2实例)基于主机的定价模型非常古怪,但它似乎是此处的领先者。

结论

过去,我已经造成了相当大的伤害,所以这更多是一些人的一些友好建议的集合,这些人多次用头撞墙。

如果您对Namshi用来监视和记录日志的基础结构感到好奇,请允许我简要介绍一下:

  • 我们的旧系统通过专门的传输方式(例如winston-graylog2)登录到Graylog
  • 我们其余的应用程序正在容器中运行并登录到stdout
  • 每个主机上都有一个容器,用于收集所有docker日志并将其运送到sematext的logene
  • 在暂存阶段,我们给开发人员更多的自由,让他们看看kubernetes的仪表板
  • NewRelic监控崩溃和性能
  • Sensu进行检查以确保一切正常运行(例如,从计算机上ping google.com ,检查网站上是否至少有X个产品,等等)

如果您想了解有关日志记录的更多信息,我建议您这篇文章,它对我的​​撰写有很大帮助。

干杯!