一个由网络闪断导致的CICS交易网关异常的案例分享

本文描述了一则因网络问题导致的cics交易中间件异常的处理方法与思路，如有问题欢迎随时交流~
一、问题描述：
10月25日，柜面网关 系统 报ctg报错：
10/25/15 03:16:02.775 [9300] TRN:CCL9126E Required message queue (key 0x3EF2022D) already exists, will not reuse
Teller2:
10/25/15 13:26:02.181 [9300] TRN:CCL9126E Required message queue (key 0xE3EA022D) already exists, will not reuse
二、解决过程：
    1.由于CTG7.2已经过期，无法得到IBM实验室的技术支持。只能先通过自己的经验来进行问题方向性的判断。商业软件有问题，第一反应是上官网搜索相关信息。在官网搜索CCL9126E，可以看到有两个ARPA对这个现象的描述：
下面是CCL9126E产生的原因：
When a client application is terminated, CICS TG does not
delete the IPC queue that is used by the client application to
communicate with the client daemon. This causes the IPC queue
to be left behind. Subsequent client applications that are
allocated to the same process ID find the residual IPC queue
and the reported messages are issued.
升级到7.2.0.5之后，ctg的行为变为：
CICS TG has been changed so that when the client application
terminates, CICS TG deletes the IPC queue used by the client
application to communicate with the client daemon.
我们可以看到CCL9126E便是因为有残留的IPC queue导致。 换句话说，一个pid是 2000的ctg应用程序 由于某些原因退出，当另外一个ctg程序也是PID也是2000时候，便会报上面的错误。另外，7.2.0.5的ctg能够删除残留的IPC queue，而在之前版本,残留IPC queue会导致ctg crash。换句话说，现在的报错不会导致ctg宕机，这样留给我们分析处理问题的时间。
     2.问题现在转换成了为何有IPC queue有残留，另外，能否找到是否还有其他残留的IPC queue。IPC queue有残留,那便牵扯一个问题，谁可能残留下来IPC queue。跟应用开发人员沟通，应用一共有两个适配器和一个监控程序跟ctg相关。
由于适配器程序启动之后，便不会产生新的进程，进程PID保持不变。不会出现“allocated to the same process ID”。因此可以排除适配器的问题。焦点便集中在了监控程序上。跟应用沟通，拿到 监控程序和log日志位置。
当检查10月25日监控程序log，发现：
20151025031602:检查CTG状态开始
CTG状态检查异常:
20151025031602:发送告警消息开始
20151025031603:发送告警消息结束，发送结果：0
20151025031603:检查CTG状态结束
检查监控程序：
outputList=`cicscli -l | grep CCL8042I`
corStatus=`echo "$outputList" | grep -E "(PRDCOR11)|(PRDCOR21)" | grep "is available" | wc | awk '{print $1 }'`
if [ $corStatus -eq 2 ];then
        outputList="CTG状态检查正常:"$LF_CHAR$outputList
        echo "$outputList"
else
        outputList="CTG状态检查异常:"$LF_CHAR$outputList
        echo "$outputList"
        cd $PRGDIR
可以看到是 cicscli -l 执行的结果异常导致报错。这时可以判断应该跟这个监控程序有关。
虽然可能是这个监控程序分配到了相同的PID，导致了报错，但是这里无法判断是 这个监控程序残留下来的IPC queue。问题好像进入到了迷雾之中。
     3.回到起点：为何有IPC queue有残留。这时一条思路是，能否通过操作系统来查看IPC queue的相关信息。
通过ipcs -a 可以看到生产相关message queue信息：
------ Message Queues --------
key        msqid      owner      perms      used-bytes   messages   
0x9102c001 211288064  tlfc       666        0            0          
0x9202c001 211320833  tlfc       666        0            0          
0xb3d2022d 1973125122 tlfc       666        0            0          
0x289a022d 1975517187 tlfc       666        0            0          
0x0b00022d 1974009860 tlfc       666        0            0          
0xef2a022d 1973190662 tlfc       666        0            0          
0x9fea022d 1973288967 tlfc       666        0            0          
0xeb9a022d 1973354504 dcmaint    666        0            0          
0x1706022d 1973420042 tlfc       666        0            0      
满眼的key和msqid，查阅了相关IPC资料，只说产生是通过pid和一个相关算法得到的，至于反推回谁创建的，没有任何资料。
刚出现的思路，又变得迷茫起来。开发的同事提供了一个非常好的思路，能否看谁在操作message queue。
通过ipcs -p
------ Message Queues PIDs --------
msqid      owner      lspid      lrpid    
211288064 tlfc        25741      5866
211320833 tlfc         5865     25741
1973125122 tlfc            0         0
1975517187 tlfc        22582       313
1974009860 tlfc        23019     22582
1973190662 tlfc            0         0
1973288967 tlfc            0         0
1973354504 dcmaint         0         0
1973420042 tlfc            0         0
可以看到 pid不为0的进程都能找到相关进程信息，那lspid和lrpid为0的便是很有可能残留的IPC queue。
但是，这些信息还是不能确认为何有残留。问题再次陷入了僵局。这时一个想法出现：既然ipcs是检查ipc资源的工具，它是否还有别的参数能看一些更有价值的信息。能否在之前的分析道路上走的更深一步。
      4.通过ipcs 的man手册，可以看到 里面有个-t的参数，
ipcs -q -t
------ Message Queues Send/Recv/Change Times --------
msqid    owner      send                 recv                 change             
211288064 tlfc       Oct 28 10:42:08      Oct 28 10:42:08      Sep 29 02:18:40    
211320833 tlfc       Oct 28 10:42:08      Oct 28 10:42:08      Sep 29 02:18:40    
1973125122 tlfc       Not set              Not set              Sep 23 16:38:05    
1975517187 tlfc       Oct 28 10:42:08      Oct 28 10:42:08      Oct 23 23:24:42    
1974009860 tlfc       Oct 28 10:42:08      Oct 28 10:42:08      Oct 23 23:04:01    
1973190662 tlfc       Not set              Not set              Sep 23 16:42:04    
1973288967 tlfc       Not set              Not set              Sep 23 16:44:04    
1973354504 dcmaint    Not set              Not set              Sep 23 16:45:40    
1973420042 tlfc       Not set              Not set              Sep 23 16:48:04 
9月23日，这是一个出现问题的时间点，那天网络瞬断导致ctg挂起.看到这些残留的ipc queue的信息，想到9月23日ctg挂起的时候，检查ctg状态，当时用cicscli -l命令都挂在那里。那root cause可能便是当时监控进程中cicscli也挂起了，后来清理掉了这些进程，但是IPC资源未释放。
所有的线索都联系起来了。
      5.找测试人员和开发人员，在准生产模拟断开的测试，让ctg挂起。然后等监控程序运行一段时间，发现进程里面确实有cicscli -l进程挂起。kill掉挂起的进程。发现IPC queue有残留，至此问题真相解开了。
三、问题总结
9月23日，网络瞬断，导致ctg挂起，因此监控程序里面的cicscli -l命令也被挂起，当挂起的cicscli -l命令被kill掉之后，这个进程原来拥有的IPC queue便残留了下来了。由于PID是系统随机分配的，所以，平时很难有pid相同的现象出现，但是由于监控程序每隔两分钟调用一次cicscli -l，一天便有720次的调用机会，10天便有7200次调用。在这种频率下，很有可能导致pid一样。
四、解决方案
使用ipcrm -q msqid 的方式，可以将残留的message queue删除掉。
当遇到思路走不下去的时候，可以换个角度和思路去看一下，也许换个思路，问题的解决便会变得简单一些。