search

envoyproxy / envoy

Cloud-native high-performance edge/middle/service proxy
https://www.envoyproxy.io
Apache License 2.0
24.85k stars 4.78k forks source link

Crash in ConnectionImpl::onMessageBeginBase #3337

Closed ddunbar closed 6 years ago

ddunbar commented 6 years ago

Description: Envoy crashes with the supplied configuration file, and using tcpkali as a server.

I tested with Envoy trunk on macOS, using f95269d5f06da435d14162b14cde664edec95109.

Repro steps:

# Start tcpkali in listening mode, with a dummy reply:
$ tcpkali -T300 -l127.1:4444 --listen-mode=active -e1 'HTTP/1.1 200 OK\nContent-Length: 4\n\nnice\r\n' --dump-all

# Start Envoy with the included configuration, it will crash immediately:
$ envoy-static -c envoy-crash.json 
[2018-05-09 16:16:50.817][49754746][info][main] source/server/server.cc:188] initializing epoch 0 (hot restart version=disabled)
[2018-05-09 16:16:50.819][49754746][info][main] source/server/server.cc:190] statically linked extensions:
[2018-05-09 16:16:50.819][49754746][info][main] source/server/server.cc:192]   access_loggers: envoy.file_access_log,envoy.http_grpc_access_log
[2018-05-09 16:16:50.819][49754746][info][main] source/server/server.cc:195]   filters.http: envoy.buffer,envoy.cors,envoy.ext_authz,envoy.fault,envoy.grpc_http1_bridge,envoy.grpc_json_transcoder,envoy.grpc_web,envoy.gzip,envoy.health_check,envoy.http_dynamo_filter,envoy.ip_tagging,envoy.lua,envoy.rate_limit,envoy.router,envoy.squash
[2018-05-09 16:16:50.819][49754746][info][main] source/server/server.cc:198]   filters.listener: envoy.listener.original_dst,envoy.listener.proxy_protocol,envoy.listener.tls_inspector
[2018-05-09 16:16:50.819][49754746][info][main] source/server/server.cc:201]   filters.network: envoy.client_ssl_auth,envoy.echo,envoy.ext_authz,envoy.http_connection_manager,envoy.mongo_proxy,envoy.ratelimit,envoy.redis_proxy,envoy.tcp_proxy
[2018-05-09 16:16:50.826][49754746][info][main] source/server/server.cc:203]   stat_sinks: envoy.dog_statsd,envoy.metrics_service,envoy.statsd
[2018-05-09 16:16:50.826][49754746][info][main] source/server/server.cc:205]   tracers: envoy.dynamic.ot,envoy.lightstep,envoy.zipkin
[2018-05-09 16:16:50.826][49754746][info][main] source/server/server.cc:208]   transport_sockets.downstream: raw_buffer,ssl
[2018-05-09 16:16:50.826][49754746][info][main] source/server/server.cc:211]   transport_sockets.upstream: raw_buffer,ssl
[2018-05-09 16:16:50.881][49754746][info][config] source/server/configuration_impl.cc:52] loading 1 listener(s)
[2018-05-09 16:16:50.900][49754746][info][config] source/server/configuration_impl.cc:92] loading tracing configuration
[2018-05-09 16:16:50.900][49754746][info][config] source/server/configuration_impl.cc:114] loading stats sink configuration
[2018-05-09 16:16:50.900][49754746][info][main] source/server/server.cc:387] starting main dispatch loop
[2018-05-09 16:16:50.901][49754746][info][upstream] source/common/upstream/cluster_manager_impl.cc:131] cm init: all clusters initialized
[2018-05-09 16:16:50.901][49754746][info][main] source/server/server.cc:371] all clusters initialized. initializing init manager
[2018-05-09 16:16:50.901][49754746][info][config] source/server/listener_manager_impl.cc:608] all dependencies initialized. starting workers
[2018-05-09 16:16:50.902][49754746][critical][assert] source/common/http/http1/codec_impl.cc:376] assert failure: !current_header_map_
[2018-05-09 16:16:50.902][49754746][critical][backtrace] bazel-out/darwin-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] Caught Abort trap: 6, suspect faulting address 0x7fff74b1fb6e
[2018-05-09 16:16:50.951][49754746][critical][backtrace] bazel-out/darwin-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:87] Backtrace obj<envoy-static> thr<0>:
[2018-05-09 16:16:50.951][49754746][critical][backtrace] bazel-out/darwin-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:99] thr<0> obj<envoy-static                        0x000000010416a7d6 _ZN8backward7details6unwindINS_14StackTraceImplINS_10system_tag10darwin_tagEE8callbackEEEmT_m>
[2018-05-09 16:16:50.951][49754746][critical][backtrace] bazel-out/darwin-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:105] thr<0> #0 0x10416a7d6: 
[2018-05-09 16:16:50.951][49754746][critical][backtrace] bazel-out/darwin-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:99] thr<0> obj<envoy-static>
[2018-05-09 16:16:50.985][49754746][critical][backtrace] bazel-out/darwin-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:105] thr<0> #1 0x10416a345: backward::StackTraceImpl<backward::system_tag::darwin_tag>::load_here(unsigned long) + 101
[2018-05-09 16:16:50.985][49754746][critical][backtrace] bazel-out/darwin-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:105] thr<0> #2 0x10416a141: backward::StackTraceImpl<backward::system_tag::darwin_tag>::load_from(void*, unsigned long) + 49
[2018-05-09 16:16:50.985][49754746][critical][backtrace] bazel-out/darwin-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:105] thr<0> #3 0x10416869e: Envoy::BackwardsTrace::captureFrom(void*) + 46
[2018-05-09 16:16:50.985][49754746][critical][backtrace] bazel-out/darwin-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:105] thr<0> #4 0x10416855f: Envoy::SignalAction::sigHandler(int, __siginfo*, void*) + 143
[2018-05-09 16:16:51.087][49754746][critical][backtrace] bazel-out/darwin-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:110] end backtrace thread 0
Abort trap: 6

