(VANAGON-57) inform on STDERR, not STDOUT #474

mckern · 2017-04-07T19:19:37Z

I'm not in love with this approach, but it's not drastically different
than how Vanagon handled notification/informing users of state/status
previously. The only difference is now the output is explicit, and can
be more easily/predictably filtered. I think that this is a hold-over
bandaid until we've got a better logging/notification system in place
in Vanagon but it should address the concerns in VANAGON-57.

As is, I'm not wedded to this approach and I'd love to hear any ideas anyone else has.

I'm not in love with this approach, but it's not drastically different than how Vanagon handled notification/informing users of state/status previously. The only difference is now the output is explicit, and can be more easily/predictably filtered. I think that this is a hold-over bandaid until we've got a better logging/notification system in place in Vanagon but it should address the concerns in VANAGON-57.

mcdonaldseanp

@mckern there are several things that I saw and looked like they should go to stdout, not stderr.

Other than that everything looks good

mcdonaldseanp · 2017-04-07T21:15:00Z

lib/vanagon/component/source/http.rb

@@ -78,7 +78,7 @@ def file
        #
        # @raise [RuntimeError] an exception is raised if the sum does not match the sum of the file
        def verify # rubocop:disable Metrics/AbcSize
-          puts "Verifying file: #{file} against sum: '#{sum}'"
+          $stderr.puts "Verifying file: #{file} against sum: '#{sum}'"


This seems like it should go to stdout

mcdonaldseanp · 2017-04-07T21:15:15Z

lib/vanagon/component/source/http.rb

