Вскрытие показало: виноват пробел

http://eatabit.com/blog/articles/post-mortem-a-single-whitespace-char.html
  • Перевод


Мы — небольшой стартап в Чарльстоне, Южная Каролина. Мы принимаем заказы с помощью текстовых сообщений и распечатываем их непосредственно в ресторанах.

Мы запустили eatabit.com в Чарльстоне почти год назад. За это время наш API распечатал более 9300 заказов на еду у наших клиентов — это рестораны, стадионы, курсы гольфа. Работа с мобильной связью не отличается простотой — особенно в зонах с повышенной нагрузкой на сеть, как на стадионах во время матчей, но наши системы отслеживают ситуации вроде плохого качества сигнала или разрывов.



Ночь со среды на четверг обычно вторая после ночи со вторника на среду по минимальной загрузке. Поэтому, когда мониторы начали выдавать волну предупреждений около полуночи, мы подумали, что это случайность. К сожалению, это была не она…



Что ж, разрывы бывают. Иногда в ресторан приходят новые сотрудники, которые выдёргивают из розетки вилку принтера, чтобы «отключить на ночь», но в этот раз проблема возникла со ВСЕМИ принтерами. Наш поставщик SIM-карт, T-Mobile, иногда перезагружает базовые станции, и на 60-90 секунд отключаются принтеры в целом районе, но не ВСЕ принтеры Чарльстона.

Ок, начинаем решать проблему с лога самих принтеров…



Принтеры на основе чипсета Arduino Mega (ATMega 1280), поэтому мы запускаем Arduino IDE и изучаем статус системы:

SYSTEM::State: Polling.
SYSTEM::Polling: SYSTEM::State: Idle.
              
WEB::Starting Poll!
WEB::Poll Request:
              
GET /v1/printer/***************/orders.txt  HTTP/1.1
HOST: api.eatabit.io
Authorization: Basic ***********************************************
User-Agent: Eatabit_Device/0.5.1
Content-Length: 67
Content-Type: application/x-www-form-urlencoded
Accept: */*
Connection: close
              
pickup_minutes=15&delivery_minutes=30&paper_status=1&cell_signal=15
              
WEB::Request Length: 351
WEB::Request Page Status: 0
              
AT+CSQ
+CSQ: 20,0
OK
              
GSM::CSQ:20
              
AT#SKTD=0,80,"api.eatabit.io",0,0
CONNECT
              
GSM::SEND: Socket Enabled
GSM::RCXV: Header Sent
              
HTTP/1.1 505 HTTP Version Not Supported
Connection: close
Server: Cowboy
Date: Wec, 21 Oct 2014 19:22:32 GMT
Content-Length: 0
Стоп… что?
HTTP/1.1 505 HTTP Version Not Supported

Девять месяцев мы работали с этой самой прошивкой Arduino без вопросов, а теперь это? Внезапно? В полночь? По всему городу? Забавно… Что же это такое?

Server: Cowboy
Наше приложение развернуто на Heroku, мы используем веб-сервер Unicorn. Так что же это за «Ковбой», который общается с нашим сервисом?
Так, пробуем cURL и воспроизводим запрос через командную строку на моем Маке:
curl "http://api.eatabit.io/v1/printer/***************/orders.text?pickup_minutes=30&delivery_minutes=90&state=ok" \
> -X GET \
> -u ***************:****************** \
> -v \
> --user-agent "Eatabit_Device/0.5.1"
              