Config:

{
  "listeners": [
    {
      "address": "tcp://127.0.0.1:1111",
      "filters": [
        {
          "type": "read",
          "name": "http_connection_manager",
          "config": {
            "codec_type": "http1",
            "stat_prefix": "mycluster",
            "route_config": {
              "virtual_hosts": [
                {
                  "name": "mycluster",
                  "domains": ["*"],
                  "routes": [
                    {
                      "prefix": "/",
                      "use_websocket": true,
                      "cluster": "mycluster"
                    }
                  ]
                }
              ]
            },
            "filters": [
              {
                "type": "decoder",
                "name": "router",
                "config": {}
              }
            ]
          }
        }
      ]
    }
  ],
  "admin": {
    "access_log_path": "/dev/null",
    "address": "tcp://127.0.0.1:8001"
  },
  "cluster_manager": {
    "clusters": [
      {
        "name": "mycluster",
        "connect_timeout_ms": 1000,
        "type": "strict_dns",
        "lb_type": "round_robin",
        "health_check": {
          "type": "http",
          "timeout_ms": 1000,
          "interval_ms": 5000,
          "unhealthy_threshold": 1,
          "healthy_threshold": 3,
          "path": "/health",
          "service_name": "my-service-name"
        },
        "hosts": [ { "url": "tcp://127.0.0.1:4444" } ]
      }
    ]
  }
}

Call Stack:

