日誌分析的模式發現功能實現(1)

01-28

模式發現，幾乎已經快成為日誌分析產品中標配的機器學習功能。當然各家有各家的實現方式。準備開啟一個系列文章，分別介紹幾家主要的產品里該功能的做法，以及可行的類似效果的實現方式。當然，肯定不是人家真正的實現方式，畢竟我可不是偷代碼的……

作為系列文章的開始，還是要給不清楚這個功能的讀者先科普一下這個功能的作用。

大家如果只分析個Nginx日誌，是用不著模式發現功能的。但是如果你開始做一個全公司的AIOps平台，接入來自不同部門的應用日誌、設備日誌、系統日誌以後，你會發現什麼你再也沒時間挨個寫正則、配告警了，因為種類太多了——像思科的ASA日誌種類大概有三百多種，何況公司通常不會只採購同一型號的設備，而是多家。

但是在進行日常巡檢、故障排查的時候，又有必要了解日誌的整體狀態、有哪些種類、佔比多少、趨勢如何。所以，我們需要一個特定的功能，能自動進行日誌的文本格式分類。這就是『模式發現』功能。有時候，也會按照其主要技術實現，叫做『日誌聚類』功能。

---------------------------

好了，現在進入第一篇的主題，當然從行業老大說起：

Splunk 是從 6.2 版本推出的這個功能，會基於當前搜索語句的結果集做模式探測，根據精度調整，做成不同數量的聚類。然後給每個聚類分組內，提取出一個關鍵詞（個別情況下也有零個或多個的）。也就是通過機器學習的手段，探測你的日誌可能有什麼模式，其最具識別性的關鍵內容是什麼。

這個頁面雖然看著是特定的，但是以splunk一切皆命令的理念，頁面的內容也是可以直接用 SPL 獲取的。這個對應的語句就是：index=_internal | cluster t=0.8 lableonly=true | findkeywords labelfield=cluster_label | sort - percentInputGroup

好了，看起來在splunk里達到這個目的很簡單呢！那麼轉過頭來，我們在開源的 ELK 上，能做到么？

我們目前當然在 ES 里是沒法做聚類分析什麼的了。不過在日誌場景下，也不是沒有近似的辦法。

第一步：完成山寨版的日誌模式分組

其實如何山寨模式分組，Splunk 也有類似 SPL 命令做出了示範。這個命令叫 typelearner。

這個命令的大致意思是：把日誌里的英文單詞、數字、空格等字元都隱藏掉，剩下各種標點符號，就代表一種日誌類型。簡單的處理方式就是：

# cat cisco.asa.log | nsed 『s/^(.{128}).*/1/』 | nsed 『s/[0-9a-zA-Z]*//g』 | nsed 『s/[[:space:]]/_/g』 n

然後將這個純標點符號的字元串，存為事件的一個欄位，我們沿襲 Splunk 的叫法： punct 。

這樣，我們只要簡單的對 punct 欄位做 terms aggregation 就可以獲取模式分組了。

這個操作，也可以直接在 Logstash 里配置完成：

filter {n fingerprint {n source => 」message」n target => 「punct」n method => 「PUNCTUATION」n }n}n

第二步：完成分組內的關鍵詞查找

然後查找關鍵詞。什麼叫關鍵詞呢？就是要能讓本分組跟其他分組有顯著差異的一個詞。這個顯然不能再用 terms aggregation 了。否則出來的是最多的詞，而不是最有差異性的詞。ES 對這個也提供了現成的聚合方式：significant_terms aggregation。

然後這裡有另一個問題：一般我們都是在 not_analyzed 欄位上做聚合統計的。現在顯然並沒有具體哪個欄位來提供單個欄位值做聚合！我們需要用的就是分詞的日誌原文內容。

所以這塊我們需要對原文欄位的 mapping 做出特殊定義：

"message": {n "type": "text",n "fielddata": true,n "index_options": "docs",n "norms": falsen }, n

即重新放開 fielddata —— ES 5.0 里，text 類型欄位已經默認關閉 fielddata 了。（ES 6.0 後，text 類型欄位單獨提供了一個 significant_text aggregation，但是不能再加 sub aggregation，這樣我們就拿不到對應的日誌原文樣例了，可惜）

至於內存的問題，或者交給 Circuit Breaker 來控制；或者自己通過請求中的 terminate_after參數預先控制。

就模式發現這個功能來說，通過 terminate_after 參數預定義控制應該是個不錯的思路。因為本來就是一個不確定的猜測，加太大的數據量來做這事兒，沒多少性價比。

所以我們最終發出的請求是這樣：

#!/bin/bashncurl -XPOST http://localhost:9200/logstash-2016.07.18/logs/_search?pretty&terminate_after=30000&size=0 -d n{n "aggs": {n "group": {n "terms": {n "field": "punct"n },n "aggs": {n "keyword": {n "significant_terms": {n "size": 1,n "field": "message"n },n "aggs": {n "hit": {n "top_hits": {n "_source": {n "include": [ "message" ]n },n "size":1n }n }n }n }n }n }n }n}n n

