Can't push new app with ruby-buildpack v1.1.3 about ruby-buildpack

[cf-gitbot]

We have created an issue in Pivotal Tracker to manage this. You can view the current status of your issue at: https://www.pivotaltracker.com/story/show/82704022.

[jchesterpivotal]

Hi Will;

Ruby 2.1.3 is broken on buildpack 1.1.2, because of an unexpected change in the URLs of upstream binaries.

Buildpack 1.1.3 resolved this issue and added code to make the cause of errors more visible. It was bundled with cf-release v192.

Our releases page on github shows the exciting story of how it unfolded. :)

Cheers,

JC.

[TildeWill]

Thank you for the info about Ruby 2.1.3 on buildpack 1.1.2, but our issue is different. Yesterday, around 3pm PT we could not push a new app using Ruby 2.1.3 and buildpack 1.1.3. It failed during bundle install. Please reopen this issue.

[jchesterpivotal]

Sorry, I got confused. I was looking at the text of the original report, not the title.

What do you get from cf logs?

[TildeWill]

Here's the push, followed by cf logs

± mtm+wr |master ✗| → cf push clock-trash
Using manifest file /Users/pivotal/workspace/feedback/manifest.yml

Creating app clock-trash in org Pivotal Feedback / space staging as [email protected]...
OK

App clock-trash is a worker, skipping route creation
Uploading clock-trash...
Uploading app files from: /Users/pivotal/workspace/feedback
Uploading 1.4M, 830 files
OK
Binding service redis to app clock-trash in org Pivotal Feedback / space staging as [email protected]...
OK

Starting app clock-trash in org Pivotal Feedback / space staging as [email protected]...
OK
-----> Downloaded app package (800K)
Note: checking out '48a89f7ed6814cfce869bbaf9acb945baa10bd2f'.
You are in 'detached HEAD' state. You can look around, make experimental
changes and commit them, and you can discard any commits you make in this
state without impacting any branches by performing another checkout.
If you want to create a new branch to retain commits you create, you may
do so (now or later) by using -b with the checkout command again. Example:
  git checkout -b new_branch_name
