Nomad autodiscover fails to pick up some tasks

Nomad autodiscover introduced in #16853 seems to completely miss some new Nomad tasks, and therefore never ship any logs for them. The cause seems to be that it uses event's `AllocModifyIndex` to check for changes, when it should actually use `ModifyIndex`.

- Version: 7.13.4 (amd64)
- Operating System: CentOS 8
- Discuss Forum URL:
- Steps to Reproduce: 

## Test setup

1) Let's start a local Nomad dev instance. I'm using sudo here, because my task run with exec driver. This also requires sudo for alloc tasks later.

```bash
$ ./nomad version
Nomad v1.1.2 (60638a086ef9630e2a9ba1e237e8426192a44244)
$ sudo ./nomad agent -dev -alloc-dir /tmp/nomad_alloc -bind 0.0.0.0 -log-level=INFO
```

2) Let's run filebeat with a minimal Nomad autodiscovery config outputting to `/tmp`:

```yml
filebeat.autodiscover.providers:
  - type: nomad
    address: http://127.0.0.1:4646
    scope: node
    hints.enabled: true
    templates:
    - config:
      - type: log
        paths:
          - "/tmp/nomad_alloc/${data.nomad.allocation.id}/alloc/logs/${data.meta.nomad.task.name}.stderr.[0-9]*"
          - "/tmp/nomad_alloc/${data.nomad.allocation.id}/alloc/logs/${data.meta.nomad.task.name}.stdout.[0-9]*"

output.file:
  path: /tmp
  filename: filebeat.json

logging.level: debug
logging.to_files: true
logging.files:
  path: /tmp
  name: filebeat.log
```

```bash
rm /tmp/filebeat*; ./filebeat
```

3) Let's save Nomad allocation events for later comparison

```bash
$ curl -kSs "localhost:4646/v1/event/stream?topic=Allocation" > /tmp/alloc-events.json
```

4) Let's run some test jobs

