The stream doesn't stop

[iv5d]

Proto file(s) Subscribe(stream SubscribeRequest) returns (stream SubscribeResponse)

Command line arguments / config

ghz --insecure \
--skipTLS \
--call grpc.Stream.Subscribe \
-d "{"id": {"security_id": 8}}" \
0.0.0.0:5644 \
-r 1 \
-c 1 \
-n 1 \
--count-errors \
-t 0 \
--stream-call-duration 10s\
--stream-call-count 1\

Describe the bug The stream doesn't stop

To Reproduce Run the command

Expected behavior The stream stops

Environment

• OS: [e.g. Windows 10]
• ghz: [e.g. Версия 0.96.0]

Screenshots

Additional context If use flag "-t 10s" to stop, an error occurs rpc error: code = DeadlineExceeded desc = context deadline exceeded

ghz --insecure \
--skipTLS \
--call grpc.Stream.Subscribe \
-d "{"id": {"security_id": 8}}" \
0.0.0.0:5644 \
-r 1 \
-c 1 \
-n 1 \
--count-errors \
-t 10s

Tell me how you can stop the stream without an error?

[bojand]

Hmm really not sure I think more details are needed, but I am guessing something is wrong on the server end with respect to what it does with the data sent.

We can test using https://grpcb.in/:

ghz --insecure \
  --proto ./testdata/hello.proto \
  --call hello.HelloService.BidiHello \
  -d '{"greeting": "helloasdf"}' \
  -r 1 -c 1 -n 1 \
  -t 0 \
  --count-errors \
  --stream-call-duration 10s \
  --stream-call-count 1 \
  --debug=ghz.log \
  grpcb.in:9000

Summary:
  Count:	1
  Total:	1.12 s
  Slowest:	117.93 ms
  Fastest:	117.93 ms
  Average:	117.93 ms
  Requests/sec:	0.89

Response time histogram:
  117.932 [1]	|∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎
  117.932 [0]	|
  117.932 [0]	|
  117.932 [0]	|
  117.932 [0]	|
  117.932 [0]	|
  117.932 [0]	|
  117.932 [0]	|
  117.932 [0]	|
  117.932 [0]	|
  117.932 [0]	|

Latency distribution:
  10 % in 117.93 ms
  25 % in 117.93 ms
  50 % in 117.93 ms
  75 % in 117.93 ms
  90 % in 117.93 ms
  95 % in 117.93 ms
  99 % in 117.93 ms

Status code distribution:
  [OK]   1 responses

and the debug log shows details:

{
  "level": "debug",
  "time": "2021-08-12T22:50:03.670612-03:00",
  "message": "Start Run",
  "config": {
    "proto": "./testdata/hello.proto",
    "protoset": "",
    "call": "hello.HelloService.BidiHello",
    "cacert": "",
    "cert": "",
    "key": "",
    "count-errors": true,
    "skipTLS": false,
    "skipFirst": 0,
    "cname": "",
    "authority": "",
    "insecure": true,
    "total": 1,
    "concurrency": 1,
    "concurrency-schedule": "const",
    "concurrency-start": 0,
    "concurrency-end": 0,
    "concurrency-step": 1,
    "concurrency-step-duration": "0s",
    "concurrency-max-duration": "0s",
    "connections": 1,
    "rps": 1,
    "duration": "0s",
    "duration-stop": "close",
    "max-duration": "0s",
    "timeout": "0s",
    "data": {
      "greeting": "helloasdf"
    },
    "data-file": "",
    "binary-file": "",
    "metadata-file": "",
    "stream-interval": "0s",
    "stream-call-duration": "10s",
    "stream-call-count": 1,
    "stream-dynamic-messages": false,
    "output": "",
    "format": "summary",
    "connect-timeout": "10s",
    "keepalive": "0s",
    "cpus": 12,
    "debug": "ghz.log",
    "host": "grpcb.in:9000",
    "load-schedule": "const",
    "load-start": 0,
    "load-end": 0,
    "load-step": 0,
    "load-step-duration": "0s",
    "load-max-duration": "0s",
    "lb-strategy": "",
    "max-recv-message-size": "",
    "max-send-message-size": ""
  }
}
{
  "level": "debug",
  "time": "2021-08-12T22:50:03.672925-03:00",
  "message": "Creating client connection",
  "options": [
    {},
    {},
    {}
  ]
}
{
  "level": "debug",
  "time": "2021-08-12T22:50:03.673127-03:00",
  "message": "Worker ticker.",
  "delta": 1
}
{
  "level": "debug",
  "time": "2021-08-12T22:50:03.673176-03:00",
  "message": "Creating worker with ID: g0c0",
  "workerID": "g0c0"
}
{
  "level": "debug",
  "time": "2021-08-12T22:50:04.676372-03:00",
  "message": "Received stop from pacer."
}
{
  "level": "debug",
  "time": "2021-08-12T22:50:04.676501-03:00",
  "message": "Making request",
  "workerID": "g0c0",
  "call type": "bidi",
  "call": "hello.HelloService.BidiHello",
  "input": [
    {
      "greeting": "helloasdf"
    }
  ],
  "metadata": {}
}
{
  "level": "debug",
  "time": "2021-08-12T22:50:04.676847-03:00",
  "message": "Send message",
  "workerID": "g0c0",
  "call type": "bidi",
  "call": "hello.HelloService.BidiHello",
  "payload": "greeting:\"helloasdf\"",
  "error": null
}
{
  "level": "debug",
  "time": "2021-08-12T22:50:04.676915-03:00",
  "message": "Close send",
  "workerID": "g0c0",
  "call type": "bidi",
  "call": "hello.HelloService.BidiHello",
  "error": null
}
{
  "level": "debug",
  "time": "2021-08-12T22:50:04.794447-03:00",
  "message": "Receive message",
  "workerID": "g0c0",
  "call type": "bidi",
  "call": "hello.HelloService.BidiHello",
  "response": "reply:\"hello helloasdf\"",
  "error": null
}
{
  "level": "debug",
  "time": "2021-08-12T22:50:04.794547-03:00",
  "message": "Received RPC Stats",
  "statsID": 0,
  "code": "OK",
  "error": null,
  "duration": 0.117931981,
  "stats": {
    "Client": true,
    "BeginTime": "2021-08-12T22:50:04.676604-03:00",
    "EndTime": "2021-08-12T22:50:04.794539-03:00",
    "Trailer": {},
    "Error": null
  }
}
{
  "level": "debug",
  "time": "2021-08-12T22:50:04.794671-03:00",
  "message": "Receive message",
  "workerID": "g0c0",
  "call type": "bidi",
  "call": "hello.HelloService.BidiHello",
  "response": null,
  "error": "EOF"
}
{
  "level": "debug",
  "time": "2021-08-12T22:50:04.794708-03:00",
  "message": "Waiting for report"
}
{
  "level": "debug",
  "time": "2021-08-12T22:50:04.794735-03:00",
  "message": "Finilizing report"
}
{
  "level": "debug",
  "time": "2021-08-12T22:50:04.794772-03:00",
  "message": "Closing client connections"
}
{
  "level": "debug",
  "time": "2021-08-12T22:50:04.794885-03:00",
  "message": "Run finished"
}
{
  "level": "debug",
  "time": "2021-08-12T22:50:04.794956-03:00",
  "message": "Printing report to stdout",
  "path": "stdout"
}