且构网

分享程序员开发的那些事...
且构网 - 分享程序员编程开发的那些事

EM agent无法启动的原因及分析

更新时间:2022-09-02 10:09:30

昨天收到一条报警短信,短信内容大体如下:
Agent is Unreachable(REASON=javax.net.ssl.SSLPeerUnverifiedException:xxxx.com:cn=xxxxx).Host is unreachable.
看着短信内容,应该是agent罢工了。可能出现了网络问题。
结果不一会儿就接到了同事的电话,让我看看是不是有问题。
登录到agent所在的服务器,查看agent进程还是存在的。
这个时候尝试agent的upload操作失败,就准备重新启动一下agent试试,但是尝试重启的时候报了下面的错误。
$ ./emctl start agent
Oracle Enterprise Manager 10g Release 5 Grid Control 10.2.0.5.0.  
Copyright (c) 1996, 2009 Oracle Corporation.  All rights reserved.
Starting agent ....... failed.
Failed to start HTTP listener.
Consult the log files in: /U01/app/oracle/product/agent10g/sysman/log

在指定的目录下查看日志,里面提示进程自动退出,也没有给出很明确的信息来
41921 :: Wed Sep 30 09:07:34 2015::AgentLifeCycle.pm: Exited loop with retCode=1
9380 :: Wed Sep 30 10:06:27 2015::AgentLifeCycle.pm: Processing status agent
9380 :: Wed Sep 30 10:06:27 2015::AgentStatus.pm:Processing status agent
9380 :: Wed Sep 30 10:06:27 2015::AgentStatus.pm:emdctl status returned 1
22086 :: Wed Sep 30 11:06:50 2015::AgentLifeCycle.pm: Processing status agent
22086 :: Wed Sep 30 11:06:50 2015::AgentStatus.pm:Processing status agent
22086 :: Wed Sep 30 11:06:50 2015::AgentStatus.pm:emdctl status returned 1
861 :: Wed Sep 30 11:40:27 2015::AgentLifeCycle.pm: Processing start agent
861 :: Wed Sep 30 11:40:27 2015::AgentLifeCycle.pm: EMHOME is /U01/app/oracle/product/agent10g 
861 :: Wed Sep 30 11:40:27 2015::AgentLifeCycle.pm: service name is  
861 :: Wed Sep 30 11:40:28 2015::AgentLifeCycle.pm:status agent returned with retCode=1
861 :: Wed Sep 30 11:40:32 2015::AgentLifeCycle.pm:Watch dog processs id: 906 exited with an exit code of 55
861 :: Wed Sep 30 11:40:32 2015::AgentLifeCycle.pm: Exited loop with retCode=1

查看历史日志,发现这个agent已经已经很久没有使用了,可能这个问题还没有想象的那么简单。算是个遗留问题吧。
----- Sat Jun 27 15:09:49 2015::Checking status of EMAgent : 24232 -----
-- Timestamp (2014,07,01,14,53,38) of file /U01/app/oracle/product/agent10g/sysman/emd/upload/rawdata4.dat is more than 24 hours old. Current Time is Sat Jun 27 15:09:
52 2015----- Sat Jun 27 15:09:52 2015::Received restart request from EMAgent : 24232 -----
----- Sat Jun 27 15:09:52 2015::Stopping EMAgent : 24232 -----
----- Sat Jun 27 15:10:02 2015::Failed to reap child process EMAgent : 24232 -----
----- Sat Jun 27 15:10:02 2015::Agent Launched with PID 20174 at time Sat Jun 27 15:10:02 2015 -----
----- Sat Jun 27 15:10:02 2015::Execing EMAgent process is taking longer than expected 120 secs. -----
----- Sat Jun 27 15:10:02 2015::Time elapsed between Launch of Watchdog process and execing EMAgent is 15996749 secs -----
(pid=20174): starting emagent version 10.2.0.5.0
(pid=20174): emagent now exiting abnormally - initialization failure. Consult '.trc' and '.log' files.
----- Sat Jun 27 15:10:05 2015::Checking status of EMAgent : 20174 -----
----- Sat Jun 27 15:10:05 2015::EMAgent exited at Sat Jun 27 15:10:05 2015 with return value 55. -----
----- Sat Jun 27 15:10:05 2015::EMAgent has exited due to initialization failure. -----
----- Sat Jun 27 15:10:05 2015::Stopping other components. -----
----- Sat Jun 27 15:10:05 2015::Commiting Process death. -----
----- Sat Jun 27 15:10:05 2015::Exiting watchdog loop
查看最近的日志
 --- Standalone agent
----- Wed Sep 30 11:44:40 2015::Agent Launched with PID 3354 at time Wed Sep 30 11:44:40 2015 -----
----- Wed Sep 30 11:44:40 2015::Time elapsed between Launch of Watchdog process and execing EMAgent is 0 secs -----
(pid=3354): starting emagent version 10.2.0.5.0
(pid=3354): emagent now exiting abnormally - initialization failure. Consult '.trc' and '.log' files.
----- Wed Sep 30 11:44:43 2015::Checking status of EMAgent : 3354 -----
----- Wed Sep 30 11:44:43 2015::EMAgent exited at Wed Sep 30 11:44:43 2015 with return value 55. -----
----- Wed Sep 30 11:44:43 2015::EMAgent has exited due to initialization failure. -----
----- Wed Sep 30 11:44:43 2015::Stopping other components. -----
----- Wed Sep 30 11:44:43 2015::Commiting Process death. -----
----- Wed Sep 30 11:44:43 2015::Exiting watchdog loop
 -----
 --- Standalone agent