[2018-05-09 16:16:50.901][49754746][info][config] source/server/listener_manager_impl.cc:608] all dependencies initialized. starting workers
[2018-05-09 16:16:50.902][49754746][critical][assert] source/common/http/http1/codec_impl.cc:376] assert failure: !current_header_map_
[2018-05-09 16:16:50.902][49754746][critical][backtrace] bazel-out/darwin-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] Caught Abort trap: 6, suspect faulting address 0x7fff74b1fb6e
[2018-05-09 16:16:50.951][49754746][critical][backtrace] bazel-out/darwin-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:87] Backtrace obj<envoy-static> thr<0>:
[2018-05-09 16:16:50.951][49754746][critical][backtrace] bazel-out/darwin-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:99] thr<0> obj<envoy-static                        0x000000010416a7d6 _ZN8backward7details6unwindINS_14StackTraceImplINS_10system_tag10darwin_tagEE8callbackEEEmT_m>
[2018-05-09 16:16:50.951][49754746][critical][backtrace] bazel-out/darwin-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:105] thr<0> #0 0x10416a7d6: 
[2018-05-09 16:16:50.951][49754746][critical][backtrace] bazel-out/darwin-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:99] thr<0> obj<envoy-static>
[2018-05-09 16:16:50.985][49754746][critical][backtrace] bazel-out/darwin-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:105] thr<0> #1 0x10416a345: backward::StackTraceImpl<backward::system_tag::darwin_tag>::load_here(unsigned long) + 101
[2018-05-09 16:16:50.985][49754746][critical][backtrace] bazel-out/darwin-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:105] thr<0> #2 0x10416a141: backward::StackTraceImpl<backward::system_tag::darwin_tag>::load_from(void*, unsigned long) + 49
[2018-05-09 16:16:50.985][49754746][critical][backtrace] bazel-out/darwin-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:105] thr<0> #3 0x10416869e: Envoy::BackwardsTrace::captureFrom(void*) + 46
[2018-05-09 16:16:50.985][49754746][critical][backtrace] bazel-out/darwin-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:105] thr<0> #4 0x10416855f: Envoy::SignalAction::sigHandler(int, __siginfo*, void*) + 143
[2018-05-09 16:16:51.087][49754746][critical][backtrace] bazel-out/darwin-fastbuild/bin/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:110] end backtrace thread 0
Abort trap: 6
mattklein123 commented 6 years ago

@ggreenway

ggreenway commented 6 years ago

This is not websocket-specific. I deleted the "use_websocket" line from the config and get the same result.

ggreenway commented 6 years ago 
#1  0x00007ffff711202a in __GI_abort () at abort.c:89
#2  0x0000000000b9bc90 in Envoy::Http::Http1::ConnectionImpl::onMessageBeginBase (this=0x2548fc8) at source/common/http/http1/codec_impl.cc:376
#3  0x0000000000b9ab22 in Envoy::Http::Http1::ConnectionImpl::<lambda(http_parser*)>::operator()(http_parser *) const (__closure=0x0, parser=0x2548fd8) at source/common/http/http1/codec_impl.cc:246
#4  0x0000000000b9ab47 in Envoy::Http::Http1::ConnectionImpl::<lambda(http_parser*)>::_FUN(http_parser *) () at source/common/http/http1/codec_impl.cc:248
#5  0x0000000000ba343d in http_parser_execute (parser=0x2548fd8, settings=0x1b6ad00 <Envoy::Http::Http1::ConnectionImpl::settings_>, data=0x28e6c30 "HTTP/1.1 200 OK\nContent-Length: 4\n\nnice\r\n", len=41)
    at external/com_github_nodejs_http_parser/http_parser.c:775
#6  0x0000000000b9b939 in Envoy::Http::Http1::ConnectionImpl::dispatchSlice (this=0x2548fc8, slice=0x28e6c30 "HTTP/1.1 200 OK\nContent-Length: 4\n\nnice\r\n", len=41)
    at source/common/http/http1/codec_impl.cc:327
#7  0x0000000000b9b80d in Envoy::Http::Http1::ConnectionImpl::dispatch (this=0x2548fc8, data=...) at source/common/http/http1/codec_impl.cc:316
#8  0x0000000000a9e8b1 in Envoy::Http::CodecClient::onData (this=0x25fec60, data=...) at source/common/http/codec_client.cc:115
#9  0x0000000000aa003c in Envoy::Http::CodecClient::CodecReadFilter::onData (this=0x254af00, data=...)
    at bazel-out/k8-dbg/bin/source/common/http/_virtual_includes/codec_client_lib/common/http/codec_client.h:160
