Sensu-go: some checks are not being schedule by schedulerd

[Alexc0007]

some of my checks are not being scheduled automatically by schedulerd.
some other checks run just fine.
check definition is basically almost the same for those checks so i cant figure out what's wrong.

here is an example of a check that stops scheduling automatically:
=== cpu_load
Name: cpu_load
Interval: 180
Command: /usr/lib64/nagios/plugins/check_load -w 15,10,5 -c 30,25,20
Cron:
Timeout: 0
TTL: 0
Subscriptions: all
Handlers:
Runtime Assets:
Hooks:
Publish?: true
Stdin?: false
Proxy Entity Name:
Namespace: default
Metric Format: nagios_perfdata
Metric Handlers: influx-db

has anyone encountered such behaviour?

Expected Behavior

check interval is 180 seconds , so i expect the check to run every 3 minutes.

Current Behavior

after restarting the backend it seems like the check start executing correctly every 3 minutes , but at some point it just stops.

if i try to re-run the check , it works fine , but then again - not being executed on its own.

here is an example of several checks that are being executed just fine , along with
cpu_load and check_self_signed_cert_rootca that stopped executing 3 days ago during the weekend

Possible Solution

i have no idea why it happens or what is causing it...
so i cant offer a solution

Steps to Reproduce (for bugs)

the only thing in common between the checks that are not working properly
is that they all have low amount of subscriptions...
they are basic checks and should run on all servers , so they use the "all"
subscription.

Your Environment

most of the checks run on amazon-linux or amazon-linux2
however the checks that are running on also run on same enviromnets

[Alexc0007]

as i keep debugging this case , i can see constant errors in the backend log:
{"component":"eventd","error":"error setting silenced entries: couldn't get silenced entries: etcdserver: too many operations in txn request","level":"error","msg":"eventd - error handling event","time":"2019-06-24T09:04:58Z"}

when sensu stop executing some of the checks(those checks mentioned above) - about 10 minutes after , those errors stop.
when i restart the backend , the errors return

[annaplotkin]

@Alexc0007 what version are you running?

[Alexc0007]

