Rule evaluation failure after reload with newly added rules

[jsravn]

Bug Report

What did you do?

1. docker run -p 9090:9090 prom/prometheus:v2.7.1
2. Edit /etc/prometheus/prometheus.yml, enable the - "first_rules.yml" file.
3. Create /etc/prometheus/first_rules.yml:

groups:       
- name: testgroup
  rules:      
  - record: test            
    expr: 22222         
    labels:             
      instance: my-second

4. Reload prometheus - kill -SIGHUP 1. Everything is fine.
5. Update /etc/prometheus/first_rules.yml:

groups:       
- name: testgroup
  rules:      
  - record: test            
    expr: 11111         
    labels:             
      instance: my-first
  - record: test         
    expr: 22222          
    labels:              
      instance: my-second

6. Reload prometheus - kill -SIGHUP 1.
7. Wait for the next rule evaluation. An error is produced:

level=info ts=2019-02-08T10:28:36.906865554Z caller=main.go:695 msg="Loading configuration file" filename=/etc/prometheus/prometheus.yml
level=info ts=2019-02-08T10:28:36.907330758Z caller=main.go:722 msg="Completed loading of configuration file" filename=/etc/prometheus/prometheus.yml
level=warn ts=2019-02-08T10:28:43.395453805Z caller=manager.go:514 component="rule manager" group=testgroup msg="Error on ingesting results from rule evaluation with different value but same timestamp" numDropped=1

8. Data for the instance: my-second rule is missing at that timestamp.

What did you expect to see?

I expected to see no errors, and data for instance: my-second at the evaluation time. Although they have the same identifier test, they should be unique time series as they have different labels.

What did you see instead? Under which circumstances?

Log error, and missing data for the instance: my-second rule at the evaluation time.

More details

• This only happens when the recording rule identifier matches, and the new rule is prepended before the other ones.
• All the subsequent recording rules with the same identifier fail in the next rule evaluation. After that, they succeed.

Environment

docker container

• System information:

/prometheus $ uname -srm
Linux 4.20.6-arch1-1-ARCH x86_64

• Prometheus version:

/prometheus $ prometheus --version
prometheus, version 2.7.1 (branch: HEAD, revision: 62e591f928ddf6b3468308b7ac1de1c63aa7fcf3)
  build user:       root@f9f82868fc43
  build date:       20190131-11:16:59
  go version:       go1.11.5

• Prometheus configuration file:

/etc/prometheus $ cat prometheus.yml
# my global config
global:
  scrape_interval:     15s # Set the scrape interval to every 15 seconds. Default is every 1 minute.                             
  evaluation_interval: 15s # Evaluate rules every 15 seconds. The default is every 1 minute.                                     
  # scrape_timeout is set to the global default (10s).

# Alertmanager configuration
alerting:
  alertmanagers:
  - static_configs:
    - targets:
      # - alertmanager:9093

# Load rules once and periodically evaluate them according to the global 'evaluation_interval'.                                  
rule_files:                
- "first_rules.yml"
  # - "second_rules.yml"

# A scrape configuration containing exactly one endpoint to scrape:                                                              
# Here it's Prometheus itself.
scrape_configs:
  # The job name is added as a label `job=<job_name>` to any timeseries scraped from this config.                                
  - job_name: 'prometheus'

    # metrics_path defaults to '/metrics'
    # scheme defaults to 'http'.

    static_configs:
    - targets: ['localhost:9090']

/etc/prometheus $ cat first_rules.yml 
groups:
- name: testgroup
  rules:
  - record: test
    expr: 11111
    labels:
      name: my-first
  - record: test
    expr: 22222
    labels:
      name: my-second

• Logs:

level=info ts=2019-02-08T10:28:36.906865554Z caller=main.go:695 msg="Loading configuration file" filename=/etc/prometheus/prometheus.yml
level=info ts=2019-02-08T10:28:36.907330758Z caller=main.go:722 msg="Completed loading of configuration file" filename=/etc/prometheus/prometheus.yml
level=warn ts=2019-02-08T10:28:43.395453805Z caller=manager.go:514 component="rule manager" group=testgroup msg="Error on ingesting results from rule evaluation with different value but same timestamp" numDropped=1  

• Logs with debug on:

