search

jmxtrans / jmxtrans-agent

Java Agent based JMX metrics exporter.
MIT License
178 stars 110 forks source link

Problem with springboot java and jmxtrans-agent #111

Open maogouste opened 6 years ago

maogouste commented 6 years ago

Hello,

I'm trying to add jmxtrans-agent to internal java with springboot application.

It's started with : 

/opt/jdk1.8/bin/java -javaagent:/servers/jmxtrans-agent/jmxtrans-agent.jar=/servers/jmxtrans-agent/jmxtrans-agent.xml -Dinfluxdb_instance=dots-server_01 -Dorg.jmxtrans.agent.JmxTransAgent.diagnostic=true -Dorg.jmxtrans.agent.util.logging.Logger.level=TRACE -Djavax.net.ssl.trustStore=/etc/digiplug/cacerts -Djavax.net.ssl.trustStorePassword=changeit -jar /servers/dgpapps/dots/dots-server.jar --slot.id=01

It correctly generates some point and finishes with a stack : 

sept. 19 16:27:56  java[79309]: 2017-09-19 16:27:56.965 WARNING [jmxtrans-agent-1] org.jmxtrans.agent.JmxTransExporter - Ignore exception flushing metrics
sept. 19 16:27:56  java[79309]: java.net.SocketTimeoutException: Connect timed out
sept. 19 16:27:56  java[79309]: at java.net.SocksSocketImpl.readSocksReply(SocksSocketImpl.java:126)
sept. 19 16:27:56  java[79309]: at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:502)
sept. 19 16:27:56  java[79309]: at java.net.Socket.connect(Socket.java:589)
sept. 19 16:27:56  java[79309]: at sun.net.NetworkClient.doConnect(NetworkClient.java:175)
sept. 19 16:27:56  java[79309]: at sun.net.www.http.HttpClient.openServer(HttpClient.java:463)
sept. 19 16:27:56  java[79309]: at sun.net.www.http.HttpClient.openServer(HttpClient.java:558)
sept. 19 16:27:56  java[79309]: at sun.net.www.http.HttpClient.<init>(HttpClient.java:242)
sept. 19 16:27:56  java[79309]: at sun.net.www.http.HttpClient.New(HttpClient.java:339)
sept. 19 16:27:56  java[79309]: at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1209)
sept. 19 16:27:56  java[79309]: at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1157)
sept. 19 16:27:56  java[79309]: at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1032)
sept. 19 16:27:56  java[79309]: at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:966)
sept. 19 16:27:56  java[79309]: at sun.net.www.protocol.http.HttpURLConnection.getOutputStream0(HttpURLConnection.java:1316)
sept. 19 16:27:56  java[79309]: at sun.net.www.protocol.http.HttpURLConnection.getOutputStream(HttpURLConnection.java:1291)
sept. 19 16:27:56  java[79309]: at org.jmxtrans.agent.influxdb.InfluxDbOutputWriter.writeMetrics(InfluxDbOutputWriter.java:192)
sept. 19 16:27:56  java[79309]: at org.jmxtrans.agent.influxdb.InfluxDbOutputWriter.sendMetrics(InfluxDbOutputWriter.java:160)
sept. 19 16:27:56  java[79309]: at org.jmxtrans.agent.influxdb.InfluxDbOutputWriter.sendMetrics(InfluxDbOutputWriter.java:153)
sept. 19 16:27:56  java[79309]: at org.jmxtrans.agent.influxdb.InfluxDbOutputWriter.postCollect(InfluxDbOutputWriter.java:147)
sept. 19 16:27:56  java[79309]: at org.jmxtrans.agent.OutputWriterCircuitBreakerDecorator.postCollect(OutputWriterCircuitBreakerDecorator.java:124)
sept. 19 16:27:56  java[79309]: at org.jmxtrans.agent.OutputWritersChain.postCollect(OutputWritersChain.java:70)
sept. 19 16:27:56  java[79309]: at org.jmxtrans.agent.JmxTransExporter.collectAndExport(JmxTransExporter.java:214)
sept. 19 16:27:56  java[79309]: at org.jmxtrans.agent.JmxTransExporter$2.run(JmxTransExporter.java:131)
sept. 19 16:27:56  java[79309]: at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
sept. 19 16:27:56  java[79309]: at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
sept. 19 16:27:56  java[79309]: at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
sept. 19 16:27:56  java[79309]: at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
sept. 19 16:27:56  java[79309]: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
sept. 19 16:27:56  java[79309]: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
sept. 19 16:27:56  java[79309]: at java.lang.Thread.run(Thread.java:748)

My xml : 

<?xml version="1.0" encoding="UTF-8"?>
<jmxtrans-agent>
    <queries>
        <query objectName="java.lang:type=Threading"               attributes="DaemonThreadCount,ThreadCount,PeakThreadCount" resultAlias="#attribute#" />
        <query objectName="java.lang:type=Runtime"                 attribute="Uptime"                                         resultAlias="Uptime" />
        <query objectName="java.lang:type=OperatingSystem"         attributes="OpenFileDescriptorCount,ProcessCpuTime"        resultAlias="#attribute#" />
        <query objectName="java.lang:type=ClassLoading"            attribute="LoadedClassCount"                               resultAlias="LoadedClassCount" />
        <query objectName="java.lang:type=Compilation"             attribute="TotalCompilationTime"                           resultAlias="TotalCompilationTime" />
        <query objectName="java.lang:type=GarbageCollector,name=*" attributes="CollectionCount,CollectionTime"                resultAlias="%name%.#attribute#" />
        <query objectName="java.lang:type=Memory"                  attributes="HeapMemoryUsage,NonHeapMemoryUsage"            resultAlias="#attribute#.#key#" />
        <query objectName="java.lang:type=MemoryPool,name=*"       attributes="Usage,PeakUsage"                               resultAlias="%name%.#attribute#.#key#" />

        <query objectName="Catalina:type=GlobalRequestProcessor,name=*" attributes="bytesReceived,bytesSent,requestCount,processingTime" resultAlias="%name%.#attribute#" />
        <query objectName="Catalina:type=RequestProcessor,name=*"       attributes="bytesReceived,bytesSent,requestCount,processingTime" resultAlias="%name%.#attribute#" />
        <query objectName="Catalina:type=ThreadPool,name=*"             attribute="currentThreadCount,currentThreadsBusy"                resultAlias="%name%.#attribute#" />
        <query objectName="Catalina:type=Manager,context=*,host=*"  attribute="activeSessions"                           resultAlias="activeSessions" />
    </queries>

    <outputWriter class="org.jmxtrans.agent.influxdb.InfluxDbOutputWriter">
        <url>http://xx.yy.zz.aa:8086</url>
        <database>java_db</database>
        <tags>host=#hostname#,instance=${influxdb_instance}</tags>
        <reloadConfigurationCheckIntervalInSeconds>60</reloadConfigurationCheckIntervalInSeconds>
        <connectTimeoutMillis>3000</connectTimeoutMillis>
        <readTimeoutMillis>5000</readTimeoutMillis>
    </outputWriter>

    <outputWriter class="org.jmxtrans.agent.ConsoleOutputWriter">
        <enabled>false</enabled>
    </outputWriter>

    <collectIntervalInSeconds>10</collectIntervalInSeconds>

</jmxtrans-agent>

On the same server, I have a logstash that export correctly with the same xml and jar. I can graph it.

I see the "Ignore exception flushing metrics" exception at https://github.com/jmxtrans/jmxtrans-agent/blob/master/src/main/java/org/jmxtrans/agent/JmxTransExporter.java

But, I have no idea what it may mean.

I tried to debug by myself, but couldn't progress further.

Gerard.

cyrille-leclerc commented 6 years ago

The HTTP connection from jmxtrans-agent embedded in your spring boot app to influxdb fails with a socket timeout ("SocketTimeoutException: Connect timed out").

You are likely to have a firewall issue between the springboot server and the influxdb server.

Could you try a curl http://xx.yy.zz.aa:8086 from the springboot server to verify that the network connectivity to the influxdb server is opened?

maogouste commented 6 years ago

I thank you for your fast answer.

