背景

某项目OSB生产环境RFC接口概率性调用失败,大概10次调用就会有一次失败,可以稳定重现,以下是该问题的一些重要信息

封装了1个简单的sap rfc查询接口,没其他逻辑,只返回结果。

  • 1. OSB生产环境节点服务器单机运行,依旧存在问题,每个单机都会出现。
  • 2. OSB生产环境配置连接SAP单个节点IP,依旧存在问题,每个SAP节点都会出现。
  • 3. 重启OSB生产环境服务器后,依然会出现问题。
  • 4. 【重点】使用JAVA写代码 去调用SAP RFC接口,不会出现这个问题。
  • 5. 【重点】OSB的测试环境调用 SAP的测试环境RFC接口,不会出现这个问题。
  • 6. 【重点】OSB的测试环境调用 SAP的生产环境RFC接口,不会出现这个问题。
  • 7. 【重点】OSB的生产环境调用 SAP的测试环境RFC接口,会出现时而请求测试的sap,时而请求生产的sap。也会出现这个not found问题。

看起来很诡异是吧,这也是给这个问题取名幽灵RFC的原因,但看现象无法做出最基本的可能性判断,没有规律可循。错误日志如下(摘取重要的片段):

Caused by: oracle.tip.adapter.sa.api.JCABindingException: oracle.tip.adapter.sa.impl.fw.ext.org.collaxa.thirdparty.apache.wsif.WSIFException: servicebus:/HRIICenter/TempSyn/Resources/TotalAnnualLeave.wsdl [ TotalAnnualLeave_PT::ZPB_PT_0002(parameters,parameters) ] - WSIF JCA Execute of operation 'ZPB_PT_0002' failed due to: javax.resource.ResourceException: java.lang.RuntimeException: ZPB_PT_0002 not found in SAP.; nested exception is: 
	javax.resource.ResourceException: javax.resource.ResourceException: java.lang.RuntimeException: ZPB_PT_0002 not found in SAP.
	at oracle.tip.adapter.sa.impl.JCABindingReferenceImpl.request(JCABindingReferenceImpl.java:308)
	at com.bea.wli.sb.transports.jca.binding.JCATransportOutboundOperationBindingServiceImpl.invoke(JCATransportOutboundOperationBindingServiceImpl.java:164)
	... 113 more
Caused by: oracle.tip.adapter.sa.impl.fw.ext.org.collaxa.thirdparty.apache.wsif.WSIFException: servicebus:/HRIICenter/TempSyn/Resources/TotalAnnualLeave.wsdl [ TotalAnnualLeave_PT::ZPB_PT_0002(parameters,parameters) ] - WSIF JCA Execute of operation 'ZPB_PT_0002' failed due to: javax.resource.ResourceException: java.lang.RuntimeException: ZPB_PT_0002 not found in SAP.; nested exception is: 
	javax.resource.ResourceException: javax.resource.ResourceException: java.lang.RuntimeException: ZPB_PT_0002 not found in SAP.
	at oracle.tip.adapter.sa.impl.fw.wsif.jca.WSIFOperation_JCA.performOperation(WSIFOperation_JCA.java:693)
	at oracle.tip.adapter.sa.impl.fw.wsif.jca.WSIFOperation_JCA.executeOperation(WSIFOperation_JCA.java:360)
	at oracle.tip.adapter.sa.impl.fw.wsif.jca.WSIFOperation_JCA.executeRequestResponseOperation(WSIFOperation_JCA.java:340)
	at oracle.tip.adapter.sa.impl.JCABindingReferenceImpl.invokeWsifProvider(JCABindingReferenceImpl.java:405)
	at oracle.tip.adapter.sa.impl.JCABindingReferenceImpl.request(JCABindingReferenceImpl.java:306)
	... 114 more
