Repository: ansible/ansible
Pull request: debug: hide loop variables while using var
##### SUMMARY

Fixes: #65856

Signed-off-by: Abhijeet Kasurde <akasurde@redhat.com>

##### ISSUE TYPE
- Bugfix Pull Request




Problem statement:
Debug verbosity not working as expected
##### SUMMARY
The `debug` module is too noisy, and doesnt output only what is being requested. And the `verbosity` property isnt working as expected.

The `debug` module is outputting more than is being asked. 

When I set `verbosity: 3` and do not use `-v` / `-vv` / `-vvv` etc on the command line, I get blue, skipped, output from debug. 

When I set `verbosity: 0` it actually ouputs more info than  `verbosity: 3` as it includes the `msg` - which is the only thing it should be outputing - plus it includes the complete `{{item}}`.

The only semi effective way I've found to limit the output of `debug` is to use `loop_control` which still results in too much noise, as it outputs the requested value twice, eg:

```
- name: Debug list of files
      debug: 
        msg:  " path is {{item.path}}"
        verbosity: 0
      loop: "{{findfiles.files}}"
#      with_items: "{{findfiles.files}}"
      loop_control:
        label: "{{ item.path }}"
```
Will result in the following - not the file path is printed twice per result. Once would have been enough:
```
ok: [localhost] => (item=/home/user/file1.txt) => {
    "msg": " path is /home/user/file1.txt"
}
ok: [localhost] => (item=/home/user/file2.txt) => {
    "msg": " path is /home/user/file2.txt"
}
```

The documentation says the following:

> A number that controls when the debug is run, if you set to 3 it will only run debug when -vvv or above

However, when I run ` ansible-playbook debug_bug.yaml  -i localhost, -K -v` with `debug` set to `verbosity: 3` I get a lot of `skipping`, blue, output. So the color of the output has changed, but its basically the same as not using `loop_control`,






##### ISSUE TYPE
- Bug Report

##### COMPONENT NAME
debug

##### ANSIBLE VERSION
<!--- Paste verbatim output from "ansible --version" between quotes -->
```
ansible 2.8.4
  config file = None
  configured module search path = [u'/home/anton/.ansible/plugins/modules', u'/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/local/lib/python2.7/dist-packages/ansible
  executable location = /usr/local/bin/ansible
  python version = 2.7.15+ (default, Oct  7 2019, 17:39:04) [GCC 7.4.0]

```

##### CONFIGURATION
<!--- Paste verbatim output from "ansible-config dump --only-changed" between quotes -->
```paste below

```

##### OS / ENVIRONMENT
Ubuntu 18.04.3 LTS (Bionic Beaver)


##### STEPS TO REPRODUCE
Run the following example

<!--- Paste example playbooks or commands between quotes below -->
```yaml

# ansible-playbook debug_bug.yaml  -i localhost, -K
---
- name: debug too noisy
  hosts: all
  connection: local
  gather_facts: yes

  vars:
   - vm_host: localhost
   - ansible_user: deploy
   - no_log: True
  tasks:


    - name: loop over files
      find:
        paths: "{{ ansible_env.HOME }}"
        patterns: '*.*'
        recurse: no
      register: findfiles
      become: yes


    - name: Debug list of files
      debug: 
        msg:  " path is {{item.path}}"
        verbosity: 3
      loop: "{{findfiles.files}}"
#      with_items: "{{findfiles.files}}"
#      loop_control:
#        label: "{{ item.path }}"

```


### Other things I've tried
To limit `debug` output to what I've asked to output, I've also tried:

- using var `ANSIBLE_DEBUG: false`
- using var `no_log: True`
- using var  `ANSIBLE_VERBOSITY: 0`

None of these appear to have any impact, and still result in the debug output containing the `msg` and the complete `item`. 

If I use the following, rather than using  `msg:  " path is {{item.path}}"` the noise is even worse. The `item` is printed twice! Once unformatted, and once pretty, and then the actual `var` output.