----- Wed Sep 30 11:51:57 2015::Agent Launched with PID 6076 at time Wed Sep 30 11:51:57 2015 -----
----- Wed Sep 30 11:51:57 2015::Time elapsed between Launch of Watchdog process and execing EMAgent is 1 secs -----
(pid=6076): starting emagent version 10.2.0.5.0
(pid=6076): emagent now exiting abnormally - initialization failure. Consult '.trc' and '.log' files.
----- Wed Sep 30 11:52:00 2015::Checking status of EMAgent : 6076 -----
----- Wed Sep 30 11:52:00 2015::EMAgent exited at Wed Sep 30 11:52:00 2015 with return value 55. -----
----- Wed Sep 30 11:52:00 2015::EMAgent has exited due to initialization failure. -----
----- Wed Sep 30 11:52:00 2015::Stopping other components. -----
----- Wed Sep 30 11:52:00 2015::Commiting Process death. -----
----- Wed Sep 30 11:52:00 2015::Exiting watchdog loop

查看其它相关的日志,发现了这么一段内容。
2015-09-30 13:53:08,557 Thread-37161840 ERROR engine: [oracle_emd,sadb.com:3872,EMDUploadStats] : nmeegd_GetMetricData failed : em_error=failed to get upload statistics: Inappropriate ioctl for device
Error connecting to https://sadbcom:3872/emd/main/

2015-09-30 13:53:08,557 Thread-37161840 WARN  collector: <nmecmc.c> Error exit. Error message: em_error=failed to get upload statistics: Inappropriate ioctl for device
Error connecting to https://sadb.cyou.com:3872/emd/main/
这部分日志算是唯一能够看明白,而且相关的了。那么到底是怎么回事,为什么尝试连接的时候出错了?
排查了EM sever段的网络连接情况,是没有问题的。
那么我们还是按部就班来看看这个地址为什么不通。试试老办法ping
# ping sadb.com
PING sadb.com (10.127.xxx.34) 56(84) bytes of data.
64 bytes from sadb.cyou.com (10.127.xxx.34): icmp_seq=1 ttl=64 time=0.185 ms
64 bytes from sadb.cyou.com (10.127.xxx.34): icmp_seq=2 ttl=64 time=0.182 ms
查看网卡配置的IP情况
# ifconfig
eth0      Link encap:Ethernet  HWaddr C8:1F:66:B8:97:xxxx  
          inet addr:10.127.xxx.71  Bcast:10.127.xxx.255  Mask:255.255.255.0
          inet6 addr: fe80::ca1f:66ff:feb8:975a/64 Scope:Link
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:7609183417 errors:0 dropped:0 overruns:0 frame:0
          TX packets:6700541034 errors:0 dropped:162 overruns:0 carrier:0
          collisions:0 txqueuelen:1000 
          RX bytes:957747424255 (891.9 GiB)  TX bytes:1573971126949 (1.4 TiB)
          Interrupt:35 
这个时候就有些奇怪了,ping的主机名应该是本机,怎么ping出来的IP不同了。
看看配置文件里怎么写的。
# cat /etc/hosts
#127.0.0.1   localhost localhost.localdomain localhost4 localhost4.localdomain4
#::1         localhost localhost.localdomain localhost6 localhost6.localdomain6
10.11.154.95 xxx.no.xxxxx.com
10.127.xxxx.34 sadb.com
127.0.0.1               localhost localhost.localdomain localhost
::1             localhost6.localdomain6 localhost6
10.127.xxx.134   adb.com
10.127.xxx.88   sadb3.com
10.127.2.128    sadb2.com
10.127.xxx.71  sadb.com
10.127.2.85 newcomm.com
10.25.36.117  xxx.no.xxx.com
这段内容还是蛮考验眼力的。
如果眼尖还是会发现配置上有问题,那就是adb.com出现了两个IP,一个是xxx.34 一个是xxx.71
这个错误还是一个很常规的错误,但是结合具体的问题分析就很容易被误导。
再次尝试ping就会发现IP地址已经指向了正确的地址了。
# ping sadb.cyou.com
PING sadb.com (10.127.xxx.71) 56(84) bytes of data.
64 bytes from sadb.com (10.127.xxx.71): icmp_seq=1 ttl=64 time=0.026 ms
这个时候再没有尝试启动,只是做了一个简单验证,发现upload已经没有问题了。
$ ./emctl status agent
Oracle Enterprise Manager 10g Release 5 Grid Control 10.2.0.5.0.  
Copyright (c) 1996, 2009 Oracle Corporation.  All rights reserved.
---------------------------------------------------------------
Agent Version     : 10.2.0.5.0
OMS Version       : 10.2.0.5.0
Protocol Version  : 10.2.0.5.0
Agent Home        : /U01/app/oracle/product/agent10g
Agent binaries    : /U01/app/oracle/product/agent10g
Agent Process ID  : 24232
Parent Process ID : 39174
Agent URL         : https://sadb.com:3872/emd/main/
Repository URL    : https://emserver.com:1159/em/upload
Started at        : 2015-06-27 13:09:43
Started by user   : oracle
Last Reload       : 2015-06-27 13:09:43
Last successful upload                       : 2015-09-30 14:08:02
Total Megabytes of XML files uploaded so far :   897.22
Number of XML files pending upload           :        0
Size of XML files pending upload(MB)         :     0.00
Available disk space on upload filesystem    :    72.83%
Last successful heartbeat to OMS             : 2015-09-30 08:17:43
---------------------------------------------------------------
Agent is Running and Ready
明白了问题的原因,其实发现还是一个蛮低级的错误,但是为什么会出现这种情况呢,还是因为做了故障转移,主备进行了切换,结果/etc/hosts里面的信息知识做了追加。
所以这些潜在的问题细小,但是出现问题的时候又很容易被误导。尤其需要注意一下。