Nicer Ansible output for Puppet tasks

In a previous post, I wrote about executing Puppet from within an Ansible playbook. But the output did not look very nice. In this post I take a closer look at how to change that.

Just as a reminder, the output of Puppet looks like this, when called from inside Ansible:

ansible-playbook -s -i /etc/ansible/puppet_hosts -l "server01*" puppet-ansible-test.yaml
 
PLAY [Test Puppet agent execution via ansible] ******************************** 
 
GATHERING FACTS *************************************************************** 
ok: [server01.example.com]
 
TASK: [Puppet run] ************************************************************ 
changed: [server01.example.com]
 
TASK: [debug var=puppet_agent_result.stdout_lines] **************************** 
ok: [server01.example.com] => {
    "puppet_agent_result.stdout_lines": [
        "\u001b[0;32mInfo: Retrieving plugin\u001b[0m", 
        "\u001b[0;32mInfo: Caching catalog for server01.example.com\u001b[0m", 
        "\u001b[0;32mInfo: Applying configuration version '1414749704'\u001b[0m", 
        "\u001b[mNotice: /Stage[main]//Node[server01.example.com]/File[/tmp/ansible-test]/content: ", 
        "--- /tmp/ansible-test\t2014-10-31 11:03:09.792572953 +0100", 
        "+++ /tmp/puppet-file20141031-19593-alc2zo-0\t2014-10-31 11:11:44.243616162 +0100", 
        "@@ -1 +1 @@", 
        "-Jst a test", 
        "+Just a test", 
        "\\ No newline at end of file", 
        "\u001b[0m", 
        "\u001b[0;32mInfo: FileBucket adding {md5}280ef2f78e2399bbefb3b2a487b79281\u001b[0m", 
        "\u001b[0;32mInfo: /Stage[main]//Node[server01.example.com]/File[/tmp/ansible-test]: Filebucketed /tmp/ansible-test to puppet with sum 280ef2f78e2399bbefb3b2a487b79281\u001b[0m", 
        "\u001b[mNotice: /Stage[main]//Node[server01.example.com]/File[/tmp/ansible-test]/content: content changed '{md5}280ef2f78e2399bbefb3b2a487b79281' to '{md5}9543518919cb69d012934d9a78fb50b3'\u001b[0m", 
        "\u001b[mNotice: Finished catalog run in 0.20 seconds\u001b[0m"
    ]
}
 
PLAY RECAP ******************************************************************** 
server01.example.com      : ok=3    changed=1    unreachable=0    failed=0

Ansible offers callback plugins. And according to this gist you can use them to change Ansible’s output. So, does this also work for the Puppet output?

As stated in the docs of Ansible, the parameter callback_plugins in ansible.cfg tells Ansible where to find the plugins. On my system it is /usr/share/ansible_plugins/callback_plugins. So I create human_log.py in this directory. Calling Ansible, shows it does not work completely. It is not working for the debug task:

ansible-playbook -s -i /etc/ansible/puppet_hosts -l "server01*" puppet-ansible-test.yaml
 
PLAY [all] ******************************************************************** 
 
GATHERING FACTS *************************************************************** 
ok: [server01.example.com]
 
TASK: [Puppet run] ************************************************************ 
changed: [server01.example.com]
 
cmd:
/usr/bin/puppet agent --test --verbose
 
start:
2014-12-12 14:00:56.459456
 
end:
2014-12-12 14:01:02.815022
 
delta:
0:00:06.355566
 
stdout:
Info: Retrieving plugin
Info: Loading facts in /var/lib/puppet/lib/facter/service_env.rb
Info: Loading facts in /var/lib/puppet/lib/facter/puppet_vardir.rb
Info: Loading facts in /var/lib/puppet/lib/facter/service.rb
Info: Loading facts in /var/lib/puppet/lib/facter/facter_dot_d.rb
Info: Loading facts in /var/lib/puppet/lib/facter/root_home.rb
Info: Loading facts in /var/lib/puppet/lib/facter/pe_version.rb
Info: Caching catalog for server01.example.com
Info: Applying configuration version '1418388530'
Notice: /Stage[main]//Node[server01.example.com]/File[/tmp/test]/ensure: defined content as '{md5}0bf60adb1435639a42b490e7e80d25c7'
Notice: Finished catalog run in 0.19 seconds
 
