(Scouter-CounterExecutingManager) javax.management.InstanceNotFoundException 오류 문의

[wasgosu]

안녕하세요~ 매번 도움 많이 받고 있습니다.

이번 오류는 scouter agent가 설치된 서버에서 발생되는 에러 로그인데..
사용량이 많을 때 발생을 합니다.
근데 해당 에러 로그가 왜 발생하는지 원인을 모르겠어서요.. 원인만 알면 해결할 수 있을 것 같은데..
아래 로그는 어떨때 발생을 하나요?
혹.. 비슷한 에러를 보신적이 있으신가요? 사용하는 agent version이 좀 되서 버그인가 싶기도 해서요.

1. Scouter agent version 0.4.22 입니다.
2. 해당 로그는 jboss-eap 인스턴스의 server.log 에서 복사했습니다.
3. 현상을 확인해보니 주말에는 사용을 안하는 장비가 에러발생은 안됩니다.

에러 로그

ERROR [stderr] (Scouter-CounterExecutingManager) javax.management.InstanceNotFoundException: jboss.as.expr:subsystem=datasources,data-source=MallDS,statistics=pool
121 09:46:00,081 ERROR [stderr] (Scouter-CounterExecutingManager) at org.jboss.as.jmx.PluggableMBeanServerImpl.findDelegate(PluggableMBeanServerImpl.java:1083)
122 09:46:00,081 ERROR [stderr] (Scouter-CounterExecutingManager) at org.jboss.as.jmx.PluggableMBeanServerImpl.getAttribute(PluggableMBeanServerImpl.java:378)
123 09:46:00,082 ERROR [stderr] (Scouter-CounterExecutingManager) at scouter.agent.counter.task.JBossJMXPerf.process(JBossJMXPerf.java:129)
124 09:46:00,082 ERROR [stderr] (Scouter-CounterExecutingManager) at sun.reflect.GeneratedMethodAccessor31.invoke(Unknown Source)
125 09:46:00,082 ERROR [stderr] (Scouter-CounterExecutingManager) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
126 09:46:00,082 ERROR [stderr] (Scouter-CounterExecutingManager) at java.lang.reflect.Method.invoke(Method.java:606)
127 09:46:00,083 ERROR [stderr] (Scouter-CounterExecutingManager) at scouter.agent.counter.CounterExecutingManager$Invocation.process(CounterExecutingManager.java:92)
128 09:46:00,083 ERROR [stderr] (Scouter-CounterExecutingManager) at scouter.agent.counter.CounterExecutingManager.run(CounterExecutingManager.java:57)

[gaiajeon]

로그 메시지는 scouter가 JBOSS의 DataSource 성능 정보를 JMX를 통해 수집할때 발생하는 메시지인데요.
jmx로 "jboss.as.expr:subsystem=datasources,data-source=MallDS,statistics=pool" 검색했을때 해당 mbean을 찾을 수 없다고 하는 메시지입니다. 혹시 MailDS는 사용하고 계신 데이터 소스인지 확인해주세요. 만약 사용하고 있다면 JBOSS의 버젼을 알려주세요.

[gaiajeon]

https://issues.jboss.org/browse/JBEAP-13845

위 URL이 뭔가 답을 알려주는 것 같은데요.
JBOSS에 한해서 문제가 발생한 것 같구요.
위 링크에서 잘 설명해주고 있지만 간단히 정리하자면
If enabled RBAC, InstanceNotFoundException is thrown when getting jboss.as and jboss.as.expr MBeans from application on EAP.
==> The exeption can be occurred by getting mbeans via MBeanServer as in-vm access
==> If connect via JMXConnectorFactory , the mbeans can be gotten.
이라고 되어 있습니다.

[wasgosu]

리얼은 jennifer로 구성해서 사용중이고, Staging, QA는 scouter 를 구성해서 사용하고 있습니다.
해당 오류가 발생되고 있는 버전은 jboss-eap-6.3 상용 버전과, wildfly-13.0.0.Final 오픈소스 버전 둘다 발생되고 있습니다. 알려주신 RBAC 기능은 확인해보니 default 는 OFF되있는 기능이네요..
저는 RBAC기능을 사용하지 않습니다..
scouter가 JBOSS의 DataSource 성능 정보를 JMX를 통해 수집할때 불필요한 에러 로그를 발생시키는것 같은 생각이 좀 듭니다.. jennifer 나 jmx mbean으로 호출했던 다른 APM은 db 정보 조회할때 발생되지 않는 에러인데..
MailDS는 연동해서 사용하고 있는 DB 이름 맞습니다..

