Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

FS2 bidirectional-streaming random test failure #164

Closed
juanpedromoreno opened this issue Feb 12, 2018 · 4 comments
Closed

FS2 bidirectional-streaming random test failure #164

juanpedromoreno opened this issue Feb 12, 2018 · 4 comments
Labels
bug Something isn't working help wanted Extra attention is needed tests Improves or modifies tests

Comments

@juanpedromoreno
Copy link
Member

juanpedromoreno commented Feb 12, 2018 •
edited
Loading

After #163, one of the fs2 tests has been ignored because a random failure we are not able to fix at this moment. It's being manifesting in this way:

[info] frees-rpc client with fs2.Stream as streaming implementation and compression enabled
[info] - should be able to run unary services
[info] - should be able to run server streaming services
[info] - should be able to run client streaming services
[info] - should be able to run client bidirectional streaming services
[info] - should be able to run multiple rpc services *** FAILED ***
[info]   List() was not equal to List(E(A(100,200),foo3), E(A(1000,2000),foo4)) (RPCTests.scala:164)
@juanpedromoreno juanpedromoreno added the bug Something isn't working label Feb 12, 2018
@L-Lavigne L-Lavigne self-assigned this Mar 16, 2018
@L-Lavigne L-Lavigne removed their assignment Apr 2, 2018
@juanpedromoreno juanpedromoreno mentioned this issue Apr 4, 2018
Merged
This was referenced Apr 17, 2018
Closed
Closed
@L-Lavigne L-Lavigne added the tests Improves or modifies tests label May 8, 2018
@L-Lavigne L-Lavigne self-assigned this May 11, 2018
@L-Lavigne
Copy link
Contributor

L-Lavigne commented May 16, 2018 •
edited
Loading

This issue recently started happening locally, also intermittently. I haven't found the cause yet, and trying to simplify the FS2->Monix conversions and their execution contexts hasn't helped so far.

I created logging interceptors on both the client and server side (seen here: 2be5d80) and recorded the results of a failed and a successful run of the same FS2 bidirectional test: https://github.com/frees-io/freestyle-rpc/blob/2be5d801b05e8146e921d0e2b52757d177586e64/modules/server/src/test/scala/fs2/RPCTests.scala#L146

I'll update this post with further findings.

FS2 Success:

