Error messages should be redirected to stderr, not stdout.

[Salamandar]

I was trying to call FPM while redirecting stdout to out.log and stderr to err.log

• err.log

  /usr/lib/ruby/gems/2.4.0/gems/backports-3.6.7/lib/backports/1.8.7/fixnum/div.rb:1: warning: constant ::Fixnum is deprecated
  /usr/lib/ruby/gems/2.4.0/gems/backports-3.6.7/lib/backports/1.8.7/fixnum/fdiv.rb:1: warning: constant ::Fixnum is deprecated
  /usr/lib/ruby/gems/2.4.0/gems/backports-3.6.7/lib/backports/2.1.0/bignum/bit_length.rb:1: warning: constant ::Bignum is deprecated
  /usr/lib/ruby/gems/2.4.0/gems/backports-3.6.7/lib/backports/2.1.0/fixnum/bit_length.rb:1: warning: constant ::Fixnum is deprecated
  /usr/lib/ruby/gems/2.4.0/gems/backports-3.6.7/lib/backports/1.8.7/fixnum/div.rb:1: warning: constant ::Fixnum is deprecated
  /usr/lib/ruby/gems/2.4.0/gems/backports-3.6.7/lib/backports/1.8.7/fixnum/fdiv.rb:1: warning: constant ::Fixnum is deprecated
  /usr/lib/ruby/gems/2.4.0/gems/backports-3.6.7/lib/backports/2.1.0/bignum/bit_length.rb:1: warning: constant ::Bignum is deprecated
  /usr/lib/ruby/gems/2.4.0/gems/backports-3.6.7/lib/backports/2.1.0/fixnum/bit_length.rb:1: warning: constant ::Fixnum is deprecated

  Those are only warnings…

• out.log

  {:timestamp=>"2017-07-24T16:11:56.355325+0200", :message=>"Force flag given. Overwriting package at /tmp/kpxBuild/5.0/Release/Linux_Ninja_Gcc/vecima_bravura-5.0.r66509.zip", :level=>:warn}
  {:timestamp=>"2017-07-24T16:11:58.033172+0200", :message=>"Created package", :path=>"/tmp/kpxBuild/5.0/Release/Linux_Ninja_Gcc/vecima_bravura-5.0.r66509.zip"}
  {:timestamp=>"2017-07-24T16:11:58.324156+0200", :message=>"Invalid output package (-t flag) type \"rpam\". Expected one of: apk, cpan, deb, dir, empty, freebsd, gem, npm, osxpkg, p5p, pacman, pear, pkgin, pleaserun, puppet, python, rpm, sh, solaris, tar, virtualenv, zip", :level=>:warn}
  {:timestamp=>"2017-07-24T16:11:58.324216+0200", :message=>"Fix the above problems, and you'll be rolling packages in no time!", :level=>:fatal}

  Oh, here are my errors !

Errors should be redirected to stderr, warnings are okay in stderr too.

[AnthonyMastrean]

I went digging around for the FPM-specific error messages, for example

Fix the above problems, and you'll be rolling package in no time!

You can find it in fpm/command and you'll see that it's just calling logger.fatal(). That appears to be the built-in Logger. The docs indicate that an instance can write exclusively to a file or STDOUT/STDERR.

I think you'd need a much broader change to "fix" logging. Something like...

• Create three separate Loggers, one each for: file, STDOUT, and STDERR
• For all log messages, log to the file and STDOUT
• For all log messages of ERROR or great, log to the file and STDERR

I think maybe this comment provides some info on the author's opinion on logging 😅

      # Log both stdout and stderr as 'info' because nobody uses stderr for
      # actually reporting errors and as a result 'stderr' is a misnomer.

I can't actually find any Logger.new calls, so maybe I'm not figuring out the whole situation 🤷‍♂️

[AnthonyMastrean]

Oh, I see... the author is using another one of his gems, Cabin, to provide some specialized logging.

[jordansissel]

Indeed. The logs of fpm is not necessarily intended to be passed to other programs for additional processing, so in this respect the concept of "stdout" (to be piped to another program) and "stderr" (for human consumption) separately doesn't have much difference because there is only one stream of text reporting coming from fpm and that is from the logger. Any other output is writing files to disk (such as the package to be created).

Given this, it's hard for me to understand the value of having two different streams "non errors" and "errors" being routed to two different file descriptors.

Regarding the report, that some things show up in err.log for the given example, these are not warnings I can control as they are triggered by dependencies as they interact with the Ruby interpreter and are written by Ruby to stderr and not by fpm.

[AnthonyMastrean]

@jordansissel However, fpm is a command-line utility and is probably expected to behave as such, especially if it's run as part of a CI or other kind of automated pipeline. I would expect two major behaviors (besides, obviously, producing packages)

• Proper exit codes (success = 0; failure = non-zero)
• Proper STDOUT/STDERR logging (???)

The definition of "proper", in these contexts, is hardly settled in all of the industry, though!

It looks like fpm is consistent in it's own logging to the file and, finally, STDOUT. I think there might be two actions here...

• Fix the backports gem errors that are reported on STDERR, so that stream is empty. The version in use seems to be from late-2015 and there are updates. Maybe one of these is OK?

• Clarify in the docs (and maybe it's already here, I haven't thoroughly reviewed) how fpm will produce output and where to look for it.

[deragon]

@jordansissel, I just hit this problem because in my build script, I parse STDOUT to fetch the name of the created package, ignoring any other line, including errors. Thus when an error occurs, I do not see the error on the console. If the error was sent to STDERR, it would show up. That is the standard Unix way of doing things. logger.error() and logger.fatal() should be redirected to STDERR.