Caused by: javax.resource.ResourceException: javax.resource.ResourceException: java.lang.RuntimeException: ZPB_PT_0002 not found in SAP.
	at oracle.tip.adapter.sap.outbound.SAPInteractionImpl.execute(SAPInteractionImpl.java:639)
	at oracle.tip.adapter.sa.impl.fw.wsif.jca.WSIFOperation_JCA.performOperation(WSIFOperation_JCA.java:555)
	... 118 more
Caused by: javax.resource.ResourceException: java.lang.RuntimeException: ZPB_PT_0002 not found in SAP.
	at oracle.tip.adapter.sap.outbound.SAPConnectionImpl.getFunction(SAPConnectionImpl.java:445)
	at oracle.tip.adapter.sap.outbound.SAPInteractionImpl.execRFC(SAPInteractionImpl.java:361)
	at oracle.tip.adapter.sap.outbound.SAPInteractionImpl.execute(SAPInteractionImpl.java:585)
	... 119 more
Caused by: java.lang.RuntimeException: ZPB_PT_0002 not found in SAP.
	at oracle.tip.adapter.sap.outbound.SAPConnectionImpl.getFunction(SAPConnectionImpl.java:442)
	... 121 more

重点是这句ZPB_PT_0002 not found in SAP.;,也就是在SAP里没有找到ZPB_PT_0002这个函数,但实际上是有这个函数,如果不存在的话应该一直不存在,不可能有时候有有时候没有。

背景交代完毕。

解决思路

按照我解决第三方系统交互的问题三步骤

  • 1. 找到能稳定重现的方法,便于调试,能自动化就自动化
  • 2. 抓包,和第三方系统交互的本质就是网络数据包的交互,往往能从包中看出一些蛛丝马迹,但前提条件是通信的协议不能是加密,https就不行
  • 3. 反编译源码,按照错误栈找到出错的代码位置,从源码中找线索

第一步就是要有能稳定重现的方法,如果一个bug不能稳定重现甚至无法重现,不要急于扎进去,很可能会浪费大量的时间在等待bug上,所以磨刀不误砍柴工,花点时间找到重现bug的方法是值得的,而且可能在这个过程中就找到了问题的原因。

重现脚本

接口是rest的接口,因此可以用curl调用,脚本也不复杂,就是不断执行curl命令对接口进行调用。

#!/bin/bash  
  
for((i=1;i<=100;i++));  
do
echo $i
curl http://$host:$port/HRIICenter/TempSyn/PS/TotalAnnualLeaveRest -X POST -d '{"I_BEGDA" : "2019-01-01","I_ENDDA" : "2019-12-31"
,"I_PERNR" : "10006315"}' -H 'Content-Type:application/json'
sleep 2s 
done

确实执行一段时间后就会报错,虽然没有稳定重现,但报错的频率满足查看问题的要求。

抓包

如果有条件,在遇到和第三方系统交互的疑难杂症时,抓包往往就是最后的杀手锏,为了排除其他因素的影响,把SAP的地址配置成了单机地址,不经过负载均衡服务器,因此只要抓取和SAP单机交互的网络包就行。命令如下

tcpdump -i eth0 host 172.16.xx.xx -w sap.prap -Z root

tcpdump会把数据包保存到sap.prap文件中,抓取完毕后可以从服务器下载下来,本地用wireshark工具进行分析,分析得到几个重要的信息:

  • 基本每个包都包含dummyFactory关键字,我们都幽灵有名字了。
  • 报错的包没抓到,比如我掉了10次接口,有两次报错了,但只抓到了8条数据

关键字问题属于sap协议部分,也没必要去猜测,当作一个线索就行,报错的包没抓到就很奇怪,一开始我分析可能错误根本就没到SAP那边,在osb这边就报错了,为了花了大量时间在找OSB的问题,走了弯路,这里就不详述,但找bug走弯路是正常的,如果一帆风顺反而心理没底。

源码

