Crystal: Log inside spec don't work in some cases

[bararchy]

require "log"
require "spec"

module Main
  backend = ::Log::IOBackend.new(STDOUT)
  ::Log.setup { |c| c.bind("*", :debug, backend) }
  Log = ::Log.for("*")
end

Log.info { "Top level print in specs works" }

Log.error { "before describe works" }

describe Main do
  Log.error { "inside describe works" }
  it "something" do
    Log.error { "inside it does not work" }
  end
end

Log.error { "inside it does not work" } won't run, all other runs fine.

[asterite]

These lines are problematic: https://github.com/crystal-lang/crystal/blob/d08b646e1c98efae75e9dd4684aae2fa2ca34234/src/spec/dsl.cr#L290-L302

[bcardiff]

You should be able to run the specs with LOG_LEVEL=error crystal spec ... and see the logs

[kostya]

Also, there is backend problem:

require "log"
require "spec"

L = Log.for("spec")
L.backend = Log::IOBackend.new(File.open("/tmp/1.log", "a"))
L.level = Log::Severity::Info

it "1" do
  L.info { "bla" } 
  1.should eq 1
end

Log outputted to Stdout instead of file. WHY?

[asterite]

Because when you include "spec" it configures the log with Log.setup_from_env(default_level: :none). See https://github.com/crystal-lang/crystal/issues/9462#issuecomment-642641967

I don't understand why that code is there in spec.

[z64]

Personally I'm fine with this behavior. I'm more interested in the spec output than any interior logging, so the reduced noise is good when reviewing in the terminal or CI logs. Especially on other spec output formats (-v).

Assuming we stick with it, I don't think its actually documented in the public Log or Spec docs?
I was adding logging to a shard, which I'll eventually test with capture, but first I had to dig into the spec runner source code to discover why they weren't printing while I was developing the patch, to see that it wasn't my misunderstanding of Log.

[asterite]

I think changing the behavior of Log just because you are requiring spec is unexpected and we shouldn't do it. The reason is that it happens implicitly. Like all implicit things, they are worse and less easy to understand than explicit things.

When I run specs in Ruby or Elixir, if the logger outputs to stdout, I see the output in stdout too. If I want to silence that I can configure it specifically in the spec_helper or something like that. I think we should leave this configuration change to the users so it's explicit.

But that's just my opinion.

[kostya]

@z64 this is not about output something in specs. Main problem, when you test huge codebase which use logging pretty much, all outputted to stdout, which is not desired.

[bcardiff]

@kostya if you want to test that the log are generated you can use Log.capture spec helper added in #9201

In #9145 we make the Log.setup methods remove all the existing bindings.

The Spec.log_spec method that by default turns off the output to stdout is removing the backend you expect.
On other crystal programs the desired log output was :info to STDOUT. But we think this same default does not play well for specs. If you want to have output to stdout setting LOG_LEVEL=INFO env var should be enough.

You can configure additional logging in Spec.before_suite. If you call Log.setup you will remove all existing bindings. If you want to add a backend to a specific source as I understand you are trying to do, you can do the following

require "log"
require "spec"

Spec.before_suite do
  backend = Log::IOBackend.new(File.open("/tmp/1.log", "a"))
  Log.builder.bind("spec", :info, backend)
end

L = Log.for("spec")

it "1" do
  L.info { "bla" }
  1.should eq 1
end

The stdout of the spec will be clean of los messages and the file will containt what you expect.