Kafka刪除Topic后被自動創(chuàng)建

背景

最近在釋放資源擴容到新集群味混，老集群由于還有極少部分Topic用戶在使用士复，另外Topic總數(shù)比較多暇矫，準(zhǔn)備保留一小波機器給剩余的Topic蔗崎，其余沒有使用的Topic進行刪除處理我擂，刪除的時候發(fā)現(xiàn)每次刪除完Topic衬以，還會創(chuàng)建出來Topic只是分區(qū)是1個比較糾結(jié)，懷疑是老集群bug校摩，老集群是基于社區(qū)Kafka內(nèi)核版本0.8.2.1的看峻，比較古老很多bug，社區(qū)已經(jīng)不在處理衙吩。

分析

日志分析

[2020-07-07 18:22:44,683] INFO [Partition state machine on Controller 271]: Invoking state change to NonExistentPartition for partitions [org.horizon_divide_data,75],[org.horizon_divide_data,78],[org.horizon_divide_data,69],[org.horizon_divide_data,30],[org.horizon_divide_data,26],[org.horizon_divide_data,44],[org.horizon_divide_data,70],[org.horizon_divide_data,62],[org.horizon_divide_data,21],[org.horizon_divide_data,77],[org.horizon_divide_data,0],[org.horizon_divide_data,8],[org.horizon_divide_data,91],[org.horizon_divide_data,65],[org.horizon_divide_data,13],[org.horizon_divide_data,20],[org.horizon_divide_data,61],[org.horizon_divide_data,34],[org.horizon_divide_data,84],[org.horizon_divide_data,27],[org.horizon_divide_data,63],[org.horizon_divide_data,54],[org.horizon_divide_data,94],[org.horizon_divide_data,49],[org.horizon_divide_data,52],[org.horizon_divide_data,37],[org.horizon_divide_data,86],[org.horizon_divide_data,93],[org.horizon_divide_data,7],[org.horizon_divide_data,74],[org.horizon_divide_data,22],[org.horizon_divide_data,58],[org.horizon_divide_data,81],[org.horizon_divide_data,5],[org.horizon_divide_data,32],[org.horizon_divide_data,45],[org.horizon_divide_data,76],[org.horizon_divide_data,87],[org.horizon_divide_data,57],[org.horizon_divide_data,40],[org.horizon_divide_data,53],[org.horizon_divide_data,41],[org.horizon_divide_data,43],[org.horizon_divide_data,47],[org.horizon_divide_data,23],[org.horizon_divide_data,59],[org.horizon_divide_data,1],[org.horizon_divide_data,73],[org.horizon_divide_data,67],[org.horizon_divide_data,39],[org.horizon_divide_data,25],[org.horizon_divide_data,35],[org.horizon_divide_data,88],[org.horizon_divide_data,48],[org.horizon_divide_data,64],[org.horizon_divide_data,51],[org.horizon_divide_data,85],[org.horizon_divide_data,11],[org.horizon_divide_data,16],[org.horizon_divide_data,29],[org.horizon_divide_data,28],[org.horizon_divide_data,90],[org.horizon_divide_data,24],[org.horizon_divide_data,38],[org.horizon_divide_data,15],[org.horizon_divide_data,60],[org.horizon_divide_data,9],[org.horizon_divide_data,17],[org.horizon_divide_data,6],[org.horizon_divide_data,80],[org.horizon_divide_data,2],[org.horizon_divide_data,14],[org.horizon_divide_data,56],[org.horizon_divide_data,42],[org.horizon_divide_data,95],[org.horizon_divide_data,79],[org.horizon_divide_data,4],[org.horizon_divide_data,19],[org.horizon_divide_data,3],[org.horizon_divide_data,89],[org.horizon_divide_data,33],[org.horizon_divide_data,66],[org.horizon_divide_data,36],[org.horizon_divide_data,55],[org.horizon_divide_data,46],[org.horizon_divide_data,92],[org.horizon_divide_data,31],[org.horizon_divide_data,83],[org.horizon_divide_data,71],[org.horizon_divide_data,50],[org.horizon_divide_data,82],[org.horizon_divide_data,18],[org.horizon_divide_data,12],[org.horizon_divide_data,68],[org.horizon_divide_data,72],[org.horizon_divide_data,10] (kafka.controller.PartitionStateMachine)

