Debug log shows unexpected entries

I am posting this on behalf of a customer.
As the customer described in a support case:
this is the code I am running. Note below the code, the associated debug log. Why is it that I am getting debug messages both from the If block and also the else block at the end of the script.

 /***test for the presence of a particular URI in the list of keys from a committed record */
var test_existence = false;
var fields = MetricRecord.fields;
var out_metric_entries = fields.sni_bytes_out.entries;
var out_metric_entry_key_match = "sites.web.com";
var device_object = MetricRecord.object;

for(var entry of out_metric_entries){
if(entry.key.value === out_metric_entry_key_match) {
//debug("success in match of entry.key.value: " + entry.key.value);

test_existence = true;
}
}

if (test_existence = true) {

device_object.metricAddCount("traffic to sites.web.com", 1);
debug("Matched at least one of entry.key.value to ç");
} else {

device_object.metricAddCount("no traffic to sites.web.com", 1);

debug(" 'no traffic to sites.web.com' should be: 1000");
}

The issue is that when I run the trigger, I see erratic behavior on the associate chart and also in the debug log. Please note that I included the trigger code at the end of this email, after the debug log.

First the chart… as you see below I am attempting to graph the two metrics in the trigger. Only one of them should be visible at any one time. When I first start the trigger, I see entries in the debug log indicating that the trigger is running (see the debug log below). However, I do not see anything on the graph. When I go into the script and change the value of the metric in the metricAddCount() method from 1 to 10, then I see the second chart. Note that the appliance goes back and fills in all the missing values in the chart that were not showing before.


Then there is the debug log… it seems that no matter whether the code in the last if/else blocks is being executed, both the debug statements execute. That can’t be right…

[Tue Dec 10 08:55:00]   'no traffic to sites.web.com' should be: 1

[Tue Dec 10 08:55:00]  Matched at least one of entry.key.value to sites.web.com

[Tue Dec 10 08:55:30]   'no traffic to sites.web.com' should be: 1

[Tue Dec 10 08:55:30]  Matched at least one of entry.key.value to sites.web.com

[Tue Dec 10 08:56:00]   'no traffic to sites.web.com' should be: 1

[Tue Dec 10 08:56:00]  Matched at least one of entry.key.value to sites.web.com

[Tue Dec 10 08:56:30]   'no traffic to sites.web.com' should be: 1

[Tue Dec 10 08:56:30]  Matched at least one of entry.key.value to sites.web.com

[Tue Dec 10 08:57:00]   'no traffic to sites.web.com' should be: 1

[Tue Dec 10 08:57:00]  Matched at least one of entry.key.value to sites.web.com

[Tue Dec 10 08:57:30]   'no traffic to sites.web.com' should be: 1

[Tue Dec 10 08:57:30]  Matched at least one of entry.key.value to sites.web.com

[Tue Dec 10 08:58:00]   'no traffic to sites.web.com' should be: 1

[Tue Dec 10 08:58:00]  Matched at least one of entry.key.value to sites.web.com

[Tue Dec 10 08:58:30]   'no traffic to sites.web.com' should be: 1

[Tue Dec 10 08:58:30]  Matched at least one of entry.key.value to sites.web.com

[Tue Dec 10 08:59:00]   'no traffic to sites.web.com' should be: 1

[Tue Dec 10 08:59:00]  Matched at least one of entry.key.value to sites.web.com

[Tue Dec 10 08:59:30]   'no traffic to sites.web.com' should be: 1

[Tue Dec 10 08:59:30]  Matched at least one of entry.key.value to sites.web.com

[Tue Dec 10 09:00:00]   'no traffic to sites.web.com' should be: 1

[Tue Dec 10 09:00:00]  Matched at least one of entry.key.value to sites.web.com

[Tue Dec 10 09:00:30]   'no traffic to sites.web.com' should be: 1

[Tue Dec 10 09:00:30]  Matched at least one of entry.key.value to sites.web.com

[Tue Dec 10 09:01:00]   'no traffic to sites.web.com' should be: 1

[Tue Dec 10 09:01:00]  Matched at least one of entry.key.value to sites.web.com

[Tue Dec 10 09:01:30]   'no traffic to sites.web.com' should be: 1

[Tue Dec 10 09:01:30]  Matched at least one of entry.key.value to sites.web.com

[Tue Dec 10 09:02:00]   'no traffic to sites.web.com' should be: 1

[Tue Dec 10 09:02:00]  Matched at least one of entry.key.value to sites.web.com

[Tue Dec 10 09:02:30]   'no traffic to sites.web.com' should be: 1

[Tue Dec 10 09:02:30]  Matched at least one of entry.key.value to sites.web.com

[Tue Dec 10 09:03:00]   'no traffic to sites.web.com' should be: 1

[Tue Dec 10 09:03:00]  Matched at least one of entry.key.value to sites.web.com

Thank you for any input

A quick look at the code: if “fields” has two values, one “true” and one “false”, you are going to get both entries.

Instead of the for loop, try using something like “out_metric_entries.lookup( “http://sites.web.com/”);” to evaluate the existence of the value. **(no idea if my syntax is correct, btw)

Actually, entries includes entries.key.value which is a string (a URI) and a corresponding entries.value which is a number (the # of byte). In the loop I am simply sequencing over all the keys to see if sites.web.com exists in the list of keys. if it does exist, then i set the flag to true.

The metrics are created once once out of the for loop. depending on the flag “test_existence” either one or the other metric is set to “10”

The problem is that the debug statements execute in more the if block and the else block. That cannot be right…

This is not an equivalency check, but a value assignment. It will always return true, and thus that block of code will always run.

2 Likes

The better way to write this is actually the simpler one, too:

var test_existence = false;
var fields = MetricRecord.fields;
var out_metric_entries = fields.sni_bytes_out.entries;
var out_metric_entry_key_match = "sites.web.com";
var device_object = MetricRecord.object;

for (var entry of out_metric_entries) {
  if (entry.key.value === out_metric_entry_key_match) {
    //debug("success in match of entry.key.value: " + entry.key.value);

    test_existence = true;
  }
}

if (test_existence) {
  device_object.metricAddCount("traffic to sites.web.com", 1);
  debug("Matched at least one of entry.key.value to ç");
} else {
  device_object.metricAddCount("no traffic to sites.web.com", 1);

  debug(" 'no traffic to sites.web.com' should be: 1000");
}

I think the trigger runs in a way that won’t allow this to work as expected. For example, this runs as one would expect:

const entries = MetricRecord.fields.sni_bytes_out['entries']

entries.forEach(entry => {
  if (entry.key.value === 'sites.web.com') {
    debug('match')
  }
})
...
[Thu Dec 13 00:10:00]  match

But when you try and add a boolean flag, the output is not as expected:

const entries = MetricRecord.fields.sni_bytes_out['entries']
let flag

entries.forEach(entry => {
  if (entry.key.value === 'sites.web.com') {
    flag = true
  }
})

debug(`flag value: ${flag}`)

flag ? debug('match') : debug('no match')
....
[Fri Dec 13 00:12:00]  match
[Fri Dec 13 00:12:00]  no match
[Fri Dec 13 00:12:00]  flag value: undefined
[Fri Dec 13 00:12:00]  flag value: true

I think this would be more constructive if we had an idea of what the trigger is trying to accomplish as opposed to trying to work backwards from a dead end. It seems likely that there is an easier way to solve the problem this trigger was intended for.

1 Like

Glad you addressed this; I always cringe a bit when I see the use of a boolean flag instead of doing the operations you want when your condition is met.

The trigger is trying to ascertain whether there is traffic going to sites.web.com by looking through the SNI keys. If it find the SNI it sets a custom metric to a value = 10.

So what I understand here is that a Boolean flag will not work within an if statement and I should use the first construct…

Another source of confusion is due to how the debug() function works. As a reminder, for debug() and log();

Multiple calls to debug and log statements in which the message is the same value will display once every 30 seconds.

Take for instance the following trigger with the METRIC_RECORD_COMMIT event, a Datastore metric type of ‘extrahop.device.ssl_client_detail’ and metric detail of ‘30sec’:

function getRandomInt(min, max) {
  min = Math.ceil(min);
  max = Math.floor(max);
  return Math.floor(Math.random() * (max - min)) + min; //The maximum is exclusive and the minimum is inclusive
}

debug(getRandomInt(1,1000))

This trigger printed ~150 random numbers for me. This is because debug will only display unique messages. I believe the problem with if conditional in this case is that it is being executed far more times than we can reliably track with the debug() function, hence the unexpected behavior.