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

Lua filter: httpCall() terminates abruptly in envoy_on_response() when used after bodyChunks() #8785

Open
v1b1 opened this issue Oct 28, 2019 · 8 comments
Open

Lua filter: httpCall() terminates abruptly in envoy_on_response() when used after bodyChunks() #8785

v1b1 opened this issue Oct 28, 2019 · 8 comments
Labels
bug help wanted Needs help!

Comments

@v1b1
Copy link

v1b1 commented Oct 28, 2019

Title: Lua filter: httpCall() terminates abruptly in envoy_on_response() when used after bodyChunks()

Description:
In an attempt to shadow an upstream response using a Lua filter, I use envoy_on_response() to collect the response data using either body() or bodyChunks(), then use httpCall() to send the data to a special logging cluster. Buffering the response with body() and sending with httpCall() works as expected, but using bodyChunks() followed by httpCall() does not; the connection to the logging cluster terminates from the Lua side before it is able to finish sending the data.

Envoy Version: v1.11.1 (alpine docker image)

Repro steps:

  1. Using the config below, start Envoy as a reverse proxy for a service that responds with ~2 MiB payloads. (e.g. GET /xxlarge); I run Envoy and the services on a separate server from my tests. The logging cluster simply responds with status code 204.
  2. Run curl -s -o /dev/null -D - envoy-host:8080/log/buffer/xxlarge to observe expected behaviour with buffered responses. Logs are provided in buffered_output below.
  3. Run curl -s -o /dev/null -D - envoy-host:8080/log/xxlarge to see that envoy_on_response() does not complete execution. Note that the output of logDebug() calls after httpCall() do not appear. Logs provided in streamed_output below.

Notes: If the response payload is small enough and txn_logger is fast enough to receive the data from httpCall(), then I am able to see the final logDebug() call in the streamed response example.

Config:
lds.yaml

version_info: "0"
resources:
- "@type": type.googleapis.com/envoy.api.v2.Listener
  name: vip_listener
  address:
    socket_address:
      address: 0.0.0.0
      port_value: 8080
  per_connection_buffer_limit_bytes: 10000000
  filter_chains:
  - filters:
    - name: envoy.http_connection_manager
      typed_config:
        "@type": type.googleapis.com/envoy.config.filter.network.http_connection_manager.v2.HttpConnectionManager
        stat_prefix: vip_http
        codec_type: auto
        rds:
          route_config_name: vip_routes
          config_source:
            path: /envoy/conf/rds.yaml
        http_filters:
          - name: envoy.health_check
            typed_config:
              "@type": type.googleapis.com/envoy.config.filter.http.health_check.v2.HealthCheck
              pass_through_mode: false
              headers:
                - name: ":path"
                  exact_match: "/healthcheck"
          - name: envoy.lua
            typed_config:
              "@type": type.googleapis.com/envoy.config.filter.http.lua.v2.Lua
              inline_code: |
                function envoy_on_request(handle)
                  local metadata = handle:streamInfo():dynamicMetadata()
                  local headers = handle:headers()
                  local rid = headers:get("x-request-id")
                  if rid ~= nil then
                    metadata:set("envoy.lua", "req.x-request-id", rid)
                  end
                end

                function envoy_on_response(handle)
                  local cluster = handle:metadata():get("mirror_response_cluster")
                  if cluster == nil then return end
                  local headers = {
                    [":method"] = "POST",
                    [":path"] = "/response",
                    [":authority"] = cluster,
                  }
                  local metadata = handle:streamInfo():dynamicMetadata():get("envoy.lua")
                  for key, value in pairs(metadata) do
                    if key == "req.x-request-id" then headers[":path"] = "/response/for/" .. value end
                  end
                  handle:logDebug("vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv")
                  if (handle:metadata():get("buffer_response") == "buffered") then
                    local res = handle:body()
                    local body = res:getBytes(0, res:length())
                    handle:logDebug("!!!! Body buffered! Can we at least fire off a log?")
                    local h, b = handle:httpCall(cluster, headers, body, 0)
                  else
                    local t = {}
                    for chunk in handle:bodyChunks() do
                      local body = chunk:getBytes(0, chunk:length())
                      table.insert(t, body)
                    end
                    handle:logDebug("!!!! Last chunk buffered! Can we at least fire off a log?")
                    local h, b = handle:httpCall(cluster, headers, table.concat(t, ""), 0)
                  end
                  handle:logDebug("^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^")
                end
          - name: envoy.router
            config: {}
        access_log:
          - name: envoy.file_access_log
            typed_config:
              "@type": type.googleapis.com/envoy.config.accesslog.v2.FileAccessLog
              format: '[%START_TIME%] "%REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%"
                %RESPONSE_CODE% %RESPONSE_FLAGS% %BYTES_RECEIVED% %BYTES_SENT% %DURATION% %RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)%
                "%REQ(X-FORWARDED-FOR)%" "%REQ(USER-AGENT)%" "%REQ(X-REQUEST-ID)%" "%REQ(:AUTHORITY)%" "%UPSTREAM_HOST%"
                '
              path: /dev/stdout

rds.yaml

version_info: "0"
resources:
  - "@type": type.googleapis.com/envoy.api.v2.RouteConfiguration
    name: vip_routes
    virtual_hosts:
      - name: incoming
        domains:
          - "*"
        retry_policy:
          per_try_timeout: 120s
        routes:
          - match:
              prefix: /log/buffer/
            route:
              prefix_rewrite: /
              cluster: test
            metadata:
              filter_metadata:
                envoy.lua:
                  mirror_response_cluster: txn_logger
                  buffer_response: buffered
          - match:
              prefix: /log/
            route:
              prefix_rewrite: /
              cluster: test
            metadata:
              filter_metadata:
                envoy.lua:
                  mirror_response_cluster: txn_logger
          - match:
              prefix: /
            route:
              cluster: test

