search

rsocket / rsocket-go

rsocket-go implementation
Apache License 2.0
508 stars 46 forks source link

RSocket mono failure. #110

Closed d-wojciechowski closed 1 year ago

d-wojciechowski commented 3 years ago

Hey recently I encountered an error with communication via RSocket.

The idea of code is to provide a tree structure of file system on the other side of communication.

On the server side, where file system calculation is done I receive following log from this place: https://github.com/d-wojciechowski/plm-companion-addon/blob/golang-just-16-update/server/FileServerService.go please take a look at handler function Navigate, where that calculation is done.

Server starting with parameters: -v: true, -noWnc: true, -port: 4040
INFO : 2021/04/24 10:59:58 Server starting with parameters: -v: true, -noWnc: true, -port: 4040
INFO : 2021/04/24 10:59:58 Attempt to create server on addr 0.0.0.0:4040
INFO : 2021/04/24 10:59:58 Server instance started on addr 0.0.0.0:4040
INFO : 2021/04/24 11:00:13 Acceptor initialization started
INFO : 2021/04/24 11:00:13 RequestResponse initialization start
INFO : 2021/04/24 11:00:13 RequestResponse initialization start
INFO : 2021/04/24 11:00:13 RequestChannel initialization start
INFO : 2021/04/24 11:00:13 RequestChannel initialization ended
INFO : 2021/04/24 11:00:13 requestStreamHandler initialization start
INFO : 2021/04/24 11:00:13 requestStreamHandler initialization ended
INFO : 2021/04/24 11:00:13 Acceptor initialization ended
INFO : 2021/04/24 11:00:13 Service FileService with method navigate execution start
INFO : 2021/04/24 11:00:13 Navigation to 
INFO : 2021/04/24 11:00:13 Path is C:, Users, allst, AppData, Local, Temp
INFO : 2021/04/24 11:00:13 Starting build of response data
INFO : 2021/04/24 11:00:13 Build C: path element
INFO : 2021/04/24 11:00:13 Build Users path element
INFO : 2021/04/24 11:00:13 Build allst path element
INFO : 2021/04/24 11:00:13 Build AppData path element
INFO : 2021/04/24 11:00:13 Build Local path element
INFO : 2021/04/24 11:00:13 Build Temp path element
INFO : 2021/04/24 11:00:13 Full response build finished.
INFO : 2021/04/24 11:00:13 Service FileService with method navigate execution ended
panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xc0000005 code=0x0 addr=0x28 pc=0x891f0c]

goroutine 46 [running]:
github.com/rsocket/rsocket-go/internal/socket.(*DuplexConnection).sendPayload.func2.1()
    C:/Users/allst/go/pkg/mod/github.com/rsocket/rsocket-go@v0.8.3/internal/socket/duplex.go:1062 +0x2c
github.com/rsocket/rsocket-go/core/framing.(*writeableFrame).Done(...)
    C:/Users/allst/go/pkg/mod/github.com/rsocket/rsocket-go@v0.8.3/core/framing/writeable.go:25
github.com/rsocket/rsocket-go/core/framing.(*WriteablePayloadFrame).Done(0xc00009ea00)
    C:/Users/allst/go/pkg/mod/github.com/rsocket/rsocket-go@v0.8.3/core/framing/writeable_payload.go:88 +0xc7
github.com/rsocket/rsocket-go/core/transport.(*Transport).Send.func1(0xc00022dd50, 0xa7bc98, 0xc00009ea00)
    C:/Users/allst/go/pkg/mod/github.com/rsocket/rsocket-go@v0.8.3/core/transport/transport.go:112 +0x4d
github.com/rsocket/rsocket-go/core/transport.(*Transport).Send(0xc0000a40c0, 0xa7bc98, 0xc00009ea00, 0xc00022dd00, 0x0, 0x0)
    C:/Users/allst/go/pkg/mod/github.com/rsocket/rsocket-go@v0.8.3/core/transport/transport.go:124 +0x1ad
github.com/rsocket/rsocket-go/internal/socket.(*DuplexConnection).drainOne(0xc00006d180, 0xa7bc98, 0xc00009ea00, 0x0)
    C:/Users/allst/go/pkg/mod/github.com/rsocket/rsocket-go@v0.8.3/internal/socket/duplex.go:1182 +0x134
