Log message not read properly? #79

Closed
jaypipes opened this Issue Nov 28, 2012 · 9 comments

Comments

Projects
None yet
4 participants

Using this default recipe content:

if node["platform_family"] == "debian"

  package "ubuntu-cloud-keyring" do
    action :install
  end

  apt_uri = node["openstack"]["apt"]["uri"]
  ::Chef::Log.info("Setting APT repository to #{apt_uri}, with components:")

  apt_components = node["openstack"]["apt"]["components"]

  # Simple variable substitution for LSB codename and OpenStack release
  apt_components.each do | comp |
    comp = comp.gsub "%release%", node["openstack"]["release"]
    comp = comp.gsub "%codename%", node["lsb"]["codename"]
    ::Chef::Log.info("  #{comp}")
  end

  apt_repository "openstack-ppa" do
    uri node["openstack"]["apt"]["uri"]
    distribution node["lsb"]["codename"]
    components apt_components
  end

end

and running the following ChefSpec test:

require "chefspec"

describe "openstack-common::default" do
  before do
    @chef_run = ::ChefSpec::ChefRunner.new.converge "openstack-common::default"
  end

  describe "apt setup" do
    it "sets apt repositories correctly" do
      Chef::Recipe.any_instance.stub(:apt_repository)
      @chef_run = ::ChefSpec::ChefRunner.new(:log_level => :info) do |n|
        n.set["platform_family"] = "debian"
        n.set["lsb"]["codename"] = "precise"
        n.set["openstack"]["release"] = "folsom"
      end
      @chef_run.converge "openstack-common::default"
      @chef_run.should install_package "ubuntu-cloud-keyring"
      @chef_run.should log "  precise-updates/folsom"
      @chef_run.should log "  main"
    end
  end
end

I get a failure, even though the log output clearly shows the expected log lines are logged:

jpipes@uberbox:~/repos/att-cloud/cookbook-openstack-common$ bundle exec rspec cookbooks/openstack-common/
[2012-11-28T13:07:48-05:00] INFO: Run List is []
[2012-11-28T13:07:48-05:00] INFO: Run List expands to []
[2012-11-28T13:07:48-05:00] INFO: Setting APT repository to http://ubuntu-cloud.archive.canonical.com/ubuntu, with components:
[2012-11-28T13:07:48-05:00] INFO:   precise-updates/folsom
[2012-11-28T13:07:48-05:00] INFO:   main
[2012-11-28T13:07:48-05:00] INFO: Processing package[ubuntu-cloud-keyring] action install (openstack-common::default line 22)
F

Failures:

  1) openstack-common::default apt setup sets apt repositories correctly
     Failure/Error: @chef_run.should log "  precise-updates/folsom"
       expected chef_run: recipe[openstack-common::default] to log "  precise-updates/folsom"
     # ./cookbooks/openstack-common/spec/default_spec.rb:16:in `block (3 levels) in <top (required)>'

Thoughts?
-jay

jimhopp commented Nov 28, 2012

The log matcher is for the log method, not Chef::Log. See the note about
the log matcher in the chefspec readme.

If you really want to match Chef::Log, you can use the rspec should_receive
matcher.

-Jim

On Wed, Nov 28, 2012 at 10:09 AM, jaypipes notifications@github.com wrote:

Using this default recipe content:

if node["platform_family"] == "debian"

package "ubuntu-cloud-keyring" do
action :install
end

apt_uri = node["openstack"]["apt"]["uri"]
::Chef::Log.info("Setting APT repository to #{apt_uri}, with components:")

apt_components = node["openstack"]["apt"]["components"]

Simple variable substitution for LSB codename and OpenStack release

apt_components.each do | comp |
comp = comp.gsub "%release%", node["openstack"]["release"]
comp = comp.gsub "%codename%", node["lsb"]["codename"]
::Chef::Log.info(" #{comp}")
end

apt_repository "openstack-ppa" do
uri node["openstack"]["apt"]["uri"]
distribution node["lsb"]["codename"]
components apt_components
end
end

and running the following ChefSpec test:

require "chefspec"
describe "openstack-common::default" do
before do
@chef_run = ::ChefSpec::ChefRunner.new.converge "openstack-common::default"
end

describe "apt setup" do
it "sets apt repositories correctly" do
Chef::Recipe.any_instance.stub(:apt_repository)
@chef_run = ::ChefSpec::ChefRunner.new(:log_level => :info) do |n|
n.set["platform_family"] = "debian"
n.set["lsb"]["codename"] = "precise"
n.set["openstack"]["release"] = "folsom"
end
@chef_run.converge "openstack-common::default"
@chef_run.should install_package "ubuntu-cloud-keyring"
@chef_run.should log " precise-updates/folsom"
@chef_run.should log " main"
end
endend