[I created two test jobs](https://gist.github.com/zemm/dbf12775566bef26b0c49d19ed008143) with tasks that are just `exec` scripts which produce test log by printing out it's name and a counter from 1 to 10 in intervals of 1 second, after which they idle silently. There should be 10 lines of log per task at the end.

Let's run two test jobs. The fist one consists of two groups of one task each. The second one has one group with three tasks. It's not that important, but this setup reproduced the problem for me. Optionally wait some time in between.

```bash
$ nomad job run count-to-ten-1.hcl
==> Monitoring evaluation "6cb442a9"
    Evaluation triggered by job "count-to-ten-1"
    Evaluation within deployment: "4cb7bdef"
    Allocation "1a7c549f" created: node "40f5ad2f", group "group-1"
    Allocation "a02e35fa" created: node "40f5ad2f", group "group-2"
    Evaluation status changed: "pending" -> "complete"
==> Evaluation "6cb442a9" finished with status "complete"
$ sleep 7
$ nomad job run count-to-ten-2.hcl
==> Monitoring evaluation "c2704d2b"
    Evaluation triggered by job "count-to-ten-2"
    Evaluation within deployment: "04da1cf1"
    Allocation "3bb7e48c" created: node "40f5ad2f", group "group"
    Allocation "8ebe0866" created: node "40f5ad2f", group "group"
    Allocation "d01ac162" created: node "40f5ad2f", group "group"
    Evaluation status changed: "pending" -> "complete"
==> Evaluation "c2704d2b" finished with status "complete"
```


## Inspecting the results

We should have five allocations:

```bash
$ sudo ls -1 /tmp/nomad_alloc/
1a7c549f-9895-ea29-9ad0-630e95ddaf4f
3bb7e48c-14f3-c055-5c36-ce5966369111
8ebe0866-9a44-b1f8-26a8-2e5d1cf32af5
a02e35fa-c0bd-bf0e-107f-0f6a045664e2
d01ac162-279d-3b1f-3ff6-1258c3dec022
```

The allocations should have produced 50 lines of log (5 times 10 lines):

```bash
$ sudo sh -c 'cat /tmp/nomad_alloc/*/alloc/logs/*stdout.0'|wc -l
50
```

We **should have 50** lines of filebeat log, but in my case I **only got 30**. This will vary between the runs, but most of the time some tasks are never picked up.

```bash
$ cat /tmp/filebeat.json |jq -r '.message'|wc -l
30
```


## Analyzing the problem

The watcher prints out allocation info when it receives an event of allocation that is running:

```bash
$ cat /tmp/filebeat.log |grep allocation.id
2021-07-23T22:52:08.881Z        DEBUG   [nomad] nomad/watcher.go:162    allocation.id=3bb7e48c-14f3-c055-5c36-ce5966369111 waitIndex=13 CreateIndex=17 ModifyIndex=25 AllocModifyIndex=17 updated=false
2021-07-23T22:52:08.901Z        DEBUG   [nomad] nomad/watcher.go:162    allocation.id=8ebe0866-9a44-b1f8-26a8-2e5d1cf32af5 waitIndex=13 CreateIndex=17 ModifyIndex=25 AllocModifyIndex=17 updated=false
2021-07-23T22:52:08.902Z        DEBUG   [nomad] nomad/watcher.go:162    allocation.id=d01ac162-279d-3b1f-3ff6-1258c3dec022 waitIndex=13 CreateIndex=17 ModifyIndex=25 AllocModifyIndex=17 updated=false
```

I only got 3 of the 5 allocations here, as inspected with the 30 log lines shipped. Now let's inspect the Nomad allocations event stream that was saved in the beginning:

```bash
$ cat /tmp/alloc-events.json | jq -rf ./filter-alloc-events-2.jq 2>/dev/null
1a7c549f-9895-ea29-9ad0-630e95ddaf4f CreateIndex=11 ModifyIndex=11 AllocModifyIndex=11 DesiredStatus=run ClientStatus=pending Type=PlanResult
a02e35fa-c0bd-bf0e-107f-0f6a045664e2 CreateIndex=11 ModifyIndex=11 AllocModifyIndex=11 DesiredStatus=run ClientStatus=pending Type=PlanResult
a02e35fa-c0bd-bf0e-107f-0f6a045664e2 CreateIndex=11 ModifyIndex=13 AllocModifyIndex=11 DesiredStatus=run ClientStatus=pending Type=AllocationUpdated
1a7c549f-9895-ea29-9ad0-630e95ddaf4f CreateIndex=11 ModifyIndex=13 AllocModifyIndex=11 DesiredStatus=run ClientStatus=pending Type=AllocationUpdated
1a7c549f-9895-ea29-9ad0-630e95ddaf4f CreateIndex=11 ModifyIndex=15 AllocModifyIndex=11 DesiredStatus=run ClientStatus=running Type=AllocationUpdated
a02e35fa-c0bd-bf0e-107f-0f6a045664e2 CreateIndex=11 ModifyIndex=15 AllocModifyIndex=11 DesiredStatus=run ClientStatus=running Type=AllocationUpdated
d01ac162-279d-3b1f-3ff6-1258c3dec022 CreateIndex=17 ModifyIndex=17 AllocModifyIndex=17 DesiredStatus=run ClientStatus=pending Type=PlanResult
3bb7e48c-14f3-c055-5c36-ce5966369111 CreateIndex=17 ModifyIndex=17 AllocModifyIndex=17 DesiredStatus=run ClientStatus=pending Type=PlanResult
8ebe0866-9a44-b1f8-26a8-2e5d1cf32af5 CreateIndex=17 ModifyIndex=17 AllocModifyIndex=17 DesiredStatus=run ClientStatus=pending Type=PlanResult
3bb7e48c-14f3-c055-5c36-ce5966369111 CreateIndex=17 ModifyIndex=19 AllocModifyIndex=17 DesiredStatus=run ClientStatus=pending Type=AllocationUpdated
8ebe0866-9a44-b1f8-26a8-2e5d1cf32af5 CreateIndex=17 ModifyIndex=19 AllocModifyIndex=17 DesiredStatus=run ClientStatus=pending Type=AllocationUpdated
d01ac162-279d-3b1f-3ff6-1258c3dec022 CreateIndex=17 ModifyIndex=19 AllocModifyIndex=17 DesiredStatus=run ClientStatus=pending Type=AllocationUpdated
1a7c549f-9895-ea29-9ad0-630e95ddaf4f CreateIndex=11 ModifyIndex=20 AllocModifyIndex=11 DesiredStatus=run ClientStatus=running Type=AllocationUpdated
a02e35fa-c0bd-bf0e-107f-0f6a045664e2 CreateIndex=11 ModifyIndex=20 AllocModifyIndex=11 DesiredStatus=run ClientStatus=running Type=AllocationUpdated
8ebe0866-9a44-b1f8-26a8-2e5d1cf32af5 CreateIndex=17 ModifyIndex=24 AllocModifyIndex=17 DesiredStatus=run ClientStatus=running Type=AllocationUpdated
3bb7e48c-14f3-c055-5c36-ce5966369111 CreateIndex=17 ModifyIndex=24 AllocModifyIndex=17 DesiredStatus=run ClientStatus=running Type=AllocationUpdated
d01ac162-279d-3b1f-3ff6-1258c3dec022 CreateIndex=17 ModifyIndex=24 AllocModifyIndex=17 DesiredStatus=run ClientStatus=running Type=AllocationUpdated
```

As we can see, Filebeat completely missed allocations `a02e35fa-c0bd-bf0e-107f-0f6a045664e2` and `1a7c549f-9895-ea29-9ad0-630e95ddaf4f`. Further more we can see that the `AllocModifyIndex` remains the same in consecutive events for a given allocation, while `ModifyIndex` grows for each event per allocation. Also `ModifyIndex` only ever advances, where as `AllocModifyIndex` actually chronologically sometimes goes backwards, but it's compared against advancing counter.

Now [looking at the `nomad/watcher.go` code](https://github.com/elastic/beats/blob/v7.13.4/x-pack/libbeat/common/nomad/watcher.go#L133)

```go
		// the allocation has not changed since last seen, ignore
		if w.waitIndex > alloc.AllocModifyIndex {
```

This should actually compare against `ModifyIndex` instead. I'd maybe also consider adding a debug message for the skip, since that's what helped me while debugging this.

```diff
diff --git a/x-pack/libbeat/common/nomad/watcher.go b/x-pack/libbeat/common/nomad/watcher.go
index eba77e764a..200c48a47d 100644
--- a/x-pack/libbeat/common/nomad/watcher.go
+++ b/x-pack/libbeat/common/nomad/watcher.go
@@ -131,7 +131,10 @@ func (w *watcher) sync() error {
 
        for _, alloc := range allocations {
                // the allocation has not changed since last seen, ignore
-               if w.waitIndex > alloc.AllocModifyIndex {
+               if w.waitIndex > alloc.ModifyIndex {
+                       w.logger.Debugf("Skip allocation:%s ClientStatus:%s because w.waitIndex=%v > alloc.ModifyIndex=%v",
+                               alloc.ID, alloc.ClientStatus,
+                               fmt.Sprint(w.waitIndex), fmt.Sprint(alloc.ModifyIndex))
                        continue
                }
```

I've built and tested this earlier, but don't have it on hand now.


Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Nomad autodiscover fails to pick up some tasks #27035

Test setup

Inspecting the results

Analyzing the problem

Metadata

Assignees

Labels

Type

Fields

Projects

Milestone

Relationships

Development

Nomad autodiscover fails to pick up some tasks #27035

Description

Test setup

Inspecting the results

Analyzing the problem

Metadata

Metadata

Assignees

Labels

Type

Fields

Projects

Milestone

Relationships

Development

Issue actions