#10 0x000000000084d967 in Envoy::Network::FilterManagerImpl::onContinueReading (this=0x2708018, filter=0x0) at source/common/network/filter_manager_impl.cc:56
#11 0x000000000084d9fe in Envoy::Network::FilterManagerImpl::onRead (this=0x2708018) at source/common/network/filter_manager_impl.cc:66
#12 0x0000000000844e86 in Envoy::Network::ConnectionImpl::onRead (this=0x2708000, read_buffer_size=41) at source/common/network/connection_impl.cc:213
#13 0x0000000000845cff in Envoy::Network::ConnectionImpl::onReadReady (this=0x2708000) at source/common/network/connection_impl.cc:441
#14 0x0000000000845b97 in Envoy::Network::ConnectionImpl::onFileEvent (this=0x2708000, events=3) at source/common/network/connection_impl.cc:417
#15 0x00000000008435bb in Envoy::Network::ConnectionImpl::ConnectionImpl(Envoy::Event::Dispatcher&, std::unique_ptr<Envoy::Network::ConnectionSocket, std::default_delete<Envoy::Network::ConnectionSocket> >&&, std::unique_ptr<Envoy::Network::TransportSocket, std::default_delete<Envoy::Network::TransportSocket> >&&, bool)::{lambda(unsigned int)#3}::operator()(unsigned int) const ()
    at source/common/network/connection_impl.cc:64
#16 0x000000000084737c in std::_Function_handler<void(unsigned int), Envoy::Network::ConnectionImpl::ConnectionImpl(Envoy::Event::Dispatcher&, Envoy::Network::ConnectionSocketPtr&&, Envoy::Network::TransportSocketPtr&&, bool)::<lambda(uint32_t)> >::_M_invoke(const std::_Any_data &, <unknown type in /tmp/_bazel_ggreenway/b9fd27fba8ca60f63bd77691369bf22f/execroot/envoy/bazel-out/k8-dbg/bin/source/exe/envoy-static, CU 0x3c74d2c, DIE 0x3cd45c4>) (__functor=..., 
    __args#0=<unknown type in /tmp/_bazel_ggreenway/b9fd27fba8ca60f63bd77691369bf22f/execroot/envoy/bazel-out/k8-dbg/bin/source/exe/envoy-static, CU 0x3c74d2c, DIE 0x3cd45c4>)
    at /usr/include/c++/5/functional:1871
#17 0x000000000083a68a in std::function<void (unsigned int)>::operator()(unsigned int) const (this=0x26a6988, __args#0=3) at /usr/include/c++/5/functional:2267
#18 0x00000000008396a8 in Envoy::Event::FileEventImpl::<lambda(int, short int, void*)>::operator()(int, short, void *) const (__closure=0x0, what=38, arg=0x26a6900)
    at source/common/event/file_event_impl.cc:60
#19 0x00000000008396d8 in Envoy::Event::FileEventImpl::<lambda(int, short int, void*)>::_FUN(int, short, void *) () at source/common/event/file_event_impl.cc:61
#20 0x0000000000dd5d52 in event_persist_closure (ev=<optimized out>, base=0x25a62c0) at event.c:1580
#21 event_process_active_single_queue (base=base@entry=0x25a62c0, max_to_process=max_to_process@entry=2147483647, endtime=endtime@entry=0x0, activeq=<optimized out>) at event.c:1639
#22 0x0000000000dd64af in event_process_active (base=0x25a62c0) at event.c:1738
#23 event_base_loop (base=0x25a62c0, flags=0) at event.c:1961
#24 0x000000000083419e in Envoy::Event::DispatcherImpl::run (this=0x25583c0, type=Envoy::Event::Dispatcher::RunType::Block) at source/common/event/dispatcher_impl.cc:161
#25 0x00000000007d9ff2 in Envoy::Server::InstanceImpl::run (this=0x25cf340) at source/server/server.cc:405
#26 0x0000000000433a10 in Envoy::MainCommonBase::run (this=0x2590998) at source/exe/main_common.cc:83
#27 0x0000000000420860 in Envoy::MainCommon::run (this=0x2590500) at bazel-out/k8-dbg/bin/source/exe/_virtual_includes/envoy_main_common_lib/exe/main_common.h:44
#28 0x0000000000419d91 in main (argc=3, argv=0x7fffffffe408) at source/exe/main.cc:30
ggreenway commented 6 years ago

