当前位置：首页 > article >正文

【排查案例】无认证集群空白分区创建元凶排查记录

article 2025/1/23 1:16:20

无认证集群空白分区创建元凶排查记录

前言
正文
- SparkSQL Thrift审计
- 通过edit查找操作
- 抓包分析请求
- NodeManager日志追踪
- 结论
后记

前言

今天分享一个最近在生产环境排查的空白分区的问题，先说业务感知，业务那边反馈本身这条业务链每个小时数据应该是3个分区，但是在业务链末端的输出数据中产生了4个分区，其中一个是空白分区，目前业务能够确认那个空白分区压根是不需要的，但是并不确定是什么位置出现的这个分区。

集群的信息大概说明一下，首先没有开审计日志，其次没有开kerberos，也没有ranger这种权限管理，所以这块基本是没法从日志分析出操作细节的。

分区添加可以通过sparksql的thrift，也可能直接启了一个sparksql做操作，因此，接到这个问题以后感觉还是挺摸不着头脑的，但是只要是人做的就一定有蛛丝马迹存在，下面说一下我的整个排查过程。

在这里插入图片描述

正文

SparkSQL Thrift审计

集群有几个常驻的SparkSQL Thrift用来平时做一些快速查询，这几个是开了审计日志的，在问题传达到我这后我第一时间检查了审计日志，并没有相关分区的创建历史，因此直接排除通过thrift进行创建这条路

通过edit查找操作

前面已经说了，我们HDFS没有审计日志，并且NameNode日志是INFO级别，不会记录目录创建的信息，但是我们知道NameNode有一个edit可以记录一段时间内详细的操作信息，因此，我们可以优先根据分区信息，找到edit文件。

直接在hdfs列出指定日期下的空白分区的信息：

hadoop fs -ls /$path/2025-01-21/*|grep 100003

从中选择一个分区信息直接在NameNode的edit目录下grep搜索，然后将指定的edit解析成xml文件

hdfs oev -i edits_0000000105678248337-0000000105678297660 -o /data4/edit_bak/edits_1027.xml

在这里插入图片描述
下面是解析出来的xml种有关问题分区创建的信息：

  <RECORD>
    <OPCODE>OP_MKDIR</OPCODE>
    <DATA>
      <TXID>105678280997</TXID>
      <LENGTH>0</LENGTH>
      <INODEID>20403610530</INODEID>
      <PATH>$path</PATH>
      <TIMESTAMP>1737425813445</TIMESTAMP>
      <PERMISSION_STATUS>
        <USERNAME>mr</USERNAME>
        <GROUPNAME>users</GROUPNAME>
        <MODE>488</MODE>
      </PERMISSION_STATUS>
    </DATA>
  </RECORD>

这个操作的具体时间戳就拿到了，我们可以把操作的具体时间定位到秒级：
在这里插入图片描述

抓包分析请求

对于这种非安全集群，已有条件是不可能追踪请求的，但是我们可以通过tcpdump在NameNode进行抓包，来捕捉具体的请求，原因是客户端执行的操作质量都会经过NameNode，因此只要监听RPC端口就可以，分区的创建操作是每个小时都有，因此我们只需要抓一个小时做排查就行；

需要注意的是，tcpdump抓NameNode的请求包可能量很大，为了方便分析，我们最好分包保存

使用下面命令进行分包保存，筛掉本机的请求：

tcpdump -i bond0 -G 60 -nn 'host 10.0.0.1 and port 9000 and not src 10.0.0.1' -w tcpdump/capture_%H%M%S.pcap

上面的命令解释一下：

-i指定了网卡设备名称是bond0
-G指定60秒滚动一个pcap文件
-nn不使用主机名，而是直接使用ip
抓取host 10.0.0.1的9000端口并且源端ip不为10.0.0.1
-w写入的pcap文件名，%H%M%S使用当前时间来命名文件

然后我们根据edit里面查到的分区创建操作，取对应时间的数据包做分析即可，下面是我们用wireshark拆包的界面：

在这里插入图片描述
这里请求是很多的，我们要用筛选器直接筛选数据包中包含我们业务分区的内容，在筛选框直接筛选：

data contains "partition=100003"

这里就抓到了mkdir操作创建了100003分区，并且所有请求都来自于一个NodeManager存算节点
在这里插入图片描述

到这里我们基本可以确认是Spark任务或者一个SparkSQL实例进行的分区创建，因为集群是Spark on Yarn，下一步我们直接通过NodeManager日志做进一步的排查

NodeManager日志追踪

到这里，我们只要找到指定发包时间的指定节点在进行什么操作连接NameNode就可以了，从抓包情况我们可以知道大概率是一个任务进行的操作，那么我们直接从NodeManager运行日志过滤10点以后得Start Container Request操作：

cat yarn-mr-NodeManager.log |grep "Start Container Request" > /tmp/nodemanager.log

我们将得到类似下面这样的日志信息：

2025-01-21 10:00:28,712 INFO org.apache.hadoop.yarn.server.nodemanager.NMAuditLogger: USER=mr   IP=10.0.0.4  OPERATION=Start Container Request       TARGET=ContainerManageImpl      RESULT=SUCCESS    APPID=application_1684894983964_217978895       CONTAINERID=container_e77_1684894983964_217978895_01_000127
2025-01-21 10:00:28,754 INFO org.apache.hadoop.yarn.server.nodemanager.NMAuditLogger: USER=mr   IP=10.0.0.4  OPERATION=Start Container Request       TARGET=ContainerManageImpl      RESULT=SUCCESS    APPID=application_1684894983964_217978895       CONTAINERID=container_e77_1684894983964_217978895_01_000126
2025-01-21 10:00:28,759 INFO org.apache.hadoop.yarn.server.nodemanager.NMAuditLogger: USER=mr   IP=10.0.0.4  OPERATION=Start Container Request       TARGET=ContainerManageImpl      RESULT=SUCCESS    APPID=application_1684894983964_217978895       CONTAINERID=container_e77_1684894983964_217978895_01_000125
2025-01-21 10:00:28,759 INFO org.apache.hadoop.yarn.server.nodemanager.NMAuditLogger: USER=mr   IP=10.0.0.4  OPERATION=Start Container Request       TARGET=ContainerManageImpl      RESULT=SUCCESS    APPID=application_1684894983964_217978895       CONTAINERID=container_e77_1684894983964_217978895_01_000128

其实我们只需要appid，所以也可以直接这样筛选出来：


cat yarn-mr-NodeManager.log|grep "2025-01-21 10"|grep "Start Container "|awk -F'APPID=' '{split($2, a, " "); if (a[1] != "") appid[a[1]]} END {for (id in appid) print id}'

在这里插入图片描述