A curl from the server produces data.

curl -G 'http://xx.yy.yy.aa:8086/query?pretty=true' --data-urlencode "db=java_db" --data-urlencode "q=SELECT mean(\"value\") AS \"mean_value\" FROM \"java_db\".\"autogen\".\"ThreadCount\" WHERE time > now() - 5m AND \"host\"='' AND \"instance\"='logstash' GROUP BY time(10s)"

retrieves : 

{
    "results": [
        {
            "statement_id": 0,
            "series": [
                {
                    "name": "ThreadCount",
                    "columns": [
                        "time",
                        "mean_value"
                    ],
                    "values": [
                        [
                            "2017-09-20T08:26:40Z",
                            54
                        ],
...snip...
                            54
                        ],
                        [
                            "2017-09-20T08:31:40Z",
                            null
                        ]
                    ]
                }
            ]
        }
    ]
}

Furthermore, on the same server, a logstash is tooled the same way with the same jmxtrans-agent jar and xml without problem

But, it succesfully generates some data points before failing in stack.

it looks like something is interfering with the normal action of jmxtrans-agent.

kerlandsson commented 6 years ago

That error should not stop the reporting, it is just a warning, and as it says in the message, it should be ignored. What is logged after the error? You mention that the reporting finishes, could you elaborate on that?

On Wed, Sep 20, 2017 at 10:41 AM, maogouste notifications@github.com wrote:

I thank you for your fast answer.

A curl from the server produces data.

curl -G 'http://xx.yy.yy.aa:8086/query?pretty=true' --data-urlencode "db=java_db" --data-urlencode "q=SELECT mean("value") AS "mean_value" FROM "java_db"."autogen"."ThreadCount" WHERE time > now() - 5m AND "host"='' AND "instance"='logstash' GROUP BY time(10s)"

retrieves :

{ "results": [ { "statement_id": 0, "series": [ { "name": "ThreadCount", "columns": [ "time", "mean_value" ], "values": [ [ "2017-09-20T08:26:40Z", 54 ],

54 ], [ "2017-09-20T08:31:40Z", null ] ] } ] } ] }

Furthermore, on the same server, a logstash is tooled the same way with the same jmxtrans-agent jar and xml without problem

But, it succesfully generates some data points before failing in stack.

it looks like something is interfering with the normal action of jmxtrans-agent.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/jmxtrans/jmxtrans-agent/issues/111#issuecomment-330785877, or mute the thread https://github.com/notifications/unsubscribe-auth/AD-iaagYjU5Pc62iffbZNrAntJ43krDvks5skM_LgaJpZM4Pcfrx .

maogouste commented 6 years ago

That error should not stop the reporting, it is just a warning, and as it says in the message, it should be ignored.

What is logged after the error?

Nothing is logged after the error. But the ConsoleOutputWriter keep on producing data.

You mention that the reporting finishes, could you elaborate on that?

Influxdb have one point at the start of the java. And nothing.

2017-09-20 10:01 GMT+01:00 Kristoffer Erlandsson notifications@github.com:

That error should not stop the reporting, it is just a warning, and as it says in the message, it should be ignored. What is logged after the error? You mention that the reporting finishes, could you elaborate on that?

On Wed, Sep 20, 2017 at 10:41 AM, maogouste notifications@github.com wrote:

I thank you for your fast answer.

A curl from the server produces data.

curl -G 'http://xx.yy.yy.aa:8086/query?pretty=true' --data-urlencode "db=java_db" --data-urlencode "q=SELECT mean("value") AS "mean_value" FROM "java_db"."autogen"."ThreadCount" WHERE time > now() - 5m AND "host"='' AND "instance"='logstash' GROUP BY time(10s)"

retrieves :

{ "results": [ { "statement_id": 0, "series": [ { "name": "ThreadCount", "columns": [ "time", "mean_value" ], "values": [ [ "2017-09-20T08:26:40Z", 54 ],

54 ], [ "2017-09-20T08:31:40Z", null ] ] } ] } ] }

Furthermore, on the same server, a logstash is tooled the same way with the same jmxtrans-agent jar and xml without problem

But, it succesfully generates some data points before failing in stack.

it looks like something is interfering with the normal action of jmxtrans-agent.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/jmxtrans/jmxtrans-agent/issues/111# issuecomment-330785877, or mute the thread https://github.com/notifications/unsubscribe-auth/AD- iaagYjU5Pc62iffbZNrAntJ43krDvks5skM_LgaJpZM4Pcfrx .

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/jmxtrans/jmxtrans-agent/issues/111#issuecomment-330790941, or mute the thread https://github.com/notifications/unsubscribe-auth/AbYM3ITENhJRou9pZSZq2leafBhSUl-Hks5skNRkgaJpZM4Pcfrx .

cyrille-leclerc commented 6 years ago

@maogouste I have improved the troubleshooting messages with #112

Can you please test the jmxtrans-agent snapshot https://oss.sonatype.org/content/repositories/snapshots/org/jmxtrans/agent/jmxtrans-agent/1.2.7-SNAPSHOT/jmxtrans-agent-1.2.7-20170920.100756-1.jar and share with us the error message.

maogouste commented 6 years ago 
sept. 20 13:18:17  java[12860]: 2017-09-20 13:18:17.019 INFO [main] org.jmxtrans.agent.JmxTransAgent - Starting 'JMX metrics exporter agent: 1.2.7-SNAPSHOT' with configuration '/servers/jmxtrans-agent/jmxtrans-agent.xml'...
sept. 20 13:18:17  java[12860]: 2017-09-20 13:18:17.05 INFO [main] org.jmxtrans.agent.JmxTransAgent - PropertiesLoader: Empty Properties Loader
sept. 20 13:18:17  java[12860]: 2017-09-20 13:18:17.558 INFO [main] org.jmxtrans.agent.influxdb.InfluxDbOutputWriter - InfluxDbOutputWriter is configured with url=http://xx.yy.zz.aa:8086, database=java_db, user=null, password=null, tags=host=servername,instance=dots-server_01, connectTimeoutMills=3000, readTimeoutMillis=5000
sept. 20 13:18:17  java[12860]: 2017-09-20 13:18:17.583 INFO [main] org.jmxtrans.agent.JmxTransExporter - Configuration reload interval: 60secs
sept. 20 13:18:17  java[12860]: 2017-09-20 13:18:17.584 INFO [main] org.jmxtrans.agent.JmxTransAgent - JmxTransAgent started with configuration '/servers/jmxtrans-agent/jmxtrans-agent.xml'
sept. 20 13:18:58  java[12860]: 2017-09-20 13:18:58.904 WARNING [jmxtrans-agent-1] org.jmxtrans.agent.JmxTransExporter - Ignore exception flushing metrics
sept. 20 13:18:58  java[12860]: java.io.IOException: Exception sending metrics to 'http://xx.yy.zz.aa:8086/write?precision=ms&db=java_db': java.net.SocketTimeoutException: Connect timed out
sept. 20 13:18:58  java[12860]: at org.jmxtrans.agent.influxdb.InfluxDbOutputWriter.sendMetrics(InfluxDbOutputWriter.java:161)
sept. 20 13:18:58  java[12860]: at org.jmxtrans.agent.influxdb.InfluxDbOutputWriter.postCollect(InfluxDbOutputWriter.java:153)
sept. 20 13:18:58  java[12860]: at org.jmxtrans.agent.OutputWriterCircuitBreakerDecorator.postCollect(OutputWriterCircuitBreakerDecorator.java:124)
sept. 20 13:18:58  java[12860]: at org.jmxtrans.agent.OutputWritersChain.postCollect(OutputWritersChain.java:70)
sept. 20 13:18:58  java[12860]: at org.jmxtrans.agent.JmxTransExporter.collectAndExport(JmxTransExporter.java:214)
sept. 20 13:18:58  java[12860]: at org.jmxtrans.agent.JmxTransExporter$2.run(JmxTransExporter.java:131)
sept. 20 13:18:58  java[12860]: at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
sept. 20 13:18:58  java[12860]: at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
sept. 20 13:18:58  java[12860]: at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
sept. 20 13:18:58  java[12860]: at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
sept. 20 13:18:58  java[12860]: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
sept. 20 13:18:58  java[12860]: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
sept. 20 13:18:58  java[12860]: at java.lang.Thread.run(Thread.java:748)
sept. 20 13:18:58  java[12860]: Caused by: java.net.SocketTimeoutException: Connect timed out
sept. 20 13:18:58  java[12860]: at java.net.SocksSocketImpl.readSocksReply(SocksSocketImpl.java:126)
sept. 20 13:18:58  java[12860]: at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:502)
sept. 20 13:18:58  java[12860]: at java.net.Socket.connect(Socket.java:589)
sept. 20 13:18:58  java[12860]: at sun.net.NetworkClient.doConnect(NetworkClient.java:175)
sept. 20 13:18:58  java[12860]: at sun.net.www.http.HttpClient.openServer(HttpClient.java:463)
sept. 20 13:18:58  java[12860]: at sun.net.www.http.HttpClient.openServer(HttpClient.java:558)
sept. 20 13:18:58  java[12860]: at sun.net.www.http.HttpClient.<init>(HttpClient.java:242)
sept. 20 13:18:58  java[12860]: at sun.net.www.http.HttpClient.New(HttpClient.java:339)
sept. 20 13:18:58  java[12860]: at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1209)
sept. 20 13:18:58  java[12860]: at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1157)
sept. 20 13:18:58  java[12860]: at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1032)
sept. 20 13:18:58  java[12860]: at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:966)
sept. 20 13:18:58  java[12860]: at sun.net.www.protocol.http.HttpURLConnection.getOutputStream0(HttpURLConnection.java:1316)
sept. 20 13:18:58  java[12860]: at sun.net.www.protocol.http.HttpURLConnection.getOutputStream(HttpURLConnection.java:1291)
sept. 20 13:18:58  java[12860]: at org.jmxtrans.agent.influxdb.InfluxDbOutputWriter.writeMetrics(InfluxDbOutputWriter.java:204)
sept. 20 13:18:58  java[12860]: at org.jmxtrans.agent.influxdb.InfluxDbOutputWriter.sendMetrics(InfluxDbOutputWriter.java:170)
sept. 20 13:18:58  java[12860]: at org.jmxtrans.agent.influxdb.InfluxDbOutputWriter.sendMetrics(InfluxDbOutputWriter.java:159)
sept. 20 13:18:58  java[12860]: ... 12 more
cyrille-leclerc commented 6 years ago