I get a failure, even though the log output clearly shows the expected log
lines are logged:

jpipes@uberbox:~/repos/att-cloud/cookbook-openstack-common$ bundle exec rspec cookbooks/openstack-common/
[2012-11-28T13:07:48-05:00] INFO: Run List is []
[2012-11-28T13:07:48-05:00] INFO: Run List expands to []
[2012-11-28T13:07:48-05:00] INFO: Setting APT repository to http://ubuntu-cloud.archive.canonical.com/ubuntu, with components:
[2012-11-28T13:07:48-05:00] INFO: precise-updates/folsom
[2012-11-28T13:07:48-05:00] INFO: main
[2012-11-28T13:07:48-05:00] INFO: Processing package[ubuntu-cloud-keyring] action install (openstack-common::default line 22)
F

Failures:

  1. openstack-common::default apt setup sets apt repositories correctly
    Failure/Error: @chef_run.should log " precise-updates/folsom"
    expected chef_run: recipe[openstack-common::default] to log " precise-updates/folsom"

    ./cookbooks/openstack-common/spec/default_spec.rb:16:in `block (3 levels) in <top (required)>'

Thoughts?
-jay


Reply to this email directly or view it on GitHubhttps://github.com/acrmp/chefspec/issues/79.

Ah, OK, sorry, I didn't pick up on that. Thanks, Jim :)

jaypipes closed this Nov 28, 2012

Sorry, Jim, I've tried both of these, with no luck:

      ::Chef::Log.any_instance.should_receive(:info).with("  precise-updates/folsom")
      ::Chef::Log.should_receive(:info).with("  precise-updates/folsom")

thx in advance from this Ruby newb.

jaypipes reopened this Nov 28, 2012

jimhopp commented Nov 28, 2012

Hmm. We've got a bunch of examples like:

Chef::Log.should_receive(:warn).with("No nfs_mounts_config was found for
xxx::nfs_mounts")

We don't have any :info's, though. Are you sure your log level is info?

On Wed, Nov 28, 2012 at 10:34 AM, jaypipes notifications@github.com wrote:

Sorry, Jim, I've tried both of these, with no luck:

  ::Chef::Log.any_instance.should_receive(:info).with("  precise-updates/folsom")
  ::Chef::Log.should_receive(:info).with("  precise-updates/folsom")

thx in advance from this Ruby newb.


Reply to this email directly or view it on GitHubhttps://github.com/acrmp/chefspec/issues/79#issuecomment-10814787.

Yep, absolutely sure:

this in recipe:

if node["platform_family"] == "debian"

  package "ubuntu-cloud-keyring" do
    action :install
  end

  apt_uri = node["openstack"]["apt"]["uri"]
  ::Chef::Log.info("Setting APT repository to #{apt_uri}, with components:")

  apt_components = node["openstack"]["apt"]["components"]

  # Simple variable substitution for LSB codename and OpenStack release
  apt_components.each do | comp |
    comp = comp.gsub "%release%", node["openstack"]["release"]
    comp = comp.gsub "%codename%", node["lsb"]["codename"]
    ::Chef::Log.info("  #{comp}")
  end

  apt_repository "openstack-ppa" do
    uri node["openstack"]["apt"]["uri"]
    distribution node["lsb"]["codename"]
    components apt_components
  end

end

and this spec:

describe "openstack-common::default" do
  before do
    @chef_run = ::ChefSpec::ChefRunner.new.converge "openstack-common::default"
  end

  describe "apt setup" do
    it "sets apt repositories correctly" do
      Chef::Recipe.any_instance.stub(:apt_repository)
      @chef_run = ::ChefSpec::ChefRunner.new(:log_level => :info) do |n|
        n.set["platform_family"] = "debian"
        n.set["lsb"]["codename"] = "precise"
        n.set["openstack"]["release"] = "folsom"
      end
      @chef_run.converge "openstack-common::default"
      @chef_run.should install_package "ubuntu-cloud-keyring"
      ::Chef::Log.should_receive(:info).with("  precise-updates/folsom")
      ::Chef::Log.should_receive(:info).with("  main")
    end
  end
end

produces this:

jpipes@uberbox:~/repos/att-cloud/cookbook-openstack-common$ bundle exec rspec cookbooks/openstack-common
[2012-11-28T14:09:55-05:00] INFO: Run List is []
[2012-11-28T14:09:55-05:00] INFO: Run List expands to []
[2012-11-28T14:09:55-05:00] INFO: Setting APT repository to http://ubuntu-cloud.archive.canonical.com/ubuntu, with components:
[2012-11-28T14:09:55-05:00] INFO:   precise-updates/folsom
[2012-11-28T14:09:55-05:00] INFO:   main
[2012-11-28T14:09:55-05:00] INFO: Processing package[ubuntu-cloud-keyring] action install (openstack-common::default line 22)
F

Failures:

  1) openstack-common::default apt setup sets apt repositories correctly
     Failure/Error: ::Chef::Log.should_receive(:info).with("  precise-updates/folsom")
       (<Chef::Log (class)>).info("  precise-updates/folsom")
           expected: 1 time
           received: 0 times
     # ./cookbooks/openstack-common/spec/default_spec.rb:19:in `block (3 levels) in <top (required)>'

