Kapacitor: Procstat alerts on all nodes when one influx enterprise node goes down

[cl0udgeek]

I have a tick script that looks like this:

    |query('''
            SELECT count(pid) as count
            from "sdp_monitoring"."13m"."procstat"
            where "pattern" = 'kafka'
            ''')
        .groupBy('cluster', 'host')
        .period(45s)
        .every(10s)
    |deadman(0.0, 10s)
        .stateChangesOnly()
        .exec('/kapacitor/tick-scripts/hpomi.py', 'Kafka Process Down Alert', 'Kafka Process Down', 'Kafka Process Down')

and telegraf input that has this:

[agent]
  interval = "10s"

[global_tags]
  cluster = "{{ kafka_cluster }}"
  broker = "{{ ansible_hostname }}"

[[inputs.procstat]]
  pattern = "kafka"

[[inputs.cpu]]
  percpu = true
  totalcpu = true

[[inputs.disk]]

[[inputs.diskio]]

[[inputs.processes]]

[[inputs.mem]]

[[inputs.system]]

[[outputs.influxdb]]
  urls = [ "{{ influx_cluster }}" ]
  database = "monitoring"
  retention_policy = "13m"
  precision = "s"

I'm also running a 7 node influx cluster (3 meta and 4 data) and have a replication policy on the monitoring db as 2. I've simulated that when I take on influx node down, Kapacitor will throw a process down alert and then right after throw a process up alert on state change. The processes are fine, looks like its being triggered by just taking one influxdb node down.

[desa]

@k1ng87 Thanks for the report. I've got a couple asks

1. Does this happen if any one of the data nodes is taken down? If not, is there a specific one that causes the issue?
2. Would it be possible to see your Kapacitor configuration? The section on InfluxDB in particular.

My current thinking is that Kapacitor is configured against a specific InfluxDB data node in the cluster. And so when that node goes down and is no longer reachable, it triggers the deadman.

One way to verify that this is the case would be to check the Kapacitor logs. If you see logs like the following

[<task_name>:query1] 2017/08/23 10:33:34 E! Post ....

That would be a good indicator.

If this is indeed the case, a quick fix would be to point Kapacitor to the load balancer in front of the data nodes.

The longer term fix, would be to have Kapacitor do some kind of service discovery for all of the data nodes in the cluster.

[cl0udgeek]

@desa its happening when any node goes down. I have kapacitor pointed to an route 53 record that sits in front of any ELB.

[desa]

@k1ng87 That rules that out. When you take down the data node, do you remove that node from the LB?

[cl0udgeek]

nope...just do a service stop

[cl0udgeek]

trying to simulate a failure...it happened when one of my data nodes (ec2 instance) went corrupt.

[desa]

I see. I think I know whats happening.

1. The process is stopped.
2. Eventually Kapacitor queries the node that went down since it was still in the LB.
3. That query fails and results in the deadman being triggered in a CRIT
4. The next query that comes up succeeds and it returns back to OK

There are a couple of things that I can think of that will somewhat remedy the issue in the short term.

1. Increase the time of the deadman to be double that of the every from the query. This way we'll be resilient to the failure of one node going down.
2. Have an external service that pings each of the data nodes in the cluster to see if they're still respond. If they don't respond, trigger an alert, and remove them from the LB.

Both of these are temporary fixes. We'll need a better solution long term, but this should mend things temporarily.

[cl0udgeek]

so right now its this:

    |query('''
            SELECT count(pid) as count
            from "sdp_monitoring"."13m"."procstat"
            where "pattern" = 'kafka'
            ''')
        .groupBy('cluster', 'host')
        .period(45s)
        .every(10s)
    |deadman(0.0, 10s)
        .stateChangesOnly()
        .exec('/kapacitor/tick-scripts/hpomi.py', 'Kafka Process Down Alert', 'Kafka Process Down', 'Kafka Process Down')

so change the deadman or the query?

also, telegraf is sending the procstat input every 10s

[desa]

I'd try changing the deadman

    |query('''
            SELECT count(pid) as count
            from "sdp_monitoring"."13m"."procstat"
            where "pattern" = 'kafka'
            ''')
        .groupBy('cluster', 'host')
        .period(45s)
        .every(10s)
    |deadman(0.0, 20s)
        .stateChangesOnly()
        .exec('/kapacitor/tick-scripts/hpomi.py', 'Kafka Process Down Alert', 'Kafka Process Down', 'Kafka Process Down')

[cl0udgeek]