Looking at a packet capture, an HTTP response was sent BEFORE the HTTP request for the health check. Basically as soon as the connection was established, a response was sent.

pcap.tar.gz

mattklein123 commented 6 years ago

Yeah we probably just need a check for this and then convert it to an invalid protocol exception. cc @alyssawilk

htuch commented 6 years ago

FWIW, I have a repeater for this using https://github.com/envoyproxy/envoy/pull/3338 and a corpus that local fuzzing discovered.

htuch commented 6 years ago 
events {
  downstream_send_bytes: "POST /test/long/url HTTP/1.1\r\nhost: host\r\nx-lyft-user-id: 123\r\nx-forwarded-for: 10.0.0.1\r\ntransfer-encoding: chunked\r\n\r\n400\r\naaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa;aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa\r\n0\r\n\r\n"
}
events {
  upstream_recv_bytes {
  }
}
events {
  upstream_recv_bytes {
  }
}
events {
  upstream_send_bytes: "\r"
}
events {
}
events {
  upstream_send_bytes: "\nStack trace:\n"
}
events {
  upstream_recv_bytes {
  }
}
events {
  upstream_send_bytes: "\nStack trace:\n"
}
events {
  upstream_send_bytes: ""
}
events {
  upstream_recv_bytes {
  }
}
events {
  upstream_send_bytes: "1"
}
events {
}

gives

[2018-05-10 18:12:19.322][107597][trace][connection] source/common/network/connection_impl.cc:321] [C39] writing 1 bytes, end_stream false
[2018-05-10 18:12:19.322][107606][trace][router] source/common/router/router.cc:866] [C37][S17736560302139167007] buffering 0 bytes
[2018-05-10 18:12:19.322][107478][debug][misc] test/integration/h1_capture_fuzz_test.cc:25] Processing event: upstream_recv_bytes {
}                                

[2018-05-10 18:12:19.322][107597][trace][connection] source/common/network/connection_impl.cc:321] [C39] writing 14 bytes, end_stream false
[2018-05-10 18:12:19.322][107606][trace][http] source/common/http/conn_manager_impl.cc:732] [C37][S17736560302139167007] decode data called: filter=0x7b100001e940 status=3
[2018-05-10 18:12:19.322][107478][debug][misc] test/integration/h1_capture_fuzz_test.cc:25] Processing event: upstream_send_bytes: "\nStack trace:\n"

[2018-05-10 18:12:19.322][107606][trace][http] source/common/http/http1/codec_impl.cc:322] [C37] parsed 1156 bytes
[2018-05-10 18:12:19.322][107597][trace][connection] source/common/network/connection_impl.cc:384] [C39] socket event: 2
[2018-05-10 18:12:19.322][107606][trace][connection] source/common/network/connection_impl.cc:227] [C37] readDisable: enabled=true disable=true
[2018-05-10 18:12:19.322][107478][debug][misc] test/integration/h1_capture_fuzz_test.cc:25] Processing event: upstream_send_bytes: ""

[2018-05-10 18:12:19.322][107597][trace][connection] source/common/network/connection_impl.cc:452] [C39] write ready
[2018-05-10 18:12:19.322][107606][trace][connection] source/common/network/connection_impl.cc:384] [C38] socket event: 2
[2018-05-10 18:12:19.322][107478][debug][misc] test/integration/h1_capture_fuzz_test.cc:25] Processing event: upstream_recv_bytes {
}                                                

[2018-05-10 18:12:19.322][107606][trace][connection] source/common/network/connection_impl.cc:452] [C38] write ready
[2018-05-10 18:12:19.322][107597][trace][connection] source/common/network/raw_buffer_socket.cc:67] [C39] write returns: 15
[2018-05-10 18:12:19.322][107606][debug][connection] source/common/network/connection_impl.cc:461] [C38] connected
[2018-05-10 18:12:19.322][107478][debug][misc] test/integration/h1_capture_fuzz_test.cc:25] Processing event: upstream_send_bytes: "1"

[2018-05-10 18:12:19.322][107597][trace][connection] source/common/network/connection_impl.cc:321] [C39] writing 14 bytes, end_stream false
[2018-05-10 18:12:19.322][107606][debug][client] source/common/http/codec_client.cc:63] [C38] connected
[2018-05-10 18:12:19.322][107478][debug][misc] test/integration/h1_capture_fuzz_test.cc:25] Processing event:
[2018-05-10 18:12:19.322][107597][trace][connection] source/common/network/connection_impl.cc:321] [C39] writing 1 bytes, end_stream false
[2018-05-10 18:12:19.322][107597][debug][connection] source/common/network/connection_impl.cc:98] [C39] closing data_to_write=15 type=0
[2018-05-10 18:12:19.322][107606][debug][pool] source/common/http/http1/conn_pool.cc:249] [C38] attaching to next request
[2018-05-10 18:12:19.322][107597][trace][connection] source/common/network/connection_impl.cc:384] [C39] socket event: 2
[2018-05-10 18:12:19.322][107597][trace][connection] source/common/network/connection_impl.cc:452] [C39] write ready
[2018-05-10 18:12:19.322][107606][debug][router] source/common/router/router.cc:968] [C37][S17736560302139167007] pool ready
[2018-05-10 18:12:19.323][107597][trace][connection] source/common/network/raw_buffer_socket.cc:67] [C39] write returns: 15
[2018-05-10 18:12:19.323][107606][trace][connection] source/common/network/connection_impl.cc:321] [C38] writing 260 bytes, end_stream false
[2018-05-10 18:12:19.323][107597][debug][connection] source/common/network/connection_impl.cc:487] [C39] write flush complete
[2018-05-10 18:12:19.323][107606][trace][connection] source/common/network/connection_impl.cc:321] [C38] writing 1036 bytes, end_stream false
[2018-05-10 18:12:19.323][107597][debug][connection] source/common/network/connection_impl.cc:133] [C39] closing socket: 1
[2018-05-10 18:12:19.323][107606][trace][connection] source/common/network/connection_impl.cc:452] [C38] write ready
[2018-05-10 18:12:19.323][107597][debug][testing] source/server/connection_handler_impl.cc:50] [C39] adding to cleanup list
[2018-05-10 18:12:19.323][107606][trace][connection] source/common/network/raw_buffer_socket.cc:67] [C38] write returns: 1296
[2018-05-10 18:12:19.323][107597][trace][main] source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=1)
[2018-05-10 18:12:19.323][107606][trace][connection] source/common/network/connection_impl.cc:384] [C37] socket event: 2
[2018-05-10 18:12:19.323][107597][trace][main] source/common/event/dispatcher_impl.cc:52] clearing deferred deletion list (size=1)
[2018-05-10 18:12:19.323][107478][debug][connection] source/common/network/connection_impl.cc:98] [C36] closing data_to_write=0 type=1
[2018-05-10 18:12:19.323][107606][trace][connection] source/common/network/connection_impl.cc:452] [C37] write ready
[2018-05-10 18:12:19.323][107478][debug][connection] source/common/network/connection_impl.cc:133] [C36] closing socket: 1
[2018-05-10 18:12:19.323][107606][trace][connection] source/common/network/connection_impl.cc:384] [C38] socket event: 2
[2018-05-10 18:12:19.323][107606][trace][connection] source/common/network/connection_impl.cc:452] [C38] write ready
[2018-05-10 18:12:19.323][107606][trace][connection] source/common/network/connection_impl.cc:384] [C38] socket event: 3
[2018-05-10 18:12:19.323][107606][trace][connection] source/common/network/connection_impl.cc:452] [C38] write ready
[2018-05-10 18:12:19.323][107478][info][testing] test/integration/server.cc:58] stopping integration test server
[2018-05-10 18:12:19.323][107606][trace][connection] source/common/network/connection_impl.cc:422] [C38] read ready
[2018-05-10 18:12:19.323][107606][trace][connection] source/common/network/raw_buffer_socket.cc:25] [C38] read returns: 30
[2018-05-10 18:12:19.323][107606][trace][connection] source/common/network/raw_buffer_socket.cc:25] [C38] read returns: 0
[2018-05-10 18:12:19.323][107606][trace][http] source/common/http/http1/codec_impl.cc:305] [C38] parsing 30 bytes
[2018-05-10 18:12:19.323][107606][critical][assert] source/common/http/http1/codec_impl.cc:376] assert failure: !current_header_map_
llchan commented 6 years ago