17:25:05.499 [grpc-default-worker-ELG-1-2] DEBUG io.grpc.netty.NettyClientHandler - [id: 0xdf16c2f3, L:/127.0.0.1:65382 - R:localhost/127.0.0.1:50051] OUTBOUND HEADERS: streamId=31 headers=GrpcHttp2OutboundHeaders[:authority: localhost:50051, :path: /RPCService/biStreaming, :method: POST, :scheme: http, content-type: application/grpc, te: trailers, user-agent: grpc-java-netty/1.11.0, grpc-accept-encoding: gzip, grpc-trace-bin: ] streamDependency=0 weight=16 exclusive=false padding=0 endStream=false
17:25:05.499 [grpc-default-executor-0] DEBUG f.rpc.fs2.ClientLoggingInterceptor - onReady
17:25:05.499 [grpc-default-worker-ELG-1-3] DEBUG io.grpc.netty.NettyServerHandler - [id: 0xde84dfef, L:/127.0.0.1:50051 - R:/127.0.0.1:65382] INBOUND HEADERS: streamId=31 headers=GrpcHttp2RequestHeaders[:path: /RPCService/biStreaming, :authority: localhost:50051, :method: POST, :scheme: http, te: trailers, content-type: application/grpc, user-agent: grpc-java-netty/1.11.0, grpc-accept-encoding: gzip, grpc-trace-bin: ] streamDependency=0 weight=16 exclusive=false padding=0 endStream=false
17:25:05.500 [grpc-default-executor-0] DEBUG f.rpc.fs2.ServerLoggingInterceptor - onReady
17:25:05.502 [grpc-default-worker-ELG-1-2] DEBUG io.grpc.netty.NettyClientHandler - [id: 0xdf16c2f3, L:/127.0.0.1:65382 - R:localhost/127.0.0.1:50051] OUTBOUND DATA: streamId=31 padding=0 endStream=false length=14 bytes=0000000009c801900308666f6f33
17:25:05.503 [grpc-default-worker-ELG-1-2] DEBUG io.grpc.netty.NettyClientHandler - [id: 0xdf16c2f3, L:/127.0.0.1:65382 - R:localhost/127.0.0.1:50051] OUTBOUND DATA: streamId=31 padding=0 endStream=false length=14 bytes=0000000009d00fa01f08666f6f34
17:25:05.503 [grpc-default-worker-ELG-1-3] DEBUG io.grpc.netty.NettyServerHandler - [id: 0xde84dfef, L:/127.0.0.1:50051 - R:/127.0.0.1:65382] INBOUND DATA: streamId=31 padding=0 endStream=false length=14 bytes=0000000009c801900308666f6f33
17:25:05.504 [grpc-default-worker-ELG-1-3] DEBUG io.grpc.netty.NettyServerHandler - [id: 0xde84dfef, L:/127.0.0.1:50051 - R:/127.0.0.1:65382] INBOUND DATA: streamId=31 padding=0 endStream=false length=14 bytes=0000000009d00fa01f08666f6f34
17:25:05.504 [grpc-default-executor-0] DEBUG f.rpc.fs2.ServerLoggingInterceptor - E(A(100,200),foo3)
17:25:05.505 [grpc-default-executor-0] DEBUG f.rpc.fs2.ServerLoggingInterceptor - E(A(1000,2000),foo4)
17:25:05.505 [grpc-default-worker-ELG-1-2] DEBUG io.grpc.netty.NettyClientHandler - [id: 0xdf16c2f3, L:/127.0.0.1:65382 - R:localhost/127.0.0.1:50051] OUTBOUND DATA: streamId=31 padding=0 endStream=true length=0 bytes=
17:25:05.505 [scala-execution-context-global-26] DEBUG freestyle.rpc.fs2.Utils$ - Processing: E(A(100,200),foo3)
17:25:05.505 [grpc-default-worker-ELG-1-3] DEBUG io.grpc.netty.NettyServerHandler - [id: 0xde84dfef, L:/127.0.0.1:50051 - R:/127.0.0.1:65382] INBOUND DATA: streamId=31 padding=0 endStream=true length=0 bytes=
17:25:05.506 [grpc-default-executor-0] DEBUG f.rpc.fs2.ServerLoggingInterceptor - onHalfClose
17:25:05.508 [grpc-default-worker-ELG-1-3] DEBUG io.grpc.netty.NettyServerHandler - [id: 0xde84dfef, L:/127.0.0.1:50051 - R:/127.0.0.1:65382] OUTBOUND HEADERS: streamId=31 headers=GrpcHttp2OutboundHeaders[:status: 200, content-type: application/grpc, grpc-encoding: identity, grpc-accept-encoding: gzip] streamDependency=0 weight=16 exclusive=false padding=0 endStream=false
17:25:05.509 [grpc-default-worker-ELG-1-3] DEBUG io.grpc.netty.NettyServerHandler - [id: 0xde84dfef, L:/127.0.0.1:50051 - R:/127.0.0.1:65382] OUTBOUND DATA: streamId=31 padding=0 endStream=false length=28 bytes=0000000009c801900308666f6f330000000009d00fa01f08666f6f34
17:25:05.509 [scala-execution-context-global-22] DEBUG freestyle.rpc.fs2.Utils$ - Processing: E(A(1000,2000),foo4)
17:25:05.509 [grpc-default-worker-ELG-1-2] DEBUG io.grpc.netty.NettyClientHandler - [id: 0xdf16c2f3, L:/127.0.0.1:65382 - R:localhost/127.0.0.1:50051] INBOUND HEADERS: streamId=31 headers=GrpcHttp2ResponseHeaders[:status: 200, content-type: application/grpc, grpc-encoding: identity, grpc-accept-encoding: gzip] streamDependency=0 weight=16 exclusive=false padding=0 endStream=false
17:25:05.509 [grpc-default-worker-ELG-1-2] DEBUG io.grpc.netty.NettyClientHandler - [id: 0xdf16c2f3, L:/127.0.0.1:65382 - R:localhost/127.0.0.1:50051] INBOUND DATA: streamId=31 padding=0 endStream=false length=28 bytes=0000000009c801900308666f6f330000000009d00fa01f08666f6f34
17:25:05.509 [grpc-default-executor-0] DEBUG f.rpc.fs2.ClientLoggingInterceptor - onHeaders: Metadata(content-type=application/grpc,grpc-encoding=identity,grpc-accept-encoding=gzip)
17:25:05.510 [grpc-default-executor-0] DEBUG f.rpc.fs2.ClientLoggingInterceptor - E(A(100,200),foo3)
17:25:05.510 [grpc-default-worker-ELG-1-3] DEBUG io.grpc.netty.NettyServerHandler - [id: 0xde84dfef, L:/127.0.0.1:50051 - R:/127.0.0.1:65382] OUTBOUND DATA: streamId=31 padding=0 endStream=false length=14 bytes=0000000009c801900308666f6f33
17:25:05.511 [grpc-default-executor-0] DEBUG f.rpc.fs2.ClientLoggingInterceptor - E(A(1000,2000),foo4)
17:25:05.511 [grpc-default-worker-ELG-1-2] DEBUG io.grpc.netty.NettyClientHandler - [id: 0xdf16c2f3, L:/127.0.0.1:65382 - R:localhost/127.0.0.1:50051] INBOUND DATA: streamId=31 padding=0 endStream=false length=14 bytes=0000000009c801900308666f6f33
17:25:05.512 [grpc-default-worker-ELG-1-3] DEBUG io.grpc.netty.NettyServerHandler - [id: 0xde84dfef, L:/127.0.0.1:50051 - R:/127.0.0.1:65382] OUTBOUND DATA: streamId=31 padding=0 endStream=false length=14 bytes=0000000009d00fa01f08666f6f34
17:25:05.512 [grpc-default-executor-0] DEBUG f.rpc.fs2.ClientLoggingInterceptor - E(A(100,200),foo3)
17:25:05.512 [grpc-default-worker-ELG-1-2] DEBUG io.grpc.netty.NettyClientHandler - [id: 0xdf16c2f3, L:/127.0.0.1:65382 - R:localhost/127.0.0.1:50051] INBOUND DATA: streamId=31 padding=0 endStream=false length=14 bytes=0000000009d00fa01f08666f6f34
17:25:05.513 [grpc-default-executor-0] DEBUG f.rpc.fs2.ClientLoggingInterceptor - E(A(1000,2000),foo4)
17:25:05.515 [grpc-default-worker-ELG-1-3] DEBUG io.grpc.netty.NettyServerHandler - [id: 0xde84dfef, L:/127.0.0.1:50051 - R:/127.0.0.1:65382] OUTBOUND HEADERS: streamId=31 headers=GrpcHttp2OutboundHeaders[grpc-status: 0] streamDependency=0 weight=16 exclusive=false padding=0 endStream=true
17:25:05.515 [grpc-default-executor-0] DEBUG f.rpc.fs2.ServerLoggingInterceptor - onComplete
17:25:05.515 [grpc-default-worker-ELG-1-2] DEBUG io.grpc.netty.NettyClientHandler - [id: 0xdf16c2f3, L:/127.0.0.1:65382 - R:localhost/127.0.0.1:50051] INBOUND HEADERS: streamId=31 headers=GrpcHttp2ResponseHeaders[grpc-status: 0] streamDependency=0 weight=16 exclusive=false padding=0 endStream=true
17:25:05.516 [grpc-default-executor-0] DEBUG f.rpc.fs2.ClientLoggingInterceptor - onClose: Status{code=OK, description=null, cause=null} Metadata()

