HTTP: редиректы, POST и GET запросы, и “потерянные” данные

Автор: | 23/11/2019
 

Имеется приложение, которое должно принимать данные через POST-запросы от клиентов.

Перед этим приложением имеется некий прокси, не важно какой – AWS Application Load Balancer, NGINX или любой другой. Мы изначально столкнулись с проблемой на AWS ALB, потом я начал тестить на NGINX, что бы искючить влияение самого AWS-сервиса – воспроизводится везде, т.к. не зависит от проксирующей службы.

Прокси помимо проксирования трафика к приложению выполняет редирект с HTTP (80) на HTTPS (443).

Собственно, проблема возникает именно во время такого редиректа:

  1. клиент отправляет POST по HTTP
  2. прокси возвращает клиенту редирект 301 или 302 на HTTPS
  3. клиент отправляет запрос на HTTPS, но:
    1. либо запрос превращается в GET
    2. либо он остаётся POST, но все данные после редиректа “пропадают”

Setup – тестовая площадка

Для тестирования будем использовать следующий сетап:

  1. на входе API-запросы принимаются NGINX
  2. NGINX через proxy_pass по HTTP передаёт запрос бекенду
    • в роли бекенда используем Go-приложение в Docker-контейнере, что бы воспроизвести проблему с POST, который превращается в GET
    • и Python-приложение, что бы воспроизвести проблему с “потерянными” данными и пустым Сontent-length

NGINX

Тут всё совершенно стандартно – обычный NGINX, который принимает соединения на порт 80, и редиректит их на HTTPS:

server {

    listen 80;

    server_name dev.poc.example.com;

    location / {

        return 302 https://dev.poc.example.com$request_uri;
    }
}
...

И server 443 {} – тоже стандартный, с proxy_pass на бекенд, тут для тестов используем 8081:

...
server {

    listen       443 ssl;
    server_name  dev.poc.example.com;

    ...

    location / {

        proxy_pass http://localhost:8081;

        proxy_set_header Host $host;
        proxy_set_header X-Real-IP $remote_addr;
        proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
        proxy_set_header X-Forwarded-Proto $scheme;

    }
}

Go-app в Docker

Там на самом деле несколько контейнеров, нас интересует их проксирующий go-queue-consumer, в котором крутися стандартный NGINX (весь этот сетап ещё в Proof of Concept, потому не удивляйтесь количеству NGINX в этой схеме).

Нам от него интересны логи, в которых будет POST или GET.

Python web-server

И для тестирования HTTP message body – используем нагугленный Python-скрипт:

#!/usr/bin/env python3
"""
Very simple HTTP server in python for logging requests
Usage::
    ./server.py [<port>]
"""
from http.server import BaseHTTPRequestHandler, HTTPServer
import logging

class S(BaseHTTPRequestHandler):
    def _set_response(self):
        self.send_response(200)
        self.send_header('Content-type', 'text/html')
        self.end_headers()

    def do_GET(self):
        logging.info("GET request,\nPath: %s\nHeaders:\n%s\n", str(self.path), str(self.headers))
        self._set_response()
        self.wfile.write("GET request for {}".format(self.path).encode('utf-8'))

    def do_POST(self):
        content_length = int(self.headers['Content-Length']) # <--- Gets the size of data
        post_data = self.rfile.read(content_length) # <--- Gets the data itself
        logging.info("POST request,\nPath: %s\nHeaders:\n%s\n\nBody:\n%s\n",
                str(self.path), str(self.headers), post_data.decode('utf-8'))

        self._set_response()
        self.wfile.write("POST request for {}".format(self.path).encode('utf-8'))

def run(server_class=HTTPServer, handler_class=S, port=8081):
    logging.basicConfig(level=logging.INFO)
    server_address = ('', port)
    httpd = server_class(server_address, handler_class)
    logging.info('Starting httpd...\n')
    try:
        httpd.serve_forever()
    except KeyboardInterrupt:
        pass
    httpd.server_close()
    logging.info('Stopping httpd...\n')

if __name__ == '__main__':
    from sys import argv

    if len(argv) == 2:
        run(port=int(argv[1]))
    else:
        run()

Примеры – воспроизводим проблему

POST теряет данные после редиректа

Первое, с чем столкнулись, и что вообще заставило углубиться в проблему – после выполнения редиректа с HTTP на HTTPS – POST-запрос терял данные.

Т.е, обратился бекенд-разработчик, который сказал, что после редиректа на бекенд не приходят данные.

Что бы воспроизвести проблему – используем Python-скрипт, приведённый выше.

Запускаем его на порту 8081:

[simterm]

root@ip-10-0-15-118:/home/admin# ./test_post.py 8081
INFO:root:Starting httpd...

[/simterm]

Выполняем curl с POST с какими-то данными в --data:

[simterm]

$ curl -vL -X POST http://dev.poc.example.com/ -d "param1=value1&param2=value2"
...
*   Trying 52.***.***.224:80... 
...
> Content-Length: 27
...
< HTTP/1.1 302 Moved Temporarily
...
< Content-Length: 161
< Connection: keep-alive
< Location: https://dev.poc.example.com/
...
> POST / HTTP/1.1
> Host: dev.poc.example.com
> User-Agent: curl/7.67.0
> Accept: */*
> 
* Mark bundle as not supporting multiuse
< HTTP/1.1 502 Bad Gateway
< Server: nginx/1.10.3
...
< Content-Type: text/html
< Content-Length: 173

[/simterm]

Что тут происходит:

  1. POST-запрос с данными на HTTP, Content-Length: 27
  2. 302 редирект на HTTPS
  3. POST на HTTPS, Content-Length: 173

В логах NGINX видим нормальный HTTP POST:

[simterm]

...
==> /var/log/nginx/dev.poc.example.com-error.log <==
2019/11/23 09:52:41 [error] 19793#19793: *51100 upstream prematurely closed connection while reading response header from upstream, client: 194.***.***.26, server: dev.poc.example.com, request: "POST / HTTP/1.1", upstream: "http://127.0.0.1:8081/", host: "dev.poc.example.com"

==> /var/log/nginx/dev.poc.example.com-access.log <==
194.***.***.26 - - [23/Nov/2019:09:52:41 +0000] "POST / HTTP/1.1" 502 173 "-" "curl/7.67.0"
...

[/simterm]

И посмотрим stderr нашего Python-сервера:

[simterm]

...
Exception happened during processing of request from ('127.0.0.1', 38224)
Traceback (most recent call last):
  File "/usr/lib/python3.5/socketserver.py", line 313, in _handle_request_noblock
    self.process_request(request, client_address)
  File "/usr/lib/python3.5/socketserver.py", line 341, in process_request
    self.finish_request(request, client_address)
  File "/usr/lib/python3.5/socketserver.py", line 354, in finish_request
    self.RequestHandlerClass(request, client_address, self)
  File "/usr/lib/python3.5/socketserver.py", line 681, in __init__
    self.handle()
  File "/usr/lib/python3.5/http/server.py", line 422, in handle
    self.handle_one_request()
  File "/usr/lib/python3.5/http/server.py", line 410, in handle_one_request
    method()
  File "./test_post.py", line 22, in do_POST
    content_length = int(self.headers['Content-Length']) # <--- Gets the size of data
TypeError: int() argument must be a string, a bytes-like object or a number, not 'NoneType'
...

[/simterm]

Нас тут интересуют вот эти строки:


content_length = int(self.headers[‘Content-Length‘])
TypeError: int() argument must be a string, a bytes-like object or a number, not ‘NoneType

Т.е. к приложению Content-Length пришёл совершенно пустой.

При этом, если выполнить прямой запрос на HTTP (с отключенным редиректом в NGINX) или HTTPS – всё работает, как ожидается:

[simterm]

$ curl -vL -X POST https://dev.poc.example.com/ -d "param1=value1&param2=value2"
...
> POST / HTTP/1.1
> Host: dev.poc.example.com
> User-Agent: curl/7.67.0
> Accept: */*
> Content-Length: 27
> Content-Type: application/x-www-form-urlencoded
> 
* upload completely sent off: 27 out of 27 bytes
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< Server: nginx/1.10.3
< Date: Sat, 23 Nov 2019 09:55:07 GMT
< Content-Type: text/html
< Transfer-Encoding: chunked
< Connection: keep-alive
< 
* Connection #0 to host dev.poc.example.com left intact
POST request for /

