Logs of machines chef-clients

[Fodoj]

As far as I can see logs of chef-client running on machine resources is not shown inside chef-client run of provisioner node. Is there a configuration option for this or this feature doesn't exist?

[keen99]

I've been beating my head on this as well.

the problems are multiple -

first: the way the remote chef-client is run, output from it will -only- output in the local chef if the local chef is running at debug log level.

so if debug level is OK for you, add a -l debug to your chef-client run. this is currently the -only- way I've found to get remote client log output to the local client at all.

If you dont want everything to be debug - and are OK with using a remote log file -

you can provide configuration to the remote client via:

with_machine_options({
  :convergence_options => {
    :chef_config => "
      log_level :info
      log_location '/var/log/chef.log'
    "
  },
})

...but any log_level you might specify in that config is overriden by the command line args (correctly). when local chef-client runs remote chef-client, it passes the -l flag - default of -l auto, otherwise whatever log_level the local client is running at.

-l auto on the remote, running without a connected tty, will....not log at all. so even if you specify a file output, it'll be empty.

so you need to at least pass -l info or greater to the local so you get -l info on the other end. (obviously you could use the local config file, too) give it a logfile so you can inspect it, otherwise it just blackholes.

at least, that's been what I've found (yesterday...)

[Fodoj]

-l debug sounds like a reasonable solution in my situation. There is even a simpler (but less useful than full log) solution: to use chef reports. Then you will get reports for each chef-client run, including provisioner node. For provisioner node report you will set how long it took to provision node X, and then you can open report for node X to see what exactly took that long. One thing to keep in mind is that numbers in reports are not that precise if they took less than a minute.

[keen99]

@Fodoj pointer to details on that? :)

[jkeiser]

I think it would be reasonable to add a mode that would print stdout and stderr to a file for each machine. You could even tee it to stdout.

I just hacked something up that probably does that, but it's completely untested (not even run) at the moment. If you are able to give a branch a try, then please do and let me know if it does what you need! The branch of chef-provisioning is jk/output_per_machine.

You can use the feature by specifying this in machine_options:

machine 'blah' do
  machine_options convergence_options: { machine_output_path: "/Users/jkeiser/output" }
end

It will then create a file for each machine in the specified directory, and stream the output to it. It will also stream the output to stdout still.

[jkeiser]

Hmm, I just realized that doesn't completely solve what you want--you are saying that if you don't set -l debug, you don't get any output from the chef-client?

Still, might help for massive runs. I know it's been asked for.

[jkeiser]

@Fodoj oh! I know what you need. Disregard the previous message and branch. chef-provisioning should already do what you want.

You need this:

machine 'blah' do
  machine_options convergence_options: { stream: true }
end

The relevant code is here.

[keen99]

ohhh ho ho, magic! :)

I'll give that a kick tomorrow!

On Thu, Aug 27, 2015 at 10:56 PM, John Keiser [email protected] wrote:

@Fodoj https://github.com/Fodoj oh! I know what you need. Disregard.

You need this:

machine 'blah' do machine_options convergence_options: { stream: true }end

The relevant code is here https://github.com/chef/chef-provisioning/blob/master/lib/chef/provisioning/transport.rb#L72 .

— Reply to this email directly or view it on GitHub https://github.com/chef/chef-provisioning/issues/425#issuecomment-135619328 .

[Fodoj]

@keen99 what I meant was this: https://docs.chef.io/reporting.html Still good to have this reporting

[Fodoj]

@jkeiser awesome, thanks!

[Fodoj]

@keen99 @jkeiser

So, actually neither of two solutions work:

1. -l debug on provisioner node shows lots of, well, debug information, but still doesn't output any logs from clients that are created and provisioned
2. stream: true didn't do anything at all.

[jkeiser]

Ugh, I see why stream: true didn't do anything. -l debug should have, though. What were you expecting it to do, and what did it do instead?

[Fodoj]

@jkeiser So if I have a recipe:

machine "web" do 
  recipe "my_app"
end

and then I run it with chef-client, then inside log of chef client I wanted to see also logs of another chef client run that happens inside node web after it's created. So in that case I would like to see how my_app recipe was run inside web node.

[jkeiser]

@Fodoj it should print the log of the node to your current console--what are you seeing?

[Fodoj]

@jkeiser

all it shows is

[2015-08-28T14:52:50+00:00] INFO: Executing sudo chef-client -l auto on [email protected]
[2015-08-28T14:58:40+00:00] INFO: Completed chef-client -l auto on [email protected]: exit status 0

