I have a weird problem with an API I'm writing. The API has makes http get requests to other services and times out in certain situations- another service being off/unreachable in most cases.
I'm trying to run the system entirely on AWS, but when running the API on there I get frequent timeouts trying to access services on the same instance. The API is written in ruby+sinatra; I never had problems with its python predecessor. If I curl the url for other services from the AWS instance command line, I never get timeouts. When I run the API locally (other services on AWS), it works fine, every single time.
Initially I thought it might be the http library I was using- net/http, which turned out to be problematic even locally. Switching to open-uri or rest-client fixed all local problems, but when I run on AWS I still get timeouts 20% of the time.
The API is ruby+sinatra using open-uri to do http requests. The other services are either ruby+sinatra or java. I'm running on a 32-bit Amazon Linux small instance, ruby 1.9.3, java 1.6; my local machine is Mac with Snow Leopard with ruby 1.9.3 and java 1.6 as well.
Any ideas or tips to further narrow down what might be happening?
UPDATE: My big sinatra app and little sinatra app behave differently!?
The test version of my sinatra app to call my java service, both running on AWS... works fine.
require 'rubygems'
require 'uri'
require 'open-uri'
require 'sinatra'
set :port, 6969
get '/wtf' do
xid = params[:xid]
state = params[:state]
service_addr = 'http://prod.myserver.com'
rid = 'xxx'
json = "{\"state\":\"#{state}\",\"sid\":\"0xac99d8929a89e6c01b56378336dec3a8L\",\"m\":\"set\",\"rid\":\"#{rid}\",\"id\":\"#{xid}\"}"
paramStr = URI.escape("rid=#{rid}&id=#{xid}&json=#{json}")
response = open(service_addr+"?"+paramStr)
status = response.status[0]
body = response.read
body
end
The big version, running with Rack + as a better structured sinatra app... fails 20+% of the time!
require 'uri'
require 'open-uri'
class MyApp < Sinatra::Base
get '/wtf' do
xid = params[:xid]
state = params[:state]
service_addr = 'http://prod.myserver.com'
rid = 'xxx'
json = "{\"state\":\"#{state}\",\"sid\":\"0xac99d8929a89e6c01b56378336dec3a8L\",\"m\":\"set\",\"rid\":\"#{rid}\",\"id\":\"#{xid}\"}"
paramStr = URI.escape("rid=#{rid}&id=#{xid}&json=#{json}")
response = open(service_addr+"?"+paramStr)
status = response.status[0]
body = response.read
body
end
end
UPDATE 2: Detailed error readout using mechanize- always a gateway timeout
For the simple version, it works every time (no timeouts). For the complicated version, here are readouts with mechanize when it works, and doesn't.
When it works:
I, [2012-05-22T22:45:53.267464 #11610] INFO -- : Net::HTTP::Get: /? ### big long get str
D, [2012-05-22T22:45:53.267587 #11610] DEBUG -- : request-header: accept => */*
D, [2012-05-22T22:45:53.267630 #11610] DEBUG -- : request-header: user-agent => Mechanize/2.5.1 Ruby/1.9.3p125 (http://github.com/tenderlove/mechanize/)
D, [2012-05-22T22:45:53.267676 #11610] DEBUG -- : request-header: accept-encoding => gzip,deflate,identity
D, [2012-05-22T22:45:53.267713 #11610] DEBUG -- : request-header: accept-charset => ISO-8859-1,utf-8;q=0.7,*;q=0.7
D, [2012-05-22T22:45:53.267750 #11610] DEBUG -- : request-header: accept-language => en-us,en;q=0.5
D, [2012-05-22T22:45:53.267787 #11610] DEBUG -- : request-header: host => prod.pixieplug.com:9001
I, [2012-05-22T22:45:53.341814 #11610] INFO -- : status: Net::HTTPOK 1.1 200 OK
D, [2012-05-22T22:45:53.341916 #11610] DEBUG -- : response-header: content-type => application/json;charset=ISO-8859-1
D, [2012-05-22T22:45:53.341962 #11610] DEBUG -- : response-header: transfer-encoding => chunked
D, [2012-05-22T22:45:53.342009 #11610] DEBUG -- : response-header: server => Jetty(8.0.y.z-SNAPSHOT)
D, [2012-05-22T22:45:53.342137 #11610] DEBUG -- : Read 167 bytes (167 total)
98.247.240.63 - - [22/May/2012 22:45:53] "GET /wtf?xid=00:00:00:00:00:17&state=255 HTTP/1.1" 200 167 0.0777
When it doesn't:
I, [2012-05-22T22:46:23.665908 #11610] INFO -- : Net::HTTP::Get: /?# long list of params
D, [2012-05-22T22:46:23.666014 #11610] DEBUG -- : request-header: accept => */*
D, [2012-05-22T22:46:23.666053 #11610] DEBUG -- : request-header: user-agent => Mechanize/2.5.1 Ruby/1.9.3p125 (http://github.com/tenderlove/mechanize/)
D, [2012-05-22T22:46:23.666090 #11610] DEBUG -- : request-header: accept-encoding => gzip,deflate,identity
D, [2012-05-22T22:46:23.666125 #11610] DEBUG -- : request-header: accept-charset => ISO-8859-1,utf-8;q=0.7,*;q=0.7
D, [2012-05-22T22:46:23.666161 #11610] DEBUG -- : request-header: accept-language => en-us,en;q=0.5
D, [2012-05-22T22:46:23.666233 #11610] DEBUG -- : request-header: host => prod.pixieplug.com:9001
I, [2012-05-22T22:46:28.675045 #11610] INFO -- : status: Net::HTTPGatewayTimeOut 1.1 504 Gateway Timeout
D, [2012-05-22T22:46:28.675156 #11610] DEBUG -- : response-header: content-type => application/json;charset=ISO-8859-1
D, [2012-05-22T22:46:28.675195 #11610] DEBUG -- : response-header: transfer-encoding => chunked
D, [2012-05-22T22:46:28.675232 #11610] DEBUG -- : response-header: server => Jetty(8.0.y.z-SNAPSHOT)
D, [2012-05-22T22:46:28.675332 #11610] DEBUG -- : Read 48 bytes (48 total)
Mechanize::ResponseCodeError - 504 => Net::HTTPGatewayTimeOut for http://prod.pixieplug.com:9001/?# long list of params -- unhandled response:
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/mechanize-2.5.1/lib/mechanize/http/agent.rb:304:in `fetch'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/mechanize-2.5.1/lib/mechanize.rb:407:in `get'
/home/ec2-user/elphi-api/routes/sandbox.rb:15:in `block in <class:MyApp>'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/sinatra-1.3.2/lib/sinatra/base.rb:1212:in `call'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/sinatra-1.3.2/lib/sinatra/base.rb:1212:in `block in compile!'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/sinatra-1.3.2/lib/sinatra/base.rb:785:in `[]'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/sinatra-1.3.2/lib/sinatra/base.rb:785:in `block (3 levels) in route!'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/sinatra-1.3.2/lib/sinatra/base.rb:801:in `route_eval'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/sinatra-1.3.2/lib/sinatra/base.rb:785:in `block (2 levels) in route!'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/sinatra-1.3.2/lib/sinatra/base.rb:822:in `block in process_route'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/sinatra-1.3.2/lib/sinatra/base.rb:820:in `catch'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/sinatra-1.3.2/lib/sinatra/base.rb:820:in `process_route'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/sinatra-1.3.2/lib/sinatra/base.rb:784:in `block in route!'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/sinatra-1.3.2/lib/sinatra/base.rb:783:in `each'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/sinatra-1.3.2/lib/sinatra/base.rb:783:in `route!'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/sinatra-1.3.2/lib/sinatra/base.rb:886:in `dispatch!'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/sinatra-1.3.2/lib/sinatra/base.rb:719:in `block in call!'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/sinatra-1.3.2/lib/sinatra/base.rb:871:in `block in invoke'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/sinatra-1.3.2/lib/sinatra/base.rb:871:in `catch'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/sinatra-1.3.2/lib/sinatra/base.rb:871:in `invoke'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/sinatra-1.3.2/lib/sinatra/base.rb:719:in `call!'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/sinatra-1.3.2/lib/sinatra/base.rb:705:in `call'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/rack-protection-1.2.0/lib/rack/protection/xss_header.rb:22:in `call'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/rack-protection-1.2.0/lib/rack/protection/base.rb:47:in `call'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/rack-protection-1.2.0/lib/rack/protection/base.rb:47:in `call'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/rack-protection-1.2.0/lib/rack/protection/path_traversal.rb:16:in `call'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/rack-protection-1.2.0/lib/rack/protection/json_csrf.rb:17:in `call'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/rack-protection-1.2.0/lib/rack/protection/base.rb:47:in `call'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/rack-protection-1.2.0/lib/rack/protection/xss_header.rb:22:in `call'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/rack-1.4.1/lib/rack/session/abstract/id.rb:205:in `context'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/rack-1.4.1/lib/rack/session/abstract/id.rb:200:in `call'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/rack-1.4.1/lib/rack/logger.rb:15:in `call'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/rack-1.4.1/lib/rack/head.rb:9:in `call'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/rack-1.4.1/lib/rack/methodoverride.rb:21:in `call'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/sinatra-1.3.2/lib/sinatra/showexceptions.rb:21:in `call'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/rack-1.4.1/lib/rack/lint.rb:48:in `_call'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/rack-1.4.1/lib/rack/lint.rb:36:in `call'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/rack-1.4.1/lib/rack/showexceptions.rb:24:in `call'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/rack-1.4.1/lib/rack/commonlogger.rb:20:in `call'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/rack-1.4.1/lib/rack/chunked.rb:43:in `call'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/rack-1.4.1/lib/rack/content_length.rb:14:in `call'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/thin-1.3.1/lib/thin/connection.rb:80:in `block in pre_process'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/thin-1.3.1/lib/thin/connection.rb:78:in `catch'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/thin-1.3.1/lib/thin/connection.rb:78:in `pre_process'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/thin-1.3.1/lib/thin/connection.rb:53:in `process'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/thin-1.3.1/lib/thin/connection.rb:38:in `receive_data'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/eventmachine-0.12.10/lib/eventmachine.rb:256:in `run_machine'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/eventmachine-0.12.10/lib/eventmachine.rb:256:in `run'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/thin-1.3.1/lib/thin/backends/base.rb:61:in `start'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/thin-1.3.1/lib/thin/server.rb:159:in `start'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/rack-1.4.1/lib/rack/handler/thin.rb:13:in `run'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/rack-1.4.1/lib/rack/server.rb:265:in `start'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/rack-1.4.1/lib/rack/server.rb:137:in `start'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/gems/rack-1.4.1/bin/rackup:4:in `<top (required)>'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/bin/rackup:19:in `load'
/home/ec2-user/.rvm/gems/ruby-1.9.3-p125/bin/rackup:19:in `<main>'
98.247.240.63 - - [22/May/2012 22:46:28] "GET /wtf?xid=00:00:00:00:00:17&state=255 HTTP/1.1" 500 157221 5.1385