Hi @annaplotkin ,
i tried it on 5.7 , 5.8 , 5.9 , 5.10 - it was the same behavior.
i re-created etcd from scratch and defined all my checks today on version 5.7 - the errors stated above disappeared...
however the scheduler was still stopping execution for some checks...
all the checks with subscription "all" were affected again...
i re-checked their configuration(for the million'th time) and couldnt find anything wrong...
when ever the schedule stop scheduling those checks , nothing abnormal appear on the logs(on log-level: debug)
so i still have no idea what's causing it...

[Alexc0007]

a small update:
im still facing the same issue...
some checks just stop working...

i erased all checks from sensu and started adding them by small bulks....
the first few bulks worked fine for over 3-4 days...
then when added some more checks , it seems like they messed it up again...
im now trying to figure out what could have caused that...

does anyone know if there are any forbidden characters on check "command" or is there a length limit to that field?

[palourde]

Hi @Alexc0007,

Thanks for the update. Could you provide us both the sensu-agent and sensu-backend logs, at the debug level if possible, the next time this problem happens? You could upload them to https://gist.github.com/ or something like this.

Regarding the forbidden characters or length limit for the command, I'm not aware of any. The only thing we do is truncate the check result output if it's too long.

Thanks

[Alexc0007]

Hi Simon ,
thank you for trying to help...
i have separated my different checks across several sensu instances in order to debug which bulk is causing the reported issues....
once i see the issue , ill grab the logs for the time it happened and post them as you requested...

ill provide about 3 minutes of logs on the exact incident time... (on debug mode this is ALOT of logs)

[Alexc0007]

well , today sensu stopped again
i didnt have debug mode of an agent in this case but here are 2 minutes logs of the backend:
https://gist.github.com/Alexc0007/f6b1fdeebc76b7297cdc973e198f6f66
they show the 2 minutes where the scheduler stopped scheduling all the checks under subscription "all" and some more checks

basically there is nothing to see in those logs....
what ever is causing it - is not reported in the logs...

[palourde]

Hi @Alexc0007,

Thanks for these logs! Like you mentioned, everything looks normal on the backend side. For example, we can see here a check using the all subscription being scheduled:

Jul 4 04:49:15 localhost sensu-backend[12823]: {"check":"check_connectivity_to_etcd","component":"schedulerd","level":"debug","msg":"sending check request","time":"2019-07-04T04:49:15Z","topic":"sensu:check:default:all"}

We already started to suspect a problem on the agent side, and this new information just confirms it.

The next step would be to grab the logs from an agent whose entity is subscribed to the all subscription. I believe it will contains valuable information and will let us know understand what's going on.

Thanks!

[Alexc0007]

hi Simon , ill try to get u agent logs(those are a bit difficult because those are production machines and i have to make sure they dont run out of disk space)
the schedule u mentioned was one of the last schedules of the check...
right after that point , the scheduler stopped scheduling the "all" checks...

and another thing: all the machines are subscribed as all....
so its possible that the logs ill give u will not present the issue if it is in fact on the agent side...
any machine could be the one causing the problem....
and there are a lot....

[Alexc0007]

Hi Simon , i added agent side logs from where sensu scheduler stopped working...
its here: https://gist.github.com/Alexc0007/f6b1fdeebc76b7297cdc973e198f6f66
scroll down....

as you can see , since 17:33:59 sensu agent started sending only keepalive events....
and its doing it for hours since then....
it doesnt send any other events...
it keeps sending only keepalives till i restart the backend

hope there is some info in there that can help u understand what happened....

[palourde]

Thanks @Alexc0007 for these logs!

I can indeed see the behavior you reported, but unfortunately the agent does not tell us why.

Do you have the sensu-backend logs for the same time period as the sensu-agent ones? (Jul 4 17:00:00 to Jul 4 17:59:58). Being able to correlate the agent & backend logs would be immensely useful.

Thanks again

[Alexc0007]

Hi Simon
you want a full hour of logs? it would be a huge logfile....
ill get u the logs for those several minutes where it all went to hell... :)

[palourde]

@Alexc0007 The more, the better =)

[Alexc0007]

added 2 more logs of sensu agent and backend for the same time where they stopped working....
on the agent as in the previous case - since 03:35 its only keepalives....

https://gist.github.com/Alexc0007/f6b1fdeebc76b7297cdc973e198f6f66

from what i see , there is nothing to see there...
what ever is causing it , its not in the logs...
and that is what scares me the most...
i am 99% sure the issue is caused by a bad configuration or output of one of my checks - since i have 6 more sensu instances with different checks that are working fine for over 4 days now...
and i have those 2 instances with a set of specific checks that i identified as problematic and they crash every day...

i can fix anything related to my checks , but sensu just wont let me know whats killing him....
and that is the main issue as i see it.
i need to know that next time i add a check that is causing issues - ill be able to know about it so i can fix it.

[Alexc0007]

@palourde
Hi Simon , any chance you discovered something new?

[palourde]

Hi @Alexc0007

Thanks for these! I was out for the weekend, I'll take a look at these today and let you know.

Thanks

[Alexc0007]

update:
it keeps happening again and again...
i have reduced the list of checks that might be causing it to about 20 checks...
but its very hard to understand which one is responsible...

until this issue is discovered , its gonna be super hard to trust the system...

[Alexc0007]

im starting to think about a different direction to address that problem...
since my environment is very dynamic and hundred of hosts are being replaced every day , its possible that the following happens:
all my configuration on the hosts is being installed by puppet , so its possible that after puppet installs the agent and start its service - its trying to start and execute the checks it gets from the scheduler.
its also possible that at that time , the host is missing some of the files / configurations it needs to run some of the checks... or maybe even missing the checks themselves...

after trying to execute a "corrupted" check , it might receive a kind of a broken output that it tries to send to the backend...
is it possible that an output of a sort may kill the backend?
is it possible that the backend wouldnt document such an error?
as we can see , what ever the error is , its not documented...

ill try to play with that theory a bit , maybe ill find something...