抓包给我们两个重要的线索,带着这两个线索,我们下一步就要去源代码里寻找线索,商业产品一般不提供源码,我们只能从jar包反编译得到源码,还好oracle的产品源码虽然庞大复杂,但没有加混淆,还是可以看得懂的。这里寻找源码也有个问题

怎么知道代码在哪个jar包里,osb系统有几百个jar包,而且分散到不同目录

解决办法很简单,把weblogic上的jar包全部下载下来,解压开,用everything工具对类名进行搜索(java的类名和文件名是一样的)就能找到指定的类,还能知道在哪个jar包里

下载jar包

到osb_server目录下执行以下命令即可

mkdir -p osb_jars
find . -name '*.jar'|xargs -i cp {} -r -t osb_jars/
tar -cvf osb_jars.tar osb_jars

下载到本地,解压,全选所有的jar包,用7-Zip解压,注意解压的时候将每个jar包解压到单独的目录中,这样我们就能知道类属于哪个jar包

我们的源码就隐藏在这源码的海洋之中,我们需要一个工具将她找出来,everything就派上用场了,如果你还没试过everything,那简直太遗憾了,这是我用过最好用的工具,不过,今天她不是了,今天的主角还没出场。

我们从栈底找到抛出错误的源码位置在SAPConnectionImpl的第442行

Caused by: java.lang.RuntimeException: ZPB_PT_0002 not found in SAP.
	at oracle.tip.adapter.sap.outbound.SAPConnectionImpl.getFunction(SAPConnectionImpl.java:442)

用everything搜索到代码的位置,从目录可以看出在SAPAdapter.jar这个jar包中,对该包进行反编译。

确实是这个地方抛出来了。

源码分析

别以为找到源码就是找到问题了,只是往万里长征迈出了一步而已,商业软件的源码往往十分庞大,因为商业软件要考虑到工程性,安全性,扩展等多方面,代码抽象程度很高,而且没有提供技术文档,很难从片段代码理解整个系统的架构。java反编译工具jd-gui查看源码不是很方面,我的解决方案是将jar包导入到idea中,idea可以非常方便的分析源码,导入的方式有很多,可以打到本地maven仓库,也可以直接作为第三方lib导入。分析的过程这里就不详述,总之需要一点经验,更多的是需要耐心,以下是整理出jco里面核心的几个类调用关系。

获取function过程
JCO获取destination(连接)过程
创建Respository

几个比较重要的信息:

  • JCo运行时runtime是静态变量,全局性的。
public abstract class JCo {
    private static final String factoryClass = "com.sap.conn.jco.rt.JCoRuntimeFactory";
    private static JCoInterface runtime = createJCo();
    private static synchronized JCoInterface createJCo() {
        if (runtime == null) {
            Class serviceManagerClass;
            Method loadLibraryMethod;
            if (Environment.inJTS()) {
                try {
                    serviceManagerClass = Class.forName("com.sap.vmc.service.core.ServiceManager");
                    loadLibraryMethod = serviceManagerClass.getMethod("loadLibrary", String.class);
                    loadLibraryMethod.invoke((Object)null, "JCo");
                } catch (Exception var3) {
                    throw new RuntimeException(var3);
                }
            } else {
                try {
                    serviceManagerClass = Class.forName("com.sap.conn.jco.rt.JCoRuntimeFactory");
                    loadLibraryMethod = serviceManagerClass.getMethod("getRuntime");
                    runtime = (JCoInterface)loadLibraryMethod.invoke((Object)null);
                } catch (Exception var2) {
                    throw new RuntimeException(var2);
                }
            }
        }
        return runtime;
    }
    //.....more
}
  • JCo运行时(JCoRuntime)的实现类是DefaultJCoRuntime,该类是JCo资源的顶层类,JCo资源都可以从这个类获取。
