4

I have been getting a sizeable number of BADREQ entries in my HAProxy log (10+ per minute).

Example:

Oct 1 19:46:00 LB haproxy[19022]: 69.171.251.8:57356 [01/Oct/2018:19:46:00.903] sitename sitename/ -1/-1/-1/-1/5 400 187 - - PRNN 19/19/0/0/5 0/0 ""

Almost all of them seem to be coming from Facebook's crawler.

The crawler seems to be scraping content just fine for the most part. However, a small number of these requests are resulting in BADREQ errors.

As suggested elsewhere, I used socat to see the last error by running the following command:

sudo echo "show errors" | sudo socat unix-connect:/var/run/haproxy.stat stdio

This gave me the following output:

  invalid request
  backend mysite (#2), server <NONE> (#-1), event #127
  src 69.171.251.1:61042, session #9717, session flags 0x00000080
  HTTP msg state 26, msg flags 0x00000000, tx flags 0x00000000
  HTTP chunk len 0 bytes, HTTP body len 0 bytes
  buffer flags 0x00808002, out 0 bytes, total 517 bytes
  pending 517 bytes, wrapping at 32776, error at position 0:

  00000  \x16\x03\x01\x02\x00\x01\x00\x01\xFC\x03\x03 B\x9B\xF8\xAE\xFB=\xD7dN
  00021+ \x8D\xAD\xCCP\x99\x9C\xEEow#w\n
  00033  \xB5\x99\x16g@\x1F{\x9A5H\x00\x00\xAA\xC00\xC0,\xC0(\xC0$\xC0\x14\xC0
  00057+ \n
  00058  \x00\xA5\x00\xA3\x00\xA1\x00\x9F\x00k\x00j\x00i\x00h\x009\x008\x007
  00080+ \x006\xCC\xA9\xCC\xA8\xCC\x14\xCC\x13\xCC\xAA\xCC\x15\x00\x88\x00\x87
  00098+ \x00\x86\x00\x85\xC02\xC0.\xC0*\xC0&\xC0\x0F\xC0\x05\x00\x9D\x00=\x005
  00120+ \x00\x84\xC0/\xC0+\xC0'\xC0#\xC0\x13\xC0\t\x00\xA4\x00\xA2\x00\xA0\x00
  00141+ \x9E\x00g\x00@\x00?\x00>\x003\x002\x001\x000\x00\x9A\x00\x99\x00\x98
  00164+ \x00\x97\x00E\x00D\x00C\x00B\xC01\xC0-\xC0)\xC0%\xC0\x0E\xC0\x04\x00
  00187+ \x9C\x00<\x00/\x00\x96\x00A\xC0\x12\xC0\x08\x00\x16\x00\x13\x00\x10
  00206+ \x00\r\xC0\r\xC0\x03\x00\n
  00214  \x00\xFF\x01\x00\x01)\x00\x00\x00\x14\x00\x12\x00\x00\x0Ffb.mysite.c
  00242+ om\x00\x0B\x00\x04\x03\x00\x01\x02\x00\n
  00254  \x00\x1C\x00\x1A\x00\x17\x00\x19\x00\x1C\x00\e\x00\x18\x00\x1A\x00\x16
  00272+ \x00\x0E\x00\r\x00\x0B\x00\x0C\x00\t\x00\n
  00284  \x00\r\x00 \x00\x1E\x06\x01\x06\x02\x06\x03\x05\x01\x05\x02\x05\x03
  00302+ \x04\x01\x04\x02\x04\x03\x03\x01\x03\x02\x03\x03\x02\x01\x02\x02\x02
  00319+ \x033t\x00\x00\x00\x10\x00\x0B\x00\t\x08http/1.1\x00\x15\x00\xAE\x00
  00344+ \x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00
  00361+ \x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00
  00378+ \x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00
  00395+ \x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00
  00412+ \x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00
  00429+ \x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00
  00446+ \x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00
  00463+ \x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00
  00480+ \x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00
  00497+ \x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00
  00514+ \x00\x00\x00

I'll be honest, I have no idea how to make sense of the above!

Update: I managed to capture traffic on port 80 using tcpdump. I downloaded the capture file and opened it with WinShark.

I caught a few requests coming from Facebook IP 31.13.127.5:

10622   15.837038   31.13.127.5 MYSERVERIP TCP  66  47658 → 80 [ACK] Seq=1 Ack=1 Win=61440 Len=0 TSval=1921577847 TSecr=59275252

10701   15.848790   31.13.127.5 MYSERVERIP TCP  583 47658 → 80 [PSH, ACK] Seq=1 Ack=1 Win=61440 Len=517 TSval=1921577859 TSecr=59275252

10702   15.848846   MYSERVERIP  31.13.127.5 HTTP    253 HTTP/1.0 400 Bad request  (text/html)

10914   15.927603   31.13.127.5 MYSERVERIP  TCP 66  47658 → 80 [FIN, ACK] Seq=518 Ack=189 Win=63488 Len=0 TSval=1921577937 TSecr=59275274

10915   15.927611   MYSERVERIP  31.13.127.5 TCP 66  80 → 47658 [ACK] Seq=189 Ack=519 Win=30080 Len=0 TSval=59275294 TSecr=1921577937

12044   17.419319   31.13.127.5 MYSERVERIP  TCP 74  53712 → 80 [SYN] Seq=0 Win=61320 Len=0 MSS=1460 SACK_PERM=1 TSval=1921579431 TSecr=0 WS=2048

12045   17.419337   MYSERVERIP  31.13.127.5 TCP 74  80 → 53712 [SYN, ACK] Seq=0 Ack=1 Win=28960 Len=0 MSS=1460 SACK_PERM=1 TSval=59275667 TSecr=1921579431 WS=128

12125   17.493182   31.13.127.5 MYSERVERIP  TCP 66  53712 → 80 [ACK] Seq=1 Ack=1 Win=61440 Len=0 TSval=1921579505 TSecr=59275667

12126   17.501269   31.13.127.5 MYSERVERIP  TCP 583 53712 → 80 [PSH, ACK] Seq=1 Ack=1 Win=61440 Len=517 TSval=1921579513 TSecr=59275667

12127   17.501387   MYSERVERIP  31.13.127.5 HTTP    253 HTTP/1.0 400 Bad request  (text/html)

12179   17.576974   31.13.127.5 MYSERVERIP  TCP 66  53712 → 80 [FIN, ACK] Seq=518 Ack=189 Win=63488 Len=0 TSval=1921579589 TSecr=59275687
Wayne
  • 73
  • 1
  • 11

1 Answers1

3

What you see in that log is a TLS Client Hello message.

That is the initial message sent by the client to initiate the negotiation, consequently there is nothing encrypted in that message. You'll notice there are two fields in that message which contains text. Those are the SNI (server name indication) and the ALPN (application layer protocol negotiation) next protocol fields. The rest of the message is binary data and thus not as easy to read.

At that early stage of TLS the application layer protocol is not yet negotiated and session keys have not been established. The client hasn't even received a certificate that it could validate. That means there is no way the client can have sent any HTTP request yet, and with no HTTP request there isn't anything to send a status code in response to.

The log entry surely sounds like HAProxy thinks it is responding to an HTTP request, even though none has been sent.

From that it sounds like what is happening here is that the server is speaking HTTP and the client is speaking HTTPS. The TLS Client Hello message is thus being misinterpreted as an HTTP request and rejected as invalid.

It would be useful for you to capture the traffic such that it can be inspected to find out what is actually being sent on the wire. If I am right about the above you should see a TLS Client Hello that can be decoded using Wireshark (or similar) and an unencrypted HTTP response with the 400 error code.

What's also going to be interesting about that packet capture will be the port number.

One way what you see could have happened is if a user has entered a URL with protocol and port number such as https://example.com:80/ and facebook is trying to retrieve that URL repeatedly (as it keeps failing).

I tried to put such a malformed URL into facebook myself, and sure enough facebook sent a Client Hello message to port 80. My (Apache) web server responded with a 400 status code as expected.

Your packet capture confirms that the traffic in your case is also happening on port 80. So presumably somebody have given facebook a https URL pointing to your site and overriding the correct port number with 80 instead.

Your server is correctly responding with a 400 code and facebook realize that fetching the URL has failed. There isn't anything to fix. Your server is working as intended, and the only problem was a user error when entering the URL into facebook.

It is possible to find out a bit more about the faulty URL by having your server auto detect the protocol in order to support both HTTP and HTTPS on the same port. However I wouldn't recommend such hacks, and I don't know if any web server software supports it.

kasperd
  • 30,455
  • 17
  • 76
  • 124
  • Thanks for your reply! I spent the past few hours trying to setup Wireshark on my local Windows machine to capture traffic on my remote server, to no avail. I have tshark and tcpdump installed on the server in question. What kind of command should I run? I tried capturing everything on port 80 but there's a lot there and I don't have too much knowledge about this kind of stuff. – Wayne Oct 29 '18 at 09:28
  • Here is an example of a `tcpdump` command that you could use `tcpdump -pni eth0 'net 69.171.224.0/19' -s0 -Uw 933521.pcap`. It will capture traffic until you press ctrl-c saving it to a file named `933521.pcap`. You can download the file and load it into Wireshark to inspect it further. – kasperd Oct 29 '18 at 09:35
  • @Wayne The meaning of the flags is as follows: `-p` don't use promiscuous mode, only capture what the server would already see. `-n` don't do DNS queries for all the IP addresses seen in the capture. `-i eth0` specify an interface to capture from, will need to be changed if the interface isn't named `eth0`. `'net 69.171.224.0/19'` tells `tcpdump` which traffic you are interested in. `-s0` capture full packets without truncation. `-U` flush after each packet so you can download the file while `tcpdump` is running. `-w 933521.pcap` write packets to the named file. – kasperd Oct 29 '18 at 09:38
  • Hi @kasperd. Thank you very much. After I responded to you, I went off and played around with tcpdump. I managed to capture some traffic from a Facebook IP that received a 400 Bad Request. I have added that info to my post. – Wayne Oct 29 '18 at 10:22
  • @Wayne I have updated my answer. There isn't anything for you to fix on your server. The 400 status code is indeed the correct response in this case. The root cause appears to be user error. – kasperd Oct 29 '18 at 10:41
  • Hi kasperd, thank you for your answer. I will award that bounty when Server Fault allows me to (it says I have to wait to hours). These seem to be coming in at a rate of every 2-3 seconds. Surely there weren't enough of this kind of mistake to result in so many requests? I switched to HTTPS a couple of months ago. I have a theory that this has something to do with FB re-crawling content that was originally shared as plain HTTP. – Wayne Oct 29 '18 at 10:54
  • @Wayne Do you have a redirection from http to https? And could that redirection possibly be redirecting to https URLs with a port number? Could you accidentally have made `http://example.com:80/` redirect to `https://example.com:80/`? – kasperd Oct 29 '18 at 11:07
  • I just tried that and it seems that my load balancer will redirect `http://example.com:80/img/example.png` to `https://example.com:80/img/example.png` - I have no idea how to go about preventing that though. I've never specified port 80 in any of my URLs, unless this is something that FB has decided to do. – Wayne Oct 29 '18 at 11:14
  • I disabled the HTTPS redirect for the affected subdomains, yet the errors still continue to roll in. – Wayne Oct 29 '18 at 11:20
  • @Wayne The invalid URLs may have been cached. – kasperd Oct 29 '18 at 11:21