Chris Sampson created NIFI-7811:
-----------------------------------
Summary: PrometheusReportingTask starts even if there's a port
clash and it cannot possibly work (and the logs are unhelpful)
Key: NIFI-7811
URL: https://issues.apache.org/jira/browse/NIFI-7811
Project: Apache NiFi
Issue Type: Bug
Components: Core Framework
Affects Versions: 1.11.4
Reporter: Chris Sampson
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:
{quote}
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
{quote}
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):
{code:java}
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
{code}
Also, when subsequently stopping the task:
{code:java}
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
{code}
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
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
