likes
comments
collection
share

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

作者站长头像
站长
· 阅读数 22

零、故事的开始从一次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么?怎么变成....好像是一个秒级时间戳了??

一、一次离谱的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,但是不出意外的话,意外出现了。

0
0
0
0
0
1590039403
1590039403
1590039403
1590039403

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

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

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

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

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

public static void hahaha(Integer s){
}

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

hahaha(new Integer(0));

此时,IDEA会机智的提示你:

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

如果你按照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值嘛??!!

三、原来是这样!

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

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

四、我们简单用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

五、小结

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执行的,同样会有影响。这个缓存机制是有利于性能的,所以我理解应该不会去掉

转载自:https://juejin.cn/post/7363121082457653263
评论
请登录