Sensu-go: Entity definition not updated in round robin proxy checks

[ybulach]

Hi !

When executing a round robin check for proxy entities, the entities definition does not seem to
be updated when some attributes are modified (tested with annotations and subscriptions) and the
resulting command with token substitution uses old attributes.

Expected Behavior

Updated annotations, subscriptions, etc. of proxy entities are expected to be used by round robin
proxy checks tokens substitution (i.e. an IP address).

Current Behavior

Round robin proxy checks use old annotations on tokens substitution, as seen in events (but the
entity definition in events is up to date).

Non round-robin checks with the same definition work as expected.

Steps to Reproduce (for bugs)

Using Docker, create two containers (a backend and an agent) using this docker-compose file:

version: "3"

services:
  backend:
    image: sensu/sensu:5.21.0
    hostname: backend
    command: sensu-backend start --log-level debug
    ports:
      - 3000:3000
      - 8080:8080
    volumes:
      - ./backend:/var/lib/sensu
    networks:
      sensu:

  agent:
    image: sensu/sensu:5.21.0
    hostname: agent
    command: sensu-agent start --backend-url 'ws://backend:8081' --subscriptions proxy
    depends_on:
      - backend
    networks:
      sensu:

networks:
  sensu:

Create a proxy entity and a dummy check:

---
type: CheckConfig
api_version: core/v2
metadata:
  name: ping
spec:
  check_hooks: null
  command: ping {{ .annotations.ip_address }} -c 3
  interval: 15
  proxy_requests:
    entity_attributes:
    - entity.entity_class == 'proxy'
  publish: true
  round_robin: true
  subscriptions:
  - proxy
  timeout: 10

---
type: Entity
api_version: core/v2
metadata:
  annotations:
    ip_address: 127.0.0.1
  name: proxy
spec:
  entity_class: proxy



md5-65466e3693937ca423be9dc77249a040



$ sensuctl event info proxy ping --format json | jq .entity.metadata.annotations.ip_address
"127.0.0.1"
$ sensuctl event info proxy ping --format json | jq .check.command                         
"ping 127.0.0.1 -c 3"



md5-d6050a61fa092925010ee0a150a1dd4c



---
type: Entity
api_version: core/v2
metadata:
  annotations:
    ip_address: 8.8.8.8
  name: proxy
spec:
  entity_class: proxy



md5-f05c026bb09947bf4a6b467305e0f75b



$ sensuctl event info proxy ping --format json | jq .entity.metadata.annotations.ip_address
"8.8.8.8"
$ sensuctl event info proxy ping --format json | jq .check.command                         
"ping 127.0.0.1 -c 3"



md5-6520ad082c716af99b3f0bd401316177



{"component":"cache","level":"debug","msg":"rebuilding the cache for resource type *v2.Silenced","time":"2020-06-25T14:52:19Z"}
{"component":"cache","level":"debug","msg":"rebuilding the cache for resource type *v2.Entity","time":"2020-06-25T14:52:19Z"}

The same steps but with a check with round_robin: false work as expected.

Context

In real life, i use proxy entities with many annotations (usernames, password, ip addresses, etc.) as well as subscriptions
to filter them with proxy_requests.entity_attributes. Many agents run those proxy checks, so round_robin is a must have.

Your Environment

• Sensu version used: 5.21.0
• Installation method: Docker

[echlebek]

Do subsequent executions of the check also exhibit this problem? The entity cache is only updated every 5 seconds, and is not invalidated/refreshed when entities change.

[ybulach]

All executions of the check show this problem (have seen it last for days). The only way i found for now is to restart the backends, so the new entities definitions are cached.

[mcbsd]

We are facing exactly same issue. What we do, as we don't want to restart the sensu backend, we delete and create proxy check - then all new definitions are propagated properly.
Even when check interval is changed on fly (without backend restart or delete/create), it has no effect and check is scheduled all time according "buffered" value when it was loaded completely from scratch very last time (which is even service restart of delete/create)
I'd say this is pretty serious as it breaks the generic concept of Sensu management.

[echlebek]

Please list your Sensu version, OS, etcd version (if applicable), and hardware configuration. Many people are updating checks without issue, and we do explicit QA around updating checks, so it will likely be difficult to reproduce the issue.

[mcbsd]

@echlebek
Our setup:
5.21.0 compiled from source; cluster with 3 nodes
embedded etcd
RedHat 7.8
Virtual Machine on RedHat Virtualization cluster
Proxy checks are configured to be scheduled round robin with splay enabled