stderr:
 
 
TASK: [debug var=puppet_agent_result] ***************************************** 
ok: [server01.example.com] => {
    "puppet_agent_result": {
        "changed": true, 
        "cmd": "/usr/bin/puppet agent --test --verbose", 
        "delta": "0:00:06.355566", 
        "end": "2014-12-12 14:01:02.815022", 
        "failed": false, 
        "failed_when_result": false, 
        "invocation": {
            "module_args": "/usr/bin/puppet agent --test --verbose", 
            "module_name": "shell"
        }, 
        "rc": 2, 
        "start": "2014-12-12 14:00:56.459456", 
        "stderr": "", 
        "stdout": "\u001b[0;32mInfo: Retrieving plugin\u001b[0m\n\u001b[0;32mInfo: Loading facts in /var/lib/puppet/lib/facter/service_env.rb\u001b[0m\n\u001b[0;32mInfo: Loading facts in /var/lib/puppet/lib/facter/puppet_vardir.rb\u001b[0m\n\u001b[0;32mInfo: Loading facts in /var/lib/puppet/lib/facter/service.rb\u001b[0m\n\u001b[0;32mInfo: Loading facts in /var/lib/puppet/lib/facter/facter_dot_d.rb\u001b[0m\n\u001b[0;32mInfo: Loading facts in /var/lib/puppet/lib/facter/root_home.rb\u001b[0m\n\u001b[0;32mInfo: Loading facts in /var/lib/puppet/lib/facter/pe_version.rb\u001b[0m\n\u001b[0;32mInfo: Caching catalog for server01.example.com\u001b[0m\n\u001b[0;32mInfo: Applying configuration version '1418388530'\u001b[0m\n\u001b[mNotice: /Stage[main]//Node[server01.example.com]/File[/tmp/test]/ensure: defined content as '{md5}0bf60adb1435639a42b490e7e80d25c7'\u001b[0m\n\u001b[mNotice: Finished catalog run in 0.19 seconds\u001b[0m", 
        "stdout_lines": [
            "\u001b[0;32mInfo: Retrieving plugin\u001b[0m", 
            "\u001b[0;32mInfo: Loading facts in /var/lib/puppet/lib/facter/service_env.rb\u001b[0m", 
            "\u001b[0;32mInfo: Loading facts in /var/lib/puppet/lib/facter/puppet_vardir.rb\u001b[0m", 
            "\u001b[0;32mInfo: Loading facts in /var/lib/puppet/lib/facter/service.rb\u001b[0m", 
            "\u001b[0;32mInfo: Loading facts in /var/lib/puppet/lib/facter/facter_dot_d.rb\u001b[0m", 
            "\u001b[0;32mInfo: Loading facts in /var/lib/puppet/lib/facter/root_home.rb\u001b[0m", 
            "\u001b[0;32mInfo: Loading facts in /var/lib/puppet/lib/facter/pe_version.rb\u001b[0m", 
            "\u001b[0;32mInfo: Caching catalog for server01.example.com\u001b[0m", 
            "\u001b[0;32mInfo: Applying configuration version '1418388530'\u001b[0m", 
            "\u001b[mNotice: /Stage[main]//Node[server01.example.com]/File[/tmp/test]/ensure: defined content as '{md5}0bf60adb1435639a42b490e7e80d25c7'\u001b[0m", 
            "\u001b[mNotice: Finished catalog run in 0.19 seconds\u001b[0m"
        ], 
        "warnings": []
    }
}
 
PLAY RECAP ******************************************************************** 
server01.example.com      : ok=3    changed=1    unreachable=0    failed=0