//获取destination
DefaultJCoRuntime.getDestinationManager().getDestination("xxxx");
//获取仓库Repository
DefaultJCoRuntime.getDestinationManager().getDestination("xxxx").getRepository();
//获取Function
DefaultJCoRuntime.getDestinationManager().getDestination("xxxx").getRepository().getFunction();
  • 仓库(JCoRepository)的实现类是AbapRepository,AbapRepository继承自抽象类BasicRepository,BasicRepository实现JCoRepository,获取function的核心逻辑如下:

AbapRepository.java

public JCoFunctionTemplate getFunctionTemplate(String functionName) throws JCoException {
    this.lastAccessTimestamp = System.currentTimeMillis();
    JCoFunctionTemplate template = super.getFunctionTemplate(functionName);
    if (template != null) {
        return template;
    } else {
        AbapException exc = null;
        try {
            template = this.queryFunctionTemplate(functionName);
        } catch (AbapException var5) {
            if (!"FU_NOT_FOUND".equalsIgnoreCase(var5.getKey())) {
                exc = var5;
            }
        }
        if (template != null) {
            super.addFunctionTemplate(template);
            template = super.getFunctionTemplate(functionName);
        } else if (exc != null) {
            throw exc;
        }
        return template;
    }
}

注意到super.getFunctionTemplate(functionName);调用BasicRepository的方法,方法如下:

public JCoFunctionTemplate getFunctionTemplate(String functionName) throws JCoException {
    this.lastAccessTimestamp = System.currentTimeMillis();
    if (functionName == null) {
        throw new IllegalArgumentException("Provide a valid function name: null is not allowed");
    } else {
        return this.storage.loadFunctionTemplate(functionName);
    }
}

storage就是存储function的地方,storage的实现类是MetaDataStorage

回到AbapRepository,注意到如果找不到function,会进行sap的查询

template = this.queryFunctionTemplate(functionName);

代码到这里就不具体展开了。

开始祭出今天的主角。

Arthas(阿尔萨斯)

通过上面源码分析,有几个问题

  • 1. 为什么storage没有存储我们需要的function
  • 2. 就算没有存储,重新查找为什么也找不到

要是能够在这里加System.out就好了*

我们是不是很经常会有这些问题,面对生产的代码bug,没有日志,不能调试,只能在那边猜测,只能不断的加System.out不断的部署,不断后悔为什么当时这里不加日志,为什么日志不打印出这个变量。

现在,有这么一个工具能够解决所有的问题,允许你偷窥运行时的代码,允许你不重新部署程序的情况下,动态的加日志。

这,就是今天的主角,神器Arthas,这个工具早有耳闻,但一直没机会用,这次彻底被她的黑科技震撼到,这个工具允许你动态入侵jvm,动态注入代码,甚至修改代码,可能是我孤陋寡闻,对jvm不了解,可能jvm本身就提供了这个功能,不管怎么说,这个工具刷新了我对jvm的认识,原来,还能这么干。

本文不介绍Arthas的使用方法,我会专门开一个专栏介绍这个工具,以表达我对她的喜爱。

  • 通过jps命令找到osb_server1的进程号20109,这个也是一个非常有用的小技巧
$ jps -v|grep osb_server1
20109 Server -Xms8192m -Xmx16384m -XX:PermSize=2048m -XX:MaxPermSize=4096m -Dweblogic.Name=osb_server1 .....
  • 运行arthas,选择中意的jvm,就可以正式入侵了
$ java -jar arthas-boot.jar 
[INFO] arthas-boot version: 3.1.7
[INFO] Found existing java process, please choose one and hit RETURN.
* [1]: 13656 weblogic.Server
  [2]: 11308 weblogic.NodeManager
  [3]: 2966 org.apache.derby.drda.NetworkServerControl
  [4]: 26866 oracle.sysman.gcagent.tmmain.TMMain
  [5]: 14567 weblogic.Server
  [6]: 20109 weblogic.Server
  [7]: 3014 weblogic.Server
