Greetings. I want to say I am very excited about this project. I have been following for a little while and I have decided to finally try it out. Unfortunately, I am having major resource leakage on the sensu-client 0.14.0-1 release on Ubuntu 12.04.5. Almost immediately after launch, the sensu-client uses 100% CPU and starts consuming memory very quickly. I can’t figure out why this is happening. I turned off SSL on the client for the time being, but the same thing was happening with it enabled. I am trying to start with a simple metric that grabs the CPU utilization of a ROS node using SNMP and logs it in a redis database with a timestamp.
My client.json:
{
“client”: {
“name”: "client.example.tld,
“address”: “10.35.10.88”,
“subscriptions”: [ “ui” ]
}
}
``
My rabbitmq.json:
{
“rabbitmq”: {
“host”: “server.example.tld”,
“port”: 5672,
“vhost”: “/sensu”,
“user”: “sensu”,
“password”: “REDACTED”
}
}
``
My simple plugin (client_redis.py)
#!/usr/bin/python
import sys
import json
from redis.client import Redis
r = Redis(host=‘localhost’, port=6379, db=0)
def print_data(pattern):
for key in r.keys(pattern):
json_data = json.loads(r.get(key))
val = json_data[‘value’]
timestamp = int(json_data[‘timestamp’])
print("%s %s %s" % (key,val,timestamp))
print_data(sys.argv[1])
``
Example use of the plugin:
sensu@client:/etc/sensu/plugins$ ./client_redis.py “*./NODE.cpu_usage”
client./NODE.cpu_usage 1.867 1414511902
``
My check (cpu_usage_metrics.json)
{
“checks”: {
“cpu_usage_metrics”: {
“type”: “metric”,
“command”: “client_redis.py “*./NODE.cpu_usage””,
“subscribers”: [
“ui”
],
“interval”: 15
}
}
}
``
sensu-client.log:
{“timestamp”:“2014-10-28T16:46:09.457313-0400”,“level”:“warn”,“message”:“config file does not exist or is not readable”,“file”:"/etc/sensu/config.json"}
{“timestamp”:“2014-10-28T16:46:09.457404-0400”,“level”:“warn”,“message”:“ignoring config file”,“file”:"/etc/sensu/config.json"}
{“timestamp”:“2014-10-28T16:46:09.457452-0400”,“level”:“warn”,“message”:“loading config files from directory”,“directory”:"/etc/sensu/conf.d"}
{“timestamp”:“2014-10-28T16:46:09.457503-0400”,“level”:“warn”,“message”:“loading config file”,“file”:"/etc/sensu/conf.d/rabbitmq.json"}
{“timestamp”:“2014-10-28T16:46:09.457544-0400”,“level”:“warn”,“message”:“loading config file”,“file”:"/etc/sensu/conf.d/client.json"}
{“timestamp”:“2014-10-28T16:46:09.457603-0400”,“level”:“warn”,“message”:“config file applied changes”,“file”:"/etc/sensu/conf.d/client.json",“changes”:{“client”:[null,{“name”:“client.example.tld”,“address”:“10.35.10.88”,“subscriptions”:[“ui”]}]}}
{“timestamp”:“2014-10-28T16:46:09.459447-0400”,“level”:“warn”,“message”:“loading extension files from directory”,“directory”:"/etc/sensu/extensions"}
{“timestamp”:“2014-10-28T16:46:09.472502-0400”,“level”:“debug”,“message”:“connecting to transport”,“name”:“rabbitmq”,“settings”:{“host”:“vm-server.example.tld”,“port”:5672,“vhost”:"/sensu",“user”:“sensu”,“password”:“REDACTED”}}
{“timestamp”:“2014-10-28T16:46:09.529060-0400”,“level”:“debug”,“message”:“scheduling keepalives”}
{“timestamp”:“2014-10-28T16:46:09.529271-0400”,“level”:“debug”,“message”:“publishing keepalive”,“payload”:{“name”:“client.example.tld”,“address”:“10.35.10.88”,“subscriptions”:[“ui”],“version”:“0.14.0”,“timestamp”:1414529169}}
{“timestamp”:“2014-10-28T16:46:09.529609-0400”,“level”:“debug”,“message”:“subscribing to client subscriptions”}
{“timestamp”:“2014-10-28T16:46:09.529695-0400”,“level”:“debug”,“message”:“subscribing to a subscription”,“subscription”:“ui”}
{“timestamp”:“2014-10-28T16:46:09.529914-0400”,“level”:“debug”,“message”:“scheduling standalone checks”}
{“timestamp”:“2014-10-28T16:46:09.530026-0400”,“level”:“debug”,“message”:“binding client tcp and udp sockets”,“options”:{“bind”:“127.0.0.1”,“port”:3030}}
from /opt/sensu/bin/sensu-client:23:in <main>' from /opt/sensu/bin/sensu-client:23:in
load’
from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/sensu-0.14.0/bin/sensu-client:10:in <top (required)>' from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/sensu-0.14.0/lib/sensu/client.rb:12:in
run’
from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/sensu-em-2.4.0/lib/eventmachine.rb:187:in run' from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/sensu-em-2.4.0/lib/eventmachine.rb:187:in
run_machine’
from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/amqp-1.3.0/lib/amqp/session.rb:659:in receive_data' from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/amqp-1.3.0/lib/amqp/session.rb:921:in
receive_frame’
from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/amqp-1.3.0/lib/amqp/session.rb:947:in receive_frameset' from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/amqp-1.3.0/lib/amqp/session.rb:947:in
call’
from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/amqp-1.3.0/lib/amqp/channel.rb:1476:in block in <class:Channel>' from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/amqp-1.3.0/lib/amqp/channel.rb:1450:in
handle_open_ok’
from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/amqp-1.3.0/lib/amqp/callbacks.rb:59:in exec_callback_once_yielding_self' from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/amqp-1.3.0/lib/amqp/callbacks.rb:59:in
each’
from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/amqp-1.3.0/lib/amqp/callbacks.rb:59:in block in exec_callback_once_yielding_self' from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/amqp-1.3.0/lib/amqp/callbacks.rb:59:in
call’
from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/amqp-1.3.0/lib/amqp/channel.rb:289:in block (2 levels) in initialize' from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/sensu-em-2.4.0/lib/em/deferrable.rb:191:in
succeed’
from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/sensu-em-2.4.0/lib/em/deferrable.rb:151:in set_deferred_status' from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/sensu-em-2.4.0/lib/em/deferrable.rb:151:in
call’
from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/amqp-1.3.0/lib/amqp/channel.rb:936:in block in once_open' from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/amqp-1.3.0/lib/amqp/channel.rb:936:in
call’
from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/amqp-1.3.0/lib/amqp/exchange.rb:539:in block in publish' from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/amqp-1.3.0/lib/amqp/exchange.rb:772:in
basic_publish’
from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/amq-protocol-1.9.2/lib/amq/protocol/client.rb:1741:in encode' from /opt/sensu/embedded/lib/ruby/gems/2.0.0/gems/amq-protocol-1.9.2/lib/amq/protocol/client.rb:182:in
encode_body’
4529169}
8075491
``
The second to last line was the value of “body” during runtime and seems to be the timestamp on the keepalive message. The last is the number of elements in “array”
gdb – following this: https://blog.nelhage.com/2013/03/tracking-an-eventmachine-leak/
0x00007ff18450e10e in rb_class_of () from /opt/sensu/embedded/lib/libruby.so.2.0
(gdb) next
Single stepping until exit from function rb_class_of,
which has no line number information.
0x00007ff18450e483 in rb_obj_class () from /opt/sensu/embedded/lib/libruby.so.2.0
(gdb) next
Single stepping until exit from function rb_obj_class,
which has no line number information.
0x00007ff184510367 in rb_obj_alloc () from /opt/sensu/embedded/lib/libruby.so.2.0
(gdb) next
Single stepping until exit from function rb_obj_alloc,
which has no line number information.
0x00007ff1845103ea in rb_class_new_instance () from /opt/sensu/embedded/lib/libruby.so.2.0
(gdb) next
Single stepping until exit from function rb_class_new_instance,
which has no line number information.
0x00007ff1845f3ba3 in call_cfunc_m1 () from /opt/sensu/embedded/lib/libruby.so.2.0
(gdb) next
Single stepping until exit from function call_cfunc_m1,
which has no line number information.
0x00007ff1845f47a9 in vm_call_cfunc_with_frame () from /opt/sensu/embedded/lib/libruby.so.2.0
(gdb) next
Single stepping until exit from function vm_call_cfunc_with_frame,
which has no line number information.
0x00007ff1845f48e3 in vm_call_cfunc () from /opt/sensu/embedded/lib/libruby.so.2.0
(gdb) next
Single stepping until exit from function vm_call_cfunc,
which has no line number information.
0x00007ff1845f95ef in vm_exec_core () from /opt/sensu/embedded/lib/libruby.so.2.0
(gdb) p rb_eval_string(“GC.start”)
$1 = 8
(gdb) p rb_eval_string("$gdb_objs = Hash.new 0")
$2 = 56869760
(gdb) p rb_eval_string(“ObjectSpace.each_object {|o| $gdb_objs[o.class] += 1}”)
$3 = 16202367
(gdb) p rb_backtrace()
$4 = 26
(gdb) p rb_eval_string("$stderr.puts(body)")
$5 = 8
…
(gdb) p rb_eval_string("$stderr.puts(array.length)")
$10 =8
``
rabbitmq log
=INFO REPORT==== 28-Oct-2014::16:46:09 ===
accepting AMQP connection <0.13215.0> (10.35.10.88:38877 -> 192.168.9.210:5672)
``
sensu-server log
{“timestamp”:“2014-10-28T16:39:24.914565-0400”,“level”:“warn”,“message”:“config file does not exist or is not readable”,“file”:"/etc/sensu/config.json"}
{“timestamp”:“2014-10-28T16:39:24.918690-0400”,“level”:“warn”,“message”:“ignoring config file”,“file”:"/etc/sensu/config.json"}
{“timestamp”:“2014-10-28T16:39:24.918900-0400”,“level”:“warn”,“message”:“loading config files from directory”,“directory”:"/etc/sensu/conf.d"}
{“timestamp”:“2014-10-28T16:39:24.919069-0400”,“level”:“warn”,“message”:“loading config file”,“file”:"/etc/sensu/conf.d/rabbitmq.json"}
{“timestamp”:“2014-10-28T16:39:24.919225-0400”,“level”:“warn”,“message”:“loading config file”,“file”:"/etc/sensu/conf.d/api.json"}
{“timestamp”:“2014-10-28T16:39:24.919491-0400”,“level”:“warn”,“message”:“config file applied changes”,“file”:"/etc/sensu/conf.d/api.json",“changes”:{“api”:[null,{“host”:“localhost”,“port”:4567,“user”:"ad
min",“password”:“REDACTED”}]}}
{“timestamp”:“2014-10-28T16:39:24.919673-0400”,“level”:“warn”,“message”:“loading config file”,“file”:"/etc/sensu/conf.d/client.json"}
{“timestamp”:“2014-10-28T16:39:24.919957-0400”,“level”:“warn”,“message”:“config file applied changes”,“file”:"/etc/sensu/conf.d/client.json",“changes”:{“client”:[null,{“name”:“client.example.tld”,"addre
ss":“10.35.10.88”,“subscriptions”:[“ui”]}]}}
{“timestamp”:“2014-10-28T16:39:24.920129-0400”,“level”:“warn”,“message”:“loading config file”,“file”:"/etc/sensu/conf.d/redis.json"}
{“timestamp”:“2014-10-28T16:39:24.920370-0400”,“level”:“warn”,“message”:“config file applied changes”,“file”:"/etc/sensu/conf.d/redis.json",“changes”:{“redis”:[null,{“host”:“localhost”,“port”:6379}]}}
{“timestamp”:“2014-10-28T16:39:24.920545-0400”,“level”:“warn”,“message”:“loading config file”,“file”:"/etc/sensu/conf.d/cpu_usage_metrics.json"}
{“timestamp”:“2014-10-28T16:39:24.920797-0400”,“level”:“warn”,“message”:“config file applied changes”,“file”:"/etc/sensu/conf.d/cpu_usage_metrics.json",“changes”:{“checks”:{“cpu_usage_metrics”:[null,{“type”:“metric”,“command”:“client_redis.py “*./NODE.cpu_usage””,“subscribers”:[“ui”],“interval”:15}]}}}
{“timestamp”:“2014-10-28T16:39:24.941037-0400”,“level”:“warn”,“message”:“loading extension files from directory”,“directory”:"/etc/sensu/extensions"}
{“timestamp”:“2014-10-28T16:39:24.941576-0400”,“level”:“warn”,“message”:“loaded extension”,“type”:“mutator”,“name”:“ruby_hash”,“description”:“returns ruby hash event data”}
{“timestamp”:“2014-10-28T16:39:24.941778-0400”,“level”:“warn”,“message”:“loaded extension”,“type”:“mutator”,“name”:“json”,“description”:“returns JSON formatted event data”}
{“timestamp”:“2014-10-28T16:39:24.941950-0400”,“level”:“warn”,“message”:“loaded extension”,“type”:“mutator”,“name”:“only_check_output”,“description”:“returns check output”}
{“timestamp”:“2014-10-28T16:39:24.942111-0400”,“level”:“warn”,“message”:“loaded extension”,“type”:“handler”,“name”:“debug”,“description”:“returns raw event data”}
{“timestamp”:“2014-10-28T16:39:24.973848-0400”,“level”:“debug”,“message”:“connecting to redis”,“settings”:{“host”:“localhost”,“port”:6379}}
{“timestamp”:“2014-10-28T16:39:24.977841-0400”,“level”:“debug”,“message”:“connecting to transport”,“name”:“rabbitmq”,“settings”:{“ssl”:{“cert_chain_file”:"/etc/sensu/ssl/chain.pem",“private_key_file”:"/etc/sensu/ssl/key.pem"},“host”:“server.example.tld”,“port”:5671,“vhost”:"/sensu",“user”:“sensu”,“password”:“REDACTED”}}
{“timestamp”:“2014-10-28T16:39:25.217859-0400”,“level”:“debug”,“message”:“subscribing to keepalives”}
{“timestamp”:“2014-10-28T16:39:25.218411-0400”,“level”:“debug”,“message”:“subscribing to results”}
{“timestamp”:“2014-10-28T16:39:25.229265-0400”,“level”:“info”,“message”:“i am now the master”}
{“timestamp”:“2014-10-28T16:39:25.229518-0400”,“level”:“debug”,“message”:“scheduling check requests”}
{“timestamp”:“2014-10-28T16:39:25.229781-0400”,“level”:“debug”,“message”:“monitoring clients”}
{“timestamp”:“2014-10-28T16:39:25.229955-0400”,“level”:“debug”,“message”:“pruning aggregations”}
{“timestamp”:“2014-10-28T16:39:35.220621-0400”,“level”:“debug”,“message”:“updated master lock timestamp”}
{“timestamp”:“2014-10-28T16:39:42.231363-0400”,“level”:“info”,“message”:“publishing check request”,“payload”:{“name”:“cpu_usage_metrics”,“issued”:1414528782,“command”:“client_redis.py “*./NODE.cpu_usage””},“subscribers”:[“ui”]}
``
pmap:
root@client:/etc/sensu/conf.d# pmap -x pidof /opt/sensu/embedded/bin/ruby
13490: /opt/sensu/embedded/bin/ruby /opt/sensu/bin/sensu-client -b -c /etc/sensu/config.json -d /etc/sensu/conf.d -e /etc/sensu/extensions -p /var/run/sensu/sensu-client.pid -l /var/log/sensu/sensu-client.log -L DEBUG
Address Kbytes RSS Dirty Mode Mapping
0000000000400000 0 4 4 r-x-- ruby
0000000000600000 0 4 4 r---- ruby
0000000000601000 0 4 4 rw— ruby
00000000023c1000 0 12960 12960 rw— [ anon ]
000000000306a000 0 517308 517308 rw— [ anon ]
00007ff179d48000 0 63092 63092 rw— [ anon ]
00007ff180221000 0 56 0 r-x-- libresolv-2.15.so
00007ff180239000 0 0 0 ----- libresolv-2.15.so
``
Has anyone seen an issue like this before?