level=info ts=2019-02-08T13:55:49.17010164Z caller=main.go:695 msg="Loading configuration file" filename=/etc/prometheus/prometheus.yml
level=debug ts=2019-02-08T13:55:49.171150335Z caller=manager.go:217 component="discovery manager scrape" msg="Starting provider" provider=string/0 subs=[prometheus]
level=debug ts=2019-02-08T13:55:49.171307068Z caller=manager.go:217 component="discovery manager notify" msg="Starting provider" provider=string/0 subs=[defc8654e1f8780ce80f9010266ce592]
level=debug ts=2019-02-08T13:55:49.171393607Z caller=manager.go:235 component="discovery manager scrape" msg="discoverer channel closed" provider=string/0
level=debug ts=2019-02-08T13:55:49.171422194Z caller=manager.go:235 component="discovery manager notify" msg="discoverer channel closed" provider=string/0
level=info ts=2019-02-08T13:55:49.171924503Z caller=main.go:722 msg="Completed loading of configuration file" filename=/etc/prometheus/prometheus.yml
level=debug ts=2019-02-08T13:55:53.394962189Z caller=manager.go:502 component="rule manager" group=testgroup msg="Rule evaluation result discarded" err="duplicate sample for timestamp" sample="{__name__=\"test\", instance=\"my-second\"} => 22222 @[1549634153394]"
level=warn ts=2019-02-08T13:55:53.395017411Z caller=manager.go:514 component="rule manager" group=testgroup msg="Error on ingesting results from rule evaluation with different value but same timestamp" numDropped=1

[simonpasquier]

So I've done some investigation and it was "expected" that when rules are moved around, the first evaluation after the reload may fail... The corner case was documented in 1692f3c (see also 6f813b4) but I don't think it is called out in the docs.

That being said, the code has changed a bit since then and rules within a group are no longer evaluated in parallel so I guess that the stale markers could be inserted after all rules of the group have been evaluated. @brian-brazil what do you think?

[brian-brazil]

That would break rules that depended on previous results in the group.

…

On Fri 8 Feb 2019, 15:34 Simon Pasquier ***@***.*** wrote: So I've done some investigation and it was "expected" that when rules are moved around, the first evaluation after the reload may fail... The corner case was documented in 1692f3c <1692f3c> (see also 6f813b4 <6f813b4>) but I don't think it is called out in the docs. That being said, the code has changed a bit since then and rules within a group are no longer evaluated in parallel so I guess that the stale markers could be inserted after all rules of the group have been evaluated. @brian-brazil <https://github.com/brian-brazil> what do you think? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#5193 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AGyTdqmk9eMoxmojVtPEjLSEWtwc6sz-ks5vLZj_gaJpZM4au4n9> .

[dbrinegar]

Another thought is special case handling on config reload. Keeping manager logic as is, but when config reloads then dump the rule caches: write them all as stale at the time of config reload, empty the previous-seen caches, then on next eval loop everything carries on from scratch with abandoned time series marked stale and resumed time series carrying on after the NaN.

[brian-brazil]

I don't see why we'd write things as stale, we generally want to avoid any changes when there's a reload and the rules remain the same.

[dbrinegar]

Yes that's a bit of a brute force approach with blind writes. Perhaps we could make the config reload handler idea more nuanced and try to remap old rule cache to new rules, so where a rule has simply moved in the list it will carry on with the previous rule's cache.

Then old rules that were deleted or changed would be left over after the remap, and those caches would be candidates to mark stale. We could mark them stale ahead of the new rule eval (a smaller blind pass), or keep them for reconciliation against the results of the new eval. I can see trade-offs either way, but maybe reconciliation at the end of the new eval is the happy path so one can hand old rules results to a new rule and not lose continuity. That path minimizes stale writes, and handles this reorder failure case as well as the case of terminating output of a deleted rule.

The main point of this approach is that the normal path is completely untouched, we just do reconciliation on config reload. Just thinking out loud (and happy to dig into details and test cases in a write up if the approach sounds useful to consider further.)

[brian-brazil]

That sounds kinda like what we do for scrapes, so a similar approach could work. I wouldn't worry about supporting reorders much, they should be rare.

[jsravn]

I made a potential fix in #5368.