[/simterm]

И stdout Python-приложения:

[simterm]

...
INFO:root:POST request,
Path: /
Headers:
Host: dev.poc.example.com
X-Real-IP: 194.***.***.26
X-Forwarded-For: 194.***.***.26
X-Forwarded-Proto: https
Connection: close
Content-Length: 27
User-Agent: curl/7.67.0
Accept: */*
Content-Type: application/x-www-form-urlencoded

Body:
param1=value1&param2=value2

127.0.0.1 - - [23/Nov/2019 09:55:07] "POST / HTTP/1.0" 200 -

[/simterm]

Теперь – посмотрим на вторую проблему.

POST становится GET

В процессе дебага описанной выше проблемы, когда на бекенд не доходили данные при POST, нашлось ещё одно интересное поведение запросов при HTTP-редиректах.

Теперь посмотрим, как POST превращается в …. GET 🙂

“Всё сложно”. Детали поведения рассмотрим в конце этого поста, сейчас – давайте попробуем один и тот же запрос на один и тот же ендпоинт, но используя два разных клиента – curl, и Postman (в виде standalone-приложения на рабочей машине).

curl

Выполняем запрос с типом POST на HTTP, добавляем -L, что бы проследовать по редиректам на HTTPS.

Тут в роли бекенда уже используем не Python-скрипт, как в примерах выше, а наш реальный бекенд в Docker-контейнере, что бы продемонстрировать его нормальную и не очень работу.

Сами данные значения и ошибки сейчас не имеют – нам интересен только тип запроса в логах NGINX:

[simterm]

$ curl -vL -X POST http://dev.poc.example.com/skin/api/v1/receipt -d "{}"
...
> POST /skin/api/v1/receipt HTTP/1.1
> Host: dev.poc.example.com
> User-Agent: curl/7.67.0
> Accept: */*
> 
* Mark bundle as not supporting multiuse
< HTTP/1.1 400 Bad Request
< Server: nginx/1.10.3
< Date: Sat, 23 Nov 2019 10:07:37 GMT
< Content-Type: application/json; charset=utf-8
< Content-Length: 58
< Connection: keep-alive
< 
* Connection #1 to host dev.poc.example.com left intact
{"message":"Validation failed: unable to parse json body"}

[/simterm]

Ещё раз – на ошибки не обращаем внимания, т.к. реальные данные к бекенду не отправили, нас сейчас интересует исключительно тип запроса в логах, давайте ещё глянем в логах NGINX:

[simterm]

==> /var/log/nginx/dev.poc.example.com-access.log <==
194.***.***.26 - - [23/Nov/2019:10:07:37 +0000] "POST /skin/api/v1/receipt HTTP/1.1" 400 58 "-" "curl/7.67.0"

[/simterm]

Тут всё хорошо, да? POST отправили – POST приняли.

Если мы curl-ом отправим явный GET – ответ бекенда будет другим:

[simterm]

$ curl -L -X GET  http://dev.poc.example.com/skin/api/v1/receipt -d "{}"
404 page not found

[/simterm]

И вот этот же GET в логе NGINX:

[simterm]

