Lua receives empty body on httpCall to GRPC

[mtalbot]

When calling a GRPC service from a lua filter the returned body is always empty. Digging into this I think its related to the response handling code that copies the c++ string to a c string as the body of the http request starts with a null char because the grpc wire format is uncompressed. This doesn't happen though on the request sending, the lua string handles having a null as the first char.

local bit = require("bit")

function codeToProto(code)
  return "\n\n" .. code
end

function protoToGRPC(proto)
  local protoLength = string.len(proto)
  local protoLengthBytes = {}
  for i = 0, 3 do
      protoLengthBytes[i] = bit.band(bit.rshift(protoLength,i * 8), 0xff)
  end
  return string.char(0, protoLengthBytes[3], protoLengthBytes[2], protoLengthBytes[1], protoLengthBytes[0]) .. proto
end

function envoy_on_request(request_handle)
  local code = request_handle:headers():get("code")

  print("Making request for cluster of " .. code)

  local headers, response = request_handle:httpCall(
    "servicediscovery",
    {
      [":method"] = "POST",
      [":path"] = "/envoy.Discovery/Lookup",
      [":authority"] = "routing",
      ["Content-Type"] = "application/grpc+proto",
      ["TE"] = "trailers"
    },
    protoToGRPC(codeToProto(code)),
    5000
  )
  for key,value in pairs(headers) do print(key,value) end
  print(string.byte(response, 1))
  cluster = string.sub(response, 6)
  print(string.len(response))

  request_handle:headers():add("cluster", cluster)
end

ends up with the following debug print

Making request for cluster of 1234567
:status	200
grpc-accept-encoding	gzip
x-envoy-upstream-service-time	221
grpc-encoding	identity
content-type	application/grpc

0

[zuercher]

I expect you're getting a GRPC error, which is encoded in trailers. Trailers, unfortunately, are not exposed by the Envoy's request_handle:httpCall. You could confirm this by turning on debug logging in Envoy. The trailers should be logged, including grpc-status and grpc-message trailers.

[mtalbot]

No, the response is fine

The request packet is

