Ignoring failed reads during tar generation

[scruti]

Resolves #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 methods 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 since is related to file reading and seems to appear randomly, 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:

  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 🎉

I marked that it resolves the closed Issue #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'

[coveralls]

Coverage remained the same when pulling d441168 on scruti:fix-tar-read-error into 447bfee on rainforestapp:master.

[coveralls]

Coverage remained the same when pulling ce0f279 on scruti:fix-tar-read-error into 38b4810 on rainforestapp:master.

[jipiboily]

Interesting. I'll have to read about it a bit more, I don't have much time now.

@ukd1 @smathieu @paul: thoughts?

[jipiboily]

FYI, we just decided to deprecate Fourchette. You can (and probably should) use the Heroku review apps instead which was inspired by Fourchette.

https://devcenter.heroku.com/articles/github-integration-review-apps

Thanks!

[ukd1]

Closing this, due to deprecation of Fourchette! So long and thanks for all the fish!