Fasthttp: Ridiculously large headers cause connection to be reset without response

[oschwald]

This happens when the headers exceed the ReadBufferSize. Rather than resetting the connection, it would be nice if the server responded with a 413 Entity Too Large and did not log an error.

Site and name have been changed to protect the guilty.

fasthttp/workerpool.go:215: error when serving connection "127.0.0.1:13010"<->"127.0.0.1:42518": error when reading request headers: need more data: cannot find trailing lf. buf="GET /test HTTP/1.1\nHost: nottest.com\nUser-Agent: Mozilla/5.0 (Linux; Android 6.0.1; SM-G930V Build/MMB29M) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/53.0.2785.124 Mobile Safari/537.36\nReferer: htt"...".test.org%2Ftest-power-and-forces%2Ftest-force-lookup%2Ftest-dark-side%2Fstar-wars-resources-and-videos%2Fvideos%2Fstar-wars-new-hope.html%3FLordVaderSaber%2BVideo&h=sAQFArwyt?referrer=http://www.test"

Request:

GET /test HTTP/1.1
Host: nottest.com
user-agent: Mozilla/5.0 (Linux; Android 6.0.1; SM-G930V Build/MMB29M) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/53.0.2785.124 Mobile Safari/537.36
referer: http://www.test.org/test-power-and-forces/test-force-lookup/test-dark-side/star-wars-resources-and-videos/videos/star-wars-new-hope.html?LordVaderSaber%20Video?referrer=http://lm.facebook.com/l.php?u=http%3A%2F%2Fwww.test.org%2Ftest-power-and-forces%2Ftest-force-lookup%2Ftest-dark-side%2Fstar-wars-resources-and-videos%2Fvideos%2Fstar-wars-new-hope.html%3FLordVaderSaber%2BVideo&h=sAQFArwyt?referrer=http://www.test.org/test-power-and-forces/test-force-lookup/test-dark-side/star-wars-resources-and-videos/videos/star-wars-new-hope.html?LordVaderSaber%20Video?referrer=http://www.test.org/test-power-and-forces/test-force-lookup/test-dark-side/star-wars-resources-and-videos/videos/star-wars-new-hope.html?LordVaderSaber%20Video?referrer=http://lm.facebook.com/l.php?u=http%3A%2F%2Fwww.test.org%2Ftest-power-and-forces%2Ftest-force-lookup%2Ftest-dark-side%2Fstar-wars-resources-and-videos%2Fvideos%2Fstar-wars-new-hope.html%3FLordVaderSaber%2BVideo&h=sAQFArwyt?referrer=http://www.test.org/test-power-and-forces/test-force-lookup/test-dark-side/star-wars-resources-and-videos/videos/star-wars-new-hope.html?LordVaderSaber%20Video?referrer=http://lm.facebook.com/l.php?u=http%3A%2F%2Fwww.test.org%2Ftest-power-and-forces%2Ftest-force-lookup%2Ftest-dark-side%2Fstar-wars-resources-and-videos%2Fvideos%2Fstar-wars-new-hope.html%3FLordVaderSaber%2BVideo&h=sAQFArwyt?referrer=http://www.test.org/test-power-and-forces/test-force-lookup/test-dark-side/star-wars-resources-and-videos/videos/star-wars-new-hope.html?LordVaderSaber%20Video?referrer=http://www.test.org/test-power-and-forces/test-force-lookup/test-dark-side/star-wars-resources-and-videos/videos/star-wars-new-hope.html?LordVaderSaber%20Video?referrer=http://lm.facebook.com/l.php?u=http%3A%2F%2Fwww.test.org%2Ftest-power-and-forces%2Ftest-force-lookup%2Ftest-dark-side%2Fstar-wars-resources-and-videos%2Fvideos%2Fstar-wars-new-hope.html%3FLordVaderSaber%2BVideo&h=sAQFArwyt?referrer=http://www.test.org/test-power-and-forces/test-force-lookup/test-dark-side/star-wars-resources-and-videos/videos/star-wars-new-hope.html?LordVaderSaber%20Video?referrer=http://www.test.org/test-power-and-forces/test-force-lookup/test-dark-side/star-wars-resources-and-videos/videos/star-wars-new-hope.html?LordVaderSaber%20Video?referrer=http://lm.facebook.com/l.php?u=http%3A%2F%2Fwww.test.org%2Ftest-power-and-forces%2Ftest-force-lookup%2Ftest-dark-side%2Fstar-wars-resources-and-videos%2Fvideos%2Fstar-wars-new-hope.html%3FLordVaderSaber%2BVideo&h=sAQFArwyt?referrer=http://www.test.org/test-power-and-forces/test-force-lookup/test-dark-side/star-wars-resources-and-videos/videos/star-wars-new-hope.html?LordVaderSaber%20Video?referrer=http://lm.facebook.com/l.php?u=http%3A%2F%2Fwww.test.org%2Ftest-power-and-forces%2Ftest-force-lookup%2Ftest-dark-side%2Fstar-wars-resources-and-videos%2Fvideos%2Fstar-wars-new-hope.html%3FLordVaderSaber%2BVideo&h=sAQFArwyt?referrer=http://www.test.org/test-power-and-forces/test-force-lookup/test-dark-side/star-wars-resources-and-videos/videos/star-wars-new-hope.html?LordVaderSaber%20Video?referrer=http://www.test.org/test-power-and-forces/test-force-lookup/test-dark-side/star-wars-resources-and-videos/videos/star-wars-new-hope.html?LordVaderSaber%20Video?referrer=http://lm.facebook.com/l.php?u=http%3A%2F%2Fwww.test.org%2Ftest-power-and-forces%2Ftest-force-lookup%2Ftest-dark-side%2Fstar-wars-resources-and-videos%2Fvideos%2Fstar-wars-new-hope.html%3FLordVaderSaber%2BVideo&h=sAQFArwyt?referrer=http://www.test.org/test-power-and-forces/test-force-lookup/test-dark-side/star-wars-resources-and-videos/videos/star-wars-new-hope.html?LordVaderSaber%20Video?referrer=http://lm.facebook.com/l.php?u=http%3A%2F%2Fwww.test.org%2Ftest-power-and-forces%2Ftest-force-lookup%2Ftest-dark-side%2Fstar-wars-resources-and-videos%2Fvideos%2Fstar-wars-new-hope.html%3FLordVaderSaber%2BVideo&h=sAQFArwyt?referrer=http://www.test.org/test-power-and-forces/test-force-lookup/test-dark-side/star-wars-resources-and-videos/videos/star-wars-new-hope.html?LordVaderSaber%20Video