But do we really need the debug task? It is just a workaround to get the Puppet output when something changed or failed. With the new Ansible plugin it seems possible to realize this without the debug tasks.

Currently the plugin changes the output only for runner_on_ok and runner_on_failed. But we need it to only log for runner_on_changed. I could not find a reference Ansible implements this inside callbacks, instead Ansible hides it inside the res object. As shown in this gist, the status in runner_on_ok can be ok or changed.

Let us change the human_log.py to just print the output when something changed:

def runner_on_ok(self, host, res):
  if res.pop('changed', False):
    human_log(res)
  else:
    pass

This little change fixes the output and makes it even possible to remove the Ansible debug task. The output now looks like this when something changed:

ansible-playbook -s -i /etc/ansible/puppet_hosts -l "server01*" puppet-ansible-test.yaml
 
PLAY [all] ******************************************************************** 
 
GATHERING FACTS *************************************************************** 
ok: [server01.example.com]
 
TASK: [Puppet run] ************************************************************ 
changed: [server01.example.com]
 
stdout:
Info: Retrieving plugin
Info: Loading facts in /var/lib/puppet/lib/facter/service_env.rb
Info: Loading facts in /var/lib/puppet/lib/facter/puppet_vardir.rb
Info: Loading facts in /var/lib/puppet/lib/facter/service.rb
Info: Loading facts in /var/lib/puppet/lib/facter/facter_dot_d.rb
Info: Loading facts in /var/lib/puppet/lib/facter/root_home.rb
Info: Loading facts in /var/lib/puppet/lib/facter/pe_version.rb
Info: Caching catalog for server01.example.com
Info: Applying configuration version '1418390818'
Notice: /Stage[main]//Node[server01.example.com]/File[/tmp/test]/content: 
--- /tmp/test	2014-12-12 14:31:31.073989661 +0100
+++ /tmp/puppet-file20141212-14315-f1o4yt-0	2014-12-12 14:32:14.069988080 +0100
@@ -1 +1 @@
-ust a test
+Just a test
\ No newline at end of file
 
Info: FileBucket got a duplicate file {md5}6836618568499b53b0c33675e31e0474
Info: /Stage[main]//Node[server01.example.com]/File[/tmp/test]: Filebucketed /tmp/test to puppet with sum 6836618568499b53b0c33675e31e0474
Notice: /Stage[main]//Node[server01.example.com]/File[/tmp/test]/content: content changed '{md5}6836618568499b53b0c33675e31e0474' to '{md5}0bf60adb1435639a42b490e7e80d25c7'
Notice: Finished catalog run in 0.23 seconds
 
PLAY RECAP ******************************************************************** 
server01.example.com      : ok=2    changed=0    unreachable=0    failed=0

As you can see, the plugin also removes the unicode signes, which makes it even more readable. And this is the output when everything passes:

ansible-playbook -s -i /etc/ansible/puppet_hosts -l "server01*" puppet-ansible-test.yaml
 
PLAY [all] ******************************************************************** 
 
GATHERING FACTS *************************************************************** 
ok: [server01.example.com]
 
TASK: [Puppet run] ************************************************************ 
ok: [server01.example.com]
 
PLAY RECAP ******************************************************************** 
server01.example.com      : ok=2    changed=0    unreachable=0    failed=0

This Ansible callback plugin is the solution to our logging problem. With this callback plugin, we can change the Puppet output and also shorten our playbook. When you got question about this topic, do not hesitate to contact me or leave a comment.

Christian Zunker

The Scala Type System: Parameterized Types and Variances, Part 3

With the help of co- and contravariance annotations in Scala you can derive relationships between parameterized classes from their type parameters. The compiler checks with specific rules how the type parameters are used in a generic class. In this, he … Continue reading

The Scala Type System: Parameterized Types and Variances, Part 2

What is the Scala type checker trying to say with the error message that a covariant type occurs in contravariant position? Which rules apply behind the scenes? How can these rules be explained by the known principle of subtype polymorphism? … Continue reading