==> /var/log/nginx/dev.poc.example.com-access.log <==
194.***.***.26 - - [23/Nov/2019:10:07:37 +0000] "POST /skin/api/v1/receipt HTTP/1.1" 400 58 "-" "curl/7.67.0"
194.***.***.26 - - [23/Nov/2019:10:09:57 +0000] "GET /skin/api/v1/receipt HTTP/1.1" 404 18 "-" "curl/7.67.0"

[/simterm]

Всё правильно – всё логично, да?

Postman

А теперь – повторяем этот же запрос из Postman.

Нам важно отправить другим клиентом, QA-тима воспроизводила как раз в Postman, но должно быть и в прочих.

Выполняем такой же запрос – POST на HTTP, и сработает редирект на HTTPS:

И? 🙂

И теперь – смотрим лог NGINX снова, последняя запись:

[simterm]

==> /var/log/nginx/dev.poc.example.com-access.log <==
194.***.***.26 - - [23/Nov/2019:10:07:37 +0000] "POST /skin/api/v1/receipt HTTP/1.1" 400 58 "-" "curl/7.67.0"
194.***.***.26 - - [23/Nov/2019:10:09:57 +0000] "GET /skin/api/v1/receipt HTTP/1.1" 404 18 "-" "curl/7.67.0"
194.***.***.26 - - [23/Nov/2019:10:11:44 +0000] "GET /skin/api/v1/receipt HTTP/1.1" 404 18 "http://dev.poc.example.com/skin/api/v1/receipt" "PostmanRuntime/7.19.0"

[/simterm]

Ээээ…

Шта?!?

Но я ведь отправил явный POST?

Ещё раз:

  1. выполняем запрос curl, срабатывает редирект HTTP => HTTPS, видим POST – всё отлично
  2. выполняем запрос из Postman, срабатывает редирект HTTP => HTTPS, видим GETWTF???

POST, GET и “потерянные данные”

Зато теперь сновится понятно – куда “потерялись” наши данные из POST – потому что он превратился к GET.

Причина проблемы, 3xx redirects и HTTP RFC

Собственно, обе проблемы вызваны одной и той же причиной.

Начнём со чтения кода 301 в RFC 2616 – https://tools.ietf.org/html/rfc2616#section-10.3.2 – нас тут особенно интересует Note к описанию 301 редиректа:

Note: When automatically redirecting a POST request after
receiving a 301 status code, some existing HTTP/1.0 user agents
will erroneously change it into a GET request.

Т.е. некоторые существующие агенты HTTP/1.0 после выполнения POST и получения 301 – меняют его тип (хотя не должны, см. ниже), и выполняют GET.

Но это оказалось только вершиной айсберга.

Читаем дальше, про код 302, в том же RFC 2016 – https://tools.ietf.org/html/rfc2616#section-10.3.3 – и снова внимание на Note:

Note: RFC 1945 and RFC 2068 specify that the client is not allowed
to change the method on the redirected request. However, most
existing user agent implementations treat 302 as if it were a 303
response, performing a GET on the Location field-value regardless
of the original request method. The status codes 303 and 307 have
been added for servers that wish to make unambiguously clear which
kind of reaction is expected of the client.

RFC 1945 про 3хх редиректы – https://tools.ietf.org/html/rfc1945#section-9.3

RFC 2068 про 3хх редиректы – https://tools.ietf.org/html/rfc2068#section-10.3.2

Т.е. – RFC 1945 and RFC 2068 говорят, что клиент не должен менять метод для редиректнутого запроса, но при этом большинство считают код 302 как 303.

Идём ниже, и читаем описание кода 303https://tools.ietf.org/html/rfc2616#section-10.3.4:

The response to the request can be found under a different URI and
SHOULD be retrieved using a GET method on that resource.

Т.е., когда клиент считает, что он получил 303 код – он всегда выполняет GET.

Т.е, что мы видим в случае с Postman (и нашими мобильными клиентами, на которых проблема и проявилась изначально):

  1. клиент отправляет POST на HTTP
  2. получает редирект на HTTPS с кодом 301 или 302
  3. воспринимает его, как редирект 303
  4. и меняет тип своего запроса уже к HTTPS на GET, с “потерей” отправленных данных

