jolokia returns "Error handling response: Not expected status value in response body: 403"

[ScubaDrew]

Bug report

Relevant telegraf.conf:

# Telegraf Configuration
[agent]
  ## Default data collection interval for all inputs
  interval = "10s"
  ## Rounds collection interval to 'interval'
  ## ie, if interval="10s" then always collect on :00, :10, :20, etc.
  round_interval = true

  ## Telegraf will send metrics to outputs in batches of at
  ## most metric_batch_size metrics.
  metric_batch_size = 1000
  ## For failed writes, telegraf will cache metric_buffer_limit metrics
  ## output, and will flush this buffer on a successful write. Oldest
  ## are dropped first when this buffer fills.
  metric_buffer_limit = 10000

  ## Collection jitter is used to jitter the collection by a random
  ## Each plugin will sleep for a random time within jitter before
  ## This can be used to avoid many plugins querying things like sysfs
  ## same time, which can have a measurable effect on the system.
  collection_jitter = "0s"

  ## Default flushing interval for all outputs. You shouldn't set this
  ## interval. Maximum flush_interval will be flush_interval +
  flush_interval = "10s"
  ## Jitter the flush interval by a random amount. This is primarily to
  ## large write spikes for users running a large number of telegraf
  ## ie, a jitter of 5s and interval 10s means flushes will happen every
  flush_jitter = "0s"

  ## Run telegraf in debug mode
  debug = true
  ## Run telegraf in quiet mode
  quiet = false
  ## Override default hostname, if empty use os.Hostname()
  hostname = ""
  ## If set to true, do no set the "host" tag in the telegraf agent.
  omit_hostname = false

[[outputs.influxdb]]
  urls = ["http://172.20.0.4:30085","http://172.20.0.5:30085"] #
  database = "telegraf" # required
  retention_policy = "default"
  write_consistency = "any"
  timeout = "5s"
  username = "test"
  password = "test"
[[inputs.jolokia]]
   context = "/jmx/jolokia"
   [[inputs.jolokia.servers]]
     host = "localhost"
     port = "8080"
   [[inputs.jolokia.metrics]]
     name = "java.lang:type=Memory"
     mbean  = "java.lang:type=Memory,*"

  [[inputs.jolokia.metrics]]
    name = "class_count"
    mbean  = "java.lang:type=ClassLoading"
    attribute = "LoadedClassCount,UnloadedClassCount,TotalLoadedClassCount"

System info:

[Include Telegraf version, operating system name, and other relevant details]

.13 and 1.0.0-beta3 result in same thing.

curl http://localhost:8080/jmx/jolokia/:

{"request":{"type":"version"},"value":{"agent":"1.3.2","protocol":"7.2","config":{"agentId":"10.244.1.14-13-510a39c3-servlet","agentType":"servlet"},"info":{"product":"jetty","vendor":"Eclipse","version":"9.3.z-SNAPSHOT"}},"timestamp":1470962452,"status":200}

Steps to reproduce:

1. Run telegraf

Actual behavior:

2016/08/12 00:22:20 Attempting connection to output: influxdb
2016/08/12 00:22:20 Successfully connected to output: influxdb
2016/08/12 00:22:20 Starting Telegraf (version 1.0.0-beta3)
2016/08/12 00:22:20 Loaded outputs: influxdb
2016/08/12 00:22:20 Loaded inputs: jolokia
2016/08/12 00:22:20 Tags enabled: host=dev-60ern
2016/08/12 00:22:20 Agent Config: Interval:10s, Debug:true, Quiet:false, Hostname:"dev-60ern", Flush Interval:10s
Error handling response: Not expected status value in response body: 403
Error handling response: Not expected status value in response body: 403

Additional info:

Executing CURL seems to work and return a 200 response code

http://localhost:8080/jmx/jolokia/read/java.laang:type=Memory