cds.yaml

version_info: "0"
resources:
  - "@type": type.googleapis.com/envoy.api.v2.Cluster
    name: test
    connect_timeout: 0.25s
    type: strict_dns
    lb_policy: round_robin
    load_assignment:
      cluster_name: test
      endpoints:
        - lb_endpoints:
            - endpoint:
                address:
                  socket_address:
                    address: app
                    port_value: 8080
    drain_connections_on_host_removal: true
    circuit_breakers:
      thresholds:
        - max_connections: 10000
          max_pending_requests: 10000
          max_requests: 10000
          max_retries: 0
          priority: DEFAULT
  - "@type": type.googleapis.com/envoy.api.v2.Cluster
    name: txn_logger
    connect_timeout: 0.25s
    type: strict_dns
    lb_policy: round_robin
    load_assignment:
      cluster_name: txn_logger
      endpoints:
        - lb_endpoints:
            - endpoint:
                address:
                  socket_address:
                    address: logger
                    port_value: 5000
    drain_connections_on_host_removal: true
    circuit_breakers:
      thresholds:
        - max_connections: 10000
          max_pending_requests: 10000
          max_requests: 10000
          max_retries: 0
          priority: DEFAULT

envoy.yaml

admin:
  access_log_path: /dev/null
  address:
    socket_address:
      address: 0.0.0.0
      port_value: 8001
dynamic_resources:
  cds_config:
    path: '/envoy/conf/cds.yaml'
  lds_config:
    path: '/envoy/conf/lds.yaml'

Logs:
buffered_output

[2019-10-28 14:26:58.270][20][debug][main] [source/server/connection_handler_impl.cc:280] [C0] new connection
[2019-10-28 14:26:58.271][20][debug][http] [source/common/http/conn_manager_impl.cc:246] [C0] new stream
[2019-10-28 14:26:58.272][20][debug][http] [source/common/http/conn_manager_impl.cc:619] [C0][S4761526198635461934] request headers complete (end_stream=true):
':authority', '10.5.130.68:9999'
':path', '/log/buffer/xxlarge'
':method', 'GET'
'user-agent', 'curl/7.29.0'
'accept', '*/*'

[2019-10-28 14:26:58.272][20][debug][http] [source/common/http/conn_manager_impl.cc:1111] [C0][S4761526198635461934] request end stream
[2019-10-28 14:26:58.273][20][debug][lua] [source/extensions/filters/common/lua/lua.cc:37] coroutine finished
[2019-10-28 14:26:58.273][20][debug][router] [source/common/router/router.cc:401] [C0][S4761526198635461934] cluster 'test' match for URL '/log/buffer/xxlarge'
[2019-10-28 14:26:58.273][20][debug][router] [source/common/router/router.cc:514] [C0][S4761526198635461934] router decoding headers:
':authority', '10.5.130.68:9999'
':path', '/xxlarge'
':method', 'GET'
':scheme', 'http'
'user-agent', 'curl/7.29.0'
'accept', '*/*'
'x-forwarded-proto', 'http'
'x-request-id', '2e329727-a93e-4ec3-9a57-2254747ae2cc'
'x-envoy-expected-rq-timeout-ms', '15000'
'x-envoy-original-path', '/log/buffer/xxlarge'

[2019-10-28 14:26:58.273][20][debug][pool] [source/common/http/http1/conn_pool.cc:88] creating a new connection
[2019-10-28 14:26:58.273][20][debug][client] [source/common/http/codec_client.cc:26] [C1] connecting
[2019-10-28 14:26:58.273][20][debug][connection] [source/common/network/connection_impl.cc:704] [C1] connecting to 10.200.1.101:8080
[2019-10-28 14:26:58.273][20][debug][connection] [source/common/network/connection_impl.cc:713] [C1] connection in progress
[2019-10-28 14:26:58.273][20][debug][pool] [source/common/http/conn_pool_base.cc:20] queueing request due to no available connections
[2019-10-28 14:26:58.273][20][debug][connection] [source/common/network/connection_impl.cc:552] [C1] connected
[2019-10-28 14:26:58.273][20][debug][client] [source/common/http/codec_client.cc:64] [C1] connected
[2019-10-28 14:26:58.273][20][debug][pool] [source/common/http/http1/conn_pool.cc:241] [C1] attaching to next request
[2019-10-28 14:26:58.273][20][debug][router] [source/common/router/router.cc:1503] [C0][S4761526198635461934] pool ready
[2019-10-28 14:26:58.280][20][debug][router] [source/common/router/router.cc:994] [C0][S4761526198635461934] upstream headers complete: end_stream=false
[2019-10-28 14:26:58.281][20][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:582] script log: vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv
[2019-10-28 14:26:58.281][20][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:311] yielding for full body
[2019-10-28 14:26:58.281][20][debug][lua] [source/extensions/filters/common/lua/lua.cc:40] coroutine yielded
[2019-10-28 14:26:58.288][20][debug][client] [source/common/http/codec_client.cc:95] [C1] response complete
[2019-10-28 14:26:58.289][20][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:55] resuming body due to end stream
[2019-10-28 14:26:58.295][20][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:582] script log: !!!! Body buffered! Can we at least fire off a log?
[2019-10-28 14:26:58.295][20][debug][router] [source/common/router/router.cc:401] [C0][S6278964145888681587] cluster 'txn_logger' match for URL '/response/for/2e329727-a93e-4ec3-9a57-2254747ae2cc'
[2019-10-28 14:26:58.295][20][debug][router] [source/common/router/router.cc:514] [C0][S6278964145888681587] router decoding headers:
':path', '/response/for/2e329727-a93e-4ec3-9a57-2254747ae2cc'
':method', 'POST'
':authority', 'txn_logger'
':scheme', 'http'
'content-length', '4000000'
'x-envoy-internal', 'true'
'x-forwarded-for', '10.200.1.98'

