When listening on the firehose I randomly get "Required field not set: method" error

[youngm]

When listening to the firehose in my more heavily used environments I occasionally (depending on router load) get the exception below. It appears that there is something wrong with loggregator or gorouter that causes it to occasionally somehow create an event without the required field "method".

Anyway, when the firehose gets this error it disconnects from the firehose causing me to have to reconnect. Would it be possible for the cf-java-client to somehow log or communicate the error but continue pulling from the firehose if consumer wishes to ignore it?

2018-04-23T19:27:21.334Z [WARN ] [cloudfoundry-client-nio-1] i.n.c.AbstractChannelHandlerContext: An exception '{}' [enable DEBUG level for full stacktrace] was thrown by a user handler's exceptionCaught() method while handling the following exception:
reactor.core.Exceptions$ErrorCallbackNotImplemented: java.lang.IllegalStateException: Required field not set:
method
Caused by: java.lang.IllegalStateException: Required field not set:
method
	at com.squareup.wire.internal.Internal.missingRequiredFields(Internal.java:116)
	at org.cloudfoundry.dropsonde.events.HttpStartStop$Builder.build(HttpStartStop.java:458)
	at org.cloudfoundry.dropsonde.events.HttpStartStop$ProtoAdapter_HttpStartStop.decode(HttpStartStop.java:558)
	at org.cloudfoundry.dropsonde.events.HttpStartStop$ProtoAdapter_HttpStartStop.decode(HttpStartStop.java:473)
	at org.cloudfoundry.dropsonde.events.Envelope$ProtoAdapter_Envelope.decode(Envelope.java:529)
	at org.cloudfoundry.dropsonde.events.Envelope$ProtoAdapter_Envelope.decode(Envelope.java:463)
	at com.squareup.wire.ProtoAdapter.decode(ProtoAdapter.java:195)
	at com.squareup.wire.ProtoAdapter.decode(ProtoAdapter.java:189)
	at org.cloudfoundry.reactor.doppler.ReactorDopplerEndpoints.toEnvelope(ReactorDopplerEndpoints.java:69)
	at reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:100)
	at reactor.core.publisher.MonoFlatMapMany$FlatMapManyInner.onNext(MonoFlatMapMany.java:238)
	at reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:108)
	at reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:108)
	at reactor.ipc.netty.channel.FluxReceive.drainReceiver(FluxReceive.java:211)
	at reactor.ipc.netty.channel.FluxReceive.onInboundNext(FluxReceive.java:326)
	at reactor.ipc.netty.channel.ChannelOperations.onInboundNext(ChannelOperations.java:319)
	at reactor.ipc.netty.http.client.HttpClientOperations.onInboundNext(HttpClientOperations.java:590)
	at reactor.ipc.netty.http.client.HttpClientWSOperations.onInboundNext(HttpClientWSOperations.java:177)
	at reactor.ipc.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:132)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
	at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:310)
	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:297)
	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:413)
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:265)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1359)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:935)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:138)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:645)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:580)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:497)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:459)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
	at java.lang.Thread.run(Thread.java:748)
	Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: 
Assembly trace from producer [reactor.core.publisher.FluxMap] :
	reactor.core.publisher.Flux.checkpoint(Flux.java:2615)
	reactor.core.publisher.Flux.checkpoint(Flux.java:2565)
	org.cloudfoundry.reactor.doppler.ReactorDopplerEndpoints.firehose(ReactorDopplerEndpoints.java:50)
	org.cloudfoundry.reactor.doppler._ReactorDopplerClient.firehose(_ReactorDopplerClient.java:44)
	org.cloudfoundry.reactor.doppler.ReactorDopplerClient.firehose(ReactorDopplerClient.java:14)
-- Trim user classes --
	org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65)
	org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
	java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
Error has been observed by the following operator(s):
	|_	Flux.checkpoint(ReactorDopplerEndpoints.java:50)

[youngm]

Or perhaps it might be possible to mark "method" optional for cf-java-client? I know the official protobuf says it is required. But I suspect the loggregator team isn't interested in tracking down this issue in the v1 space so perhaps a workaround like this is in order? :)

[twoseat]

Thanks for the report Mike. I think a colleague was looking into something like this, so I'm going to wait for him to return from vacation next week to check with him. If I'm just imagining it then I'll make it optional.

[nebhale]

Yep, we should make it @Nullable, because even if the spec says one thing, in practice the truth is different.