{"request":{"mbean":"java.lang:type=Memory","type":"read"},"value":{"ObjectPendingFinalizationCount":0,"Verbose":true,"HeapMemoryUsage":{"init":247463936,"committed":239271936,"max":4260102144,"used":37482112},"NonHeapMemoryUsage":{"init":2555904,"committed":98787328,"max":1593835520,"used":97617856},"ObjectName":{"objectName":"java.lang:type=Memory"}},"timestamp":1470961302,"status":200}

[sparrc]

it might be a permissions issue for the telegraf user, what happens when you use curl as telegraf?

sudo -u telegraf curl http://localhost:8080/jmx/jolokia/read/java.lang:type=Memory

[ScubaDrew]

Thanks @sparrc ! I Did a top to see who telegraf is running as and found it running as root. I ran the curl as root as you suggested and it comes back fine:

PID PPID USER STAT VSZ %VSZ CPU %CPU COMMAND
14 1 root S 7718m 49% 2 0% java -d64 -server -XX:+UseConcMark
12 1 root S 241m 2% 0 0% telegraf -config /config/telegraf.
124 0 root S 6304 0% 0 0% bash
1 0 root S 1536 0% 0 0% /bin/sh /app/vault /app/vault-asse
13 1 root S 1524 0% 0 0% crond
153 124 root R 1520 0% 2 0% top

sudo -u root curl http://localhost:8080/jmx/jolokia/read/java.lang:type=Memory

{"request":{"mbean":"java.lang:type=Memory","type":"read"},"value":{"ObjectPendingFinalizationCount":0,"Verbose":true,"HeapMemoryUsage":{"init":247463936,"committed":239271936,"max":4260102144,"used":87624168},"NonHeapMemoryUsage":{"init":2555904,"committed":94519296,"max":1593835520,"used":93247816},"ObjectName":{"objectName":"java.lang:type=Memory"}},"timestamp":1471020559,"status":200}

[sparrc]

any ideas @saiello ?

[ScubaDrew]

Looking at the plugin code I noticed that a POST request was being used. I simulated this with CURL and found the issue. It would be very very helpful if this error was output.

curl -H "Content-Type: application/json" -X POST -d '{ "type": "read", "mbean": "java.lang:type=Memory" }' https://localhost:8080/jmx/jolokia/

{"request":{"mbean":"java.lang:type=Memory","type":"read"},"stacktrace":"java.lang.Exception: HTTP method post is not allowed according to the installed security policy\n\tat org.jolokia.http.HttpRequestHandler.executeRequest(HttpRequestHandler.java:214)\n\tat org.jolokia.http.HttpRequestHandler.handlePostRequest(HttpRequestHandler.java:137)\n\tat org.jolokia.http.AgentServlet$3.handleRequest(AgentServlet.java:420)\n\tat org.jolokia.http.AgentServlet.handleSecurely(AgentServlet.java:313)\n\tat org.jolokia.http.AgentServlet.handle(AgentServlet.java:284)\n\tat org.jolokia.http.AgentServlet.doPost(AgentServlet.java:252)\n\tat javax.servlet.http.HttpServlet.service(HttpServlet.java:707)\n\tat javax.servlet.http.HttpServlet.service(HttpServlet.java:790)\n\tat org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:845)\n\tat org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:583)\n\tat org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1160)\n\tat org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:511)\n\tat org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1092)\n\tat org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)\n\tat org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:119)\n\tat org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)\n\tat org.eclipse.jetty.server.Server.handle(Server.java:518)\n\tat org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:308)\n\tat org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:244)\n\tat org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)\n\tat org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)\n\tat org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)\n\tat org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceAndRun(ExecuteRE/jolokia/^Cva.lang:type=Memory" }'

[sparrc]

I went to fix this, but we are actually already reporting any HTTP errors more fully in the code. Jolokia has a very strange behavior where it returns an HTTP 200 status code, but then returns a 403 status code in the JSON response body.

I'm going to add a note about it in the config.

I'm not sure how to handle the error message because this is a very non-standard way of returning an http error...not to mention that I don't really understand why the jolokia maintainers think that a POST request is somehow less secure than a GET 😖 .