github.com/rsocket/rsocket-go/internal/socket.(*DuplexConnection).drain(0xc00006d180, 0x0, 0xc000302000)
    C:/Users/allst/go/pkg/mod/github.com/rsocket/rsocket-go@v0.8.3/internal/socket/duplex.go:1163 +0x165
github.com/rsocket/rsocket-go/internal/socket.(*DuplexConnection).LoopWrite(0xc00006d180, 0xa79758, 0xc000050ec0, 0x0, 0x0)
    C:/Users/allst/go/pkg/mod/github.com/rsocket/rsocket-go@v0.8.3/internal/socket/duplex.go:1299 +0x172
github.com/rsocket/rsocket-go/internal/socket.(*resumeServerSocket).Start(0xc000030e60, 0xa79758, 0xc000050ec0, 0x0, 0x0)
    C:/Users/allst/go/pkg/mod/github.com/rsocket/rsocket-go@v0.8.3/internal/socket/resumable_server_socket.go:36 +0x7d
github.com/rsocket/rsocket-go.(*server).Serve.func3.2(0xa79758, 0xc000050ec0, 0xa80a18, 0xc000030e60)
    C:/Users/allst/go/pkg/mod/github.com/rsocket/rsocket-go@v0.8.3/server.go:202 +0x50
created by github.com/rsocket/rsocket-go.(*server).Serve.func3
    C:/Users/allst/go/pkg/mod/github.com/rsocket/rsocket-go@v0.8.3/server.go:201 +0x6b0

Panic is being raised after return mono.Just(toPayload(getFullResult(root, protoPath.FullExpand), make([]byte, 1)))

On kotlin/java side I have following exception:

java.lang.RuntimeException: com.google.protobuf.InvalidProtocolBufferException: While parsing a protocol message, the input ended unexpectedly in the middle of a field. This could mean either that the input has been truncated or that an embedded message misreported its own length.

code which is responsible for that :

        return FileServiceClient(connector.getConnection())
            .navigate(pathObj)
            .retry(5)
            .block() ?: emptyResponse

The FileServiceClient is generated by rsocket-rpc-java, code you can check here : https://github.com/d-wojciechowski/plm-companion/blob/master/src/main/kotlin/pl/dwojciechowski/service/impl/FileServiceImpl.kt

Your Environment

jjeffcaii commented 3 years ago

Thanks for report! It seems a bug. When sending a large payload, it will be split to some little frames first, the original releasable payload resource will be released after all little frames done. But I check the code, here it is not releasable and miss nil check.

I'll fix it soon.

jjeffcaii commented 3 years ago

Please use v0.8.4 and feel free if you have any question. 😃

d-wojciechowski commented 3 years ago

Hey @jjeffcaii ! Thanks for very very fast fix & response!

Indeed now there is no panic at the end of execution, but on the client side I receive an error: java.lang.RuntimeException: com.google.protobuf.InvalidProtocolBufferException: While parsing a protocol message, the input ended unexpectedly in the middle of a field. This could mean either that the input has been truncated or that an embedded message misreported its own length.

Do you think that this may be managed under this issue, or I should open another issue on "RSocker-java" or "RSocket-rpc-java"? Or would you be able to help me figure out where is the issue? Because I am not sure if that comes from my code/libraries(rsocket-go/rsocket-rpc-java/rsocket-java)?

Best regards!

jjeffcaii commented 3 years ago

Try remove Fragment(1024).Resume() from server, I think it is not necessary here. Then you can open the debug level log, the SDK will print each binary payload, and you can validate the binary message.

jjeffcaii commented 3 years ago

By the way, use logger.SetLevel(logger.DebugLevel) to open it.

jjeffcaii commented 3 years ago

To be honest, I think the Java implementation is much more stable than the Go, so let's check the Go SDK first. 😄

d-wojciechowski commented 3 years ago

Thanks for the nice hint! When the fragment is disabled on both client and server, the message is delivered correctly (Resume did not affect the result).

From debug i received 33k of lines. It starts as follows:

