from:http://pfmiles.github.io/blog/recently-hessian-deserialize-problem-and-thread-pool-executor-experience/
最近工作中遇到一個詭異的問題:別人遠程調用我們的系統暴露的服務,同步調用,底層使用hessian協議做序列化;
調用方系統報空指針,反序列化失敗:
2013-04-18 16:52:10,308 [AvatarRuleChargeService.java:74] [com.alibaba.itbu.billing.biz.adaptor.avatar.AvatarRuleChargeService] ERROR com.alibaba.itbu.billing.biz.adaptor.crm.ChargeProxy :: avatar charge sys error com.alibaba.dubbo.rpc.RpcException: Failed to invoke the method match in the service com.alibaba.china.ruleservice.RuleService. Tried 3 times of the providers [172.22.6.83:20980, 172.22.6.80:20980, 172.22.9.76:20980] (3/3) from the registry dubbo-reg1.hst.xyi.cn.alidc.net:9090 on the consumer 172.30.118.26 using the dubbo version 2.4.9. Last error is: Failed to invoke remote method: match, provider: dubbo://172.22.6.83:20980/com.alibaba.china.ruleservice.RuleService?anyhost=true&application=billing&check=false&default.reference.filter=dragoon&dubbo=2.4.9&interface=com.alibaba.china.ruleservice.RuleService&methods=match&pid=18616&revision=1.0-SNAPSHOT&side=consumer&timeout=5000×tamp=1366275108588&version=1.0.0, cause: com.alibaba.com.caucho.hessian.io.HessianProtocolException: 'com.alibaba.china.ruleservice.RuleServiceImpl$DynamicPluginInvocationMatchedResult' could not be instantiated com.alibaba.com.caucho.hessian.io.HessianProtocolException: 'com.alibaba.china.ruleservice.RuleServiceImpl$DynamicPluginInvocationMatchedResult' could not be instantiated at com.alibaba.com.caucho.hessian.io.JavaDeserializer.instantiate(JavaDeserializer.java:275) at com.alibaba.com.caucho.hessian.io.JavaDeserializer.readObject(JavaDeserializer.java:155) at com.alibaba.com.caucho.hessian.io.SerializerFactory.readObject(SerializerFactory.java:396) at com.alibaba.com.caucho.hessian.io.Hessian2Input.readObjectInstance(Hessian2Input.java:2070) at com.alibaba.com.caucho.hessian.io.Hessian2Input.readObject(Hessian2Input.java:2005) at com.alibaba.com.caucho.hessian.io.Hessian2Input.readObject(Hessian2Input.java:1990) at com.alibaba.com.caucho.hessian.io.Hessian2Input.readObject(Hessian2Input.java:1538) at com.alibaba.dubbo.common.serialize.support.hessian.Hessian2ObjectInput.readObject(Hessian2ObjectInput.java:94) at com.alibaba.dubbo.common.serialize.support.hessian.Hessian2ObjectInput.readObject(Hessian2ObjectInput.java:99) at com.alibaba.dubbo.rpc.protocol.dubbo.DecodeableRpcResult.decode(DecodeableRpcResult.java:83) at com.alibaba.dubbo.rpc.protocol.dubbo.DecodeableRpcResult.decode(DecodeableRpcResult.java:109) at com.alibaba.dubbo.rpc.protocol.dubbo.DubboCodec.decodeBody(DubboCodec.java:97) at com.alibaba.dubbo.remoting.exchange.codec.ExchangeCodec.decode(ExchangeCodec.java:128) at com.alibaba.dubbo.remoting.exchange.codec.ExchangeCodec.decode(ExchangeCodec.java:87) at com.alibaba.dubbo.rpc.protocol.dubbo.DubboCountCodec.decode(DubboCountCodec.java:49) at com.alibaba.dubbo.remoting.transport.netty.NettyCodecAdapter$InternalDecoder.messageReceived(NettyCodecAdapter.java:135) at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:80) at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559) at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:274) at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:261) at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:349) at org.jboss.netty.channel.socket.nio.NioWorker.processSelectedKeys(NioWorker.java:280) at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:200) at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108) at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:44) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662) Caused by: java.lang.reflect.InvocationTargetException at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27) at java.lang.reflect.Constructor.newInstance(Constructor.java:513) at com.alibaba.com.caucho.hessian.io.JavaDeserializer.instantiate(JavaDeserializer.java:271) ... 28 more Caused by: java.lang.NullPointerException at com.alibaba.china.ruleservice.RuleServiceImpl$DynamicPluginInvocationMatchedResult.<init>(RuleServiceImpl.java:163) ... 33 more at com.alibaba.dubbo.rpc.cluster.support.FailoverClusterInvoker.doInvoke(FailoverClusterInvoker.java:101) at com.alibaba.dubbo.rpc.cluster.support.AbstractClusterInvoker.invoke(AbstractClusterInvoker.java:226) at com.alibaba.dubbo.rpc.cluster.support.wrapper.MockClusterInvoker.invoke(MockClusterInvoker.java:72) at com.alibaba.dubbo.rpc.proxy.InvokerInvocationHandler.invoke(InvokerInvocationHandler.java:52) at com.alibaba.dubbo.common.bytecode.proxy1.match(proxy1.java) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149) at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:88) at com.alibaba.itbu.billing.framework.aop.OpenApiLogAspect.logExecuteTime(OpenApiLogAspect.java:38) at sun.reflect.GeneratedMethodAccessor199.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:627) at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:616) at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:64) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204) at $Proxy107.match(Unknown Source) at com.alibaba.itbu.billing.biz.adaptor.avatar.AvatarRuleChargeService.chargeByFactor(AvatarRuleChargeService.java:72) at com.alibaba.itbu.billing.biz.charge.times.RuleChargeByTimesProcessor.getChargeResult(RuleChargeByTimesProcessor.java:62) at com.alibaba.itbu.billing.biz.charge.times.ChargeByTimesProcessor.charge(ChargeByTimesProcessor.java:117) at com.alibaba.itbu.billing.biz.task.ChargeByIncInstantTimesTask.charge(ChargeByIncInstantTimesTask.java:174) at com.alibaba.itbu.billing.biz.task.ChargeByIncInstantTimesTask$1.run(ChargeByIncInstantTimesTask.java:109) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662) Caused by: com.alibaba.dubbo.remoting.RemotingException: com.alibaba.com.caucho.hessian.io.HessianProtocolException: 'com.alibaba.china.ruleservice.RuleServiceImpl$DynamicPluginInvocationMatchedResult' could not be instantiated com.alibaba.com.caucho.hessian.io.HessianProtocolException: 'com.alibaba.china.ruleservice.RuleServiceImpl$DynamicPluginInvocationMatchedResult' could not be instantiated at com.alibaba.com.caucho.hessian.io.JavaDeserializer.instantiate(JavaDeserializer.java:275) at com.alibaba.com.caucho.hessian.io.JavaDeserializer.readObject(JavaDeserializer.java:155) at com.alibaba.com.caucho.hessian.io.SerializerFactory.readObject(SerializerFactory.java:396) at com.alibaba.com.caucho.hessian.io.Hessian2Input.readObjectInstance(Hessian2Input.java:2070) at com.alibaba.com.caucho.hessian.io.Hessian2Input.readObject(Hessian2Input.java:2005) at com.alibaba.com.caucho.hessian.io.Hessian2Input.readObject(Hessian2Input.java:1990) at com.alibaba.com.caucho.hessian.io.Hessian2Input.readObject(Hessian2Input.java:1538) at com.alibaba.dubbo.common.serialize.support.hessian.Hessian2ObjectInput.readObject(Hessian2ObjectInput.java:94) at com.alibaba.dubbo.common.serialize.support.hessian.Hessian2ObjectInput.readObject(Hessian2ObjectInput.java:99) at com.alibaba.dubbo.rpc.protocol.dubbo.DecodeableRpcResult.decode(DecodeableRpcResult.java:83) at com.alibaba.dubbo.rpc.protocol.dubbo.DecodeableRpcResult.decode(DecodeableRpcResult.java:109) at com.alibaba.dubbo.rpc.protocol.dubbo.DubboCodec.decodeBody(DubboCodec.java:97) at com.alibaba.dubbo.remoting.exchange.codec.ExchangeCodec.decode(ExchangeCodec.java:128) at com.alibaba.dubbo.remoting.exchange.codec.ExchangeCodec.decode(ExchangeCodec.java:87) at com.alibaba.dubbo.rpc.protocol.dubbo.DubboCountCodec.decode(DubboCountCodec.java:49) at com.alibaba.dubbo.remoting.transport.netty.NettyCodecAdapter$InternalDecoder.messageReceived(NettyCodecAdapter.java:135) at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:80) at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559) at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:274) at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:261) at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:349) at org.jboss.netty.channel.socket.nio.NioWorker.processSelectedKeys(NioWorker.java:280) at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:200) at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108) at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:44) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662) Caused by: java.lang.reflect.InvocationTargetException at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27) at java.lang.reflect.Constructor.newInstance(Constructor.java:513) at com.alibaba.com.caucho.hessian.io.JavaDeserializer.instantiate(JavaDeserializer.java:271) ... 28 more Caused by: java.lang.NullPointerException at com.alibaba.china.ruleservice.RuleServiceImpl$DynamicPluginInvocationMatchedResult.<init>(RuleServiceImpl.java:163) ... 33 more at com.alibaba.dubbo.remoting.exchange.support.DefaultFuture.returnFromResponse(DefaultFuture.java:190) at com.alibaba.dubbo.remoting.exchange.support.DefaultFuture.get(DefaultFuture.java:110) at com.alibaba.dubbo.remoting.exchange.support.DefaultFuture.get(DefaultFuture.java:84) at com.alibaba.dubbo.rpc.protocol.dubbo.DubboInvoker.doInvoke(DubboInvoker.java:96) at com.alibaba.dubbo.rpc.protocol.AbstractInvoker.invoke(AbstractInvoker.java:144) at com.alibaba.dubbo.rpc.listener.ListenerInvokerWrapper.invoke(ListenerInvokerWrapper.java:74) at com.alibaba.dubbo.monitor.dragoon.filter.DragoonFilter.invoke0(DragoonFilter.java:82) at com.alibaba.dubbo.monitor.dragoon.filter.DragoonFilter.invoke(DragoonFilter.java:34) at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) at com.alibaba.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java:75) at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) at com.alibaba.dubbo.rpc.protocol.dubbo.filter.FutureFilter.invoke(FutureFilter.java:53) at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) at com.alibaba.dubbo.rpc.filter.ConsumerContextFilter.invoke(ConsumerContextFilter.java:48) at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) at com.alibaba.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:53) at com.alibaba.dubbo.rpc.cluster.support.FailoverClusterInvoker.doInvoke(FailoverClusterInvoker.java:77) ... 32 more
看到這個日志第一反映是覺得RuleServiceImpl.java:163
數據錯誤,拋空指針,但檢查那塊代碼發現那個地方根本不可能拋空指針 —— 所有用到的變量都是new
出來的;
而且,依據調用方提供的錯誤日志的拋出時間,我在被調用方系統的所有機器的日志里查找了一遍,沒有發現對應的服務端日志;照理說服務端拋空指針,服務端也會有對應日志,但沒有任何線索…
因此只好翻開了JavaDeserializer.java:275
作檢查,發現有這么一段:
public JavaDeserializer(Class cl) { _type = cl; _fieldMap = getFieldMap(cl); _readResolve = getReadResolve(cl); if (_readResolve != null) { _readResolve.setAccessible(true); } Constructor []constructors = cl.getDeclaredConstructors(); long bestCost = Long.MAX_VALUE; for (int i = 0; i < constructors.length; i++) { Class []param = constructors[i].getParameterTypes(); long cost = 0; for (int j = 0; j < param.length; j++) { cost = 4 * cost; if (Object.class.equals(param[j])) cost += 1; else if (String.class.equals(param[j])) cost += 2; else if (int.class.equals(param[j])) cost += 3; else if (long.class.equals(param[j])) cost += 4; else if (param[j].isPrimitive()) cost += 5; else cost += 6; } if (cost < 0 || cost > (1 << 48)) cost = 1 << 48; cost += param.length << 48; if (cost < bestCost) { _constructor = constructors[i]; bestCost = cost; } } if (_constructor != null) { _constructor.setAccessible(true); Class []params = _constructor.getParameterTypes(); _constructorArgs = new Object[params.length]; for (int i = 0; i < params.length; i++) { _constructorArgs[i] = getParamArg(params[i]); } } }
看完這段后,再結合遠程調用的返回結果類后恍然大悟:
上面這段代碼,是hessian在反序列化的時候,用于在被反序列化的類里面找一個“得分最低”的構造函數,反序列化時會加以調用;
構造函數的“得分”規則大致是:參數越少得分越低;參數個數相同時,參數類型越接近JDK內置類得分越低
而我們的調用返回的類只有一個構造函數,當然只有這個構造函數會被選中
但是,hessian反序列化調用被選中的構造函數時,是這樣來創造該構造函數需要的參數的:
protected static Object getParamArg(Class cl) { if (! cl.isPrimitive()) return null; else if (boolean.class.equals(cl)) return Boolean.FALSE; else if (byte.class.equals(cl)) return new Byte((byte) 0); else if (short.class.equals(cl)) return new Short((short) 0); else if (char.class.equals(cl)) return new Character((char) 0); else if (int.class.equals(cl)) return new Integer(0); else if (long.class.equals(cl)) return new Long(0); else if (float.class.equals(cl)) return new Float(0); else if (double.class.equals(cl)) return new Double(0); else throw new UnsupportedOperationException(); }
可以看到,如果參數不是primitive
類型,會被null
代替;但不巧的是我們的構造函數內部對該參數調用了一個方法,因此拋出了空指針…
也就是說這個空指針是拋在客戶端反序列化的時候而不是服務端內部,因此服務端當然找不到對應的錯誤日志了;
解決的辦法也很簡單:可以新增一個無參構造函數(無參構造函數肯定“得分”最低一定會被選中);或者修改代碼保證任意參數為null
的時候都不會出問題
下面這個問題更有意思,說的是ThreadPoolExecutor
的RejectedExecutionHandler
的使用:
threadPool = new ThreadPoolExecutor(5, maxThreadNum, 5, TimeUnit.MINUTES, new SynchronousQueue<Runnable>(), tf, new RejectedExecutionHandler() { public void rejectedExecution(Runnable r, ThreadPoolExecutor e) { logger.error("Ep thread pool exhausted, epId: " + id + "!!"); r.run(); } });
這個代碼是說,當我這個ThreadPool不夠用,又不能再新增線程數的時候,由調用方線程自己來執行這個Runnable
任務…
本來這看上去沒什么問題,問題出在這個Runnable
本身的實現上 —— 它內部將執行它的線程block到了一個blocking queue上面,當調用方主線程親自來執行它時,使得主線程再也回不去做它自己該做的事情了,因此會出大問題…
所以這么看來,“當線程池不夠用就讓調用方線程自己來干”的這個策略在實際使用時要非常謹慎
這個問題是通過一個方便的thread dump分析工具: tda來查找的,因為出問題的這個應用是個多線程程序,有1600多個常駐線程,thread dump非常之大,肉眼直接看很不方便,但tda能將thread dump變得更友好易讀,方便排查問題,在此推薦一下