spark透過kafka-appender指定日誌輸出到kafka引發的死鎖問題

在採用 log4j 的kafka-appender收集 spark 任務執行日誌時，發現提交到 yarn 上的任務始終 ACCEPTED 狀態，無法進入 RUNNING 狀態，並且會重試兩次後超時。期初認為是yarn資源不足導致，但在確認yarn資源充裕的時候問題依舊，而且基本上能穩定復現。
起初是這麼配置spark日誌輸出到kafka的：
log4j.rootCategory=INFO, console, kafka log4j.appender.console=org.apache.log4j.ConsoleAppender log4j.appender.console.target=System.err log4j.appender.console.layout=org.apache.log4j.PatternLayout log4j.appender.console.layout.ConversionPattern=%d{yyyy/MM/dd HH:mm:ss.SSS} %p %c{1}: [${log4j.pipelineId}] %m%n # Kafka appender log4j.appender.kafka=org.apache.kafka.log4jappender.KafkaLog4jAppender # Set Kafka topic and brokerList log4j.appender.kafka.topic=yarn_spark_log log4j.appender.kafka.brokerList=localhost:9092 log4j.appender.kafka.compressionType=none log4j.appender.kafka.syncSend=false log4j.appender.kafka.maxBlockMs=10 log4j.appender.kafka.layout=org.apache.log4j.PatternLayout log4j.appender.kafka.layout.ConversionPattern=%d{yyyy/MM/dd HH:mm:ss.SSS} %p %c{1}: [${log4j.pipelineId}] %m
這裡用 org.apache.kafka.log4jappender.KafkaLog4jAppender 預設將所有日誌都輸出到kafka，這個appender已經被kafka官方維護，穩定性應該是可以保障的。
問題定位
發現問題後，嘗試將輸出到kafka的規則去掉，問題解除！於是把問題定位到跟日誌輸出到kafka有關。透過其他測試，證實目標kafka其實是正常的，這就非常奇怪了。
檢視yarn的ResourceManager日誌，發現有如下超時
2020-05-07 21:49:48,230 INFO org.apache.hadoop.yarn.util.AbstractLivelinessMonitor: Expired:appattempt_1578970174552_3204_000002 Timed out after 600 secs
2020-05-07 21:49:48,230 INFO org.apache.hadoop.yarn.server.resourcemanager.rmapp.attempt.RMAppAttemptImpl: Updating application attempt appattempt_1578970174552_3204_000002 with final
state: FAILED, and exit status: -1000
2020-05-07 21:49:48,231 INFO org.apache.hadoop.yarn.server.resourcemanager.rmapp.attempt.RMAppAttemptImpl: appattempt_1578970174552_3204_000002 State change from LAUNCHED to FINAL_SAV
ING on event = EXPIRE
表明，yarn本身是接收任務的，但是發現任務遲遲沒有啟動。在spark的場景下其實是指只有driver啟動了，但是沒有啟動executor。
而檢視driver日誌，發現日誌輸出到一個地方就卡住了，不往下繼續了。透過對比成功執行和卡住的情況發現，日誌卡在這條上：
2020/05/07 19:37:10.324 INFO SecurityManager: Changing view acls to: yarn,root
2020/05/07 19:37:10.344 INFO Metadata: Cluster ID: 6iG6WHA2SoK7FfgGgWHt_A
卡住的情況下，只會打出 SecurityManager 這行，而無法打出 Metadata 這行。
猜想 Metadata 這行是 kafka-client 本身打出來的，因為整個上下文只有yarn, spark, kafka-client可能會打出這個日誌。
在kafka-client 2.2.0版本中找到這個日誌是輸出位置：
public synchronized void update(MetadataResponse metadataResponse, long now) { ... String newClusterId = cache.cluster().clusterResource().clusterId(); if (!Objects.equals(previousClusterId, newClusterId)) { log.info("Cluster ID: {}", newClusterId); } ... }
看到 synchronized ，高度懷疑死鎖。於是考慮用 jstack 分析：
在yarn上執行spark任務的時候，driver程序叫ApplicationMaster，executor程序叫CoarseGrainedExecutorBackend。這裡首先嚐試再復現過程中找到drvier最終在哪個節點上執行，然後快速使用jstack -F