昨天收到一条报警短信,短信内容大体如下:
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
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里面的信息知识做了追加。
所以这些潜在的问题细小,但是出现问题的时候又很容易被误导。尤其需要注意一下。
所以这些潜在的问题细小,但是出现问题的时候又很容易被误导。尤其需要注意一下。
来自 “ ITPUB博客 ” ,链接:http://blog.itpub.net/23718752/viewspace-1813099/,如需转载,请注明出处,否则将追究法律责任。
转载于:http://blog.itpub.net/23718752/viewspace-1813099/