Is bundler fetching a gem **before** showing the "Fetching gem" message on screen?

[jrodrigosm]

I recently found that, when deploying to Heroku (which is currently using Bundler 1.17.3), bundler's ouput was stalling for several minutes:

(... messages here ...)
remote: Installing devise-security 0.14.3
(... output **stopped for 4 minutes 45 seconds** - and then all the messages below showed immediately)
remote: Fetching bootstrap-sass 3.4.1
remote: Fetching sassc-rails 2.1.2
remote: Installing sassc-rails 2.1.2
remote: Installing bootstrap-sass 3.4.1
remote: Bundle complete! 56 Gemfile dependencies, 119 gems now installed.
remote: Gems in the groups development and test were not installed.
(... more messages here ...)

@schneems was very helpful in finding the source of the problem. At the beginning we thought it might be a problem with the devise-security gem, but we soon found that the culprits were bootstrap-sass and sassc, which were taking a long time to fech/install.

The thing is that bundler did not show the "Fetching bootstrap-sass" message until it was downloaded/installed - so we could not know why the output was stalling, as the last message shown was "Fetching devise-security" (that's why we though there was an issue with devise-security).

Could this somehow be an issue with bundler ordering, and how messages are shown on screen? Maybe something could be done so that bundler does not mislead us about which gem is taking so long to download/install?

[bronzdoc]

@jrodrigosm Is this still an issue for you?

[schneems]

I'm seeing this behavior with another app still. One option: could we add some debug output when gems are installing, record the amount of time the app is spending to install each individual gem and then output that to the shell?

[deivid-rodriguez]

Yeah, very confusing indeed :(

The problem is that we have several concurrent threads (I guess you were using the --jobs flag in these cases?) that all print the log messages to the screen, so if sassc and devise-security get installed on separate threads, and sassc starts earlier, then the log message for devise-security is printed last, and it's indeed pretty confusing.

One possibility is that each thread saves the cursor location of the end of the last message it printed, and when done, it prints :heavy_check_mark: right there. But it will require quite a bit of terminal magic.

[schneems]

Brainstorming here, on other possible fixes to mitigate this issue.

As a user i'm not sure there's a meaningful difference to me between "fetching" and "installing". While I understand they are two separate actions, I mentally group them both as being needed to "install" a gem. So what if we had it so that we got rid of them and grouped them both under a single banner of "installing". And instead, we emit an output when the gem is done installing. Maybe something like this:

remote: Installing bootstrap-sass 3.4.1
remote: Installing sassc-rails 2.1.2
remote: Finished sassc-rails 2.1.2 (366 s)
remote: Finished bootstrap-sass 3.4.1 (377 s)
remote: Bundle complete! 56 Gemfile dependencies, 119 gems now installed.

[deivid-rodriguez]

That seems like a good idea to me! :+1:

[simi]

I think for RubyGems 4 we can also consider renaming "fetching" to "downloading".

:thinking: Fetching rails, Installing rails, those both sounds naturally to me, but Finished rails do not. What about rails installed successfully?

[deivid-rodriguez]

Yeah, I mean :+1: to the idea, the specific wording can be refined.

Also, I think we don't need to wait until rubygems 4 for this, nor to a new bundler major. I believe we can release improvements like this any time?

[simi]

:thinking: I think this deserves at least minor version bump.

[deivid-rodriguez]

Minor is fine, sure, but I don't think this deserves to wait for a major version bump.

[collimarco]

Is there any chance to have only 1 line of output for each gem?

Every time that I run an update I check each line to see the version change and having two separate outputs (fetching, installing) is really confusing because I need to read every gem two times... Moreover the two outputs are not nearby. It would be useful to group them in two consecutive lines at least. Or, have only 1 line.

Users that use bundle don't care about low level details, they just want to know what gems/versions have changed.

[deivid-rodriguez]

Sorry I never replied here.

I think one line of output per gem would be ideal, but since we print log messages from several parallel threads, that's a bit tricky to implement because we'll need to move the cursor back and forth.

The suggested improvement at least clarifies which gems took long to install, although it does make the output even more verbose. We just got someone who implemented it at https://github.com/rubygems/rubygems/pull/7622, so I think we can start with that, and try to balance verbosity with usefulness of the output.