Integrate official release of cloudfoundry-client

antechrestos commented 8 years ago

Impact

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

gberche-orange commented 7 years ago

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

gberche-orange commented 7 years ago

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 commented 7 years ago

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 commented 7 years ago

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 commented 7 years ago

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>

[ ] 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 commented 7 years ago

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

[ ] 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

antechrestos commented 7 years ago

Well done @gberche-orange

gberche-orange commented 7 years ago

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 commented 7 years ago

@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.

cloudfoundry-community / autosleep

Integrate official release of cloudfoundry-client #252