Failed expansion results in the expression; kills other expansions
- 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
Assessment
This issue has not been assessed yet.