在java化項目中，部署到k8s集群后，一度出現(xiàn)無法定位問題的情況始苇。起初懷疑是日志調(diào)用鏈改造導(dǎo)致的，也修復(fù)了一些問題筐喳，但沒有解決根本問題

問題表現(xiàn)

1. 日志搜集不夠?qū)崟r
   在k8s中執(zhí)行kubectl logs --tail=500 test-6bb5648c4c-4fmrr -n testns隨機取一條記錄催式，在kibana界面無法查詢
2. 日志沒有被搜集
   上個問題或許過一段時間能查詢到，但有些日志則是完全無法查到避归，就算過了10分鐘也無法查到

3. 查看近幾天的日志荣月，發(fā)現(xiàn)如下規(guī)律：

   
   
   image.png

由上圖可知，日志在某個時間正常梳毙，然后越來越少哺窄。

問題定位

1. 首先查看elasticsearch
   • 查看索引狀態(tài)，一切正常

   get http://localhost :9200/test*
   green  open  test-2020.09.08                         6xRJEYkbRa-EIJRwFvXaow   3   1   37078449            2    205.3gb         97.7gb
   green  open   test-2020.09.07                         RrUCdqUFR26FBKcM91yMiA   3   1   39189071            0    190.2gb         95.1gb
   

   • 查看日志：除了個幾個由于mapping 解析錯誤的日志账锹，沒有異常
2. 再定位logstash日志
   • 曾發(fā)現(xiàn)有大量的grokFailure日志萌业，這個問題也會導(dǎo)致日志丟失，修正了grok牌废，但依然出現(xiàn)如上問題
   • 也曾發(fā)現(xiàn)由于匹配規(guī)則導(dǎo)致的一些日志遺漏咽白。但同樣沒有解決問題
3. 再查看kafka是否異常
   • 首先定位消費是否有延后，執(zhí)行如下命令
     ./kafka-consumer-groups.sh --bootstrap-server 10.64.175.183:9092 --describe --group test_k8
     發(fā)現(xiàn)一切正常鸟缕，并沒有阻塞導(dǎo)致日志查不到的現(xiàn)象。