[Alexc0007]

well , after investigating my theories , its seems like this is not the case...
@palourde
is there anything new in this area?
any chance anyone suspect something?

[Alexc0007]

i have some more news ,
i noticed that backend dies every time an instance is being removed while its connected to the backend...
i get the following error message:
Jul 11 08:46:41 localhost sensu-backend[8831]: {"addr":"REMOVED","component":"agentd","id":"REMOVED","level":"warning","msg":"stopping session","recv error":"Connection error: websocket: close 1006 (abnormal closure): unexpected EOF","time":"2019-07-11T08:46:41Z"}

and several minutes after that i can see that the scheduler stopped working...
it happened to me on 5 different sensu machines and everytime the scheduler stopped working it was after this kind of error....

[palourde]

Hi @Alexc0007,

I'll continue to investigate on my side and try to reproduce this bug (I've been unsuccessful so far), but meanwhile do you think you would be able to upgrade to 5.11.0, which has been released yesterday? There's a couple of bug fixes in that release that could possibly help alleviate the behavior you are seeing, and maybe if we are lucky, solve it for good.

Thanks

[roganartu]

That disconnect behaviour is possibly related to #3106 @Alexc0007

[Alexc0007]

Hi Simon (@palourde )
i upgraded one of my sensu servers to the newest version today , its behaving the same as the others...
the scheduler keeps dying and i can always see the error for the broken connection just before that...

@roganartu - about what you said , im not sure this is the same case.
i use a lot of spot instances + auto scaling mechanism for the application , so when traffic is high there are more instances to deal with the load.
when traffic is a bit lower , the instances are terminated...

i probably dont see a reconnection attemp from the same instance...
every time an instance is terminated , a new one can come to replace it...
i didnt experience issues of agents that are losing connection to the backend... keepalive events are being sent constantly without issues.

[palourde]

So this is interesting, I've just tried to reproduce #3106 and I ended up with a similar behavior as described in this issue.

What I did is simply configure sensu-agent & sensu-backend on the same virtual machine, add a simple check and drop the traffic going from the agent to the backend with iptables -A INPUT -p tcp --sport 8081 -j DROP. Here are the logs:

Jul 11 15:39:39 localhost.localdomain sensu-agent[5259]: {"component":"agent","level":"info","msg":"message received","payload":"{\"config\":{\"command\":\"echo 1\",\"handlers\":[],\"high_flap_threshold\":0,\"interval\":15,\"low_flap_threshold\":0,\"publish\":true,\"runtime_assets\":null,\"subscriptions\":[\"system\"],\"proxy_entity_name\":\"\",\"check_hooks\":null,\"stdin\":false,\"subdue\":null,\"ttl\":0,\"timeout\":0,\"round_robin\":false,\"output_metric_format\":\"\",\"output_metric_handlers\":null,\"env_vars\":null,\"metadata\":{\"name\":\"check-echo\",\"namespace\":\"default\"}},\"assets\":null,\"hooks\":null,\"issued\":1562859579}","time":"2019-07-11T15:39:39Z","type":"check_request"}
Jul 11 15:39:39 localhost.localdomain sensu-agent[5259]: {"component":"agent","level":"info","msg":"scheduling check execution: check-echo","time":"2019-07-11T15:39:39Z"}
Jul 11 15:39:39 localhost.localdomain sensu-agent[5259]: {"assets":null,"check":"check-echo","component":"agent","level":"debug","msg":"fetching assets for check","namespace":"default","time":"2019-07-11T15:39:39Z"}
Jul 11 15:39:39 localhost.localdomain sensu-agent[5259]: {"component":"agent","level":"info","msg":"sending message","payload":"{\"timestamp\":1562859579,\"entity\":{\"entity_class\":\"agent\",\"system\":{\"hostname\":\"localhost.localdomain\",\"os\":\"linux\",\"platform\":\"centos\",\"platform_family\":\"rhel\",\"platform_version\":\"7.6.1810\",\"network\":{\"interfaces\":[{\"name\":\"lo\",\"addresses\":[\"127.0.0.1/8\",\"::1/128\"]},{\"name\":\"eth0\",\"mac\":\"52:54:00:8a:fe:e6\",\"addresses\":[\"10.0.2.15/24\",\"fe80::5054:ff:fe8a:fee6/64\"]}]},\"arch\":\"amd64\"},\"subscriptions\":[\"system\"],\"last_seen\":1562858429,\"deregister\":false,\"deregistration\":{},\"user\":\"agent\",\"redact\":[\"password\",\"passwd\",\"pass\",\"api_key\",\"api_token\",\"access_key\",\"secret_key\",\"private_key\",\"secret\"],\"metadata\":{\"name\":\"localhost.localdomain\",\"namespace\":\"default\"}},\"check\":{\"command\":\"echo 1\",\"handlers\":[],\"high_flap_threshold\":0,\"interval\":15,\"low_flap_threshold\":0,\"publish\":true,\"runtime_assets\":null,\"subscriptions\":[\"system\"],\"proxy_entity_name\":\"\",\"check_hooks\":null,\"stdin\":false,\"subdue\":null,\"ttl\":0,\"timeout\":0,\"round_robin\":false,\"duration\":0.005125971,\"executed\":1562859579,\"history\":null,\"issued\":1562859579,\"output\":\"1\\n\",\"status\":0,\"total_state_change\":0,\"last_ok\":0,\"occurrences\":0,\"occurrences_watermark\":0,\"output_metric_format\":\"\",\"output_metric_handlers\":null,\"env_vars\":null,\"metadata\":{\"name\":\"check-echo\",\"namespace\":\"default\"}},\"metadata\":{\"namespace\":\"default\"}}","time":"2019-07-11T15:39:39Z","type":"event"}
Jul 11 15:39:39 localhost.localdomain sensu-agent[5259]: {"component":"agent","level":"info","msg":"sending event","time":"2019-07-11T15:39:39Z"}
# Here I applied the iptables rule. The agent will now attempt to send keepalives. Meanwhile, the check is no longer scheduled
Jul 11 15:39:49 localhost.localdomain sensu-agent[5259]: {"component":"agent","level":"info","msg":"sending keepalive","time":"2019-07-11T15:39:49Z"}
Jul 11 15:40:09 localhost.localdomain sensu-agent[5259]: {"component":"agent","level":"info","msg":"sending keepalive","time":"2019-07-11T15:40:09Z"}
[...]
# Finally, ~15 minutes later, the both the agent and backend noticed that the connection timed out.
Jul 11 15:55:18 localhost.localdomain sensu-agent[5259]: {"component":"agent","error":"Connection error: read tcp 127.0.0.1:54640-\u003e127.0.0.1:8081: read: connection timed out","level":"error","msg":"transport receive error","time":"2019-07-11T15:55:18Z"}
Jul 11 15:55:29 localhost.localdomain sensu-backend[4932]: {"addr":"127.0.0.1:54640","agent":"localhost.localdomain","component":"agentd","level":"warning","msg":"stopping session","recv error":"Connection error: read tcp 127.0.0.1:8081-\u003e127.0.0.1:54640: read: connection timed out","time":"2019-07-11T15:55:29Z"}

The websocket library we use does support pings & pongs, so I believe we could use that to detect problems with the connection and attempt to re-establish it.

[Alexc0007]

ohh , finally!
this is good...
so now we know for sure this is the cause for the behavior...
now its time to figure out a fix...

[palourde]

@Alexc0007 Well, I couldn't say we know for sure, but it looks indeed promising. I'm working on a potential patch, I'll let you know once I know more.

[palourde]

Hi @Alexc0007 & @roganartu,

I simply wanted to let you know that I've pushed a PR with a possible patch for this issue: https://github.com/sensu/sensu-go/pull/3138.

While I'm confident it fixes #3106, I have good reasons to think it will also solve this particular problem.

Also, please let me know if you are interested in already testing this patch in your environment!

[Alexc0007]

Hi @palourde
i would gladly install this version on one of my sensu instances to make sure its working as intended...
do you have a repository where i can download the patched version?

