Skip to content
This repository

Calling Model#save can raise AWS::S3::Errors::RequestTimeout #751

Open
indirect opened this Issue February 21, 2012 · 111 comments
André Arko

Hi guys, I've been noticing that after switching to aws-sdk, calling #save on a model with a paperclip attachment will now sometimes (I assume only those times when S3 times out) raise an AWS::S3::Errors::RequestTimeout error. It seems completely crazy to me to have to add a rescue AWS::S3::Errors::RequestTimeout clause after every single time that I ever call save anywhere in my app. Shouldn't paperclip just catch the error and either retry or report that the save failed? Thanks.

505aaron

Try setting the :whiny option to false.

André Arko

The source says this about the :whiny option:

    # * +whiny+: Will raise an error if Paperclip cannot post_process an uploaded file due
    #   to a command line error. This will override the global setting for this attachment.
    #   Defaults to true. This option used to be called :whiny_thumbanils, but this is
    #   deprecated.

Unfortunately, :whiny doesn't apply to my situation at all. First, this isn't happening during post-processing, it's happening when Paperclip tries to write the file to S3. Second, the problem I am reporting is not that Paperclip is writing out errors into the logs, it is that Paperclip doesn't catching exceptions raised by the aws-s3 library that it uses. As a result, I am seeing exceptions in my application any time S3 has a hiccup. Not very cool. :(

Prem Sichanugrist
Collaborator

Yeah, that's totally sucks. I think we could do better on this one.

But then, how do you think we should handle this? I'd want to do a retry for once or twice, but for third time should it adds the error to the model?

André Arko

Yeah, that seems like exactly the right answer to me.

neuralnw

One thing for sure that it is happening on Ruby 1.9. It works fine on 1.8. According to a link here https://forums.aws.amazon.com/thread.jspa?threadID=74945, it said :encoding => "BINARY" would solve the problem. But I don't know where I should set this variable.

André Arko

There is not a chance that changing the encoding will stop Amazon S3 from having timeouts. :P

neuralnw

I 'm running Jruby 1.6.7 and worked on Ruby 1.8, but not with 1.9. To me then looks like something to do with 1.9

Charles Lee

@indirect This is a slightly parallel issue, but I was having timeouts every single time until I explicitly marked the file with a binary encoding. I'm guessing this is a problem with the AWS gem, not paperclip. I'm sure there will sometimes be a legitimate timeout error when S3 is down, for which this error should be addressed.

@tcpipmen I was uploading a file from a form, and used file.tempfile.binmode. Not sure if that's the right thing to do, but I no longer timeout every single time. Try that out.

Jasper Kennis

@charles-luv Where do you set "file.tempfile.binmode"? I'd like to try that too. The issue seems highly related to Issue #721 indeed, I posted some details about the trouble I was experiencing there.

Charles Lee

@jasperkennis with a file object, try:

filename = "destination_filename"
s3_obj = s3.buckets["bucket_name"].objects[filename]
s3_obj.write(file.tempfile.binmode)
Keil Miller

I am having the same issue I believe.

New rails 3.2.3 app
aws-sdk (1.3.9)
paperclip (3.0.1)
paperclip-env_aware (0.0.3)

set my credentials in paperclip_env.yml

I did not ignore the yml file. Git defaults and ignored /public/system (for dev only). Pushed to heroku cedar stack. Timed out with an error 500 upon trying to upload a file with my app online. Checked the logs.

Logs summarized
Started PUT
Command :: identify
Command :: convert
[paperclip] saving
[paperclip] Saving attachments.
Error R12 (Exit timeout) -> Process failed to exit within 10 seconds of SIGTERM
Stopping process with SIGKILL
Process exited with status 137
Completed 500 Internal Server Error in 23052ms
AWS::S3::Errors::RequestTimeout (Your socket connection to the server was not read from or written to within the timeout period. Idle connections will be closed.):

Keil Miller

Degrading to gem "paperclip", "~> 2.7" (2.7.0) immediately solved the issue. There is definitely a bug somewhere. Let me know when it is resolved! :)

Prem Sichanugrist
Collaborator

Oh my, this is going to be hard to debug :/

André Arko
Prem Sichanugrist
Collaborator

HAHAHAHA ;)

Keil Miller

Debug == roll version back... :p

Jasper Kennis

Not sure if a debug is needed. It seems like 2.x and 3.x just follow a different strategy, which can be fine, but it should be documented very clearly.

Prem Sichanugrist
Collaborator

It's not a different strategy though. We've switched to aws-sdk since 2.7 and it seems like the problem came since then. Unless if people has a problem with 3.0.1 but not 3.0.0, then we have some problem on our side.

Anyhow, too much chit-chat on this. If anybody can provide me a backtrace when that error happen it would be great.

Stefan Wrobel

I'm currently using 2.7 with aws-sdk and it's fine. See backtraces here: #721

Philipp Brumm
brumm commented April 04, 2012

I think I may have found the issue? Consider this:

1.9.2p180 :003 > object = b.objects['test.png']
 => <AWS::S3::S3Object:mybucket/test.png> 

# specifying a path via :file
1.9.2p180 :004 > object.write(:file => "~/Desktop/test.png", :acl => :public_read)
 => <AWS::S3::S3Object:mybucket/test.png> 

# specifying a pure path
1.9.2p180 :005 > object.write("~/Desktop/test.png", :acl => :public_read)
 => <AWS::S3::S3Object:mybucket/test.png> 

# File.new with :encoding option set to "BINARY"
1.9.2p180 :006 > object.write(File.new("~/Desktop/test.png", :encoding => "BINARY"), :acl => :public_read)
 => <AWS::S3::S3Object:mybucket/test.png> 