So gave that a shot but it happened again last night in one of our QA environments...

[desa]

@k1ng87 hmm. My reasoning was a bit off previously. I was assuming, mistakenly, that there was only kapacitor interacting with the cluster.

I'm still pretty sure the issue is related to the LB. I'll do some work today to try to confirm my theory. I'm curious to know if the problem still exists if I remove the downed node from the LB.

My plan is the following

1. Start a 3 data node cluster
2. Point the LB at two of the data nodes
3. Set up the Kapacitor task
4. Kill the data node that doesn't have the LB pointing at it
5. See if deadman is triggered

My guess is that the deadman will not be triggered. And the reason why we're seeing the deadman trigger is that the batch queries keep hitting the same node.

Did you notice if there were any logs like

[<task_name>:query<n>] 2017/08/23 10:33:34 E! Post ....

around the time of the deadman trigger?

Looking at the task a bit more, I think it might be possible to convert this task to a stream task

    |from()
      .database('sdp_monitoring')
      .retentionPolicy('13m')
      .measurement('procstat')
      .where(lambda: "pattern" == 'kafka')
      .groupBy('cluster', 'host')
    |window()
      .period(45s)
      .every(10s)
    |count('pid')
      .as('pid')
    |deadman(0.0, 20s)
        .stateChangesOnly()
        .exec('/kapacitor/tick-scripts/hpomi.py', 'Kafka Process Down Alert', 'Kafka Process Down', 'Kafka Process Down')

Using a stream instead of a batch will remove the LB from the equation.

[cl0udgeek]

so I did upgrade to the current release of influx and taking a node down did not trigger deadman to go off.....but for some reason, deadman got triggered on the env last night...

I did search for this E! Post in the kapacitor logs but did not see anything in there...

will try to changeit to a stream too and see what happens...

[desa]

I'd definitely recommend trying the stream task.

[cl0udgeek]

going to try it but can you help me understand why the logic would run differently in a stream vs batch?

[cl0udgeek]