[mmacdermaid]

@oschwald thank you for opening the issue. We have a large amount of data being passed around in headers and I originally was looking into the code as I thought there might be a bug and it sent me down a rabbit hole I probably didn't need to be in.

error when reading request headers: need more data: cannot find trailing lf.

Isn't exactly a great error, so it lead me to both these sections of code firing all the time on our requests.

    n := bytes.IndexByte(s.b, ':')
    if n < 0 {
        s.err = errNeedMore
        return false
    }

and

    n = bytes.IndexByte(s.b, '\n')
    if n < 0 {
        s.err = errNeedMore
        return false
    }

Both are returning errNeedMore on the requests that are too large, and it doesn't make sense because the headers we are dealing with as far as I have known for years now are properly formed, and I couldn't find anything wrong with raw requests when peeking at them.

Upping the defaultReadBufferSize = 4069 to an appropriate amount has stopped these errors from spamming my logs.

[valyala]

Agreed with @oschwald - the server should return 413 Entity Too Large instead of just silently closing the connection. Will look into this.

@mmacdermaid correctly proposed a workaround for big headers - increasing Server.ReadBufferSize value, since by default request header size is limited by 4Kb.

[mmacdermaid]

@valyala I've been testing the header sizes over the last few days and I've found some interesting things. Right now I'm running a binary with the header size at

defaultReadBufferSize  = 131072

