http://habrahabr.ru/company/enterra/blog/241732/



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

Мы запустили 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? Поверхностный поиск в Гугле не дал определенного ответа на этот вопрос. Мы отправили запросы и туда, и туда, и все еще ждем ответа. Оставайтесь на связи.