2021/04/26 10:56:53 [DEBUG] 
Frame => Stream ID: 0 Type: SETUP Flags: 0b0010000000 Length: 74
Data:

2021/04/26 10:56:53 [DEBUG] 
Frame => Stream ID: 1 Type: REQUEST_RESPONSE Flags: 0b0100000000 Length: 38
Metadata:
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 01 00 0b 46 69 6c 65 53 65 72 76 69 63 65 00 |....FileService.|
|00000010| 08 6e 61 76 69 67 61 74 65 00 00                |.navigate..     |
+--------+-------------------------------------------------+----------------+
Data:
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 10 01                                           |..              |
+--------+-------------------------------------------------+----------------+
2021/04/26 10:56:53 [DEBUG] 
Frame => Stream ID: 1 Type: PAYLOAD Flags: 0b0111100000 Length: 1024
Metadata:
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00                                              |.               |
+--------+-------------------------------------------------+----------------+
Data:
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 0a fe dd 04 0a 02 43 3a 10 01 1a 0f 0a 0b 24 47 |......C:......$G|
|00000010| 65 74 43 75 72 72 65 6e 74 10 01 1a 10 0a 0c 24 |etCurrent......$|
|00000020| 52 65 63 79 63 6c 65 2e 42 69 6e 10 01 1a 0f 0a |Recycle.Bin.....|
|00000030| 0b 24 57 69 6e 52 45 41 67 65 6e 74 10 01 1a 18 |.$WinREAgent....|
|00000040| 0a 16 44 6f 63 75 6d 65 6e 74 73 20 61 6e 64 20 |..Documents and |
|00000050| 53 65 74 74 69 6e 67 73 1a 13 0a 11 44 75 6d 70 |Settings....Dump|
|00000060| 53 74 61 63 6b 2e 6c 6f 67 2e 74 6d 70 1a 0d 0a |Stack.log.tmp...|
|00000070| 09 47 4f 47 20 47 61 6d 65 73 10 01 1a 09 0a 05 |.GOG Games......|
|00000080| 49 6e 74 65 6c 10 01 1a 10 0a 0c 4f 6e 65 44 72 |Intel......OneDr|
|00000090| 69 76 65 54 65 6d 70 10 01 1a 0c 0a 08 50 65 72 |iveTemp......Per|
|000000a0| 66 4c 6f 67 73 10 01 1a 11 0a 0d 50 72 6f 67 72 |fLogs......Progr|
|000000b0| 61 6d 20 46 69 6c 65 73 10 01 1a 17 0a 13 50 72 |am Files......Pr|
|000000c0| 6f 67 72 61 6d 20 46 69 6c 65 73 20 28 78 38 36 |ogram Files (x86|
|000000d0| 29 10 01 1a 0f 0a 0b 50 72 6f 67 72 61 6d 44 61 |)......ProgramDa|
|000000e0| 74 61 10 01 1a 0c 0a 08 50 79 74 68 6f 6e 33 39 |ta......Python39|
|000000f0| 10 01 1a 0c 0a 08 52 65 63 6f 76 65 72 79 10 01 |......Recovery..|
|00000100| 1a 1d 0a 19 53 79 73 74 65 6d 20 56 6f 6c 75 6d |....System Volum|
|00000110| 65 20 49 6e 66 6f 72 6d 61 74 69 6f 6e 10 01 1a |e Information...|
|00000120| fc da 04 0a 05 55 73 65 72 73 10 01 1a 0b 0a 09 |.....Users......|
|00000130| 41 6c 6c 20 55 73 65 72 73 1a 0b 0a 07 44 65 66 |All Users....Def|
|00000140| 61 75 6c 74 10 01 1a 0e 0a 0c 44 65 66 61 75 6c |ault......Defaul|
|00000150| 74 20 55 73 65 72 1a 0a 0a 06 50 75 62 6c 69 63 |t User....Public|
|00000160| 10 01 1a 85 da 04 0a 05 61 6c 6c 73 74 10 01 1a |........allst...|
|00000170| 0b 0a 07 2e 4f 72 69 67 69 6e 10 01 1a 17 0a 13 |....Origin......|
|00000180| 2e 51 74 57 65 62 45 6e 67 69 6e 65 50 72 6f 63 |.QtWebEngineProc|
|00000190| 65 73 73 10 01 1a 0c 0a 08 2e 61 6e 64 72 6f 69 |ess.......androi|
|000001a0| 64 10 01 1a 08 0a 04 2e 61 77 73 10 01 1a 0a 0a |d.......aws.....|
|000001b0| 06 2e 61 7a 75 72 65 10 01 1a 0f 0a 0d 2e 62 61 |..azure.......ba|
|000001c0| 73 68 5f 68 69 73 74 6f 72 79 1a 0f 0a 0d 2e 62 |sh_history.....b|
|000001d0| 61 73 68 5f 70 72 6f 66 69 6c 65 1a 09 0a 07 2e |ash_profile.....|
|000001e0| 62 61 73 68 72 63 1a 0a 0a 06 2e 63 61 63 68 65 |bashrc.....cache|
|000001f0| 10 01 1a 0a 0a 06 2e 63 6f 6e 64 61 10 01 1a 0a |.......conda....|
|00000200| 0a 08 2e 63 6f 6e 64 61 72 63 1a 12 0a 0e 2e 64 |...condarc.....d|
|00000210| 62 75 73 2d 6b 65 79 72 69 6e 67 73 10 01 1a 08 |bus-keyrings....|
|00000220| 0a 04 2e 64 6c 76 10 01 1a 0b 0a 07 2e 64 6f 63 |...dlv.......doc|
|00000230| 6b 65 72 10 01 1a 0b 0a 07 2e 64 6f 74 6e 65 74 |ker.......dotnet|
|00000240| 10 01 1a 0c 0a 08 2e 65 63 6c 69 70 73 65 10 01 |.......eclipse..|
|00000250| 1a 1e 0a 1c 2e 65 6d 75 6c 61 74 6f 72 5f 63 6f |.....emulator_co|
|00000260| 6e 73 6f 6c 65 5f 61 75 74 68 5f 74 6f 6b 65 6e |nsole_auth_token|
|00000270| 1a 0c 0a 0a 2e 67 69 74 63 6f 6e 66 69 67 1a 0b |.....gitconfig..|
|00000280| 0a 07 2e 67 72 61 64 6c 65 10 01 1a 16 0a 12 2e |...gradle.......|
|00000290| 69 70 79 6e 62 5f 63 68 65 63 6b 70 6f 69 6e 74 |ipynb_checkpoint|
|000002a0| 73 10 01 1a 0c 0a 08 2e 69 70 79 74 68 6f 6e 10 |s.......ipython.|
|000002b0| 01 1a 09 0a 05 2e 6a 64 6b 73 10 01 1a 07 0a 03 |......jdks......|
|000002c0| 2e 6d 32 10 01 1a 0f 0a 0b 2e 70 6c 61 74 66 6f |.m2.......platfo|
|000002d0| 72 6d 69 6f 10 01 1a 13 0a 0f 2e 70 6c 75 67 69 |rmio.......plugi|
|000002e0| 6e 56 65 72 69 66 69 65 72 10 01 1a 0e 0a 0a 2e |nVerifier.......|
|000002f0| 73 6f 6e 61 72 6c 69 6e 74 10 01 1a 08 0a 04 2e |sonarlint.......|
|00000300| 73 73 68 10 01 1a 08 0a 04 2e 73 77 74 10 01 1a |ssh.......swt...|
|00000310| 0a 0a 08 2e 76 69 6d 69 6e 66 6f 1a 0b 0a 07 2e |....viminfo.....|
|00000320| 76 73 63 6f 64 65 10 01 1a 0e 0a 0a 33 44 20 4f |vscode......3D O|
|00000330| 62 6a 65 63 74 73 10 01 1a 19 0a 15 41 6e 64 72 |bjects......Andr|
|00000340| 6f 69 64 53 74 75 64 69 6f 50 72 6f 6a 65 63 74 |oidStudioProject|
|00000350| 73 10 01 1a d4 cf 04 0a 07 41 70 70 44 61 74 61 |s........AppData|
|00000360| 10 01 1a aa cf 04 0a 05 4c 6f 63 61 6c 10 01 1a |........Local...|
|00000370| 14 0a 10 2e 49 64 65 6e 74 69 74 79 53 65 72 76 |....IdentityServ|
|00000380| 69 63 65 10 01 1a 06 0a 02 32 4b 10 01 1a 0d 0a |ice......2K.....|
|00000390| 09 41 43 50 68 6f 65 6e 69 78 10 01 1a 0a 0a 06 |.ACPhoenix......|
|000003a0| 41 6d 61 7a 6f 6e 10 01 1a 0b 0a 07 41 6e 64 72 |Amazon......Andr|
|000003b0| 6f 69 64 10 01 1a 1f 0a 1b 41 6e 64 72 6f 69 64 |oid......Android|
|000003c0| 20 4f 70 65 6e 20 53 6f 75 72 63 65 20 50 72 6f | Open Source Pro|
|000003d0| 6a 65 63 74 10 01 1a 08 0a 04 41 70 70 73 10 01 |ject......Apps..|
|000003e0| 1a 0e 0a 0a 42 61 74 74 6c 65 2e 6e 65 74 10 01 |....Battle.net..|
|000003f0| 1a 1a 0a 16 42 6c                               |....Bl          |
+--------+-------------------------------------------------+----------------+
2021/04/26 10:56:53 [DEBUG] 
Frame => Stream ID: 1 Type: PAYLOAD Flags: 0b0010100000 Length: 1024
Metadata:

Data:
............. [ next block looks similar]

End it ends with:

2021/04/26 10:56:53 [DEBUG] 
Frame => Stream ID: 11 Type: PAYLOAD Flags: 0b0000100000 Length: 232
Metadata:

Data:
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 74 2e 4c 4f 47 32 1a 0c 0a 0a 6e 74 75 73 65 72 |t.LOG2....ntuser|
|00000010| 2e 69 6e 69 1a 08 0a 04 74 65 6d 70 10 01 1a 0a |.ini....temp....|
|00000020| 0a 08 74 65 78 74 2e 74 78 74 1a 0b 0a 09 74 65 |..text.txt....te|
|00000030| 78 74 32 2e 74 78 74 1a 15 0a 11 64 65 66 61 75 |xt2.txt....defau|
|00000040| 6c 74 75 73 65 72 31 30 30 30 30 30 10 01 1a 0d |ltuser100000....|
|00000050| 0a 0b 64 65 73 6b 74 6f 70 2e 69 6e 69 1a 0c 0a |..desktop.ini...|
|00000060| 08 74 75 74 6f 72 69 61 6c 10 01 1a 0a 0a 06 57 |.tutorial......W|
|00000070| 43 48 2e 43 4e 10 01 1a 0b 0a 07 57 69 6e 64 6f |CH.CN......Windo|
|00000080| 77 73 10 01 1a 0e 0a 0c 68 69 62 65 72 66 69 6c |ws......hiberfil|
|00000090| 2e 73 79 73 1a 0d 0a 0b 6d 73 64 69 61 38 30 2e |.sys....msdia80.|
|000000a0| 64 6c 6c 1a 0e 0a 0c 70 61 67 65 66 69 6c 65 2e |dll....pagefile.|
|000000b0| 73 79 73 1a 0e 0a 0c 73 77 61 70 66 69 6c 65 2e |sys....swapfile.|
|000000c0| 73 79 73 1a 09 0a 05 74 6f 6f 6c 73 10 01 0a 06 |sys....tools....|
|000000d0| 0a 02 44 3a 10 01 12 01 5c 1a 07 77 69 6e 64 6f |..D:....\..windo|
|000000e0| 77 73                                           |ws              |
+--------+-------------------------------------------------+----------------+
2021/04/26 10:57:13 [DEBUG] 
Frame => Stream ID: 0 Type: KEEPALIVE Flags: 0b0010000000 Length: 14

So the output from rsocket looks fine.

So thanks to you there is workaround (remove specification of fragment size).

Data looks fine to me which is being sent from server side, I am not sure if the Metadata is correct (it is empty in data blocks which are consequent fragments). But length in frames seems to be fine as well.

jjeffcaii commented 1 year ago

Closed since it has been long time ago.