* Hostname was NOT found in DNS cache
*   Trying 54.225.219.28...
* Connected to api.eatabit.io (54.225.219.28) port 80 (#0)
* Server auth using Basic with user '***************'
> GET /v1/printer/***************/orders.text?pickup_minutes=30&delivery_minutes=90&state=ok  HTTP/1.1
> Authorization: Basic ***********************************************<
> User-Agent: Eatabit_Device/0.5.1
> Host: api.eatabit.io
> Accept: */*
>
< HTTP/1.1 200 OK
* Server Cowboy is not blacklisted
< Server: Cowboy
< Connection: keep-alive
< Date: Mon, 21 Oct 2014 01:25:11 GMT
< Status: 200 OK
< Content-Type: text/plain
< Content-Length: 7
< Etag: "26f14889eed7cc4b3b78cc667c7ee9eb"
< Cache-Control: max-age=0, private, must-revalidate
< X-Request-Id: dce1a529-fff1-4222-b997-21d7c074487f
< X-Runtime: 1.135825
< Via: 1.1 vegur
<
* Connection #0 to host api.eatabit.io left intact
{0:0}{}%

Вроде всё нормально… WTF?! Смотрим на прошивку Arduino, где создается остальная часть запроса.

if(isCommsBufferAvailable()) {
  //make the chunk
  uint8_t dataLength = snprintf(( char * )tempString, sizeof(tempString), 
    "pickup_minutes=%hhu&delivery_minutes=%hhu&paper_status=%hhu&cell_signal=%hhu",
    settings.getPickupMinutes(),
    settings.getDeliveryMinutes(),
    printer.hasPaper(),
    gsmModem.getSignal()
    );
  uint8_t contentLength[4];
  dataLength = strlen( ( char * ) tempString);
  itoa(dataLength,( char * ) contentLength, 10);
  
  IF_DEBUG(DEBUG_INFO) PORT_DEBUG.println("WEB::Starting Poll!");
  reserveCommsBuffer();
  
  //build the header for the POLL request
  strcpy( ( char * ) commsOrderBuffer, "GET /v1/printer/");
  
  strcat( ( char * ) commsOrderBuffer, ( char * ) settings.getIMEI());
  strcat( ( char * ) commsOrderBuffer, "/orders.txt  HTTP/1.1\r\n");
  strcat( ( char * ) commsOrderBuffer, "HOST: ");
  strcat( ( char * ) commsOrderBuffer, SERVER_NAME);
  strcat( ( char * ) commsOrderBuffer, "\r\n");
  strcat( ( char * ) commsOrderBuffer, "Authorization: Basic ");
  
  strcat( ( char * ) commsOrderBuffer, ( char * ) settings.getAccess());        
  strcat( ( char * ) commsOrderBuffer, "\r\n");
  strcat( ( char * ) commsOrderBuffer, "User-Agent: Eatabit_Device/");
  strcat( ( char * ) commsOrderBuffer, SOFTWARE_VER);
  strcat( ( char * ) commsOrderBuffer, "\r\n");
  strcat( ( char * ) commsOrderBuffer, "Content-Length: ");
  strcat( ( char * ) commsOrderBuffer, ( char * ) contentLength);
  strcat( ( char * ) commsOrderBuffer, "\r\n");
  strcat( ( char * ) commsOrderBuffer, "Content-Type: application/x-www-form-urlencoded\r\n");
  strcat( ( char * ) commsOrderBuffer, "Accept: */*\r\n");
  strcat( ( char * ) commsOrderBuffer, "Connection: close\r\n");      
  strcat( ( char * ) commsOrderBuffer, "\r\n");
  strcat( ( char * ) commsOrderBuffer, ( char * ) tempString);
  IF_DEBUG(DEBUG_BUFFERS) {
    temp1 = strlen((char*) commsOrderBuffer);
    PORT_DEBUG.println("WEB::Poll Request: ");
    PORT_DEBUG.println((char*)commsOrderBuffer);
    PORT_DEBUG.print("WEB::Request Length: ");
    PORT_DEBUG.println(temp1); 
  }
  temp1 = gsmModem.requestPage( (uint8_t *) SERVER_NAME, PORT_NUMBER, commsOrderBuffer, commsOrderBuffer, ORDER_QUE_MAX_ORDER_SIZE);
  IF_DEBUG(DEBUG_BUFFERS) {
    PORT_DEBUG.print("WEB::Request Page Status: ");
    PORT_DEBUG.println(temp1);
  }
  
  //go wait for the response
  _state = WEB_WAIT_POLL;
} 
else {
  IF_DEBUG(DEBUG_BUFFERS) PORT_DEBUG.println("WEB::Buffer In use!");
}     
break;