[sushantdewan123]

I am seeing the exact same issue for Wavefront PCF nozzle
https://github.com/wavefrontHQ/cloud-foundry-nozzle

We recently updated the client to 3.11.0.RELEASE

org.cloudfoundry
cloudfoundry-client-reactor
3.11.0.RELEASE

Do we need to change anything in our code to handle this? We want to avoid reconnecting if we see this issue and hoping the cf-java-client handles this for us (which was the ask in the original ticket).

Just curious - how did @youngm get around this issue?

Any help/pointers on this appreciated!

[youngm]

@sushantdewan123 I haven't yet upgraded to a version with this fix. I will be soon. I'm hoping it will just work. Are you seeing otherwise?

[sushantdewan123]

Thanks for the quick response @youngm
the only fix I see in this commit id b85dec7
is

@Nullable
 abstract Method getMethod();

this is what I see in this code - org.cloudfoundry.dropsonde.events.HttpStartStop

@Override
    public HttpStartStop build() {
      if (startTimestamp == null
          || stopTimestamp == null
          || requestId == null
          || peerType == null
          || method == null
          || uri == null
          || remoteAddress == null
          || userAgent == null
          || statusCode == null
          || contentLength == null) {
        throw Internal.missingRequiredFields(startTimestamp, "startTimestamp",
            stopTimestamp, "stopTimestamp",
            requestId, "requestId",
            peerType, "peerType",
            method, "method",
            uri, "uri",
            remoteAddress, "remoteAddress",
            userAgent, "userAgent",
            statusCode, "statusCode",
            contentLength, "contentLength");
      }
      return new HttpStartStop(startTimestamp, stopTimestamp, requestId, peerType, method, uri, remoteAddress, userAgent, statusCode, contentLength, applicationId, instanceIndex, instanceId, forwarded, super.buildUnknownFields());
    }
  }

still throwing IllegalStateException with the latest version - 3.11.0.RELEASE

Error has been observed by the following operator(s):
   2018-07-07T08:47:37.42+0530 [APP/PROC/WEB/0] OUT     |_      Flux.checkpoint(ReactorDopplerEndpoints.java:50)
   2018-07-07T08:47:37.42+0530 [APP/PROC/WEB/0] OUT 2018-07-06 20:17:37.422  WARN 14 --- [ry-client-nio-2] i.n.c.AbstractChannelHandlerContext      : An exception '{
}' [enable DEBUG level for full stacktrace] was thrown by a user handler's exceptionCaught() method while handling the following exception:
   2018-07-07T08:47:37.42+0530 [APP/PROC/WEB/0] OUT reactor.core.Exceptions$ErrorCallbackNotImplemented: java.lang.IllegalStateException: Required field not set:
   2018-07-07T08:47:37.42+0530 [APP/PROC/WEB/0] OUT   method
   2018-07-07T08:47:37.42+0530 [APP/PROC/WEB/0] OUT Caused by: java.lang.IllegalStateException: Required field not set:
   2018-07-07T08:47:37.42+0530 [APP/PROC/WEB/0] OUT   method
   2018-07-07T08:47:37.42+0530 [APP/PROC/WEB/0] OUT     at com.squareup.wire.internal.Internal.missingRequiredFields(Internal.java:116) ~[app/:na]
   2018-07-07T08:47:37.42+0530 [APP/PROC/WEB/0] OUT     at org.cloudfoundry.dropsonde.events.HttpStartStop$Builder.build(HttpStartStop.java:458) ~[app/:na]
   2018-07-07T08:47:37.42+0530 [APP/PROC/WEB/0] OUT     at org.cloudfoundry.dropsonde.events.HttpStartStop$ProtoAdapter_HttpStartStop.decode(HttpStartStop.java:558)
~[app/:na]
   2018-07-07T08:47:37.42+0530 [APP/PROC/WEB/0] OUT     at org.cloudfoundry.dropsonde.events.HttpStartStop$ProtoAdapter_HttpStartStop.decode(HttpStartStop.java:473)

I really don't want to catch IllegalStateException with message prefix - "Required field not set: method" and reconnect. Because what if exception or the message prefix changes tomorrow. Request the cf-java-client to fix it in the client and not throw that exception?

[sushantdewan123]

Maybe @nebhale or @twoseat can chime in ^^^
Unfortunately, this is a blocker issue for us :(