4. 定位filebeat
   通過以上定位排抬，那基本出問題的可能只能是filebeat了懂从。
   • 查看filebeat日志
     kubectl logs filebeat-7sx7r -n kube-syste

      {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":660940,"time":{"ms":2108}},"total":{"ticks":7503770,"time":{"ms":25202},"value":7503770},"user":{"ticks":6842830,"time":{"ms":23094}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":21},"info":{"ephemeral_id":"3d0c7300-0a5b-405f-8fba-356fc3b3c085","uptime":{"ms":12930017}},"memstats":{"gc_next":131488384,"memory_alloc":74631384,"memory_total":1093590548216},"runtime":{"goroutines":128}},"filebeat":{"events":{"active":145,"added":61940,"done":61795},"harvester":{"open_files":13 1,"running":131,"started":2}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":61793,"batches":47,"total":61793}},"outputs":{"kafka":{"bytes_read":51946,"bytes_write":9380778}},"pipeline":{"clients":4,"events":{"active":573,"filtered":2,"published":61938,"total":61940},"queue":{"acked":61793}}},"registrar":{"states":{"current":39,"update":61795},"writes":{"success":49,"total":49}},"system":{"load":{"1":3.62,"15":3.97,"5":4.14,"norm":{"1":0.2263,"15":0.2481,"5":0.2588}}}}}}```  
     

   上面是filebeat自帶的monitoring日志，也就是filbeat的運行狀態(tài)蹲蒲，我們重點關(guān)注：
   "harvester":{"open_files":131,"running":131,"started":2}
   發(fā)現(xiàn)filbeat居然持有這么多文件番甩，也就是說還有131個文件還在搜集的狀態(tài)。
   • 回到對應(yīng)節(jié)點届搁，查看文件狀態(tài)缘薛。lsof |grep deleted

   之所以有這個步驟，1是因為之前cmo發(fā)現(xiàn)k8s報錯了卡睦，大量的文件顯示被刪除宴胧，但實際沒有刪除，仍然被filebeat持有表锻。不過因為當時只發(fā)現(xiàn)只有某個節(jié)點存在這種現(xiàn)象恕齐，不是普遍現(xiàn)象，所以沒有在意瞬逊。2.是filbeat持有這么多文件不正常显歧，現(xiàn)在發(fā)現(xiàn)是只要部署了該應(yīng)用的節(jié)點就有這種現(xiàn)象仪或，也就是filebeat啟動了搜集。

終極原因

定位到上面士骤，其實已經(jīng)差不多了范删，但要想揭開真相，還需要解決以下三個問題：

1. 為什么持有這么多文件拷肌？
2. 為什么持有這么多文件會導(dǎo)致上面的一系列問題呢瓶逃？
3. 還有沒有其他問題呢？
   除了第三個我們可以再解決了前面兩個問題之后觀察就能看出廓块，那么我們重點就是上面兩個問題了厢绝。

出現(xiàn)上述情況，直接原因我們可想而知是在##系統(tǒng)刪除了相關(guān)的日志文件之后带猴，filbeat還持有文件昔汉。

這里可能有兩個原因：

1. filebeat持有的文件沒有搜集完，所以繼續(xù)持有拴清，也就是那么多文件它都沒有搜集完靶病。
2. filebeat已經(jīng)搜集完了，但仍然沒有釋放文件口予。

最開始我們懷疑是因為filebeat沒有配置正確娄周，比如close_*配置選項。最后結(jié)合k8s中日志的輪轉(zhuǎn)方式排查沪停，filebeat采取的是默認配置：

1. close_renamed :這種情況在日志輪轉(zhuǎn)的時候發(fā)生煤辨，默認值是flase。
2. close_removed: 這個一般發(fā)生在日志真正刪除后木张。 默認值是true众辨。也就是會出現(xiàn)上述情況，日志被刪除了舷礼，filebeat仍繼續(xù)持有文件鹃彻。
3. close_inactive: 默認值是5分鐘

理論上說這個配置是正確的，因為要保證日志搜集完妻献，且發(fā)生輪轉(zhuǎn)的時候日志依然繼續(xù)搜集蛛株，也能基本上保證搜集完以后關(guān)閉harvest。那么我們暫時排除第二種可能育拨。

filebeat搜集速度過慢

我們繼續(xù)定位第一種可能：filebeat持有的文件沒有搜集完谨履，所以繼續(xù)持有，也就是那么多文件它都沒有搜集完至朗。

• 如何定位屉符？
  現(xiàn)在單從filebeat的日志已經(jīng)無法看出了。于是想到去看filebeat的注冊表，filebeat的registry文件中存放的是被采集的所有日志的相關(guān)信息矗钟。

  1. 進入到k8s中相應(yīng)的filebeat節(jié)點
     kubectl exec -it filebeat-lh2bq -n kube-system /bin/bash
  2. 查看其中registry文件唆香，截取一條

  {"source":"/data/docker/containers/0eb0397149bcd687a40cd4313b853354ff43e41a6257ccb5ab972d7170881037/0eb0397149bcd687a40cd4313b853354ff43e41a6257ccb5ab972d7170881037-json.log","offset":114912226,"timestamp":"2020-09-08T08:43:41.079295459Z","ttl":-1,"type":"container","meta":null,"FileStateOS":{"inode":8143887,"device":64512}}
  

  重點關(guān)注inode和offset,inode代表某個文件,offset代表filebeat讀到該文件的位置，字節(jié)數(shù)吨艇。

  3. 結(jié)合使用stat查看所在node的真正文件狀態(tài)躬它，持續(xù)觀察（也就是每隔一段更新registry信息）:
     發(fā)現(xiàn)，當文件被刪除時东涡，inode依然還在冯吓，同時filebeat中的注冊表信息依然在更新，也就是offset持續(xù)增長疮跑，
     114912226->117408238->122393532组贺。最后緩慢增長到198596250，也就是200M祖娘。至此filebeat關(guān)閉這個文件失尖，文件被真正刪除。

docker中的配置：

 "storage-opts":["overlay2.override_kernel_check=true"],
  "log-driver": "json-file",
   "log-opts": {
  "max-size": "200m",
  "max-file": "3"
 }

至此就可以解釋上面兩個問題了渐苏，filebeat沒有搜集完導(dǎo)致一直持有文件掀潮，文件輪轉(zhuǎn)越快，filebeat持有的文件數(shù)越多琼富，搜集性能相應(yīng)的下降仪吧，因此越來越慢，最終導(dǎo)致日志不能實時的查詢鞠眉，以及日志丟失的問題（也許并不會丟失薯鼠，只是長時間查不到）。

解決問題

既然發(fā)現(xiàn)了這個問題就要著手解決
最開始想到兩個解決方案：

1. 日志輪轉(zhuǎn)文件數(shù)設(shè)置更大
2. 日志級別設(shè)置設(shè)置高一點凡蚜，之前是debug

讀者可以想一想這兩個方案有沒有問題人断？

顯然是有問題的，這兩個方案并沒有真正解決問題朝蜘，只是延緩了問題的發(fā)生。第一個問題照舊涩金，第二個在并發(fā)量暴增或者日志需要放開是就有問題谱醇。

問題真正的根因所在是filebeat搜集的速度跟不上日志打印的速度。 我們必須找出filebeat慢的原因步做，按理說讀文件應(yīng)該相當快才對副渴，肯定是有哪里的配置不對，導(dǎo)致filebeat的性能如此的低全度。
最終重新審視filebeat部署文檔煮剧，發(fā)現(xiàn)我們部署的時候限制了filebeat的性能：

# filebeat.yaml部分片段 
resources:
  limits:
    memory: 500Mi
    cpu: 200m
  requests:
    cpu: 200m
    memory: 500Mi

這里的200m代表了200*1/1000 個cpu，也就是只有20%的cpu，這樣顯然filebeat在多線程處理的時候性能被大大壓縮勉盅，也就無法跟上我們?nèi)罩据敵龅乃俣扔悠摹６襨8s具有cpu壓縮的問題，它在低cpu的時候仍然能運行草娜，我們無法監(jiān)控到錯誤挑胸，所以很難發(fā)現(xiàn)。
修改配置文件取消限制宰闰，重新部署filebeat 解決
再次查看cpu：

cpu狀態(tài)