[Alexc0007]

Hi @palourde ,
i see the issue was closed... however we didnt test it and we are not sure its even fixing the behavior described in this post...
when will i be able to install a fixed version?

our whole sensu project is frozen because of this...
we thought about maybe buying the enterprise version , but not till we see a fully working OS version that fits our needs(or most of our needs)

[Alexc0007]

after testing the new version - the issue is not resolved
it should be re-opened
several minutes after this error in the log:
Jul 21 09:05:45 localhost sensu-backend[12214]: {"addr":"REMOVED","agent":REMOVED,"component":"agentd","level":"warning","msg":"stopping session","recv error":"Connection error: websocket: close 1006 (abnormal closure): unexpected EOF","time":"2019-07-21T09:05:45Z"}

the scheduler stopped scheduling new checks...

[Alexc0007]

any news about this one?

[palourde]

@Alexc0007 For your information, it appears an another user reported a similar problem but with round-robin checks, which I was indeed able to reproduce: https://github.com/sensu/sensu-go/issues/3156

However, a similar check with a simple interval (and without round-robin) continued to work without any problem after the cluster got back online.

[Alexc0007]

@palourde
Hi Simon ,
seems like this case: https://github.com/sensu/sensu-go/issues/3168
is very similar to what i see....

as for #3156 , i never had those errors in my logs... so its probably a different issue.

BTW: did Matt pass the profile i provided to the dev teams?
maybe it can show u something u didnt see before...

[Alexc0007]

i tried checking how long does it take sensu to realize an instance is terminated and no longer there...
i had an instance receive termination request at 11:08.
at 11:12 instance was terminated completely...

sensu reported this message only at 11:28(8:28 UTC):
Aug 15 08:28:42 localhost sensu-backend[3373]: {"addr":"10.12.19.147:50892","agent":"HOSTNAME","component":"agentd","level":"warning","msg":"stopping session","recv error":"Connection error: websocket: close 1006 (abnormal closure): unexpected EOF","time":"2019-08-15T08:28:42Z"}

after that the scheduler died...
why does it take that long for sensu to realize the agent is dead?

[noahbailey]

I've also experienced some issues like this. We have a test environment in AWS connected via IPsec to some on-prem monitoring/logging where our Sensu Go backend is. Now and then I'll see the metrics from these servers partially drop out. Keepalives generally continue despite this.

Here was a recent incident of this happening: (x.x.x.x is AWS, y.y.y.y is our office)

Aug 23 08:01:40 mycoolserver sensu-agent[1185]: {"component":"agent","error":"Connection error: read tcp x.x.x.x:43748-\u003ey.y.y.y:8081: read: connection reset by peer","level":"error","msg":"transport receive error","time":"2019-08-23T08:01:40Z"}
Aug 23 08:03:47 mycoolserver sensu-agent[1185]: {"component":"agent","error":"dial tcp y.y.y.y:8081: connect: connection timed out","level":"error","msg":"reconnection attempt failed","time":"2019-08-23T08:03:47Z"}

And logs from the backend server:

Aug 23 08:02:13 sensubox sensu-backend[2397]: {"component":"keepalived","entity":"mycoolserver","is_leader":"true","level":"warning","msg":"keepalive timed out","namespace":"dev","previous_status":"alive","status":"dead","time":"2019-08-23T08:02:13Z"}

In this case, about 1/4 of the checks and metrics didn't work after this.

__Versions:__

Host | Version
----- | ------
agent | sensu-agent version 5.10.2#13bafd5, build 13bafd56ce60cb8c91838bfa4e65c6ff512c3d0d, built 2019-06-27T17:48:41Z
backend | sensu-backend version 5.11.1#39d2bf2, build 39d2bf22c416f9a78f22c4817dc74ab62d7f4d63, built 2019-07-18T13:30:28Z

This did occur with the backend on 5.10.x as well. I will update the agent to 5.11.x as well and see if it occurs again this weekend.

Thanks for checking this out!

[johannagnarsson]

