Add an option for `:exec` mixin to print commands

[AlexWayfer]

Hello.

I'm switching to toys from rake.

And there is in rake sh command prints executing command itself, like:

sh 'git status'
# > git status
# On branch master

In toys there is sh method after include :exec, but without ability to print getting command.

Maybe it even be with true default.

[dazuma]

The :exec mixin already logs all commands by default, but at the INFO level (which will not show up by default because the verbosity defaults to WARN). If you pass -v, those log entries will show up.

include :exec
def run
  exec ["echo", "hello"]
end

% toys foo
hello
% toys foo -v
[2020-07-06 10:02:03  INFO]  ["echo", "hello"]
hello
%

You can also change the log level used by :exec using the :log_level option.

include :exec
def run
  # Log at the "any" level, i.e. always log.
  sh "echo hello", log_level: Logger::UNKNOWN
end

% toys foo
[2020-07-06 10:03:17   ANY]  echo hello
hello
%

Alternatively, to set the log level for all commands:

# Set the default log level for all exec commands:
include :exec, log_level: Logger::UNKNOWN
def run
  sh "echo hello"
end

See the configuration options section of https://dazuma.github.io/toys/gems/toys-core/v0.10.3/Toys/StandardMixins/Exec.html

[AlexWayfer]

OK, but [2020-07-06 10:03:17 ANY] is pretty ugly for me, although I know that this is standard (default). Can I change this format somehow?

[dazuma]

You can change the logger by constructing a new logger with whatever formatter you want, and passing it in the logger: keyword argument. However, I admit this is not convenient. I'll see if there's a better way to customize the logger.

@AlexWayfer Question for you: would you prefer seeing all log entries with a different simpler format, or just the ones related to exec commands?

[AlexWayfer]

@AlexWayfer Question for you: would you prefer seeing all log entries with a different simpler format, or just the ones related to exec commands?

What kind of logs are here beside "exec commands"?

[dazuma]

Exec is the only standard mixin that makes heavy use of the logger. But any tool can log:

tool "foo" do
  def run
    logger.info "Hello, world!"
    logger.warn "This is a warning"
  end
end

[AlexWayfer]

Exec is the only standard mixin that makes heavy use of the logger. But any tool can log:

tool "foo" do
  def run
    logger.info "Hello, world!"
    logger.warn "This is a warning"
  end
end

Oh… I didn't know about available logger getter. OK, thank you. But I wanted a simple output exactly for exec actions. Some third-party logging would be better with a format closer to standard, but can be configurable separately, I guess.

[AlexWayfer]

I've discovered a :logger option for include method.

So, in the current version of toys I can do something like:

subtool_apply do
  unless include? :exec
    include :exec,
      exit_on_nonzero_status: true,
      logger: Logger.new(
        $stdout, formatter: ->(_severity, _datetime, _progname, msg) { "> #{msg}\n" }
      ),
      log_level: Logger::UNKNOWN
  end
end

It's a huge, but does what I want. And this is should be duplicated in outer code if there is another include :exec, which will be executed before (in case of external templates).

It can be simplified via adding a :logger_formatter option for include, as :log_level, but only a little bit.

But! I think, we should change a formatter only when we print exactly exec logs. There is no way to recognize only these logs except condition for severity inside a block. So, the code will be yet larger and not 100% precise:

subtool_apply do
  unless include? :exec
    exec_logger = Logger.new($stdout)
    original_formatter = exec_logger.formatter
    exec_logger.formatter = lambda do |severity, datetime, progname, msg|
      if severity == 'ANY'
        "> #{msg}\n"
      else
        original_formatter.call(severity, datetime, progname, msg)
      end
    end
    include :exec,
      exit_on_nonzero_status: true,
      logger: exec_logger,
      log_level: Logger::UNKNOWN
  end
end

So, you know… after a day of usage default logger I think I'm OK with its format, although it's still a bit ugly.

If you want, you can add an option with separate logger exactly for logging exec commands, maybe even only it's formatter, like :exec_logger_formatter. It's the shortest way to do what I wanted. But we can forget about this and you can close this issue if you want.