autosleep icon indicating copy to clipboard operation
autosleep copied to clipboard

Published 20 hours ago • verified publisher icon cloudfoundry-community

Integrate official release of cloudfoundry-client

Open antechrestos opened this issue 8 years ago • 9 comments

Impact

  • evolution from spring to netty
  • evolution from protobuf to square-wire (fields renamed)

Beware of some errors on recent message

antechrestos avatar Aug 25 '16 07:08 antechrestos

Note related initiated branch by @antechrestos at https://github.com/cloudfoundry-community/autosleep/compare/feature/upgrade_client_version

gberche-orange avatar Nov 23 '16 10:11 gberche-orange

If the recent logs usage needs to be preserved (w.r.t. #187 and alternative use of firehose )

  • [x] update to cf-java-client 2.0.2 release and verify if basic acceptance tests work
  • [ ] Ensure recent logs is reliably working in the cf-java version we are targetting
    • [x] verify integration test coverage in cf-java-client for recent logs: none yet in https://github.com/cloudfoundry/cf-java-client/blob/master/integration-test/src/test/java/org/cloudfoundry/client/v2/ApplicationsTest.java
    • [x] check cf-java-client backlog for analysis on the recent logs issues:
      • https://www.pivotaltracker.com/story/show/114250415 initial story "create/review/update client/applicationsV2 integration tests"
      • https://www.pivotaltracker.com/story/show/114251435 create/review/update operations/applications integration tests (pending unplanned)
    • [x] Reproduce the missing log error reported by @antechrestos in https://github.com/cloudfoundry/cf-java-client/issues/551#issuecomment-243103141 on latest version, using he provided test program
    • [ ] contribute cf-java-client integration tests for recent logs: in https://github.com/cloudfoundry/cf-java-client/blob/da9b119c3fa00bd1cb68ad3c5011d09c58960f31/integration-test/src/test/java/org/cloudfoundry/client/v2/ApplicationsTest.java#L95-L95 upLoadAndGetLogs
      • [ ] install prerequisites for running all integration tests (PCF requiring local disk space ~ 3GBs as tests are destructive) ?
    • [ ] work with the community to bring a fix
  • [ ] Adapt autosleep code to cf-java-client latest release (leveraging https://github.com/cloudfoundry-community/autosleep/compare/feature/upgrade_client_version)

gberche-orange avatar Nov 23 '16 10:11 gberche-orange

started update to cf-java-client 2.0.2 release and verify if basic acceptance tests work in https://github.com/orange-cloudfoundry/autosleep/tree/feature/upgrade_client_version-2.0.2

Indeed observing log related error traces when running acceptance tests:

2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT ERROR - pool-1-thread-2 - o.c.a.w.ApplicationStopper(140) - error while requesting cloudfoundry api
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT org.cloudfoundry.autosleep.access.cloudfoundry.CloudFoundryException: java.lang.IllegalStateException: Unexpected call to beginMessage()
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at org.cloudfoundry.autosleep.access.cloudfoundry.CloudFoundryApi.waitForResult(CloudFoundryApi.java:444)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at org.cloudfoundry.autosleep.access.cloudfoundry.CloudFoundryApi.getApplicationActivity(CloudFoundryApi.java:237)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at org.cloudfoundry.autosleep.worker.ApplicationStopper.handleApplicationEnrolled(ApplicationStopper.java:120)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at org.cloudfoundry.autosleep.worker.ApplicationStopper.lambda$run$14(ApplicationStopper.java:203)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at org.cloudfoundry.autosleep.util.ApplicationLocker.executeThreadSafe(ApplicationLocker.java:47)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at org.cloudfoundry.autosleep.worker.ApplicationStopper.run(ApplicationStopper.java:196)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at java.lang.Thread.run(Thread.java:745)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT Caused by: java.lang.IllegalStateException: Unexpected call to beginMessage()
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at com.squareup.wire.ProtoReader.beginMessage(ProtoReader.java:90)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at org.cloudfoundry.dropsonde.events.ContainerMetric$ProtoAdapter_ContainerMetric.decode(ContainerMetric.java:309)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at org.cloudfoundry.dropsonde.events.ContainerMetric$ProtoAdapter_ContainerMetric.decode(ContainerMetric.java:277)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at org.cloudfoundry.dropsonde.events.Envelope$ProtoAdapter_Envelope.decode(Envelope.java:576)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at org.cloudfoundry.dropsonde.events.Envelope$ProtoAdapter_Envelope.decode(Envelope.java:499)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at com.squareup.wire.ProtoAdapter.decode(ProtoAdapter.java:195)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at com.squareup.wire.ProtoAdapter.decode(ProtoAdapter.java:189)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at org.cloudfoundry.reactor.doppler.ReactorDopplerEndpoints.toEnvelope(ReactorDopplerEndpoints.java:66)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxMap$MapConditionalSubscriber.onNext(FluxMap.java:215)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.MonoFlatMap$FlattenSubscriber$InnerSubscriber.onNext(MonoFlatMap.java:191)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:120)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxFlatMap$FlatMapMain.drainLoop(FluxFlatMap.java:658)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxFlatMap$FlatMapMain.drain(FluxFlatMap.java:538)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxFlatMap$FlatMapInner.onSubscribe(FluxFlatMap.java:1069)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxUsing$UsingFuseableSubscriber.onSubscribe(FluxUsing.java:306)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxJust.subscribe(FluxJust.java:69)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxUsing.subscribe(FluxUsing.java:114)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxFlatMap$FlatMapMain.onNext(FluxFlatMap.java:382)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.innerNext(FluxConcatMap.java:258)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxConcatMap$ConcatMapInner.onNext(FluxConcatMap.java:740)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:166)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxUsing$UsingFuseableSubscriber.onNext(FluxUsing.java:312)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxFilterFuseable$FilterFuseableSubscriber.onNext(FluxFilterFuseable.java:112)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxPeekFuseable$PeekFuseableConditionalSubscriber.onNext(FluxPeekFuseable.java:380)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:942)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.MonoReduceSeed$ReduceSubscriber.onComplete(MonoReduceSeed.java:146)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxFlatMap$FlatMapMain.checkTerminated(FluxFlatMap.java:798)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxFlatMap$FlatMapMain.drainLoop(FluxFlatMap.java:558)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxFlatMap$FlatMapMain.drain(FluxFlatMap.java:538)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxFlatMap$FlatMapMain.onComplete(FluxFlatMap.java:531)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.UnicastProcessor.checkTerminated(UnicastProcessor.java:280)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.UnicastProcessor.drainRegular(UnicastProcessor.java:176)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.UnicastProcessor.drain(UnicastProcessor.java:256)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.UnicastProcessor.onComplete(UnicastProcessor.java:351)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.multipart.MultipartParser.onNext(MultipartParser.java:106)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.multipart.MultipartParser.onNext(MultipartParser.java:44)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.multipart.MultipartTokenizer.pushToken(MultipartTokenizer.java:326)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.multipart.MultipartTokenizer.pushDelimiterToken(MultipartTokenizer.java:320)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.multipart.MultipartTokenizer.trailingCrLf(MultipartTokenizer.java:397)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.multipart.MultipartTokenizer.onNext(MultipartTokenizer.java:191)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.multipart.MultipartTokenizer.onNext(MultipartTokenizer.java:33)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:120)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxSubscribeOn$SubscribeOnSubscriber.onNext(FluxSubscribeOn.java:148)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.common.NettyChannelHandler$InboundSink.next(NettyChannelHandler.java:601)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.common.NettyChannelHandler.doRead(NettyChannelHandler.java:134)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.NettyHttpClientHandler.channelRead(NettyHttpClientHandler.java:133)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:350)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:435)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:293)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:267)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:250)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:350)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:350)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1066)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:900)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:411)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:248)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:350)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1334)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:926)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:123)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:571)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:512)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:426)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:398)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:877)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	... 1 common frames omitted
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT java.lang.IllegalStateException: Unexpected call to beginMessage()
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at com.squareup.wire.ProtoReader.beginMessage(ProtoReader.java:90)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at org.cloudfoundry.dropsonde.events.ContainerMetric$ProtoAdapter_ContainerMetric.decode(ContainerMetric.java:309)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at org.cloudfoundry.dropsonde.events.ContainerMetric$ProtoAdapter_ContainerMetric.decode(ContainerMetric.java:277)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at org.cloudfoundry.dropsonde.events.Envelope$ProtoAdapter_Envelope.decode(Envelope.java:576)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at org.cloudfoundry.dropsonde.events.Envelope$ProtoAdapter_Envelope.decode(Envelope.java:499)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at com.squareup.wire.ProtoAdapter.decode(ProtoAdapter.java:195)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at com.squareup.wire.ProtoAdapter.decode(ProtoAdapter.java:189)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at org.cloudfoundry.reactor.doppler.ReactorDopplerEndpoints.toEnvelope(ReactorDopplerEndpoints.java:66)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxMap$MapConditionalSubscriber.onNext(FluxMap.java:215)
2016-11-23T18:51:41.85+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.MonoFlatMap$FlattenSubscriber$InnerSubscriber.onNext(MonoFlatMap.java:191)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:120)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxFlatMap$FlatMapMain.drainLoop(FluxFlatMap.java:658)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxFlatMap$FlatMapMain.drain(FluxFlatMap.java:538)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxFlatMap$FlatMapInner.onSubscribe(FluxFlatMap.java:1069)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxUsing$UsingFuseableSubscriber.onSubscribe(FluxUsing.java:306)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxJust.subscribe(FluxJust.java:69)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxUsing.subscribe(FluxUsing.java:114)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxFlatMap$FlatMapMain.onNext(FluxFlatMap.java:382)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.innerNext(FluxConcatMap.java:258)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxConcatMap$ConcatMapInner.onNext(FluxConcatMap.java:740)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:166)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxUsing$UsingFuseableSubscriber.onNext(FluxUsing.java:312)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxFilterFuseable$FilterFuseableSubscriber.onNext(FluxFilterFuseable.java:112)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxPeekFuseable$PeekFuseableConditionalSubscriber.onNext(FluxPeekFuseable.java:380)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:942)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.MonoReduceSeed$ReduceSubscriber.onComplete(MonoReduceSeed.java:146)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxFlatMap$FlatMapMain.checkTerminated(FluxFlatMap.java:798)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxFlatMap$FlatMapMain.drainLoop(FluxFlatMap.java:558)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxFlatMap$FlatMapMain.drain(FluxFlatMap.java:538)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxFlatMap$FlatMapMain.onComplete(FluxFlatMap.java:531)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.UnicastProcessor.checkTerminated(UnicastProcessor.java:280)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.UnicastProcessor.drainRegular(UnicastProcessor.java:176)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.UnicastProcessor.drain(UnicastProcessor.java:256)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.UnicastProcessor.onComplete(UnicastProcessor.java:351)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.multipart.MultipartParser.onNext(MultipartParser.java:106)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.multipart.MultipartParser.onNext(MultipartParser.java:44)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.multipart.MultipartTokenizer.pushToken(MultipartTokenizer.java:326)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.multipart.MultipartTokenizer.pushDelimiterToken(MultipartTokenizer.java:320)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.multipart.MultipartTokenizer.trailingCrLf(MultipartTokenizer.java:397)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.multipart.MultipartTokenizer.onNext(MultipartTokenizer.java:191)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.multipart.MultipartTokenizer.onNext(MultipartTokenizer.java:33)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:120)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxSubscribeOn$SubscribeOnSubscriber.onNext(FluxSubscribeOn.java:148)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.common.NettyChannelHandler$InboundSink.next(NettyChannelHandler.java:601)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.common.NettyChannelHandler.doRead(NettyChannelHandler.java:134)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.NettyHttpClientHandler.channelRead(NettyHttpClientHandler.java:133)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:350)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:435)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:293)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:267)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:250)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:350)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:350)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1066)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:900)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:411)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:248)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:350)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1334)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:926)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:123)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:571)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:512)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:426)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:398)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:877)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	... 1 common frames omitted
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT Wrapped by: org.cloudfoundry.autosleep.access.cloudfoundry.CloudFoundryException: java.lang.IllegalStateException: Unexpected call to beginMessage()
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at org.cloudfoundry.autosleep.access.cloudfoundry.CloudFoundryApi.waitForResult(CloudFoundryApi.java:444)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at org.cloudfoundry.autosleep.access.cloudfoundry.CloudFoundryApi.getApplicationActivity(CloudFoundryApi.java:237)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at org.cloudfoundry.autosleep.worker.ApplicationStopper.handleApplicationEnrolled(ApplicationStopper.java:120)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at org.cloudfoundry.autosleep.worker.ApplicationStopper.lambda$run$14(ApplicationStopper.java:203)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at org.cloudfoundry.autosleep.util.ApplicationLocker.executeThreadSafe(ApplicationLocker.java:47)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at org.cloudfoundry.autosleep.worker.ApplicationStopper.run(ApplicationStopper.java:196)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.multipart.MultipartTokenizer.pushToken(MultipartTokenizer.java:326)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.multipart.MultipartTokenizer.pushDelimiterToken(MultipartTokenizer.java:320)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.multipart.MultipartTokenizer.trailingCrLf(MultipartTokenizer.java:397)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.multipart.MultipartTokenizer.onNext(MultipartTokenizer.java:191)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.multipart.MultipartTokenizer.onNext(MultipartTokenizer.java:33)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:120)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.publisher.FluxSubscribeOn$SubscribeOnSubscriber.onNext(FluxSubscribeOn.java:148)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.common.NettyChannelHandler$InboundSink.next(NettyChannelHandler.java:601)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.common.NettyChannelHandler.doRead(NettyChannelHandler.java:134)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.NettyHttpClientHandler.channelRead(NettyHttpClientHandler.java:133)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:350)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:435)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:293)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:267)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:250)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:350)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:350)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1066)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:900)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:411)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:248)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:350)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1334)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at java.lang.Thread.run(Thread.java:745)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.core.Exceptions.failWithOverflow(Exceptions.java:137)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.http.multipart.MultipartParser.onNext(MultipartParser.java:44)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at reactor.ipc.netty.common.NettyChannelHandler$InboundSink.next(NettyChannelHandler.java:601)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:350)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:250)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:350)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:372)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:358)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:411)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1334)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:926)
2016-11-23T18:51:41.86+0100 [APP/PROC/WEB/0]OUT 	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:398)

Will not need to reproduce with smaller test case, such as the one provided by Benjamin

gberche-orange avatar Nov 23 '16 18:11 gberche-orange

Running @antechrestos program adapated to perform retries and measure:

  • error rate
  • amount of logs lost
  • probability of getting full logs after N retries

I obtain the following results:

  • error rate without retry: increase with size of the recent buffer with 300 lines, this is 100% error rate.
  • amount of logs lost: varies randomly from 10% to 90% of logs
  • probability of getting full logs after N retries: with 300 lines, 30% chances of getting all logs after 100 retries

See sample into cf-java-client-recent-logs-error-rate.txt

gberche-orange avatar Nov 25 '16 12:11 gberche-orange

Same with update to the latest versions

    <netty.version>4.1.6.Final</netty.version>
    <okhttp.version>3.4.2</okhttp.version>
    <reactor-netty.version>0.5.2.RELEASE</reactor-netty.version>

Next:

  • [ ] look deeper in the multipart issue in reactor-netty reported by benjamin in https://github.com/cloudfoundry/cf-java-client/issues/551#issuecomment-243103141
    • [ ] enable wire traces
    • [ ] debug into the multipart issue
      • [x] look at source code and unit tests: custom state machine, could not find unit tests
      • [x] capture the returned data from the recentLog endpoint as to be able to reproduce systematically (and not have loggregator responses vary overtime)
        • [ ] with a modification to the cf-java-client code to write the data to disk.
        • [x] try with wiremock configuring TLS self signed certificates
      • [x] replay the captured data

