elastic / elastic/logstash

Failed expansion results in the expression; kills other expansions

Open
#3,237 2 comments 0 reactions 0 assignees View on GitHub
bug
Dominant language
Java
Stars
14.9k
Forks
3.5k
Avg merge
19h 14m
Merged PRs (30d)
63

Description

**Expected:**
- `"%{variable}"` should expand to `""` if `variable` is absent
- `"%{variable}"` failing should _not_ affect expansion of `%{other}`

**Observed:**

With logstash 1.4.0 on the `opentsdb` output, we see:
- `"%{variable}"` expands to `"%{variable}"` if `variable` is absent (see also: #2530)
- `"%{variable}"` failing causes all other expansions in the output block to fail

I wouldn't believe either of these if I hadn't seen the output.

**Configuration:**

```
opentsdb {
metrics => [
"usage", 1,
"user_id", "%{@user_id}",
"app", "%{@app}",
"subapp", "%{@subapp}",
"action", "%{@action}",
"user_type", "%{user_type}",
"env", "%{@env}",
"first_visit", "%{[metadata][first_visit]}",
"useful", "%{@useful}"
]
}
```

Yes, I know we shouldn't have prefixed everything interesting with `@`. We're also re-using `@version` and `tags`. Worse, `tags` is _my_ fault. Ne'er mind.

**Output:**

`put usage 1431488930 1 user_id=%{@user_id} app=%{@app} subapp=%{@subapp} action=%{@action} user_type=unknown env=%{@env} first_visit=0 useful=%{@useful}`

Wut.

**Method:** (Linux)

Use `lsof -u logstash` to dump files open by the `logstash` user. Note the PID and the file descriptor numbers associated with your output. For example:

```
# lsof -u logstash
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
java 19578 logstash 30u IPv6 8599722 0t0 TCP localhost:37093->localhost:4242 (ESTABLISHED)
java 19578 logstash 31u IPv6 8599723 0t0 TCP localhost:37094->localhost:4242 (ESTABLISHED)
java 19578 logstash 32u IPv6 8599724 0t0 TCP localhost:37095->localhost:4242 (ESTABLISHED)
```

Our PID is `19578`, and we're talking to OpenTSDB (port `4242`) on file descriptors `30`, `31`, and `32`.

Plug them into an `strace` command:

```
# strace -p 19578 -f -e write=30,31,32 -e trace=write
[pid 19684] write(35, "\1", 1) = 1
[pid 19684] write(18, "*3\r\n$5\r\nblpop\r\n$8\r\nlogstash\r\n$1\r"..., 36) = 36
[pid 19691] write(26, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 19690] write(28, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 19693] write(1, "{\"@timestamp\":\"2015-05-13T04:57:"..., 608) = 608
[pid 19693] write(31, "put usage 1431493042 1 user_id=n"..., 185) = 185
...
```

Append `2>&1 | grep \|` to the command line to filter out everything except the write dumps.

Feed in the data for which you're seeing problems. In our case, we saw this whenever `@subapp` was absent:

```
| 00000 70 75 74 20 75 73 61 67 65 20 31 34 33 31 34 38 put usag e 143148 |
| 00010 38 39 33 30 20 31 20 75 73 65 72 5f 69 64 3d 25 8930 1 u ser_id=% |
| 00020 7b 40 75 73 65 72 5f 69 64 7d 20 61 70 70 3d 25 {@user_i d} app=% |
| 00030 7b 40 61 70 70 7d 20 73 75 62 61 70 70 3d 25 7b {@app} s ubapp=%{ |
| 00040 40 73 75 62 61 70 70 7d 20 61 63 74 69 6f 6e 3d @subapp} action= |
| 00050 25 7b 40 61 63 74 69 6f 6e 7d 20 75 73 65 72 5f %{@actio n} user_ |
| 00060 74 79 70 65 3d 75 6e 6b 6e 6f 77 6e 20 65 6e 76 type=unk nown env |
| 00070 3d 25 7b 40 65 6e 76 7d 20 66 69 72 73 74 5f 76 =%{@env} first_v |
| 00080 69 73 69 74 3d 30 20 75 73 65 66 75 6c 3d 25 7b isit=0 u seful=%{ |
| 00090 40 75 73 65 66 75 6c 7d @useful} |
```

Expansion started working again when we forced `@subapp` to have a value.

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.