Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Problem with springboot java and jmxtrans-agent #111

Open
maogouste opened this issue Sep 19, 2017 · 10 comments
Open

Problem with springboot java and jmxtrans-agent #111

maogouste opened this issue Sep 19, 2017 · 10 comments
Labels

Comments

@maogouste
Copy link

maogouste commented Sep 19, 2017

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
Copy link
Member

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
Copy link
Author

maogouste commented Sep 20, 2017

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
Copy link
Member

kerlandsson commented Sep 20, 2017 via email

@maogouste
Copy link
Author

maogouste commented Sep 20, 2017 via email

@cyrille-leclerc
Copy link
Member

@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
Copy link
Author

maogouste commented Sep 20, 2017

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
Copy link
Member

@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
Copy link
Author

It says 404

@cyrille-leclerc
Copy link
Member

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
Copy link
Author

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?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

3 participants