FS2 Failure:

17:24:13.732 [grpc-default-worker-ELG-1-2] DEBUG io.grpc.netty.NettyClientHandler - [id: 0xeea96519, L:/127.0.0.1:65325 - R:localhost/127.0.0.1:50051] OUTBOUND HEADERS: streamId=31 headers=GrpcHttp2OutboundHeaders[:authority: localhost:50051, :path: /RPCService/biStreaming, :method: POST, :scheme: http, content-type: application/grpc, te: trailers, user-agent: grpc-java-netty/1.11.0, grpc-accept-encoding: gzip, grpc-trace-bin: ] streamDependency=0 weight=16 exclusive=false padding=0 endStream=false
17:24:13.733 [grpc-default-executor-0] DEBUG f.rpc.fs2.ClientLoggingInterceptor - onReady
17:24:13.734 [grpc-default-worker-ELG-1-3] DEBUG io.grpc.netty.NettyServerHandler - [id: 0x120d788b, L:/127.0.0.1:50051 - R:/127.0.0.1:65325] INBOUND HEADERS: streamId=31 headers=GrpcHttp2RequestHeaders[:path: /RPCService/biStreaming, :authority: localhost:50051, :method: POST, :scheme: http, te: trailers, content-type: application/grpc, user-agent: grpc-java-netty/1.11.0, grpc-accept-encoding: gzip, grpc-trace-bin: ] streamDependency=0 weight=16 exclusive=false padding=0 endStream=false
17:24:13.735 [grpc-default-worker-ELG-1-2] DEBUG io.grpc.netty.NettyClientHandler - [id: 0xeea96519, L:/127.0.0.1:65325 - R:localhost/127.0.0.1:50051] OUTBOUND DATA: streamId=31 padding=0 endStream=false length=14 bytes=0000000009c801900308666f6f33
17:24:13.735 [grpc-default-executor-0] DEBUG f.rpc.fs2.ServerLoggingInterceptor - onReady
17:24:13.735 [grpc-default-worker-ELG-1-3] DEBUG io.grpc.netty.NettyServerHandler - [id: 0x120d788b, L:/127.0.0.1:50051 - R:/127.0.0.1:65325] INBOUND DATA: streamId=31 padding=0 endStream=false length=14 bytes=0000000009c801900308666f6f33
17:24:13.736 [grpc-default-executor-0] DEBUG f.rpc.fs2.ServerLoggingInterceptor - E(A(100,200),foo3)
17:24:13.736 [grpc-default-worker-ELG-1-2] DEBUG io.grpc.netty.NettyClientHandler - [id: 0xeea96519, L:/127.0.0.1:65325 - R:localhost/127.0.0.1:50051] OUTBOUND DATA: streamId=31 padding=0 endStream=false length=14 bytes=0000000009d00fa01f08666f6f34
17:24:13.736 [grpc-default-worker-ELG-1-3] DEBUG io.grpc.netty.NettyServerHandler - [id: 0x120d788b, L:/127.0.0.1:50051 - R:/127.0.0.1:65325] INBOUND DATA: streamId=31 padding=0 endStream=false length=14 bytes=0000000009d00fa01f08666f6f34
17:24:13.737 [grpc-default-executor-0] DEBUG f.rpc.fs2.ServerLoggingInterceptor - E(A(1000,2000),foo4)
17:24:13.738 [grpc-default-worker-ELG-1-2] DEBUG io.grpc.netty.NettyClientHandler - [id: 0xeea96519, L:/127.0.0.1:65325 - R:localhost/127.0.0.1:50051] OUTBOUND DATA: streamId=31 padding=0 endStream=true length=0 bytes=
17:24:13.739 [grpc-default-worker-ELG-1-3] DEBUG io.grpc.netty.NettyServerHandler - [id: 0x120d788b, L:/127.0.0.1:50051 - R:/127.0.0.1:65325] INBOUND DATA: streamId=31 padding=0 endStream=true length=0 bytes=
17:24:13.739 [grpc-default-executor-0] DEBUG f.rpc.fs2.ServerLoggingInterceptor - onHalfClose
17:24:13.743 [grpc-default-worker-ELG-1-3] DEBUG io.grpc.netty.NettyServerHandler - [id: 0x120d788b, L:/127.0.0.1:50051 - R:/127.0.0.1:65325] OUTBOUND HEADERS: streamId=31 headers=GrpcHttp2OutboundHeaders[:status: 200, content-type: application/grpc, grpc-status: 0] streamDependency=0 weight=16 exclusive=false padding=0 endStream=true
17:24:13.743 [grpc-default-executor-0] DEBUG f.rpc.fs2.ServerLoggingInterceptor - onComplete
17:24:13.744 [grpc-default-worker-ELG-1-2] DEBUG io.grpc.netty.NettyClientHandler - [id: 0xeea96519, L:/127.0.0.1:65325 - R:localhost/127.0.0.1:50051] INBOUND HEADERS: streamId=31 headers=GrpcHttp2ResponseHeaders[:status: 200, content-type: application/grpc, grpc-status: 0] streamDependency=0 weight=16 exclusive=false padding=0 endStream=true
17:24:13.744 [grpc-default-executor-0] DEBUG f.rpc.fs2.ClientLoggingInterceptor - onClose: Status{code=OK, description=null, cause=null} Metadata(content-type=application/grpc)