[2020-07-07 18:22:44,999] INFO [delete-topics-thread-271], Deletion of topic org.horizon_divide_data successfully completed (kafka.controller.TopicDeletionManager$DeleteTopicsThread)

[2020-07-07 18:22:44,999] DEBUG [Topic Deletion Manager 271], Waiting for signal to start or continue topic deletion (kafka.controller.TopicDeletionManager)

[2020-07-07 18:22:45,008] DEBUG [TopicChangeListener on Controller 271]: Topic change listener fired for path /brokers/topics with children org.com.sankuai.bb.op.psgs,org.test_ysj_error_log...... (kafka.controller.PartitionStateMachine$TopicChangeListener)

[2020-07-07 18:22:45,172] INFO [TopicChangeListener on Controller 271]: New topics: [Set()], deleted topics: [Set()], new partition replica assignment [Map()] (kafka.controller.PartitionStateMachine$TopicChangeListener)

[2020-07-07 18:22:45,231] DEBUG [DeleteTopicsListener on 271]: Delete topics listener fired for topics org.sec_hids_bash_data to be deleted (kafka.controller.PartitionStateMachine$DeleteTopicsListener)

[2020-07-07 18:22:45,231] INFO [DeleteTopicsListener on 271]: Starting topic deletion for topics org.sec_hids_bash_data (kafka.controller.PartitionStateMachine$DeleteTopicsListener)

[2020-07-07 18:22:45,251] INFO [delete-topics-thread-271], Handling deletion for topics org.sec_hids_bash_data (kafka.controller.TopicDeletionManager$DeleteTopicsThread)

[2020-07-07 18:22:45,270] DEBUG [Replica state machine on controller 271]: Are all replicas for topic org.sec_hids_bash_data deleted Map([Topic=org.sec_hids_bash_data,Partition=0,Replica=334] -> OnlineReplica, [Topic=org.sec_hids_bash_data,Partition=0,Replica=860] -> OnlineReplica) (kafka.controller.ReplicaStateMachine)

[2020-07-07 18:22:45,333] INFO [delete-topics-thread-271], Deletion of topic org.sec_hids_bash_data (re)started (kafka.controller.TopicDeletionManager$DeleteTopicsThread)

[2020-07-07 18:22:45,333] INFO [Topic Deletion Manager 271], Topic deletion callback for org.sec_hids_bash_data (kafka.controller.TopicDeletionManager)

[2020-07-07 18:22:45,500] INFO [Topic Deletion Manager 271], Partition deletion callback for [org.sec_hids_bash_data,0] (kafka.controller.TopicDeletionManager)

[2020-07-07 18:22:54,178] INFO [Replica state machine on controller 271]: Invoking state change to OfflineReplica for replicas [Topic=org.sec_hids_bash_data,Partition=0,Replica=860],[Topic=org.sec_hids_bash_data,Partition=0,Replica=334] (kafka.controller.ReplicaStateMachine)

[2020-07-07 18:22:54,178] DEBUG [Controller 271]: Removing replica 860 from ISR 334,860 for partition [org.sec_hids_bash_data,0]. (kafka.controller.KafkaController)

[2020-07-07 18:22:54,179] WARN [Controller 271]: Cannot remove replica 860 from ISR of [org.sec_hids_bash_data,0] - leaderAndIsr is empty. (kafka.controller.KafkaController)

[2020-07-07 18:22:54,179] DEBUG [Controller 271]: Removing replica 334 from ISR 334,860 for partition [org.sec_hids_bash_data,0]. (kafka.controller.KafkaController)