@maogouste you have a connect timeout when the JVM tries to open an HTTP socket on port 8086 to the IP xx.yy.zz.aa.

If a curl http://xx.yy.zz.aa:8086 is successful when the JVM is not, then there may be an http proxy issue. Could you go through an http proxy when using curl but not when using java or vice versa?

Can you try to execute from the application server the following command to test a jvm access to :http://xx.yy.zz.aa:808

jrunscript -e "println(new java.net.URL(\"http://xx.yy.zz.aa:8086\").openConnection().getResponseCode())"
maogouste commented 6 years ago

It says 404

cyrille-leclerc commented 6 years ago

I think I understood, the http connection from your java application seem to go through a Sock Proxy as you can see java.net.SocksSocketImpl.connect in the stack trace.

Shouldn't you exclude the ip address of your influxdb server from your jvm proxy config?

sept. 19 16:27:56  java[79309]: java.net.SocketTimeoutException: Connect timed out
sept. 19 16:27:56  java[79309]: at java.net.SocksSocketImpl.readSocksReply(SocksSocketImpl.java:126)
sept. 19 16:27:56  java[79309]: at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:502)
sept. 19 16:27:56  java[79309]: at java.net.Socket.connect(Socket.java:589)
sept. 19 16:27:56  java[79309]: at sun.net.NetworkClient.doConnect(NetworkClient.java:175)
sept. 19 16:27:56  java[79309]: at sun.net.www.http.HttpClient.openServer(HttpClient.java:463)
maogouste commented 6 years ago

The jmxtrans-agent connection should pass directly. No proxy of any kind needed.

But, proxies are defined for the corporate application.

Is it possible to define our own? In this case, none?