6
[INFO] arthas home: /home/oracle/.arthas/lib/3.1.7/arthas
[INFO] Try to attach process 20109
[INFO] Attach process 20109 success.
[INFO] arthas-client connect 127.0.0.1 3658
  ,---.  ,------. ,--------.,--.  ,--.  ,---.   ,---.                           
 /  O  \ |  .--. ''--.  .--'|  '--'  | /  O  \ '   .-'                          
|  .-.  ||  '--'.'   |  |   |  .--.  ||  .-.  |<code>.  </code>-.                          
|  | |  ||  |\  \    |  |   |  |  |  ||  | |  |.-'    |                         
<code>--' </code>--'<code>--' '--'   </code>--'   <code>--'  </code>--'<code>--' </code>--'<code>-----'                          
                                                                                
wiki      https://alibaba.github.io/arthas                                      
tutorials https://alibaba.github.io/arthas/arthas-tutorials                     
version   3.1.7                                                                 
pid       20109                                                                 
time      2019-12-09 10:43:44

调试

我们先查看当前有哪几个仓库(Resposity),以为获取Function是通过仓库获取。

[arthas@20109]$ getstatic com.sap.conn.jco.rt.JCoRuntimeFactory runtime 'repositoryManager.repositories'
field: runtime
@HashMap[
    @String[Qxx]:@AbapRepository[com.sap.conn.jco.rt.AbapRepository@689a1a2d],
    @String[Gxx]:@AbapRepository[com.sap.conn.jco.rt.AbapRepository@5257cff2],
    @String[Pxx]:@AbapRepository[com.sap.conn.jco.rt.AbapRepository@705be0d4],
]
Affect(row-cnt:1) cost in 312 ms.

总共三个仓库,接口使用的是Pxx仓库,我们查看该仓库里面存储的Function

[arthas@20109]$ getstatic com.sap.conn.jco.rt.JCoRuntimeFactory runtime 'repositoryManager.repositories.Pxx.storage'
field: runtime
@MetaDataStorage[
    PREFIX=@String[/com/sap/conn/jco/repository/],
    FUNCTIONS=@String[functions],
    STRUCTURES=@String[structures],
    CLASSES=@String[classes],
    storageName=@String[Pxx],
    repository=@AbapRepository[com.sap.conn.jco.rt.AbapRepository@705be0d4],
    functions=@DefaultSharedStorage[com.sap.conn.jco.util.DefaultSharedStorage@215f2f3f],
    structures=@DefaultSharedStorage[com.sap.conn.jco.util.DefaultSharedStorage@7016e236],
    classes=@DefaultSharedStorage[com.sap.conn.jco.util.DefaultSharedStorage@6e5d80b7],
    storeKeeper=@StoreKeeper[com.sap.conn.jco.rt.MetaDataStorage$StoreKeeper@3cada6fc],
]

这里面存储了所有和SAP连接的对象信息,继续查看functions

[arthas@20109]$ getstatic com.sap.conn.jco.rt.JCoRuntimeFactory runtime 'repositoryManager.repositories.Pxx.storage.functions'
field: runtime
@DefaultSharedStorage[
    name=@String[/com/sap/conn/jco/repository/PRD/functions],
    map=@Hashtable[isEmpty=false;size=31],
]
Affect(row-cnt:1) cost in 275 ms.

有31个函数,如果需要查看具体函数名称,需要遍历map,这个语法稍微有点不一样

[arthas@20109]$ getstatic com.sap.conn.jco.rt.JCoRuntimeFactory runtime 'repositoryManager.repositories.Pxx.storage.functions.map.{ #this.name }'
field: runtime
@ArrayList[
    //....打码
    @String[ZPB_PT_0002],
    //....打码
]
Affect(row-cnt:1) cost in 352 ms.

可以看到是有ZPB_PT_0002这个函数的,那为什么会找不到,通过源码分析可以知道是通过AbapRepository.getFunctionTemplate获取函数,那么我们可以监控这个方法的输入和输出,通过arthas的watch命令实现。