If you need additional inputs, or some debug outputs. Please let us know.

[mcbsd]

We just verified this on ad hoc created "one node" Sensu Go instance with 5.21.0 enterprise version and we observe the same.
We defined proxy check with 5 min interval. It was scheduled every 5 min automatically. Then we redefined the check to have interval 60s with result that check definition visible in GUI was seen with 60s interval but in reality it was still scheduled by 5 min from previous definition. When we restarted backend service, only then the scheduling switched to 60s interval.

[echlebek]

If you run the service at INFO log level, and change the interval of a check, do you then observe a log message that says "restarting scheduler"?

[mcbsd]

@echlebek
After the check definition is changed, these messages popped up:

sensu-backend[7415]: {"component":"schedulerd","level":"info","msg":"check configs updated","time":"2020-07-16T09:36:49+02:00"}
sensu-backend[7415]: {"component":"schedulerd","level":"info","msg":"restarting scheduler","time":"2020-07-16T09:36:49+02:00"}

After that, we observed behavior as reported - check was still scheduled according previous interval definition even it was displayed correctly (definition itself) in the dashboard or via sensuctl.

[mcbsd]

@echlebek
Hi, did the output help? Anything else what we can provide from our side?

[nikkictl]

Thanks for providing additional logs for this issue. I was able to reproduce it as you've described, but did not observe the restarting scheduler log message. After restarting the backend, the issue resolves itself and the new entity information is loaded in the check command. Since the scheduler is not getting restarted, that is likely the culprit of this bug!

[nikkictl]

The more I do look into this though, I notice that we only trigger scheduler restarts via an interrupt when the check is updated, not when the entity is updated. This leads me to believe that the proxy entities loaded into the round robin schedulers are perhaps stale.

[mcbsd]

Hi @nikkictl , any news when this could be fixed? Thank You.

[nikkictl]

@mcbsd we'll probably want to re-evaluate this bug now that 6.0 has shipped and some changes around entity management have occurred. I'll see what I can do to have this investigation planned!

[calebhailey]

Is #3876 related?

[nikkictl]

@calebhailey I think more investigation would be required to determine if #3876 is related, but I could see how some related components could cause similar behaviors.

@mcbsd this work is planned and we hope to have a fix in an upcoming release!

[nikkictl]

I was able to determine the cause of this bug. https://github.com/sensu/sensu-go/commit/b237584bd4d6be5fe7873d258d25d5ad17fb3036 retains a copy of the original check command and replaces it within the event's check to guard against publishing sensitive/redacted client attribute values. This approach is problematic because while it protects redacted values from being shown, it can actually emit stale data (like described in the original issue).

For proxy requests, token substitution actually occurs before the check request is sent (ex. for entity matching), so unless we want to bloat the message that is sent across the wire (sending the original commands for all checks and hooks), we might want to consider reconciling this issue in the backend, rather than the agent. Modifying the check request could have implications on backend/agent compatibility as well.

This is a tricky one, I am trying to determine which Sensu component should be responsible for ensuring this behavior in a secure way (ex. schedulerd could send the original store values, eventd could replace the check command with what is in the store). The expected behavior should really reflected the pre-substituted value to protect potentially redacted values and prevent stale values from being populated.

@mcbsd expected behavior:

$ sensuctl event info proxy ping --format json | jq .check.command                         
"ping new_value -c 3"

What I believe the more secure expected behavior should be:

$ sensuctl event info proxy ping --format json | jq .check.command                         
"ping {{ .annotations.ip_address }} -c 3"

[nikkictl]

Another issue in how this current behavior manifests itself is with redacted values in the check command:

$ sensuctl event info proxy ping --format json | jq .check.command
"ping 127.0.0.1 -c 3"
$ sensuctl event info proxy ping --format json | jq .entity.metadata.annotations.ip_address
"127.0.0.1"

# redact ip_address within the proxy entity
$ sensuctl edit entity proxy
Updated /api/core/v2/namespaces/default/entities/proxy
$ sensuctl event info proxy ping --format json | jq .check.command
"ping 127.0.0.1 -c 3"
$ sensuctl event info proxy ping --format json | jq .entity.metadata.annotations.ip_address
"REDACTED"

[nikkictl]

This has been resolved in https://github.com/sensu/sensu-go/pull/4008 and is expected to release in 6.1.0!

[mcbsd]

@nikkictl thanks a lot!