I'm also seeing this with the same stack trace. I see a read error in my trace-level log that isn't mentioned above, so figured I'd post my log as well:

[2018-05-29 21:29:06.548][120239][debug][main] external/envoy/source/server/server.cc:131] flushing stats
[2018-05-29 21:29:06.616][120239][trace][connection] external/envoy/source/common/network/connection_impl.cc:385] [C1] socket event: 3
[2018-05-29 21:29:06.616][120239][trace][connection] external/envoy/source/common/network/connection_impl.cc:453] [C1] write ready
[2018-05-29 21:29:06.616][120239][trace][connection] external/envoy/source/common/network/connection_impl.cc:423] [C1] read ready
[2018-05-29 21:29:06.616][120239][trace][connection] external/envoy/source/common/network/raw_buffer_socket.cc:25] [C1] read returns: 2
[2018-05-29 21:29:06.616][120239][trace][connection] external/envoy/source/common/network/raw_buffer_socket.cc:25] [C1] read returns: -1
[2018-05-29 21:29:06.616][120239][trace][connection] external/envoy/source/common/network/raw_buffer_socket.cc:33] [C1] read error: 11
[2018-05-29 21:29:06.616][120239][trace][http] external/envoy/source/common/http/http1/codec_impl.cc:305] [C1] parsing 2 bytes
[2018-05-29 21:29:06.616][120239][critical][assert] external/envoy/source/common/http/http1/codec_impl.cc:376] assert failure: !current_header_map_
[2018-05-29 21:29:06.616][120239][critical][backtrace] bazel-out/k8-fastbuild/bin/external/envoy/source/server/_virtual_includes/backtrace_lib/server/backtrace.h:114] Caught Aborted, suspect faulting address 0x9c690001d5af
[2018-05-29 21:29:06.617][120239][critical] Backtrace (most recent call first) from thread 0:
  #1 ?? ??:0
  #2 ?? ??:0
  #3 
  #4 Envoy::Http::Http1::ConnectionImpl::onMessageBeginBase() at codec_impl.cc:376 (discriminator 4)
  #5 Envoy::Http::Http1::ConnectionImpl::{lambda(http_parser*)#1}::operator()(http_parser*) const at codec_impl.cc:246
  #6 Envoy::Http::Http1::ConnectionImpl::{lambda(http_parser*)#1}::_FUN(http_parser*) at codec_impl.cc:248
  #7 http_parser_execute at http_parser.c:775 (discriminator 3)
  #8 Envoy::Http::Http1::ConnectionImpl::dispatchSlice(char const*, unsigned long) at codec_impl.cc:327
  #9 Envoy::Http::Http1::ConnectionImpl::dispatch(Envoy::Buffer::Instance&) at codec_impl.cc:316 (discriminator 2)
  #10 Envoy::Http::CodecClient::onData(Envoy::Buffer::Instance&) at codec_client.cc:115
  #11 Envoy::Http::CodecClient::CodecReadFilter::onData(Envoy::Buffer::Instance&, bool) at codec_client.h:160
  #12 Envoy::Network::FilterManagerImpl::onContinueReading(Envoy::Network::FilterManagerImpl::ActiveReadFilter*) at filter_manager_impl.cc:56
  #13 Envoy::Network::FilterManagerImpl::onRead() at filter_manager_impl.cc:66
  #14 Envoy::Network::ConnectionImpl::onRead(unsigned long) at connection_impl.cc:214
  #15 Envoy::Network::ConnectionImpl::onReadReady() at connection_impl.cc:442
  #16 Envoy::Network::ConnectionImpl::onFileEvent(unsigned int) at connection_impl.cc:418
  #17 Envoy::Network::ConnectionImpl::ConnectionImpl(Envoy::Event::Dispatcher&, std::unique_ptr<Envoy::Network::ConnectionSocket, std::default_delete<Envoy::Network::ConnectionSocket> >&&, std::unique_ptr<Envoy::Network::TransportSocket, std::default_delete<Envoy::Network::TransportSocket> >&&, bool)::{lambda(unsigned int)#3}::operator()(unsigned int) const at connection_impl.cc:65
  #18 std::_Function_handler<void (unsigned int), Envoy::Network::ConnectionImpl::ConnectionImpl(Envoy::Event::Dispatcher&, std::unique_ptr<Envoy::Network::ConnectionSocket, std::default_delete<Envoy::Network::ConnectionSocket> >&&, std::unique_ptr<Envoy::Network::TransportSocket, std::default_delete<Envoy::Network::TransportSocket> >&&, bool)::{lambda(unsigned int)#3}>::_M_invoke(std::_Any_data const&, unsigned int&&) at std_function.h:316
  #19 std::function<void (unsigned int)>::operator()(unsigned int) const at std_function.h:706
  #20 Envoy::Event::FileEventImpl::assignEvents(unsigned int)::{lambda(int, short, void*)#1}::operator()(int, short, void*) const at file_event_impl.cc:60
  #21 Envoy::Event::FileEventImpl::assignEvents(unsigned int)::{lambda(int, short, void*)#1}::_FUN(int, short, void*) at file_event_impl.cc:61
  #22 event_persist_closure at event.c:1580
  #23  (inlined by) event_process_active_single_queue at event.c:1639
  #24 event_process_active at event.c:1738
  #25  (inlined by) event_base_loop at event.c:1961
  #26 Envoy::Event::DispatcherImpl::run(Envoy::Event::Dispatcher::RunType) at dispatcher_impl.cc:161 (discriminator 4)
  #27 Envoy::Server::InstanceImpl::run() at server.cc:390
  #28 Envoy::MainCommonBase::run() at main_common.cc:83
  #29 Envoy::MainCommon::run() at main_common.h:44
  #30 main at main.cc:30 (discriminator 1)
  #31 
  #32 ?? ??:0
  #33 
  #34 _start at ??:?
  #35

