Skip to content
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

[chef/chef]Fix duplicate logs #7698

Conversation

dheerajd-msys
Copy link
Contributor

@dheerajd-msys dheerajd-msys commented Sep 27, 2018

Signed-off-by: dheerajd-msys dheeraj.dubey@msystechnologies.com

Description

This fixes the duplicate logs for log_location

Issues Resolved

fixes #7184

Manual testing completed :

  1. With chef-client
    a) when :log_location is set STDOUT
[azure@dh-rhel chef]$ bundle exec chef-client -z -o starter -c ../chef-repo/client.rb
[2018-09-27T05:31:18-04:00] INFO: Started chef-zero at chefzero://localhost:1 with repository at /home/azure/chef-repo
  One version per cookbook

Starting Chef Client, version 14.5.24
[2018-09-27T05:31:18-04:00] INFO: *** Chef 14.5.24 ***
[2018-09-27T05:31:18-04:00] INFO: Platform: x86_64-linux
[2018-09-27T05:31:18-04:00] INFO: Chef-client pid: 120873
[2018-09-27T05:31:18-04:00] INFO: The plugin path /etc/chef/ohai/plugins does not exist. Skipping...
[2018-09-27T05:31:22-04:00] WARN: Run List override has been provided.
[2018-09-27T05:31:22-04:00] WARN: Original Run List: [recipe[starter]]
[2018-09-27T05:31:22-04:00] WARN: Overridden Run List: [recipe[starter]]
[2018-09-27T05:31:22-04:00] INFO: Run List is [recipe[starter]]
[2018-09-27T05:31:22-04:00] INFO: Run List expands to [starter]
[2018-09-27T05:31:22-04:00] INFO: Starting Chef Run for dh-rhel.vqnxmzhfoz1exeiqi3rsinisrd.dx.internal.cloudapp.net
[2018-09-27T05:31:22-04:00] INFO: Running start handlers
[2018-09-27T05:31:22-04:00] INFO: Start handlers complete.
resolving cookbooks for run list: ["starter"]
[2018-09-27T05:31:22-04:00] INFO: Loading cookbooks [starter@0.1.0]
[2018-09-27T05:31:22-04:00] INFO: Skipping removal of obsoleted cookbooks from the cache
Synchronizing Cookbooks:
  - starter (0.1.0)
Installing Cookbook Gems:
Compiling Cookbooks...
Converging 1 resources
Recipe: starter::default
  * log[Welcome to Chef, #{node["starter_name"]}!] action write[2018-09-27T05:31:23-04:00] INFO: Processing log[Welcome to Chef, #{node["starter_name"]}!] action write (starter::default line 9)
[2018-09-27T05:31:23-04:00] INFO: Welcome to Chef, #{node["starter_name"]}!


[2018-09-27T05:31:23-04:00] WARN: Skipping final node save because override_runlist was given
[2018-09-27T05:31:23-04:00] INFO: Chef Run complete in 0.102184799 seconds
[2018-09-27T05:31:23-04:00] INFO: Skipping removal of unused files from the cache

Running handlers:
[2018-09-27T05:31:23-04:00] INFO: Running report handlers
Running handlers complete
[2018-09-27T05:31:23-04:00] INFO: Report handlers complete
Chef Client finished, 1/1 resources updated in 04 seconds
[azure@dh-rhel chef]$

b) when :log_location is set to a file "/path/to/logfile"

[azure@dh-rhel chef]$ bundle exec chef-client -z -o starter -c ../chef-repo/client.rb
[2018-09-27T05:23:25-04:00] INFO: Started chef-zero at chefzero://localhost:1 with repository at /home/azure/chef-repo
  One version per cookbook

Starting Chef Client, version 14.5.24
[2018-09-27T05:23:25-04:00] INFO: *** Chef 14.5.24 ***
[2018-09-27T05:23:25-04:00] INFO: Platform: x86_64-linux
[2018-09-27T05:23:25-04:00] INFO: Chef-client pid: 120415
[2018-09-27T05:23:25-04:00] INFO: The plugin path /etc/chef/ohai/plugins does not exist. Skipping...
[2018-09-27T05:23:29-04:00] WARN: Run List override has been provided.
[2018-09-27T05:23:29-04:00] WARN: Original Run List: [recipe[starter]]
[2018-09-27T05:23:29-04:00] WARN: Overridden Run List: [recipe[starter]]
[2018-09-27T05:23:29-04:00] INFO: Run List is [recipe[starter]]
[2018-09-27T05:23:29-04:00] INFO: Run List expands to [starter]
[2018-09-27T05:23:29-04:00] INFO: Starting Chef Run for dh-rhel.vqnxmzhfoz1exeiqi3rsinisrd.dx.internal.cloudapp.net
[2018-09-27T05:23:29-04:00] INFO: Running start handlers
[2018-09-27T05:23:29-04:00] INFO: Start handlers complete.
resolving cookbooks for run list: ["starter"]
[2018-09-27T05:23:29-04:00] INFO: Loading cookbooks [starter@0.1.0]
[2018-09-27T05:23:29-04:00] INFO: Skipping removal of obsoleted cookbooks from the cache
Synchronizing Cookbooks:
  - starter (0.1.0)
Installing Cookbook Gems:
Compiling Cookbooks...
Converging 1 resources
Recipe: starter::default
  * log[Welcome to Chef, #{node["starter_name"]}!] action write[2018-09-27T05:23:29-04:00] INFO: Processing log[Welcome to Chef, #{node["starter_name"]}!] action write (starter::default line 9)
[2018-09-27T05:23:29-04:00] INFO: Welcome to Chef, #{node["starter_name"]}!


[2018-09-27T05:23:29-04:00] WARN: Skipping final node save because override_runlist was given
[2018-09-27T05:23:29-04:00] INFO: Chef Run complete in 0.0932818 seconds
[2018-09-27T05:23:29-04:00] INFO: Skipping removal of unused files from the cache

Running handlers:
[2018-09-27T05:23:29-04:00] INFO: Running report handlers
Running handlers complete
[2018-09-27T05:23:29-04:00] INFO: Report handlers complete
Chef Client finished, 1/1 resources updated in 03 seconds
[azure@dh-rhel chef]$
  1. With chef-apply
    a) when :log_location is set STDOUT
[azure@dh-rhel chef]$ bundle exec chef-apply ../chef-repo/cookbooks/starter/recipes/default.rb -c ../chef-repo/client.rb
Recipe: (chef-apply cookbook)::(chef-apply recipe)
  * log[Welcome to Chef, #{node["starter_name"]}!] action write

[azure@dh-rhel chef]$

b) when :log_location is set to a file "/path/to/logfile"

[azure@dh-rhel chef]$ bundle exec chef-apply ../chef-repo/cookbooks/starter/recipes/default.rb -c ../chef-repo/client.rb
Recipe: (chef-apply cookbook)::(chef-apply recipe)
  * log[Welcome to Chef, #{node["starter_name"]}!] action write

[azure@dh-rhel chef]$
  1. With chef-solo
    a) when :log_location is set STDOUT
[azure@dh-rhel chef]$ bundle exec chef-solo -j ../chef-repo/node.json -c ../chef-repo/client.rb
[2018-09-27T05:42:38-04:00] INFO: Started chef-zero at chefzero://localhost:1 with repository at /home/azure/chef-repo
  One version per cookbook

Starting Chef Client, version 14.5.24
[2018-09-27T05:42:39-04:00] INFO: *** Chef 14.5.24 ***
[2018-09-27T05:42:39-04:00] INFO: Platform: x86_64-linux
[2018-09-27T05:42:39-04:00] INFO: Chef-client pid: 121894
[2018-09-27T05:42:39-04:00] INFO: The plugin path /etc/chef/ohai/plugins does not exist. Skipping...
[2018-09-27T05:42:42-04:00] INFO: Setting the run_list to ["recipe[starter]"] from CLI options
[2018-09-27T05:42:42-04:00] INFO: Run List is [recipe[starter]]
[2018-09-27T05:42:42-04:00] INFO: Run List expands to [starter]
[2018-09-27T05:42:42-04:00] INFO: Starting Chef Run for dh-rhel.vqnxmzhfoz1exeiqi3rsinisrd.dx.internal.cloudapp.net
[2018-09-27T05:42:42-04:00] INFO: Running start handlers
[2018-09-27T05:42:42-04:00] INFO: Start handlers complete.
resolving cookbooks for run list: ["starter"]
[2018-09-27T05:42:42-04:00] INFO: Loading cookbooks [starter@0.1.0]
Synchronizing Cookbooks:
  - starter (0.1.0)
Installing Cookbook Gems:
Compiling Cookbooks...
Converging 1 resources
Recipe: starter::default
  * log[Welcome to Chef, #{node["starter_name"]}!] action write[2018-09-27T05:42:42-04:00] INFO: Processing log[Welcome to Chef, #{node["starter_name"]}!] action write (starter::default line 9)
[2018-09-27T05:42:42-04:00] INFO: Welcome to Chef, #{node["starter_name"]}!


[2018-09-27T05:42:42-04:00] INFO: Chef Run complete in 0.154306601 seconds

Running handlers:
[2018-09-27T05:42:42-04:00] INFO: Running report handlers
Running handlers complete
[2018-09-27T05:42:42-04:00] INFO: Report handlers complete
Chef Client finished, 1/1 resources updated in 03 seconds
[azure@dh-rhel chef]$

b) when :log_location is set to a file "/path/to/logfile"

[azure@dh-rhel chef]$ bundle exec chef-solo -j ../chef-repo/node.json -c ../chef-repo/client.rb
[2018-09-27T05:44:23-04:00] INFO: Started chef-zero at chefzero://localhost:1 with repository at /home/azure/chef-repo
  One version per cookbook

Starting Chef Client, version 14.5.24
[2018-09-27T05:44:23-04:00] INFO: *** Chef 14.5.24 ***
[2018-09-27T05:44:23-04:00] INFO: Platform: x86_64-linux
[2018-09-27T05:44:23-04:00] INFO: Chef-client pid: 122184
[2018-09-27T05:44:23-04:00] INFO: The plugin path /etc/chef/ohai/plugins does not exist. Skipping...
[2018-09-27T05:44:26-04:00] INFO: Setting the run_list to ["recipe[starter]"] from CLI options
[2018-09-27T05:44:26-04:00] INFO: Run List is [recipe[starter]]
[2018-09-27T05:44:26-04:00] INFO: Run List expands to [starter]
[2018-09-27T05:44:26-04:00] INFO: Starting Chef Run for dh-rhel.vqnxmzhfoz1exeiqi3rsinisrd.dx.internal.cloudapp.net
[2018-09-27T05:44:26-04:00] INFO: Running start handlers
[2018-09-27T05:44:26-04:00] INFO: Start handlers complete.
resolving cookbooks for run list: ["starter"]
[2018-09-27T05:44:27-04:00] INFO: Loading cookbooks [starter@0.1.0]
Synchronizing Cookbooks:
  - starter (0.1.0)
Installing Cookbook Gems:
Compiling Cookbooks...
Converging 1 resources
Recipe: starter::default
  * log[Welcome to Chef, #{node["starter_name"]}!] action write[2018-09-27T05:44:27-04:00] INFO: Processing log[Welcome to Chef, #{node["starter_name"]}!] action write (starter::default line 9)
[2018-09-27T05:44:27-04:00] INFO: Welcome to Chef, #{node["starter_name"]}!


[2018-09-27T05:44:27-04:00] INFO: Chef Run complete in 0.1637457 seconds

Running handlers:
[2018-09-27T05:44:27-04:00] INFO: Running report handlers
Running handlers complete
[2018-09-27T05:44:27-04:00] INFO: Report handlers complete
Chef Client finished, 1/1 resources updated in 04 seconds
[azure@dh-rhel chef]$

Check List

@dheerajd-msys dheerajd-msys requested a review from a team September 27, 2018 12:20
@dheerajd-msys dheerajd-msys force-pushed the dh/MSYS-887_fix_dup_logger_chef branch 2 times, most recently from 41ed097 to f45e775 Compare September 28, 2018 11:33
@rhass
Copy link
Contributor

rhass commented Sep 28, 2018

Since we are no longer checking to see if the session is a TTY I am curious to know what happens when this is invoked over a remote non-interactive SSH session, or when it is invoked via a service such as runit, cron, systemd, or Windows scheduled task.

@dheerajd-msys
Copy link
Contributor Author

dheerajd-msys commented Oct 1, 2018

Hi @rhass ,

Reference for logic to not using TTY is #7491 (comment)

I've manually tested using knife bootstrap in order to verify for invocation over a remote non-interactive SSH session :

  1. When :log_location is set STDOUT
$ bundle exec knife bootstrap 104.42.196.109 -x azure -P azure@123456 -N dh-rhel2 -c "E:\Backup\Project\chef-starter\chef-repo\.chef\knife.rb" --sudo
Doing old-style registration with the validation key at E:/Backup/Project/chef-starter/chef-repo/.chef/msystech-validator.pem...
Delete your validation key in order to use your user credentials instead

Connecting to 104.42.196.109
104.42.196.109
104.42.196.109 We trust you have received the usual lecture from the local System
104.42.196.109 Administrator. It usually boils down to these three things:
104.42.196.109
104.42.196.109     #1) Respect the privacy of others.
104.42.196.109     #2) Think before you type.
104.42.196.109     #3) With great power comes great responsibility.
104.42.196.109
104.42.196.109 knife sudo password:
104.42.196.109
104.42.196.109 -----> Installing Chef Omnibus (-v 14)
104.42.196.109 downloading https://omnitruck-direct.chef.io/chef/install.sh
104.42.196.109   to file /tmp/install.sh.1869/install.sh
104.42.196.109 trying wget...
104.42.196.109 el 7 x86_64
104.42.196.109 Getting information for chef stable 14 for el...
104.42.196.109 downloading https://omnitruck-direct.chef.io/stable/chef/metadata?v=14&p=el&pv=7&m=x86_64
104.42.196.109   to file /tmp/install.sh.1874/metadata.txt
104.42.196.109 trying wget...
104.42.196.109 sha1     3997daaa81c2ff78cc490973d50181e5f9a08d77
104.42.196.109 sha256   711ed28d1bdfd385d83349d64e480bf76550ad8a69e0f72dc99209e1fae63321
104.42.196.109 url      https://packages.chef.io/files/stable/chef/14.5.33/el/7/chef-14.5.33-1.el7.x86_64.rpm
104.42.196.109 version  14.5.33
104.42.196.109 downloaded metadata file looks valid...
104.42.196.109 downloading https://packages.chef.io/files/stable/chef/14.5.33/el/7/chef-14.5.33-1.el7.x86_64.rpm
104.42.196.109   to file /tmp/install.sh.1874/chef-14.5.33-1.el7.x86_64.rpm
104.42.196.109 trying wget...
104.42.196.109 Comparing checksum with sha256sum...
104.42.196.109 Installing chef 14
104.42.196.109 installing with rpm...
104.42.196.109 warning: /tmp/install.sh.1874/chef-14.5.33-1.el7.x86_64.rpm: Header V4 DSA/SHA1 Signature, key ID 83ef826a: NOKEY
104.42.196.109 Preparing...                          ################################# [100%]
104.42.196.109 Updating / installing...
104.42.196.109    1:chef-14.5.33-1.el7               ################################# [100%]
104.42.196.109 Thank you for installing Chef!
104.42.196.109 Starting the first Chef Client run...
104.42.196.109 Starting Chef Client, version 14.5.33
104.42.196.109 Creating a new client identity for dh-rhel2 using the validator key.
104.42.196.109 resolving cookbooks for run list: []
104.42.196.109 Synchronizing Cookbooks:
104.42.196.109 Installing Cookbook Gems:
104.42.196.109 Compiling Cookbooks...
104.42.196.109 [2018-10-01T06:55:30+00:00] WARN: Node dh-rhel2 has an empty run list.
104.42.196.109 Converging 0 resources
104.42.196.109
104.42.196.109 Running handlers:
104.42.196.109 Running handlers complete
104.42.196.109 Chef Client finished, 0/0 resources updated in 06 seconds
  1. When :log_location is set to a file path
$ bundle exec knife bootstrap 104.42.196.109 -x azure -P azure@123456 -N dh-rhel2 -c "E:\Backup\Project\chef-starter\chef-repo\.chef\knife.rb" --sudo
Doing old-style registration with the validation key at E:/Backup/Project/chef-starter/chef-repo/.chef/msystech-validator.pem...
Delete your validation key in order to use your user credentials instead

Connecting to 104.42.196.109
104.42.196.109 knife sudo password:
104.42.196.109
104.42.196.109 -----> Existing Chef installation detected
104.42.196.109 Starting the first Chef Client run...
104.42.196.109 Starting Chef Client, version 14.5.33
104.42.196.109 Creating a new client identity for dh-rhel2 using the validator key.
104.42.196.109 resolving cookbooks for run list: []
104.42.196.109 Synchronizing Cookbooks:
104.42.196.109 Installing Cookbook Gems:
104.42.196.109 Compiling Cookbooks...
104.42.196.109 [2018-10-01T07:10:33+00:00] WARN: Node dh-rhel2 has an empty run list.
104.42.196.109 Converging 0 resources
104.42.196.109
104.42.196.109 Running handlers:
104.42.196.109 Running handlers complete
104.42.196.109 Chef Client finished, 0/0 resources updated in 05 seconds

I am not sure if this require test cases to be written since test cases for setting logger is already there.

@dheerajd-msys dheerajd-msys changed the title [chef/chef] [WIP] Fix duplicate logs [chef/chef]Fix duplicate logs Oct 3, 2018
@electriquo
Copy link

@dheerajd-msys:
thank you.
i am suffering from the duplicate log lines. truly hope that this pool request will be merged and my log lines will be back to normal.

@@ -80,5 +80,8 @@ class Config
end
end

def self.is_default?(key)
key.is_a?(IO)
end
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

no you still can't override the meaning of this.

@@ -205,7 +205,7 @@ def configure_log_location
# Based on config and whether or not STDOUT is a tty, should we setup a
# secondary logger for stdout?
def want_additional_logger?
Chef::Config.is_default?(:log_location) && Chef::Config[:log_location].tty? && !Chef::Config[:daemonize]
!(Chef::Config.is_default?(Chef::Config[:log_location]) || STDOUT.closed? || Chef::Config[:daemonize])
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

changing the boolean logic here is also something that i'm pretty sure i investigated already and doesn't work correctly in the other use case, pretty certain that means you've changed the meaning of this check.

Chef::Config[:log_location].class == IO && Chef::Config[:log_location].tty? && !Chef::Config[:daemonize] might work correctly in both use cases and not break anything important.

If we have both an actual IO which is a tty then its very likely the log_location is STDOUT.

We want to be very careful here since the :log_location may be a String pathname or a logger instance, we might also support File objects (IDK, but I wouldn't be surprised since those will inherit from IO and would have always worked -- since they probably ducktype and work someone may have decided to use one). By limiting the check to only the EXACT class match on IO we will still support overriding this with a File. This check will now only have an edge condition that if someone hands us an actual IO object that isn't an instance of a subclass this check would fail inappropriately (but the tty? check hopefully catches that).

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks @lamont-granquist for review and suggestions, It gave me an idea to not override the is_default? instead trying out to change the code as per your suggestion.

Although the code Chef::Config[:log_location].class == IO && Chef::Config[:log_location].tty? && !Chef::Config[:daemonize] didn't seem to work out and we still get the duplicate loggers for STDOUT.

But if we change it to !(Chef::Config[:log_location].class == IO || STDOUT.closed? || Chef::Config[:daemonize]) then this worked out well for STDOUT and path/to/file and doesn't require to override is_default? as well.

Tested it with chef-client, chef-solo and chef-apply.
Please let me know your thoughts about this and we can then push the changes.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Does ( Chef::Config[:log_location].class != IO ) && STDOUT.tty? && !Chef::Config[:daemonize] work?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes @lamont-granquist, I've tried with this code change as well and it is working fine.

( Chef::Config[:log_location].class != IO ) && STDOUT.tty? && !Chef::Config[:daemonize] works out well with chef-client, chef-apply & chef-solo for STDOUT and /path/to/file

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

that is the one to go with then. it should preserve the old code behavior. the way it used to look in v12.0.0 was:

( Chef::Config[:log_location] != STDOUT ) && STDOUT.tty? && (!Chef::Config[:daemonize]) && (Chef::Config[:force_logger])

the force_logger bit is no longer relevant. we've now preserved the first three conditional -- only the first conditional has been changed to != on the class being IO rather than != on the instance being STDOUT.

i think i'm good with that.

Signed-off-by: dheerajd-msys <dheeraj.dubey@msystechnologies.com>
@dheerajd-msys dheerajd-msys force-pushed the dh/MSYS-887_fix_dup_logger_chef branch 2 times, most recently from 1c4fb58 to 4ab993f Compare October 23, 2018 07:26
@dheerajd-msys
Copy link
Contributor Author

@lamont-granquist Please take a look.

Signed-off-by: dheerajd-msys <dheeraj.dubey@msystechnologies.com>
@lamont-granquist lamont-granquist merged commit 26c57b3 into chef:master Oct 23, 2018
@lamont-granquist
Copy link
Contributor

merged!

@electriquo
Copy link

electriquo commented Oct 23, 2018

@lamont-granquist: excuse my lame question, when a new chef version\gem will be released? :shipit:

@tas50
Copy link
Contributor

tas50 commented Oct 23, 2018

@y0y0z We're aiming for later this week

@lock
Copy link

lock bot commented Dec 22, 2018

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

@lock lock bot locked as resolved and limited conversation to collaborators Dec 22, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Duplicate log lines created when redirecting STDOUT
5 participants