排查一次莫名其妙的StackOverflow

作者: 白花蛇草可乐 | 来源:发表于2019-08-20 14:20 被阅读0次

一、现象

某dubbo微服务启动后，只要被消费者调用，就发生以下错误

com.alibaba.dubbo.common.logger.slf4j.Slf4jLogger 74 error -  
[DUBBO] Got unchecked and undeclared exception which called by 192.168.1.101. 
service: com.xxx.facade.payment.service.IPaymentService, 
method: getAccountBalance, exception: java.lang.StackOverflowError: null, 
dubbo version: 2.5.3, current host: 127.0.0.1 java.lang.StackOverflowError: null
下略

这简直是个莫名其妙的事情，这一次只是追加了一个很简单的，居然造成其他既存接口出问题，而且还是StackOverflowError。

阅读日志，又发现其他很多既存接口也出现了同样错误。

（黑人问号啊……）

二、临时解决

做初步调查的时候，因为 StackOverflowError 太少见，完全没有头绪，有点慌。
先将本次修改的代码全部revert，恢复到上一次发版的状态，经验证工作正常，这样就把出错原因限定在了这次修改的代码里，而不是运行环境。
接下来本来想做的事情是把这次添加的代码再一点一点恢复回来，逐步锁定出错的代码块。
幸好，因为改的地方太零散了，这么做起来太花时间，犯懒，实在不想这么做。
所以硬着头皮重新读日志——之前看到这个错误的时候，其实给了自己一个不好的暗示：这种错误都是系统底层的问题，这一堆天书一样的日志根本不可能看懂。不过，仔细看的时候发现还是很清晰的

2019-08-15 17:20:57.422 INFO  com.xxx.commons.logs.AspectLog 44 before - [before()]com.xxx.facade.payment.service.impl.PaymentServiceImpl.getAccountBalance(), parametes:[12,13400518650]
2019-08-15 17:20:57.497 ERROR com.alibaba.dubbo.common.logger.slf4j.Slf4jLogger 74 error -  [DUBBO] Got unchecked and undeclared exception which called by 192.168.1.101. service: com.xxx.facade.payment.service.IPaymentService, method: getAccountBalance, exception: java.lang.StackOverflowError: null, dubbo version: 2.5.3, current host: 127.0.0.1 java.lang.StackOverflowError: null
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:156) ~[spring-aop-4.3.13.RELEASE.jar:4.3.13.RELEASE]
    at org.springframework.aop.framework.adapter.AfterReturningAdviceInterceptor.invoke(AfterReturningAdviceInterceptor.java:52) ~[spring-aop-4.3.13.RELEASE.jar:4.3.13.RELEASE]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.13.RELEASE.jar:4.3.13.RELEASE]
    at org.springframework.aop.aspectj.AspectJAfterThrowingAdvice.invoke(AspectJAfterThrowingAdvice.java:62) ~[spring-aop-4.3.13.RELEASE.jar:4.3.13.RELEASE]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.13.RELEASE.jar:4.3.13.RELEASE]
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92) ~[spring-aop-4.3.13.RELEASE.jar:4.3.13.RELEASE]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.13.RELEASE.jar:4.3.13.RELEASE]
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673) ~[spring-aop-4.3.13.RELEASE.jar:4.3.13.RELEASE]
    at com.xxx.facade.fuiou.constant.FuiouConstant$$EnhancerBySpringCGLIB$$fb956bdd.toString(<generated>) ~[phj-facade-payment-1.0-SNAPSHOT.jar:1.0-SNAPSHOT]
    at com.xxx.commons.logs.AspectLog.before(AspectLog.java:40) ~[phj-common-1.0-SNAPSHOT.jar:1.0-SNAPSHOT]
    at sun.reflect.GeneratedMethodAccessor83.invoke(Unknown Source) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_101]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_101]
    at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:629) ~[spring-aop-4.3.13.RELEASE.jar:4.3.13.RELEASE]
    at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:611) ~[spring-aop-4.3.13.RELEASE.jar:4.3.13.RELEASE]
    at org.springframework.aop.aspectj.AspectJMethodBeforeAdvice.before(AspectJMethodBeforeAdvice.java:43) ~[spring-aop-4.3.13.RELEASE.jar:4.3.13.RELEASE]
    at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:51) ~[spring-aop-4.3.13.RELEASE.jar:4.3.13.RELEASE]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.13.RELEASE.jar:4.3.13.RELEASE]
    at org.springframework.aop.framework.adapter.AfterReturningAdviceInterceptor.invoke(AfterReturningAdviceInterceptor.java:52) ~[spring-aop-4.3.13.RELEASE.jar:4.3.13.RELEASE]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.13.RELEASE.jar:4.3.13.RELEASE]
    at org.springframework.aop.aspectj.AspectJAfterThrowingAdvice.invoke(AspectJAfterThrowingAdvice.java:62) ~[spring-aop-4.3.13.RELEASE.jar:4.3.13.RELEASE]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.13.RELEASE.jar:4.3.13.RELEASE]
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92) ~[spring-aop-4.3.13.RELEASE.jar:4.3.13.RELEASE]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.13.RELEASE.jar:4.3.13.RELEASE]
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673) ~[spring-aop-4.3.13.RELEASE.jar:4.3.13.RELEASE]
    at com.xxx.facade.fuiou.constant.FuiouConstant$$EnhancerBySpringCGLIB$$fb956bdd.toString(<generated>) ~[phj-facade-payment-1.0-SNAPSHOT.jar:1.0-SNAPSHOT]
    at com.xxx.commons.logs.AspectLog.before(AspectLog.java:40) ~[phj-common-1.0-SNAPSHOT.jar:1.0-SNAPSHOT]
    at sun.reflect.GeneratedMethodAccessor83.invoke(Unknown Source) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_101]