so I just tried it an it seems the streams one is missing the tags output in the data when it alerts...no bueno :-(

in batch..the data object looks liek this:

"data": {
    "series": [
      {
        "values": [
          [
            "2017-06-20T15:05:06.708243035Z", 
            18.38074168678113
          ]
        ], 
        "name": "cpu", 
        "columns": [
          "time", 
          "mean"
        ], 
        "tags": {
          "cluster": "influx", 
          "host": "ip-5.dqa.domain.com"
        }
      }
    ]
  }

in the stream it looks like this:

"data": {
    "series": [
      {
        "values": [
          [
            "2017-08-25T15:22:00Z", 
            0
          ]
        ], 
        "name": "stats", 
        "columns": [
          "time", 
          "emitted"
        ]
      }
    ]
  }

seems to be missing the tags part...

[desa]

Here's a reference with a bit more detail https://community.influxdata.com/t/batch-versus-stream-processing-combine/792/2

The difference between a stream and a batch is that with a batch task, Kapacitor issues queries to InfluxDB, and with a stream task, all writes to the InfluxDB cluster are mirrored to Kapacitor.

My running theory is that since the downed node is still a part of the LB, it's possible for Kapacitor to issue queries to the downed node, which would result in the deadman firing.

A stream task would remove the LB from the equation since any node if the cluster that receives a write will mirror that write to Kapacitor.

[desa]

so I just tried it an it seems the streams one is missing the tags output in the data when it alerts...no bueno :-(

Not sure I understand what this means. Can you show me the resulting alert data.

[cl0udgeek]

yeah sorry...just made an edit to the post showing it...also...I'm on this version Kapacitor 1.3.1 (git: master 3b5512f7276483326577907803167e4bb213c613)

[desa]

Was this alert data

"data": {
    "series": [
      {
        "values": [
          [
            "2017-06-20T15:05:06.708243035Z", 
            18.38074168678113
          ]
        ], 
        "name": "cpu", 
        "columns": [
          "time", 
          "mean"
        ], 
        "tags": {
          "cluster": "influx", 
          "host": "ip-5.dqa.domain.com"
        }
      }
    ]
  }

generated from a deadman?

[cl0udgeek]

so it just happened again and this is what I see in the kapacitor logs when it happened:

[uncleanelection_alert:query1] 2017/08/25 15:38:40 D! starting next batch query: SELECT mean(metric_value_number) FROM sdp_monitoring."13m".BrokerMetrics WHERE kafka_metric_name = 'UncleanLeaderElectionsPerSec' AND time >= '2017-08-25T15:38:00.593475898Z' AND time < '2017-08-25T15:38:40.593475898Z' GROUP BY cluster, host [uncleanelection_alert:query1] 2017/08/25 15:38:40 E! failed to get conn: dial tcp 10.47.7.252:8088: getsockopt: connection refused [connectproc_alert:query1] 2017/08/25 15:38:44 D! starting next batch query: SELECT count(pid) AS count FROM sdp_monitoring."13m".procstat WHERE pattern = 'connect' AND time >= '2017-08-25T15:37:59.949575339Z' AND time < '2017-08-25T15:38:44.949575339Z' GROUP BY cluster, host [connectproc_alert:query1] 2017/08/25 15:38:44 E! failed to get conn: dial tcp 10.47.1.42:8088: getsockopt: connection refused [cpu_alert:query1] 2017/08/25 15:38:44 D! starting next batch query: SELECT mean(usage_user) FROM sdp_monitoring."13m".cpu WHERE time >= '2017-08-25T15:38:14.955109092Z' AND time < '2017-08-25T15:38:44.955109092Z' GROUP BY cluster, host [cpu_alert:query1] 2017/08/25 15:38:44 E! failed to get conn: dial tcp 10.47.7.252:8088: getsockopt: connection refused [disk_alert:query1] 2017/08/25 15:38:44 D! starting next batch query: SELECT max(used_percent) FROM sdp_monitoring."13m".disk WHERE time >= '2017-08-25T15:33:44.966570636Z' AND time < '2017-08-25T15:38:44.966570636Z' GROUP BY cluster, host [disk_alert:query1] 2017/08/25 15:38:44 E! failed to get conn: dial tcp 10.47.1.42:8088: getsockopt: connection refused [mem_alert:query1] 2017/08/25 15:38:44 D! starting next batch query: SELECT mean(used_percent) FROM sdp_monitoring."13m".mem WHERE time >= '2017-08-25T15:37:44.993644144Z' AND time < '2017-08-25T15:38:44.993644144Z' GROUP BY cluster, host [mem_alert:query1] 2017/08/25 15:38:45 E! failed to get conn: dial tcp 10.47.7.252:8088: getsockopt: connection refused [schemaproc_alert:query1] 2017/08/25 15:38:45 D! starting next batch query: SELECT count(pid) AS count FROM sdp_monitoring."13m".procstat WHERE pattern = 'schemar' AND time >= '2017-08-25T15:38:00.004506299Z' AND time < '2017-08-25T15:38:45.004506299Z' GROUP BY cluster, host [schemaproc_alert:query1] 2017/08/25 15:38:45 E! failed to get conn: dial tcp 10.47.7.252:8088: getsockopt: connection refused [schemarproc_alert:query1] 2017/08/25 15:38:45 D! starting next batch query: SELECT count(pid) AS count FROM sdp_monitoring."13m".procstat WHERE pattern = 'schemar' AND time >= '2017-08-25T15:38:00.010261082Z' AND time < '2017-08-25T15:38:45.010261082Z' GROUP BY cluster, host [schemarproc_alert:query1] 2017/08/25 15:38:45 E! failed to get conn: dial tcp 10.47.7.252:8088: getsockopt: connection refused [zookeeperproc_alert:query1] 2017/08/25 15:38:45 D! starting next batch query: SELECT count(pid) AS count FROM sdp_monitoring."13m".procstat WHERE pattern = 'zookeeper' AND time >= '2017-08-25T15:38:00.038542172Z' AND time < '2017-08-25T15:38:45.038542172Z' GROUP BY cluster, host [zookeeperproc_alert:query1] 2017/08/25 15:38:45 E! failed to get conn: dial tcp 10.47.7.252:8088: getsockopt: connection refused [kafkaproc_alert:query1] 2017/08/25 15:38:48 D! starting next batch query: SELECT count(pid) AS count FROM sdp_monitoring."13m".procstat WHERE pattern = 'kafka' AND time >= '2017-08-25T15:38:03.070066125Z' AND time < '2017-08-25T15:38:48.070066125Z' GROUP BY cluster, host [kafkaproc_alert:query1] 2017/08/25 15:38:48 E! failed to get conn: dial tcp 10.47.1.42:8088: getsockopt: connection refused [kafka_upr_alert:query1] 2017/08/25 15:38:48 D! starting next batch query: SELECT mean(metric_value_number) FROM sdp_monitoring."13m".BrokerMetrics WHERE kafka_metric_name = 'UnderReplicatedPartitions' AND time >= '2017-08-25T15:38:08.585839971Z' AND time < '2017-08-25T15:38:48.585839971Z' GROUP BY cluster, host [kafka_upr_alert:query1] 2017/08/25 15:38:48 E! failed to get conn: dial tcp 10.47.7.252:8088: getsockopt: connection refused [offline_partition_alert:query1] 2017/08/25 15:38:49 D! starting next batch query: SELECT mean(metric_value_number) FROM sdp_monitoring."13m".BrokerMetrics WHERE kafka_metric_name = 'OfflinePartitionsCount' AND time >= '2017-08-25T15:38:09.701383591Z' AND time < '2017-08-25T15:38:49.701383591Z' GROUP BY cluster, host [offline_partition_alert:query1] 2017/08/25 15:38:49 E! failed to get conn: dial tcp 10.47.1.42:8088: getsockopt: connection refused [uncleanelection_alert:query1] 2017/08/25 15:38:50 D! starting next batch query: SELECT mean(metric_value_number) FROM sdp_monitoring."13m".BrokerMetrics WHERE kafka_metric_name = 'UncleanLeaderElectionsPerSec' AND time >= '2017-08-25T15:38:10.593466722Z' AND time < '2017-08-25T15:38:50.593466722Z' GROUP BY cluster, host [uncleanelection_alert:query1] 2017/08/25 15:38:50 E! failed to get conn: dial tcp 10.47.7.252:8088: getsockopt: connection refused [connectproc_alert:query1] 2017/08/25 15:38:54 D! starting next batch query: SELECT count(pid) AS count FROM sdp_monitoring."13m".procstat WHERE pattern = 'connect' AND time >= '2017-08-25T15:38:09.949580921Z' AND time < '2017-08-25T15:38:54.949580921Z' GROUP BY cluster, host [connectproc_alert:query1] 2017/08/25 15:38:54 E! failed to get conn: dial tcp 10.47.1.42:8088: getsockopt: connection refused [cpu_alert:query1] 2017/08/25 15:38:54 D! starting next batch query: SELECT mean(usage_user) FROM sdp_monitoring."13m".cpu WHERE time >= '2017-08-25T15:38:24.955099869Z' AND time < '2017-08-25T15:38:54.955099869Z' GROUP BY cluster, host [cpu_alert:query1] 2017/08/25 15:38:54 E! failed to get conn: dial tcp 10.47.1.42:8088: getsockopt: connection refused [disk_alert:query1] 2017/08/25 15:38:54 D! starting next batch query: SELECT max(used_percent) FROM sdp_monitoring."13m".disk WHERE time >= '2017-08-25T15:33:54.966570028Z' AND time < '2017-08-25T15:38:54.966570028Z' GROUP BY cluster, host [disk_alert:query1] 2017/08/25 15:38:54 E! failed to get conn: dial tcp 10.47.1.42:8088: getsockopt: connection refused [mem_alert:query1] 2017/08/25 15:38:54 D! starting next batch query: SELECT mean(used_percent) FROM sdp_monitoring."13m".mem WHERE time >= '2017-08-25T15:37:54.993640223Z' AND time < '2017-08-25T15:38:54.993640223Z' GROUP BY cluster, host [mem_alert:query1] 2017/08/25 15:38:54 E! failed to get conn: dial tcp 10.47.1.42:8088: getsockopt: connection refused [schemaproc_alert:query1] 2017/08/25 15:38:55 D! starting next batch query: SELECT count(pid) AS count FROM sdp_monitoring."13m".procstat WHERE pattern = 'schemar' AND time >= '2017-08-25T15:38:10.004497407Z' AND time < '2017-08-25T15:38:55.004497407Z' GROUP BY cluster, host [schemarproc_alert:query1] 2017/08/25 15:38:55 D! starting next batch query: SELECT count(pid) AS count FROM sdp_monitoring."13m".procstat WHERE pattern = 'schemar' AND time >= '2017-08-25T15:38:10.010253585Z' AND time < '2017-08-25T15:38:55.010253585Z' GROUP BY cluster, host [schemaproc_alert:query1] 2017/08/25 15:38:55 E! failed to get conn: dial tcp 10.47.1.42:8088: getsockopt: connection refused [schemarproc_alert:query1] 2017/08/25 15:38:55 E! failed to get conn: dial tcp 10.47.1.42:8088: getsockopt: connection refused [zookeeperproc_alert:query1] 2017/08/25 15:38:55 D! starting next batch query: SELECT count(pid) AS count FROM sdp_monitoring."13m".procstat WHERE pattern = 'zookeeper' AND time >= '2017-08-25T15:38:10.03853013Z' AND time < '2017-08-25T15:38:55.03853013Z' GROUP BY cluster, host [zookeeperproc_alert:query1] 2017/08/25 15:38:55 E! failed to get conn: dial tcp 10.47.7.252:8088: getsockopt: connection refused [kafkaproc_alert:query1] 2017/08/25 15:38:58 D! starting next batch query: SELECT count(pid) AS count FROM sdp_monitoring."13m".procstat WHERE pattern = 'kafka' AND time >= '2017-08-25T15:38:13.070055764Z' AND time < '2017-08-25T15:38:58.070055764Z' GROUP BY cluster, host [kafkaproc_alert:query1] 2017/08/25 15:38:58 E! failed to get conn: dial tcp 10.47.1.42:8088: getsockopt: connection refused [kafka_upr_alert:query1] 2017/08/25 15:38:58 D! starting next batch query: SELECT mean(metric_value_number) FROM sdp_monitoring."13m".BrokerMetrics WHERE kafka_metric_name = 'UnderReplicatedPartitions' AND time >= '2017-08-25T15:38:18.585845744Z' AND time < '2017-08-25T15:38:58.585845744Z' GROUP BY cluster, host [kafka_upr_alert:query1] 2017/08/25 15:38:58 E! failed to get conn: dial tcp 10.47.7.252:8088: getsockopt: connection refused [offline_partition_alert:query1] 2017/08/25 15:38:59 D! starting next batch query: SELECT mean(metric_value_number) FROM sdp_monitoring."13m".BrokerMetrics WHERE kafka_metric_name = 'OfflinePartitionsCount' AND time >= '2017-08-25T15:38:19.701395415Z' AND time < '2017-08-25T15:38:59.701395415Z' GROUP BY cluster, host [offline_partition_alert:query1] 2017/08/25 15:38:59 E! failed to get conn: dial tcp 10.47.1.42:8088: getsockopt: connection refused

all of those IPs are influx nodes...

naw...but just an example...that was a CPU one but deadman in batch includes the tags part too.

[desa]

Whats the replication factor on sdp_monitoring."13m"

[cl0udgeek]

have a replication factor of 2....running 4 data nodes and 3 meta nodes...

[desa]

@k1ng87 Just tested the stream version myself, and there's an initial trigger of the deadman that doesn't have tags, but that goes away after the deadman starts receiving data. Can you confirm that this is not the behavior you're seeing.

Before data:

"data":
{
  "series": [
    {
      "name": "stats",
      "columns": [
        "time",
        "emitted"
      ],
      "values": [
        [
          "2017-08-25T16:18:10Z",
          0
        ]
      ]
    }
  ]
}

After data

"data":
{
  "series": [
    {
      "name": "stats",
      "tags": {
        "cluster_id": "michaels-example-cluster",
        "cpu": "cpu-total",
        "host": "Michaels-MBP-2.router.edm"
      },
      "columns": [
        "time",
        "emitted"
      ],
      "values": [
        [
          "2017-08-25T16:03:30Z",
          1
        ]
      ]
    }
  ]
}

[desa]

Were those logs from the time when a data node was downed? Or just during normal runtime?

[cl0udgeek]

no, the data nodes were up and running...that happened when I started to see kapacitor throw alerts on deadman...that was also when the tick scripts were running in batch mode but now redeploying to run in stream mode

----EDIT------

correction...those two nodes were down...just didn't notice it before until a coworker pointed out the health check...

[cl0udgeek]

so I switched the tick scripts to do streams now but now I'm not getting alerts...I see that it is subscribed to influx and the tasks are running but don't see any alerts come through.

[desa]

What's the output of

kapacitor show <task name>

This should show us where things are getting hung up.

[cl0udgeek]

nvm....configured the hostname wrong in the kapacitor config...working now

[cl0udgeek]

I'd like to open this backup as this still keeps happening...I did notice that kapacitor was maxing out the CPU so we bumped the ec2 to a c4.4xlarge but now they keep happening sporadically where all of the deadman alerts go off.

The ec2 runs on an ASG and if I terminate the ec2 and let ASG build a new one it works fine for some time but the then the behavior comes back. Looked at disk space and memory and those are fine too and influx is healthy as well but still unsure why this is still happening.