[2019-10-28 14:26:58.295][20][debug][pool] [source/common/http/http1/conn_pool.cc:88] creating a new connection
[2019-10-28 14:26:58.296][20][debug][client] [source/common/http/codec_client.cc:26] [C2] connecting
[2019-10-28 14:26:58.296][20][debug][connection] [source/common/network/connection_impl.cc:704] [C2] connecting to 10.200.1.103:5000
[2019-10-28 14:26:58.296][20][debug][connection] [source/common/network/connection_impl.cc:713] [C2] connection in progress
[2019-10-28 14:26:58.296][20][debug][pool] [source/common/http/conn_pool_base.cc:20] queueing request due to no available connections
[2019-10-28 14:26:58.296][20][debug][lua] [source/extensions/filters/common/lua/lua.cc:40] coroutine yielded
[2019-10-28 14:26:58.296][20][debug][pool] [source/common/http/http1/conn_pool.cc:198] [C1] response complete
[2019-10-28 14:26:58.296][20][debug][pool] [source/common/http/http1/conn_pool.cc:203] [C1] saw upstream close connection
[2019-10-28 14:26:58.296][20][debug][connection] [source/common/network/connection_impl.cc:101] [C1] closing data_to_write=0 type=1
[2019-10-28 14:26:58.296][20][debug][connection] [source/common/network/connection_impl.cc:190] [C1] closing socket: 1
[2019-10-28 14:26:58.296][20][debug][client] [source/common/http/codec_client.cc:82] [C1] disconnect. resetting 0 pending requests
[2019-10-28 14:26:58.296][20][debug][pool] [source/common/http/http1/conn_pool.cc:129] [C1] client disconnected, failure reason:
[2019-10-28 14:26:58.296][20][debug][connection] [source/common/network/connection_impl.cc:520] [C1] remote close
[2019-10-28 14:26:58.296][20][debug][connection] [source/common/network/connection_impl.cc:552] [C2] connected
[2019-10-28 14:26:58.296][20][debug][client] [source/common/http/codec_client.cc:64] [C2] connected
[2019-10-28 14:26:58.296][20][debug][pool] [source/common/http/http1/conn_pool.cc:241] [C2] attaching to next request
[2019-10-28 14:26:58.296][20][debug][router] [source/common/router/router.cc:1503] [C0][S6278964145888681587] pool ready
[2019-10-28 14:26:58.296][20][debug][connection] [source/common/network/connection_impl.cc:449] [C2] onAboveWriteBufferHighWatermark
[2019-10-28 14:26:58.336][20][debug][connection] [source/common/network/connection_impl.cc:440] [C2] onBelowWriteBufferLowWatermark
[2019-10-28 14:26:58.593][20][debug][client] [source/common/http/codec_client.cc:95] [C2] response complete
[2019-10-28 14:26:58.593][20][debug][router] [source/common/router/router.cc:994] [C0][S6278964145888681587] upstream headers complete: end_stream=true
[2019-10-28 14:26:58.593][20][debug][http] [source/common/http/async_client_impl.cc:91] async http request response headers (end_stream=true):
':status', '204'
'date', 'Mon, 28 Oct 2019 14:26:57 GMT'
'server', 'Kestrel'
'x-envoy-upstream-service-time', '297'

[2019-10-28 14:26:58.593][20][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:208] async HTTP response complete
[2019-10-28 14:26:58.593][20][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:582] script log: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[2019-10-28 14:26:58.593][20][debug][lua] [source/extensions/filters/common/lua/lua.cc:37] coroutine finished
[2019-10-28 14:26:58.593][20][debug][http] [source/common/http/conn_manager_impl.cc:1378] [C0][S4761526198635461934] encoding headers via codec (end_stream=false):
':status', '200'
'content-type', 'text/html; charset=utf-8'
'content-length', '4000000'
'server', 'envoy'
'date', 'Mon, 28 Oct 2019 14:26:58 GMT'
'x-envoy-upstream-service-time', '7'

[2019-10-28T14:26:58.271Z] "GET /log/buffer/xxlarge HTTP/1.1" 200 - 0 4000000 323 7 "-" "curl/7.29.0" "-" "-" "-" "-" "2e329727-a93e-4ec3-9a57-2254747ae2cc" "-" "10.5.130.68:9999" "10.200.1.101:8080"
[2019-10-28 14:26:58.594][20][debug][pool] [source/common/http/http1/conn_pool.cc:198] [C2] response complete
[2019-10-28 14:26:58.594][20][debug][pool] [source/common/http/http1/conn_pool.cc:236] [C2] moving to ready
[2019-10-28 14:26:58.609][20][debug][connection] [source/common/network/connection_impl.cc:520] [C0] remote close
[2019-10-28 14:26:58.609][20][debug][connection] [source/common/network/connection_impl.cc:190] [C0] closing socket: 0
[2019-10-28 14:26:58.609][20][debug][main] [source/server/connection_handler_impl.cc:80] [C0] adding to cleanup list
[2019-10-28 14:26:59.027][12][debug][main] [source/server/server.cc:170] flushing stats

