Push from Windows fails (in combination with resource matching)

[cwesdorp]

Hi,

when pushing a new app to CF using the Java Client on the Windows platform fails. The push fails with an Unknown Cloud Foundry Exception. When going to the target CF console and trying to start the app results in a message "Description:The app package is invalid: bits have not been uploaded"

Checking the code I think the resource matching in DefaultApplications
might be the cause, using a (really) old version which doesn't have this it works from windows.

From what I see it is not possible to skip the resource matching.

• Is this a bug that should be fixed?
• Or can configuration be added to skip resource matching?

The call stack is this

Caused by: org.cloudfoundry.UnknownCloudFoundryException: Unknown Cloud Foundry Exception
	at org.cloudfoundry.reactor.util.ErrorPayloadMapper.lambda$null$10(ErrorPayloadMapper.java:110)
	at reactor.core.publisher.MonoThenMap$ThenMapMain.onNext(MonoThenMap.java:120)
	at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:67)
	at reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:108)
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:115)
	at reactor.core.publisher.FluxUsing$UsingFuseableSubscriber.onNext(FluxUsing.java:351)
	at reactor.core.publisher.FluxFilterFuseable$FilterFuseableSubscriber.onNext(FluxFilterFuseable.java:103)
	at reactor.core.publisher.FluxPeekFuseable$PeekFuseableConditionalSubscriber.onNext(FluxPeekFuseable.java:428)
	at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:962)
	at reactor.core.publisher.MonoReduceSeed$ReduceSeedSubscriber.onComplete(MonoReduceSeed.java:150)
	at reactor.core.publisher.FluxMap$MapSubscriber.onComplete(FluxMap.java:130)
	at reactor.ipc.netty.channel.FluxReceive.terminateReceiver(FluxReceive.java:375)
	at reactor.ipc.netty.channel.FluxReceive.drainReceiver(FluxReceive.java:198)
	at reactor.ipc.netty.channel.FluxReceive.onInboundComplete(FluxReceive.java:338)
	at reactor.ipc.netty.channel.ChannelOperations.onInboundComplete(ChannelOperations.java:343)
	at reactor.ipc.netty.channel.ChannelOperations.onHandlerTerminate(ChannelOperations.java:419)
	at reactor.ipc.netty.channel.ChannelOperations.onOutboundError(ChannelOperations.java:367)
	at reactor.ipc.netty.http.client.HttpClientOperations.onOutboundError(HttpClientOperations.java:497)
	at reactor.ipc.netty.channel.ChannelOperations.onError(ChannelOperations.java:225)
	at reactor.core.publisher.MonoThenMap$ThenMapMain.secondError(MonoThenMap.java:184)
	at reactor.core.publisher.MonoThenMap$ThenMapMain$ThenMapInner.onError(MonoThenMap.java:247)
	at reactor.core.publisher.Operators$MonoSubscriber.onError(Operators.java:1005)
	at reactor.core.publisher.MonoThenIgnore$ThenAcceptInner.onError(MonoThenIgnore.java:295)
	at reactor.core.publisher.Operators.error(Operators.java:227)
	at reactor.ipc.netty.FutureMono$DeferredFutureMono.subscribe(FutureMono.java:128)
	at reactor.core.publisher.MonoSource.subscribe(MonoSource.java:72)
	at reactor.core.publisher.MonoThenIgnore$ThenIgnoreMain.drain(MonoThenIgnore.java:147)
	at reactor.core.publisher.MonoThenIgnore$ThenIgnoreMain.ignoreDone(MonoThenIgnore.java:183)
	at reactor.core.publisher.MonoThenIgnore$ThenIgnoreInner.onComplete(MonoThenIgnore.java:230)
	at reactor.core.publisher.MonoIgnoreEmpty$IgnoreElementsSubscriber.onComplete(MonoIgnoreEmpty.java:80)
	at reactor.core.publisher.Operators$MonoSubscriber.onComplete(Operators.java:1000)
	at reactor.core.publisher.MonoThenIgnore$ThenAcceptInner.onComplete(MonoThenIgnore.java:303)
	at reactor.ipc.netty.FutureMono$FutureSubscription.operationComplete(FutureMono.java:168)
	at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:507)
	at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:481)
	at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:420)
	at io.netty.util.concurrent.DefaultPromise.setSuccess(DefaultPromise.java:95)
	at io.netty.channel.DefaultChannelPromise.setSuccess(DefaultChannelPromise.java:76)
	at io.netty.channel.DefaultChannelPromise.setSuccess(DefaultChannelPromise.java:71)
	at reactor.ipc.netty.channel.ChannelOperationsHandler$PublisherSender.operationComplete(ChannelOperationsHandler.java:550)
	at reactor.ipc.netty.channel.ChannelOperationsHandler$PublisherSender.operationComplete(ChannelOperationsHandler.java:407)
	at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:507)
	at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:481)
	at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:420)
	at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:104)
	at io.netty.util.internal.PromiseNotificationUtil.trySuccess(PromiseNotificationUtil.java:48)
	at io.netty.channel.ChannelOutboundBuffer.safeSuccess(ChannelOutboundBuffer.java:668)
	at io.netty.channel.ChannelOutboundBuffer.remove(ChannelOutboundBuffer.java:257)
	at io.netty.channel.ChannelOutboundBuffer.removeBytes(ChannelOutboundBuffer.java:337)
	at io.netty.channel.socket.nio.NioSocketChannel.doWrite(NioSocketChannel.java:448)
	at io.netty.channel.AbstractChannel$AbstractUnsafe.flush0(AbstractChannel.java:856)
	at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0(AbstractNioChannel.java:362)
	at io.netty.channel.AbstractChannel$AbstractUnsafe.flush(AbstractChannel.java:823)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.flush(DefaultChannelPipeline.java:1296)
	at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:776)
	at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:768)
	at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:749)
	at io.netty.handler.logging.LoggingHandler.flush(LoggingHandler.java:249)
	at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:776)
	at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:768)
	at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:749)
	at io.netty.handler.ssl.SslHandler.forceFlush(SslHandler.java:1572)
	at io.netty.handler.ssl.SslHandler.flushIfNeeded(SslHandler.java:1094)
	at io.netty.handler.ssl.SslHandler.channelReadComplete(SslHandler.java:1076)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelReadComplete(AbstractChannelHandlerContext.java:398)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelReadComplete(AbstractChannelHandlerContext.java:380)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelReadComplete(AbstractChannelHandlerContext.java:373)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelReadComplete(ChannelInboundHandlerAdapter.java:97)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelReadComplete(AbstractChannelHandlerContext.java:398)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelReadComplete(AbstractChannelHandlerContext.java:380)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelReadComplete(AbstractChannelHandlerContext.java:373)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelReadComplete(DefaultChannelPipeline.java:1339)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelReadComplete(AbstractChannelHandlerContext.java:398)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelReadComplete(AbstractChannelHandlerContext.java:380)
	at io.netty.channel.DefaultChannelPipeline.fireChannelReadComplete(DefaultChannelPipeline.java:932)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:139)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:624)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:559)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:476)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:438)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
	at java.lang.Thread.run(Thread.java:748)