0000   02 00 00 00 45 00 01 2a 00 00 40 00 40 06 00 00   ....E..*..@.@...
0010   7f 00 00 01 7f 00 00 01 da b9 23 1d 37 55 17 b9   ..........#.7U..
0020   6f 69 9b b6 80 18 18 eb ff 1e 00 00 01 01 08 0a   oi..............
0030   3d 2c d8 58 3d 2c d8 57 50 52 49 20 2a 20 48 54   =,.X=,.WPRI * HT
0040   54 50 2f 32 2e 30 0d 0a 0d 0a 53 4d 0d 0a 0d 0a   TP/2.0....SM....
0050   00 00 0c 04 00 00 00 00 00 00 04 10 00 00 00 00   ................
0060   02 00 00 00 00 00 00 04 08 00 00 00 00 00 0f ff   ................
0070   00 01 00 00 99 01 04 00 00 00 01 04 a7 60 87 a5   .............`..
0080   72 1e a2 5b 62 f4 9a 44 98 b6 2e 5a bb 9f d2 f8   r..[b..D...Z....
0090   2a 49 93 ea f9 90 43 f7 2d 9e 98 ce 73 f5 b6 bc   *I....C.-...s...
00a0   15 24 c9 f5 83 41 87 2d 29 b0 f6 a4 d5 4d 86 5f   .$...A.-)....M._
00b0   90 1d 75 d0 62 0d 26 3d 4c 4d 65 64 ff 75 d8 74   ..u.b.&=LMed.u.t
00c0   9f 40 02 74 65 86 4d 83 35 05 b1 1f 0f 0d 02 31   .@.te.M.5......1
00d0   37 40 8c f2 b1 6a ee 7f 4b 1a a4 96 ca 87 47 83   7@...j..K.....G.
00e0   4d 96 97 40 8b f2 b4 a7 b3 c0 ec 90 b2 2d 29 ec   M..@.........-).
00f0   87 0b a2 5c 2e ae 05 c5 40 96 f2 b1 6a ee 7f 4b   ...\....@...j..K
0100   17 cd 65 22 4b 22 d6 76 59 26 a4 a7 b5 2b 52 8f   ..e"K".vY&...+R.
0110   83 6c 00 07 00 00 11 00 01 00 00 00 01 00 00 00   .l..............
0120   00 0c 0a 0a 70 68 6f 73 31 32 33 34 38 38         ....phos123488

The response packet is

0000   02 00 00 00 45 00 00 c4 00 00 40 00 40 06 00 00   ....E.....@.@...
0010   7f 00 00 01 7f 00 00 01 23 1d da b9 6f 69 9b e7   ........#...oi..
0020   37 55 18 b8 80 18 18 e7 fe b8 00 00 01 01 08 0a   7U..............
0030   3d 2c d9 2e 3d 2c d9 2c 00 00 4b 01 24 00 00 00   =,..=,.,..K.$...
0040   01 00 00 00 00 0f 88 5f 10 61 70 70 6c 69 63 61   ......._.applica
0050   74 69 6f 6e 2f 67 72 70 63 40 0d 67 72 70 63 2d   tion/grpc@.grpc-
0060   65 6e 63 6f 64 69 6e 67 08 69 64 65 6e 74 69 74   encoding.identit
0070   79 40 14 67 72 70 63 2d 61 63 63 65 70 74 2d 65   y@.grpc-accept-e
0080   6e 63 6f 64 69 6e 67 04 67 7a 69 70 00 00 16 00   ncoding.gzip....
0090   00 00 00 00 01 00 00 00 00 11 0a 0f 63 69 72 63   ............circ
00a0   75 69 74 2d 64 65 66 61 75 6c 74 00 00 14 01 25   uit-default....%
00b0   00 00 00 01 00 00 00 00 0f 40 0b 67 72 70 63 2d   .........@.grpc-
00c0   73 74 61 74 75 73 01 30                           status.0

[2020-02-14 09:48:25.976][26][debug][http] [source/common/http/conn_manager_impl.cc:1257] [C97][S7104143247181254501] request end stream
Making request for cluster of phos123488
[2020-02-14 09:48:25.983][26][debug][router] [source/common/router/router.cc:434] [C0][S14126135176097527152] cluster 'emtservicediscovery' match for URL '/com.concur.midtier.envoy.EntityDiscovery/LookupEntity'
[2020-02-14 09:48:25.984][26][debug][router] [source/common/router/router.cc:549] [C0][S14126135176097527152] router decoding headers:
':path', '/com.concur.midtier.envoy.EntityDiscovery/LookupEntity'
':method', 'POST'
':authority', 'emtrouting'
':scheme', 'http'
'content-type', 'application/grpc+proto'
'te', 'trailers'
'content-length', '17'
'x-envoy-internal', 'true'
'x-forwarded-for', '172.17.0.2'
'x-envoy-expected-rq-timeout-ms', '5000'

[2020-02-14 09:48:25.985][26][debug][client] [source/common/http/codec_client.cc:31] [C98] connecting
[2020-02-14 09:48:25.985][26][debug][connection] [source/common/network/connection_impl.cc:711] [C98] connecting to 192.168.65.2:8989
[2020-02-14 09:48:25.985][26][debug][connection] [source/common/network/connection_impl.cc:720] [C98] connection in progress
[2020-02-14 09:48:25.987][26][debug][http2] [source/common/http/http2/codec_impl.cc:912] [C98] setting stream-level initial window size to 268435456
[2020-02-14 09:48:25.988][26][debug][http2] [source/common/http/http2/codec_impl.cc:934] [C98] updating connection-level initial window size to 268435456
[2020-02-14 09:48:25.988][26][debug][pool] [source/common/http/conn_pool_base.cc:20] queueing request due to no available connections
[2020-02-14 09:48:25.988][26][debug][lua] [source/extensions/filters/common/lua/lua.cc:40] coroutine yielded
[2020-02-14 09:48:25.988][26][debug][connection] [source/common/network/connection_impl.cc:559] [C98] connected
[2020-02-14 09:48:25.989][26][debug][client] [source/common/http/codec_client.cc:69] [C98] connected
[2020-02-14 09:48:25.989][26][debug][pool] [source/common/http/http2/conn_pool.cc:98] [C98] creating stream
[2020-02-14 09:48:25.989][26][debug][router] [source/common/router/router.cc:1618] [C0][S14126135176097527152] pool ready
[2020-02-14 09:48:26.020][26][debug][router] [source/common/router/router.cc:1036] [C0][S14126135176097527152] upstream headers complete: end_stream=false
[2020-02-14 09:48:26.020][26][debug][http] [source/common/http/async_client_impl.cc:93] async http request response headers (end_stream=false):
':status', '200'
'content-type', 'application/grpc'
'grpc-encoding', 'identity'
'grpc-accept-encoding', 'gzip'
'x-envoy-upstream-service-time', '32'

[2020-02-14 09:48:26.021][26][debug][client] [source/common/http/codec_client.cc:101] [C98] response complete
[2020-02-14 09:48:26.021][26][debug][pool] [source/common/http/http2/conn_pool.cc:236] [C98] destroying stream: 0 remaining
[2020-02-14 09:48:26.021][26][debug][http] [source/common/http/async_client_impl.cc:119] async http request response trailers:
'grpc-status', '0'

[2020-02-14 09:48:26.021][26][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:218] async HTTP response complete
:status	200
grpc-accept-encoding	gzip
x-envoy-upstream-service-time	32
grpc-encoding	identity
content-type	application/grpc

0
[2020-02-14 09:48:26.022][26][debug][lua] [source/extensions/filters/common/lua/lua.cc:37] coroutine finished

The body just isn't being returned

[stale]

This issue has been automatically marked as stale because it has not had activity in the last 30 days. It will be closed in the next 7 days unless it is tagged "help wanted" or other activity occurs. Thank you for your contributions.

[stale]

This issue has been automatically closed because it has not had activity in the last 37 days. If this issue is still valid, please ping a maintainer and ask them to label it as "help wanted". Thank you for your contributions.

[james-thomson]

We're seeing the same underlying issue without GRPC.
It seems that the httpCall function allows null byte in the request body but the response body is a null terminated string.

Can this ticket be reopened so that the entire response body can be accessed in the lua script?

[dio]

@mtalbot @james-thomson I have a draft here: #13199, which I believe can solve this issue. However, to be sure, could you try this image: dio123/envoy:lua-httpcall-raw-data (note that this image is ubuntu-based image) and see if this works for you? Thank you!