as you can see, something like 6 minutes of remote logs are not there ;)

[jkeiser]

Is that on the console or in the local chef-client log?

[Fodoj]

@jkeiser that's inside chef-client log of machine that executes this recipe:

machine "web" do 
  recipe "my_app"
end

[jkeiser]

@Fodoj I believe the output of the machine in question goes to the console rather than the logfile. I totally get that that's not useful to you if you're running remotely, but you might want to check it anyway--run chef-client from a terminal and see? At least then we can be sure what the problem is.

[Fodoj]

@jamesc I am running it manually from the provisioner node. I get full log of provisioner chef client, but I don't get the log of chef client of machine that it provisions in the same log.

[jkeiser]

@Fodoj What is the full command you run, and are you looking at the output that appears on the console, or in a file somewhere? (It's super possible this is now broken, I just want to make darn sure, since chef-client -l debug should be printing out that stuff to the console.)

[keen99]

yeah, looks like your debug log_level isn't getting set...or at least not in a way that gets passed down, since your remote was still -l auto

how are you passing debug? -l debug? or local client.rb?

On Fri, Aug 28, 2015 at 11:46 AM, John Keiser [email protected] wrote:

@Fodoj https://github.com/Fodoj What is the full command you run, and are you looking at the output that appears on the console, or in a file somewhere? (It's super possible this is now broken, I just want to make darn sure, since chef-client -l debug should be printing out that stuff to the console.)

— Reply to this email directly or view it on GitHub https://github.com/chef/chef-provisioning/issues/425#issuecomment-135811056 .

[Fodoj]

It works fine for provisioner node - shows debug info. It also gets passed down. But in provisioner node log I don't get of provisioned nodes.

Full command: chef-client -o "recipe[cluster]" -l debug

Best regards, Kirill Shirinkin

On Fri, Aug 28, 2015 at 6:20 PM, david raistrick [email protected] wrote:

yeah, looks like your debug log_level isn't getting set...or at least not in a way that gets passed down, since your remote was still -l auto how are you passing debug? -l debug? or local client.rb? On Fri, Aug 28, 2015 at 11:46 AM, John Keiser [email protected] wrote:

@Fodoj https://github.com/Fodoj What is the full command you run, and are you looking at the output that appears on the console, or in a file somewhere? (It's super possible this is now broken, I just want to make darn sure, since chef-client -l debug should be printing out that stuff to the console.)

— Reply to this email directly or view it on GitHub https://github.com/chef/chef-provisioning/issues/425#issuecomment-135811056 .

---

Reply to this email directly or view it on GitHub: https://github.com/chef/chef-provisioning/issues/425#issuecomment-135823517

[jkeiser]

@Fodoj cool, seems like the right command. Where are you reading the output you pasted? Are you seeing the [INFO] lines in a file, or on the command line console where you ran that command?

[Fodoj]

command line console

[keen99]

stream didn't work for me (-l info on the cmdline and -l info on the remote, no output between

but -l debug on the local client passed it to the remote and I got output from the remote to the local.(using master from earlier in the week):

chef-client -z $file -l debug |grep -v "WARN:.*Chef 13"

[2015-08-28T14:29:25-04:00] INFO: Executing chef-client -l debug on [email protected]
[2015-08-28T14:29:29-04:00] DEBUG: #<ChefZero::RestRequest:0x007f89231334a0 @env={"GATEWAY_INTERFACE"=>"CGI/1.1"...
....
--- END RESPONSE ---
[2015-08-28T14:29:35-04:00] INFO: Completed chef-client -l debug on [email protected]: exit status 0

[Fodoj]

@keen99 so it shows you all the recipes etc inside remote machine ?

[keen99]

....I take that back.

-l debug is giving me the zero chef-server debug output, not the zero chef-client output, I think. Definitely not the client output

[2015-08-28T15:40:50-04:00] DEBUG: {"run_list":["example","runuserdata"]}
[2015-08-28T15:40:51-04:00] DEBUG:
--- RESPONSE (200) ---
{
  "example": {
    "recipes": [

I should be able to find this (which logged on the client in the loglocation file I spec'd) but it's not there.

[2015-08-28T19:40:58+00:00] ERROR: ruby_block[doaws] (runuserdata::default
line 57) had an error: NoMethodError: undefined method `log' for
Chef::Resource::RubyBlock

I've been away from a -server world for a while (and glad to be) so I think my brain just fuzzed - it saw output, obviously it must be from the client right? :)

[Fodoj]

I am totally confused and I think one of you at least misunderstands the problem. I will compile a reproducible demo to show what I mean, give me 1-2 days for this. :)

[jeremiahsnapp]

I was having problems capturing debug log_level output as well but I think I figured out what's going on.

Whenever I run chef-client -z provision.rb -l debug obviously a ton of output scrolls by so I pipe it to less or redirect it to a file. But piping or redirecting apparently causes the node's chef-client run to stop streaming the output.

To overcome this I append --force-formatter to the command and now I can pipe or redirect the output without losing any output.

By the way, this is true of any of the log_levels.

To demonstrate this I have the following machine resource.

machine 'supermarket' do
  machine_options({
                    convergence_options: { chef_version: "12.6.0" },
                    transport_options: {
                      ip_address: '10.0.3.213',
                      username: 'dev-lxc',
                      ssh_options: {
                        password: "dev-lxc"
                      }
                    }
                  })
end

And here is the output for each log level with and without --force-formatter.

$ chef-client -z provision.rb | egrep 'version 12.6.0|chef-client -l'
[2016-01-06T00:54:15-05:00] INFO: Executing sudo chef-client -l info on [email protected]
[2016-01-06T00:54:17-05:00] INFO: Completed chef-client -l info on [email protected]: exit status 0
$
$ chef-client -z provision.rb --force-formatter | egrep 'version 12.6.0|chef-client -l'
[2016-01-06T00:54:32-05:00] INFO: Executing sudo chef-client -l info on [email protected]
                  Starting Chef Client, version 12.6.0
[2016-01-06T00:54:33-05:00] INFO: Completed chef-client -l info on [email protected]: exit status 0
    - run 'chef-client -l info' on supermarket

$ chef-client -z provision.rb -l info | egrep 'version 12.6.0|chef-client -l'
[2016-01-06T00:38:03-05:00] INFO: Executing sudo chef-client -l info on [email protected]
[2016-01-06T00:38:05-05:00] INFO: Completed chef-client -l info on [email protected]: exit status 0
$
$ chef-client -z provision.rb -l info --force-formatter | egrep 'version 12.6.0|chef-client -l'
[2016-01-06T00:30:39-05:00] INFO: Executing sudo chef-client -l info on [email protected]
                  Starting Chef Client, version 12.6.0
[2016-01-06T00:30:41-05:00] INFO: Completed chef-client -l info on [email protected]: exit status 0
    - run 'chef-client -l info' on supermarket

$ chef-client -z provision.rb -l debug | egrep 'version 12.6.0|chef-client -l'
[2016-01-06T00:38:24-05:00] INFO: Executing sudo chef-client -l debug on [email protected]
[2016-01-06T00:38:26-05:00] INFO: Completed chef-client -l debug on [email protected]: exit status 0
$
$ chef-client -z provision.rb -l debug --force-formatter | egrep 'version 12.6.0|chef-client -l'
[2016-01-06T00:29:57-05:00] INFO: Executing sudo chef-client -l debug on [email protected]
                  Starting Chef Client, version 12.6.0
[2016-01-06T00:29:59-05:00] INFO: Completed chef-client -l debug on [email protected]: exit status 0
    - run 'chef-client -l debug' on supermarket[2016-01-06T00:29:59-05:00] DEBUG: Closing SSH session on [email protected]

$ chef-client -z provision.rb -l error | egrep 'version 12.6.0|chef-client -l'
$
$ chef-client -z provision.rb -l error --force-formatter | egrep 'version 12.6.0|chef-client -l'
    [supermarket] Starting Chef Client, version 12.6.0
    - run 'chef-client -l error' on supermarket

$ chef-client -z provision.rb -l warn | egrep 'version 12.6.0|chef-client -l'
$
$ chef-client -z provision.rb -l warn --force-formatter | egrep 'version 12.6.0|chef-client -l'
    [supermarket] Starting Chef Client, version 12.6.0
    - run 'chef-client -l warn' on supermarket

[ikozel]

@jeremiahsnapp - thanks! --force-formatter option displays you'l get both:

• client/provisioner output
• client/target_node_chef_client_run output

sudo chef-client -z -o systems-infrastructure::my_app -E prod --force-formatter

[andrewmelis]

@jeremiahsnapp thank you! the --force-formatter option worked for me as well.