[cwesdorp]

Short update; I found that from the MultipartHttpClientRequest which is used to upload the application the closeDelimiter is not sent. After the ZIP file is uploaded it doesn't do anything and falls into a time out after 2 minutes.
This happens only on windows.

The related part in the log file

|000bc1b0| e4 01 76 18 6b 00 77 65 62 2f 77 69 64 67 65 74 |..v.k.web/widget|
|000bc1c0| 73 2f 53 70 72 69 6e 74 72 46 65 65 64 62 61 63 |s/SprintrFeedbac|
|000bc1d0| 6b 57 69 64 67 65 74 2f 53 70 72 69 6e 74 72 46 |kWidget/SprintrF|
|000bc1e0| 65 65 64 62 61 63 6b 2e 78 6d 6c 50 4b 05 06 00 |eedback.xmlPK...|
|000bc1f0| 00 00 00 c9 01 c9 01 b5 a2 00 00 36 1f 6b 00 00 |...........6.k..|
|000bc200| 00                                              |.               |
+--------+-------------------------------------------------+----------------+
15:42:26.642 [cloudfoundry-client-nio-4] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x39ed4147, L:/10.211.55.3:62315 - R:api.eu-gb.bluemix.net/5.10.124.140:443] FLUSH
15:42:26.657 [cloudfoundry-client-nio-4] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x39ed4147, L:/10.211.55.3:62315 - R:api.eu-gb.bluemix.net/5.10.124.140:443] USER_EVENT: [Response Write Completed]
15:42:26.657 [cloudfoundry-client-nio-4] TRACE reactor.ipc.netty.channel.ChannelOperationsHandler - [id: 0x39ed4147, L:/10.211.55.3:62315 - R:api.eu-gb.bluemix.net/5.10.124.140:443] End of the pipeline, User event [Response Write Completed]
15:42:26.665 [cloudfoundry-client-nio-4] DEBUG reactor.ipc.netty.channel.ChannelOperationsHandler - [id: 0x39ed4147, L:/10.211.55.3:62315 - R:api.eu-gb.bluemix.net/5.10.124.140:443] Write state change false

... two minutes waiting here ...