[arthas@20109]$ watch com.sap.conn.jco.rt.AbapRepository getFunctionTemplate "{params,returnObj}"  -x 2
Press Q or Ctrl+C to abort.
Affect(class-cnt:3 , method-cnt:2) cost in 1357 ms.
ts=2019-12-09 10:57:17; [cost=0.227407ms] result=@ArrayList[
    @Object[][
        @String[ZPB_PT_0002],
    ],
    @AbapFunctionTemplate[
        serialVersionUID=@Long[3000120080918],
        name=@String[ZPB_PT_0002]
        //...打码
    ],
]

开启脚本,等待出错

[arthas@20109]$ watch com.sap.conn.jco.rt.AbapRepository getFunctionTemplate "{params,returnObj}"  -x 2
1==>ts=2019-12-09 11:00:38; [cost=0.157042ms] result=@ArrayList[
    @Object[][
        @String[ZPB_PT_0002],
    ],
    @AbapFunctionTemplate[
        serialVersionUID=@Long[3000120080918],
        name=@String[ZPB_PT_0002],
        //....
    ],
]
2==>ts=2019-12-09 11:00:38; [cost=0.259235ms] result=@ArrayList[
    @Object[][
        @String[ZFN_xxxx],
    ],
    @AbapFunctionTemplate[
        serialVersionUID=@Long[3000120080918],
        name=@String[ZFN_xxxx],
        //...
    ],
]
3==>ts=2019-12-09 11:00:40; [cost=9.737618ms] result=@ArrayList[
    @Object[][
        @String[ZPB_PT_0002],
    ],
    null,
]
4==>ts=2019-12-09 11:00:42; [cost=0.184786ms] result=@ArrayList[
    @Object[][
        @String[ZFN_xxxx],
    ],
    @AbapFunctionTemplate[
        serialVersionUID=@Long[3000120080918],
        name=@String[ZFN_xxxx],
        //...
    ],
]

为了方便说明,我这里加了1,2,3,4标识符(arthas没有这个功能,我后期加的),1是正常的,2观察到其他接口执行了查询函数ZFN_xxxx信息,接着3就报错了(返回null),我们大胆的预测因为2影响了3,我们测试了几次下来发现确实是这样的,每次2调完,3必然报错。

我们掌握了稳定出现bug的方法,离真相更进一步了。那么这个ZFN_xxxx是在哪个仓库里呢?

可以打印所有仓库的function可以找到ZFN_xxxx在Gxx这个仓库里。

getstatic com.sap.conn.jco.rt.JCoRuntimeFactory runtime 'repositoryManager.repositories.Pxx.storage.functions.map.{ #this.name }'
getstatic com.sap.conn.jco.rt.JCoRuntimeFactory runtime 'repositoryManager.repositories.Gxx.storage.functions.map.{ #this.name }'
getstatic com.sap.conn.jco.rt.JCoRuntimeFactory runtime 'repositoryManager.repositories.Qxx.storage.functions.map.{ #this.name }'

为什么Gxx仓库的调用会影响到Pxx仓库的调用?

我们可以调试更高一层的代码,注意到报错是oracle.tip.adapter.sap.outbound.SAPConnectionImpl.getFunction(SAPConnectionImpl.java:445),我们可以监控这个方法看有什么线索

先看下这个方法的逻辑

public JCoFunction getFunction(JCoRepository rfcRepository, String name)
    throws ResourceException
  {
    JCoFunction function = null;
    try
    {
      JCoDestination rfcClient = getRfcClient();
      if (rfcRepository == null) {
        rfcRepository = rfcClient.getRepository();
      }
      function = rfcRepository.getFunction(name);
      if (function == null)
      {
        this.mConnector.ping();
        throw new RuntimeException(name + " not found in SAP.");
      }
    }
    catch (Exception ex)
    {
      throw new ResourceException(ex);
    }
    return function;
  }

输入参数是rfcRepository和function的名称,如果rfcRepository为空那么就从rfcClient中获取(实际上rfcRepository是写死的,都是null)

[arthas@20109]$ watch oracle.tip.adapter.sap.outbound.SAPConnectionImpl getFunction "{params,returnObj==null}"  -x 2
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 1066 ms.
ts=2019-12-09 11:12:56; [cost=0.34454ms] result=@ArrayList[
    @Object[][
        null,
        @String[ZPB_PT_0002],
    ],
    @Boolean[false],
]
ts=2019-12-09 11:13:01; [cost=0.242924ms] result=@ArrayList[
    @Object[][
        null,
        @String[ZFN_xxx],
    ],
    @Boolean[false],
]
ts=2019-12-09 11:13:02; [cost=0.238415ms] result=@ArrayList[
    @Object[][
        null,
        @String[ZFN_xxx],
    ],
    @Boolean[false],
]
ts=2019-12-09 11:13:04; [cost=16.399515ms] result=@ArrayList[
    @Object[][
        null,
        @String[ZPB_PT_0002],
    ],
    @Boolean[true],
]

为了查看方法,用returnObj==null作为是否为空的标识,可以发现,确实是ZFN_xxx一调用,就为null了,但这个看不出任何有用的信息。既然输入参数都一样,那么问题肯定处在程序内部,我们注意到程序内部是通过getRfcClient获取destination的,getRfcClient代码如下

public JCoDestination getRfcClient()
    throws Exception
  {
    JCoDestination rfcClient = null;
    try
    {
      rfcClient = this.mConnector.getDestination();
    }
    catch (JCoException ex)
    {
      throw ex;
    }
    return rfcClient;
  }

是从mConnector.getDestination中获取。那我们继续观察,这两个对象前后两次的差异

[arthas@20109]$ watch oracle.tip.adapter.sap.outbound.SAPConnectionImpl getFunction "{target.mConnector.hashCode(),target.mConnector.mJcoClient.hashCode(),params,returnObj==null}"  -x 2
1==>ts=2019-12-09 11:20:34; [cost=0.44004ms] result=@ArrayList[
    @Integer[1056877372],
    @Integer[516351721],
    @Object[][
        null,
        @String[ZPB_PT_0002],
    ],
    @Boolean[false],
]
2==>ts=2019-12-09 11:20:35; [cost=0.26188ms] result=@ArrayList[
    @Integer[1178413082],
    @Integer[1810668648],
    @Object[][
        null,
        @String[ZFN_xxx],
    ],
    @Boolean[false],
]
3==>ts=2019-12-09 11:20:36; [cost=29.289555ms] result=@ArrayList[
    @Integer[1056877372],
    @Integer[1810668648],
    @Object[][
        null,
        @String[ZPB_PT_0002],
    ],
    @Boolean[true],
]
4==>ts=2019-12-09 11:20:47; [cost=0.436022ms] result=@ArrayList[
    @Integer[1736997770],
    @Integer[516351721],
    @Object[][
        null,
        @String[ZPB_PT_0002],
    ],
    @Boolean[false],
]
5==>ts=2019-12-09 11:20:51; [cost=0.280053ms] result=@ArrayList[
    @Integer[1736997770],
    @Integer[516351721],
    @Object[][
        null,
        @String[ZPB_PT_0002],
    ],
    @Boolean[false],
]

1和3比较,在mConnector(1178413082)不变的情况下,mJcoClient改变了,而且变成了和2一样的mJcoClient(1810668648),也就是说,ZFN_xxx的调用改变了ZPB_PT_0002的destination,也就是sap连接,连到别的sap去了,所以找不到,这样确实很多问题都可以说得通了

  • 1. 为什么抓包抓不到错误的,因为调用的是别的sap模块,所以没抓到
  • 2. 为什么java程序不会出这个问题,因为问题是出在sapadapter级别的
  • 3. 为什么会间歇性的出错,不是间歇性的,是有触发条件的,条件是ZFN_xxx调用

接下来的问题就变成了,为什么在conection不变的情况下,destination改变了,唯一的一种可能是调用了改变的方法,在SapConnector中找到改变mJcoClient的唯一入口:

public JCoDestination refreshDestination()
  {
    try
    {
      this.mJcoClient = JCoDestinationManager.getDestination(this.mName);
    }
    catch (JCoException e)
    {
      e.printStackTrace();
    }
    return this.mJcoClient;
  }

说明有程序调用了这个方法对mJcoClient进行刷新,我们测试下来的结果也确实是这样的,但没找到调用的函数,但理论上,就算刷新了,也不会有问题,刷新就一行代码JCoDestinationManager.getDestination(this.mName);`通过追踪源码,可以找到该函数的核心逻辑:

Hashtable<String, RfcDestination> destinations = new Hashtable(29);
protected JCoDestination searchDestination(String destinationName, String scopeType) throws JCoException {
    RfcDestination destination = (RfcDestination)this.destinations.get(destinationName);
    //....
    return (JCoDestination)destination;
}

观察destinations的数据情况

[arthas@20109]$ getstatic com.sap.conn.jco.rt.JCoRuntimeFactory runtime 'destinationManager.destinations'
field: runtime
@Hashtable[
    @String[dummyFactory]:@RfcDestination[destination dummyFactory with properties: {sap.connection.meta.chche=, jco.destination.userid=xxx, jco.client.lang=EN, jco.client.ashost=172.xxx.xxx.153, jco.destination.auth_type=CONFIGURED_USER, jco.client.destination=dummyFactory, jco.client.user=xxx, propertiesProvider=oracle.tip.adapter.sap.share.connection.SapDestinationDataProvider, sap.connection.name=dummyFactory, jco.client.sysnr=00, sap.connection.meta.usedt=, jco.client.client=800}],
]
Affect(row-cnt:1) cost in 239 ms.
[arthas@20109]$ getstatic com.sap.conn.jco.rt.JCoRuntimeFactory runtime 'destinationManager.destinations'
field: runtime
@Hashtable[
    @String[dummyFactory]:@RfcDestination[destination dummyFactory with properties: {jco.destination.pool_capacity=30, sap.connection.meta.chche=, jco.destination.userid=xxx, jco.client.lang=ZH, jco.client.ashost=172.xxx.xxx.94, jco.destination.auth_type=CONFIGURED_USER, jco.client.destination=dummyFactory, jco.client.user=xxx, propertiesProvider=oracle.tip.adapter.sap.share.connection.SapDestinationDataProvider, sap.connection.name=dummyFactory, jco.client.sysnr=00, jco.destination.peak_limit=150, sap.connection.meta.usedt=, jco.client.client=800}],
]
Affect(row-cnt:1) cost in 254 ms.

可以发现两次jco.client.ashost是不一样的,说明是两个仓库,但是名称一样,都是dummyFactory,关键是这个是Hashtable的结构存储,因为问题的根本原因是

sap多个模块的仓库名称设置了相同的名称,导致了配置冲突,接口调到别的仓库里去了。

至此,该问题在应用层终结。

遗留问题

  • 1. destination的名称怎么来的,可以确定的是dummyFactory这个名称不是在应用层这边配置的,很有可能在sap端配置的,如果有新的进展再来更新。
  • 2. 何时调用refreshDestination进行刷新,这个只能成为一个遗憾了,因为刷新是没有规律的,也找不到刷新的代码。

总结

程序员和侦探有点类似,一个是寻找线索做案件调查,一个是寻找线索解决bug,过程都是一样的,需要从各个线索中找到问题的关键,解决bug过程也是一件很有意思的事情,也是希望大家碰到问题的时候不要害怕,再难的问题只要花时间总能找到问题的本质,本文涉及内容较多,我也是尽量事无巨细的记录下来,希望能给阅读本文的你提供一些解决问题的思路。

,
Trackback

no comment untill now

Add your comment now