Sensu-go: Proxy check requests are scheduled too infrequently

[nikkictl]

It appears that events for proxy check requests are not updated each interval. Rather, the splayed executions are not scheduled until _after_ the whole interval.

Expected Behavior

60 second check interval, 2 proxy entities, 50% splay:

• 60s between proxy1 executions
• 60s between proxy2 executions
• 15s between proxy1 -> proxy2 execution

Current Behavior

60 second check interval, 2 proxy entities, 50% splay:

• 90s between proxy1 executions
• 90s between proxy2 executions
• 15s between proxy1 -> proxy2 execution

Possible Solution

Splayed executions should be scheduled immediately, not after the original interval.

Steps to Reproduce (for bugs)

1. Create the following proxy entities

{
  "type": "Entity",
  "api_version": "core/v2",
  "metadata": {
    "name": "proxy1",
    "namespace": "default"
  },
  "spec": {
    "deregister": false,
    "deregistration": {},
    "entity_class": "proxy",
    "last_seen": 0,
    "subscriptions": null,
    "system": {
      "network": {
        "interfaces": null
      }
    }
  }
}
{
  "type": "Entity",
  "api_version": "core/v2",
  "metadata": {
    "name": "proxy2",
    "namespace": "default"
  },
  "spec": {
    "deregister": false,
    "deregistration": {},
    "entity_class": "proxy",
    "last_seen": 0,
    "subscriptions": null,
    "system": {
      "network": {
        "interfaces": null
      }
    }
  }
}

1. Create the following check

{
  "type": "CheckConfig",
  "api_version": "core/v2",
  "metadata": {
    "name": "check-proxy",
    "namespace": "default"
  },
  "spec": {
    "check_hooks": null,
    "command": "echo hi",
    "env_vars": null,
    "handlers": [],
    "high_flap_threshold": 0,
    "interval": 60,
    "low_flap_threshold": 0,
    "output_metric_format": "",
    "output_metric_handlers": null,
    "proxy_entity_name": "",
    "proxy_requests": {
      "entity_attributes": [
        "entity.entity_class == 'proxy'"
      ],
      "splay": true,
      "splay_coverage": 50
    },
    "publish": true,
    "round_robin": false,
    "runtime_assets": null,
    "stdin": false,
    "subdue": null,
    "subscriptions": [
      "proxy"
    ],
    "timeout": 0,
    "ttl": 0
  }
}

1. Start the backend
2. Start the agent (--subscriptions proxy)
3. Executions are 90 seconds apart: sensuctl event info proxy1 check-proxy --format json | jq .check.history
4. Executions are 90 seconds apart: sensuctl event info proxy2 check-proxy --format json | jq .check.history

Context

With the check splay and proxy entity configurations, each check should execute every 60 seconds (and 15 seconds apart from each other: 60 second interval * 50% / 2 entities = 15 second splay). The current behavior is not at parity with 1.x or docs.

Reported by AdamskiEM/@adammcdonagh in the community slack.

Your Environment

• Sensu version used (sensuctl, sensu-backend, and/or sensu-agent): 5.9.0
• Installation method (packages, binaries, docker etc.): binaries
• Operating System and version (e.g. Ubuntu 14.04): MacOS

[palourde]

We should try first to reproduce and detect this issue in the our automated testing!

[nikkictl]

@palourde The automated test is flaky at best. But it only validates the splay between two different checks, rather than additionally validating the proper interval in the check history. I'll add a note to https://github.com/sensu/sensu-go-qa-crucible/issues/41 about this.

[roganartu]

I noticed this recently, and did some digging. I believe I have found the root cause of this, and figured I should provide details to make it easier for whoever ends up fixing this.

https://github.com/sensu/sensu-go/blob/27ad8a3db009abfee339de2ad649a7f74266291f/backend/schedulerd/interval_scheduler.go#L47-L60
This is where the logic controlling the scheduling and the resulting wait occur. The defer means that the timer isn't reset until the check has been published, which is probably a bug in general, but I suspect the time taken to publish a single check isn't long enough to notice this in the non-proxy case.

Basically, what the defer results in (as described in the issue above) is the check schedule time drifting by approximately the amount of time it takes for executor.processCheck on line 57 to complete.

This executor.processCheck call ultimately ends up here:
https://github.com/sensu/sensu-go/blob/27ad8a3db009abfee339de2ad649a7f74266291f/backend/schedulerd/executor.go#L248-L257
Where you can see that we sleep for splay * numEntities number of seconds, and since splay is calculated as splay_coverage / 100.0 * interval / num_entities this results in check scheduling drifting by approximately interval * splay_percentage every time the timer fires.

A simple solution is to remove the defer so that the timer is reset immediately, though I'm not sure whether that creates a condition where the a timer could fire for a check that is still being scheduled (say with a splay_coverage of 100%). Perhaps a more robust solution would be to time the function internally and reset the timer to interval - func_time, eg:

func (s *IntervalScheduler) schedule(timer CheckTimer, executor *CheckExecutor) {
    start := time.Now()
    defer func() {
        elapsed := time.Since(start)
        s.resetTimerLess(timer, elapsed)
    }
    ...
} 

Where resetTimerLess resets the timer to min(0, s.check.Interval - elapsed). resetTimer doesn't appear to be used anywhere else though, so perhaps it's ok to break that existing interface to add the elapsed arg.

I'm happy to draft a PR if we can agree on an approach.

[echlebek]

I like the idea of resetting the timer immediately. Since this function is executed in the same goroutine as the select that consumes the timer, it should be safe, and produce a more accurate result. Thanks @roganartu