List() was not equal to 
List(E(A(100,200),foo3), E(A(1000,2000),foo4))

@L-Lavigne L-Lavigne added the help wanted Extra attention is needed label May 17, 2018
@fedefernandez
Copy link
Contributor

In the FS2 failure is missing the Processing: E(A(100,200),foo3) that happens just before of onHalfClose in the success. Then there are more differences, but I think all because of the data hasn't been processed.

L-Lavigne pushed a commit that referenced this issue May 29, 2018
Ignoring new bidirectional tests on Travis until #164 is fixed
53f29d7 
Also re-activating a test which may have been ignored by mistke.
@L-Lavigne L-Lavigne mentioned this issue May 29, 2018
Merged
L-Lavigne pushed a commit that referenced this issue May 29, 2018
Ignoring new bidirectional tests on Travis until #164 is fixed (#281)
3cc6181 
Also re-activating a test which may have been ignored by mistke.
@L-Lavigne L-Lavigne mentioned this issue May 29, 2018
Closed
@L-Lavigne L-Lavigne changed the title fs2 Random Test Failure FS2 bidirectional-streaming random test failure May 29, 2018
@L-Lavigne L-Lavigne removed their assignment May 30, 2018
@pepegar pepegar mentioned this issue Jun 4, 2018
Closed
@juanpedromoreno
Copy link
Member Author

Is this fixed now? Could we close it?

@fedefernandez
Copy link
Contributor

Yest

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working help wanted Extra attention is needed tests Improves or modifies tests
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@fedefernandez @juanpedromoreno @L-Lavigne