As you can see, the log messages show up...

Contributor

jimhopp-lookout commented Nov 29, 2012

Hmm. You might try removing the .with and confirm that your expectation is indeed correct (i.e., it should fail with 'expected 1 time/received 15 times).

Just a thought.

Another idea would be to change the log level to :warn.
On Nov 28, 2012, at 11:10 AM, jaypipes wrote:

Yep, absolutely sure:

this in recipe:

if node["platform_family"] == "debian"

package "ubuntu-cloud-keyring" do
action :install
end

apt_uri = node["openstack"]["apt"]["uri"]
::Chef::Log.info("Setting APT repository to #{apt_uri}, with components:")

apt_components = node["openstack"]["apt"]["components"]

Simple variable substitution for LSB codename and OpenStack release

apt_components.each do | comp |
comp = comp.gsub "%release%", node["openstack"]["release"]
comp = comp.gsub "%codename%", node["lsb"]["codename"]
::Chef::Log.info(" #{comp}")
end

apt_repository "openstack-ppa" do
uri node["openstack"]["apt"]["uri"]
distribution node["lsb"]["codename"]
components apt_components
end

end
and this spec:

describe "openstack-common::default" do
before do
@chef_run = ::ChefSpec::ChefRunner.new.converge "openstack-common::default"
end

describe "apt setup" do
it "sets apt repositories correctly" do
Chef::Recipe.any_instance.stub(:apt_repository)
@chef_run = ::ChefSpec::ChefRunner.new(:log_level => :info) do |n|
n.set["platform_family"] = "debian"
n.set["lsb"]["codename"] = "precise"
n.set["openstack"]["release"] = "folsom"
end
@chef_run.converge "openstack-common::default"
@chef_run.should install_package "ubuntu-cloud-keyring"
::Chef::Log.should_receive(:info).with(" precise-updates/folsom")
::Chef::Log.should_receive(:info).with(" main")
end
end
end
produces this:

jpipes@uberbox:~/repos/att-cloud/cookbook-openstack-common$ bundle exec rspec cookbooks/openstack-common
[2012-11-28T14:09:55-05:00] INFO: Run List is []
[2012-11-28T14:09:55-05:00] INFO: Run List expands to []
[2012-11-28T14:09:55-05:00] INFO: Setting APT repository to http://ubuntu-cloud.archive.canonical.com/ubuntu, with components:
[2012-11-28T14:09:55-05:00] INFO: precise-updates/folsom
[2012-11-28T14:09:55-05:00] INFO: main
[2012-11-28T14:09:55-05:00] INFO: Processing package[ubuntu-cloud-keyring] action install (openstack-common::default line 22)
F

Failures:

  1. openstack-common::default apt setup sets apt repositories correctly
    Failure/Error: ::Chef::Log.should_receive(:info).with(" precise-updates/folsom")
    (<Chef::Log (class)>).info(" precise-updates/folsom")
    expected: 1 time
    received: 0 times

    ./cookbooks/openstack-common/spec/default_spec.rb:19:in `block (3 levels) in <top (required)>'

As you can see, the log messages show up...


Reply to this email directly or view it on GitHub.

On 11/29/2012 12:53 PM, jimhopp-lookout wrote:

Hmm. You might try removing the .with and confirm that your expectation
is indeed correct (i.e., it should fail with 'expected 1 time/received
15 times).

Just a thought.

Nah, that didn't work unfortunately... I commented out the with() and
got the same result:

  1. openstack-common::default apt setup sets apt repositories correctly
    Failure/Error: ::Chef::Log.should_receive(:info) #.with("
    precise-updates/folsom")
    (<Chef::Log (class)>).info(any args)
    expected: 1 time
    received: 0 times

    ./cookbooks/openstack-common/spec/default_spec.rb:19:in `block (3

levels) in <top (required)

Another idea would be to change the log level to :warn.

Yeah, unfortunately that didn't have any effect. :(

-jay

Contributor

acrmp commented Nov 29, 2012

Hi Jay,

Your problem may be that you need to move the line with your expectation (should_receive) before the line where you call #converge.

Cheers,

Andrew.

doink! @acrmp that was it. :) Thanks for the heads up!

jaypipes closed this Nov 30, 2012

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment