Spell 基于最长公共子序列的在线日志解析方法

文章目录

01 日志模板挖掘
02 基于 LCS 的日志解析流程
- 2.1 日志键匹配查找
- 2.2 拆分与合并处理
- - 2.2.1 拆分过程
  - 2.2.2 合并过程
03 匹配查找优化
- 3.1 前缀树预过滤
- 3.2 倒排索引查找
04 Spell 日志解析实验
- 4.1 Spell 实现步骤
- 4.2 测试数据集
- 4.3 Spell 解析结果
- 4.4 Spell 查找优化
参考资料

01 日志模板挖掘

系统日志通常包含两个部分，一个部分是日志时间戳、日志类型和主机名等结构化的信息，另一部分则是开发人员通过代码打印的日志文本内容。下图展示的就是 Linux 系统中 syslog 消息数据包的格式，PRI 和 HEADER 即为日志结构化部分，而 MSG 则是日志正文内容。

日志文本内容通常是异常检测和故障诊断等任务的主要关注点，它可以进一步地分为常量和变量两部分，其中，常量描述的是当前程序的行为或功能，而变量则反映程序运行过程中的动态上下文信息。日志文本内容常量部分在本质上对应的就是开发人员在程序中编写的日志打印语句，例如下面这些日志记录的日志打印语句就是printf("Accepted password for %s from %s port %d ssh2")，其中变量则是由系统运行时的取值决定的。如果用*代替日志内容中的变量部分就可以得到其日志模板（也被称为日志键）为Accepted password for * from * port * ssh2。

Accepted password for root from 112.64.243.186 port 2371 ssh2
Accepted password for root from 115.135.143.16 port 2421 ssh2
Accepted password for root from 155.164.230.92 port 2532 ssh2

所以，日志模板就可以直接代表某一类型的日志数据，这一特性使得日志模板在日志处理应用中备受关注。首先，使用日志模板而非原始日志数据进行下游业务，使得需要处理的日志数据规模急剧收缩，因为大量的日志条目都可以匹配相同的日志模板。另外，内容相似的异构日志数据可以通过日志模板挖掘被统一到一个日志模板集合中，这在一定程度上解决的高复杂度系统中日志数据异构的问题。

不仅能有效压缩日志数据规模，日志模板还可以有效保留日志数据的关键信息。日志模板往往通过日志文本内容的常量部分来标识，而日志事件的主要内涵就是通过常量部分来表征，所以日志模板可以有效保留日志事件信息。另外，日志模板又往往与程序中的日志打印语句对应，所以它也可以在一定程度上保留日志打印语句的上下文关系信息，从而实现对程序执行路径的记录。

总的来说，日志模板挖掘是进行日志异常检测等下游业务的基础，本文介绍一种在线日志解析方法 Spell：《Spell: Online Streaming Parsing of Large Unstructured System Logs》

02 基于 LCS 的日志解析流程

Spell 是一种基于最长公共子序列的在线流式日志解析方法。该方法能够动态地提取日志模板，并能实时解析和维护日志内容。其中，最长公共子序列(Longest Common Subsequence, LCS)的定义是对于一个序列 S，如果它是两个或多个已知序列的子序列，且是符合此条件的子序列中长度最大的，则称 S 为已知序列的最长公共子序列。

Spell 基于 LCS 实现流式日志解析的关键在于维护一个存储日志键和其他信息的数据结构 LCSMap。LCSMap 中保存每一个具体日志键内容的数据结构称为 LCSObject ，它包含两部分内容：一部分是已解析的 LCS 序列LCSseq，另一部分是记录参数位置的列表 paramPos。使用LCSMap 实现基于 LCS 的日志解析流程如下图所示：

如上图所示，基于 LCS 的日志解析流程主要包含两个关键步骤：新 LCS 获取、LCSMap 更新。当新的日志条目到达时，首先使用一组预定义的定界符将其解析为字符串组序列。然后，将该日志记录序列与当前 LCSMap 中所有 LCSObject 中的日志键 LCSseq 进行比较，查找与新到日志记录匹配的日志键 LCSseq。如果 LCSMap 列表为空或者没有找到匹配的日志键，则创建一个新的 LCSObject 并将其插入 LCSMap 中。

2.1 日志键匹配查找

当一个解析后的新日志记录的新日志序列到达时，依据该日志序列搜索 LCSMap 中匹配的日志键。查找过程使用循环遍历，简单地遍历整个LCSMap中的日志键集合。对于集合中的每个日志键，维持一个指向日志键头部的指针和另一个指向新日志记录序列头部的指针。如果两指针指向的元素匹配，则将两个指针都移进；否则只能前进新日志记录序列的指针，当该到达的结尾时，检查日志键指针是否也到达末尾。

在查找过程中，同时计算 LCSObject 中 LCSseq 日志键与新日志序列的最长公共子序列 LCS 的长度。最终保留最长 LCS 对应的 LCSObject 索引，如果该长度值大于日志序列中元素数量的一半，则该 LCSObject 保存的日志键为该新日志序列最佳匹配的日志键。因此，除非新日志序列中参数值的总长度超过其大小的一半，否则新 LCS的长度可以很好地指示对应 LCSObject 中的日志键是否与该日志序列共享相同的日志键。

如果存在多个具有相同最大值的 LCSObject，则选择索引值最小的哪一个，因为它与新日志序列集合相似性值较高。然后，使用回溯来生成新的 LCS 序列，以表示匹配 LCSObject 和新日志序列中所有日志条目的日志键。如果 LCSMap 中现有日志键集合中的任何一个都不与新日志序列匹配且长度至少为序列长度一半的 LCS，则在LCSMap 中为该新日志序列创建一个新的 LCSObject，并将其 LCSseq 设置为日志序列本身。具体算法和其 LCS查找方法 LCSsearch 伪代码如下所示：

//基于LCS的日志数据解析算法
输入：原始日志数据
输出：存储日志数据解析后元数据的数据结构LCSMap初始化LCSMap；While 一个新日志数据到达 do将新日志数据解析为日志键和参数值向量为LCSMap读访问加锁使用LCSsearch方法遍历LCSMap寻找匹配日志键，若没有则创建newLCS为LCSMap读访问解锁If newLCS不为NULL为LCSMap写访问加锁将newLCS添加到LCSMap中为LCSMap写访问解锁end ifend whilereturn LCSMap
//-------------------------------------
//LCSMap查找方法LCSsearch
输入：新日志序列和LCSMap
输出：一个可为NULL的新最长公共子串LCS初始化最初匹配子串长度maxlFor each LCSObject in LCSMap do计算最长公共子串长度lIf maxl小于或者等于lmaxl = lend ifend forif maxl小于日志键长度的二分之一设置newLCS为NULL，并返回该匹配LCSelse获取该新日志的最长公共子串LCS，并将其作为newLCS返回end if

2.2 拆分与合并处理

在 LCSMap 的维护中可能出现日志键元素被错判断为参数，或者参数数量过多时参数被错判断为日志键元素的情况。针对这两种情况，Spell 通过定期应用拆分和合并过程来清理当前已解析的日志键。

2.2.1 拆分过程

拆分过程被应用于 LCSMap 中的每个 LCSObject，并在 LCSObject 中引入了另一个字段 params。 params是一个键值对集合，这些键值对存储从历史记录中看到的每个参数位置的所有参数值，以及每个参数值出现的频次。这些键值对可以在回溯过程中轻松生成和更新以生成LCS。

上文中我们提到每个 LCSObject 都有一个 paramPos 列表，该列表中包含了日志序列中参数值位置和 LCSseq 日志键参数的占位符。拆分过程的基本思想是利用上述观察结果并分割一些现有参数，并且将参数值包含在日志键中，对 LCSMap 中的每个 LCSObject 遍历 params 字段中键值对应的参数列表，并计算每个参数位置处唯一元素的数量。如果该位置的唯一元素数量小于拆分阈值，并且该元素包含任何数字值，则认为该位置将有助于日志键。在这种情况下，将该日志键拆分为几个新的 LCSObject，用每个新 LCSObject 的 LCSseq 中相同位置的唯一元素替换该 LCSseq 日志键中的参数位置。

2.2.2 合并过程

基于 LCS 的日志模板提取方法中是使用阈值来区分两个序列的 LCS 是否是有效的日志键，但是在某些情况下，一个日志条目中的参数数量可能太多，以至于这种基于阈值的方法无法正确提取日志键。为了解决此问题 Spell 中引入了合并过程。

合并过程首先将可能具有相同消息类型的当前 LCSObject 聚类在一起，然后在每个位置计算不同标记的数量这些 LCSObject 中的 LCSseq。在将 LCSMap 划分集群的过程中，如果每个集群满足以下条件，就看作具有相同日志键的LCSObject：

对于日志序列元素位置的子集，当前群集中此位置的所有日志键仅存在一个唯一元素
对于每个其他日志序列元素位置，当前群集中所有日志键的唯一元素数超过了合并阈值

对于具有数字的位置和仅具有字符串的位置，合并阈值是不同的。考虑一个位置中的任何日志键元素中是否有数字，那么该位置可以是参数位置。在这一分区步骤之后，可以认为一个群集内的所有日志序列都具有相同的日志键。因此，可以将它们合并到单个 LCSObject 中，将条件二中的位置分配为参数位置，并将条件一中的元素作为消息类型的一部分插入到 LCSseq 中。

03 匹配查找优化

原始的 Spell 方法是使用循环遍历的方式进行匹配查找的，这种方法的时间复杂度为O(mn)，所以当日志键规模很大时，这种查找方式的效率极低。为此 Spell 中使用前缀树进行预过滤和倒排索引查找优化这一查找过程。

在维护LCSMap 的过程中，当有新的日志记录到达时，首先进行预过滤搜索前缀树中现有日志键；如果未发现匹配的日志键，进一步在倒排索引中查找匹配的日志键；最后，如果仍未找到匹配的日志键，使用简单的循环遍历方法将其与 LCSMap 中保存的所有日志键进行比较，并相应地更新 LCSMap；如果遍历之后仍然无匹配日志键，则计算并创建一个新的 LCSObject 保存该日志键并插入到 LCSMap 中。该流程的示意图如下所示：

3.1 前缀树预过滤

在实际情况中日志记录中的参数往往会出现在结尾处，这使得使用前缀树进行日志键查找十分准确和高效。相较于倒排索引查找和循环遍历，前缀树方法在时间复杂的上具有明显的优势，对于大多数日志记录，它们的日志键很可能已经在索引树中存在，并且前缀树方法的时间复杂度仅为O(n)。

上图展示了一个使用前缀树查找日志键的示例，其中LCSMap中已存在的日志键集合 strs = {ABC; ACD; AD; EF}，由一棵前缀树 T 索引。当一个新的日志记录被解析为日志键元素序列 a=ABPCa=ABPCa=ABPC 到达时。将 aaa 的每个元素与前缀树T的每个节点进行比较，便可以有效地修剪T中的大多数分支，并将其中 aaa 与T中的任何节点都不匹配的字符标记为日志键中的参数。在 a=ABPCa=ABPCa=ABPC 的情况下，将 ABC 标识为的匹配的日志键，并将 P 标识为其参数。

前缀树查找匹配日志键在效率上具有明显的优势，但此方法仅保证在对于特定日志键已经存在的情况下才能返回。而且，它不能保证返回的日志键是最佳匹配项，即对应最长的日志键。例如，如果 a=DAPBCa=DAPBCa=DAPBC 且 LCSMap 中日志键为{DA，ABC}，则经过前缀树查找返回的匹配日志键 DA 而不是 ABC。在某些情况下，LCSMap 中存在到达日志记录序列对应的日志键，但是日志键按前缀树返回的日志键是元素个数少于一个该日志记录序列元素总数的一半，这种返回的日志键也不是最佳匹配日志键。

3.2 倒排索引查找

为了避免构建复杂的前缀树，前缀树无法包含保存所有情况的日志键序列。在前缀树查找过程中没有找到匹配日志键时，需要对 LCSMap 进行二次遍历查找对应日志键。为了避免遍历整个 LCSMap 保存的日志键集，使用倒排索引查找的方法，该方法可以跳过检查一定数量的日志键。反向索引I建立在 LCSMap 的日志键集合 Strs 之上，一个倒排索引查找日志键实例如下图所示。对于 Strs 中的每个唯一字符，在出现的所有日志键中记录其日志键位置和元素出现位置并排序，倒排索引查找的子序列的过程如下。

对于 a=ABPCa=ABPCa=ABPC 中的每个字符，找到它是否出现在索引表I中。如果不存在，则将该字符视为参数并跳过；否则，为匹配的反向列表分配一个唯一的、自动递增的ID，即 ID1、2、3 分别指向A，B和C。
对于该匹配列表，使用排序合并联接样式方法对其进行扫描。与其尝试在所有列表中查找相等的项，我们尝试按照分配给这些列表的ID的顺序查找在反向索引矩阵中是否有相同字符串ID的列来构成的子序列。例如，A列表中的（1,1），B列表中的（1,2），C列表中的（1,3）遵循分配的ID的顺序，并共享相同的字符串ID值1并形成一个适当的子序列。
对于最后一步返回的所有匹配日志键中找到最长的，并检查其长度是否大于日志记录元素序列长度的一般。这样就完成了反向索引查找过程。在这种方法中，考虑了所有字符串，时间复杂度仅为O（c*n），其中 c 是每个反向列表的平均长度，即日志键集合中重复字符的平均数量。

04 Spell 日志解析实验

4.1 Spell 实现步骤

基于 LCS 的流式日志解析方法 Spell 解析日志的抽象流程如下：

初始化，包括(1)日志对象 LCSObject，包括日志模板 LCSseq 和行数列表 lineIds；(2)存放所有日志对象的列表 LCSMap。
流式的读取日志
当读取到一个新的日志条目之后，遍历 LCSMap，寻找该日志与所有 LCSObject 的最大公共子序列，如果子序列的长度大于日志序列长度的一半，则认为该日志该与日志键匹配。如果找到匹配的日志对象，跳转5，如果没有，或者 LCSMap 为空，则跳转第4步；
将该行日志初始化为一个新的 LCSObject，放入列表 LCSMap 中。
将该行日志更新到匹配的 LCSObject 的行数列表 lineIds 中，并且更新 LCSseq。
跳转到第2步，直到日志读取完毕。

4.2 测试数据集

本测试数据集是在一个 203 个节点的 HDFS 集群中使用基准工作负载产生的，在日志产生过程中根据手工制定的规则通过人工来识别并标记异常 ✅。这些日志数据根据块 ID 分割成称为追踪（trace）的日志序列，然后每条与块 ID 关联的追踪都被标记了正常或异常的标签。除此之外，HDFS 日志数据集还包括具体异常类型的信息，所以也可以将它用于重复问题识别的研究。

部分数据样式如下所示：

081109 203518 143 INFO dfs.DataNode$DataXceiver: Receiving block blk_-1608999687919862906 src: /10.250.19.102:54106 dest: /10.250.19.102:50010081109 203518 35 INFO dfs.FSNamesystem: BLOCK* NameSystem.allocateBlock: /mnt/hadoop/mapred/system/job_200811092030_0001/job.jar. blk_-1608999687919862906081109 203519 143 INFO dfs.DataNode$DataXceiver: Receiving block blk_-1608999687919862906 src: /10.250.10.6:40524 dest: /10.250.10.6:50010081109 203519 145 INFO dfs.DataNode$DataXceiver: Receiving block blk_-1608999687919862906 src: /10.250.14.224:42420 dest: /10.250.14.224:50010081109 203519 145 INFO dfs.DataNode$PacketResponder: PacketResponder 1 for block blk_-1608999687919862906 terminating081109 203519 145 INFO dfs.DataNode$PacketResponder: PacketResponder 2 for block blk_-1608999687919862906 terminating081109 203519 145 INFO dfs.DataNode$PacketResponder: Received block blk_-1608999687919862906 of size 91178 from /10.250.10.6081109 203519 145 INFO dfs.DataNode$PacketResponder: Received block blk_-1608999687919862906 of size 91178 from /10.250.19.102

4.3 Spell 解析结果

LCSMap 数据结构中的一个 LCSObject 解析结果如下所示：

{"lcsseq": "081109 * INFO dfs.DataNode$DataXceiver: * Served block * to * ", "lineids": [47, 48, 65, 70, 71, 72, 81, 82, 83, 84, 85, 86, 87, 88, 89, 90, 91, 92, 93, 94, 95, 96, 97, 98, 99, 100, 101, 102, 103, 104, 105, 106, 107, 108, 109, 110, 111, 112, 113, 114, 115, 116, 120, 121, 122, 123, 124, 125, 126, 127, 128, 129, 130, 131, 132, 133, 134, 135, 136, 137, 138, 139, 140, 141, 142, 143, 144, 145, 146, 147, 148, 149, 150, 151, 152, 153, 154, 155, 156, 160, 161, 162, 163, 164, 165, 166, 167, 168, 169, 170, 171, 172, 173, 174, 175, 176, 178, 179, 180, 181, 182, 183, 184, 185, 186, 187, 188, 189, 190, 191, 192, 193, 194, 195, 196, 197, 198, 199, 200], "postion": [1, 4, 7, 9]}

解析后的结构化日志数据的字段包括LineId,Month,Date,Time,Type,Component,Content,EventId,EventTemplate,ParameterList，部分结果如下所示：

1    81109   203518  143 INFO    dfs.DataNode$DataXceiver    Receiving block blk_-1608999687919862906 src: /10.250.19.102:54106 dest: /10.250.19.102:50010   6af214fd    Receiving block <*> src <*> <*> dest <*> 50010  ['blk_-1608999687919862906', '/10.250.19.102:54106', '/10.250.19.102']2   81109   203518  35  INFO    dfs.FSNamesystem    BLOCK* NameSystem.allocateBlock: /mnt/hadoop/mapred/system/job_200811092030_0001/job.jar. blk_-1608999687919862906  26ae4ce0    BLOCK* NameSystem.allocateBlock <*>   ['mnt/hadoop/mapred/system/job_200811092030_0001/job.jar. blk_-1608999687919862906']3 81109   203519  143 INFO    dfs.DataNode$DataXceiver    Receiving block blk_-1608999687919862906 src: /10.250.10.6:40524 dest: /10.250.10.6:50010   6af214fd    Receiving block <*> src <*> <*> dest <*> 50010  ['blk_-1608999687919862906', '/10.250.10.6:40524', '/10.250.10.6']4   81109   203519  145 INFO    dfs.DataNode$DataXceiver    Receiving block blk_-1608999687919862906 src: /10.250.14.224:42420 dest: /10.250.14.224:50010   6af214fd    Receiving block <*> src <*> <*> dest <*> 50010  ['blk_-1608999687919862906', '/10.250.14.224:42420', '/10.250.14.224']5   81109   203519  145 INFO    dfs.DataNode$PacketResponder    PacketResponder 1 for block blk_-1608999687919862906 terminating    dc2c74b7    PacketResponder <*> for block <*> terminating   ['1', 'blk_-1608999687919862906']6  81109   203519  145 INFO    dfs.DataNode$PacketResponder    PacketResponder 2 for block blk_-1608999687919862906 terminating    dc2c74b7    PacketResponder <*> for block <*> terminating   ['2', 'blk_-1608999687919862906']

使用 HDFS 数据集的10万条日志数据解析得到的主要日志模板如下所示：

EventId  EventTemplate   Occurrences
6af214fd    Receiving block <*> src <*> <*> dest <*> 50010  23611
26ae4ce0    BLOCK* NameSystem.allocateBlock <*>   7940
dc2c74b7    PacketResponder <*> for block <*> terminating   22224
fe505892    Received block <*> of size <*>  22254
5eaa2a11    BLOCK* NameSystem.addStoredBlock blockMap updated <*> 50010 is added to <*> size <*>  22287
f8efb72f    <*> 50010 Transmitted block <*> to <*> 50010  25
19c98479    <*> 50010 Starting thread to transfer block <*> to <*> 50010 <*>    26
ebbb5fe2    BLOCK* ask <*> 50010 to replicate <*> to datanode(s) <*> 50010 <*>  26
3a7f0f8e    <*> 50010 Served block <*> to <*> 407
32777b38    Verification succeeded for <*>    1088
f441c5d6    writeBlock blk_-3102267849859399193 received exception java.net.SocketTimeoutException  1
88608495    PacketResponder blk_-3102267849859399193 2 Exception java.io.EOFException   1
5b992f13    writeBlock <*> received exception java.io.IOException Could not read from stream  62
dba996ef    Deleting block <*> file <*> 22
0567184d    Receiving empty packet for block <*>  24

4.4 Spell 查找优化

原始的 Spell 方法是使用循环遍历的方式进行匹配查找的，这种方法的时间复杂度为O(mn)，所以当日志键规模很大时，这种查找方式的效率极低。为此 Spell 中使用前缀树进行预过滤和倒排索引查找优化这一查找过程。增加优化措施和原生 LCS 方法日志解析效率对比实验如下。

根据 HDFS 数据集的10万条日志数据构造的前缀树如下图所示：

通过控制变量法针对日志数据量的对比实现结果如下图所示：

参考资料

Du M , Li F . Spell: Online Streaming Parsing of Large Unstructured System Logs | J. IEEE Transactions on Knowledge and Data Engineering, 2018, PP:1-1.