(2 ^17) which is insane for a maximum header size. This size should be way over the maximum amount of data we are putting in headers

and I still have logs with

 error when serving connection "IP"<->"IP": error when reading request headers: need more data: cannot find trailing lf.

I started doing an ioutil.ReadAll(r) on the r *bufio.Reader right before that error (https://github.com/valyala/fasthttp/blob/master/header.go#L1331) , and outputting it's entire contents, since the buffered peek you are doing shows start-end

Sometimes I'm getting weird results with just

GET / HTTP/1.1
User-Agent: fasthttp

(we don't have any GET requests coming to that endpoint, it is all POST)

Sometimes it's just a single letter (I assume the P in POST)

P 

Then other times I will actually see a request that is one of ours (H1-H6 actually have names I've just scrubbed some data)

POST / HTTP/1.1
Host: thehost
User-Agent: Go-http-client/1.1
Content-Length: 1595
Connection: keep-alive
Content-Type: application/json
H1: 39485739847593
H2: fosjdfsdf-asd3242-as
H3: 4
H4: asd=1;sdf=2
H5: 1477065183024
H6: 101248,100426,100719,101373,100073,100616,100199,100611,100571,101328,100033,100227,100593,101037,100803,100906,101443,100475,101267,101325,100648,100494,101111,100132,100409,100731,100153,100901,100356,101138,100960,100991,100912,100488,101073,100743,100954,100749,100759,100708,101086,100739,100664,100360,100204,100989,100399,101078,100632,101242,100718,100935,101234,100344,100727,101210,100917,100455,101126,100587,100890,100760,100751,101010,100309,100213,100342,100024,100054,100231,100110,100368,100818,100376,100812,100713,100051,101473,100807,100816,101477,101472,100817,100036,100247,100660,100663,100594,101000,100083,101080,100104,100375,100303,100983,100208,100048,100904,101361,100412,100599,100293,100278,101075,101427,101098,100497,101350,101170,100271,101332,100956,101355,101458,101465,101376,101439,101415,101060,101420,100410,101419,100768,100933,100742,101244,101280,101457,100514,101393,101391,101154,101287,100156,100754,100750,101091,100323,101446,101102,101411,100146,101329,101259,100920,101356,100100,100626,101303,101369,100763,101404,101333,101 

Then the length will always be 1448 and it looks like it stops reading there (or there isn't more to read?!?). Could this be a connection being closed while you are reading off of it? (It seems unlikely since the read length is always 1448).

I can't find a defaultReadBufferSize that stops every log from happening, regardless of the actual size of our headers even though they are much less than 2^20 which also sees these logs. I've tried almost every iteration of power of two for header size all the way up to 2^20

This makes me think there might actually be bug somewhere, but I can't find anything that stands out.

Thoughts?

[ghost]

@mmacdermaid Can you try rename your header's names to X-H1, X-H2, X-H3, X-H4, X-H5, X-H6 and try to reproduce the error again?

[mmacdermaid]

@kataras They are named X- the actual value.

An example that I could expose is

X-Mm-Exch-Id: 4

[valyala]

@mmacdermaid , now fasthttp server returns valid http response instead of just silently closing connection on request parsing errors.

The error log message now contains the amount of data read from the client additionally to head and tail request header snippets. This may help in finding the root cause of the issue.

[mmacdermaid]

@valyala Awesome. I will rebuild a version with fast http when I get a chance and deploy it to see what I can come up with. Thanks for the support.

[oschwald]

Thanks!

[mmacdermaid]

2016/11/13 22:53:31 error when serving connection "10.200.168.19:9090"<->"10.200.168.10:23058": error when reading request headers: small read buffer. Increase ReadBufferSize. Buffer size=65536, contents: "POST / HTTP/1.1\r\nHost: <MyHost>\r\nUser-Agent: Go-http-client/1.1\r\nContent-Length: 4901\r\nConnection: keep-alive\r\nContent-Type: application/json\r\nX-Mm-1: 739214049155986"..."6:0.507003,1693896:0.507003,1693896:0.507003,1693896:0.507003,1693896:0.507003,1693896:0.507003,1693896:0.507003,1693896:0.507003,1693896:0.507003,1693896:0.507003,1693896:0.507003,1693896:0.507003,16"
2016/11/13 23:40:08 error when serving connection "10.200.168.19:9090"<->"10.200.168.13:19799": error when reading request headers: small read buffer. Increase ReadBufferSize. Buffer size=65536, contents: "POST / HTTP/1.1\r\nHost: <MyHost>\r\nUser-Agent: Go-http-client/1.1\r\nContent-Length: 4713\r\nConnection: keep-alive\r\nContent-Type: application/json\r\nX-Mm-1: 800977894746277"...":0.865171,1709039:0.865171,1709039:0.865171,1709039:0.865171,1709039:0.865171,1709039:0.865171,1709039:0.865171,1709039:0.865171,1709039:0.865171,1709039:0.865171,1709039:0.865171,1709039:0.865171,170"
2016/11/14 00:11:24 error when serving connection "10.200.168.19:9090"<->"10.200.168.17:44778": error when reading request headers: small read buffer. Increase ReadBufferSize. Buffer size=65536, contents: "POST / HTTP/1.1\r\nHost: <MyHost>\r\nUser-Agent: Go-http-client/1.1\r\nContent-Length: 4954\r\nConnection: keep-alive\r\nContent-Type: application/json\r\nX-Mm-1: 546850687642211"..."400,1518584:0.697400,1518584:0.697400,1518584:0.697400,1518584:0.697400,1518584:0.697400,1518584:0.697400,1518584:0.697400,1518584:0.697400,1518584:0.697400,1518584:0.697400,1518584:0.697400,1518584:0"

These are the most recent messages with the new build.

65536 is pretty insane for a header size already. We have big headers. Stuff like this floating around.

"X-Mm-1": "101248,100426,100719,101373,100073,100616,100199,100611,100571,101328,100033,100227,100593,101037,100906,101443,100475,101267,101325,100648,100494,101111,100132,100731,100153,100901,100356,101138,100960,100991,100912,100488,101073,100743,100954,100749,100759,100708,101086,100739,100664,100360,100204,100989,100399,101078,100632,101242,100718,100935,101234,100344,100727,101210,100917,101126,100587,100890,100760,100751,101010,100309,100213,100342,100024,100054,100110,100368,100818,100376,100812,100713,100051,101473,100807,100816,101477,101472,100817,100036,100247,101432,101000,100083,101080,100104,100375,100303,100983,100208,100048,100904,101361,100412,100599,100293,100278,101075,101427,101098,100497,101350,101170,100271,101332,100956,101355,101458,101465,101376,101439,101415,101060,101420,101476,100410,100768,100933,100742,101244,101280,101457,100514,101393,101391,101154,101287,100156,100754,100750,101091,100323,101446,101102,101411,100146,101329,101489,101259,100920,101356,100100,100626,101303,101369,100763,101404,101449,101333,101399,101405,100757,101408,101261,100984,100169,101414,100413,101224,100672,100826,101286,100128,101379,101334,100645,101413,101426,101241,100781,101258,101269,100226,101421,101422,100476,100922,101255,100195,101320,101450,100618,101368,101277,101410,100580,100794,100232,100283,100741,100242,101220,100355,101285,101481,101135,101412,100955,101187,100871,100573,101378,101262,101407,101433,101406,101146,101403,101239,100431,101281,101276,101448,101183,101040,100401,100877,101240,100802,101416,101114,101315,100733,101136,101387,100592,100221,101165,101292,101251,101291,101360,101307,101266,101351,0,101294,101340,101314,101245,101228,101313,101306,101341,101342,101346,101343,101257,101288,100072,101367,101345,101339,101310,101263,101279"

But still, we're talking length of 3-4k, not 65k.

Was built with head being at 89fe89ae7451443b184bf5796e11ff0e4e5480d1

[erikdubbelboer]

Closed due to age.