前言日志是开发者分析程序、排查问题的重要工具。随着系统架构从早期的单体应用演进到如今的微服务架构，日志的重要性也逐渐提升。日志除了可以用来辅助排错，还可以用来对微服务请求的整个链路进行性能分析，甚至可以用来解决分布式系统中的一致性问题。同时，系统产生的日志量和日志管理难度也明显增加。于是，日志管理工具诞生并迭代升级。从最开始登录跳板机查看日志，到构建分布式日志中心统一管理日志流，再到云平台厂商提供专业的日志管理服务。开发者只需要在应用中接入SDK，将日志返回给日志平台，然后利用日志平台提供智能检索、数据分析、链接分析能力。平台简单易用的图形化界面和成熟的数据管理能力极大地提高了开发效率。但是日志管理平台也不是万能的，总有一些场景会缺席（比如本地调试产生的日志不会回流到日志平台??，不支持复杂的数据分析，以及当然最常见和最令人沮丧的是，数据丢失......），我们不得不与一堆原始日志文件作斗争。这时候我们就要从工具包中取出原来的weapon-linux命令，开始猛虎操作了。本文将根据本人在日常开发过程中遇到的场景，给出相应的日志检索语句。也欢迎大家收藏到自己的工具包中，或者在下方留言说说自己遇到的日志分析问题。博主会把它提炼到文章中。日志结构在了解日志分析语句之前，先简单介绍一下日志的类型和结构。以下序列将以本节介绍的内容为背景，给出具体的日志分析语句。有两种主要类型的日志。一种是业务日志，是业务功能实现过程中产生的日志，通常是由开发者主动在程序中埋点触发的。另一类是系统日志，范围更大，可以进一步细分，比如系统所在主机的各种指标的快照，或者依赖中间件内部打印的日志等。业务日志和系统日志通常是在不同的目录中。实际上，不同类型的系统日志一般都隔离在不同的目录中。以一个连接了Mysql和RocketMq的系统为例，它的日志目录结构可能是这样的：/log/mysql/rocketmq/app/app_name1/app_name2可见app下不同业务系统之间的日志也是隔离的，便于检索和查看。然后查看各个目录下日志文件的结构。这通常没有绝对的标准。开发者通常会根据系统的需要来设计日志文件结构，甚至会产生特定用途的日志（如mysqlbinlog和relaylog）。这里简单介绍一下我在开发系统时习惯的日志结构设计。通常我至少区分三个日志文件：application.log、application-error.log和application-warn.log。正如文件名所示，它们对应不同级别的日志。application.log会包含应用生命周期中的所有日志，而application-error.log和application-warn.log日志只记录error级别的日志和warn级别的日志，方便快速定位系统异常。但是，如果直接查看目录下的所有日志文件，会发现不止这三个文件。这是因为系统在运行过程中会产生大量的日志。如果只使用一个文件来存储日志，那么文件会变得非常大，占用大量的磁盘空间。因此，操作系统或日志工具会在配置后进行日志截断、压缩、备份等操作，以减少日志对整个主机稳定性的影响。被截断的日志将根据配置以日志名称的后缀保存，通常带有时间戳。除了按照上图的日志级别划分多个日志文件外，还可以从其他维度设计日志文件，比如打印系统流量进出的日志。流量入口可以理解为RPC接口服务端、HTTP服务服务端、MQ接收消息日志等，对面的流量出口是指RPC接口客户端、调用下游HTTP服务等，因此整个日志目录将包含以下文件application.logappilcation-error.logapplication-warn.logrpc-client.logrpc-server.logmq.log具体的日志配置不在本文讨论范围内，大家可以自行阅读logback等日志框架的文档。日志分析小操作会列出日常开发过程中常见的日志查询和分析场景，并给出相应的说明。查看日志查看单个日志文件cat是我们最常用的读取文件的命令，通过cat${filename}可以显示文件的内容。以application.log为例catapplication.log该命令适用于查看所有可读文件。查看多个日志文件前文提到，由于Logrotate机制的存在，日志文件往往会被截断为多个时间戳后缀不同的文件，而我们并不能确定我们要查询的日志在哪个文件中。这时候，可以将多个文件传递给cat命令，cat${filename}${filename2}${filename...}，cat会一个一个读取并显示文件。但是如果文件数量非常多怎么办？幸运的是，cat命令支持类正则匹配，*关键字允许我们匹配任意数量的字段。catapplication1.logapplication2.logapplication3.logcatapplication.log*当然，在文件较多的情况下使用cat命令查看全量日志并不是一个好的选择。下面会给出其他日志查询方式。查看日志的最后几行。cat命令会从头到尾读取整个日志文件并显示在控制台上，但有时我们只需要查看最近一段时间的日志即可。而且当日志文件特别大的时候，使用cat命令不仅速度慢，还会导致大量不相关的日志满屏，影响阅读。这时候使用tail命令就可以很好的解决这个问题。tail命令只能读取日志的最后几行并将其显示在屏幕上。tailapplication.log#读取application.log文件的最后一部分。tail命令还支持传入多个文件。它会按顺序读取几个文件的最后一部分，并将它们打印到控制台。tailapplication1.logapplication2.logapplication3.log如果要指定显示最近100行日志，可以使用tail-n配合查询：tail-n100application.log查看增量日志有时候，我们希望实时查看日志文件的内容，以便更快地捕捉系统的行为，tail-f命令支持动态显示文件中的新内容。如果想退出自动刷新，可以使用ctrl+c命令：tail-fapplication.log分页查看日志。有时候，因为日志内容太大，控制台会疯狂输出，关键信息直接被淹没。所以需要一个命令，以页面的形式查看日志内容，减少控制台刷新的频率。more指令为这种情况提供了很好的支持。moreapplication.logmore命令执行后，控制台会逐屏显示文件内容。可以使用空格键（空格键）显示下屏内容，按回车键（回车键）显示下一行内容，Q键退出more命令至此，主要命令为全-已经给出了文件的文本查询和部分查询，下面给出另一种查询，基于关键字的查询、关键字检索、基于关键字的日志检索的相关命令在分布式系统中，往往会有几十个或者甚至有数百个系统参与该过程。这时候流量的入口会生成一个唯一的logId来拼接标记全链路请求。当我们需要排查上下游问题时，往往会将logId提供给对方排查。同样，我们在获取到logId的时候，还需要在日志中查询与该logId关联的日志内容。这是一个典型的根据关键字检索日志的场景。grep命令很好的解决了这个问题，它可以打印出日志中匹配关键字的行。grep"logId"application.log上面的命令将打印application.log文件中所有包含logId的行。grep命令还支持多文件查询grep"logId"application1.logapplication2.logapplication3.loggrep"logId"application*.log和正则表达式匹配或者不区分大小写的匹配grep"logId"application.log-i#不区分大小写grep-E"[\w\d]*"application.log#regularexpression这里顺便提醒一下系统设计中的一个注意点。在分布式系统中，logId是通过写入当前线程的上下文来实现的，因此，如果在当前线程中有一部分任务提交给了异步线程，希望可以使用当前线程进行跟踪，您必须记住将logId传递给异步线程的上下文。检查关键字附近的日志。不知道大家有没有在程序中写过这样的日志逻辑：log.error("somethingwentwrongkeyId:{}",keyId,ex)。通过这行日志，我们期望在日志中打印出异常的keyid和stack。但是，日志系统会将这一行日志和堆栈拆分成两行进行打印。如果直接使用grep${keyId}application.log，是查询不到下一行的栈信息的。因此，我们需要查看该关键字行附近的N行日志，以帮助我们快速定位异常原因。grep也提供了这个能力：grep'somethingwentwrong'-A100application.log上面这行语句显示了logsomethingwentwrong这一行之后100行的日志，包括hit的行。这里-A是--after-context的缩写，好记。同理，也可以查看匹配行前N行的日志：grep-B100application.log其中-B是--before-context的缩写。当然这两个指令也可以一起使用~多关键字查询有时候我们可能获取不到请求的logId，我们可能只能调用方法和方法中的关键参数，如果只根据匹配方法名，我们可能会查询到很多不相关的调用，反之亦然。这个参数可能会调用很多其他方法，这些日志会影响我们找到正确的key请求。grep还提供了多关键字匹配模式。假设我们现在有一个方法叫做helloWorld(Stringname)，传入的值是ralegrep-e"helloWorld"-e"rale"application.log但是这个命令并不符合这个场景的诉求，因为它其实是一个OR关系，即包含helloWorld或rale的日志行将被过滤掉。下面我们将介绍linux的管道操作（pipeline）。Linux管道运算符|可以串联两个shell命令，前一个命令的输出将是下一个命令的输入。grep-e"helloWorld"应用程序.log|grep"rale"如上命令所示，第一个grep语句会过滤掉所有包含helloWorld的日志行并传递给下一个命令，第二个grep命令会在此基础上过滤掉包含rale的日志行。这样就构成了AND关系，符合我们的要求。反向查询（正向查询+反向查询）有时，我们可能希望对日志进行反向查询，即找出不包含某些关键字的日志，这通常适用于问题比较模糊的场景。比如现在有用户投诉了，说某个功能不正常，但是作为中台服务，我们往往很难第一时间定位到具体的方法或者服务有问题，所以这位用户（假设有一个uid）打印出所有请求并过滤掉结果的正常方法。这可以与上述流水线指令结合使用。grep"$uid"应用程序.log|grep-v"SUCCESS"-v是--revert-match的缩写，这里会先找出所有uid的日志，过滤掉SUCCESS的调用成功。在故障排查的时间间隔内查看日志时所能获取的信息只有少而不是最少，导致日志查询更好，而不是最好。当用户报告问题时，有时他们只能向我们提供事件发生的大概时间，而没有任何其他信息。所以，我们需要查询这个时间区间内所有的入口调用，结合上面的反向查询，逐步筛选出真正需要关注的内容。这里假设每一行日志都有时间戳信息。有很多方法可以实现这一点。首先，我们可以使用我们之前提到的grep正则匹配模式：grep-E'2021-10-0219:\d\d:\d\d:'application.log这里使用正则表达式公式匹配所有日志在2021年10月2日19点。同理，如果要精确到时分秒，只需将相应位上的表达式改成具体值即可。这种方法有一个明显的缺点，就是灵活性不够。如果我们需要查询晚上19:58到20:02的数据，正则表达式很难满足。所以我们需要一个新的命令来做到这一点：sed。sed是一个流编辑器，可以支持比grep更复杂的指令和编辑文件。这里只提供时间段日志查询的语句，其他功能大家可以扩展阅读：sed-n'/2021-10-0219:58:00/,/2021-10-0220:02:00/p'application.log-n会过滤掉匹配的行，p表示打印到控制台。看-n后面紧接着的内容。在这里，它代表一个范围查询。该范围可以是行号、正则表达式或两者的组合。给出的示例是完全匹配的。范围查询的规则是找出并打印出所有满足的区间。例如范围是/a/,/z/，sed会依次找到所有满足起始行包含a和结束行包含z的区间。每次找到a到z的范围，sed就开始寻找包含a的下一行，然后寻找包含z的行，直到文件末尾。这种搜索方式在日志乱序的场景下是不利的。比如20:00的日志出现在20:02之后，可能不会被过滤掉。同理，如果日志中没有19:58:00和20:02:00这两个时间点的日志，也可能没有过滤掉正确的内容。因此，我们通常需要先打印出部分日志，得到日志行的时间戳，然后根据这个时间戳进行过滤。Highlightkeywords这里有一个提高grep命令可读性的选项，即highlightkeywords，以便更快地定位日志行。grep"logId"application.log--color=autoclassification/sorting上面给出了查询日志行的说明，下面我们将讨论一些常见的日志统计和分析操作。以下大部分操作日志平台都可以提供，但不排除有的时候我们需要手撕一个日志文件。统计关键字出现次数的场景其实在开发过程中遇到过。当时线上出了一些问题，需要计算一下影响了多少百分比的流量。统计指标是根据方法关键字+执行结果，表示请求受到系统异常的影响。因为数据量已经超过了单次查询最大行数的上限，所以最后不得不把日志文件下载到机器上进行统计。这时候就需要提一个新的命令wc:grep"methodName"application.log*|grep“失败”|wc-l这里的两个grep命令会帮我们过滤掉失败的请求，wc命令会输入Stream的统计信息，统计的内容可以包括字节数、行数或者字符数。这里的-l命令表示只显示行数。如果升级统计维度，我们希望统计有多少用户受到影响（日志中包含用户的uid），那么单纯统计行数会产生重复统计。因此，我们需要根据用户ID对日志行进行重复数据删除。这里引入一个新的命令uniq，它可以对整行或者行中的部分信息进行去重，统计每个关键词关联的行数。这里需要注意的是，uniq只对排好序的行生效，所以在使用uniq之前需要截取关键字并排序才能达到预期的效果grep"methodName"application.log*|grep“失败”|剪切-d''-f1|排序|uniq-c有一堆新的shell命令，首先是cut命令，cut命令会按照指定的规则将对应位的值复制到输出流中，类似于电脑c上的ctrl+。-d声明切割日志行的分隔符，这里根据空格切割行。-f指定要取的位置的值。cut命令后生成的字符串列表以1开头为下标，所以这里取拆分后的第一个字符串（假设日志格式为userIdtimestampthreadId....，当然userId不会是开头的内容在大多数情况下是行）。然后对所有的userIds进行排序，这里使用sort命令。最后使用uniq命令去重。-c选项表示在每列旁边显示该行重复的次数。导出结果假设现在我想将上面的统计结果导出到一个文件中，传递给其他人。linux管道还支持将输出流重定向到一个文件...很多命令...>result.txt其中txt文件只是一个例子，你可以声明其他格式的文件。逆向思维——打印日志的最佳实践在介绍了上面的一些日志解析和统计方法之后，我们也思考了在系统中打印日志时的一些实践。日志格式的统一，往往可以让我们更快地完成一系列基于日志的统计分析。目前主流的日志格式通常如下：%level%d{yyyy-MM-ddHH:mm:ss.SSS}%F:%L%X{HOST_IP:-_}%X{LOG_ID:-_}%X{CLUSTER:-_}%X{STAGE:-_}[%t]%m%n%wEx-->可以看到会包含日志级别、分布式logId、时间戳、关键主机信息（ip、环境),threadid等。同理，如果我们在业务系统中打印的日志也能遵循一定的格式，将大大增强日志排查的可读性和便利性。比如在打印RPCServer日志的时候，我一般会给出三种类型的日志，Startlogs、Finishlogs和Digestlogs。privatestaticfinalStringSTART_LOG_TEMPLATE="[rpc_server_start][方法]:{}[请求]:{}";privatestaticfinalStringFINISH_LOG_TEMPLATE="[rpc_server_finish][方法]:{}[成功]:{}[持续时间]:{}s[请求]:{}[结果]:{}";privatestaticfinalStringDIGEST_LOG_TEMPLATE="[rpc_server_digest][方法]:{}[成功]:{}[持续时间]:{}s";其中Start日志是在请求开始处理之前打印的，包括输入参数，调用者等信息，而Finish日志是打印输入参数，输出参数，成功和耗时。Digest日志比较特殊，它不包含调用的任何请求响应信息，它只打印出调用的方法，是否成功，耗时等信息。摘要日志通常用于快速性能分析。小结本文提到的日志操作只是整个日志文件处理操作中的冰山一角，但一定是最常见、最有可能被用到的。希望对大家有所帮助。也欢迎大家收藏到自己的工具包中，或者在下方留言说说遇到的日志分析问题，博主会完善到文章中。
