Kapacitor: Lost default values

[juise]

Hello!

# kapacitor version
Kapacitor 1.2.0 (git: master 5408057e5a3493d3b5bd38d5d535ea45b587f8ff)

I've follow tick script — https://gist.github.com/juise/15790c2276320554f792a529404b71bb

As you can see, we use default() method like:

    |default()
        .field('threshold_delta_revenue', revenueDeltaThreshold)

After that we use it in out alert message like:

    |alert()
        .message('{{ .Level }} revenue difference at {{ .Time }} between \'mnt_compiled_stats\' ({{ index .Fields "old.revenue" | printf "%0.3f" }}) and \'9vdb\' ({{ index .Fields "new.revenue" | printf "%0.3f" }}) is {{ index .Fields "percent_delta_revenue" | printf "%0.3f" }}% threshold {{ index .Fields "threshold_delta_revenue" }}')
        .warn(lambda: ("percent_delta_revenue" > revenueDeltaThreshold))

But sometimes looks like kapacitor lost default events in various tick scripts:

[events_difference:query1] 2017/03/07 11:00:00 D! starting next batch query: SELECT mean(requests) AS request, mean(impressions) AS impression, mean(clicks) AS click, mean(conversions) AS conversion, mean(revenue) AS revenue, mean(cost) AS cost FROM telegraf.autogen.datamart WHERE datamart = 'mnt_compiled_stats' AND time >= '2017-03-07T08:00:00Z' AND time < '2017-03-07T09:00:00Z' GROUP BY time(1h, 0s) fill(0)
[events_difference:query2] 2017/03/07 11:00:00 D! starting next batch query: SELECT mean(request) AS request, mean(impression) AS impression, mean(click) AS click, mean(conversion) AS conversion, sum(revenue) AS revenue, sum(cost) AS cost FROM telegraf.autogen."9vdb" WHERE interval = 'hour' AND type = 'synthetic' AND time >= '2017-03-07T08:00:00Z' AND time < '2017-03-07T09:00:00Z' GROUP BY time(1h, 0s) fill(0)
...
[events_difference:alert22] 2017/03/07 11:00:00 E! error evaluating expression for level WARNING: no field or tag exists for percent_delta_conversion
[events_difference:alert7] 2017/03/07 11:00:00 E! error evaluating expression for level WARNING: no field or tag exists for percent_delta_cost
[events_difference:alert13] 2017/03/07 11:00:00 E! error evaluating expression for level WARNING: no field or tag exists for percent_delta_request
[events_difference:alert7] 2017/03/07 11:00:00 E! error evaluating expression for level WARNING: no field or tag exists for percent_delta_cost
[events_difference:alert13] 2017/03/07 11:00:00 E! error evaluating expression for level WARNING: no field or tag exists for percent_delta_request
[events_difference:alert16] 2017/03/07 11:00:00 E! error evaluating expression for level WARNING: no field or tag exists for percent_delta_impression
...
[events_difference:alert13] 2017/03/07 11:00:00 D! OK alert triggered id:datamart:nil msg:OK request difference at 2017-03-07 08:00:00 +0000 UTC between 'mnt_compiled_stats' (46739007) and '9vdb' (40002185) is %!f(MISSING)% threshold <no value> data:&{datamart map[] [time new.click new.conversion new.cost new.impression new.request new.revenue old.click old.conversion old.cost old.impression old.request old.revenue percent_delta_click threshold_delta_click threshold_delta_conversion threshold_delta_cost] [[2017-03-07 08:00:00 +0000 UTC 728546 11227 4650.30268 2.6694919e+07 4.0002185e+07 7424.18391 728548 11234 5053.90939562 2.67363e+07 4.6739007e+07 8847.96388335 0.00027451863158489687 1 1 1]]}
[events_difference:alert10] 2017/03/07 11:00:00 D! WARNING alert triggered id:datamart:nil msg:WARNING revenue difference at 2017-03-07 08:00:00 +0000 UTC between 'mnt_compiled_stats' (8847.964) and '9vdb' (7424.184) is %!f(MISSING)% threshold <no value> data:&{datamart map[] [time new.click new.conversion new.cost new.impression new.request new.revenue old.click old.conversion old.cost old.impression old.request old.revenue percent_delta_click threshold_delta_click threshold_delta_conversion threshold_delta_cost] [[2017-03-07 08:00:00 +0000 UTC 728546 11227 4650.30268 2.6694919e+07 4.0002185e+07 7424.18391 728548 11234 5053.90939562 2.67363e+07 4.6739007e+07 8847.96388335 0.00027451863158489687 1 1 1]]}

And what we have in out slack alerts:

[14:00]
WARNING revenue difference at 2017-03-07 08:00:00 +0000 UTC between 'mnt_compiled_stats' (8847.964) and '9vdb' (7424.184) is %!f(MISSING)% threshold <no value>

[14:00]  
OK request difference at 2017-03-07 08:00:00 +0000 UTC between 'mnt_compiled_stats' (46739007) and '9vdb' (40002185) is %!f(MISSING)% threshold <no value>

[14:00]  
OK cost difference at 2017-03-07 08:00:00 +0000 UTC between 'mnt_compiled_stats' (5053.909) and '9vdb' (4650.303) is %!f(MISSING)% threshold 1

But sometimes it's work correctly:

[12:00]  
WARNING revenue difference at 2017-03-07 06:00:00 +0000 UTC between 'mnt_compiled_stats' (9406.509) and '9vdb' (7722.518) is 17.902% threshold 1

[12:00]  
WARNING cost difference at 2017-03-07 06:00:00 +0000 UTC between 'mnt_compiled_stats' (5299.467) and '9vdb' (4904.938) is 7.445% threshold 1

[juise]

Up!

[nathanielc]

@juise Hmm the error message doesn't seem to match the TICKscript segment you provided.

This error here is causing the problem:

E! error evaluating expression for level WARNING: no field or tag exists for percent_delta_conversion

but your warn lambda expression doesn't contain a reference to the percent_delta_conversion field.

Any idea what might be going on there? Is it possible the TICKscript is out of date?

[juise]

@nathanielc Hello!

Hmm the error message doesn't seem to match the TICKscript segment you provided.

If you will take a look at debug log, you will seen right messages:

[events_difference:alert13] 2017/03/07 11:00:00 D! OK alert triggered id:datamart:nil msg:OK request difference at 2017-03-07 08:00:00 +0000 UTC between 'mnt_compiled_stats' (46739007) and '9vdb' (40002185) is %!f(MISSING)% threshold <no value> data:&{datamart map[] [time new.click new.conversion new.cost new.impression new.request new.revenue old.click old.conversion old.cost old.impression old.request old.revenue percent_delta_click threshold_delta_click threshold_delta_conversion threshold_delta_cost] [[2017-03-07 08:00:00 +0000 UTC 728546 11227 4650.30268 2.6694919e+07 4.0002185e+07 7424.18391 728548 11234 5053.90939562 2.67363e+07 4.6739007e+07 8847.96388335 0.00027451863158489687 1 1 1]]}
[events_difference:alert10] 2017/03/07 11:00:00 D! WARNING alert triggered id:datamart:nil msg:WARNING revenue difference at 2017-03-07 08:00:00 +0000 UTC between 'mnt_compiled_stats' (8847.964) and '9vdb' (7424.184) is %!f(MISSING)% threshold <no value> data:&{datamart map[] [time new.click new.conversion new.cost new.impression new.request new.revenue old.click old.conversion old.cost old.impression old.request old.revenue percent_delta_click threshold_delta_click threshold_delta_conversion threshold_delta_cost] [[2017-03-07 08:00:00 +0000 UTC 728546 11227 4650.30268 2.6694919e+07 4.0002185e+07 7424.18391 728548 11234 5053.90939562 2.67363e+07 4.6739007e+07 8847.96388335 0.00027451863158489687 1 1 1]]}

Other messages, it's just example.

This error here is causing the problem:
E! error evaluating expression for level WARNING: no field or tag exists for percent_delta_conversion
but your warn lambda expression doesn't contain a reference to the percent_delta_conversion field.

Yep, you are right! But, as you can see in the script, that I've post https://gist.github.com/juise/15790c2276320554f792a529404b71bb#file-events_difference_batch-tick-L110, the percent_delta_conversion and other percent_delta_* fields will calculate as lambda expression result.

Any idea what might be going on there? Is it possible the TICKscript is out of date?

The script it up to date. I have no idea what is going on, but, the problem is flapping by different percent_delta_* fields, by example:

[05:00] 
OK cost difference at 2017-03-15 23:00:00 +0000 UTC between 'mnt_compiled_stats' (4878.255) and '9vdb' (5078.073) is %!f(MISSING)% threshold 1

[05:00]  
OK revenue difference at 2017-03-15 23:00:00 +0000 UTC between 'mnt_compiled_stats' (7633.473) and '9vdb' (7635.819) is %!f(MISSING)% threshold <no value>

[14:00] 
WARNING revenue difference at 2017-03-16 08:00:00 +0000 UTC between 'mnt_compiled_stats' (7343.249) and '9vdb' (6330.241) is 13.795% threshold 1

[14:00]  
WARNING cost difference at 2017-03-16 08:00:00 +0000 UTC between 'mnt_compiled_stats' (4368.047) and '9vdb' (4129.044) is 5.472% threshold 1

[15:00]  
WARNING revenue difference at 2017-03-16 09:00:00 +0000 UTC between 'mnt_compiled_stats' (7662.019) and '9vdb' (6538.199) is 14.667% threshold 1

[15:00]  
OK cost difference at 2017-03-16 09:00:00 +0000 UTC between 'mnt_compiled_stats' (4747.769) and '9vdb' (4467.411) is %!f(MISSING)% threshold 1

As you can see, sometimes the value is percent - it's okay, sometimes the value is %!f(MISSING)%.

[retexica]

Got same trouble

[nathanielc]

@juise I see now, something is definitely not right. Could you add |log() nodes before and after the eval node on line 109 of your script? Then share the logs for both a good case and a case where the fields ends up missing?

The eval node should always set the value( as you have correctly assumed) so my guess is there is some edge case that is causing it to do otherwise. The log data should help expose that edge case.

[juise]

@nathanielc, I've update tick script and add |log() around every eval node call — https://gist.github.com/juise/5c2460728b91438e1cbcceec8878d408.

You can find the log in attachement — events_difference_kapacitor.log.zip

[juise]

@nathanielc is there any updates on this issue?