```
- name: Debug list of files
      debug: 
        var:  item.path
        verbosity: 0
      loop: "{{findfiles.files}}"
```


<!--- HINT: You can paste gist.github.com links for larger files -->

##### EXPECTED RESULTS
I expect `debug` to print exactly what is being requested, no more, especially when using `verbosity: 0`. And especially when not using `ansible-playbook ... -v / -vvvv`.


##### ACTUAL RESULTS

For too much noise! For example, when using:

```
- name: Debug list of files
      debug: 
        var: item.path
        verbosity: 0
      loop: "{{findfiles.files}}"
```

The output is - notice the `item` is printed twice - including unformatted and pretty, and then the `var` is printed:

```
ok: [localhost] => (item={u'rusr': True, u'uid': 1000, u'rgrp': True, u'xoth': False, u'islnk': False, u'woth': False, u'nlink': 1, u'issock': False, u'mtime': 1576110963.0364165, u'gr_name': u'user', u'path': u'/home/user/file1.txt', u'xusr': False, u'atime': 1576110963.0364165, u'inode': 18884540, u'isgid': False, u'size': 0, u'isdir': False, u'ctime': 1576110963.0364165, u'isblk': False, u'wgrp': True, u'xgrp': False, u'isuid': False, u'dev': 64769, u'roth': True, u'isreg': True, u'isfifo': False, u'mode': u'0664', u'pw_name': u'user', u'gid': 1000, u'ischr': False, u'wusr': True}) => {
    "ansible_loop_var": "item", 
    "item": {
        "atime": 1576110963.0364165, 
        "ctime": 1576110963.0364165, 
        "dev": 64769, 
        "gid": 1000, 
        "gr_name": "user", 
        "inode": 18884540, 
        "isblk": false, 
        "ischr": false, 
        "isdir": false, 
        "isfifo": false, 
        "isgid": false, 
        "islnk": false, 
        "isreg": true, 
        "issock": false, 
        "isuid": false, 
        "mode": "0664", 
        "mtime": 1576110963.0364165, 
        "nlink": 1, 
        "path": "/home/user/file1.txt", 
        "pw_name": "user", 
        "rgrp": true, 
        "roth": true, 
        "rusr": true, 
        "size": 0, 
        "uid": 1000, 
        "wgrp": true, 
        "woth": false, 
        "wusr": true, 
        "xgrp": false, 
        "xoth": false, 
        "xusr": false
    }, 
    "item.path": "/home/user/file1.txt"
}
```

If I use the following, with `loop_control`, I still get too much noise, and still get the complete `item` printed, albeit only once:

```
- name: Debug list of files
      debug: 
        var: item.path
        verbosity: 0
      loop: "{{findfiles.files}}"
#      with_items: "{{findfiles.files}}"
      loop_control:
        label: "{{ item.path }}"
```
Also, using `label: "{{ item.path }}"` or `label:  item.path  ` doesnt make any difference - still prints way too much!

Hints from issue discussion:
Files identified in the description:
None

If these files are inaccurate, please update the `component name` section of the description or use the `!component` bot command.

