function_clause in cowboy_protocol:parse_method/2 #448

Open
asabil opened this Issue Feb 25, 2013 · 43 comments

Comments

Projects
None yet
Contributor

asabil commented Feb 25, 2013

I see many of these errors in production:

Supervisor {<0.1285.0>,ranch_conns_sup} had child exit
with reason no function clause matching
cowboy_protocol:parse_method(<<>>, {state,#Port<0.148433938>,ranch_tcp...})

I tried to track this further, but couldn't make much sense of it. so I ended up adding the following clause:

parse_method(_, State, _SoFar) ->
    error_terminate(400, State).

This occurs with cowboy 0.8.1

Owner

essen commented Feb 25, 2013

I see similar with parse_uri_fragment when running ct tests sometimes but never managed to understand why yet.

Contributor

asabil commented Feb 25, 2013

Another one:

{function_clause,[{cowboy_protocol,parse_uri_path,[<<0 bytes>>,{state,#Port<0.40691452>,ranch_tcp,[cowboy_router,cowboy_handler],true,
Owner

essen commented Feb 25, 2013

Saw that one sometimes too.

Owner

essen commented Feb 26, 2013

I can reproduce if I do something like send "GET\n" or "GET /#\n" or similar. Do you think this is what happens?

Contributor

asabil commented Feb 26, 2013

I doubt that, I see it way too often in production for it to be because of an invalid HTTP request.

Owner

essen commented Mar 2, 2013

The tests will run all night. I'll see tomorrow morning if I get more details on what's happening exactly.

Owner

essen commented Mar 2, 2013

Tests ran all night. Not a single of these failures. That's odd, it happens fairly more often on my laptop than on the machine I used there. Perhaps it only does that on some systems?

Contributor

dergraf commented Mar 26, 2013

Out of stupidity I accidentally made an https request to a cowboy instance that isn't serving https. Since my request URI uses host:port the request went through and caused the identical behavior.

Contributor

asabil commented Mar 28, 2013

I haven't been able to reproduce this with the described method in my environment, could you please verify which version of cowboy/ranch you are running?

Contributor

dergraf commented Mar 28, 2013

it is cowboy tag 0.8.1

Owner

essen commented Apr 25, 2013

Anyone managed to find anything more on this?

Contributor

asabil commented Apr 26, 2013

Unfortunately not, I still see the error in the logs over both plain tcp and ssl

Contributor

dergraf commented Apr 26, 2013

Sorry, no news on that one as well.
Am 26.04.2013 08:46 schrieb "Ali Sabil" notifications@github.com:

Unfortunately not, I still see the error in the logs over both plain tcp
and ssl


Reply to this email directly or view it on GitHubhttps://github.com/extend/cowboy/issues/448#issuecomment-17057936
.

Contributor

asabil commented Nov 26, 2013

I think I might have found something here. It looks like this is caused by some web browsers trying to use spdy/2 to connect to the server

I am unsure if this is related, but I have been investigating why cowboy_req:method(Req) sometimes returns {<<>>, _} causing a bad match when matching against {<<"POST">>, _} within middleware.

Are there known conditions by which the method is set to <<>>?

Owner

essen commented Oct 3, 2014

Maybe if the request is " / HTTP/1.1" it will accept the method as <<>>. If true this needs to be fixed, but is unrelated to this ticket.

Owner

essen commented Oct 3, 2014

There is indeed an issue like this, I will fix it now.

Owner

essen commented Oct 3, 2014

This particular issue is now fixed.

Excellent, thanks for fixing & clarifying.

Contributor

okeuday commented Oct 4, 2014

Thanks, I saw the parse_uri_path issue too.

lpgauth commented Oct 6, 2014

I see these all the time (cowboy 1.0), I've tried reproducing by replaying a tcpdump without any luck. My hunch is that the the parse_request/3 buffer is somehow non-empty when a new keep-alive requests comes in...

I see these errors randomly in production. :-(

 {function_clause,[{cowboy_protocol,parse_method,[<<0 bytes>>,{state,#Port<0.13633640>,ranch_tcp,[cowboy_router,cowboy_handler],false,[{...

Why? So I tried to reproduce this log..., finally I got it!

Simple http client (using ruby) (cowboy server? latest version example src : $ ./_rel/echo_get_example/bin/echo_get_example console)

# simple_http_request.rb
require 'socket'

host = '127.0.0.1'
port = 8080

s = TCPSocket.open host, port
s.puts "GE"  # case 1
#s.puts "GET /123" # case 2

while line = s.gets
  puts line.chop
end

s.close

Test :
run server

$) ./_rel/echo_get_example/bin/echo_get_example console

run http request client

$) ruby ./simple_http_request.rb

Result:
case 1

=ERROR REPORT==== 9-Mar-2015::18:20:06 ===
Error in process <0.160.0> on node 'echo_get_example@127.0.0.1' with exit value: {function_clause,[{cowboy_protocol,parse_method,[<<0 bytes>>,{state,#Port<0.496>,ranch_tcp,[cowboy_router,cowboy_handler],false,[{listener,http},{dispatch,[{'_',[],[{[],[],toppage_handler,[]}]}]}],undefined,undefined,5,1,100,4096,64,4096,100,5000,1425892811771},<<3 bytes>>],[{file,"src/co...


=ERROR REPORT==== 9-Mar-2015::18:20:06 ===
Ranch listener http had connection process started with cowboy_protocol:start_link/4 at <0.160.0> exit with reason: {function_clause,[{cowboy_protocol,parse_method,[<<>>,{state,#Port<0.496>,ranch_tcp,[cowboy_router,cowboy_handler],false,[{listener,http},{dispatch,[{'_',[],[{[],[],toppage_handler,[]}]}]}],undefined,undefined,5,1,100,4096,64,4096,100,5000,1425892811771},<<"GE\n">>],[{file,"src/cowboy_protocol.erl"},{line,168}]}]}

case 2

=ERROR REPORT==== 9-Mar-2015::18:23:31 ===
Error in process <0.161.0> on node 'echo_get_example@127.0.0.1' with exit value: {function_clause,[{cowboy_protocol,parse_uri_path,[<<0 bytes>>,{state,#Port<0.511>,ranch_tcp,[cowboy_router,cowboy_handler],false,[{listener,http},{dispatch,[{'_',[],[{[],[],toppage_handler,[]}]}]}],undefined,undefined,5,1,100,4096,64,4096,100,5000,1425893016611},<<3 bytes>>,<<5 bytes>>],[{file,"src...


=ERROR REPORT==== 9-Mar-2015::18:23:31 ===
Ranch listener http had connection process started with cowboy_protocol:start_link/4 at <0.161.0> exit with reason: {function_clause,[{cowboy_protocol,parse_uri_path,[<<>>,{state,#Port<0.511>,ranch_tcp,[cowboy_router,cowboy_handler],false,[{listener,http},{dispatch,[{'_',[],[{[],[],toppage_handler,[]}]}]}],undefined,undefined,5,1,100,4096,64,4096,100,5000,1425893016611},<<"GET">>,<<"/123\n">>],[{file,"src/cowboy_protocol.erl"},{line,200}]}]}

Is above tests helpful to fix this issue?

Owner

essen commented Mar 9, 2015

I don't know what language it is written in or what it does exactly.

@snaiper80 I was able to replicate both of those errors on my app with your script. I found the first error in the logs for my app earlier today. Google returned this page in search results when I searched for terms appearing in the error.

@essen @snaiper80's Ruby script opens a TCP connection on port 8080 to 127.0.0.1 and sends the string "GE" over the connection (using Ruby's IO.puts). It then calls gets on the connection to retrieve the response. Then it closes the connection. So the script is basically sending a very malformed HTTP request to the server.

I am trying to re-create the error with an Erlang script. If I successfully re-create the error I will post the script here.

Got it! This Erlang code is equivalent to @snaiper80's Ruby script:

-module(simple_http_request).

-export([test/0]).

test() ->
    send_malformed_request("localhost", 8080).

send_malformed_request(Server, Port) when is_integer(Port) ->
    {ok, Socket} = gen_tcp:connect(Server, Port, [binary, {packet, 0}, {active, false}]),
    ok = gen_tcp:send(Socket, "GE\n"), % snaiper80's case 1
    %ok = gen_tcp:send(Socket, "GET /123\n"), % snaiper80's case 2
    {ok, Bin} = do_receive(Socket, []),
    ok = gen_tcp:close(Socket),
    Bin.

do_receive(Socket, Bs) ->
    case gen_tcp:recv(Socket, 100) of
        {ok, B} ->
            do_receive(Socket, [Bs, B]);
        {error, Error} ->
            erlang:display(Error),
            {ok, list_to_binary(Bs)}
    end. 
Owner

essen commented Apr 21, 2015

Right. Please see the beginning of the ticket though, we think there is a bug that occurs on normal requests.

As for these cases in particular they should be fixed once all rfc7230 tests are added and the fixes are written for them.

I was able to replicate this error by doing what @dergraf did. I tried using HTTPS to access a HTTP cowboy server. I consistently got the error in cowboy_protocol:parse_method/2.

Owner

essen commented May 15, 2015

Sounds like a way to trigger the crash, but doesn't explain the initial issue. Anyway I will fix the cases where input is bad so that it doesn't crash.

lpgauth commented May 15, 2015

But... let it crash :)

Owner

essen commented May 15, 2015

Sure but "don't pollute the logs" is also true.

lpgauth commented May 15, 2015

@essen I'm just trolling. I reported the same issue on twitter about a year ago and you said it was expected to crash on bad input :)

Owner

essen commented May 15, 2015

Twitter, IRC or even real life chat have no value, only tickets matter. And this ticket highlights a common problem of crashes creating unnecessary logs. So we're going to solve that, and then hope for the best that that's all it was.

lpgauth commented May 15, 2015

FYI, we had the same issue which was caused by reading the body of the cowboy:req() in a different process then the one replying, but not passing back the updated cowboy:req(). The was therefore a state mismatch since the socket is mutable, but not the cowboy:req().

Owner

essen commented May 15, 2015

Yeah. The thing I wonder however is how we can get <<>> in the place the original report talks about. Hence my belief that maybe there's a second separate issue.

Contributor

ferd commented May 15, 2015

We do generate that kind of exception thousands of times a day here. Reading the code I just assumed it was due to incomplete requests, clients sending garbage down the line after a response or whatever, clients getting disconnected between packets for some reason.

It'd be interesting if it were something else, but I'd guess we'd need to keep a buffer of what's been parsed so far to know what it looks like.

One example would have been Trailers after some chunked encodings, especially if unanounced or something, which would be ignored (does mainline Cowboy support trailers yet?) and left over the line.

Owner

essen commented May 15, 2015

Yeah. Whatever it is, I will work on that part on Monday. I may or may not already have tests in place to cover it.

I am seeing a lot of these cowboy errors in my tsung tests, as for me these look to be load related, @ferd might be pointing us in the right direction here...

essen added the Bug label Aug 15, 2015

Owner

essen commented Mar 4, 2016

Randomly came across this issue again, by using https on an http listener. Could repeat and trace.

The reason it crashes is because the request is invalid, of course, but more precisely because when we receive data we look for \n to know we have the whole line, and then the functions parsing the different parts of the request-line look for their own delimiters, like \s. If there's a \n but no \s, or if there's a \n but not an \r\n, or similar cases, it will crash and make a lot of noise at the same time.

At this point in the connection we should close the connection without logging errors if the request is obviously wrong. Note that my current set of changes for Cowboy 2 already have some things in that direction but probably not covering all cases yet. Feedback will be important in getting rid of all these unnecessary logs.

The other changes and additions to Cowboy 2 (including trailers and removing the ability to mess up the Req object and the connection flow entirely) should rule out any other possible issue.

essen added this to the 2.0 Tasks milestone Feb 4, 2017

If you add a % to the end of a request it will also generate this error:

[error] Ranch protocol #PID<0.654.0> (:cowboy_protocol) of listener HelloPhoenix.Endpoint.HTTP terminated
** (exit) an exception was raised:
** (FunctionClauseError) no function clause matching in :cow_uri.urldecode/2
(cowboy) /cowboy/src/cow_uri.erl:26: :cow_uri.urldecode("%", "he")
(cowboy) /cowboy/src/cowboy_router.erl:331: :cowboy_router."-split_path/2-lc$^1/1-1-"/1
(cowboy) /cowboy/src/cowboy_router.erl:331: :cowboy_router.split_path/2
(cowboy) /cowboy/src/cowboy_router.erl:271: :cowboy_router.match_path/4
(cowboy) /cowboy/src/cowboy_router.erl:169: :cowboy_router.execute/2
(cowboy) /cowboy/src/cowboy_protocol.erl:442: :cowboy_protocol.execute/4

Owner

essen commented Feb 17, 2017

That's not related to this ticket.

macpie commented Mar 29, 2017

Using Cowboy 1.0.2, I am seeing this:

2017-03-23 00:00:27.675 [error] emulator Error in process <0.2046.2> on node 'some_app@127.0.0.1' with exit value:
{{badmatch,{error,badarg}},[{cowboy_req,body,2,[{file,"src/cowboy_req.erl"},{line,510}]},{cowboy_protocol,next_request,3,[{file,"src/cowboy_protocol.erl"},{line,480}]}]}
2017-03-23 00:00:27.675 [error] <0.2046.2> Ranch listener https terminated with reason: no match of right hand value {error,badarg} in cowboy_req:body/2 line 510
2017-03-23 00:00:37.570 [error] <0.2956.2> SSL: hello: tls_handshake.erl:174:Fatal error: protocol version
2017-03-23 00:00:55.003 [error] emulator Error in process <0.4049.2> on node 'some_app@127.0.0.1' with exit value:
{function_clause,[{cowboy_protocol,parse_method,[<<>>,{state,{sslsocket,{gen_tcp,#Port<0.36136>,tls_connection,<0.313.0>},<0.4048.2>},ranch_ssl,[cowboy_router,cowboy_handler],false,[{listener,https},{dispatch,[{'_',[],[{[<<"websocket">>],[],some_app_ws_handler,[]},{[],[],cowboy_static,{priv_file,some_app,"static/index.html"}},{[<<"...">>],[],cowboy_http_static,[{directory,{priv_dir,some_app,[]}},{mimetypes,[{<<".css">>,[<<"text/css">>]},{<<".js">>,[<<"application/javascript">>]},{<<".json">>,[<<"application/json">>]},{<<".html">>,[<<"text/html">>]}]}]}]}]}],undefined,undefined,5,1,100,4096,64,4096,100,5000,1490227259881},<<"id\n">>],[{file,"src/cowboy_protocol.erl"},{line,168}]}]}
2017-03-23 00:00:55.003 [error] <0.4049.2> Ranch listener https terminated with reason: no function clause matching cowboy_protocol:parse_method(<<>>, {state,{sslsocket,{gen_tcp,#Port<0.36136>,tls_connection,<0.313.0>},<0.4048.2>},ranch_ssl,[cowboy_router,...],...}, <<"id\n">>) line 168
2017-03-23 00:00:55.693 [error] <0.4073.2> SSL: hello: tls_handshake.erl:174:Fatal error: protocol version
2017-03-23 00:00:56.210 [error] <0.4107.2> SSL: certify: tls_record.erl:215:Fatal error: bad record mac
...

I am not sure, but is this related to this ticket?

Owner

essen commented Mar 30, 2017

One of them is, possibly.

macpie commented Mar 31, 2017

ok thanks, I will try with 2.0

Nagasaki45 referenced this issue in Nagasaki45/krihelinator Apr 8, 2017

Open

Research cowboy failures in logs #147

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment