New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Duplicate log lines when using a formatter #8138

Open
anandsuresh opened this Issue Jan 20, 2019 · 4 comments

Comments

Projects
None yet
2 participants
@anandsuresh
Copy link
Contributor

anandsuresh commented Jan 20, 2019

Description

When running chef-solo with a custom formatter, every log line is printed twice. This seems similar to #7184.

Chef Version

v14.8.12

Platform Version

SunOS 5.11 joyent_20180816T001857Z i86pc i386 i86pc Solaris

Replication Case

Client Output

[root@jpc1-anand-01 /var/chef]# chef-solo -W -c solo.rb -F doc
Starting Chef Client, version 14.8.12
Starting Chef Client, version 14.8.12
resolving cookbooks for run list: ["chef"]
resolving cookbooks for run list: ["chef"]
Synchronizing Cookbooks:
Synchronizing Cookbooks:
  - chef (0.0.0)
  - chef (0.0.0)
Installing Cookbook Gems:
Installing Cookbook Gems:
Compiling Cookbooks...
Compiling Cookbooks...
Converging 6 resources
Converging 6 resources
Recipe: chef::default
  * directory[/var/chef] action createRecipe: chef::default
  * directory[/var/chef] action create (up to date)
 (up to date)
  * directory[/var/chef/bin] action create  * directory[/var/chef/bin] action create
    - Would create new directory /var/chef/bin
    - Would create new directory /var/chef/bin

  * gem_package[chef] action install  * gem_package[chef] action install (up to date)
 (up to date)
  * gem_package[berkshelf] action install  * gem_package[berkshelf] action install (up to date)
 (up to date)
  * template[/var/chef/bin/run-chef] action create  * template[/var/chef/bin/run-chef] action create
    * Parent directory /var/chef/bin does not exist.
    * Parent directory /var/chef/bin does not exist.
    * Assuming directory /var/chef/bin would have been created
    * Assuming directory /var/chef/bin would have been created
    - Would create new file /var/chef/bin/run-chef
    - Would create new file /var/chef/bin/run-chef
    - Would change mode from '' to '0755'
    - Would change mode from '' to '0755'

  * link[/opt/local/bin/run-chef] action create  * link[/opt/local/bin/run-chef] action create
    - Would create symlink at /opt/local/bin/run-chef to /var/chef/bin/run-chef
    - Would create symlink at /opt/local/bin/run-chef to /var/chef/bin/run-chef

[2019-01-20T20:14:03+00:00] WARN: In why-run mode, so NOT performing node save.

Running handlers:

Running handlers:
Running handlers complete
Running handlers complete
Chef Client finished, 3/6 resources would have been updated
Chef Client finished, 3/6 resources would have been updated

Stacktrace

@anandsuresh

This comment has been minimized.

Copy link
Contributor Author

anandsuresh commented Jan 20, 2019

I first noticed this issue after upgrading from v 12.10.24 to v14.8.12. I'd be happy to run any diagnostics and/or provide additional information.

@lamont-granquist

This comment has been minimized.

Copy link
Contributor

lamont-granquist commented Jan 22, 2019

This seems to be isolated to chef-solo (chef-client -z does not behave this way) and want_additional_loggers? is returning false, so this is not related to the other double-logging bugs at all.

Chef::Config.formatters contains two instances of the doc formatter and looks like Chef::Application#configure_logging is being called twice:

[["doc", nil]]
[["doc", nil], ["doc", nil]]
Starting Chef Client, version 14.9.13
Starting Chef Client, version 14.9.13
@lamont-granquist

This comment has been minimized.

Copy link
Contributor

lamont-granquist commented Jan 22, 2019

with more debugging:

% chef-solo -W -c solo.rb -F doc
/Users/lamont/.rvm/gems/ruby-2.5.3/gems/chef-14.9.13/lib/chef/application.rb:56:in `reconfigure'
/Users/lamont/.rvm/gems/ruby-2.5.3/gems/chef-14.9.13/lib/chef/application/solo.rb:232:in `reconfigure'
/Users/lamont/.rvm/gems/ruby-2.5.3/gems/chef-14.9.13/lib/chef/application/solo.rb:221:in `run'
/Users/lamont/.rvm/gems/ruby-2.5.3/gems/chef-14.9.13/bin/chef-solo:24:in `<top (required)>'
/Users/lamont/.rvm/gems/ruby-2.5.3/bin/chef-solo:23:in `load'
/Users/lamont/.rvm/gems/ruby-2.5.3/bin/chef-solo:23:in `<main>'
/Users/lamont/.rvm/gems/ruby-2.5.3/bin/ruby_executable_hooks:24:in `eval'
/Users/lamont/.rvm/gems/ruby-2.5.3/bin/ruby_executable_hooks:24:in `<main>'
[["doc", nil]]
/Users/lamont/.rvm/gems/ruby-2.5.3/gems/chef-14.9.13/lib/chef/application/client.rb:403:in `configure_logging'
/Users/lamont/.rvm/gems/ruby-2.5.3/gems/chef-14.9.13/lib/chef/application.rb:56:in `reconfigure'
/Users/lamont/.rvm/gems/ruby-2.5.3/gems/chef-14.9.13/lib/chef/application/client.rb:313:in `reconfigure'
/Users/lamont/.rvm/gems/ruby-2.5.3/gems/chef-14.9.13/lib/chef/application.rb:64:in `run'
/Users/lamont/.rvm/gems/ruby-2.5.3/gems/chef-14.9.13/lib/chef/application/solo.rb:224:in `run'
/Users/lamont/.rvm/gems/ruby-2.5.3/gems/chef-14.9.13/bin/chef-solo:24:in `<top (required)>'
/Users/lamont/.rvm/gems/ruby-2.5.3/bin/chef-solo:23:in `load'
/Users/lamont/.rvm/gems/ruby-2.5.3/bin/chef-solo:23:in `<main>'
/Users/lamont/.rvm/gems/ruby-2.5.3/bin/ruby_executable_hooks:24:in `eval'
/Users/lamont/.rvm/gems/ruby-2.5.3/bin/ruby_executable_hooks:24:in `<main>'
[["doc", nil], ["doc", nil]]

my guess is that this is related to the way that Chef::Application::Solo is launching a Chef::Application::Client to do its work here:

  # Get this party started
  def run
    setup_signal_handlers
    reconfigure
    for_ezra if Chef::Config[:ez]
    if !Chef::Config[:solo_legacy_mode]
      Chef::Application::Client.new.run
    else
      setup_application
      run_application
    end
  end
@lamont-granquist

This comment has been minimized.

Copy link
Contributor

lamont-granquist commented Jan 22, 2019

The best workaround here is to use chef-client -z and not chef-solo

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