streamed_output

[2019-10-28 14:34:56.694][19][debug][main] [source/server/connection_handler_impl.cc:280] [C0] new connection
[2019-10-28 14:34:56.694][19][debug][http] [source/common/http/conn_manager_impl.cc:246] [C0] new stream
[2019-10-28 14:34:56.696][19][debug][http] [source/common/http/conn_manager_impl.cc:619] [C0][S12691433455413425278] request headers complete (end_stream=true):
':authority', '10.5.130.68:9999'
':path', '/log/xxlarge'
':method', 'GET'
'user-agent', 'curl/7.29.0'
'accept', '*/*'

[2019-10-28 14:34:56.696][19][debug][http] [source/common/http/conn_manager_impl.cc:1111] [C0][S12691433455413425278] request end stream
[2019-10-28 14:34:56.696][19][debug][lua] [source/extensions/filters/common/lua/lua.cc:37] coroutine finished
[2019-10-28 14:34:56.696][19][debug][router] [source/common/router/router.cc:401] [C0][S12691433455413425278] cluster 'test' match for URL '/log/xxlarge'
[2019-10-28 14:34:56.696][19][debug][router] [source/common/router/router.cc:514] [C0][S12691433455413425278] router decoding headers:
':authority', '10.5.130.68:9999'
':path', '/xxlarge'
':method', 'GET'
':scheme', 'http'
'user-agent', 'curl/7.29.0'
'accept', '*/*'
'x-forwarded-proto', 'http'
'x-request-id', '02bf15f6-d67f-41b5-a9c8-0fe67309426a'
'x-envoy-expected-rq-timeout-ms', '15000'
'x-envoy-original-path', '/log/xxlarge'

[2019-10-28 14:34:56.696][19][debug][pool] [source/common/http/http1/conn_pool.cc:88] creating a new connection
[2019-10-28 14:34:56.697][19][debug][client] [source/common/http/codec_client.cc:26] [C1] connecting
[2019-10-28 14:34:56.697][19][debug][connection] [source/common/network/connection_impl.cc:704] [C1] connecting to 10.200.1.130:8080
[2019-10-28 14:34:56.697][19][debug][connection] [source/common/network/connection_impl.cc:713] [C1] connection in progress
[2019-10-28 14:34:56.697][19][debug][pool] [source/common/http/conn_pool_base.cc:20] queueing request due to no available connections
[2019-10-28 14:34:56.697][19][debug][connection] [source/common/network/connection_impl.cc:552] [C1] connected
[2019-10-28 14:34:56.697][19][debug][client] [source/common/http/codec_client.cc:64] [C1] connected
[2019-10-28 14:34:56.697][19][debug][pool] [source/common/http/http1/conn_pool.cc:241] [C1] attaching to next request
[2019-10-28 14:34:56.697][19][debug][router] [source/common/router/router.cc:1503] [C0][S12691433455413425278] pool ready
[2019-10-28 14:34:56.704][19][debug][router] [source/common/router/router.cc:994] [C0][S12691433455413425278] upstream headers complete: end_stream=false
[2019-10-28 14:34:56.704][19][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:582] script log: vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv
[2019-10-28 14:34:56.704][19][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:337] yielding for next body chunk
[2019-10-28 14:34:56.704][19][debug][lua] [source/extensions/filters/common/lua/lua.cc:40] coroutine yielded
[2019-10-28 14:34:56.704][19][debug][http] [source/common/http/conn_manager_impl.cc:1378] [C0][S12691433455413425278] encoding headers via codec (end_stream=false):
':status', '200'
'content-type', 'text/html; charset=utf-8'
'content-length', '4000000'
'server', 'envoy'
'date', 'Mon, 28 Oct 2019 14:34:56 GMT'
'x-envoy-upstream-service-time', '7'

[2019-10-28 14:34:56.707][19][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:337] yielding for next body chunk
[2019-10-28 14:34:56.707][19][debug][lua] [source/extensions/filters/common/lua/lua.cc:40] coroutine yielded
[2019-10-28 14:34:56.707][19][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:337] yielding for next body chunk
[2019-10-28 14:34:56.707][19][debug][lua] [source/extensions/filters/common/lua/lua.cc:40] coroutine yielded
[2019-10-28 14:34:56.708][19][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:337] yielding for next body chunk
[2019-10-28 14:34:56.708][19][debug][lua] [source/extensions/filters/common/lua/lua.cc:40] coroutine yielded
...
[2019-10-28 14:34:56.723][19][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:337] yielding for next body chunk
[2019-10-28 14:34:56.723][19][debug][lua] [source/extensions/filters/common/lua/lua.cc:40] coroutine yielded
[2019-10-28 14:34:56.724][19][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:337] yielding for next body chunk
[2019-10-28 14:34:56.724][19][debug][lua] [source/extensions/filters/common/lua/lua.cc:40] coroutine yielded
[2019-10-28 14:34:56.724][19][debug][client] [source/common/http/codec_client.cc:95] [C1] response complete
[2019-10-28 14:34:56.724][19][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:334] body complete. no more body chunks
[2019-10-28 14:34:56.724][19][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:582] script log: !!!! Last chunk buffered! Can we at least fire off a log?
[2019-10-28 14:34:56.734][19][debug][router] [source/common/router/router.cc:401] [C0][S14559515594191298660] cluster 'txn_logger' match for URL '/response/for/02bf15f6-d67f-41b5-a9c8-0fe67309426a'
[2019-10-28 14:34:56.734][19][debug][router] [source/common/router/router.cc:514] [C0][S14559515594191298660] router decoding headers:
':path', '/response/for/02bf15f6-d67f-41b5-a9c8-0fe67309426a'
':method', 'POST'
':authority', 'txn_logger'
':scheme', 'http'
'content-length', '4000000'
'x-envoy-internal', 'true'
'x-forwarded-for', '10.200.1.132'