gberche-orange avatar Nov 25 '16 16:11 gberche-orange

Successfull capture and replay in two steps:

Set up wiremock in record mode

  • Step 1: record mock for v2/info and api java -jar ./wiremock-standalone-2.4.1.jar --https-port 8443 --proxy-all="https://api.site.com" --verbose --record-mappings
  • Step 2: manually edit the recorded mapping for v2/info and edit the doppler endpoint to return to 127.0.0.1
  • Step 3: record mocks for doppler java -jar ./wiremock-standalone-2.4.1.jar --https-port 8443 --proxy-all="https://doppler.site.com" --verbose --record-mappings
  • Step 4: replay recorded mocks for v2/info and doppler java -jar ./wiremock-standalone-2.4.1.jar --https-port 8443" --verbose

Exceptions are now more systematic, althrough still non-deterministic

[...]
016-11-28 19:19:49,732 DEBUG - main - o.c.r.Sandbox(188) - caught exception. retry #2. got 83 envelopes. 1st_ts=2016-11-28T17:32:12.343200777Z last_ts=2016-11-28T17:32:22.075679388Z Exception=org.cloudfoundry.reactor.doppler.ReadEnvelopeError: java.net.ProtocolException: Unexpected field encoding: 7
 2016-11-28 19:19:50,584 DEBUG - main - o.c.r.Sandbox(188) - caught exception. retry #3. got 83 envelopes. 1st_ts=2016-11-28T17:32:12.343200777Z last_ts=2016-11-28T17:32:22.075679388Z Exception=org.cloudfoundry.reactor.doppler.ReadEnvelopeError: java.net.ProtocolException: Unexpected field encoding: 7
 2016-11-28 19:19:51,279 DEBUG - main - o.c.r.Sandbox(188) - caught exception. retry #4. got 83 envelopes. 1st_ts=2016-11-28T17:32:12.343200777Z last_ts=2016-11-28T17:32:22.075679388Z Exception=org.cloudfoundry.reactor.doppler.ReadEnvelopeError: java.net.ProtocolException: Expected VARINT or LENGTH_DELIMITED but was 1
 2016-11-28 19:19:52,073 DEBUG - main - o.c.r.Sandbox(188) - caught exception. retry #5. got 83 envelopes. 1st_ts=2016-11-28T17:32:12.343200777Z last_ts=2016-11-28T17:32:22.075679388Z Exception=org.cloudfoundry.reactor.doppler.ReadEnvelopeError: java.net.ProtocolException: Expected VARINT or LENGTH_DELIMITED but was 1
 2016-11-28 19:19:52,717 DEBUG - main - o.c.r.Sandbox(188) - caught exception. retry #6. got 83 envelopes. 1st_ts=2016-11-28T17:32:12.343200777Z last_ts=2016-11-28T17:32:22.075679388Z Exception=org.cloudfoundry.reactor.doppler.ReadEnvelopeError: java.net.ProtocolException: Expected VARINT or LENGTH_DELIMITED but was 1
 2016-11-28 19:19:53,307 DEBUG - main - o.c.r.Sandbox(188) - caught exception. retry #7. got 83 envelopes. 1st_ts=2016-11-28T17:32:12.343200777Z last_ts=2016-11-28T17:32:22.075679388Z Exception=org.cloudfoundry.reactor.doppler.ReadEnvelopeError: java.net.ProtocolException: Expected VARINT or LENGTH_DELIMITED but was 1
 2016-11-28 19:19:53,728 DEBUG - main - o.c.r.Sandbox(188) - caught exception. retry #8. got 83 envelopes. 1st_ts=2016-11-28T17:32:12.343200777Z last_ts=2016-11-28T17:32:22.075679388Z Exception=org.cloudfoundry.reactor.doppler.ReadEnvelopeError: java.net.ProtocolException: Expected VARINT or LENGTH_DELIMITED but was 1
 2016-11-28 19:19:54,403 DEBUG - main - o.c.r.Sandbox(188) - caught exception. retry #9. got 83 envelopes. 1st_ts=2016-11-28T17:32:12.343200777Z last_ts=2016-11-28T17:32:22.075679388Z Exception=org.cloudfoundry.reactor.doppler.ReadEnvelopeError: java.net.ProtocolException: Expected VARINT or LENGTH_DELIMITED but was 1
 2016-11-28 19:19:55,237 DEBUG - main - o.c.r.Sandbox(188) - caught exception. retry #10. got 83 envelopes. 1st_ts=2016-11-28T17:32:12.343200777Z last_ts=2016-11-28T17:32:22.075679388Z Exception=org.cloudfoundry.reactor.doppler.ReadEnvelopeError: java.net.ProtocolException: Expected VARINT or LENGTH_DELIMITED but was 1