虽然有一堆鬼画符一样的springframework，但是有两行 com.xxx（公司名称）啊

    at com.xxx.facade.fuiou.constant.FuiouConstant$$EnhancerBySpringCGLIB$$fb956bdd.toString
    at com.xxx.commons.logs.AspectLog.before

因为这次确实在 FuiouConstant 这个类里面随手追加了一个 toString() 方法（为了在日志里面出详细信息，方便追踪）。所以试着把这个toString()删掉试验了一下，工程恢复正常。
至此，至少知道了表面上引发错误的原因，问题解决。以下开始追查根本原因。

三、原因追查

3.1、什么情况下会发生StackOverflowError？

因为StackOverflowError太特殊了，首先能够肯定的，是发生了深度嵌套调用（最常见的是递归），因为只有在线程请求的栈深度过大，超过了规定值以后，才会抛出StackOverflowError错误——这是这种错误唯一可能发生的原因。

顺便说一句，栈会发生的另一种错误是OOM，在栈动态扩展空间，但是内存不足时发生。

3.2、一个错误的调查方向

因为以前见过toString()引发StackOverflowError的事例（参看“五、附录 5.1”一节）。

所以一上来就认为是 FuiouConstant 里面的成员变量与 FuiouConstant 本身形成了某种循环调用。

不过 FuiouConstant 里面的成员变量都是String，理论上无论如何也是不可能的。

但是这个观念根深蒂固，考虑到 FuiouConstant 里面变量的内容是通过 xml 注入进去的（读了propertiy文件），会不会是这样造成的影响？

去把 PropertyPlaceholderConfigurer 的源代码研究了半天，又拼命做各种试验，最后晕头转向没有任何进展。

3.3、光看不跑

最后想到，出错信息里面还提到了“com.xxx.commons.logs.AspectLog.before”，打开看了看代码，感觉一切正常。

甚至还改造了一下，多输出了点日志

com.xxx.common.phjservicepayment.PhjServicePaymentApplicationTests 47 getAccountBalance - ==== 用户余额查询 ====
com.xxx.commons.logs.AspectLog 41 before - ====com.xxx.facade.payment.service.impl.PaymentServiceImpl
com.xxx.commons.logs.AspectLog 42 before - ----getAccountBalance
com.xxx.commons.logs.AspectLog 48 before - [before()]com.xxx.facade.payment.service.impl.PaymentServiceImpl.getAccountBalance(), parametes:[11,15288900256]
com.xxx.commons.logs.AspectLog 41 before - ====com.xxx.facade.fuiou.constant.FuiouConstant
com.xxx.commons.logs.AspectLog 42 before - ----getMchntCd
com.xxx.commons.logs.AspectLog 41 before - ====com.xxx.facade.fuiou.constant.FuiouConstant
com.xxx.commons.logs.AspectLog 42 before - ----toString
com.xxx.commons.logs.AspectLog 41 before - ====com.xxx.facade.fuiou.constant.FuiouConstant
com.xxx.commons.logs.AspectLog 42 before - ----toString
com.xxx.commons.logs.AspectLog 41 before - ====com.xxx.facade.fuiou.constant.FuiouConstant
com.xxx.commons.logs.AspectLog 42 before - ----toString

发现一直在跑FuiouConstant自身的toString()，倒是打消了之前toString嵌套调用的想法。

3.4、折腾半天快被气死

最后实在没辙了，差点要取内存的dump文件下来分析。

然后随手点了debug启动，想在输出日志时的切面里面观察变量

    @Before(value = "execution(public * com.xxx.facade..*.*(..))" ) 
    public void before(JoinPoint jp) { 
        String methodName = jp.getSignature().getName();   //获得方法名
            
             String className = jp.getThis().toString();//获得类名
             Object[] args = jp.getArgs();  //获得参数列表
             if(args != null && args.length > 0) {
                 String paraString = generateParaString(args);
                 LOGGER.info("[before()]" + this.generateReadableString(className) + "." + methodName 
                         + "(), parametes:" + paraString);
                 
             } else {
                 LOGGER.info("[before()]" + this.generateReadableString(className) + "." + methodName + "()");
             }
             
    }

