rsocket-load-balancer first request always ends up with error

[mmaszkie]

Hi,
I have a problem with rsocket-load-balancer. I have one instance of client application and 2 instances of server application. They are communicating via RSocket (request/response interaction model) using rsocket-load-balancer on the client side. Unfortunately first request always ends up with an error on the client side.

Scenario:

• I start server applications and then client application,
• during client application startup single instance of LoadBalancedRSocketMono is being created in order to manage RSocket connections between client and server instances; logs:

2019-11-06 13:10:40,661 13:10:40.661 [reactor-http-nio-2] DEBUG i.rsocket.client.RSocketSupplierPool - 
Updated active factories (size: 2)
 + RSocketSupplier{address=Address(host=xxx.yyy.zzz, port=31135)}
 + RSocketSupplier{address=Address(host=xxx.yyy.zzz, port=31842)}
Active sockets:

• I would expect that the first request from client to server ends up with success, but it's not; there are some NoAvailableRSocketException exceptions in logs:

2019-11-06 13:22:21,524 13:22:21.524 [DefaultDispatcher-worker-1] DEBUG i.r.client.LoadBalancedRSocketMono - aperture 0 is below target 10, adding 10 sockets
2019-11-06 13:22:21,524 13:22:21.524 [DefaultDispatcher-worker-1] DEBUG i.r.client.LoadBalancedRSocketMono - addSockets(10) restricted by the number of factories, i.e. addSockets(2)
2019-11-06 13:22:21,525 13:22:21.525 [DefaultDispatcher-worker-1] DEBUG i.rsocket.client.RSocketSupplierPool - Added RSocketSupplier{address=Address(host=xxx.yyy.zzz.www, port=31135)} to leasedSuppliers
2019-11-06 13:22:21,525 13:22:21.525 [DefaultDispatcher-worker-1] DEBUG i.r.client.LoadBalancedRSocketMono - Creating WeightedSocket WeightedSocket(median=0.0 quantile-low=0.0 quantile-high=0.0 inter-arrival=1000000.0 duration/pending=0.0 pending=0 availability= 0.0)-> from factory RSocketSupplier{address=Address(host=xxx.yyy.zzz.www, port=31135)}
2019-11-06 13:22:21,822 13:22:21.822 [DefaultDispatcher-worker-1] DEBUG i.rsocket.client.RSocketSupplierPool - Added RSocketSupplier{address=Address(host=xxx.yyy.zzz.www, port=31842)} to leasedSuppliers
2019-11-06 13:22:21,822 13:22:21.822 [DefaultDispatcher-worker-1] DEBUG i.r.client.LoadBalancedRSocketMono - Creating WeightedSocket WeightedSocket(median=0.0 quantile-low=0.0 quantile-high=0.0 inter-arrival=1000000.0 duration/pending=0.0 pending=0 availability= 0.0)-> from factory RSocketSupplier{address=Address(host=xxx.yyy.zzz.www, port=31842)}
2019-11-06 13:22:21,823 13:22:21.823 [DefaultDispatcher-worker-1] DEBUG i.r.client.LoadBalancedRSocketMono - Bumping refresh period, 15000->22500
2019-11-06 13:22:21,824 13:22:21.824 [DefaultDispatcher-worker-1] DEBUG i.r.client.LoadBalancedRSocketMono - addSockets(1) restricted by the number of factories, i.e. addSockets(0)
2019-11-06 13:22:21,920 13:22:21.920 [DefaultDispatcher-worker-1] INFO  io.rsocket.client.NoAvailableRSocketException: null
    at io.rsocket.client.NoAvailableRSocketException.<init>(Unknown Source)
2019-11-06 13:22:21,920 13:22:21.920 [DefaultDispatcher-worker-1] INFO  io.rsocket.client.NoAvailableRSocketException: null
    at io.rsocket.client.NoAvailableRSocketException.<init>(Unknown Source)
2019-11-06 13:22:22,246 13:22:22.246 [reactor-tcp-nio-4] DEBUG i.r.client.LoadBalancedRSocketMono - Added WeightedSocket WeightedSocket(median=0.0 quantile-low=0.0 quantile-high=0.0 inter-arrival=1000000.0 duration/pending=0.0 pending=0 availability= 1.0)-> from factory RSocketSupplier{address=Address(host=xxx.yyy.zzz.www, port=31135)} to activeSockets
2019-11-06 13:22:22,246 13:22:22.246 [reactor-tcp-nio-3] DEBUG i.r.client.LoadBalancedRSocketMono - Added WeightedSocket WeightedSocket(median=0.0 quantile-low=0.0 quantile-high=0.0 inter-arrival=1000000.0 duration/pending=0.0 pending=0 availability= 1.0)-> from factory RSocketSupplier{address=Address(host=xxx.yyy.zzz.www, port=31842)} to activeSockets

• second and every next request ends up successfully.

Described behaviour is not random, but repeatable. I noticed that during LoadBalancedRSocketMono initialization, constructor of WeightedSocket class calls subscribe() method on Mono<RSocket> object. I think this situation can lead to inconsistency between RSocket state from application perspective and their general availability beacause of subscribe() method asynchronism. Is this intuition correct? Or maybe I did something wrong? In that case how can I solve this problem?

[nicpuze]

I have a similar problem with you. When the client side starts up, it finds that LoadBalancedRSocketMono#activeSockets is sometimes unavailable, so I want to get availability through LoadBalancedRSocketMono#availability() and wait for WeightedSocket to be generated asynchronously, but sometimes, availability() finds null elements in activeSockets and throws java.lang.NullPointerException

[juri8]

I changed the code and successfully tested the new behavior using retryBackoff.

https://github.com/juri8/rsocket-java/tree/bugfix/load-balanced-rsocket-mono-error-handling

[OlegDokuka]

Hey @mmaszkie @nicpuze @juri8!

The reason for the issue was the default fail-fast strategy, which had a place only when there are no active sockets in the pool. In this particular case, such may happen when the new instances have not been yet resolved, but there was a subscription on the LoadbalancedRSocketMono to get a one. In that case, the FailinRSocket instance was returned, which led to the NoAvailableRSocketException.

We have fixed that with the 1.1.0-M1 release and introduced the new Loadbalance API.

You may give it a try by following this example