저도 좀 더 고민해볼께요..
흐음~ 해당 로그가 발생될때 어떤 행위를 했을때 발생되는지 파악후 범위를 좁혀 나가야 할 것 같습니다.

[wasgosu]

범위를 좁혀봤습니다.

1. shutdown 할때 발생되는 ERROR 입니다.
2. 기동중이거나 기동할때 발생은 안됩니다.
3. 아래 log 에서 보면 wildfly 에서 Unbound data source [java:jboss/MailSendDS] 한뒤 shutdown이 정상적으로 되는데 그 이후 scouter 에서 db 정보를 불러오지 못해서 발생되는 에러 같습니다.
   여기서 궁금한건.. shutdown이 된 후... scouter 에서jmx db정보를 연결하려고 해서 에러가 났을가요..?
   shutdown 되면 모두 끝나냐 할텐데.. 이부분이 궁금하네요 ㅎㅎ

2018-08-02 10:13:40,979 INFO [org.jboss.as.connector.deployers.jdbc] (MSC service thread 1-1) WFLYJCA0019: Stopped Driver service with driver-name = Mobile.war_org.postgresql.Driver_9_2
2018-08-02 10:13:41,005 INFO [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-6) WFLYJCA0010: Unbound data source [java:jboss/CCILinkDS]
2018-08-02 10:13:41,005 INFO [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-3) WFLYJCA0010: Unbound data source [java:jboss/MailSendDS]
2018-08-02 10:13:41,005 INFO [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-3) WFLYJCA0010: Unbound data source [java:jboss/ForDBlink]
2018-08-02 10:13:41,005 INFO [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-5) WFLYJCA0010: Unbound data source [java:jboss/FrameOneDS]
2018-08-02 10:13:41,038 INFO [org.wildfly.extension.undertow] (MSC service thread 1-5) WFLYUT0008: Undertow HTTPS listener https suspending
2018-08-02 10:13:41,052 INFO [org.wildfly.extension.undertow] (MSC service thread 1-5) WFLYUT0007: Undertow HTTPS listener https stopped, was bound to 0.0.0.0:8543
2018-08-02 10:13:41,062 INFO [org.wildfly.extension.undertow] (ServerService Thread Pool -- 75) WFLYUT0022: Unregistered web context: '/' from server 'default-server'
2018-08-02 10:13:41,233 INFO [io.undertow.servlet] (ServerService Thread Pool -- 75) Destroying Spring FrameworkServlet 'dispatcher'
2018-08-02 10:13:41,932 INFO [io.undertow.servlet] (ServerService Thread Pool -- 75) Closing Spring root WebApplicationContext
2018-08-02 10:13:42,162 ERROR [stderr] (Scouter-CounterExecutingManager) javax.management.InstanceNotFoundException: jboss.as.expr:subsystem=datasources,data-source=FrameOneDS,statistics=pool
2018-08-02 10:13:42,184 ERROR [stderr] (Scouter-CounterExecutingManager) at org.jboss.as.jmx.PluggableMBeanServerImpl.findDelegate(PluggableMBeanServerImpl.java:1110)
2018-08-02 10:13:42,184 ERROR [stderr] (Scouter-CounterExecutingManager) at org.jboss.as.jmx.PluggableMBeanServerImpl.getAttribute(PluggableMBeanServerImpl.java:386)
2018-08-02 10:13:42,184 ERROR [stderr] (Scouter-CounterExecutingManager) at scouter.agent.counter.task.JBossJMXPerf.process(JBossJMXPerf.java:129)
2018-08-02 10:13:42,184 ERROR [stderr] (Scouter-CounterExecutingManager) at sun.reflect.GeneratedMethodAccessor33.invoke(Unknown Source)
2018-08-02 10:13:42,184 ERROR [stderr] (Scouter-CounterExecutingManager) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2018-08-02 10:13:42,185 ERROR [stderr] (Scouter-CounterExecutingManager) at java.lang.reflect.Method.invoke(Method.java:498)
2018-08-02 10:13:42,185 ERROR [stderr] (Scouter-CounterExecutingManager) at scouter.agent.counter.CounterExecutingManager$Invocation.process(CounterExecutingManager.java:92)
2018-08-02 10:13:42,185 ERROR [stderr] (Scouter-CounterExecutingManager) at scouter.agent.counter.CounterExecutingManager.run(CounterExecutingManager.java:57)
2018-08-02 10:13:42,185 ERROR [stderr] (Scouter-CounterExecutingManager) javax.management.InstanceNotFoundException: jboss.as.expr:subsystem=datasources,data-source=FrameOneDS,statistics=pool
2018-08-02 10:13:42,185 ERROR [stderr] (Scouter-CounterExecutingManager) at org.jboss.as.jmx.PluggableMBeanServerImpl.findDelegate(PluggableMBeanServerImpl.java:1110)
2018-08-02 10:13:42,185 ERROR [stderr] (Scouter-CounterExecutingManager) at org.jboss.as.jmx.PluggableMBeanServerImpl.getAttribute(PluggableMBeanServerImpl.java:386)
2018-08-02 10:13:42,185 ERROR [stderr] (Scouter-CounterExecutingManager) at scouter.agent.counter.task.JBossJMXPerf.process(JBossJMXPerf.java:129)
2018-08-02 10:13:42,185 ERROR [stderr] (Scouter-CounterExecutingManager) at sun.reflect.GeneratedMethodAccessor33.invoke(Unknown Source)
2018-08-02 10:13:42,185 ERROR [stderr] (Scouter-CounterExecutingManager) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2018-08-02 10:13:42,185 ERROR [stderr] (Scouter-CounterExecutingManager) at java.lang.reflect.Method.invoke(Method.java:498)
2018-08-02 10:13:42,185 ERROR [stderr] (Scouter-CounterExecutingManager) at scouter.agent.counter.CounterExecutingManager$Invocation.process(CounterExecutingManager.java:92)
2018-08-02 10:13:42,185 ERROR [stderr] (Scouter-CounterExecutingManager) at scouter.agent.counter.CounterExecutingManager.run(CounterExecutingManager.java:57)
2018-08-02 10:13:42,186 ERROR [stderr] (Scouter-CounterExecutingManager) javax.management.InstanceNotFoundException: jboss.as:subsystem=datasources,data-source=MailSendDS,statistics=pool
2018-08-02 10:13:42,186 ERROR [stderr] (Scouter-CounterExecutingManager) at org.jboss.as.jmx.PluggableMBeanServerImpl.findDelegate(PluggableMBeanServerImpl.java:1110)
2018-08-02 10:13:42,186 ERROR [stderr] (Scouter-CounterExecutingManager) at org.jboss.as.jmx.PluggableMBeanServerImpl.getAttribute(PluggableMBeanServerImpl.java:386)
2018-08-02 10:13:42,186 ERROR [stderr] (Scouter-CounterExecutingManager) at scouter.agent.counter.task.JBossJMXPerf.process(JBossJMXPerf.java:129)