Стойте. Неужто это… между URL и HTTP версиями строки есть разница — дополнительный пробел:

strcat( ( char * ) commsOrderBuffer, "/orders.txt  HTTP/1.1\r\n");

Давайте проверим теорию, что Ковбой не может обработать более одного символа пробела между анализируемыми параметрами, добавив дополнительный пробел к концу URL.

curl "http://api.eatabit.io/v1/printer/***************/orders.text?pickup_minutes=30&delivery_minutes=90&state=ok " \
-X GET \
-u ***************:****************** \
-v \
--user-agent "Eatabit_Device/0.5.1"
              
* Hostname was NOT found in DNS cache
*   Trying 54.225.123.174...
* Connected to api.eatabit.io (54.225.123.174) port 80 (#0)
* Server auth using Basic with user '***************'
> GET /v1/printer/***************/orders.text?pickup_minutes=30&delivery_minutes=90&state=ok  HTTP/1.1
> Authorization: Basic ***********************************************<<
> User-Agent: Eatabit_Device/0.5.1
> Host: api.eatabit.io
> Accept: */*
>
< HTTP/1.1 505 HTTP Version Not Supported
< Connection: close
* Server Cowboy is not blacklisted
< Server: Cowboy
< Date: Mon, 27 Oct 2014 02:03:25 GMT
< Content-Length: 0
<
* Closing connection 0

Есть!



Таким образом, в нашем коде обнаружен баг (в форме лишнего пробела). Но почему же это все внезапно началось? Ведь этот баг существовал как минимум девять месяцев на работающей прошивке…



Что же изменилось?

Server: Cowboy

Cowboy. Кто запустил этот сервер, который по-тихому заблокировал (точнее, сделал некорректными) наши запросы? Heroku? AWS? Поверхностный поиск в Гугле не дал определенного ответа на этот вопрос. Мы отправили запросы и туда, и туда, и все еще ждем ответа. Оставайтесь на связи.
Enterra 41,81
Компания
Поделиться публикацией
Комментарии 22
  • +8
    Читая это матерые электронщики наверное испытывают примерно те же ощущения, что и айтишники лет 12 назад, когда пхп воспринимался ими как средство веб-быдлокодинга и периодически всплывал в серьезных проектах. Ну или проекты с его использованием внезапно становились серьезными.

    PS это я про ардуино, если кто не понял :)
    • +9
      Ох, получу я хабра-люлей сейчас, но… что-то сильно изменилось за 12 лет? :)
      • +12
        Если верить Курту Воннегуту,
        Everything is going to become unimaginably worse and never get better again.
        • 0
          К ПХП можно по-разному относиться, но с ним приходится считаться, если имеешь дело с ит.
          Хоть ты трижды супер-пупер джава инженер, при разговоре с контрагентом легко может случиться такой диалог:
          (к) — почему не отвечает ваш сервис?
          (вы) — ваш запрос приходит с незаполненным Accept-Encoding в хидере запроса
          (к) — это что такое? HTTP_ACCEPT?
          (вы) — омг, втф (про себя) — нет, это HTTP_ACCEPT_ENCODING
          (к) — а, понятно, спасибо

          Тоже сейчас происходит и с электронщиками. Сейчас они снисходительно смотрят на электро-школоло, а через 5 лет им придется делать двухсекундные задержки, чтобы другая железка заказчика успела подгрузить ардуиновский бутлоадер и встраивать в свои платы слоты с тем самым ненавидимым разъёмом.
          • +4
            Знаете, мне почему то кажется что ситуация, когда сервис не отвечает потому что не заполнен Accept-Encoding — это не PHP плохой и кривой язык, а данному Java разработчику надо вырвать руки.
            Пустой Accept-Encoding это вполне валидный запрос stackoverflow.com/questions/14562572/is-it-valid-to-leave-accept-encoding-field-empty
            • 0
              Не хочу углубляться в контекст, но речь шла об апи, которое предполагает зипование ответа. И если программист не дочитал описание апи до этого пункта, то это наиболее оптимальный способ обратить его внимание на то, что входящий поток неплохо бы распаковать.
              • 0
                а, забыл добавить
                ответ там был 400й, и даже с соответствующим сообщением
                только это немного не то, что ожидал от нашего сервиса тот программист
            • +1
              Ну, надо писать отказо-устойчивые приложения. Уровень паранойи должен быть таким, чтобы даже процессору и оперативной памяти доверять со скрипом: если что-то может сломаться — оно сломается; если не может — сломается тоже, да так, что мало не покажется. Тогда программы будут надежными. Наверно.

              Недавно слышал где-то историю про chkdsk.exe, который работал че-то типа почти год, проверяя какие-то дикие терабайты хранилища, и не упал, а допроверял и отсигналил, что теперь все ок. Вот это — надежность.

              Ну а про похапе… Всё, у чего низкий порог вхождения становится крайне популярным: Delphi (ведь все учили Pascal в школе или институте), PHP, JavaScript, Basic, etc. По какой-то причине низкий порог вхождения коррелирует с качеством. Интересно, почему? Это не издёвка, кстати, мне правда интересно, почему.

              Хотя, бывает и наоборот. Скажем, у bash заметно ниже порог вхождения, чем у PowerShell, но bash при этом очень хороший инструмент для своего круга задач.
              • +3
                Словно на баше так ужасного кода.

                > Это не издёвка, кстати, мне правда интересно, почему.

                Язык прощает много ошибок. Уровень вхождения позволяет к концу дня уже пойти на биржу фрилансеров делать сайты визитки. Доширак надо покупать, изучать толком нет времени, вот и получается такое качество. Учитывая, что PHP это фрактал плохого дизайна…
                • 0
                  >Недавно слышал где-то историю про chkdsk.exe, который работал че-то типа почти год, проверяя какие-то дикие терабайты хранилища, и не упал, а допроверял и отсигналил, что теперь все ок. Вот это — надежность.

                  Это Бобук в одном из недавних выпусков Радио-Т рассказывал про сервера Яндекса, только там не чекдиск был, а что-то с рейд-массивом.
                  • 0
                    Да, точно, это из Радио-Т, и да, там про рейды было, но вроде чекдиск их проверял. Могу ошибаться.
            • 0
              Arduino IDE банально неудобна. IDE можно назвать лишь с натяжкой. А как отлаживать? Я к тому, что если можно не есть кактус, зачем продолжать его есть?
            • +2
              Хорошо, что HTTP 2.0 бинарный.
              • +10
                ну текстовый протокол который «придирается» к лишнему пробелу недалеко ушел от бинарного, на самом то деле.
              • 0
                Cowboy это сервер на Э-г. В Heroku используют ковбоая для маршрутизации внутри сети. Даже книжку написали.
                • +1
                  cowboy — веб-сервер на erlang. скорей всего, на нем основан роутер heroku. думаю, Грегу это уже рассказали.
                  ну, я малость опоздал.
                  • +2
                    Hint: таким образом (добавлением пробелов или переносов строк в неожиданных местах) можно обходить DPI провайдеров.
                    • +1
                      В этом огромный минус текстовых форматов — они дают некую свободу изложения, позволяя легко выразить одно и то же разными способами.

                      Решение же довольно тривиально — приводить все к каноническому виду перед парсингом.

                      Однако DPI «по сигнатурам» к счастью с этим не справится (а значит, останется уязвимым перед пробелами-табами-переводами строк), а полноценный разбор протокола будет стоить слишком дорого.
                      • НЛО прилетело и опубликовало эту надпись здесь
                      • НЛО прилетело и опубликовало эту надпись здесь
                        • +3
                          Приходит сын к отцу-программисту:
                          – Папа, а почему солнце всходит?
                          – Ты проверял?
                          – Да…
                          – Каждый день всходит?
                          – Да, и каждый день заходит…
                          – НИЧЕГО НЕ ТРОГАЙ!!!
                          • +1
                            Вообще согласно tools.ietf.org/html/rfc7230#section-3.1.1 ответ должен быть 400, а не 505.

                          Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.

                          Самое читаемое