@@ -92,7 +92,7 @@ def download(target_url, target_file = nil, headers = { "Accept-Encoding" => "id
          uri = URI.parse(target_url.to_s)
          target_file ||= File.basename(uri.path)

-          puts "Downloading file '#{target_file}' from url '#{target_url}'"
+          $stderr.puts "Downloading file '#{target_file}' from url '#{target_url}'"


Also should go to stdout

mcdonaldseanp · 2017-04-07T21:15:33Z

lib/vanagon/driver.rb

@@ -148,7 +148,7 @@ def render
        raise Vanagon::Error, "Project requires a version set, all is lost."
      end

-      puts "rendering Makefile"
+      $stderr.puts "rendering Makefile"


should go to stdout

mcdonaldseanp · 2017-04-07T21:15:44Z

lib/vanagon/driver.rb

@@ -117,7 +117,7 @@ def run # rubocop:disable Metrics/AbcSize

      @engine.startup(@workdir)

-      puts "Target is #{@engine.target}"
+      $stderr.puts "Target is #{@engine.target}"


should go to stdout

mcdonaldseanp · 2017-04-07T21:15:54Z

lib/vanagon/driver.rb

@@ -43,8 +43,8 @@ def filter_out_components(only_build)
      # flatten all the results in to one array and set project.components to that.
      @project.components = only_build.flat_map { |comp| @project.filter_component(comp) }.uniq
      if @verbose
-        puts "Only building:"
-        @project.components.each { |comp| puts comp.name }
+        $stderr.puts "Only building:"


should go to stdout

mcdonaldseanp · 2017-04-07T21:17:08Z

lib/vanagon/engine/pooler.rb

@@ -56,7 +56,7 @@ def read_vanagon_token(path = "~/.vanagon-token")
        absolute_path = File.expand_path(path)
        return nil unless File.exist?(absolute_path)

-        puts "Reading vmpooler token from: #{path}"
+        $stderr.puts "Reading vmpooler token from: #{path}"


should go to stdout

This is exactly the message that is screwing us up in CI by being printed to stdout.

mcdonaldseanp · 2017-04-07T21:17:12Z

lib/vanagon/engine/pooler.rb

@@ -70,7 +70,7 @@ def read_vmfloaty_token(path = "~/.vmfloaty.yml")
        absolute_path = File.expand_path(path)
        return nil unless File.exist?(absolute_path)

-        puts "Reading vmpooler token from: #{path}"
+        $stderr.puts "Reading vmpooler token from: #{path}"


should go to stdout

mcdonaldseanp · 2017-04-07T21:17:18Z

lib/vanagon/engine/pooler.rb

@@ -119,7 +119,7 @@ def teardown
        )
        if response and response["ok"]
          Vanagon::Driver.logger.info "#{@target} has been destroyed"
-          puts "#{@target} has been destroyed"
+          $stderr.puts "#{@target} has been destroyed"


should go to stdout

mcdonaldseanp · 2017-04-07T21:19:55Z

lib/vanagon/optparse.rb

@@ -28,7 +28,7 @@ def initialize(banner, options = [])
        end

        opts.on('-h', '--help', 'Display help') do
-          puts opts
+          $stdout.puts opts
          exit 1


unrelated, but why would displaying help return 1 and not 0?

You know, I actually wonder who did that too. Asking for help and getting help means it did what you asked for. I'll fix that in this PR.

mcdonaldseanp · 2017-04-07T21:20:19Z

lib/vanagon/project/dsl.rb

@@ -228,7 +228,7 @@ def identifier(ident)
      #
      # @param name [String] name of component to add. must be present in configdir/components and named $name.rb currently
      def component(name)
-        puts "Loading #{name}" if @project.settings[:verbose]
+        $stderr.puts "Loading #{name}" if @project.settings[:verbose]


should go to stdout

mcdonaldseanp

Sorry, I didn't mean to approve, I want changes unless you disagree

Magisus · 2017-04-07T21:36:12Z

@mcdonaldseanp this is in response to https://github.com/puppetlabs/ci-job-configs/pull/2649. Not sure if you were following that conversation. Do you have another approach?

mckern · 2017-04-07T21:56:36Z

@mcdonaldseanp So. Let's talk about STDOUT/STDERR paradigms. Errors go to STDERR, everything else goes to STDOUT, right? BUT! Because we've only got two default output streams (technically you have a ton more, but &0, &1, and &2 are the only ones you reliably have). So, why would we send notices to STDERR and not STDOUT? Because those notices are not actually required to understand state -- they're strictly informative. Example: curl.

Here's a curl command:

mckern@flexo Desktop $ curl --output --progress-bar --location https://raw.githubusercontent.com/rbenv/ruby-build/9b5123c7fc0766b0dbd16eb5a11167e487d58db6/share/ruby-build/2.2.7
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100   386  100   386    0     0   4769      0 --:--:-- --:--:-- --:--:--  4825
mckern@flexo Desktop $

Let's redirect STDOUT:

mckern@flexo Desktop $ curl --output --progress-bar --location https://raw.githubusercontent.com/rbenv/ruby-build/9b5123c7fc0766b0dbd16eb5a11167e487d58db6/share/ruby-build/2.2.7 >/dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100   386  100   386    0     0   2507      0 --:--:-- --:--:-- --:--:--  2522
mckern@flexo Desktop $

Huh. What changed? Nothing meaningful, because the informative but not-essential output was written to STDERR in light of a lack of STDINFO or STDNICETOKNOW or STDOHTHATMAKESSENSE. I suspect that we'll often end up doing the same thing in Vanagon, and that's why so many of these informative-but-not-essential messages were redirected to STDERR instead of STDOUT.

So, with that background, where do you think some of those messages should go?

mcdonaldseanp · 2017-04-07T22:25:15Z

@mckern yeah, I get why we would put these things in stderr. It bothers me to push everything to stderr since most of it is just verbose stdout but we currently don't have a great alternative.

Is there work ticketed to get more powerful logging in vanagon? Like the ability to specify things will go to stdout when -v/--verbose are specified and either a logfile or nowhere otherwise?

mcdonaldseanp · 2017-04-07T22:27:35Z

What I would like to see eventually is the ability to do something like:

Vanagon::Driver.logger.verbose "something infomative that could go to stdout but doesn't /need/ to"

And everything that calls that will go to stdout /if/ the user specifies -v/--verbose

Magisus · 2017-04-07T22:35:05Z

Do we not have any standard logging utility for Ruby?

The C++ projects all use the one in Leatherman, which allows this.

mckern · 2017-04-07T22:36:19Z

puppetcla · 2017-04-08T02:00:20Z

CLA signed by all contributors.

underscorgan · 2017-04-10T18:16:50Z

This seems reasonable I think. Mostly worried about what this might break. Have you built anything with this?

shrug · 2017-04-11T22:09:34Z

Will merge after Vanagon 0.11.3 release... hopefully today

mckern added don't merge request for comments labels Apr 7, 2017

mckern requested review from shrug, underscorgan, joshcooper, Magisus, melissa and mcdonaldseanp April 7, 2017 19:19

mcdonaldseanp approved these changes Apr 7, 2017

View reviewed changes

mcdonaldseanp requested changes Apr 7, 2017

View reviewed changes

mcdonaldseanp approved these changes Apr 7, 2017

View reviewed changes

mckern closed this Apr 13, 2017

mckern deleted the bug/fix-notification-output branch April 13, 2017 22:20

mckern restored the bug/fix-notification-output branch April 13, 2017 22:24

mckern reopened this Apr 13, 2017

shrug merged commit e3af1e5 into puppetlabs:master Apr 18, 2017

mckern mentioned this pull request Apr 19, 2017

(VANAGON-56) Introducing Mirror URLs #473

Merged

4 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

(VANAGON-57) inform on STDERR, not STDOUT #474

(VANAGON-57) inform on STDERR, not STDOUT #474

mckern commented Apr 7, 2017

mcdonaldseanp left a comment

mcdonaldseanp Apr 7, 2017

mcdonaldseanp Apr 7, 2017

mcdonaldseanp Apr 7, 2017

mcdonaldseanp Apr 7, 2017

mcdonaldseanp Apr 7, 2017

mcdonaldseanp Apr 7, 2017

Magisus Apr 7, 2017

mcdonaldseanp Apr 7, 2017

mcdonaldseanp Apr 7, 2017

mcdonaldseanp Apr 7, 2017

mckern Apr 7, 2017

mcdonaldseanp Apr 7, 2017

mcdonaldseanp left a comment

Magisus commented Apr 7, 2017

mckern commented Apr 7, 2017

mcdonaldseanp commented Apr 7, 2017

mcdonaldseanp commented Apr 7, 2017 •

edited

Loading

Magisus commented Apr 7, 2017 •

edited

Loading

mckern commented Apr 7, 2017

puppetcla commented Apr 8, 2017

underscorgan commented Apr 10, 2017

shrug commented Apr 11, 2017

(VANAGON-57) inform on STDERR, not STDOUT #474

(VANAGON-57) inform on STDERR, not STDOUT #474

Conversation

mckern commented Apr 7, 2017

mcdonaldseanp left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mcdonaldseanp left a comment

Choose a reason for hiding this comment

Magisus commented Apr 7, 2017

mckern commented Apr 7, 2017

mcdonaldseanp commented Apr 7, 2017

mcdonaldseanp commented Apr 7, 2017 • edited Loading

Magisus commented Apr 7, 2017 • edited Loading

mckern commented Apr 7, 2017

puppetcla commented Apr 8, 2017

underscorgan commented Apr 10, 2017

shrug commented Apr 11, 2017

mcdonaldseanp commented Apr 7, 2017 •

edited

Loading

Magisus commented Apr 7, 2017 •

edited

Loading