Have you tried 5.12 ? It had this interesting tidbit in it : Some issues with check scheduling and updating have been fixed by refactoring the backend’s watcher implementation. After updating my system seems to hang in there so far.

[Alexc0007]

Hi @johannagnarsson , just installed the new version on all my servers...
ill update once i see anything

[Alexc0007]

well , after several hours of work , i can confirm that the issue is still present...
nothing changed.

[johannagnarsson]

Ok, can confirm issue still happens for me as well on 5.12.

[cwjohnston]

Hi @Alexc0007

well , after several hours of work , i can confirm that the issue is still present...
nothing changed.

As your comments seem focused on the backend version, would you please comment on which version of Sensu Agent you currently have deployed?

[Alexc0007]

Hi @cwjohnston ,
my agents are all of the newest version as well... 5.12

[Alexc0007]

another new version... and no fix for the scheduler... disappointing...

[portertech]

This bug has been reprioritized, the the top of the queue. Let's take this opportunity to instrument the scheduler, we can then observe/test it under load/stress during performance testing.

[msmith-hpe]

We've had to downgrade back to sensu core after running into this issue on agent/backend version 5.12. Eagerly awaiting any updates.

[echlebek]

@Alexc0007 since we are having a lot of trouble debugging your issue, could you try making use of the Timeout and TTL features?

Timeout - will send a failing event from the agent to the backend if the check never finishes executing
TTL - will cause a failing event to be created if the agent stops sending check responses for a given period. (Not desirable for a dynamic environment, but may help with debugging this issue.)

I expect one of several outcomes here:

1. The check times out while in execution. -> Problem with the check itself
2. The check TTL fails. -> Problem with the agent executor, or the backend session, or connection failure
3. No failing event occurs. -> Problem with the backend scheduler

This would help us direct our debugging efforts since we would get a better sense of the scope of the issue. Thanks for your patience in dealing with this issue.

[echlebek]

@noahbailey your problem looks distinct from the issue described here. While Alex has keepalives being sent from agents to the backend, your environment does not - as evidenced by your logs. What you are experiencing is the agent connection failing entirely, and keepalive failures occurring only as a result of the backend not receiving updates.

We've had reports of this problem with other IPSec users before as well. Would you mind filing a separate issue for your problem, with any additional information you can? Thank you very much!

[msmith-hpe]

To clarify, in my case I was seeing check TTL failures after an yet indeterminate amount of time. After restarting the agent, the checks run again for a while, but eventually the same issue surfaces.

Although the keepalive status appears to be okay per the backend UI, we are seeing log error messages similar to @noahbailey. Not using IPSec. The only thing between the agents/backend is an ALB, which is also handling TLS termination.

Will try to gather some more debug info and share in the new issue opened by @noahbailey or in a separate new issue if they don't get around to it.

[Alexc0007]

Hi @echlebek ,
as for Timeout - all of my checks have timeout defined... there are no timeouts...
as for TTL , i can set it up since there is no TTL on any of the checks but im confident it has nothing to do with the issue.
on sunday ill add TTLs to some checks just because u asked..
but the problem is with backend scheduler.

if the problem was with the agent , restarting the agent would probably help recovering the issue...
but its not , i tried restarting agents and they didnt come back to life up until the point i restart the backend.

[echlebek]

Interesting, and you say that it takes the backend up to 20 minutes to register that the connection has disappeared? That is very odd - in every Sensu system I've seen so far, this happens virtually instantly independent of load.

I agree with your assessment - if restarting the agent does not help, then check TTL will not tell us very much.

[palourde]

For reference, we believe we identified for good the cause behind this problem. We were able to reproduce the same behavior, namely checks not being scheduled but keepalives still coming in, and we now have a pull request open that still need a bit more testing: https://github.com/sensu/sensu-go/pull/3310

It should be part of the 5.14.0 that should be available next week if everything goes well.

[palourde]

Hi everyone! I just wanted to let you know that Sensu Go 5.14.0 is now available and hopefully it will solve this issue for good. If you believe you are still facing this problem, please reach us via Discourse, Slack or open a new issue with some details and logs so we can start investigating. Thanks