Решение

Найти решение помогла документация от Mozilla (хотя подсказка была и в Notes RFC 2016 по 302), которая в своей документации к 301 и 302 явно говорит:

It is therefore recommended to set the 302 code only as a response for GET or HEAD methods and to use 307 Temporary Redirect instead, as the method change is explicitly prohibited in that case.

Идём в NGINX, меняем код редиректа с 302 на 307:

server {

    listen 80;
...
    location / {

        # return 302 https://dev.poc.example.com$request_uri;
        return 307 https://dev.poc.example.com$request_uri; 
    }
}
...

Перечитываем конфиги NGINX и повторяем запрос с помощью curl:

[simterm]

$ curl -L -X POST http://dev.poc.example.com/skin/api/v1/receipt -d "{}"
{"message":"Validation failed: fields 'hardware_id' and 'receipt' are mandatory"}

[/simterm]

Теперь мы получили валидный ответ от бекенда, который просто хочет нормальных входных данных.

Редирект сработал, POST-запрос от нас пришёл.

Лог NGINX:

[simterm]

==> /var/log/nginx/dev.poc.example.com-access.log <==
194.***.***.26 - - [23/Nov/2019:10:07:37 +0000] "POST /skin/api/v1/receipt HTTP/1.1" 400 58 "-" "curl/7.67.0"
194.***.***.26 - - [23/Nov/2019:10:09:57 +0000] "GET /skin/api/v1/receipt HTTP/1.1" 404 18 "-" "curl/7.67.0"
194.***.***.26 - - [23/Nov/2019:10:11:44 +0000] "GET /skin/api/v1/receipt HTTP/1.1" 404 18 "http://dev.poc.example.com/skin/api/v1/receipt" "PostmanRuntime/7.19.0"
194.***.***.26 - - [23/Nov/2019:10:35:51 +0000] "POST /skin/api/v1/receipt HTTP/1.1" 422 81 "-" "curl/7.67.0"
194.***.***.26 - - [23/Nov/2019:10:36:00 +0000] "POST /skin/api/v1/receipt HTTP/1.1" 422 81 "-" "curl/7.67.0"

[/simterm]

Повторяем запрос из Postman:

Лог NGINX:

[simterm]

==> /var/log/nginx/dev.poc.example.com-access.log <==
194.***.***.26 - - [23/Nov/2019:10:07:37 +0000] "POST /skin/api/v1/receipt HTTP/1.1" 400 58 "-" "curl/7.67.0"
194.***.***.26 - - [23/Nov/2019:10:09:57 +0000] "GET /skin/api/v1/receipt HTTP/1.1" 404 18 "-" "curl/7.67.0"
194.***.***.26 - - [23/Nov/2019:10:11:44 +0000] "GET /skin/api/v1/receipt HTTP/1.1" 404 18 "http://dev.poc.example.com/skin/api/v1/receipt" "PostmanRuntime/7.19.0"
194.***.***.26 - - [23/Nov/2019:10:35:51 +0000] "POST /skin/api/v1/receipt HTTP/1.1" 422 81 "-" "curl/7.67.0"
194.***.***.26 - - [23/Nov/2019:10:36:00 +0000] "POST /skin/api/v1/receipt HTTP/1.1" 422 81 "-" "curl/7.67.0"
194.***.***.26 - - [23/Nov/2019:10:37:57 +0000] "POST /skin/api/v1/receipt HTTP/1.1" 422 81 "http://dev.poc.example.com/skin/api/v1/receipt" "PostmanRuntime/7.19.0"

[/simterm]

Всё работает, как ожидалось.

AWS Application Load Balancer redirects

Увы, при использовании редиректов на AWS ALB – он не позволяет задать другой код:

В целом – на этом всё.

Было интересно.

Ссылки  по теме

Эта же проблема на других ресурсах

Помогло найти причину и решение