Autopsy revealed: blame space

We are a small startup in Charleston, South Carolina. We accept orders via text messages and print them directly in restaurants.

We launched eatabit.com in Charleston almost a year ago. During this time, our API has printed over 9,300 orders for food from our customers — restaurants, stadiums, and golf courses. Working with mobile communication is not easy - especially in areas with increased network load, like in stadiums during matches, but our systems track situations like poor signal quality or discontinuities.
')


The night from Wednesday to Thursday is usually the second after the night from Tuesday to Wednesday for the minimum load. Therefore, when the monitors started issuing a wave of warnings around midnight, we thought it was an accident. Unfortunately, it was not she ...



Well, there are gaps. Sometimes new employees come to the restaurant and pull out the printer plug to “turn off for the night”, but this time the problem arose with ALL printers. Our SIM card provider, T-Mobile, sometimes reboots base stations, and printers in the whole area are turned off for 60-90 seconds, but not ALL Charleston printers.

Ok, we are starting to solve the problem from the log of the printers themselves ...



Printers based on the Arduino Mega chipset (ATMega 1280), so we run the Arduino IDE and examine the system status:

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 

For nine months we worked with this very Arduino firmware without any questions, and now what is this? Suddenly? At midnight? All over the city? Funny ... what is it?

 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}{}% 

It seems everything is fine ... WTF ?! We look at the Arduino firmware, where the rest of the request is created.

 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; 

Stand still. Surely this ... there is a difference between the URL and the HTTP versions of the string - an extra space:

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

Let's test the theory that a Cowboy cannot process more than one space character between the analyzed parameters by adding an extra space to the end of the 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 

There is!



Thus, a bug was detected in our code (in the form of an extra space). But why did it all start suddenly? After all, this bug existed for at least nine months on a working firmware ...



What has changed?

 Server: Cowboy 

Cowboy. Who launched this server, which quietly blocked (or rather, made incorrect) our requests? Heroku? AWS? Superficial search in Google did not give a definite answer to this question. We sent inquiries and there, and there, and still waiting for a response. Stay in touch.