Submodule 'buildpack-packager' (https://github.com/cf-buildpacks/buildpack-packager.git) registered for path 'buildpack-packager'
Cloning into 'buildpack-packager'...
Submodule path 'buildpack-packager': checked out 'fec9c4598a6496fb9fa02c288076dc120754b0b5'
-------> Buildpack version 1.1.3
-----> Compiling Ruby/Rails
-----> Using Ruby version: ruby-2.1.3
-----> Installing dependencies using 1.6.3
       Running: bundle install --without development:test --path vendor/bundle --binstubs vendor/bundle/bin -j4 --deployment
       Fetching source index from https://rubygems.org/
       Fetching source index from https://rails-assets.org/
       Fetching git://github.com/pivotal-feedback/pivotal_auth.git
       Using json 1.8.1
       Installing minitest 5.4.2
       Installing i18n 0.6.11
       Installing rake 10.3.2
       Installing thread_safe 0.3.4
       Installing builder 3.2.2
       Installing erubis 2.7.0
       Installing polyglot 0.3.5
       Installing mime-types 1.25.1
       Installing rack 1.5.2
       Installing arel 5.0.1.20140414130214
       Installing addressable 2.3.6
       Installing thor 0.19.1
       Installing hike 1.2.3
       Installing multi_json 1.8.4
       Installing tilt 1.4.1
       Installing angular-ui-bootstrap-rails 0.11.1
       Installing sass 3.2.19
       Installing timers 1.1.0
       Installing angularjs-rails 1.2.25
       Installing chunky_png 1.3.1
       Installing orm_adapter 0.5.0
       Installing fssm 0.2.10
       Installing connection_pool 2.0.0
       Installing request_store 1.1.0
       Installing execjs 2.2.1
       Installing multipart-post 2.0.0
       Installing hashie 3.3.1
       Installing htmlentities 4.3.2
       Installing jwt 1.0.0
       Installing systemu 2.6.4
       Installing mini_portile 0.6.0
       Installing mixpanel-ruby 1.5.0
       Installing httpclient 2.4.0
       Installing multi_xml 0.5.5
       Installing net-ldap 0.8.0
       Using bundler 1.6.3
       Installing rails-assets-angular 1.2.26
       Installing rails-assets-spin.js 2.0.1
       Installing newrelic_rpm 3.9.5.251
       Installing rails-assets-jquery 2.1.1
       Installing rails-assets-underscore 1.7.0
       Installing rails_stdout_logging 0.0.3
       Installing rails_serve_static_assets 0.0.2
       Installing redis 3.1.0
       Installing tzinfo 1.2.2
       Installing pg 0.17.1
       Installing rack-test 0.6.2
       Installing treetop 1.4.15
       Installing rack-protection 1.5.3
       Installing css_parser 1.3.5
       Installing select2-rails 3.5.9.1
       Installing sprockets 2.11.0
       Installing haml 4.0.5
       Installing puma 2.9.1
       Installing celluloid 0.15.2
       Installing uglifier 2.5.3
       Installing faraday 0.9.0
       Installing omniauth 1.2.2
       Installing compass 0.12.7
       Installing ckeditor 4.1.0
       Installing macaddr 1.7.1
       Installing rails-assets-bouil--angular-google-chart 0.0.11
       Installing rails-assets-ng-table 0.3.3
       Installing rails-assets-angular-spinner 0.5.1
       Installing rails-assets-select2 3.5.1
       Installing rails_12factor 0.0.2

FAILED
Server error, status code: 400, error code: 170001, message: Staging error: cannot get instances since staging failed

TIP: use 'cf logs clock-trash --recent' for more information

 |2.1.3| montgomery in ~/workspace/feedback
± mtm+wr |master ✗| → cf logs clock-trash --recent
Connected, dumping recent logs for app clock-trash in org Pivotal Feedback / space staging as [email protected]...

2014-11-14T09:15:56.41-0800 [API]     OUT Created app with guid b93a646c-d70d-4df8-a352-70a59ae44fd1
2014-11-14T09:16:11.04-0800 [DEA]     OUT Got staging request for app with id b93a646c-d70d-4df8-a352-70a59ae44fd1
2014-11-14T09:16:12.25-0800 [API]     OUT Updated app with guid b93a646c-d70d-4df8-a352-70a59ae44fd1 ({"state"=>"STARTED"})
2014-11-14T09:16:12.50-0800 [STG]     OUT -----> Downloaded app package (800K)
2014-11-14T09:16:13.54-0800 [STG]     ERR Note: checking out '48a89f7ed6814cfce869bbaf9acb945baa10bd2f'.
2014-11-14T09:16:13.54-0800 [STG]     ERR You are in 'detached HEAD' state. You can look around, make experimental
2014-11-14T09:16:13.54-0800 [STG]     ERR changes and commit them, and you can discard any commits you make in this
2014-11-14T09:16:13.54-0800 [STG]     ERR state without impacting any branches by performing another checkout.
2014-11-14T09:16:13.54-0800 [STG]     ERR If you want to create a new branch to retain commits you create, you may
2014-11-14T09:16:13.54-0800 [STG]     ERR do so (now or later) by using -b with the checkout command again. Example:
2014-11-14T09:16:13.54-0800 [STG]     ERR   git checkout -b new_branch_name
2014-11-14T09:16:13.74-0800 [STG]     OUT Submodule 'buildpack-packager' (https://github.com/cf-buildpacks/buildpack-packager.git) registered for path 'buildpack-packager'
2014-11-14T09:16:13.79-0800 [STG]     ERR Cloning into 'buildpack-packager'...
2014-11-14T09:16:14.06-0800 [STG]     OUT Submodule path 'buildpack-packager': checked out 'fec9c4598a6496fb9fa02c288076dc120754b0b5'
2014-11-14T09:16:14.23-0800 [STG]     OUT -------> Buildpack version 1.1.3
2014-11-14T09:16:14.48-0800 [STG]     OUT -----> Compiling Ruby/Rails
2014-11-14T09:16:15.45-0800 [STG]     OUT -----> Using Ruby version: ruby-2.1.3
2014-11-14T09:16:15.59-0800 [STG]     OUT -----> Installing dependencies using 1.6.3
2014-11-14T09:16:15.88-0800 [STG]     OUT        Running: bundle install --without development:test --path vendor/bundle --binstubs vendor/bundle/bin -j4 --deployment
2014-11-14T09:16:17.40-0800 [STG]     OUT        Fetching source index from https://rubygems.org/
2014-11-14T09:17:04.40-0800 [STG]     OUT        Fetching source index from https://rails-assets.org/
2014-11-14T09:17:08.89-0800 [STG]     OUT        Fetching git://github.com/pivotal-feedback/pivotal_auth.git
2014-11-14T09:17:30.19-0800 [STG]     OUT        Using json 1.8.1
2014-11-14T09:17:31.08-0800 [STG]     OUT        Installing minitest 5.4.2
2014-11-14T09:17:31.47-0800 [STG]     OUT        Installing i18n 0.6.11
2014-11-14T09:17:31.63-0800 [STG]     OUT        Installing rake 10.3.2
2014-11-14T09:17:32.10-0800 [STG]     OUT        Installing thread_safe 0.3.4
2014-11-14T09:17:32.19-0800 [STG]     OUT        Installing builder 3.2.2
2014-11-14T09:17:32.36-0800 [STG]     OUT        Installing erubis 2.7.0
2014-11-14T09:17:32.91-0800 [STG]     OUT        Installing polyglot 0.3.5
2014-11-14T09:17:33.03-0800 [STG]     OUT        Installing mime-types 1.25.1
2014-11-14T09:17:33.20-0800 [STG]     OUT        Installing rack 1.5.2
2014-11-14T09:17:33.31-0800 [STG]     OUT        Installing arel 5.0.1.20140414130214
2014-11-14T09:17:34.14-0800 [STG]     OUT        Installing addressable 2.3.6
2014-11-14T09:17:34.21-0800 [STG]     OUT        Installing thor 0.19.1
2014-11-14T09:17:34.62-0800 [STG]     OUT        Installing hike 1.2.3
2014-11-14T09:17:34.91-0800 [STG]     OUT        Installing multi_json 1.8.4
2014-11-14T09:17:35.40-0800 [STG]     OUT        Installing tilt 1.4.1
2014-11-14T09:17:35.66-0800 [STG]     OUT        Installing angular-ui-bootstrap-rails 0.11.1
2014-11-14T09:17:37.06-0800 [STG]     OUT        Installing sass 3.2.19
2014-11-14T09:17:38.87-0800 [STG]     OUT        Installing timers 1.1.0
2014-11-14T09:17:39.55-0800 [STG]     OUT        Installing angularjs-rails 1.2.25
2014-11-14T09:17:39.86-0800 [STG]     OUT        Installing chunky_png 1.3.1
2014-11-14T09:17:40.11-0800 [STG]     OUT        Installing orm_adapter 0.5.0
2014-11-14T09:17:40.26-0800 [STG]     OUT        Installing fssm 0.2.10
2014-11-14T09:17:40.69-0800 [STG]     OUT        Installing connection_pool 2.0.0
2014-11-14T09:17:40.90-0800 [STG]     OUT        Installing request_store 1.1.0
2014-11-14T09:17:41.28-0800 [STG]     OUT        Installing execjs 2.2.1
2014-11-14T09:17:41.63-0800 [STG]     OUT        Installing multipart-post 2.0.0
2014-11-14T09:17:42.33-0800 [STG]     OUT        Installing hashie 3.3.1
2014-11-14T09:17:42.43-0800 [STG]     OUT        Installing htmlentities 4.3.2
2014-11-14T09:17:42.74-0800 [STG]     OUT        Installing jwt 1.0.0
2014-11-14T09:17:43.08-0800 [STG]     OUT        Installing systemu 2.6.4
2014-11-14T09:17:43.62-0800 [STG]     OUT        Installing mini_portile 0.6.0
2014-11-14T09:17:44.32-0800 [STG]     OUT        Installing mixpanel-ruby 1.5.0
2014-11-14T09:17:44.87-0800 [STG]     OUT        Installing httpclient 2.4.0
2014-11-14T09:17:45.11-0800 [STG]     OUT        Installing multi_xml 0.5.5
2014-11-14T09:17:45.90-0800 [STG]     OUT        Installing net-ldap 0.8.0
2014-11-14T09:17:45.91-0800 [STG]     OUT        Using bundler 1.6.3
2014-11-14T09:17:46.52-0800 [STG]     OUT        Installing rails-assets-angular 1.2.26
2014-11-14T09:17:46.89-0800 [STG]     OUT        Installing rails-assets-spin.js 2.0.1
2014-11-14T09:17:47.02-0800 [STG]     OUT        Installing newrelic_rpm 3.9.5.251
2014-11-14T09:17:47.41-0800 [STG]     OUT        Installing rails-assets-jquery 2.1.1
2014-11-14T09:17:47.46-0800 [STG]     OUT        Installing rails-assets-underscore 1.7.0
2014-11-14T09:17:47.78-0800 [STG]     OUT        Installing rails_stdout_logging 0.0.3
2014-11-14T09:17:48.02-0800 [STG]     OUT        Installing rails_serve_static_assets 0.0.2
2014-11-14T09:17:48.62-0800 [STG]     OUT        Installing redis 3.1.0
2014-11-14T09:17:48.98-0800 [STG]     OUT        Installing tzinfo 1.2.2
2014-11-14T09:17:49.13-0800 [STG]     OUT        Installing pg 0.17.1
2014-11-14T09:17:49.32-0800 [STG]     OUT        Installing rack-test 0.6.2
2014-11-14T09:17:49.46-0800 [STG]     OUT        Installing treetop 1.4.15
2014-11-14T09:17:49.88-0800 [STG]     OUT        Installing rack-protection 1.5.3
2014-11-14T09:17:50.11-0800 [STG]     OUT        Installing css_parser 1.3.5
2014-11-14T09:17:50.65-0800 [STG]     OUT        Installing select2-rails 3.5.9.1
2014-11-14T09:17:50.90-0800 [STG]     OUT        Installing sprockets 2.11.0
2014-11-14T09:17:51.04-0800 [STG]     OUT        Installing haml 4.0.5
2014-11-14T09:17:51.56-0800 [STG]     OUT        Installing puma 2.9.1
2014-11-14T09:17:51.72-0800 [STG]     OUT        Installing celluloid 0.15.2
2014-11-14T09:17:52.88-0800 [STG]     OUT        Installing uglifier 2.5.3
2014-11-14T09:17:53.68-0800 [STG]     OUT        Installing faraday 0.9.0
2014-11-14T09:17:54.61-0800 [STG]     OUT        Installing omniauth 1.2.2
2014-11-14T09:17:55.08-0800 [STG]     OUT        Installing compass 0.12.7
2014-11-14T09:17:55.48-0800 [STG]     OUT        Installing ckeditor 4.1.0
2014-11-14T09:17:55.48-0800 [STG]     OUT        Installing macaddr 1.7.1
2014-11-14T09:17:55.84-0800 [STG]     OUT        Installing rails-assets-bouil--angular-google-chart 0.0.11
2014-11-14T09:17:55.92-0800 [STG]     OUT        Installing rails-assets-ng-table 0.3.3
2014-11-14T09:17:56.19-0800 [STG]     OUT        Installing rails-assets-angular-spinner 0.5.1
2014-11-14T09:17:56.46-0800 [STG]     OUT        Installing rails-assets-select2 3.5.1
2014-11-14T09:17:58.68-0800 [STG]     OUT        Installing rails_12factor 0.0.2
2014-11-14T09:17:59.03-0800 [API]     ERR Encountered error: Staging error: failed to stage application:
2014-11-14T09:17:59.03-0800 [API]     ERR Script exited with status 255

[jchesterpivotal]

Thanks.

To start, can you try vendoring gems before pushing? (They don't need to be checked into git, just physically present). In the past we've found apps with lots of dependencies failing at push time due to rubygems.org flakiness.

Second, if that doesn't work, can you point us to a repo? Like you, I don't see any other obvious errors in the log.

Cheers,

JC.

[TildeWill]

Running bundle package and then pushing a new app with Ruby 2.1.3 and ruby-buildpack 1.1.3 does indeed work. I don't think it's fair to attribute this to rubygems.org flakiness. 1.1.3 failed every time on bundling, while 1.1.2 pushed successfully during the same periods of time. I ran some more experiments for you:

+-----------------------+------------+-----------------------------------------------------------+
|                       | Ruby 2.1.1 |                        Ruby 2.1.3                         |
+-----------------------+------------+-----------------------------------------------------------+
| ruby-buildpack v1.1.2 | success    | fails on building ruby                                    |
| ruby-buildpack v1.1.3 | success    | fails when installing gems, passes when gems are vendored |
+-----------------------+------------+-----------------------------------------------------------+

The repo/commit we're using were referenced in the original comment for this issue, as a Labs pivot you should have access to that repo.

[jchesterpivotal]

That's very, very interesting, thanks for that fault isolation.

It makes me suspicious of the code we included to change fetching behaviour depending on the requested Ruby version (since Heroku changed binary URLs starting with 2.1.3).

[jchesterpivotal]

(and I wonder, if the bad workman blames his tools, what do you call the software dev who blames someone else's tools?)

[jchesterpivotal]

OK, our working hypothesis is this:

• A staging app hits a cgroup limit, which has been set up by Warden.
• The kernel OOM-kills an in-container process (at random, I think) and notifies Warden.
• Warden exits with code 255
• dea_next receives the 255 exit, sees that it is non-0, marks staging as failed.

There are several workarounds that we've identified, but the best is to increase the amount of RAM allocated to your application using cf scale.

@TildeWill can you try this and verify that it's a successful workaround in your case?

[TildeWill]

We tried increasing the memory early on in this process from 512M to 1G - deploys still failed the same way.

[jchesterpivotal]

Hmm.

Was the log you gave above for 512M or 1G?

Did you cf restate or cf push again?

Cheers,

JC.

[TildeWill]

Log above was @512m. All tests have been cf push to a new app,

$ cf delete -f clock-trash
$ cf push clock-trash

[jchesterpivotal]

Thanks.

FYI, we've transferred the Tracker story for this issue to CF Runtime to look at. The 255 error suggests Warden is the component faulting and we just don't have much expertise on that component in Buildpacks.

In the meantime, given that you've already tried scaling up, I'm not sure what workaround to offer, except pinning to 2.1.1 as you are currently. Sorry :|

We'll leave this open pending advice from Runtime.

[TildeWill]

Sounded like Runtime looked at this, and concluded the same thing you did - that app instance memory had to be increased to 2G. What is troubling is that the app only needs ~256MB to run... why does the size of the running app impact the size of the stager? It seems like the stager should get as much memory as is needed to build a droplet. Another question is why does a smaller memory allocation work for Ruby 2.1.1, but not 2.1.3?

[jchesterpivotal]

Our working hypothesis was that the compilation of Nokogiri on 2.1.3 triggered the OOM condition. The reason we threw it over the fence to Runtime was basically that we were out of our depth on Warden's OOM behaviour.

I'm not sure if we can predict staging-time memory requirements in advance. So the second reason I wanted to get Runtime involved was because I think that we need to give more explicit, visible feedback to developers about why an application has failed to stage. That's something I worry about in Buildpacks land, and we've shipped lots of small changes over the past few months to that end.

So maybe the next question is: why can't we separate buildpack staging and app production settings for RAM etc?

As before, leaving open pending further advice from Runtime.

[flavorjones]

Hi there!

We use Pivotal Tracker to provide visibility into what our team is working on. A story for this issue has been automatically created.

The current status is as follows:

• #99824460 Can't push new app with ruby-buildpack v1.1.3

This comment, as well as the labels on the issue, will be automatically updated as the status in Tracker changes.

[jfmyers9]

Hi all,

Sorry for not responding to the Github issue. We left a comment on the tracker story here explaining what might be the cause of the issues seen here. We are planning on investigating this behavior pending prioritization. Thanks.

@jfmyers9 && @mhess, CF Runtime Team