Skywalking ContextManager.activeSpan抛NullPointerException的bug

触发bug的条件 当前TraceSegment创建的太多了span(超过参数agent.span_limit_per_segment的配置, 默认300)之后,执行ContextManager.createExitSpan的时候会创建NoopExitSpan grpc agent 对远程调用拦截的时候会有两个Interceptor生效,也就是说会执行两次ContextManager.CreateExitSpan和ContextManager.StopSpan 具体原因 对于正常的ExitSpan来说,第二次执行createExitSpan的时候,如果发现当前栈的头位置已经是ExitSpan就不再创建新的,而是对这个ExitSpan调用start操作(stackDepth++)。在调用stopSpan的时候, 会检查ExitSpan的finish(stackDepth-- == 0),如果为true,才pop。所以只会pop一次,没有问题

如果因为Span太多,超过限制,创建的是NoopExitSpan的时候,第二次执行createExitSpan的时候,因为NoopExitSpan的isExit方法返回true,所以也只会创建一个Span,第二次的时候只会调用NoopExitSpan的start方法(实现为空)。但是在调用stopSpan的时候,不会对NoopExit,而是直接pop,所以就会pop出两个span,其中一个span是别的拦截器的span。

这样就会导致接下来当前线程的span都对应不上了, 后面的拦截器调用stopSpan的时候就会因为找不到span而抛出空指针异常

ERROR io.grpc.internal.SerializingExecutor - Exception while executing runnable io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1HalfClosed@5de15ec java.lang.NullPointerException: null at org.apache.skywalking.apm.agent.core.context.ContextManager.activeSpan(ContextManager.java:161) at org.apache.skywalking.apm.agent.core.context.ContextManager.stopSpan(ContextManager.java:165) at org.apache.skywalking.apm.plugin.babyfs.grpc.v1.CallServerInterceptor$ServerCallListener.onHalfClose(CallServerInterceptor.java:173) at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.halfClosed(ServerCallImpl.java:283) at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1HalfClosed.runInContext(ServerImpl.java:710) at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37) at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) 1 2 3 4 5 6 7 8 9 10 11 12 具体过程 首先是在测试环境中发现偶尔会有上面的空指针异常,一开始是怀疑某一个agent的拦截器会不会因为bug没有创建Span,就直接关闭了Span,导致对应不上的。因为agent 的插件有很多,很难定位是哪个插件的原因,幸好后来继续看日志的时候发现一个规律。在发生在这个异常之前,同一个线程中都会报如下warn:

WARN 2019-08-09 17:54:31:190 http-nio-10011-exec-1 TracingContext : More than 300 spans required to create java.lang.RuntimeException: Shadow tracing context. Thread dump at org.apache.skywalking.apm.agent.core.context.TracingContext.isLimitMechanismWorking(TracingContext.java:554) at org.apache.skywalking.apm.agent.core.context.TracingContext.access$100(TracingContext.java:47) at org.apache.skywalking.apm.agent.core.context.TracingContext$5.doProcess(TracingContext.java:327) at org.apache.skywalking.apm.agent.core.dictionary.PossibleFound.doInCondition(PossibleFound.java:50) at org.apache.skywalking.apm.agent.core.context.TracingContext.createExitSpan(TracingContext.java:323) at org.apache.skywalking.apm.agent.core.context.ContextManager.createExitSpan(ContextManager.java:122) at org.apache.skywalking.apm.plugin.grpc.v1.BlockingCallInterceptor.beforeMethod(BlockingCallInterceptor.java:42) at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.StaticMethodsInter.intercept(StaticMethodsInter.java:76) at io.grpc.stub.ClientCalls.blockingUnaryCall(ClientCalls.java) 1 2 3 4 5 6 7 8 9 10 11 后来在开发环境直接做实现,发现只要创建的span数量超过300,就能稳定复现文章开头的异常, 所以很可能跟这个是有关系的。继续看CreateExitSpan的代码,看到CreateExitSpan的时候会先判断当前已经在ExitSpan中的话就直接调用ExitSpan的start方法,start方法中会对stackDepth++, 而在StopSpan的时候,对于ExitSpan会先执行finish判断(stackDepth-- == 0),如果为true,才执行pop,逻辑完全没问题

