Graylog2 / Graylog2/graylog2-server

Race condition in input event handling leads to NullPointerException

Open
#5,106 0 comments 0 reactions 0 assignees View on GitHub
#M bug triaged
Dominant language
Java
Stars
8.1k
Forks
1.1k
Avg merge
1d 20h
Merged PRs (30d)
217

Description

## Expected Behavior

It should be possible to create an input and update it right after the creation. (e.g. when triggered from code)

## Current Behavior

When a user creates an input and updates it right after the creation, the input doesn't start and throws a `NullPointerException`.

Input creation and update triggers events which are handled by the [InputEventListener](https://github.com/Graylog2/graylog2-server/blob/master/graylog2-server/src/main/java/org/graylog2/inputs/InputEventListener.java).
The event handler for the update event restarts the input by calling `.stop()` and then `.launch()`.

The problem is this case is, that the input gets restarted while it is still starting up.

I noticed the issue when using a GELF UDP input which uses the [UDPTransport](https://github.com/Graylog2/graylog2-server/blob/0dbe6f659e79e945662658bc9c2cd468c8922b8c/graylog2-server/src/main/java/org/graylog2/inputs/transports/UdpTransport.java) class.

The [UDPTransport.launch()](https://github.com/Graylog2/graylog2-server/blob/0dbe6f659e79e945662658bc9c2cd468c8922b8c/graylog2-server/src/main/java/org/graylog2/inputs/transports/UdpTransport.java#L107-L122) method is using the `bootstrap` field several times during startup.

https://github.com/Graylog2/graylog2-server/blob/0dbe6f659e79e945662658bc9c2cd468c8922b8c/graylog2-server/src/main/java/org/graylog2/inputs/transports/UdpTransport.java#L107-L122

In [UDPTransport.stop()](https://github.com/Graylog2/graylog2-server/blob/0dbe6f659e79e945662658bc9c2cd468c8922b8c/graylog2-server/src/main/java/org/graylog2/inputs/transports/UdpTransport.java#L126-L134) the `bootstrap` variable is set to `null`.

https://github.com/Graylog2/graylog2-server/blob/0dbe6f659e79e945662658bc9c2cd468c8922b8c/graylog2-server/src/main/java/org/graylog2/inputs/transports/UdpTransport.java#L126-L134

So while the input is still running the code in `UDPTransport.launch()` the `bootstrap` field is set to `null` when `UDPTransport.stop()` gets triggered and the next time `.launch()` is using it, a `NullPointerException` gets thrown.

Example:

```
2018-09-13 20:32:43,954 INFO : org.graylog2.inputs.InputEventListener - ########## Input created: 5b9aad4b38f80c19f997f71a
2018-09-13 20:32:43,957 INFO : org.graylog2.inputs.transports.UdpTransport - ########## ENTER .launch()
2018-09-13 20:32:43,958 INFO : org.graylog2.inputs.InputEventListener - ########## Input updated: 5b9aad4b38f80c19f997f71a
2018-09-13 20:32:43,958 INFO : org.graylog2.inputs.InputStateListener - Input [GELF UDP/5b9aad4b38f80c19f997f71a] is now STARTING
2018-09-13 20:32:43,959 INFO : org.graylog2.inputs.transports.UdpTransport - ########## ENTER .stop()
2018-09-13 20:32:43,962 INFO : org.graylog2.inputs.InputStateListener - Input [GELF UDP/5b9aad4b38f80c19f997f71a] is now STOPPING
2018-09-13 20:32:43,965 WARN : org.graylog2.inputs.transports.UdpTransport - receiveBufferSize (SO_RCVBUF) for input GELFUDPInput{title=GELF, type=org.graylog2.inputs.gelf.udp.GELFUDPInput, nodeId=28164cbe-4ad9-4c9c-a76e-088655aa7889} (channel [id: 0xb4982537, L:/0:0:0:0:0:0:0:0%0:12201]) should be 262144 but is 425984.
2018-09-13 20:32:43,973 INFO : org.graylog2.inputs.transports.UdpTransport - ########## EXIT .stop()
2018-09-13 20:32:43,975 INFO : org.graylog2.inputs.InputStateListener - Input [GELF UDP/5b9aad4b38f80c19f997f71a] is now STOPPED
2018-09-13 20:32:43,976 INFO : org.graylog2.inputs.InputStateListener - Input [GELF UDP/5b9aad4b38f80c19f997f71a] is now TERMINATED
2018-09-13 20:32:44,066 INFO : org.graylog2.inputs.transports.UdpTransport - ########## EXIT .launch()
2018-09-13 20:32:44,066 WARN : org.graylog2.inputs.transports.UdpTransport - receiveBufferSize (SO_RCVBUF) for input GELFUDPInput{title=GELF, type=org.graylog2.inputs.gelf.udp.GELFUDPInput, nodeId=28164cbe-4ad9-4c9c-a76e-088655aa7889} (channel [id: 0xeb347039, L:/0:0:0:0:0:0:0:0%0:12201]) should be 262144 but is 425984.
2018-09-13 20:32:44,068 ERROR: org.graylog2.shared.inputs.InputLauncher - The [org.graylog2.inputs.gelf.udp.GELFUDPInput] input with ID <5b9aad4b38f80c19f997f71a> misfired. Reason: null
org.graylog2.plugin.inputs.MisfireException: org.graylog2.plugin.inputs.MisfireException: java.lang.NullPointerException
at org.graylog2.plugin.inputs.MessageInput.launch(MessageInput.java:158) ~[classes/:?]
at org.graylog2.shared.inputs.InputLauncher$1.run(InputLauncher.java:84) [classes/:?]
at com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:181) [metrics-core-4.0.2.jar:4.0.2]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_181]
at java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:266) [?:1.8.0_181]
at java.util.concurrent.FutureTask.run(FutureTask.java) [?:1.8.0_181]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_181]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_181]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_181]
Caused by: org.graylog2.plugin.inputs.MisfireException: java.lang.NullPointerException
at org.graylog2.inputs.transports.UdpTransport.launch(UdpTransport.java:120) ~[classes/:?]
at org.graylog2.plugin.inputs.MessageInput.launch(MessageInput.java:155) ~[classes/:?]
... 8 more
Caused by: java.lang.NullPointerException
at org.graylog2.inputs.transports.UdpTransport.launch(UdpTransport.java:115) ~[classes/:?]
at org.graylog2.plugin.inputs.MessageInput.launch(MessageInput.java:155) ~[classes/:?]
... 8 more
2018-09-13 20:32:44,072 INFO : org.graylog2.inputs.InputStateListener - Input [GELF UDP/5b9aad4b38f80c19f997f71a] is now FAILED
```

I added some custom log statements to the code to illustrate the issue.

## Possible Solution

We have to make sure to serialize the event handlers for the same input so they cannot run in parallel.

I think we can either add locks to the `InputEventHandler` or update all inputs so they are thread safe. The issue in this case is, that the `UDPTransport` is not thread safe. So we have to decide if the expect them to be thread safe or not.

## Steps to Reproduce (for bugs)

I noticed the issue while installing a content pack that contains an input with extractors and/or static fields. The content pack installation code first creates an input and then updates it to add extractors and static fields right after that. This seems to be so fast that the race condition gets triggered.

1. Create content pack with an input that has extractors and/or static fields
2. Delete the input
3. Install the content pack with the input
4. Check the logs, the input will probably not start due to the issue described above

## Context

Another problem is, that our input persistence layer doesn't offer an API to atomically create an input with extractors, converters and static fields. (it might be possible by adding the additional fields to a `Map` on input creation) But even if it would offer that API, the input system is still vulnerable to this race condition.

## Your Environment

* Graylog Version: 3.0.0-alpha.2-SNAPSHOT (rev b8b6a0699)

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.