EDIT: I should add that the C1 connection there is connected to a client cert service (i.e. one with this API), in case that helps track anything down.

mattklein123 commented 6 years ago

I've been looking at this for a bit, and it's not as straightforward as I thought. Also, I think the fuzz test failure is slightly different from the original issue. I will figure this out fully tomorrow.

mattklein123 commented 6 years ago

I've opened https://github.com/nodejs/http-parser/pull/432 to fix what I think is an http-parser bug. I will also test the original websocket issue to see if it's the same issue.

mattklein123 commented 6 years ago

I just confirmed the original issue is the same as the fuzz test issue. I will wait to see what upstream says about my fix.

ddunbar commented 6 years ago

Nice, thanks Matt!

llchan commented 6 years ago

Yeah, thanks @mattklein123 for investigating and submitting the upstream fix. :+1:

Should we poke around a bit more on envoy's side though? It seems unlikely that my super-simple golang HTTP server is responding with a CR/LF before the HTTP header. Could there be a reused connection that needs to flush out trailing CR/LF before starting the next request?

mattklein123 commented 6 years ago

@llchan yes, that's exactly what is happening. My upstream fix will flush CRL/LF.

llchan commented 6 years ago

I guess my question is more like, how did it even get into that state where there's an extra CR/LF sitting around? Shouldn't the Content-Length of the previous response give us the right size to read off? Is there some streaming parser (e.g. JSON) that consumes the data but not the newline after it?

mattklein123 commented 6 years ago

I have no idea, I didn't dig that deeply. AFAICT the parser should be eating extra CR/LF between responses and that's what I fixed it to do.

llchan commented 6 years ago

Now that the http-parser PR is merged, what's the game plan? Do we need to wait for a tagged http-parser release, or can we point at the latest master?

mattklein123 commented 6 years ago

@llchan it has not been merged. Please ping the PR there and try to get them to merge it.

llchan commented 6 years ago

Derp, my bad, misread the notification. It got the second approval it was awaiting though, so hopefully they actually merge it soon. I'm seeing many crashes a day from this so just trying to keep things moving.

ddunbar commented 6 years ago

Thanks for the persistence in getting this in!