15:44:29.511 [cloudfoundry-client-nio-4] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x39ed4147, L:/10.211.55.3:62315 - R:api.eu-gb.bluemix.net/5.10.124.140:443] USER_EVENT: SslCloseCompletionEvent(SUCCESS)
15:44:29.512 [cloudfoundry-client-nio-4] TRACE reactor.ipc.netty.channel.ChannelOperationsHandler - [id: 0x39ed4147, L:/10.211.55.3:62315 - R:api.eu-gb.bluemix.net/5.10.124.140:443] End of the pipeline, User event SslCloseCompletionEvent(SUCCESS)
15:44:29.512 [cloudfoundry-client-nio-4] DEBUG reactor.ipc.netty.http.client.HttpClient - [id: 0x39ed4147, L:/10.211.55.3:62315 - R:api.eu-gb.bluemix.net/5.10.124.140:443] RECEIVED: 155B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 48 54 54 50 2f 31 2e 31 20 35 30 30 20 49 6e 74 |HTTP/1.1 500 Int|
|00000010| 65 72 6e 61 6c 20 53 65 72 76 65 72 20 45 72 72 |ernal Server Err|
|00000020| 6f 72 0d 0a 43 6f 6e 74 65 6e 74 2d 54 79 70 65 |or..Content-Type|
|00000030| 3a 20 74 65 78 74 2f 78 6d 6c 3b 20 63 68 61 72 |: text/xml; char|
|00000040| 73 65 74 3d 22 75 74 66 2d 38 22 0d 0a 58 2d 42 |set="utf-8"..X-B|
|00000050| 61 63 6b 73 69 64 65 2d 54 72 61 6e 73 70 6f 72 |ackside-Transpor|
|00000060| 74 3a 20 46 41 49 4c 20 46 41 49 4c 0d 0a 43 6f |t: FAIL FAIL..Co|
|00000070| 6e 6e 65 63 74 69 6f 6e 3a 20 63 6c 6f 73 65 0d |nnection: close.|
|00000080| 0a 0d 0a 35 30 30 20 45 72 72 6f 72 3a 20 4e 65 |...500 Error: Ne|
|00000090| 74 77 6f 72 6b 20 65 72 72 6f 72                |twork error     |
+--------+-------------------------------------------------+----------------+
15:44:29.513 [cloudfoundry-client-nio-4] DEBUG reactor.ipc.netty.http.client.HttpClientOperations - [id: 0x39ed4147, L:/10.211.55.3:62315 - R:api.eu-gb.bluemix.net/5.10.124.140:443] Received response (auto-read:false) : [Content-Type=text/xml; charset="utf-8", X-Backside-Transport=FAIL FAIL, Connection=close]

[nebhale]

@cwesdorp What versions of cloudfoundry-client, cloudfoundry-operations, reactor-core, and reactor-netty are you using?

[cwesdorp]

cloudfoundry-client-reactor 2.13.0.RELEASE
cloudfoundry-operations 2.13.0.RELEASE
reactor-core 3.0.7.RELEASE
reactor-netty 0.6.4.RELEASE

I also tried 2.14 which has the same issue. Resource matching doesn't have anything to do with it I guess now. Whenever the app to push is > 1MB it fails. According to whireshark TLSv1.2 is used.

[nebhale]

@smaldini Any thoughts on a stalling upload?

[nebhale]

The reactor-netty team (specifically @violetagg) has done some investigation into this and we think there’s likely an issue with reactor-netty flushing specifically sized payloads. An issue has been opened against reactor-netty.

[cwesdorp]

Thanks for the feedback, i'll follow the other issue as well to track.

[violetagg]

@cwesdorp Would you be able to provide some simple reproducible scenario? It will speed up the investigation of the problem.
Thanks,
Violeta

[cwesdorp]

@violetagg I have a sample application for you here https://github.com/cwesdorp/cfjavaclient-issue780.

The example is a bit tricky because the Cloud Cache removes files already on CF from the deployment which sometimes makes the deployment work. I add two files with random data to the ZIP before pushing, this always fails when executed from Windows.

I used bluemix as target but it also fails on other CF providers.
To use the application copy src/main/resources/api.properties.sample to src/main/resources/api.properties with the parameters in there and then use "mvn verify exec:exec" to run it. A log file will be written.

[violetagg]

@cwesdorp A fix is available in Reactor Netty 0.6.5.BUILD-SNAPSHOT (http://repo.spring.io/libs-snapshot). If you are able to verify it on your side it will be great.

Regards,
Violeta

[cwesdorp]

@violetagg Yes, it works. Many, many thanks for fixing this.
When do you think you can release 0.6.5? That way I don't need to add a snapshot dependency to my production build.

Regards,
Chris

[violetagg]

The current planning is 17.08 (https://github.com/reactor/reactor-netty/milestones)