AgilePLM应用周期性崩溃-问题解决

​

问题现象

• 每周六凌晨2点左右，AgilePLM系统无法访问，登录服务器发现应用进程已崩溃，使用命令找不到weblogic应用进程（ps -ef | grep java）。
• 从weblogic服务器所有的相关日志中没有找到任何可疑的异常日志。 当Agile应用重启之后，一切恢复正常，下周六同样的问题又会再次出现。
• 由于IAgileSession创建失败，所有和Agile相关联的程序都无法正常使用。

环境说明

• CentOS Linux 7.9，JDK1.8

• Agile 9.3.6.10，Weblogic 12.2.1.3.0

原因分析

问题原因我们分析了一个多月，中间过程很曲折，走了很多弯路。如果不想看分析过程的，可以直接跳到真正原因章节。

确定异常时间

通过分析agile的weblogic日志，发现agile进程是每周六的2:10~2:11左右崩溃的。

业务程序原因排查

首先怀疑的是业务程序的定时任务。排查了所有代码并没有每周六执行的定时任务，只有每天2点执行的任务。而且存在如下疑点。

1. 如果定时任务处理的只是周六或者当天的数据，那应该过了当天或者周六就不会再次出现了。为什么每周六都出问题？难道恰好每到周六都出现异常数据？显然不可能。
2. 如果定时任务处理的是非时间条件的数据，那重启之后应该还是会查询到相同的数据。但实际是当天重启之后程序就运行正常了。
3. 如果是用户每周六凌晨都在做相同的操作引发了这个问题？通过日志分析排除了这个可能，而且就算做也不可能每周六指定时间做的。

基于上述原因，基本排除了是业务程序的问题。因为以我们目前的认知，想要通过一段业务程序来产生这样的问题是基本不可能的。

性能问题排查

接着我们开始怀疑是不是内存溢出或者线程死锁等性能问题引起的。
一开始在weblogic的日志中确实找到了内存溢出的日志

[2023-05-20T03:55:05.092+00:00] [np1-Agile] [INCIDENT_ERROR] [DFW-40104] [oracle.dfw.incident] [tid: [ACTIVE].ExecuteThread: '37' for queue: 'weblogic.kernel.Default (self-tuning)'] [userId: <WLS Kernel>] [ecid: ee1bf080-117a-47bc-8040-0fb76ab81598-0004a332,0] [errid: 55] [detailLoc: /u01/app/agile/agile936/agileDomain/servers/npi-Agile/adr/diag/ofm/agileDomain/npi-Agile/incident/incdir_55] [probKey: BEA-310003 [LowMemory]] [partition-name: DOMAIN] [tenant-name: GLOBAL] 使用问题关键字 "BEA-310003 [LowMemory]" 创建了意外事件 55

####<2023-5-19 上午11时56分57,935秒 CST> <Notice> <WebLogicServer> <npi.scc.com.cn> <npi-Agile> <Thread-3> <<WLS Kernel>> <> <17f0f822-4389-44d7-b47c-7ddabbb54bd3-004bf442> <1684468617935> <[severity-value: 32] [rid: 0] [partition-id: 0] [partition-name: DOMAIN] > <BEA-000388> <JVM called the WebLogic Server shutdown hook. The server will force shutdown now.> 

<Emergency> <oracle.dfw.incident> <np1.soo.com.cn> <np1-Agile> <[ACTIVE] ExecuteThread: '15' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <17f0f822-4389-44d7-b47c-7ddabbb54bd3-004bf10d> <1684467848201> <[severity-value: 1] [rid: 0] [partition-id: 0] [partition-name: DOMAIN] > <BEA-000000> <使用问题关键字 "BEA-310003 [LowMemory]" 创建了意外事件 47> 

我们修改了Weblogic的jvm启动参数，将内存从默认的3G调整到了6G，这个异常不在出现了，但是每周六2点还是会定时崩溃。如果是内存不足导致的，应该不会每次都这么顺序，于是只能继续分析原因。

期间找了技术大牛，还在Oracle Support官网的工程师。给Agile应用加了如下java启动参数：

# java内存溢出时自动导出dump文件
-XX:+HeapDumpOnOutOfMemoryError 
-XX:HeapDumpPath=/var/log/java.hprof 
-XX:ErrorFile=/var/log/hs_err_pid<pid>.log

# 开启飞行记录器
-XX:+UnlockCommercialFeatures -XX:+FlightRecorder 

# 启用JMX
-Dcom.sun.management.jmxremote 
-Dcom.sun.management.jmxremote.port=9899 
-Dcom.sun.management.jmxremote.authenticate=false 
-Dcom.sun.management.jmxremote.ssl=false

使用了上述方式之后依然没有发现异常日志。dump文件也没有导出。所以基本可以断定Agile没有内存溢出。而且如果是程序性能问题引起的java进程崩溃，应该会在某个特定的业务场景下触发，但我们的这个问题只有每周六2点出现，当天重启起来后又一切正常。所以性能问题原因也被排除掉了。

其他程序干扰

这个时候我们开始怀疑Agile进程是不是被其他程序干扰了才异常退出的？
查了服务器上运行的其他程序。用了history，demsg, top -c，uptime等命令搜索，还是一无所获。
还尝试了让客户运维团队停止所有监控软件，但到了周六，问题仍然发生。

重要线索发现

在排查日志时，在/var/log/secure日志里面找到了重要的线索。
每当agile应用进程被异常关闭的同一个时间点都会打印这样一些日志：
session closed for user root这些日志是哪个程序输出的，目前还没人能确定。看英文意思就是root的session被关闭了，这个root应该是linux的用户。
然后我们突然注意到每次到周六要重启agile应用的时候，都会发现xshell被关闭了，要重新连接。
和客户沟通中发现，他们公司的电脑是使用云桌面登录使用的，而且每周六凌晨都会重启。
这个时候我突然想起在另一个项目上遇到的另一个问题，就是只要使用xshell或者其他支持X11 forwarding的ssh客户端启动Agile应用后，只要xshell关闭，agile应用进程就会自动关闭。
怀着这些疑问，我在环境上做了针对性测试，终于找到了这个问题真正原因。

真正原因

如下原因必须同时满足才会发生这个问题。

1. 使用支持X11 forwarding的ssh客户端连接linux并且启动Agile应用进程。
2. 将环境变量DISPLAY指向当前客户端的IP，且没有重置。
3. ssh客户端关闭。关闭的方式有很多种，直接手动关闭或者被其他应用关闭。
   • 在这个案例里面，客户的云桌面每周六凌晨重启时就会关闭XShell
   • 直接手动关闭XShell也会触发这个问题。

解决方案

针对问题原因，只有任意一个原因不满足就不会引发这个问题。也就是说，下面任意方法都能解决此问题。

1. 使用不支持X11 forwarding的ssh客户端连接linux并且启动Agile应用进程。
   • 例如：putty，但需要注意的是，putty也有x11插件。
   • 某些堡垒机自带的ssh工具也不支持X11 forward
2. 使用修改DISPLAY变量的客户端执行 unset DISPLAY
   • 不确定如果在其他客户端上执行unset命令能否解决此问题。
   • 本文案例使用的是相同客户端
3. 前面2个原因都满足，已经用了X11的客户端启动Agile应用，那就要确保客户端的SSH工具要一直开着，不要关闭。

​