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.

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

Crash in ConnectionImpl::onMessageBeginBase #3337

Closed
ddunbar opened this issue May 9, 2018 · 20 comments · Fixed by #3913
Closed

Crash in ConnectionImpl::onMessageBeginBase #3337

ddunbar opened this issue May 9, 2018 · 20 comments · Fixed by #3913
Assignees
Labels
Milestone

Comments

@ddunbar
Copy link

ddunbar commented May 9, 2018

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

I tested with Envoy trunk on macOS, using f95269d.

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 mattklein123 added this to the 1.7.0 milestone May 9, 2018
@mattklein123
Copy link
Member

@ggreenway

@ggreenway
Copy link
Contributor

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

@ggreenway
Copy link
Contributor

#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 ggreenway changed the title Crash with WebSockets enabled, in ConnectionImpl::onMessageBeginBase Crash in ConnectionImpl::onMessageBeginBase May 10, 2018
@ggreenway
Copy link
Contributor

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
Copy link
Member

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

@htuch
Copy link
Member

htuch commented May 10, 2018

FWIW, I have a repeater for this using #3338 and a corpus that local fuzzing discovered.

@htuch
Copy link
Member

htuch commented May 10, 2018

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_

@mattklein123 mattklein123 added the help wanted Needs help! label May 18, 2018
@llchan
Copy link

llchan commented May 30, 2018

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 mattklein123 removed the help wanted Needs help! label May 31, 2018
@mattklein123 mattklein123 self-assigned this May 31, 2018
@mattklein123
Copy link
Member

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
Copy link
Member

I've opened nodejs/http-parser#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
Copy link
Member

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
Copy link
Author

ddunbar commented Jun 5, 2018

Nice, thanks Matt!

@llchan
Copy link

llchan commented Jun 5, 2018

Yeah, thanks @mattklein123 for investigating and submitting the upstream fix. 👍

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
Copy link
Member

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

@llchan
Copy link

llchan commented Jun 5, 2018

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
Copy link
Member

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.

@alyssawilk alyssawilk modified the milestones: 1.7.0, 1.8.0 Jun 21, 2018
@llchan
Copy link

llchan commented Jul 17, 2018

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
Copy link
Member

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

@llchan
Copy link

llchan commented Jul 18, 2018

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.

mattklein123 added a commit that referenced this issue Jul 20, 2018
Requires pulling upstream http-parser fix.

Fixes #3337

Signed-off-by: Matt Klein <mklein@lyft.com>
mattklein123 added a commit that referenced this issue Jul 23, 2018
…3913)

Requires pulling upstream http-parser fix.

Fixes #3337

Signed-off-by: Matt Klein <mklein@lyft.com>
@ddunbar
Copy link
Author

ddunbar commented Jul 23, 2018

Thanks for the persistence in getting this in!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

6 participants