我們可以看到請求結果如下：

{ "took" : 2179, "timed_out" : false, "terminated_early" : false, "_shards" : { "total" : 5, "successful" : 2, "failed" : 3, "failures" : [ { "shard" : 0, "index" : "logstash-2016.07.18", "node" : "L0qQ1ZcyQGmj7Ge7ZlCmYg", "reason" : { "type" : "circuit_breaking_exception", "reason" : "[request] Data too large, data for [<reused_arrays>] would be larger than limit of [415550668/396.2mb]", "bytes_wanted" : 415762160, "bytes_limit" : 415550668 } } ] }, "hits" : { "total" : 371095, "max_score" : 0.0, "hits" : [ ] },n "aggregations" : { "group" : { "doc_count_error_upper_bound" : 72, "sum_other_doc_count" : 93355,n "buckets" : [ {n "key" : "--_::._+____-_=,_=,_=,_=.,_=,_=",n "doc_count" : 98100,n "keyword" : { "doc_count" : 98100, "buckets" : [ {n "key" : "cpu_seconds",n "doc_count" : 98100,n "score" : 2.2037623779471813,n "bg_count" : 115831,n "hit" : { "hits" : { "total" : 98100, "max_score" : 1.0,n "hits" : [ { "_index" : "logstash-2016.07.18", "_type" : "logs", "_id" : "AVX-RMJbLjo3PexoUujh", "_score" : 1.0, "_source" : {n "message" : "07-15-2016 14:17:33.776 +0800 INFO Metrics - group=pipeline, name=indexerpipe, processor=index_thruput, cpu_seconds=0.000000, executes=111, cumulative_hits=161675"n } } ] } } } ] }n }, { "key" : "--_::._+____-_=,_=,_=,_=,_=,_=,_=", "doc_count" : 87058, "keyword" : { "doc_count" : 87058, "buckets" : [ { "key" : "largest_size", "doc_count" : 75663, "score" : 2.835574761742766, "bg_count" : 75663, "hit" : { "hits" : { "total" : 75663, "max_score" : 1.0, "hits" : [ { "_index" : "logstash-2016.07.18", "_type" : "logs", "_id" : "AVX-RMJbLjo3PexoUuj9", "_score" : 1.0, "_source" : { "message" : "07-15-2016 14:17:02.780 +0800 INFO Metrics - group=queue, name=nullqueue, max_size_kb=500, current_size_kb=0, current_size=0, largest_size=1, smallest_size=0" } } ] } } } ] } }, { "key" : "--_::._+____-_=,_="",_=.,_=.,_=.,_=,_=.,_=", "doc_count" : 26317, "keyword" : { "doc_count" : 26317, "buckets" : [ { "key" : "max_age", "doc_count" : 26317, "score" : 7.224805514306611, "bg_count" : 45119, "hit" : { "hits" : { "total" : 26317, "max_score" : 1.0, "hits" : [ { "_index" : "logstash-2016.07.18", "_type" : "logs", "_id" : "AVX-RMJbLjo3PexoUukH", "_score" : 1.0, "_source" : { "message" : "07-15-2016 14:17:02.780 +0800 INFO Metrics - group=per_sourcetype_thruput, series="scheduler", kbps=0.014869, eps=0.032258, kb=0.460938, ev=1, avg_age=0.000000, max_age=0" } } ] } } } ] } }, { "key" : "--_::._+____-_=,_="//////.",_=.,_=.,_=.,_=,_=.,_=", "doc_count" : 13063, "keyword" : { "doc_count" : 13063, "buckets" : [ { "key" : "log", "doc_count" : 13063, "score" : 27.241628614916287, "bg_count" : 13140, "hit" : { "hits" : { "total" : 13063, "max_score" : 1.0, "hits" : [ { "_index" : "logstash-2016.07.18", "_type" : "logs", "_id" : "AVX-RMKILjo3PexoUulQ", "_score" : 1.0, "_source" : { "message" : "07-15-2016 14:16:31.780 +0800 INFO Metrics - group=per_source_thruput, series="/applications/splunk/var/log/splunk/metrics.log", kbps=0.326188, eps=2.032164, kb=10.112305, ev=63, avg_age=0.968254, max_age=1" } } ] } } } ] } }, { "key" : "--_::._+____-_=,_=,_=.,_=.,_=.,_=.,_=.,_=.", "doc_count" : 11603, "keyword" : { "doc_count" : 11603, "buckets" : [ { "key" : "average_kbps", "doc_count" : 11603, "score" : 20.38013481592441, "bg_count" : 17357, "hit" : { "hits" : { "total" : 11603, "max_score" : 1.0, "hits" : [ { "_index" : "logstash-2016.07.18", "_type" : "logs", "_id" : "AVX-RMKILjo3PexoUulA", "_score" : 1.0, "_source" : { "message" : "07-15-2016 14:16:31.781 +0800 INFO Metrics - group=thruput, name=index_thruput, instantaneous_kbps=0.875684, instantaneous_eps=2.032165, average_kbps=0.340430, total_k_processed=33138.000000, kb=27.147461, ev=63.000000" } } ] } } } ] } }, { "key" : "--_::._+____-_=,_=,_=,_=,_=", "doc_count" : 11417, "keyword" : { "doc_count" : 11417, "buckets" : [ { "key" : "qwork_units", "doc_count" : 11417, "score" : 31.50372251905054, "bg_count" : 11417, "hit" : { "hits" : { "total" : 11417, "max_score" : 1.0, "hits" : [ { "_index" : "logstash-2016.07.18", "_type" : "logs", "_id" : "AVX-RMLOLjo3PexoUunn", "_score" : 1.0, "_source" : { "message" : "07-15-2016 14:15:29.777 +0800 INFO Metrics - group=tpool, name=indexertpool, qsize=0, workers=2, qwork_units=0" } } ] } } } ] } }, { "key" : "--_::._+____-_=,_=,_=---,_=.,_=,_=", "doc_count" : 11350, "keyword" : { "doc_count" : 11350, "buckets" : [ { "key" : "generic", "doc_count" : 11350, "score" : 31.69559471365639, "bg_count" : 11350, "hit" : { "hits" : { "total" : 11350, "max_score" : 1.0, "hits" : [ { "_index" : "logstash-2016.07.18", "_type" : "logs", "_id" : "AVX-RMJbLjo3PexoUukk", "_score" : 1.0, "_source" : { "message" : "07-15-2016 14:17:02.779 +0800 INFO Metrics - group=pipeline, name=indexerpipe, processor=syslog-output-generic-processor, cpu_seconds=0.000000, executes=104, cumulative_hits=161564" } } ] } } } ] } }, { "key" : "--_::._+____-_=,_=,_=,_=.", "doc_count" : 7135, "keyword" : { "doc_count" : 7135, "buckets" : [ { "key" : "search_health_metrics", "doc_count" : 7135, "score" : 51.010511562718996, "bg_count" : 7135, "hit" : { "hits" : { "total" : 7135, "max_score" : 1.0, "hits" : [ { "_index" : "logstash-2016.07.18", "_type" : "logs", "_id" : "AVX-RMJbLjo3PexoUujq", "_score" : 1.0, "_source" : { "message" : "07-15-2016 14:17:33.776 +0800 INFO Metrics - group=search_health_metrics, name=bundle_directory_reaper, bundle_dir_reaper_max_ms=1, bundle_dir_reaper_mean_ms=1.000000" } } ] } } } ] } }, { "key" : "--_::._+____-_=,_=,_=,_=.,_=,_=,_=,_=", "doc_count" : 5849, "keyword" : { "doc_count" : 5849, "buckets" : [ { "key" : "search_queue_metrics", "doc_count" : 5849, "score" : 62.445888186014706, "bg_count" : 5849, "hit" : { "hits" : { "total" : 5849, "max_score" : 1.0, "hits" : [ { "_index" : "logstash-2016.07.18", "_type" : "logs", "_id" : "AVX-RMKILjo3PexoUulx", "_score" : 1.0, "_source" : { "message" : "07-15-2016 14:16:31.777 +0800 INFO Metrics - group=search_concurrency, name=search_queue_metrics, enqueue_seaches_count=0, avg_time_spent_in_queue=0.000000, max_time_spent_in_queue=0, current_queue_size=0, largest_queue_size=0, min_queue_size=0" } } ] } } } ] } }, { "key" : "--_::._+____-_=,_=,_=,_=,_=,_=,_=,_=,_=,_=,_=,_=,_", "doc_count" : 5848, "keyword" : { "doc_count" : 5848, "buckets" : [ { "key" : "max_ready", "doc_count" : 5848, "score" : 62.45673734610123, "bg_count" : 5848, "hit" : { "hits" : { "total" : 5848, "max_score" : 1.0, "hits" : [ { "_index" : "logstash-2016.07.18", "_type" : "logs", "_id" : "AVX-RMJbLjo3PexoUuk5", "_score" : 1.0, "_source" : { "message" : "07-15-2016 14:17:02.776 +0800 INFO Metrics - group=searchscheduler, dispatched=1, skipped=0, total_lag=1, max_ready=0, max_pending=0, max_lag=1, window_max_lag=0, window_total_lag=0, max_running=0, actions_triggered=0, completed=1, total_runtime=0.189, max_runtime=0.189" } } ] } } } ] } } ] } } } n

響應體中可以看到因為 terminate_after 設得還是過大，所以還沒到中止條數就被 kill 了。實際只掃描了 370173 條數據。那麼我們下次就可以把 terminate_after 調成 10000 得了。

然後就是 significant_terms 返回的關鍵詞們。跟之前 splunk 的截圖相比，我們可以發現，不是完全一樣的效果，但是還是有部分關鍵詞是一致的。比如 smallest_size, total_k_processed, search_health_metrics, var, workers 等。

可以說，作為一個山寨品，這個做法是行得通的~