AbstractSpan exitSpan; AbstractSpan parentSpan = peek(); if (parentSpan != null && parentSpan.isExit()) { exitSpan = parentSpan; } else { final int parentSpanId = parentSpan == null ? -1 : parentSpan.getSpanId(); exitSpan = (AbstractSpan)DictionaryManager.findNetworkAddressSection() .find(remotePeer).doInCondition( new PossibleFound.FoundAndObtain() { @Override public Object doProcess(final int peerId) { if (isLimitMechanismWorking()) { return new NoopExitSpan(peerId); }

                        return DictionaryManager.findEndpointSection()
                            .findOnly(segment.getServiceId(), operationName)
                            .doInCondition(
                                new PossibleFound.FoundAndObtain() {
                                    [@Override](https://my.oschina.net/u/1162528)
                                    public Object doProcess(int operationId) {
                                        return new ExitSpan(spanIdGenerator++, parentSpanId, operationId, peerId);
                                    }
                                }, new PossibleFound.NotFoundAndObtain() {
                                    [@Override](https://my.oschina.net/u/1162528)
                                    public Object doProcess() {
                                        return new ExitSpan(spanIdGenerator++, parentSpanId, operationName, peerId);
                                    }
                                });
                    }
                },
                new PossibleFound.NotFoundAndObtain() {
                    [@Override](https://my.oschina.net/u/1162528)
                    public Object doProcess() {
                        if (isLimitMechanismWorking()) {
                            return new NoopExitSpan(remotePeer);
                        }

                        return DictionaryManager.findEndpointSection()
                            .findOnly(segment.getServiceId(), operationName)
                            .doInCondition(
                                new PossibleFound.FoundAndObtain() {
                                    @Override
                                    public Object doProcess(int operationId) {
                                        return new ExitSpan(spanIdGenerator++, parentSpanId, operationId, remotePeer);
                                    }
                                }, new PossibleFound.NotFoundAndObtain() {
                                    @Override
                                    public Object doProcess() {
                                        return new ExitSpan(spanIdGenerator++, parentSpanId, operationName, remotePeer);
                                    }
                                });
                    }
                });
        push(exitSpan);
    }
    exitSpan.start();
    return exitSpan;

public ExitSpan start() { if (++stackDepth == 1) { super.start(); } return this; }

@Override public boolean finish(TraceSegment owner) { if (--stackDepth == 0) { if (this.operationId == DictionaryUtil.nullValue()) { this.operationId = (Integer)DictionaryManager.findEndpointSection() .findOrPrepare4Register(owner.getServiceId(), operationName, this.isEntry(), this.isExit()) .doInCondition( new PossibleFound.FoundAndObtain() { @Override public Object doProcess(int value) { return value; } }, new PossibleFound.NotFoundAndObtain() { @Override public Object doProcess() { return DictionaryUtil.nullValue(); } } ); } return super.finish(owner); } else { return false; } } 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 同时在创建ExitSpan的时候,会检查isLimitMechanismWorking(如果已经span数量已经超过agent.span_limit_per_segment的配置就会返回true),如果为true就返回NoopExitSpan,问题就出在NoopExitSpan上面了。因为NoopExitSpan的isExit方法也返回true,也被认为是一个ExitSpan。所以如果在一个远程调用中如果被执行两次CreateSpan,只会有一个NoopExitSpan被创建出来,第二次的时候只会执行NoopExitSpan的start方法,而NoopExitSpan的start方法是空的。stopSpan也会被执行两次,两次都会执行pop操作,就导致pop出来了一个不属于当前远程调用的span,该tracesegment在后面的stopSpan方法就会因为找不到span而抛出异常。

解决办法 在createExitSpan之前先检查是否达到限制,如果达到限制,直接创建NoopExitSpan并push进stack进去,然后返回

@Override public AbstractSpan createExitSpan(final String operationName, final String remotePeer) { if (isLimitMechanismWorking()) { NoopExitSpan span = new NoopExitSpan(remotePeer); return push(span); }

    AbstractSpan exitSpan;
    AbstractSpan parentSpan = peek();
    if (parentSpan != null && parentSpan.isExit()) {
        exitSpan = parentSpan;
    }
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值