[click here for bot help](https://github.com/ansible/ansibullbot/blob/master/ISSUE_HELP.md)
<!--- boilerplate: components_banner --->
The `verbosity` argument for `debug` indicates at what verbosity level ansible was run at, that the debug task should actually output.

It does not dictate how verbose the output is when using a debug task.

So using `verbosity: 3` means that the debug task will only display when ansible was invoked with `-vvv`.

`loop_control.label` is typically the recommended way to reduce output noise.

If you have further questions please stop by IRC or the mailing list:

   * IRC: #ansible on irc.freenode.net
   * mailing list: https://groups.google.com/forum/#!forum/ansible-project 
@sivel - thanks, but I dont think this should be closed. 

> So using verbosity: 3 means that the debug task will only display when ansible was invoked with -vvv.

I've shown above that this isnt working as you've described. 

I can run `ansible-playbook debug_bug.yaml  -i myhost, --ask-pass -vv` (note: only 2 `vv`s) and with a verbosity of 3 for debug module, and the output is identical - noisy.

> loop_control.label is typically the recommended way to reduce output noise.

And I've also shown that this is also not working as you've described. Please re-read my original post. I'v demonstrated that this is NOT effectively limiting the noise from the debug module. 

The docs for `loop_control` state:

> The output of this task will display just the name field for each item instead of the entire contents of the multi-line {{ item }} variable.


However, running the following
```
- name: Debug list of files
      debug: 
        msg:  " path is {{item.path}}"
        verbosity: 3
      loop: "{{findfiles.files}}"
      loop_control:
        label: "{{ item.path }}"
```

Results in:

```
TASK [Debug list of files] *************************************************************************************************************************************************************************

ok: [10.8.21.239] => (item=/home/deploy/testpk/file1.dat) => {
    "ansible_loop_var": "item", 
    "item": {
        "atime": 1576541248.5726073, 
        "ctime": 1576467575.4846745, 
        "dev": 64768, 
        "gid": 1000, 
        "gr_name": "deploy", 
        "inode": 8498249, 
        "isblk": false, 
        "ischr": false, 
        "isdir": false, 
        "isfifo": false, 
        "isgid": false, 
        "islnk": false, 
        "isreg": true, 
        "issock": false, 
        "isuid": false, 
        "mode": "0600", 
        "mtime": 1576467575.4846745, 
        "nlink": 1, 
        "path": "/home/deploy/testpk/file1.dat", 
        "pw_name": "deploy", 
        "rgrp": false, 
        "roth": false, 
        "rusr": true, 
        "size": 355, 
        "uid": 1000, 
        "wgrp": false, 
        "woth": false, 
        "wusr": true, 
        "xgrp": false, 
        "xoth": false, 
        "xusr": false
    }, 
    "item.path": "/home/deploy/testpk/file1.dat"
}
ok: [10.8.21.239] => (item=/home/deploy/testpk/file2.dat) => {
    "ansible_loop_var": "item", 
    "item": {
        "atime": 1576541249.2916074, 
        "ctime": 1576467576.1486745, 
        "dev": 64768, 
        "gid": 1000, 
        "gr_name": "deploy", 
        "inode": 8498250, 
        "isblk": false, 
        "ischr": false, 
        "isdir": false, 
        "isfifo": false, 
        "isgid": false, 
        "islnk": false, 
        "isreg": true, 
        "issock": false, 
        "isuid": false, 
        "mode": "0600", 
        "mtime": 1576467576.1486745, 
        "nlink": 1, 
        "path": "/home/deploy/testpk/file2.dat", 
        "pw_name": "deploy", 
        "rgrp": false, 
        "roth": false, 
        "rusr": true, 
        "size": 355, 
        "uid": 1000, 
        "wgrp": false, 
        "woth": false, 
        "wusr": true, 
        "xgrp": false, 
        "xoth": false, 
        "xusr": false
    }, 
    "item.path": "/home/deploy/testpk/file2.dat"
}
ok: [10.8.21.239] => (item=/home/deploy/testpk/file3.dat) => {
    "ansible_loop_var": "item", 
    "item": {
        "atime": 1576541249.9896073, 
        "ctime": 1576467576.8056743, 
        "dev": 64768, 
        "gid": 1000, 
        "gr_name": "deploy", 
        "inode": 8498251, 
        "isblk": false, 
        "ischr": false, 
        "isdir": false, 
        "isfifo": false, 
        "isgid": false, 
        "islnk": false, 
        "isreg": true, 
        "issock": false, 
        "isuid": false, 
        "mode": "0600", 
        "mtime": 1576467576.8056743, 
        "nlink": 1, 
        "path": "/home/deploy/testpk/file3.dat", 
        "pw_name": "deploy", 
        "rgrp": false, 
        "roth": false, 
        "rusr": true, 
        "size": 355, 
        "uid": 1000, 
        "wgrp": false, 
        "woth": false, 
        "wusr": true, 
        "xgrp": false, 
        "xoth": false, 
        "xusr": false
    }, 
    "item.path": "/home/user/testpk/file3.dat"
}
```

This debug is identical, regardless of whether I use `loop_control` or not.
I cannot duplicate the behavior you describe. Running with `-vvv`, using the task you provided results in the following output:

```
TASK [Debug list of files] *******************************************************************************************************************************************************************************************************************
task path: /Users/matt/projects/ansibledev/playbooks/65856/65856.yml:8
ok: [localhost] => (item=/Users/matt/projects/ansibledev/playbooks/65856/65856.yml) => {
    "msg": " path is /Users/matt/projects/ansibledev/playbooks/65856/65856.yml"
}
```

Ok, based on the fact that your output was so different, it seems the task you listed in this issue is not the one you are actually testing with.

I've been able to deduce that the task you are actually using in testing is:

```
    - name: Debug list of files
      debug:
        var: item.path
        verbosity: 3
      loop: "{{findfiles.files}}"
      loop_control:
        label: "{{ item.path }}"
```

The difference is using `var` instead of `msg`.  And it seems in this case that the full `item` is also printed as part of the result.

This is a result of `ansible.plugins.callback.CallbackBase._clean_results` stripping `item` when using `msg` but not when using `var`.

I think we can investigate that more.

In the future, it's probably best to give us the task you are actually testing with.
> In the future, it's probably best to give us the task you are actually testing with.

This is the task in the original post:

```
    - name: Debug list of files
      debug: 
        msg:  " path is {{item.path}}"
        verbosity: 3
      loop: "{{findfiles.files}}"
#      with_items: "{{findfiles.files}}"
#      loop_control:
#        label: "{{ item.path }}"
```

This is the task in my second post:

```
- name: Debug list of files
      debug: 
        msg:  " path is {{item.path}}"
        verbosity: 3
      loop: "{{findfiles.files}}"
      loop_control:
        label: "{{ item.path }}"
```

I've tested with this, and every possible variation I can think of to make it work as expected.
That is most certainly not the task producing the output you are providing.

No where in your output are the words "path is".  The task causing your output uses `var` instead of `msg`.

In any case, as indicated, we may be open to adding some additional logic to strip `item` when using `var`.
You're right. My apologies. 

I'm constantly tweaking the task in attempt to get it to do what is expected. 

Nonetheless, I've not managed to get it to perform as expected using either `var` or `msg`.
I put up a patch for this. It follows pretty logically from what @sivel pointed to, but the relevant bits for this are in the callback plugin (which makes me actually feel safer about it).
@magick93: Greetings! Thanks for taking the time to open this issue. In order for the community to handle your issue effectively, we need a bit more information.

Here are the items we could not find in your description:
- component name

Please set the description of this issue with an appropriate template from:
https://github.com/ansible/ansible/tree/devel/.github/ISSUE_TEMPLATE

[click here for bot help](https://github.com/ansible/ansibullbot/blob/master/ISSUE_HELP.md)
<!--- boilerplate: issue_missing_data --->

Commit message: debug: hide loop variables while using var

Fixes: #65856

Signed-off-by: Abhijeet Kasurde <akasurde@redhat.com>

Patch to review:
diff --git a/changelogs/fragments/hide-loop-vars-debug-vars.yml b/changelogs/fragments/hide-loop-vars-debug-vars.yml
new file mode 100644
index 00000000000000..975ab2f75abd49
--- /dev/null
+++ b/changelogs/fragments/hide-loop-vars-debug-vars.yml
@@ -0,0 +1,3 @@
+---
+bugfixes:
+  - debug - hide loop vars in debug var display (https://github.com/ansible/ansible/issues/65856).
diff --git a/lib/ansible/plugins/callback/__init__.py b/lib/ansible/plugins/callback/__init__.py
index 12d97a5a969d92..4b44499dbb90d0 100644
--- a/lib/ansible/plugins/callback/__init__.py
+++ b/lib/ansible/plugins/callback/__init__.py
@@ -432,6 +432,9 @@ def _clean_results(self, result, task_name):
                 # 'var' value as field, so eliminate others and what is left should be varname
                 for hidme in self._hide_in_debug:
                     result.pop(hidme, None)
+                for control_var in ("ansible_loop_var", "ansible_index_var", "ansible_loop"):
+                    if control_var in result:
+                        result.pop(control_var, None)
 
     def _print_task_path(self, task, color=C.COLOR_DEBUG):
         path = task.get_path()
diff --git a/test/integration/targets/callback_default/callback_default.out.result_format_yaml_lossy_verbose.stdout b/test/integration/targets/callback_default/callback_default.out.result_format_yaml_lossy_verbose.stdout
index 10172d9ea9acaa..a83161e9347919 100644
--- a/test/integration/targets/callback_default/callback_default.out.result_format_yaml_lossy_verbose.stdout
+++ b/test/integration/targets/callback_default/callback_default.out.result_format_yaml_lossy_verbose.stdout
@@ -120,7 +120,6 @@ failed: [testhost] (item=debug-2) =>
 ok: [testhost] => (item=debug-3) => 
     msg: debug-3
 skipping: [testhost] => (item=debug-4)  => 
-    ansible_loop_var: item
     false_condition: item != 4
     item: 4
 fatal: [testhost]: FAILED! => 
@@ -200,11 +199,9 @@ skipping: [testhost] =>
 
 TASK [debug] *******************************************************************
 skipping: [testhost] => (item=1)  => 
-    ansible_loop_var: item
     false_condition: false
     item: 1
 skipping: [testhost] => (item=2)  => 
-    ansible_loop_var: item
     false_condition: false
     item: 2
 skipping: [testhost] => 
diff --git a/test/integration/targets/callback_default/callback_default.out.result_format_yaml_verbose.stdout b/test/integration/targets/callback_default/callback_default.out.result_format_yaml_verbose.stdout
index 6918104681736f..8098d224d25293 100644
--- a/test/integration/targets/callback_default/callback_default.out.result_format_yaml_verbose.stdout
+++ b/test/integration/targets/callback_default/callback_default.out.result_format_yaml_verbose.stdout
@@ -126,7 +126,6 @@ failed: [testhost] (item=debug-2) =>
 ok: [testhost] => (item=debug-3) => 
     msg: debug-3
 skipping: [testhost] => (item=debug-4)  => 
-    ansible_loop_var: item
     false_condition: item != 4
     item: 4
 fatal: [testhost]: FAILED! => 
@@ -207,11 +206,9 @@ skipping: [testhost] =>
 
 TASK [debug] *******************************************************************
 skipping: [testhost] => (item=1)  => 
-    ansible_loop_var: item
     false_condition: false
     item: 1
 skipping: [testhost] => (item=2)  => 
-    ansible_loop_var: item
     false_condition: false
     item: 2
 skipping: [testhost] => 


Code review comments:
diff_hunk: @@ -432,6 +432,9 @@ def _clean_results(self, result, task_name):
                 # 'var' value as field, so eliminate others and what is left should be varname
                 for hidme in self._hide_in_debug:
                     result.pop(hidme, None)
+                for control_var in ("ansible_loop_var", "ansible_index_var", "ansible_loop"):
+                    if control_var in result:
+                        result.pop(control_var, None)
path: lib/ansible/plugins/callback/__init__.py
text: @user1:
While not technically wrong, the use of `pop()` with a default is redundant with first checking whether the key exists. Personally I would remove the condition to make it match the previous loop (or combine the two), but if you prefer the condition you should just do `result.pop(control_var)`.

@author:
Make sense.