Details
-
Bug
-
Status: Resolved
-
Major
-
Resolution: Fixed
-
None
-
None
Description
A PrometheusReportingTask that would be unable to work properly (e.g. due to a port clash within an environment) successfully enables and continues to try operating even when it cannot realistically report metrics.
The logs that appear during the scheduled executions are also very unhelpful:
2020-09-15 13:10:43,007 ERROR [Timer-Driven Process Thread-6] o.a.n.r.p.PrometheusReportingTask PrometheusReportingTask[id=91e352aa-0174-1000-ffff-ffffd5947ec5] Error running task PrometheusReportingTask[id=91e352aa-0174-1000-ffff-ffffd5947ec5] due to java.lang.NullPointerException
The easiest way I've found to replicate this is to configure two identical PrometheusReportingTasks in the same NiFi instance (e.g. both using the default port of 9092).
Note that on initial startup of the second task, the following logs do appear (but can easily be missed):
2020-09-15 13:10:43,006 ERROR [Timer-Driven Process Thread-5] o.a.n.r.p.PrometheusReportingTask PrometheusReportingTask[id=91e352aa-0174-1000-ffff-ffffd5947ec5] Failed to start Jetty server: java.io.IOException: Failed to bind to /0.0.0.0:9092 java.io.IOException: Failed to bind to /0.0.0.0:9092 at org.eclipse.jetty.server.ServerConnector.openAcceptChannel(ServerConnector.java:346) at org.eclipse.jetty.server.ServerConnector.open(ServerConnector.java:308) at org.eclipse.jetty.server.AbstractNetworkConnector.doStart(AbstractNetworkConnector.java:80) at org.eclipse.jetty.server.ServerConnector.doStart(ServerConnector.java:236) at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) at org.eclipse.jetty.server.Server.doStart(Server.java:396) at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) at org.apache.nifi.reporting.prometheus.PrometheusServer.<init>(PrometheusServer.java:92) at org.apache.nifi.reporting.prometheus.PrometheusReportingTask.onScheduled(PrometheusReportingTask.java:100) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.apache.nifi.util.ReflectionUtils.invokeMethodsWithAnnotations(ReflectionUtils.java:142) at org.apache.nifi.util.ReflectionUtils.invokeMethodsWithAnnotations(ReflectionUtils.java:130) at org.apache.nifi.util.ReflectionUtils.invokeMethodsWithAnnotations(ReflectionUtils.java:75) at org.apache.nifi.util.ReflectionUtils.invokeMethodsWithAnnotation(ReflectionUtils.java:52) at org.apache.nifi.controller.scheduling.StandardProcessScheduler$2.run(StandardProcessScheduler.java:222) at org.apache.nifi.engine.FlowEngine$2.run(FlowEngine.java:110) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) Caused by: java.net.BindException: Address already in use at sun.nio.ch.Net.bind0(Native Method) at sun.nio.ch.Net.bind(Net.java:433) at sun.nio.ch.Net.bind(Net.java:425) at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:220) at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:85) at org.eclipse.jetty.server.ServerConnector.openAcceptChannel(ServerConnector.java:342) ... 25 common frames omitted
Also, when subsequently stopping the task:
2020-09-15 13:13:26,091 ERROR [Timer-Driven Process Thread-8] org.apache.nifi.util.ReflectionUtils Failed while invoking annotated method 'public void org.apache.nifi.reporting.prometheus.PrometheusReportingTask.OnStopped() throws java.lang.Exception' with arguments '[]'. java.lang.reflect.InvocationTargetException: null at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.apache.nifi.util.ReflectionUtils.invokeMethodsWithAnnotations(ReflectionUtils.java:142) at org.apache.nifi.util.ReflectionUtils.invokeMethodsWithAnnotations(ReflectionUtils.java:130) at org.apache.nifi.util.ReflectionUtils.quietlyInvokeMethodsWithAnnotations(ReflectionUtils.java:268) at org.apache.nifi.util.ReflectionUtils.quietlyInvokeMethodsWithAnnotation(ReflectionUtils.java:90) at org.apache.nifi.controller.scheduling.StandardProcessScheduler$3.run(StandardProcessScheduler.java:286) at org.apache.nifi.engine.FlowEngine$2.run(FlowEngine.java:110) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) Caused by: java.lang.NullPointerException: null at org.apache.nifi.reporting.prometheus.PrometheusReportingTask.OnStopped(PrometheusReportingTask.java:140) ... 17 common frames omitted
It would seem sensible to either (or both):
- Prevent the task from being enabled in the first place (if it cannot possibly report its metrics)
- Improve the logging such that when the task executes on schedule it logs something more meaningful
Attachments
Issue Links
- links to