# File.new without :encoding set, file.external_encoding is "UTF-8"
1.9.2p180 :007 > object.write(File.new("~/Desktop/test.png"), :acl => :public_read)
AWS::S3::Errors::RequestTimeout: <?xml version="1.0" encoding="UTF-8"?>
<Error><Code>RequestTimeout</Code><Message>Your socket connection to the server was not read from or written to within the timeout period. Idle connections will be closed.</Message><RequestId>12D953A74BCC9FCD</RequestId><HostId>sy6gBHDp2tUtWPHZTf/p3thSX8J2rdjKe0wfVy8SYfPcU/2yIANq46ckhUyDvLiZ</HostId></Error>
  from ~/.rvm/gems/ruby-1.9.2-p180-patched@jobmensa/gems/aws-sdk-1.3.4/lib/aws/core/client.rb:261:in `return_or_raise'
  from ~/.rvm/gems/ruby-1.9.2-p180-patched@jobmensa/gems/aws-sdk-1.3.4/lib/aws/core/client.rb:321:in `client_request'
  from (eval):3:in `put_object'
  from ~/.rvm/gems/ruby-1.9.2-p180-patched@jobmensa/gems/aws-sdk-1.3.4/lib/aws/s3/s3_object.rb:315:in `write'
  from (irb):6
  from ~/.rvm/gems/ruby-1.9.2-p180-patched@jobmensa/gems/railties-3.2.3/lib/rails/commands/console.rb:47:in `start'
  from ~/.rvm/gems/ruby-1.9.2-p180-patched@jobmensa/gems/railties-3.2.3/lib/rails/commands/console.rb:8:in `start'
  from ~/.rvm/gems/ruby-1.9.2-p180-patched@jobmensa/gems/railties-3.2.3/lib/rails/commands.rb:41:in `<top (required)>'
  from script/rails:6:in `require'
  from script/rails:6:in `<main>'

I think there may be a problem in how Paperclip is setting encodings for the FileAdapter stuff, but I haven't dug any deeper so far. Any ideas?

Philipp Brumm
brumm commented April 05, 2012

submitted pull request to fix this issue: #811

Prem Sichanugrist
Collaborator

I've merged #811 into master. Can you guys give it a try and see if it fixes your problem?

Andy Shin

@sikachu, it resolved the issue for me. Pre-commit, it worked fine on my local environment but broke in heroku land. Now it works in both places. Cheers!

Prem Sichanugrist
Collaborator

W00t! Going to release 3.0.2 later today. Thanks for confirmation.

Keil Miller

Thanks for the update guys! 3.0.2 did indeed resolve the issue. :)

Prem Sichanugrist sikachu closed this April 24, 2012
Alex Dowad

The same problem is occurring for me with version 2.7. Why not just upgrade to 3.0.2? See spree/spree#1653 and you'll understand.

Is it possible to backport this fix to the 2.7 branch?

Prem Sichanugrist
Collaborator

Yep, I can release another 2.7.x

Alex Dowad

THANKS! PAPERCLIP ROCKS!!!

...Can you post here when the new version is out?

Prem Sichanugrist sikachu reopened this June 15, 2012
Sebastian Gräßl

Is there a status on backporting it to 2.7?

Prem Sichanugrist
Collaborator

@bastilian Current ticket status: confused. >_<

See, the regression was introduced in 3.0.1 whereas the adapters wasn't mark the file as binary as it should be, resulted in wrongly calculated signature. I've looked into 2.7 code and seems like we already mark those files as binary, so I wasn't sure where else do we need to fix.

Let me have another through look at it to see if I can file the culprit.

Jonathan Hyman

I'm seeing this in 3.1.4. Has anyone else seen issues with this?

AWS::S3::Errors::RequestTimeout
Your socket connection to the server was not read from or written to within the timeout period. Idle connections will be closed.

Jonathan Hyman

@sikachu this issue is back due to a recent version of aws-sdk. I downgraded to aws-sdk 1.5.8 (which I was previously on) and it fixes my problem. It looks like aws-sdk 1.6.3 and 1.6.4 add updates to S3, it's probably due to a change in 1.6.3 if I had to guess: http://aws.amazon.com/releasenotes/5728376747252106.

Prem Sichanugrist
Collaborator

Oh, I guess our monkey patch broke ... Thanks for investigating that, I'll have a look soon.

It seems like they haven't test their library against Ruby 1.9 yet, which is kind of shame.

Claudio Poli

I'm getting Excon's timeout exceptions also during save when using Fog.

Jonathan Hyman

I just upgraded from aws-sdk 1.5.8 to 1.7.0 to try it again and got a RequestTimeout again. Leaving my aws-sdk gem at 1.5.8.

Jonathan Hyman

And I'm using paperclip master, btw. 567086e is still causing RequestTimeout issues.

Jason Fleetwood-Boldt

I am seeing this same error too with Ruby 1.9.3, paperclip 3.3.1, aws-sdk 1.7.1.

indeed, as other said, downgrading aws-sdk to 1.5.8 fixes the problem for me.

Jason Fleetwood-Boldt

Dammit I spoke too soon. It looks like it works, but I am getting zero-byte files on S3 with this configuration. Will post update if I figure this out. Any ideas?

Jason Fleetwood-Boldt

Further testing, looks like this problem was introduced in aws-sdk 1.6.3. I tested all versions between 1.5.8 and 1.7.1 here are my results:

1.5.8 - works, but getting zero-byte files
1.6.0 - works, but getting zero-byte files
1.6.1 - works, but getting zero-byte files
1.6.2 - works, but getting zero-byte files
1.6.3 - AWS::S3::Errors::RequestTimeout
1.6.4 - AWS::S3::Errors::RequestTimeout
1.6.5 - AWS::S3::Errors::RequestTimeout
1.6.6 - AWS::S3::Errors::RequestTimeout
1.6.7 - AWS::S3::Errors::RequestTimeout
1.6.8 - AWS::S3::Errors::RequestTimeout
1.6.9 - AWS::S3::Errors::RequestTimeout
1.7.0 - AWS::S3::Errors::RequestTimeout
1.7.1 - AWS::S3::Errors::RequestTimeout

Since I am consistently getting zero-byte files, I have a feeling my zero-byte problem is something else. For that reason, I will follow up regarding that problem on #1096

Jon Yurek
Collaborator

Wow, that's quite thorough. Thanks for looking into that! It should give us some more info on where to look for issues.

Fábio Maia

Hey everyone,

I submitted the pull request 1189 to fix the issue in branch 2.7.
I executed all tests and all are green and I also tested the fix in a website that I have. I'm using my fork for while in that site which includes the fix.
Could you please homologate my fix and if possible create a newer gem to 2.7 version?

Yuval Kordov

Hey guys, blast from the past. I'm seeing this error almost every time I run a simple test using Paperclip 3.3.1 and aws-sdk 1.9.1. It drives me nuts, as it occasionally doesn't happen.

Here's the simple test:

  test "create user with valid photo and photo file name obfuscation" do
    %w[file.gif file.jpg file.png].each do |filename|
      user = create(:user, photo: fixture_file_upload("/files/#{filename}", MIME::Types.type_for(filename).first.content_type))
      assert user.photo?
      assert_match(/^#{Digest::SHA1.hexdigest(filename)}\-.{8}#{Regexp.escape(File.extname(filename))}\Z/, user.photo_file_name)
    end
  end

I've tried just testing a single fixture file upload and it times out just as often.

Jason Fleetwood-Boldt
jasonfb commented May 20, 2013

My zero-byte file problem was a problem in my own code -- I filed that separately.

did you try locking your aws-sdk to version 1.6.2 ? Try that and tell us if it works. We still have our aws-sdk gem locked at 1.6.2 as I do not believe this is fixed in any higher version (I only tested up to 1.7.1, if someone has information that this works in a version > 1.7.1 please post here)

Yuval Kordov

I just upgraded to using aws-sdk 1.10.0 and paperclip 3.4.2 and the timeouts still occur.

Jason Garber
jgarber commented May 21, 2013

Also using aws-sdk 1.10.0 and paperclip 3.4.2 and the timeouts still occur.

Jason Garber
jgarber commented May 21, 2013

Downgrading aws-sdk worked for me.

gem "aws-sdk", "= 1.6.2" # Bug https://github.com/thoughtbot/paperclip/issues/751
Yuval Kordov

That's a hell of a lot of patch levels to downgrade to... :|

Jason Fleetwood-Boldt
jasonfb commented May 21, 2013

@uberllama -- that seem consistent & correct, the bug is NOT fixed in later versions of the aws-sdk gem, it is CAUSED BY later versions and AFAIK, has not yet been fixed in later versions. Consistent with what other people are saying, you must downgrade. If someone would like to bring this to the aws-sdk team's attention, that would be great.

All of the rest of of us have locked our aws-sdk to the working version and not upgraded beyond that version for this very reason. if we hear of a later version that it works in, that would be good news but as of yet I have not heard of any such later version that it works under.

Yuval Kordov

The interesting thing is I only ever encounter timeouts during tests, not in actual use. Maybe that's been blind luck.

I'm going to post this thread to the aws-sdk issues.

Yuval Kordov uberllama referenced this issue in aws/aws-sdk-ruby May 21, 2013
Closed

S3 write timeout (Ruby 2.0) #241

Jason Garber
jgarber commented May 21, 2013

Thanks @uberllama, for posting it to aws-sdk. Sounds like a similar problem. I'm on Ruby 2.0.0-p0 and my bucket's in eu-west-1

Claudio Poli

No one with the issue tried #1189 ?

Trevor Rowe

Thanks @uberllama for brining this issue to my attention. Amazon S3 is returns a RequesTimeout error when it gives up waiting for additional data from the client. This generally happens when the 'Content-Length' header of the request incorrectly reports the size of the payload it sends. I'll see what I can do about reproducing the issue and see if we can't get this resolved.

Yuval Kordov

Thanks Trevor, much appreciated!

Jason Garber
jgarber commented May 21, 2013
Trevor Rowe

I'm looking into this issue now. Can everyone still experiencing this issue report:

  • The version of Ruby you are using
  • Your environments default external encoding (Encoding.default_external)
  • Your ENV['LANG']
  • If it occurs in test cases or production code
  • If it is a test case, please provide the test case

I'm currently unable to reproduce this issue, so your help would be very much appreciated.

Jonathan Hyman

ruby 1.9.3p392 (2013-02-22 revision 39386) [x86_64-linux]
Default external encoding: #Encoding:UTF-8
ENV["LANG"]: "en_US.utf8"
Happens in real code

Yuval Kordov

Ruby: 2.0-p1.9.5 (also occured with p0)
Encoding: UTF-8
ENV["LANG"]: en_CA.UTF-8

User model as follows:

class User
  has_attached_file :photo, 
      styles: { original: '300x300#', thumb: '80x80#' },
      default_url: "/assets/users/default_photo_:style.jpg",
      use_timestamp: false,
      s3_permissions: :public_read
end

Test case as follows (file.png is a 1k png in my test/fixtures/files folder):

require 'test_helper'

class UserTest < ActiveSupport::TestCase
  include ActionDispatch::TestProcess

  test "create user with valid photo and photo file name obfuscation" do
      user = create(:user, photo: fixture_file_upload("/files/file.png", "image/png"))
      assert user.photo?
  end
end
Trevor Rowe

@uberllama The #fixture_file_upload accepts a 3rd argument (defaults binary = false). If you pass true as the third argument, does your test pass?

Yuval Kordov

If I run the test independently, it doesn't seem to time out (after 10 runs). But as soon as I run it with other test cases in the class it times out just as before.

Trevor Rowe

Could you enable HTTP logging for your test. It might be helpful to see whats going over the wire. You can do this by adding the following to your #has_attached_file call.

:s3_options => { :http_wire_trace => true, :logger => Logger.new($stdout) },

Feel free to set :logger to whatever makes the most sense.

Ashish Tonse
atonse commented May 24, 2013

Echoing @uberllama , I'm having the same issue, only in my Cucumber test suite. It goes just fine when I run the individual feature but almost always crashes when run as part of the whole suite. Could be an issue of some state left over from a previous upload?

Ruby 2.0.0-p195
Rails 3.2.13
aws-sdk 1.10.0
ENV["LANG"] = "en_US.UTF-8"

Yuval Kordov

I can't get the damned thing to time out anymore. But I guarantee as soon as I finish posting this, the next run will timeout! Inconsistency is pure aggravation. :)

Anyway:

opening connection to uberllama-test.s3.amazonaws.com:443...
opened
starting SSL for uberllama-test.s3.amazonaws.com:443...
SSL established
<- "PUT /users/photos/210/original/616d4ce8101ea057246f6deb70da6a7d89f440c5-bdef6043.png HTTP/1.1\r\nContent-Type: image/png\r\nContent-Length: 348\r\nX-Amz-Acl: public-read\r\nUser-Agent: aws-sdk-ruby/1.10.0 ruby/2.0.0 x86_64-darwin11.4.2\r\nDate: Fri, 24 May 2013 21:42:12 GMT\r\nAuthorization: AWS [snip]:[snip]=\r\nAccept-Encoding: gzip;q=1.0,deflate;q=0.6,identity;q=0.3\r\nAccept: */*\r\nHost: uberllama-test.s3.amazonaws.com\r\n\r\n"
-> "HTTP/1.1 200 OK\r\n"
-> "x-amz-id-2: [snip]\r\n"
-> "x-amz-request-id: [snip]\r\n"
-> "Date: Fri, 24 May 2013 21:42:13 GMT\r\n"
-> "ETag: \"1f7d0a0bb3e158583ba8c9ce9e16f811\"\r\n"
-> "Content-Length: 0\r\n"
-> "Server: AmazonS3\r\n"
-> "\r\n"
reading 0 bytes...
-> ""
read 0 bytes
Conn keep-alive
[AWS S3 200 0.582997 0 retries] put_object(:acl=>:public_read,:bucket_name=>"uberllama-test",:content_length=>348,:content_type=>"image/png",:data=>Paperclip::FileAdapter: file20130524-8556-imz6bt20130524-8556-vyqwm1,:key=>"users/photos/210/original/616d4ce8101ea057246f6deb70da6a7d89f440c5-bdef6043.png")  

<- "PUT /users/photos/210/thumb/616d4ce8101ea057246f6deb70da6a7d89f440c5-bdef6043.png HTTP/1.1\r\nContent-Type: image/png\r\nContent-Length: 331\r\nX-Amz-Acl: public-read\r\nUser-Agent: aws-sdk-ruby/1.10.0 ruby/2.0.0 x86_64-darwin11.4.2\r\nDate: Fri, 24 May 2013 21:42:12 GMT\r\nAuthorization: AWS [snip]:[snip]=\r\nAccept-Encoding: gzip;q=1.0,deflate;q=0.6,identity;q=0.3\r\nAccept: */*\r\nHost: uberllama-test.s3.amazonaws.com\r\n\r\n"
-> "HTTP/1.1 200 OK\r\n"
-> "x-amz-id-2: [snip]\r\n"
-> "x-amz-request-id: [snip]\r\n"
-> "Date: Fri, 24 May 2013 21:42:13 GMT\r\n"
-> "ETag: \"485842d59a1ef3ef143e92c4a7c29561\"\r\n"
-> "Content-Length: 0\r\n"
-> "Server: AmazonS3\r\n"
-> "\r\n"
reading 0 bytes...
-> ""
read 0 bytes
Conn keep-alive
[AWS S3 200 0.213178 0 retries] put_object(:acl=>:public_read,:bucket_name=>"uberllama-test",:content_length=>331,:content_type=>"image/png",:data=>Paperclip::FileAdapter: file20130524-8556-imz6bt20130524-8556-vyqwm120130524-8556-so3hnw20130524-8556-qtpexh,:key=>"users/photos/210/thumb/616d4ce8101ea057246f6deb70da6a7d89f440c5-bdef6043.png")  

<- "HEAD /users/photos/210/original/616d4ce8101ea057246f6deb70da6a7d89f440c5-bdef6043.png HTTP/1.1\r\nContent-Type: \r\nUser-Agent: aws-sdk-ruby/1.10.0 ruby/2.0.0 x86_64-darwin11.4.2\r\nDate: Fri, 24 May 2013 21:42:13 GMT\r\nAuthorization: AWS [snip]:[snip]\r\nAccept: */*\r\nHost: uberllama-test.s3.amazonaws.com\r\n\r\n"
-> "HTTP/1.1 200 OK\r\n"
-> "x-amz-id-2: [snip]\r\n"
-> "x-amz-request-id: [snip]\r\n"
-> "Date: Fri, 24 May 2013 21:42:14 GMT\r\n"
-> "Last-Modified: Fri, 24 May 2013 21:42:13 GMT\r\n"
-> "ETag: \"1f7d0a0bb3e158583ba8c9ce9e16f811\"\r\n"
-> "Accept-Ranges: bytes\r\n"
-> "Content-Type: image/png\r\n"
-> "Content-Length: 348\r\n"
-> "Server: AmazonS3\r\n"
-> "\r\n"
Conn keep-alive
[AWS S3 200 0.09868 0 retries] head_object(:bucket_name=>"uberllama-test",:key=>"users/photos/210/original/616d4ce8101ea057246f6deb70da6a7d89f440c5-bdef6043.png")  

<- "HEAD /users/photos/210/thumb/616d4ce8101ea057246f6deb70da6a7d89f440c5-bdef6043.png HTTP/1.1\r\nContent-Type: \r\nUser-Agent: aws-sdk-ruby/1.10.0 ruby/2.0.0 x86_64-darwin11.4.2\r\nDate: Fri, 24 May 2013 21:42:13 GMT\r\nAuthorization: AWS [snip]:[snip]\r\nAccept: */*\r\nHost: uberllama-test.s3.amazonaws.com\r\n\r\n"
-> "HTTP/1.1 200 OK\r\n"
-> "x-amz-id-2: [snip]\r\n"
-> "x-amz-request-id: [snip]\r\n"
-> "Date: Fri, 24 May 2013 21:42:14 GMT\r\n"
-> "Last-Modified: Fri, 24 May 2013 21:42:13 GMT\r\n"
-> "ETag: \"485842d59a1ef3ef143e92c4a7c29561\"\r\n"
-> "Accept-Ranges: bytes\r\n"
-> "Content-Type: image/png\r\n"
-> "Content-Length: 331\r\n"
-> "Server: AmazonS3\r\n"
-> "\r\n"
Conn keep-alive
[AWS S3 200 0.097156 0 retries] head_object(:bucket_name=>"uberllama-test",:key=>"users/photos/210/thumb/616d4ce8101ea057246f6deb70da6a7d89f440c5-bdef6043.png")  

<- "DELETE /users/photos/210/original/616d4ce8101ea057246f6deb70da6a7d89f440c5-bdef6043.png HTTP/1.1\r\nContent-Type: \r\nUser-Agent: aws-sdk-ruby/1.10.0 ruby/2.0.0 x86_64-darwin11.4.2\r\nDate: Fri, 24 May 2013 21:42:13 GMT\r\nAuthorization: AWS [snip]:[snip]\r\nAccept-Encoding: gzip;q=1.0,deflate;q=0.6,identity;q=0.3\r\nAccept: */*\r\nHost: uberllama-test.s3.amazonaws.com\r\n\r\n"
-> "HTTP/1.1 204 No Content\r\n"
-> "x-amz-id-2: [snip]\r\n"
-> "x-amz-request-id: [snip]\r\n"
-> "Date: Fri, 24 May 2013 21:42:14 GMT\r\n"
-> "Server: AmazonS3\r\n"
-> "\r\n"
Conn keep-alive
[AWS S3 204 0.09218 0 retries] delete_object(:bucket_name=>"uberllama-test",:key=>"users/photos/210/original/616d4ce8101ea057246f6deb70da6a7d89f440c5-bdef6043.png")  

<- "DELETE /users/photos/210/thumb/616d4ce8101ea057246f6deb70da6a7d89f440c5-bdef6043.png HTTP/1.1\r\nContent-Type: \r\nUser-Agent: aws-sdk-ruby/1.10.0 ruby/2.0.0 x86_64-darwin11.4.2\r\nDate: Fri, 24 May 2013 21:42:13 GMT\r\nAuthorization: AWS [snip]:[snip]\r\nAccept-Encoding: gzip;q=1.0,deflate;q=0.6,identity;q=0.3\r\nAccept: */*\r\nHost: uberllama-test.s3.amazonaws.com\r\n\r\n"
-> "HTTP/1.1 204 No Content\r\n"
-> "x-amz-id-2: [snip]\r\n"
-> "x-amz-request-id: [snip]\r\n"
-> "Date: Fri, 24 May 2013 21:42:14 GMT\r\n"
-> "Server: AmazonS3\r\n"
-> "\r\n"
Conn keep-alive
[AWS S3 204 0.172054 0 retries] delete_object(:bucket_name=>"uberllama-test",:key=>"users/photos/210/thumb/616d4ce8101ea057246f6deb70da6a7d89f440c5-bdef6043.png")  
Yuval Kordov

For what its worth, I haven't encountered a timeout in the last two days after adding the binary boolean to my fixture file upload call. It did happen intermittently after I first changed it though. Bizarre.

Yuval Kordov

I take it back. Seeing timeouts again today, so its still inconsistent.

Scott Carleton

Ruby: 2.0-p0
LANG=en_US.UTF-8
#Encoding:UTF-8
aws-sdk (1.9.5)

This is happening in production for me but thankfully I'm using delayed_paperclip so I can see them and easily retry them in Resque. The retry appears to always go through.

@trevorrowe any update on this?

Trevor Rowe

@ScotterC I haven't abandoned this, just sidetracked.

It sounds like you are only getting this error only on occasion (not on every request). This is likely not releated to the string encoding issue that causes this to fail for every request (which I am still unable to reproduce locally).

This is very possibly caused by transient network errors. Currently the aws-sdk only retries throttling errors, and 500 level errors. 400 level errors are generally caused by bad parameters (e.g. no such bucket) and are not retried. In this case, it sounds like it would be very helpful if the SDK automatically retried the 400 RequestTimeout errors.

Is anyone willing to reach out to me directly via email and help me recreate their particular failure case. I'm confident this issue will be easy to resolve if we can do this.

Rodrigo Oliveira

I believe I am having the same issue. Uploads are silently failing to save on S3. It started happening for me once I added 4 more attached files to the same model. Now the model has a total of 5 thumbnail images that get uploaded at the same time. Sometimes it works but it fails most of the time.

@ScotterC, I can get on email to help you dupe.

Scott Carleton

Good to hear @trevorrowe

Thankfully I'm in a better situation then most since I can periodically check and retry the uploads for production.

@goleador thanks but it sounds like we all really need to @trevorrowe to be able to duplicate this consistently. If you can help him we'd all appreciate it.

Rodrigo Oliveira

@trevorrowe let me know if I can assist

Ratnadeep Deshmane
rtdp commented June 06, 2013

I am seeing this consistently happening for me.
I am running ruby 2.0 with rails 3.2.12, paperclip 3.3.1 and aws-sdk 1.8.5.
For now, running with aws-sdk 1.6.2

Jonathan Otto
jotto commented June 09, 2013

Ruby 2.0, Paperclip 3.4.2, aws-sdk 1.11.0 on HEROKU gives me intermittent AWS::S3::Errors::RequestTimeout.... strangely, from my laptop, I cannot reproduce it.

    AWS::S3::Errors::RequestTimeout: Your socket connection to the server was not read from or written to within the timeout period. Idle connections will be closed.
        from /app/vendor/bundle/ruby/2.0.0/gems/aws-sdk-1.11.0/lib/aws/core/client.rb:360:in `return_or_raise'
        from /app/vendor/bundle/ruby/2.0.0/gems/aws-sdk-1.11.0/lib/aws/core/client.rb:461:in `client_request'
        from (eval):3:in `put_object'
        from /app/vendor/bundle/ruby/2.0.0/gems/aws-sdk-1.11.0/lib/aws/s3/s3_object.rb:1704:in `write_with_put_object'
        from /app/vendor/bundle/ruby/2.0.0/gems/aws-sdk-1.11.0/lib/aws/s3/s3_object.rb:608:in `write'
        from /app/vendor/bundle/ruby/2.0.0/gems/paperclip-3.4.2/lib/paperclip/storage/s3.rb:323:in `block in flush_writes'
        from /app/vendor/bundle/ruby/2.0.0/gems/paperclip-3.4.2/lib/paperclip/storage/s3.rb:300:in `each'
        from /app/vendor/bundle/ruby/2.0.0/gems/paperclip-3.4.2/lib/paperclip/storage/s3.rb:300:in `flush_writes'
        from /app/vendor/bundle/ruby/2.0.0/gems/paperclip-3.4.2/lib/paperclip/attachment.rb:221:in `save'
        from /app/vendor/bundle/ruby/2.0.0/gems/paperclip-3.4.2/lib/paperclip/instance_methods.rb:17:in `block in save_attached_files'
        from /app/vendor/bundle/ruby/2.0.0/gems/paperclip-3.4.2/lib/paperclip/instance_methods.rb:10:in `block in each_attachment'
        from /app/vendor/bundle/ruby/2.0.0/gems/paperclip-3.4.2/lib/paperclip/instance_methods.rb:9:in `each'
        from /app/vendor/bundle/ruby/2.0.0/gems/paperclip-3.4.2/lib/paperclip/instance_methods.rb:9:in `each_attachment'
        from /app/vendor/bundle/ruby/2.0.0/gems/paperclip-3.4.2/lib/paperclip/instance_methods.rb:16:in `save_attached_files'
        from /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.0.rc1/lib/active_support/callbacks.rb:427:in `_run__1555452637204736291__save__callbacks'
        from /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.0.rc1/lib/active_support/callbacks.rb:80:in `run_callbacks'
    ... 13 levels...
        from /app/vendor/bundle/ruby/2.0.0/gems/activerecord-4.0.0.rc1/lib/active_record/transactions.rb:326:in `block in with_transaction_returning_status'
        from /app/vendor/bundle/ruby/2.0.0/gems/activerecord-4.0.0.rc1/lib/active_record/connection_adapters/abstract/database_statements.rb:202:in `block in transaction'
        from /app/vendor/bundle/ruby/2.0.0/gems/activerecord-4.0.0.rc1/lib/active_record/connection_adapters/abstract/database_statements.rb:210:in `within_new_transaction'
        from /app/vendor/bundle/ruby/2.0.0/gems/activerecord-4.0.0.rc1/lib/active_record/connection_adapters/abstract/database_statements.rb:202:in `transaction'
        from /app/vendor/bundle/ruby/2.0.0/gems/activerecord-4.0.0.rc1/lib/active_record/transactions.rb:209:in `transaction'
        from /app/vendor/bundle/ruby/2.0.0/gems/activerecord-4.0.0.rc1/lib/active_record/transactions.rb:323:in `with_transaction_returning_status'
        from /app/vendor/bundle/ruby/2.0.0/gems/activerecord-4.0.0.rc1/lib/active_record/persistence.rb:220:in `update'
Trevor Rowe

Thank you @goleador for offering to help. Would you please email me directly at trevrowe at amazon dot com? Thanks.

Trevor Rowe

I still have not been able to reproduce the issue locally, but I've committed two changes that should address some of the symptoms. You can view the pull request here: aws/aws-sdk-ruby#276

I would be very interested in having users here try this out and giving feedback on if this resolves the issue or lessens the frequency. Thanks!

Scott Carleton

@trevorrowe Thanks Trevor!

Trevor Rowe

I just released version 1.12.0 of the aws-sdk gem. This release contains a fix that should hopefully resolve this issue. A handful of users tested this out and reported positive results. If anyone who has been having issues with this could give it a try, I would appreciate the feedback. Thanks!

Scott Carleton

@trevorrowe Thanks for your hard work. Were you ever able to replicate it on your machine?

Trevor Rowe

@ScotterC Unfortunately, I was unable to reproduce it locally. If this issue persists for anyone, please reach out to me and I'll be happy to keep working on this.

Yuval Kordov

Cheers Trevor, will try it out asap.

Jonathan Roy

@trevorrowe I still have the issue with 1.12.0

Trevor Rowe

There are two related issues. The commit I made (aws/aws-sdk-ruby#276) addresses only one of the issues. A quick summary:

  • When reading request bodies, Amazon S3 may return a request timeout error if it has waited too long
  • This error can happen when:
    • The connection is flakey or really slow
    • Their is a transient networking error that drops or corrupts some of the data, causing the request body size not to match the Content-Length header
    • The Content-Length is incorrectly calculated for a request payload

The first two scenarios are handled by my commit. They treat the 400 error returned by Amazon S3 as a retryable error (generally 400 level errors are client errors and are not retried). The 3rd cause is a little tricker.

What is (very likely) happening is there is an encoding issue. I have a 976B large png on my desktop. If I open and read the file with the wrong encoding I can get some ugly behaviors:

$ ruby -e "puts Encoding.default_external"
UTF-8

# oops, off by 14 bytes!!!
$ ruby -e "puts File.open('test.png', 'r').read.size"
962

# same wrong result
$ ruby -E UTF-8 -e "puts File.open('test.png', 'r').read.size"
962

# correct file size, by accident
$ ruby -E ASCII-8BIT -e "puts File.open('test.png', 'r').read.size"
976

# correct
ruby -E BINARY -e "puts File.open('test.png', 'r').read.size"
976

# opening the file in binary mode is also correct
ruby -e "puts File.open('test.png', 'rb').read.size"
976

# even if the default encoding is wrong
ruby -E UTF-8 -e "puts File.open('test.png', 'rb').read.size"
976

# this works too
ruby -e "puts File.open('test.png', 'r', :encoding => 'BINARY').read.size"
976

Long story short, what appears to be happening is somewhere the ACTUAL source size is being determined (in my example, this would be 976). This is then used to set the Content-Length header, but then fewer bytes are sent (in this example only 962 are sent down the socket). Amazon S3 sits waiting for the additional 14 bytes and times out.

My retry patch will not help in this scenario. It will simply recreate the same steps that led to the original timeout. I have been unable to find any code path in the SDK or paperclip where the file is being read incorrectly (obviously I must be missing something). It may be simple enough that I can force the encoding to BINARY on every value before it is read. I hesitate to do that until we can isolate the source of the error. I do not want to mask any other bigger issue.

@jonathanroy Would you be available at some time where we could meet up and debug this together? I would like to generate a minimal test case to reproduce the issue, add a test and then resolve this finally.

Jonathan Roy

@trevorrowe add me on skype (jonathanroy06) and let's talk today if you can.

Trevor Rowe

@jonathanroy I'll contact you directly. Thanks!

Prem Sichanugrist
Collaborator

@jonathanroy do you think this issue is resolved in 1.14.x? I'm not sure if we (Paperclip) should do anything else to solve the issue or not, and if this issue can be closed.

Scott Carleton

@sikachu @trevorrowe I've had 1.14 in production with a lot of images being uploaded and it looks resolved to me.

Jonathan Hyman

I just updated to aws-sdk 1.14.1 and paperclip 3.5.0 to test out if it was fixed. Attachments that don't have pre-processing are uploading fine, but attachments that do have pre-processing are timing out with

Your socket connection to the server was not read from or written to within the timeout period. Idle connections will be closed

It could be that since the preprocessing is running advpng and optipng for compression that it's taking too long. I also posted this in aws/aws-sdk-ruby#241 but for me something is still broken, going to downgrade.

Trevor Rowe

@jonhyman I would be very interested in working with you to try to replicate the issue and fix the timeout errors for the pre-processed images. I have a few ideas that could resolve the issue, but I am unable to test them myself (I can do replicate the issue). Would you be willing to email me at trevrowe at amazon dot com and setting aside some time to troubleshoot this?

Jonathan Hyman

Sure.

Clarke Brunsdon

@trevorrowe @jonhyman Did you two ever have success identifying or fixing the issues? I'm running into the exact same problem.

Jason Fleetwood-Boldt

We upgraded to aws-sdk 1.15.0 and paperclip 3.4.2 and things are looking solid (no timeouts). If we encounter the timeouts, I'll post here again.

Jason Fleetwood-Boldt

also the processing itself was hitting heroku's 30 second timeout limit (which is a separate problem from the request timeout described in this thread is about), we used this to do the processing in the background https://github.com/jrgifford/delayed_paperclip/

Jonathan Hyman

@cbrunsdon, @trevorrowe and I paired on it a few weeks ago and were able to reproduce the issue. Trevor got enough information in the repro to do further investigation and fix. This was still an issue with aws-sdk 1.15.0 when we tested it.

Clarke Brunsdon

@trevorrowe For the record, I believe the issue we ran into is a timeout when attempting to upload a zero-length file.

Trevor Rowe

Sorry for the silence. I've been out of the office for all but three days out of the last three weeks. I wan't to give special thanks to @jonhyman for helping me reproduce the issue. I will try to devote some time to this today.

Christopher Bauer

aws-sdk 1.18.0 and paperclip 3.5.1 still causes this issue. Any update for us?

scaryguy scaryguy referenced this issue in aws/aws-sdk-ruby September 16, 2013
Closed

Net::OpenTimeout - execution expired #362

scaryguy

Hi there...

I'm on Ubuntu 12.04 installed with VMWare Player.

I have Ruby 2.0 and Rails 4 installed. I'm using latest master branch.

Paperclip 3.5.1 and aws-sdk 1.11.1.

I'm experiencing this "execution timeout" issue in my development environment.

I can save images to AWS in production but I can't do it in development.

Any suggestions?

UPDATE: I've tried aws-sdk 1.18.0 and still same issue...

scaryguy

Hi peeps...

Can't decide on how to feel. I'm a little bit angry for losing almost one month because of this issue. But at the other hand, I'm happy because issue is resoleved. Do you know how?

ALL was a DNS issue...

After me changing my virtual machines and physical OS's DNS settings to use Google DNS, everthing was FIXED!!!!!!

I DON'T know who is responsible of this situation? Is it my ISP provider? Who I have to be angry with??

Here is that regular Google DNS settings:

8.8.8.8
8.8.4.4
Jonathan Hyman

@trevorrowe Were you ever able to fix this? I'm going to attempt to update again starting tomorrow when you drop the nokogiri < 1.6.0 requirement but want to know if it's even worth attempting yet.

Trevor Rowe

I have not taken a look at this in a while. I went digging through my email, and I was unable to find the sample attachment processor you were using that was reproducing the bug. If you can (re)send me that processor, I'm hoping I can clear this bug out. I have a good amount of time this week I could devote to the problem.

Jonathan Hyman
Kobe Osei-Akoto

Are you on the latest version of the gem?

Trevor is the man... I was able to resolve the same issue with his help by running :

  1. gem search aws-sdk via the command line -> lets you know what the latest version of the aws-sdk gem is
  2. gem install aws-sdk.
  3. I ran bundle update afterwards, but I was still running version 1.11.1 (in my case). I specified version '1.26.0' via (gem 'aws-sdk', '1.26.0') in my Gemfile.
  4. Ran bundle once again...

BOOM!

Hope that helps..

Claudio Poli

bundle outdated --strict
bundle update aws-sdk

Trevor Rowe

Just to update, I am currently (as in right now) working on this. Intermittent request timeouts caused by latent network issues should be fixed. The newer versions of the SDK retry these by default now.

I am still tracking down the other issues. Thanks to @jonhyman I now have a case I can reproduce locally. I am tracking the issue down, but it appears to be an issue where Paperclip::FileAdapater objects are reporting an improper value when responding to #size. There are multiple scenarios I have been able to create that can cause this behavior.

The reason older versions of the Ruby SDK are not affected is they don't ask the object for its size. Instead it simply reads the object into memory and gets the bytesize from the actual data, which is always correct.

Why does the #size matter so much?

It is sent along to S3 as the Content-Length header. S3 receives the full file and then waits for the "rest" based on the discrepancy between the actual file size and the value reported in Content-Length.

In one of my examples, the FileAdapter indicates the file is 976 bytes, when the file on disk is actually 757 bytes. The 757 bytes are read from disk and then S3 sits waiting for the additional bytes until it times out. The discrepancy appears to creep in during post processing.

I'll update this issue once the dust settles.

Trevor Rowe

As mentioned above, I was able to reproduce the issue by attempting to upload an attachment that is processed. In the example code I was given the issue can be tracked down to how a particular processor modified the file. See the following made up example that produces the buggy behavior:

require 'tempfile'
require 'paperclip'

tmpfile = Tempfile.new(['tempfile', '.png'])

`cp test.png #{tmpfile.path}`

# both report the correct size of 976 bytes
puts tmpfile.size, File.size(tmpfile.path)
# 976
# 976

# perform some processing of the png
Paperclip.run("optipng", "-zc1-9 -zm1-9 -zs0-2 -f0-5 #{tmpfile.path}")

# oops! tmpfile.size returns 976, should be 757, ** File.size is correct **
puts tmpfile.size, File.size(tmpfile.path)
# 976
# 757

Paperclip takes the result from the processor(s) and then wraps then in an IO adapter. In this case, the FileAdapter is chosen. This adapter creates a tempfile and would normally correct the size issue, except it does the following on line 15:

# second oops! 
@size = File.size(@target)

Calling File.size with a File/Tempfile object will use that objects #size attribute. If this were changes to File.size(@target.path), then the correct size would be found and then there would be no issue.

I can not be certain, but I suspect other users experiencing this issue are running into similar issues. One possible fix is to update aws-sdk to use File.size(object.path) instead of object.size on any object that responds to #path. Essentially, the SDK is being bitten by trusting the #size attribute. Secondly, a one-line patch to Paperclip::FileAdapter might potentially correct a number of processors that return bad Tempfiles.

At this point, I'm inclined to make/submit both changes.

Thoughts?

Trevor Rowe trevorrowe referenced this issue from a commit in aws/aws-sdk-ruby November 19, 2013
Trevor Rowe Now using File.size to determine file size for File/Tempfile objects.
It is possible for a File/Tempfile to report an incorrect value
from `#size`.  This change causes the SDK to prefer the response
from `File.size(file.path)` over `file.size`.

See thoughtbot/paperclip#751
9055bdc
Trevor Rowe

Version 1.28.0 of the aws-sdk has been released. I would appreciate users that have locked to an older version to give this a try. This release contains the fixes I detailed above.

Jonathan Hyman

Works for me! Thanks, @trevorrowe!

brettv

@trevorrowe, it appears that aws-sdk 1.28.0 has resolved the issue for me! (fingers crossed) Thanks for all the hard work tracking down the #size issue.

Federico Carrone

With aws-sdk 1.10 i had this isuee. With aws-sdk 1.30.0 everything works fine.

jasonivers

I'm running into this issue again with aws-sdk 1.31.0, paperclip 3.5.2. My file encoding is set as binary.

The issue occurs when doing any processing on a file that alters the file size from the original (as mentioned above)... in my case I have some TIFF files coming across with headers/profiles (from Photoshop) that make RMagick barf, so I was stripping them in the validation process (where I have to do various operations with RMagick to ensure image files meet minimum standards).

I have moved this process to the code that is creating the file (reading a remote file, writing a local file), and I no longer get this error... however, it seems to me that doing processing on a file that has already been read should not cause an S3 timeout error, as the file being pushed to S3 should be the one that Paperclip is already referencing, not the original.

Josh Cutler

I'm seeing the same thing as jasonivers

jasonivers

I looked at the code from the most recent referenced commit and fixed this issue (for me) by moving the path case to the bottom of the case statement in lib/aws/s3/data_options.rb (in the AWS-SDK gem). I don't use AWS-SDK other than with Paperclip, so I have no idea what effect that will have on any other uses of the gem, but it did fix my issue (and seemed to make it faster to write, as well).

Kevin Watt

I'm also seeing the same thing as jasonivers. aws-sdk 1.35 and paperclip 3.5.2

Did you fork the aws-sdk gem, or report the issue to them yet?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Something went wrong with that request. Please try again.