[2020-07-07 18:22:54,180] WARN [Controller 271]: Cannot remove replica 334 from ISR of [org.sec_hids_bash_data,0] - leaderAndIsr is empty. (kafka.controller.KafkaController)

[2020-07-07 18:22:54,180] DEBUG The stop replica request (delete = true) sent to broker 334 is? (kafka.controller.ControllerBrokerRequestBatch)

[2020-07-07 18:22:54,180] DEBUG The stop replica request (delete = false) sent to broker 334 is [Topic=org.sec_hids_bash_data,Partition=0,Replica=334] (kafka.controller.ControllerBrokerRequestBatch)

[2020-07-07 18:22:54,180] DEBUG The stop replica request (delete = true) sent to broker 860 is? (kafka.controller.ControllerBrokerRequestBatch)

[2020-07-07 18:22:54,180] DEBUG The stop replica request (delete = false) sent to broker 860 is [Topic=org.sec_hids_bash_data,Partition=0,Replica=860] (kafka.controller.ControllerBrokerRequestBatch)

[2020-07-07 18:22:54,180] DEBUG [Topic Deletion Manager 271], Deletion started for replicas [Topic=org.sec_hids_bash_data,Partition=0,Replica=860],[Topic=org.sec_hids_bash_data,Partition=0,Replica=334] (kafka.controller.TopicDeletionManager)

[2020-07-07 18:22:54,180] INFO [Replica state machine on controller 271]: Invoking state change to ReplicaDeletionStarted for replicas [Topic=org.sec_hids_bash_data,Partition=0,Replica=860],[Topic=org.sec_hids_bash_data,Partition=0,Replica=334] (kafka.controller.ReplicaStateMachine)

[2020-07-07 18:22:54,180] DEBUG [Topic Deletion Manager 271], Waiting for signal to start or continue topic deletion (kafka.controller.TopicDeletionManager)

[2020-07-07 18:22:54,189] DEBUG [TopicChangeListener on Controller 271]: Topic change listener fired for path /brokers/topics with children org.com.sankuai.bb.op.psgs,org.test_ysj_error_log... (kafka.controller.PartitionStateMachine$TopicChangeListener)

[2020-07-07 18:22:54,355] INFO [TopicChangeListener on Controller 271]: New topics: [Set(org.horizon_divide_data)], deleted topics: [Set()], new partition replica assignment [Map([org.horizon_divide_data,0] -> List(749, 994))] (kafka.controller.PartitionStateMachine$TopicChangeListener)

[2020-07-07 18:22:54,356] INFO [Controller 271]: New topic creation callback for [org.horizon_divide_data,0] (kafka.controller.KafkaController)

[2020-07-07 18:22:54,356] INFO [Controller 271]: New partition creation callback for [org.horizon_divide_data,0] (kafka.controller.KafkaController)

[2020-07-07 18:22:54,356] INFO [Partition state machine on Controller 271]: Invoking state change to NewPartition for partitions [org.horizon_divide_data,0] (kafka.controller.PartitionStateMachine)

[2020-07-07 18:22:54,357] INFO [Replica state machine on controller 271]: Invoking state change to NewReplica for replicas [Topic=org.horizon_divide_data,Partition=0,Replica=749],[Topic=org.horizon_divide_data,Partition=0,Replica=994] (kafka.controller.ReplicaStateMachine)

[2020-07-07 18:22:54,358] INFO [Partition state machine on Controller 271]: Invoking state change to OnlinePartition for partitions [org.horizon_divide_data,0] (kafka.controller.PartitionStateMachine)

[2020-07-07 18:22:54,358] DEBUG [Partition state machine on Controller 271]: Live assigned replicas for partition [org.horizon_divide_data,0] are: [List(749, 994)] (kafka.controller.PartitionStateMachine)

[2020-07-07 18:22:54,358] DEBUG [Partition state machine on Controller 271]: Initializing leader and isr for partition [org.horizon_divide_data,0] to (Leader:749,ISR:749,994,LeaderEpoch:0,ControllerEpoch:48) (kafka.controller.PartitionStateMachine)

[2020-07-07 18:22:54,396] INFO [Replica state machine on controller 271]: Invoking state change to OnlineReplica for replicas [Topic=org.horizon_divide_data,Partition=0,Replica=749],[Topic=org.horizon_divide_data,Partition=0,Replica=994] (kafka.controller.ReplicaStateMachine)

日志有些長互妓，涉及到的topic清理掉了，問題出現(xiàn)在刪除之后更新了兩次/brokers/topics zk節(jié)點, 第一次不包含被刪除的Topic坤塞，第二次包含被刪除的Topic

查看源碼

刪除Topic

日志里可以看到?Deletion of topic xxxx successfully completed冯勉，并且此日志是介于兩次更新zk節(jié)點之間；

TopicDeletionManager
completeDeleteTopic

分析completeDeleteTopic邏輯是將刪除Topic的/brokers/topics尺锚、/config/topics珠闰、/admin/delete_topics zk節(jié)點，并且刪除內(nèi)存里的Topic信息瘫辩。與日志[2020-07-07 18:22:45,172] INFO [TopicChangeListener on Controller 271]: New topics: [Set()], deleted topics: [Set()], new partition replica assignment [Map()] (kafka.controller.PartitionStateMachine$TopicChangeListener)對得上

創(chuàng)建Topic

[2020-07-07 18:22:54,355] INFO [TopicChangeListener on Controller 271]: New topics: [Set(org.horizon_divide_data)], deleted topics: [Set()], new partition replica assignment [Map([org.horizon_divide_data,0] -> List(749, 994))] (kafka.controller.PartitionStateMachine$TopicChangeListener)[2020-07-07 18:22:54,356] INFO [Controller 271]: New topic creation callback for [org.horizon_divide_data,0] (kafka.controller.KafkaController)[2020-07-07 18:22:54,356] INFO [Controller 271]: New partition creation callback for [org.horizon_divide_data,0] (kafka.controller.KafkaController)

New topic creation callback for 日志對應(yīng)代碼

PartitionStateMachine.scala

日志里第二次出現(xiàn)TopicChangeListener監(jiān)聽的日志如上伏嗜，此時zk上多了org.horizon_divide_data topic坛悉，而剛上面說過，Controller內(nèi)存中已經(jīng)remove掉了承绸，因此代碼中newTopics應(yīng)該是包含了刪除的org.horizon_divide_data topic裸影；

疑問

為啥第二次更新zk節(jié)點的時候，帶了這個topic呢军熏，是哪里觸發(fā)的這次更新呢轩猩？有兩點推測：1.zk更新那里是遞歸更新的會不會觸發(fā)兩次監(jiān)聽；2.集群設(shè)置了auto.create.topics.enable因為日志收集荡澎，避免造成收集側(cè)collector擁堵均践，可能有關(guān)系

1.查看zk遞歸刪除邏輯

ZkClient

代碼中看到傳參數(shù)watch->false,遞歸刪除從葉子節(jié)點到枝干節(jié)點刪除，邏輯看上去沒問題摩幔，在確認(rèn)下參數(shù)watch是干嘛的彤委？看Document說明大概意思是true的時候會監(jiān)聽節(jié)點變更，false不監(jiān)聽節(jié)點變更或衡；zk遞歸刪除引起調(diào)用兩次listener排除（PS：如果真的是因為遞歸刪除引起焦影，遞歸刪除是從child到parent刪除，邏輯上應(yīng)該是日志里第一次包含被刪除的Topic封断，而第二次不包含被刪除的Topic才對斯辰，現(xiàn)實中恰恰相反）

ZkConnection

2.查看auto.create.topics.enable相關(guān)代碼，邏輯上看坡疼，如果請求TopicMeta彬呻，而broker meta中不存在這個Topic，那么broker會調(diào)用createTopic柄瑰，而我們知道創(chuàng)建Topic邏輯就是會寫zk /brokers/topics/節(jié)點废岂。查看broker日志發(fā)現(xiàn)server.log.2:[2020-07-07 17:48:24,353] INFO [KafkaApi-253] Auto creation of topic org.com.dianping.seer.cube2 with 1 partitions and replication factor 2 is successful! (kafka.server.KafkaApis)有自動創(chuàng)建的情況，這個也是批量刪除的其中一個topic狱意，這里偷懶1共600多個broker湖苞，而我們知道獲取client獲取meta的邏輯是先根據(jù)bootstrap server 創(chuàng)建鏈接，然后自己有個算法详囤，大概就是判斷連接數(shù)最少的一個broker跟這個broker鏈接财骨，獲取broker內(nèi)存中的meta，這邊kafka日志沒有收集到es藏姐、hive之類的隆箩，沒有聚合，就沒在繼續(xù)查羔杨；另外我們內(nèi)部日志收集其實還在一直鏈接老平臺broker只是沒有寫數(shù)據(jù)而已捌臊。

KafkaApis

結(jié)論

如果集群broker配置了auto.create.topics.enable，同時有獲取topicmeta請求就會自動創(chuàng)建Topic兜材，此處邏輯也可以看到理澎，如果集群中不是全部broker開啟了這個配置逞力，那其實只要請求落在配置了這個參數(shù)的broker上就會自動創(chuàng)建這個Topic

其他想說的，Kafka的日志打得不是特別好糠爬，很多地方日志級別都是設(shè)置比較低寇荧，根本不知道服務(wù)在干嘛，controller日志相對多一些执隧，這里有個工具可以推薦阿里的Arthas?https://alibaba.github.io/arthas/?揩抡，可以通過它動態(tài)修改日志級別使用起來也很簡單，大概就是先確定classloader的hash值镀琉，輸入類似sc -d kafka.controller.ControllerContext（找代碼里的類即可）我這里以321ea24為例峦嗤，找到hash值通過logger -c xxx（前面找到的hash值）即可查看這個classloader里面有幾個日志配置，找到你要修改的日志name這里修改controller的日志name是kafka.controller 屋摔，對應(yīng)執(zhí)行?logger -c 321ea24 -n kafka.controller -l info寻仗，即可調(diào)整。

?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請聯(lián)系作者
  • 人面猴
    序言：七十年代末凡壤，一起剝皮案震驚了整個濱河市，隨后出現(xiàn)的幾起案子耙替，更是在濱河造成了極大的恐慌亚侠，老刑警劉巖，帶你破解...
    沈念sama閱讀 218,607評論 6贊 507
  • 死咒
    序言：濱河連續(xù)發(fā)生了三起死亡事件俗扇，死亡現(xiàn)場離奇詭異硝烂，居然都是意外死亡，警方通過查閱死者的電腦和手機铜幽，發(fā)現(xiàn)死者居然都...
    沈念sama閱讀 93,239評論 3贊 395
  • 救了他兩次的神仙讓他今天三更去死
    文/潘曉璐 我一進店門滞谢，熙熙樓的掌柜王于貴愁眉苦臉地迎上來，“玉大人除抛，你說我怎么就攤上這事狮杨。” “怎么了到忽？”我有些...
    開封第一講書人閱讀 164,960評論 0贊 355
  • 道士緝兇錄：失蹤的賣姜人
    文/不壞的土叔 我叫張陵橄教，是天一觀的道長。 經(jīng)常有香客問我喘漏，道長护蝶，這世上最難降的妖魔是什么？ 我笑而不...
    開封第一講書人閱讀 58,750評論 1贊 294
  • ?港島之戀（遺憾婚禮）
    正文 為了忘掉前任翩迈，我火速辦了婚禮持灰，結(jié)果婚禮上，老公的妹妹穿的比我還像新娘负饲。我一直安慰自己堤魁，他們只是感情好喂链，可當(dāng)我...
    茶點故事閱讀 67,764評論 6贊 392
  • 惡毒庶女頂嫁案：這布局不是一般人想出來的
    文/花漫 我一把揭開白布。 她就那樣靜靜地躺著姨涡，像睡著了一般衩藤。 火紅的嫁衣襯著肌膚如雪。 梳的紋絲不亂的頭發(fā)上涛漂，一...
    開封第一講書人閱讀 51,604評論 1贊 305
  • 城市分裂傳說
    那天赏表，我揣著相機與錄音，去河邊找鬼匈仗。 笑死瓢剿，一個胖子當(dāng)著我的面吹牛，可吹牛的內(nèi)容都是我干的悠轩。 我是一名探鬼主播间狂，決...
    沈念sama閱讀 40,347評論 3贊 418
  • 雙鴛鴦連環(huán)套：你想象不到人心有多黑
    文/蒼蘭香墨 我猛地睜開眼，長吁一口氣：“原來是場噩夢啊……” “哼火架！你這毒婦竟也來了鉴象？” 一聲冷哼從身側(cè)響起，我...
    開封第一講書人閱讀 39,253評論 0贊 276
  • 萬榮殺人案實錄
    序言：老撾萬榮一對情侶失蹤何鸡，失蹤者是張志新（化名）和其女友劉穎纺弊，沒想到半個月后，有當(dāng)?shù)厝嗽跇淞掷锇l(fā)現(xiàn)了一具尸體骡男，經(jīng)...
    沈念sama閱讀 45,702評論 1贊 315
  • ?護林員之死
    正文 獨居荒郊野嶺守林人離奇死亡淆游，尸身上長有42處帶血的膿包…… 初始之章·張勛 以下內(nèi)容為張勛視角 年9月15日...
    茶點故事閱讀 37,893評論 3贊 336
  • ?白月光啟示錄
    正文 我和宋清朗相戀三年，在試婚紗的時候發(fā)現(xiàn)自己被綠了隔盛。 大學(xué)時的朋友給我發(fā)了我未婚夫和他白月光在一起吃飯的照片犹菱。...
    茶點故事閱讀 40,015評論 1贊 348
  • 活死人
    序言：一個原本活蹦亂跳的男人離奇死亡，死狀恐怖吮炕，靈堂內(nèi)的尸體忽然破棺而出腊脱，到底是詐尸還是另有隱情，我是刑警寧澤龙亲，帶...
    沈念sama閱讀 35,734評論 5贊 346
  • ?日本核電站爆炸內(nèi)幕
    正文 年R本政府宣布虑椎，位于F島的核電站，受9級特大地震影響俱笛，放射性物質(zhì)發(fā)生泄漏捆姜。R本人自食惡果不足惜，卻給世界環(huán)境...
    茶點故事閱讀 41,352評論 3贊 330
  • 男人毒藥：我在死后第九天來索命
    文/蒙蒙 一迎膜、第九天 我趴在偏房一處隱蔽的房頂上張望泥技。 院中可真熱鬧，春花似錦磕仅、人聲如沸珊豹。這莊子的主人今日做“春日...
    開封第一講書人閱讀 31,934評論 0贊 22
  • 一樁弒父案，背后竟有這般陰謀
    文/蒼蘭香墨 我抬頭看了看天上的太陽店茶。三九已至蜕便，卻和暖如春，著一層夾襖步出監(jiān)牢的瞬間贩幻，已是汗流浹背轿腺。 一陣腳步聲響...
    開封第一講書人閱讀 33,052評論 1贊 270
  • 情欲美人皮
    我被黑心中介騙來泰國打工， 沒想到剛下飛機就差點兒被人妖公主榨干…… 1. 我叫王不留丛楚，地道東北人族壳。 一個月前我還...
    沈念sama閱讀 48,216評論 3贊 371
  • 代替公主和親
    正文 我出身青樓，卻偏偏與公主長得像趣些，于是被迫代替她去往敵國和親仿荆。 傳聞我的和親對象是個殘疾皇子，可洞房花燭夜當(dāng)晚...
    茶點故事閱讀 44,969評論 2贊 355