rainforestapp/fourchette — pull request #51 by scruti (2014-12-12 09:57:24+00:00)
Title: Ignoring failed reads during tar generation

Resolves rainforestapp/fourchette#24

Trying to use Fourchette with our Rails app, I run in a recurrent error: Fork app was created, DB data was copied, PR message was generated, but the generated fork was showing a standard "Welcome to Heroku app..." message.

Checking logs I found there was an error during the Tarball process.
I spent one day trying everything. Checking hooks, tracing the generated urls through Fourchette method calls, checking the Heroku's API call... deleting the Fourchette app and configuring it again... Nothing worked, we always had the same problem.
Though maybe was a naming problem, but running an `heroku run 'ls tmp'` wasn't showing any tarball file.

Finally I found the cause:
>2014-12-11T23:11:42.185216+00:00 app[web.1]: I, [2014-12-11T23:11:42.185005 #11] INFO -- : Tarball to URL as a service in progress...
**2014-12-11T23:11:42.178631+00:00 app[web.1]: tar: .: file changed as we read it**

This is a `tar` command error, doesn't seem to be too serious issue, and I can guess that is related to generation on tarball inside the same folder that we're compressing. So I read about how to solve it: http://www.ensode.net/roller/dheffelfinger/entry/tar_failing_with_error_message
About the `--ignore-failed-read` flag don't worry, is not a "I will ignore everything", it just:
> Do not exit unsuccessfully merely because an unreadable file was encountered.

After found that I tested it aliasing `tar` to `tar --ignore-failed-read` with a callback at our Fourchette app:
```ruby
def before_all
logger.info 'Placeholder for before steps... (see callbacks.rb to override)'
logger.info 'Aliasing tar command with ignored failed read option...'
system("alias tar='tar --ignore-failed-read'")
end
```
Since then it's working! Fourchette is generating correctly the forks for our PRs and we had a little party in the office :tada:

I marked that it resolves the closed Issue rainforestapp/fourchette#24 , because even he's complaining about Node.js build, actually the cause of his build failing was the same as ours:
> 2014-07-21T17:20:19.141613+00:00 app[web.1]: tar: .: file changed as we read it
(extracted from his error trace)

Our full trace:
```
2014-12-11T23:10:49.916718+00:00 app[web.1]: 192.30.252.41 - - [11/Dec/2014 23:10:49] "POST /hooks HTTP/1.1" 200 15 0.0455
2014-12-11T23:10:50.321523+00:00 app[web.1]: I, [2014-12-11T23:10:50.321399 #11] INFO -- : Creating fourchette-pr-1146
2014-12-11T23:10:51.179338+00:00 app[web.1]: I, [2014-12-11T23:10:51.179193 #11] INFO -- : Copying configs from rankia to fourchette-pr-1146
2014-12-11T23:10:52.483403+00:00 app[web.1]: I, [2014-12-11T23:10:52.483272 #11] INFO -- : Copying addons from rankia to fourchette-pr-1146
2014-12-11T23:10:53.040417+00:00 app[web.1]: I, [2014-12-11T23:10:53.040265 #11] INFO -- : Adding heroku-postgresql:hobby-dev to fourchette-pr-1146
2014-12-11T23:10:57.506166+00:00 app[web.1]: I, [2014-12-11T23:10:57.506021 #11] INFO -- : Adding pgbackups:plus to fourchette-pr-1146
2014-12-11T23:10:58.747109+00:00 app[web.1]: I, [2014-12-11T23:10:58.746971 #11] INFO -- : Postgres not enabled on rankia. Skipping data copy.
2014-12-11T23:11:02.810692+00:00 app[web.1]: I, [2014-12-11T23:11:02.810575 #11] INFO -- : Cloning repository...
2014-12-11T23:11:33.416451+00:00 app[web.1]: I, [2014-12-11T23:11:33.416223 #11] INFO -- : Preparing tarball...
2014-12-11T23:11:42.185216+00:00 app[web.1]: I, [2014-12-11T23:11:42.185005 #11] INFO -- : Tarball to URL as a service in progress...
2014-12-11T23:11:42.178631+00:00 app[web.1]: tar: .: file changed as we read it
2014-12-11T23:11:42.868083+00:00 app[web.1]: E, [2014-12-11T23:11:42.867930 #11] ERROR -- : Fourchette::PullRequest crashed!
2014-12-11T23:11:42.868091+00:00 app[web.1]:
2014-12-11T23:11:42.868089+00:00 app[web.1]: Excon::Errors::BadRequest: Expected([200, 201, 202, 206, 304]) <=> Actual(400 Bad Request)
2014-12-11T23:11:42.868093+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/excon-0.39.5/lib/excon/middlewares/expects.rb:6:in `response_call'
2014-12-11T23:11:42.868115+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:25:in `dispatch'
2014-12-11T23:11:42.868119+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/actor.rb:322:in `block in handle_message'
2014-12-11T23:11:42.868095+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/excon-0.39.5/lib/excon/middlewares/response_parser.rb:8:in `response_call'
2014-12-11T23:11:42.868105+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/platform-api-0.2.0/lib/platform-api/client.rb:611:in `create'
2014-12-11T23:11:42.868122+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/tasks.rb:55:in `block in initialize'
2014-12-11T23:11:42.871765+00:00 app[web.1]:
2014-12-11T23:11:42.868110+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/fourchette-0.1.1/lib/fourchette/fork.rb:39:in `create'
2014-12-11T23:11:42.868117+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:67:in `dispatch'
2014-12-11T23:11:42.871768+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/excon-0.39.5/lib/excon/middlewares/response_parser.rb:8:in `response_call'
2014-12-11T23:11:42.871772+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/excon-0.39.5/lib/excon/connection.rb:233:in `request'
2014-12-11T23:11:42.868099+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/excon-0.39.5/lib/excon/connection.rb:233:in `request'
2014-12-11T23:11:42.868124+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/tasks/task_fiber.rb:13:in `block in create'
2014-12-11T23:11:42.871763+00:00 app[web.1]: Excon::Errors::BadRequest: Expected([200, 201, 202, 206, 304]) <=> Actual(400 Bad Request)
2014-12-11T23:11:42.871794+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/actor.rb:416:in `block in task'
2014-12-11T23:11:42.871817+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/actor.rb:416:in `block in task'
2014-12-11T23:11:42.871774+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/heroics-0.0.12/lib/heroics/link.rb:60:in `run'
2014-12-11T23:11:42.871820+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/tasks/task_fiber.rb:13:in `block in create'
2014-12-11T23:11:42.871783+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/fourchette-0.1.1/lib/fourchette/pull_request.rb:18:in `perform'
2014-12-11T23:11:42.871779+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/fourchette-0.1.1/lib/fourchette/fork.rb:20:in `update'
2014-12-11T23:11:42.871797+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/tasks/task_fiber.rb:13:in `block in create'
2014-12-11T23:11:42.871806+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/pool_manager.rb:41:in `_send_'
2014-12-11T23:11:42.871808+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/pool_manager.rb:123:in `method_missing'
2014-12-11T23:11:42.871767+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/excon-0.39.5/lib/excon/middlewares/expects.rb:6:in `response_call'
2014-12-11T23:11:42.871770+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/excon-0.39.5/lib/excon/connection.rb:363:in `response'
2014-12-11T23:11:42.871778+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/platform-api-0.2.0/lib/platform-api/client.rb:611:in `create'
2014-12-11T23:11:42.871787+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:25:in `dispatch'
2014-12-11T23:11:42.868107+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/fourchette-0.1.1/lib/fourchette/fork.rb:20:in `update'
2014-12-11T23:11:42.868113+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:25:in `public_send'
2014-12-11T23:11:42.871781+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/fourchette-0.1.1/lib/fourchette/fork.rb:39:in `create'
2014-12-11T23:11:42.871796+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/tasks.rb:55:in `block in initialize'
2014-12-11T23:11:42.868097+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/excon-0.39.5/lib/excon/connection.rb:363:in `response'
2014-12-11T23:11:42.868111+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/fourchette-0.1.1/lib/fourchette/pull_request.rb:18:in `perform'
2014-12-11T23:11:42.868120+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/actor.rb:416:in `block in task'
2014-12-11T23:11:42.871759+00:00 app[web.1]: D, [2014-12-11T23:11:42.871671 #11] DEBUG -- : Celluloid::PoolManager: async call `perform` aborted!
2014-12-11T23:11:42.871803+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/proxies/sync_proxy.rb:33:in `method_missing'
2014-12-11T23:11:42.871805+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/proxies/actor_proxy.rb:20:in `_send_'
2014-12-11T23:11:42.868101+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/heroics-0.0.12/lib/heroics/link.rb:60:in `run'
2014-12-11T23:11:42.871785+00:00 app[web.1]:	/app/vendor/bundle/ruby/2.0.0/gems/celluloid-0.15.2/lib/celluloid/calls.rb:25:in `public_send'
2014-12-11T23:11:42.871799+00:00 app[web.1]:	(celluloid):0:in `remote procedure call'
```