[2019-10-28 14:34:56.734][19][debug][pool] [source/common/http/http1/conn_pool.cc:88] creating a new connection
[2019-10-28 14:34:56.734][19][debug][client] [source/common/http/codec_client.cc:26] [C2] connecting
[2019-10-28 14:34:56.734][19][debug][connection] [source/common/network/connection_impl.cc:704] [C2] connecting to 10.200.1.134:5000
[2019-10-28 14:34:56.735][19][debug][connection] [source/common/network/connection_impl.cc:713] [C2] connection in progress
[2019-10-28 14:34:56.735][19][debug][pool] [source/common/http/conn_pool_base.cc:20] queueing request due to no available connections
[2019-10-28 14:34:56.735][19][debug][lua] [source/extensions/filters/common/lua/lua.cc:40] coroutine yielded
[2019-10-28 14:34:56.735][19][debug][pool] [source/common/http/http1/conn_pool.cc:198] [C1] response complete
[2019-10-28 14:34:56.735][19][debug][pool] [source/common/http/http1/conn_pool.cc:203] [C1] saw upstream close connection
[2019-10-28 14:34:56.735][19][debug][connection] [source/common/network/connection_impl.cc:101] [C1] closing data_to_write=0 type=1
[2019-10-28 14:34:56.735][19][debug][connection] [source/common/network/connection_impl.cc:190] [C1] closing socket: 1
[2019-10-28 14:34:56.735][19][debug][client] [source/common/http/codec_client.cc:82] [C1] disconnect. resetting 0 pending requests
[2019-10-28 14:34:56.735][19][debug][pool] [source/common/http/http1/conn_pool.cc:129] [C1] client disconnected, failure reason:
[2019-10-28 14:34:56.735][19][debug][connection] [source/common/network/connection_impl.cc:520] [C1] remote close
[2019-10-28 14:34:56.735][19][debug][connection] [source/common/network/connection_impl.cc:552] [C2] connected
[2019-10-28 14:34:56.735][19][debug][client] [source/common/http/codec_client.cc:64] [C2] connected
[2019-10-28 14:34:56.735][19][debug][pool] [source/common/http/http1/conn_pool.cc:241] [C2] attaching to next request
[2019-10-28 14:34:56.735][19][debug][router] [source/common/router/router.cc:1503] [C0][S14559515594191298660] pool ready
[2019-10-28 14:34:56.735][19][debug][connection] [source/common/network/connection_impl.cc:449] [C2] onAboveWriteBufferHighWatermark
[2019-10-28 14:34:56.744][19][debug][connection] [source/common/network/connection_impl.cc:479] [C0] remote early close
[2019-10-28 14:34:56.744][19][debug][connection] [source/common/network/connection_impl.cc:190] [C0] closing socket: 0
[2019-10-28 14:34:56.744][19][debug][http] [source/common/http/conn_manager_impl.cc:1596] [C0][S12691433455413425278] stream reset
[2019-10-28 14:34:56.744][19][debug][router] [source/common/router/router.cc:1452] [C0][S14559515594191298660] resetting pool request
[2019-10-28 14:34:56.744][19][debug][client] [source/common/http/codec_client.cc:105] [C2] request reset
[2019-10-28 14:34:56.744][19][debug][connection] [source/common/network/connection_impl.cc:101] [C2] closing data_to_write=3044753 type=1
[2019-10-28 14:34:56.744][19][debug][connection] [source/common/network/connection_impl.cc:190] [C2] closing socket: 1
[2019-10-28 14:34:56.744][19][debug][client] [source/common/http/codec_client.cc:82] [C2] disconnect. resetting 0 pending requests
[2019-10-28 14:34:56.745][19][debug][pool] [source/common/http/http1/conn_pool.cc:129] [C2] client disconnected, failure reason:
[2019-10-28 14:34:56.745][19][debug][main] [source/server/connection_handler_impl.cc:80] [C0] adding to cleanup list
[2019-10-28T14:34:56.694Z] "GET /log/xxlarge HTTP/1.1" 200 - 0 4000000 50 7 "-" "curl/7.29.0" "-" "-" "-" "-" "02bf15f6-d67f-41b5-a9c8-0fe67309426a" "-" "10.5.130.68:9999" "10.200.1.130:8080"
[2019-10-28 14:34:58.029][12][debug][main] [source/server/server.cc:170] flushing stats
@mattklein123
Copy link
Member

mattklein123 commented Oct 28, 2019 •
edited
Loading

I'm not sure what is going on here exactly, but something is strange with the logic here:

envoy/source/extensions/filters/http/lua/lua_filter.cc

Line 43 in da56bbc

