记录工作以来遇到的最离谱的一个Bug

原创京喜研发袁天宇京东零售技术

2024年04月29日 10:40

本文介绍了在使用Kafka过程中遭遇的一个消费者异常问题。起因是offset参数异常变更，实际问题源于调用C++ native方法后，该方法直接修改了内存地址，导致JVM缓存数据发生变化。文章详细记录了问题发现、追踪和解决的过程，为解决类似技术问题提供了重要参考。

【本文目录】

故事的开始从一次Kafka的消费者说起
一次离谱的log记录
一次更离谱的定位问题过程
原来是这样！
我们简单用Java模拟复现一下
小结

问题背景

故事的开始从一次Kafka的消费者说起：

public void handleMessage() {
        Properties properties = new Properties();
        // 添加若干配置....
        KafkaConsumer<String, String> consumer = new KafkaConsumer<>(properties, new StringDeserializer(), new StringDeserializer());
        String topic = "foo_bar";
        consumer.subscribe(Collections.singleton(topic));
        while (!stopMark) {
            ConsumerRecords<String, String> records = consumer.poll(Duration.of(300, MILLIS));
            for (ConsumerRecord<String, String> record : records) {
                // 处理消息
            }
        }
}

乍一看，没有任何问题，之前的代码也都是这么写的，也都没有任何问题，但是这个topic就始终没法消费到数据？？！！！

查看日志时，我发现了一丝端倪：

[Consumer clientId=foo, groupId=bar] Setting offset for partition foo_bar-8 to the committed offset FetchPosition{offset=1590039403, offsetEpoch=Optional.empty, currentLeader=LeaderAndEpoch{leader=Optional[1.2.3.4:9000 (id: 4 rack: rack-0)], epoch=0}}

突然，我发现了一个特别的现象，“offset=1590039403”，offset初始化不是0么？怎么变成....好像是一个秒级时间戳了？？

1. 一次离谱的log记录

为了探究为啥默认的offset=0，变成了奇怪的数据，我写了如下的Test，替换消费者的消费代码，代码如下：

Thread t = new Thread(() -> {
            Integer a = 0;
            while (true) {
                System.out.println(a);
                try {
                    TimeUnit.SECONDS.sleep(1);
                } catch (Throwable ignore) {
                }
            }
        });
t.start();

简单来说，线程内有一个Integer类型的变量a，然后每隔1s，打印一下这个变量a的值。那么不出意外的话，这段代码的结果应该每秒打印一个0，但是不出意外的话，意外出现了：

在中间某一个时刻，突然打印出来变量的值变成了1590039403，当时看到结果，我人都裂开了😢。

裂开的原因如下：

•线程内部完全没有修改这个变量的操作

•这个变量是在方法内部创建的，并没有暴露给外部

2. 一次更离谱的定位问题过程

二、一次更离谱的定位问题过程

先从一个IDEA的智能提示开始，对于下面这个方法定义：

public static void hahaha(Integer s){
}

如果我们在调用的时候这么写：

hahaha(new Integer(0));

此时，IDEA会机智的提示你：

如果你按照IDEA的指示，移除"不必要的装箱"，那么就会变成下面这种调用方式：

hahaha(0);

这么一看，好像也没什么问题对吧？我理解也是，IDEA真智能👍，我就这么改了。

接下来回到问题的开始，我发现，我的程序就是调用了一个下面这样的方法后，打印出来的a变量的值就发生了变化：

public native int GetConfFile(String var1, int var2, StringBuffer var4);

注意：

1.这是一个native方法，内部是通过JNI调用的C++的so文件

2.通常来说，c++都是通过指针操作，然后返回值也可能放在参数列表中，所以这个var2虽然是传递进去的参数，但同样也是这个方法的返回值

接下来，我就按照IDEA的指示，这么调用了此方法：

StringBuffer sb = new StringBuffer();
int code = ConfigAccess.GetConfFile("myConfigFile", 0, sb);

这么一看好像，也没有什么问题，但就是调用了此方法以后，所有值等于0的Integer类，都变成了1590039403！！！！😨

1590039403？？？！！！

这不是这个myConfigFile的version值嘛？？！！

3. 原来是这样！

《吃瓜吃到八股文头上是一种怎样的体验？》

4. 我们简单用Java模拟复现一下

public static void main(String[] args) throws NoSuchFieldException, IllegalAccessException, InterruptedException {
        Thread t = new Thread(() -> {
            Integer a = 0;
            while (true) {
                System.out.println(a);
                try {
                    TimeUnit.SECONDS.sleep(1);
                } catch (Throwable ignore) {
                }
            }
        });
        t.start();
        TimeUnit.SECONDS.sleep(5);
        Integer b = 0;
        // 获取Unsafe的实例
        Field f = Unsafe.class.getDeclaredField("theUnsafe");
        f.setAccessible(true);
        Unsafe unsafe = (Unsafe) f.get(null);
        // 获取对象的字段
        Field field = Integer.class.getDeclaredField("value");
        // 计算字段在对象中的偏移量
        long offset = unsafe.objectFieldOffset(field);
        // 修改字段的值
        unsafe.putInt(b, offset, 1);
        System.out.println("+++++" + unsafe.getInt(b, offset));
    }

见证奇迹的时刻到了

0
0
0
0
0
+++++1 //此时修改了内存中的值
1
1
1
1
1

5. 小结

1. 八股文有些时候还是有用的

2. Java和C++打交道真的要谨慎、谨慎再谨慎，各种离奇的bug都能出现

3. 当我循环打印一个没有任何改变的变量却发现内容变化时，我整个人真的裂开了😑

附：Q & A

Q: 很好奇这个缓存的对象是怎么被改了的?

A: 操作主要分成以下四步：

1. 调用的”GetConfFile“是一个native方法，也就是底层是c++方法

2. c++方法通常参数传递的都是“指针”，也就是对象的内存地址

3. c++方法中修改了这个指针对应的内存地址的值

4. 好巧不巧，步骤3的内存地址是一个jvm的缓存，因此所有用到这个缓存的对象行为全部发生了异常

Q：这个是什么JDK版本呀，升级JDK还能复现吗？

A: 目前看和JDK的版本无关，因为：

1. 问题的根源是C++直接操作了内存地址的数据，而这个数据恰好被jvm缓存

2. 第四节的例子我是使用jdk17执行的，同样会有影响。这个缓存机制是有利于性能的，所以应该不会去掉

- END -

继续滑动看下一个