通过debug发现，做公用方法的同事在获取类名的时候埋了一个坑：

String className = jp.getThis().toString()

JoinPoint的getThis()方法用于获取被切的对象，但是，后面带了一个 .toString()…………

这获取的实际上是实例转然后string，不是类名啊！

所以，被切的实例（public * com.xxx.facade...）里面，只要被调用toString方法，就是进入无出口的递归调用里面，这里必然StackOverflow！

实际上，这段代码在刚刚开始调查错误的时候就看到了，但是没有debug一句一句跟着跑，跟着看，根本没意识到会出事。

四、总结（重要！）

总结1：发生稀奇古怪的错误以后，不要慌，镇静，然后强迫自己一条一条仔细读日志，哪怕觉得看不懂也要一条一条仔细读！

总结2：对于错误原因没有较大把握的时候，别瞎猜，或者说别被自己的经验带来的偏见误导。东一下西一下瞎猜瞎试的话，反而可能更浪费时间。出错位置能debug的话，一定要第一时间跟着代码跑一遍，比瞎猜强100倍。

五、附录——如何利用toString()方法触发 StackOverflowError

5.1、两个POJO中互相定义了对方类型的成员变量

其实在一对多的模型中应该是见不到这种情况的，比如 borrow_info 和 borrow_invest ，borrow_invest 的定义中有一个 borrow_info 类的成员变量是合理的，而 borrow_info 中不会出现 borrow_invest ，没有意义。
但是在一对一的关系中 —— 比如UML中定义的 1:1 关联关系中，这种互相包含从逻辑关系上来说是合理的。举例：牛郎织女。但是这种关系定义在POJO中的话造成隐患

public class A {
    private int aValue;
    private B bInstance = null;

    public A() {
        aValue = 0;
        bInstance = new B();
    }

    @Override
    public String toString() {
        return "";
    }
}


public class B {

    private int bValue;
    private A aInstance = null;

    public B() {
        bValue = 10;
        aInstance = new A();
    }

    @Override
    public String toString() {
        return "";
    }

    public static void main(String[] args) {
        A obj = new A();
        System.out.println(obj.toString());
    }
}

运行B的main()方法以后

Exception in thread "main" java.lang.StackOverflowError
    at com.xxx.bootmint.genStackOverflow.B.<init>(B.java:10)
    at com.xxx.bootmint.genStackOverflow.A.<init>(A.java:9)
    at com.xxx.bootmint.genStackOverflow.B.<init>(B.java:10)
    at com.xxx.bootmint.genStackOverflow.A.<init>(A.java:9)
    at com.xxx.bootmint.genStackOverflow.B.<init>(B.java:10)
    at com.xxx.bootmint.genStackOverflow.A.<init>(A.java:9)
    at com.xxx.bootmint.genStackOverflow.B.<init>(B.java:10)
    at com.xxx.bootmint.genStackOverflow.A.<init>(A.java:9)
……

5.2、自己瞎写toString()，使用了this

这种情况在实际工作中应当是见不到的，一般都是使用IDE自动生成toString()，不应该有人手写吧

public class C {

    private Integer id;
    private String borrowName;

    public Integer getId() {
        return id;
    }

    public void setId(Integer id) {
        this.id = id;
    }

    public String getBorrowName() {
        return borrowName;
    }

    public void setBorrowName(String borrowName) {
        this.borrowName = borrowName;
    }

    @Override
    public String toString() {
        return "borrow_info:" + this;
    }

    public static void main(String[] args) {
        C c = new C();
        System.out.println(c.toString());
    }
}

运行结果

Exception in thread "main" java.lang.StackOverflowError
    at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:449)
    at java.lang.StringBuilder.append(StringBuilder.java:136)
    at com.xxx.bootmint.genStackOverflow.C.toString(C.java:26)
    at java.lang.String.valueOf(String.java:2994)
    at java.lang.StringBuilder.append(StringBuilder.java:131)
    at com.xxx.bootmint.genStackOverflow.C.toString(C.java:26)
    at java.lang.String.valueOf(String.java:2994)
    at java.lang.StringBuilder.append(StringBuilder.java:131)
    at com.xxx.bootmint.genStackOverflow.C.toString(C.java:26)
    at java.lang.String.valueOf(String.java:2994)
    at java.lang.StringBuilder.append(StringBuilder.java:131)
    at com.xxx.bootmint.genStackOverflow.C.toString(C.java:26)
……

原因其实很简单，toString()方法中使用 "+" 号连接字符串和 this 的话，jvm会自动将 this 转变为 String 类型，那么就触发了this的toString()，然后新的toString()里面又要触发toString()，结局就是一个无限递归。