Http::FilterDataStatus StreamHandleWrapper::onData(Buffer::Instance& data, bool end_stream) {
. From my read of the logs, in the streaming case we are continuing the filter chain and not blocking while we wait for the HTTP call to complete. Off the top of my head I'm not sure why this is happening so will mark help wanted for someone to investigate.

cc @dio @derekargueta who I think have been in this code more recently.

@mattklein123 mattklein123 added this to the 1.13.0 milestone Nov 1, 2019
@mattklein123 mattklein123 modified the milestones: 1.13.0, 1.14.0 Dec 6, 2019
@mattklein123 mattklein123 modified the milestones: 1.14.0, 1.15.0 Mar 18, 2020
@mattklein123 mattklein123 modified the milestones: 1.15.0, 1.16.0 Jun 24, 2020
@dio dio mentioned this issue Jul 1, 2020
Closed
@dio
Copy link
Member

dio commented Jul 1, 2020

To properly buffer the response, the "blocking" handle:body() API is the way to go.

@dio dio closed this as completed Jul 1, 2020
@v1b1
Copy link
Author

v1b1 commented Jul 2, 2020

Hi @dio I'm not why this was closed as it's still a bug that the filter chain continues without finishing the Lua envoy_on_response() code if bodyChunks() is used. There is a noticeable difference in response times if I use body() vs bodyChunks().

@dio
Copy link
Member

dio commented Jul 2, 2020

oops sorry, I meant to close my PR which has wrong approach.

@dio dio reopened this Jul 2, 2020
@dio
Copy link
Member

dio commented Jul 2, 2020 •
edited
Loading

@v1b1 just curious, have you tried to use the latest version of Envoy? I simulated this, yes, the response from envoy (proxying data from upstream) comes early (before the httpCall is finished). But the httpCall is "always" successful (given no network problem). I simulated a slow server that sends a response after 10 secs.

And probably you can consider using "async" (fire-and-forget) httpCall? Add handle:httpCall(cluster, headers, table.concat(t, ""), 0, true) (add true as the last arg).

@v1b1
Copy link
Author

v1b1 commented Jul 6, 2020

@dio I'll give it a try when I can, we recently were allowed to update to v1.13.0 and once I have the cycles to test I will do so.

The main driver behind this is to mirror 100% of requests and responses for audit purposes, without the developers having to write and maintain the payload logging code themselves. Would an HTTP tap provide better performance?

@s-vivien
Copy link

s-vivien commented Aug 14, 2020 •
edited
Loading

Hello,

I encountered the same bug with the 1.10.0 version, I tried with the latest version 1.15.0 and the bug is still here.

Here is the envoy_on_response function I'm using :

function envoy_on_response(response_handle)
  response_handle:logDebug("- - DOWNLOAD onResponse START - -")
  response_handle:logTrace(response_handle:headers():get(":status"))
  for chunk in response_handle:bodyChunks() do
    response_handle:logDebug('-- chunk --')
  end
  response_handle:logDebug("- - chunking done - -")

  local headers, body = response_handle:httpCall(
  "mocky",
  {
     [":method"] = "GET",
     [":path"] = "/v3/78c87d3a-9857-41f6-b87b-9a8b664f1fb3?mocky-delay=30s",
     [":authority"] = "run.mocky.io",
     ["Content-Type"] = "application/json"
  },
  nil,
  15000)

  response_handle:logDebug("- - async call done - -")
  response_handle:logDebug(body)

  response_handle:logDebug("- - DOWNLOAD onResponse END - -")
end

And this is the logs I get, starting from after the chunking is done.

[2020-08-14 14:37:11.847][16][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:702] script log: -- chunk --
[2020-08-14 14:37:11.847][16][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:456] body complete. no more body chunks
[2020-08-14 14:37:11.847][16][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:702] script log: - - chunking done - -
[2020-08-14 14:37:11.847][16][debug][router] [source/common/router/router.cc:426] [C0][S18400598039333521821] cluster 'mocky' match for URL '/v3/78c87d3a-9857-41f6-b87b-9a8b664f1fb3?mocky-delay=30s'
[2020-08-14 14:37:11.847][16][debug][router] [source/common/router/router.cc:583] [C0][S18400598039333521821] router decoding headers:
':path', '/v3/78c87d3a-9857-41f6-b87b-9a8b664f1fb3?mocky-delay=30s'
':method', 'GET'
':authority', 'run.mocky.io'
':scheme', 'http'
'content-type', 'application/json'
'x-envoy-internal', 'true'
'x-forwarded-for', '172.12.35.3'
'x-envoy-expected-rq-timeout-ms', '15000'

[2020-08-14 14:37:11.847][16][debug][pool] [source/common/http/conn_pool_base.cc:71] queueing request due to no available connections
[2020-08-14 14:37:11.847][16][debug][pool] [source/common/conn_pool/conn_pool_base.cc:53] creating a new connection
[2020-08-14 14:37:11.848][16][debug][client] [source/common/http/codec_client.cc:35] [C3] connecting
[2020-08-14 14:37:11.848][16][debug][connection] [source/common/network/connection_impl.cc:753] [C3] connecting to 185.42.117.108:80
[2020-08-14 14:37:11.848][16][debug][connection] [source/common/network/connection_impl.cc:769] [C3] connection in progress
[2020-08-14 14:37:11.848][16][debug][lua] [source/extensions/filters/common/lua/lua.cc:40] coroutine yielded
[2020-08-14 14:37:11.848][16][trace][lua] [bazel-out/k8-opt/bin/source/extensions/filters/common/lua/_virtual_includes/lua_lib/extensions/filters/common/lua/lua.h:183] marking dead N5Envoy10Extensions7Filters6Common3Lua13BufferWrapperE at 0x7f28b5649870
[2020-08-14 14:37:11.848][16][trace][lua] [source/extensions/filters/http/lua/lua_filter.cc:220] buffering body
[2020-08-14 14:37:11.848][16][trace][lua] [bazel-out/k8-opt/bin/source/extensions/filters/common/lua/_virtual_includes/lua_lib/extensions/filters/common/lua/lua.h:183] marking dead N5Envoy10Extensions11HttpFilters3Lua19StreamHandleWrapperE at 0x7f28b5664790
[2020-08-14 14:37:11.848][16][trace][http] [source/common/http/conn_manager_impl.cc:1898] [C0][S2040736841487543299] encode data called: filter=0x559b06fe7b80 status=1
[2020-08-14 14:37:11.848][16][debug][pool] [source/common/http/http1/conn_pool.cc:49] [C2] response complete
[2020-08-14 14:37:11.848][16][debug][pool] [source/common/conn_pool/conn_pool_base.cc:98] [C2] destroying stream: 0 remaining
[2020-08-14 14:37:11.848][16][trace][connection] [source/common/network/connection_impl.cc:315] [C2] readDisable: disable=false disable_count=1 state=0 buffer_length=5286
[2020-08-14 14:37:11.848][16][trace][http] [source/common/http/http1/codec_impl.cc:570] [C2] parsed 5286 bytes
[2020-08-14 14:37:11.848][16][trace][main] [source/common/event/dispatcher_impl.cc:84] clearing deferred deletion list (size=1)
[2020-08-14 14:37:11.848][16][trace][connection] [source/common/network/connection_impl.cc:506] [C2] socket event: 3
[2020-08-14 14:37:11.848][16][trace][connection] [source/common/network/connection_impl.cc:607] [C2] write ready
[2020-08-14 14:37:11.848][16][trace][connection] [source/common/network/connection_impl.cc:544] [C2] read ready. dispatch_buffered_data=true
[2020-08-14 14:37:11.848][16][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:80] [C2] ssl read returns: -1
[2020-08-14 14:37:11.848][16][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:154] [C2] ssl read 0 bytes
[2020-08-14 14:37:11.848][16][trace][connection] [source/common/network/connection_impl.cc:506] [C0] socket event: 2
[2020-08-14 14:37:11.848][16][trace][connection] [source/common/network/connection_impl.cc:607] [C0] write ready
[2020-08-14 14:37:11.848][16][trace][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:258] [C0] ssl write returns: 5286
[2020-08-14 14:37:11.848][16][debug][connection] [source/common/network/connection_impl.cc:488] [C0] onBelowWriteBufferLowWatermark
[2020-08-14 14:37:11.848][16][debug][http] [source/common/http/conn_manager_impl.cc:2026] [C0][S2040736841487543299] Enabling upstream stream due to downstream stream watermark.
[2020-08-14 14:37:11.872][16][trace][connection] [source/common/network/connection_impl.cc:506] [C3] socket event: 2
[2020-08-14 14:37:11.872][16][trace][connection] [source/common/network/connection_impl.cc:607] [C3] write ready
[2020-08-14 14:37:11.872][16][debug][connection] [source/common/network/connection_impl.cc:616] [C3] connected
[2020-08-14 14:37:11.872][16][debug][client] [source/common/http/codec_client.cc:73] [C3] connected
[2020-08-14 14:37:11.872][16][debug][pool] [source/common/conn_pool/conn_pool_base.cc:146] [C3] attaching to next request
[2020-08-14 14:37:11.872][16][debug][pool] [source/common/conn_pool/conn_pool_base.cc:73] [C3] creating stream
[2020-08-14 14:37:11.872][16][debug][router] [source/common/router/upstream_request.cc:342] [C0][S18400598039333521821] pool ready
[2020-08-14 14:37:11.872][16][trace][connection] [source/common/network/connection_impl.cc:427] [C3] writing 237 bytes, end_stream false
[2020-08-14 14:37:11.872][16][trace][connection] [source/common/network/connection_impl.cc:607] [C3] write ready
[2020-08-14 14:37:11.872][16][trace][connection] [source/common/network/raw_buffer_socket.cc:68] [C3] write returns: 237
[2020-08-14 14:37:11.872][16][trace][connection] [source/common/network/connection_impl.cc:506] [C3] socket event: 2
[2020-08-14 14:37:11.872][16][trace][connection] [source/common/network/connection_impl.cc:607] [C3] write ready
 * the client gets the 200 response here at 14:37:11, but the LUA script still is executed *

 * the thread was still going on, the httpCall finally times-out 15s later and the end of the script is executed *
[2020-08-14 14:37:26.847][16][debug][router] [source/common/router/router.cc:789] [C0][S18400598039333521821] upstream timeout
[2020-08-14 14:37:26.847][16][debug][router] [source/common/router/upstream_request.cc:284] [C0][S18400598039333521821] resetting pool request
[2020-08-14 14:37:26.847][16][debug][client] [source/common/http/codec_client.cc:115] [C3] request reset
[2020-08-14 14:37:26.847][16][trace][main] [source/common/event/dispatcher_impl.cc:175] item added to deferred deletion list (size=1)
[2020-08-14 14:37:26.847][16][debug][connection] [source/common/network/connection_impl.cc:112] [C3] closing data_to_write=0 type=1
[2020-08-14 14:37:26.847][16][debug][connection] [source/common/network/connection_impl.cc:208] [C3] closing socket: 1
[2020-08-14 14:37:26.847][16][debug][client] [source/common/http/codec_client.cc:92] [C3] disconnect. resetting 0 pending requests
[2020-08-14 14:37:26.847][16][debug][pool] [source/common/conn_pool/conn_pool_base.cc:255] [C3] client disconnected, failure reason: 
[2020-08-14 14:37:26.847][16][trace][main] [source/common/event/dispatcher_impl.cc:175] item added to deferred deletion list (size=2)
[2020-08-14 14:37:26.847][16][debug][http] [source/common/http/async_client_impl.cc:99] async http request response headers (end_stream=false):
':status', '504'
'content-length', '24'
'content-type', 'text/plain'

[2020-08-14 14:37:26.847][16][trace][http] [source/common/http/async_client_impl.cc:115] async http request response data (length=24 end_stream=true)
[2020-08-14 14:37:26.847][16][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:328] async HTTP response complete
[2020-08-14 14:37:26.847][16][trace][lua] [bazel-out/k8-opt/bin/source/extensions/filters/common/lua/_virtual_includes/lua_lib/extensions/filters/common/lua/lua.h:192] marking live N5Envoy10Extensions11HttpFilters3Lua19StreamHandleWrapperE at 0x7f28b5664790
[2020-08-14 14:37:26.847][16][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:702] script log: - - async call done - -
[2020-08-14 14:37:26.847][16][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:702] script log: upstream request timeout
[2020-08-14 14:37:26.847][16][debug][lua] [source/extensions/filters/http/lua/lua_filter.cc:702] script log: - - DOWNLOAD onResponse END - -
* Here we can see the last log of the LUA script is printed *
[2020-08-14 14:37:26.847][16][debug][lua] [source/extensions/filters/common/lua/lua.cc:37] coroutine finished
[2020-08-14 14:37:26.847][16][trace][lua] [bazel-out/k8-opt/bin/source/extensions/filters/common/lua/_virtual_includes/lua_lib/extensions/filters/common/lua/lua.h:183] marking dead N5Envoy10Extensions11HttpFilters3Lua19StreamHandleWrapperE at 0x7f28b5664790
[2020-08-14 14:37:26.847][16][trace][http] [source/common/http/conn_manager_impl.cc:2119] [C0][S2040736841487543299] continuing filter chain: filter=0x559b06fe7b80
[2020-08-14 14:37:26.847][16][trace][http] [source/common/http/conn_manager_impl.cc:1924] [C0][S2040736841487543299] encoding data via codec (size=0 end_stream=true)
[2020-08-14 14:37:26.847][16][trace][connection] [source/common/network/connection_impl.cc:315] [C0] readDisable: disable=false disable_count=1 state=0 buffer_length=0
[2020-08-14 14:37:26.847][16][trace][main] [source/common/event/dispatcher_impl.cc:175] item added to deferred deletion list (size=3)
[2020-08-14 14:37:26.847][16][trace][main] [source/common/event/dispatcher_impl.cc:175] item added to deferred deletion list (size=4)
[2020-08-14 14:37:26.847][16][trace][main] [source/common/event/dispatcher_impl.cc:84] clearing deferred deletion list (size=4)
[2020-08-14 14:37:26.847][16][debug][pool] [source/common/conn_pool/conn_pool_base.cc:98] [C3] destroying stream: 0 remaining
[2020-08-14 14:37:26.847][16][trace][lua] [bazel-out/k8-opt/bin/source/extensions/filters/common/lua/_virtual_includes/lua_lib/extensions/filters/common/lua/lua.h:183] marking dead N5Envoy10Extensions11HttpFilters3Lua19StreamHandleWrapperE at 0x7f28b5664790
[2020-08-14 14:37:26.847][16][trace][lua] [bazel-out/k8-opt/bin/source/extensions/filters/common/lua/_virtual_includes/lua_lib/extensions/filters/common/lua/lua.h:183] marking dead N5Envoy10Extensions11HttpFilters3Lua19StreamHandleWrapperE at 0x7f28b5660480
[2020-08-14 14:37:26.848][16][trace][connection] [source/common/network/connection_impl.cc:506] [C0] socket event: 2
[2020-08-14 14:37:26.848][16][trace][connection] [source/common/network/connection_impl.cc:607] [C0] write ready

Expected behavior : the LUA script waits for the httpCall to end and after that the client finally gets the response
Observed behavior : the client gets the response right after the httpCall is fired, the LUA still continues

EDIT : Regardless of the timeout parameter value on the httpCall, the call always seem to finish (i.e. the response is logged)

@mattklein123 mattklein123 modified the milestones: 1.16.0, 1.17.0 Oct 7, 2020
@mattklein123 mattklein123 self-assigned this Jan 7, 2021
@mattklein123 mattklein123 modified the milestones: 1.17.0, 1.18.0 Jan 7, 2021
@mattklein123 mattklein123 modified the milestones: 1.18.0, 1.19.0 Apr 25, 2021
@mattklein123 mattklein123 removed this from the 1.19.0 milestone Jul 7, 2021
@mattklein123 mattklein123 removed their assignment Jul 19, 2022
@instagrim-dev
Copy link

Still an issue in latest stable & dev builds.

Any likelihood of this being revived or solved in a wider scoped task?
If not, perhaps @alyssawilk could provide some guidance and I can take on this contribution (internals have changed quite a bit in the last 2 years).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug help wanted Needs help!
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

lua: Block on wait for body chunk
5 participants
@dio @instagrim-dev @mattklein123 @s-vivien @v1b1