Bundler: Show "Installed" message after installing a gem

[jordan-brough]

Add an "Installed XXX in Y.YYYs" message after installing a gem.

Example output:

Fetching buffering_logger 3.1.1
Installing buffering_logger 3.1.1
Installed buffering_logger 3.1.1 in 0.004s

☝️ the last line is new.

What was the end-user or developer problem that led to this PR?

When installing gems in parallel (e.g. bundle install --jobs 4), I wanted it to be easier to tell when each gem finished installing and how long each gem took to install.

Currently, especially when reviewing logs on production servers, I have timestamps on log lines but I still can't tell which gems are taking a long time to install because I can't get a time diff between starting a particular gem and finishing the install (if I'm installing gems in parallel). Gems with native extensions are often ones that are slow that I'd like to identify.

What is your fix for the problem, implemented in this PR?

Measure the time elapsed while installing (not including fetching) and print it out.

If this looks OK I will add some tests.

Make sure the following tasks are checked

• Describe the problem / feature
• Write tests for features and bug fixes
• Write code to solve the problem
• Make sure you follow the current code style and write meaningful commit messages without tags

[welcome]

Thanks for opening a pull request and helping make RubyGems and Bundler better! Someone from the RubyGems team will take a look at your pull request shortly and leave any feedback. Please make sure that your pull request has tests for any changes or added functionality.

We use GitHub Actions to test and make sure your change works functionally and uses acceptable conventions, you can review the current progress of GitHub Actions in the PR status window below.

If you have any questions or concerns that you wish to ask, feel free to leave a comment in this PR or join our #rubygems or #bundler channel on Slack.

For more information about contributing to the RubyGems project feel free to review our CONTRIBUTING guide

[deivid-rodriguez]

This is great, and fixes an issue other people have experienced! See #3305.

One thought I'm having is that in #3305 (comment), people also complained about output being complicated to parse with two separate (possibly not consecutive) lines per gem.

So even if this change will help clarify which gem took longer to install, it will make the output even more complicated with 3 lines per gem.

I wonder if we could fix this problem (unclarity of which gems took long to install) while keeping the out as verbose as it is now, by instead of adding the "Installed " line to the output, make it replace the "Installing" line?

[jordan-brough]

instead of adding the "Installed " line to the output, make it replace the "Installing" line?

Personally I don't mind extra output, and the difference between fetching & installing could be important in some cases (network issues?). But that's an much less important edge case. I'm happy as long as I get a "start" and "stop" marker!

I'll update to remove the "Installing" line and I'll add some tests.

[deivid-rodriguez]

Personally I don't mind extra output, and the difference between fetching & installing could be important in some cases (network issues?). But that's an much less important edge case. I'm happy as long as I get a "start" and "stop" marker!

You're right, and I'm not totally sold on my own suggestion. It was mostly brainstorming to try add the useful information being added here without increasing the number of lines logged. Maybe, iterating on the suggestion, we could change everything to "after the fact" info, like

Fetched buffering_logger 3.1.1 in <0.xs>
Installed buffering_logger 3.1.1 in 0.004s
(...)

[jordan-brough]

Hm, if we want to limit to 2 lines, personally I'd prefer to have "start" and "finished" lines, so if e.g. fetching is hung at any point I can still understand what the system is trying to do right now (I can see that it started but never finished).

From a "debug stuff" perspective I'd prefer to have all of these:

• Fetching
• Fetched in XXX
• Installing
• Installed in XXX

But if we want to be concise then the first and last seem the best to pick imo.

[deivid-rodriguez]

All good points!

Keeping only "Fetching" and "Installed" may have issues too, since "Fetching" does not show up if the gem is already cached.

I'm not fully convinced but I guess all 4 would be best, indeed. If users are bothered enough about multiple lines in output per gem, they could open a new issue.

Ideally we would fix this "the right way" by properly parallelizing the input so that it just shows one line per gem that's updated with final execution time and status once done. But that's much more tricky to implement.

I wonder what @simi thinks since he participated in the linked issue too.

[jordan-brough]

@deivid-rodriguez should I go ahead and implement displaying all 4 messages, or do we want to wait to hear back from @simi or others?

[deivid-rodriguez]

Since I wouldn't want you to waste effort going in a direction we may end up changing, I'd say let's wait a bit for more input.

[jordan-brough]

@deivid-rodriguez how long would you like to wait to see if someone else wants to chime in?

[deivid-rodriguez]

I think we can go with the suggested approach 👍. After all, @simi was ok with this in the linked issue and the main thing to figure out is when to release the change, not the change itself.

In the future, I'd like to use something like https://github.com/piotrmurach/tty-progressbar#ttyprogressbar to get the best of both worlds (useful and condensed output), but that's a non trivial project.