Integrate official release of cloudfoundry-client #252

antechrestos · 2016-08-25T07:04:14Z

Impact

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

- upgrade version to 2.0.0.RELEASE - rename application log sourceName to sourceType - rename application log sourceId to sourceInstance fix #252

gberche-orange · 2016-11-23T10:04:16Z

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

gberche-orange · 2016-11-23T10:55:59Z

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

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
- 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
- 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)
- Reproduce the missing log error reported by @antechrestos in Recent log: Some messages are not well read cloudfoundry/cf-java-client#551 (comment) 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)

- upgrade version to 2.0.0.RELEASE - rename application log sourceName to sourceType - rename application log sourceId to sourceInstance fix cloudfoundry-community#252

As part of cloudfoundry-community#252

gberche-orange · 2016-11-23T18:21:15Z

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 · 2016-11-25T12:16:47Z

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 · 2016-11-25T16:17:31Z

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 Recent log: Some messages are not well read cloudfoundry/cf-java-client#551 (comment)
- enable wire traces
- debug into the multipart issue
  - look at source code and unit tests: custom state machine, could not find unit tests
  - 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.
    - try with wiremock configuring TLS self signed certificates
  - replay the captured data

gberche-orange · 2016-11-28T18:27:37Z

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 Recent log: Some messages are not well read cloudfoundry/cf-java-client#551 (comment)
- 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 · 2016-11-28T18:31:50Z

Well done @gberche-orange

gberche-orange · 2016-11-30T09:59:01Z

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 proxy forwarding using SSL - feature request wiremock/wiremock#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 · 2016-12-15T07:34:55Z

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

- upgrade version to 2.0.0.RELEASE - rename application log sourceName to sourceType - rename application log sourceId to sourceInstance fix #252

As part of #252

antechrestos added the enhancement label Aug 25, 2016

antechrestos self-assigned this Aug 25, 2016

antechrestos pushed a commit that referenced this issue Aug 25, 2016

Upgrade cf java client version

e20798f

- upgrade version to 2.0.0.RELEASE - rename application log sourceName to sourceType - rename application log sourceId to sourceInstance fix #252

gberche-orange mentioned this issue Nov 14, 2016

autosleep use of deprecated logging-endpoint, fails fetching app activity, and never stop apps #264

Closed

gberche-orange added a commit to orange-cloudfoundry/autosleep that referenced this issue Nov 23, 2016

Update to latest cf-java-client 2.0.2.RELEASE and aligning related libs

983b4fb

As part of cloudfoundry-community#252

gberche-orange mentioned this issue Nov 30, 2016

Recent log: Some messages are not well read cloudfoundry/cf-java-client#551

Closed

antechrestos pushed a commit that referenced this issue Dec 15, 2016

Upgrade cf java client version

ff4cdcd

- upgrade version to 2.0.0.RELEASE - rename application log sourceName to sourceType - rename application log sourceId to sourceInstance fix #252

antechrestos pushed a commit that referenced this issue Dec 15, 2016

Update to latest cf-java-client 2.0.2.RELEASE and aligning related libs

b2130d3

As part of #252

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Integrate official release of cloudfoundry-client #252

Integrate official release of cloudfoundry-client #252

antechrestos commented Aug 25, 2016 •

edited

Loading

gberche-orange commented Nov 23, 2016

gberche-orange commented Nov 23, 2016 •

edited

Loading

gberche-orange commented Nov 23, 2016

gberche-orange commented Nov 25, 2016

gberche-orange commented Nov 25, 2016 •

edited

Loading

gberche-orange commented Nov 28, 2016 •

edited

Loading

antechrestos commented Nov 28, 2016

gberche-orange commented Nov 30, 2016 •

edited

Loading

gberche-orange commented Dec 15, 2016

Integrate official release of cloudfoundry-client #252

Integrate official release of cloudfoundry-client #252

Comments

antechrestos commented Aug 25, 2016 • edited Loading

gberche-orange commented Nov 23, 2016

gberche-orange commented Nov 23, 2016 • edited Loading

gberche-orange commented Nov 23, 2016

gberche-orange commented Nov 25, 2016

gberche-orange commented Nov 25, 2016 • edited Loading

gberche-orange commented Nov 28, 2016 • edited Loading

antechrestos commented Nov 28, 2016

gberche-orange commented Nov 30, 2016 • edited Loading

gberche-orange commented Dec 15, 2016

antechrestos commented Aug 25, 2016 •

edited

Loading

gberche-orange commented Nov 23, 2016 •

edited

Loading

gberche-orange commented Nov 25, 2016 •

edited

Loading

gberche-orange commented Nov 28, 2016 •

edited

Loading

gberche-orange commented Nov 30, 2016 •

edited

Loading