Next:

  • [ ] look deeper in the multipart issue in reactor-netty reported by benjamin in https://github.com/cloudfoundry/cf-java-client/issues/551#issuecomment-243103141
    • [ ] debug into the multipart issue
      • [ ] simplify data reinjection code to be simpler, straightforward
      • [ ] trace the multipart code, possibly by adding logs, and diffing the logs across iterations

gberche-orange avatar Nov 28 '16 18:11 gberche-orange

Well done @gberche-orange

antechrestos avatar Nov 28 '16 18:11 antechrestos

More details on the wiremock set up. The trick was to use wiremock as a reverse proxy for individual endpoints. This has the following limitations:

  • requires configuring the proxy rules for each proxified backend
  • requires the client to be directed to local endpoint (localhost or 127.0.0.1) instead of the original hostname (or trick the local DNS to do so)

Configuring cf-java-client to go through wiremock as a forward proxy would be much simpler, however:

  • CF has moved into only supporting TLS traffic in and not raw HTTP traffic
  • forward TLS proxy in wiremock is not yet supported: See https://github.com/tomakehurst/wiremock/issues/379

While jetty does support forward proxifying TLS traffic (see https://github.com/eclipse/jetty.project/blob/jetty-9.4.x/jetty-proxy/src/test/java/org/eclipse/jetty/proxy/ConnectHandlerSSLTest.java#L126-L146 ) it does not yet allow decrypting the TLS tunnel established between the HTTP client and HTTP server: wiremock is currently only seeing encrypted TLS traffic.

This would require wiremock to modify the ConnectHandler to instead:

  • choose a hostname against which to generate a self signed certificate
    • optionally accept TLS handshake initiated by the client and extract the SNI (server name indication) to find the actually requested host name
    • or just pick the hostname provided in the CONNECT header (which should be accurate unless the http client is tricking the HTTP proxy)
  • generate a self-signed TLS certificate matching the requested hostname
  • respond to the TLS handshake from the client with the self-signed generate certificate, (lets call it clientStream2)
  • open a TLS connection to the server (serverStream1)
  • copy requests from client (clientStream2) to TLS connection to server (serverStream1)

Next steps to try to help the wiremock team for this MITM feature could be:

  • check the jetty mailing lists for discussions/attempts to implement such MITM
  • check github/other source for other jetty-derived MITM implementations (such as https://searchcode.com/?q=ConnectHandler&loc=0&loc2=10000&lan=23 )

Alternatives for using WM in cf-java-client:

  • set up programmatic reverse proxy config to the different CF endpoints (doppler, uaa) in junit test, and run as root to bind port 443
  • override DNS config programmatically in the JVM to hit the WM reverse proxy more transparently

gberche-orange avatar Nov 30 '16 09:11 gberche-orange

@antechrestos if you plan to proceed with this issue (as mentionned on the cf-java-client issue), please consider reusing upgrade_client_version-2.0.2 branch which has few commits to display jars version in traces and a unit test bug fix.

gberche-orange avatar Dec 15 '16 07:12 gberche-orange