Spring RSocket Input/Output cardinality not being handled correctly (FNF not working)

Given the following sample:

@MessageMapping("fire-and-forget.{identifier}")
public Mono<Void> fireAndForget(@DestinationVariable String identifier) {
   log.info("Fire-and-forget is correctly being invoked with identifier: {}", identifier);
   return Mono.empty();
}

I would expect to invoke this as a Fire-and-forget interaction, e.g: Following 2 examples uses the RSocket Client CLI: https://github.com/making/rsc

java -jar rsc.jar --debug --fnf --route fire-and-forget.foo-bar tcp://localhost:7000

However nothing seems to happen, if I change it to a Request/response interaction instead, a log message is being written in my console output.

java -jar rsc.jar --debug --request --route fire-and-forget.foo-bar tcp://localhost:7000

2020-06-19 14:09:46.805  INFO 26120 --- [ctor-http-nio-4] c.e.r.RSocketController                  : Fire-and-forget is correctly being invoked with identifier: foo-bar

For a full sample, checkout my code sample at https://github.com/dnijssen/rsocket-fire-and-forget and look at the RSocketController

Comment From: bclozel

I've just tried this against Spring Boot 2.4.0-SNAPSHOT and I reproduced the problem with rsc.

I've turned debugging on with this in application.properties:

spring.rsocket.server.port=9898
spring.rsocket.server.transport=tcp
logging.level.io.rsocket=DEBUG

When using java -jar rsc-0.4.2.jar tcp://127.0.0.1:9898 -debug --fnf --route fire-and-forget.foo-bar I'm getting the following and nothing more:

2020-06-22 10:58:19.157 DEBUG 3537 --- [ctor-http-nio-2] io.rsocket.FrameLogger                   : receiving -> 
Frame => Stream ID: 0 Type: SETUP Flags: 0b0 Length: 64
Data:

So it seems we're not receiving the FNF Frame.

Same thing this time, but with request java -jar rsc-0.4.2.jar tcp://127.0.0.1:9898 -debug --request --route fire-and-forget.foo-bar

2020-06-22 10:58:53.984 DEBUG 3537 --- [ctor-http-nio-3] io.rsocket.FrameLogger                   : receiving -> 
Frame => Stream ID: 0 Type: SETUP Flags: 0b0 Length: 64
Data:

2020-06-22 10:58:55.877 DEBUG 3537 --- [ctor-http-nio-3] io.rsocket.FrameLogger                   : receiving -> 
Frame => Stream ID: 1 Type: REQUEST_RESPONSE Flags: 0b100000000 Length: 33
Metadata:
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 17 66 69 72 65 2d 61 6e 64 2d 66 6f 72 67 65 74 |.fire-and-forget|
|00000010| 2e 66 6f 6f 2d 62 61 72                         |.foo-bar        |
+--------+-------------------------------------------------+----------------+
Data:

Here we're getting the REQUEST_RESPONSE Frame as expected.

I've tried using a java client to do the same:

@SpringBootTest
public class TestClient {

    @Test
    void testFnF(@Autowired RSocketRequester.Builder builder) {
        RSocketRequester requester = builder.connectTcp("localhost", 9898).block();
        requester.route("fire-and-forget.foo-bar").send().block();
    }
}

And this time I'm getting the expected logs on the server side:

2020-06-22 11:04:07.311 DEBUG 3577 --- [ctor-http-nio-2] io.rsocket.FrameLogger                   : receiving -> 
Frame => Stream ID: 0 Type: SETUP Flags: 0b0 Length: 75
Data:

2020-06-22 11:04:07.335 DEBUG 3577 --- [actor-tcp-nio-1] io.rsocket.FrameLogger                   : sending -> 
Frame => Stream ID: 1 Type: REQUEST_FNF Flags: 0b100000000 Length: 37
Metadata:
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| fe 00 00 18 17 66 69 72 65 2d 61 6e 64 2d 66 6f |.....fire-and-fo|
|00000010| 72 67 65 74 2e 66 6f 6f 2d 62 61 72             |rget.foo-bar    |
+--------+-------------------------------------------------+----------------+
Data:

2020-06-22 11:04:07.338 DEBUG 3577 --- [ctor-http-nio-2] io.rsocket.FrameLogger                   : receiving -> 
Frame => Stream ID: 1 Type: REQUEST_FNF Flags: 0b100000000 Length: 37
Metadata:
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| fe 00 00 18 17 66 69 72 65 2d 61 6e 64 2d 66 6f |.....fire-and-fo|
|00000010| 72 67 65 74 2e 66 6f 6f 2d 62 61 72             |rget.foo-bar    |
+--------+-------------------------------------------------+----------------+
Data:


2020-06-22 11:04:07.345  INFO 3577 --- [ctor-http-nio-2] com.example.demo.TestController          : Fire-and-forget is correctly being invoked with identifier: foo-bar

At that point, I'm guessing there might be an issue with the rsc client; maybe a bug or maybe we're using an outdated version here? In any case, since we're not seeing the expected frames on the rsocket server side I'm closing this issue for now.

Could you create an issue on rsc directly? We'll need to start from there and figure out if this is a problem in Framework, rsc or rsocket-java.

Thanks!

Comment From: making

@dnijssen Hi, I'm the creator of rsc. ~I have fixed the issue and cut a release~ ~Could you please test it again with 0.4.3?~ ~https://github.com/making/rsc/releases/tag/0.4.3~

I found 0.4.3 did not fix the bug. I'll rework for it.

Comment From: making

@dalbani Sorry the fix in 0.4.3 was not correct. The problem is that the cli quits earlier than flushing Fire-and-Forget data at TCP level.

I've added a workaround and released 0.4.4 https://github.com/making/rsc/releases/tag/0.4.4 Thanks!

Comment From: bclozel

Thanks a lot for the quick fix @making !

Comment From: dnijssen

Thank for fixing it so quick @making , i've tested it and works now ;)