--data fails with google's timestamp proto

[sp-carlos-clavero]

Proto file(s)
message Request {
google.protobuf.Timestamp ts = 1;
uint64 user_id = 2;
}

google.protobuf.Timestamp needs: int64 seconds and int32 nanos to be built.

Command line arguments / config
Config file "config.json" content is:

{
  "proto": "user_service.proto",
  "call": "UserService.Login",
  "name": "UserService - Login Latency",
  "total": 1,
  "concurrency": 1,
  "connections": 1,
  "host": "localhost:10001",
  "insecure": true,
  "data": {
    "ts": {
      "seconds": 20,
      "nanos": 10
    },
    "user_id": 100
  },
  "debug": "login_log.log"
}

Launching with: ./ghz --config config.json

Describe the bug
Once you launch ghz you get the following error message:
Error creating message from data. Data: '{"ts":{"nanos":10,"seconds":20},"user_id":100}' Error: json: cannot unmarshal object into Go value of type string

Full error message:
{"level":"error","time":"2020-02-20T11:32:23.575027+01:00","message":"Error from run: Error creating message from data. Data: '{\"ts\":{\"nanos\":10,\"seconds\":20},\"user_id\":100}' Error: json: cannot unmarshal object into Go value of type string","stacktrace":"main.main\n\t/home/runner/work/ghz/ghz/cmd/ghz/main.go:290\nruntime.main\n\t/opt/hostedtoolcache/go/1.13.6/x64/src/runtime/proc.go:203"}

To Reproduce
Just create a proto file that has a message that includes another proto that requires 2 or more attributes.

Expected behavior
It should marshal the data correctly and send the request. If I delete the timestamp proto it works, but this is not the expected message on my server.

Environment

• OS: macOS 10.14.6
• ghz: 0.49.0

Additional context
We have several protos with this structure of nested protos as attributes and this issue makes impossible for us to test latencies with ghz.
I have tested some of them and nested structures that include google's protos are failing.

[sp-carlos-clavero]

Further testings reveal that the issue is related to google's timestamp proto. I have created a new test with a different proto that chains a lot of other protos and the only one that causes the failure is the timestamp one. If I remove it it parses the data.

As I said before, the timestamp is needed so maybe the petition works but the latency test fails.

[bojand]

Hmm I belive the timestamp needs to be a RFC 3339 string for example like "ts":"2017-01-15T01:30:15.01Z"

https://godoc.org/github.com/golang/protobuf/ptypes/timestamp

JSON Mapping

In JSON format, the Timestamp type is encoded as a string in the RFC 3339 format. That is, the format is "{year}-{month}-{day}T{hour}:{min}:{sec}[.{frac_sec}]Z" ...

[lzuwei]

Hi changing the timestamp to string in the format "ts":"2017-01-15T01:30:15.01Z" did not seem to fix the problem.
When running ghz, it fails silently and does not run generate any metrics.

root@c544313f3ed7:~# ghz --config config.json 
^C
Summary:
  Count:	0
  Total:	10.70 s
  Slowest:	0 ns
  Fastest:	0 ns
  Average:	0 ns
  Requests/sec:	0.00

Response time histogram:

Latency distribution:

Expected Output:

root@5a8be8e8c759:~# ghz --config config.json 
^C
Summary:
  Count:	455
  Total:	4.48 s
  Slowest:	1.35 s
  Fastest:	22.37 ms
  Average:	38.63 ms
  Requests/sec:	101.67

Response time histogram:
  22.373 [1]	|
  155.151 [446]	|∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎∎
  287.929 [0]	|
  420.707 [3]	|
  553.485 [0]	|
  686.263 [0]	|
  819.041 [0]	|
  951.820 [0]	|
  1084.598 [0]	|
  1217.376 [0]	|
  1350.154 [1]	|

Latency distribution:
  10 % in 25.18 ms 
  25 % in 26.81 ms 
  50 % in 30.40 ms 
  75 % in 37.44 ms 
  90 % in 47.29 ms 
  95 % in 53.04 ms 
  99 % in 332.19 ms 

Status code distribution:
  [Unavailable]   4 responses     
  [OK]            451 responses   

Error distribution:
  [4]   rpc error: code = Unavailable desc = transport is closing 

Proto file:

message Request {
  google.protobuf.Timestamp ts = 1;
  uint64 user_id = 2;
}

config file:

{
  "proto": "user_service.proto",
  "call": "UserService.Login",
  "name": "UserService - Login Latency",
  "total": 1,
  "concurrency": 1,
  "connections": 1,
  "host": "localhost:10001",
  "insecure": true,
  "data": {
    "ts":"2017-01-15T01:30:15.01Z",
    "user_id": 100
  },
  "debug": "login_log.log"
}

[gm4422]

yeah can confirm I am facing the same issue as @Izuwei and @sp-carlos-clavero. Any fix or workaround would be appreciated

[fischernick]

I'm seeing the same problem with google.protobuf.Duration

[bojand]

Maybe I am misunderstanding the issue but I cannot reproduce this. Added tests for both google timestamp and duration and they work as expected without ant code changes. Did a quick test using gtime.proto and tsconfig.json and works as expected. Example server in Node.js:

const PROTO_PATH = '/go/ghz/testdata/gtime.proto'

const grpc = require('@grpc/grpc-js')
const protoLoader = require('@grpc/proto-loader')
const packageDefinition = protoLoader.loadSync(
  PROTO_PATH,
  {
    keepCase: true,
    longs: String,
    enums: String,
    defaults: true,
    oneofs: true
  })

const gtimeProto = grpc.loadPackageDefinition(packageDefinition).gtime

function testCall (call, callback) {
  console.dir(call.request.ts)
  const s = parseInt(call.request.ts.seconds)
  const t = s * 1000 + call.request.ts.nanos / 1000000
  const d = new Date(t)
  console.log(d.toISOString())
  callback(null, { message: 'Hello ' + call.request.userId })
}

function main () {
  const server = new grpc.Server()
  server.addService(gtimeProto.TimeService.service, { testCall })
  server.bindAsync('0.0.0.0:50051', grpc.ServerCredentials.createInsecure(), () => {
    server.start()
  })
}

main()

Run ghz

ghz --config ../testdata/tsconfig.json 0.0.0.0:50051

Summary:
  Name:		TimeService - TestCall
  Count:	1
  Total:	39.76 ms
  Slowest:	39.35 ms
  Fastest:	39.35 ms
  Average:	39.35 ms
  Requests/sec:	25.15

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

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

Status code distribution:
  [OK]   1 responses

And the output from server console:

{ seconds: '1579660230', nanos: 10000000 }
2020-01-22T02:30:30.010Z

Please add more details.