[gaiajeon]

아 그렇다면 셧다운 된 상태에서 성능을 수집하는 CounterExecutingManager 쓰레드가 한번 더 동작을 한거 같습니다. 그리곤 성능 수집 쓰레드가 종료되었을거라 보입니다. 매 DS마다 한번 이상 해당 로그가 나타나나요..? 한번 만 나타난다면 수집 쓰레드가 DS 셧다운보다 늦게 종료해서 발생하는 것으로 보입니다.

[wasgosu]

그렇겠네요~
셧다운시 DS 마다 한번만 발생합니다.
원인을 알았네요~ 추가 릴리즈 될때 해당 부분 조치 가능해지면 더 좋을 것 같습니다~^^

[gaiajeon]

코드를 살펴보니 예외 발생 시 printStaceTrace()가 호출되도록 되어 있네요.
코드를 뺄수는 있겠습니다만.
위의 예외로그가 사실 운영상의 문제가 되는 부분은 아니라서 크게 문제되진 않아 보입니다.
심각한 예외 발생 시 분석을 위해 놔두신 것 같기도 하구요.
운영자들은 이런 에러메시지를 보면 문제가 있다가 오해할 수도 있긴 합니다.
옵션등을 이용해 printStaceTrace를 막는 것도 방법일 듯 합니다.