Repository: ansible/ansible
Pull request: ensure copy action plugin returns an invocation in result
Signed-off-by: Adam Miller <admiller@redhat.com>

##### SUMMARY

Fixes #18232

Previously the action plugin for copy, which runs operations on the
control host to orchestrate executing both local actions on the
control host and remote actions on the remote host, is not returning
invocation dict in the result dict, this happens here where the
return from _copy_file() is None

When force is True, the _execute_module() method is called, which
returns the dict containing the invocation key. This patch ensures
there is always an invocation key.


##### ISSUE TYPE
<!--- Pick one below and delete the rest: -->
 - Bugfix Pull Request

##### COMPONENT NAME
<!--- Name of the module, plugin, module or task -->
copy

##### ANSIBLE VERSION
<!--- Paste verbatim output from "ansible --version" between quotes below -->
```
ansible 2.7.0.dev0 (plugins/action/copy f729467d30) last updated 2018/06/11 16:00:24 (GMT -500)
  config file = /etc/ansible/ansible.cfg
  configured module search path = [u'/home/admiller/.ansible/plugins/modules', u'/usr/share/ansible/plugins/modules']
  ansible python module location = /home/admiller/src/dev/ansible/lib/ansible
  executable location = /home/admiller/src/dev/ansible/bin/ansible
  python version = 2.7.15 (default, May 15 2018, 15:37:31) [GCC 7.3.1 20180303 (Red Hat 7.3.1-5)]
```




Problem statement:
Callback only reports module_name for copy when force argument is set to no
##### Issue Type:
- Bug Report
##### Ansible Version:

```
ansible 2.1.2.0
  config file = ansible.cfg
  configured module search path = None
```
##### Ansible Configuration:

```
[defaults]
hostfile     = ./hosts
callback_plugins = ./callback_plugins
callback_whitelist = callback
```
##### OS / ENVIRONMENT

N/A
##### COMPONENT NAME
Callbacks

##### Summary:

Callback only reports `module_name` for _copy_ when `force` argument is set to _no_
##### Steps To Reproduce:

hosts/local:

```
localhost ansible_connection=local
```

test_playbook.yml:

```
- name: test ansible callback for the copy module
  hosts: localhost
  gather_facts: no
  tasks:
  - name: copy initial
    copy:
      content: "testing"
      dest: "/tmp/test"

  - name: copy with force (module default)
    copy:
      content: "testing"
      dest: "/tmp/test"

  - name: copy without force
    copy:
      content: "testing"
      dest: "/tmp/test"
      force: no
```

callback.py:

```
from ansible.plugins.callback import CallbackBase

class CallbackModule(CallbackBase):

    def v2_runner_on_ok(self, result):
        try:
            print 'module name is %s' % str(result._result['invocation']['module_name'])
        except Exception as e:
            print 'Unable to print: %s' % str(e)
```
##### Expected Results:

```
# ansible-playbook test_playbook.yml

PLAY [test ansible callback for the copy module] *******************************

TASK [copy initial] ************************************************************
ok: [localhost]
module name is copy

TASK [copy with force (module default)] ****************************************
ok: [localhost]
module name is copy

TASK [copy without force] ******************************************************
ok: [localhost]
module name is copy

PLAY RECAP *********************************************************************
localhost                  : ok=3    changed=0    unreachable=0    failed=0
```
##### Actual Results:

Executing the playbook results in the following:

```
PLAY [test ansible callback for the copy module] *******************************

TASK [copy initial] ************************************************************
ok: [localhost]
Unable to print: 'module_name'

TASK [copy with force (module default)] ****************************************
ok: [localhost]
Unable to print: 'module_name'

TASK [copy without force] ******************************************************
ok: [localhost]
module name is copy

PLAY RECAP *********************************************************************
localhost                  : ok=3    changed=0    unreachable=0    failed=0
```

Hints from issue discussion:
I can reproduce the behavior on 2.3:

(with an extra pprint.pprint(results) thrown in callback)

```
[fedora-23:callback_copy_18232 (master %)]$ ANSIBLE_CONFIG=ansible.cfg ansible-playbook -v test.yml 
Using ansible.cfg as config file
 [WARNING]: provided hosts list is empty, only localhost is available


PLAY [test ansible callback for the copy module] *******************************

TASK [copy initial] ************************************************************
ok: [localhost] => {"changed": false, "checksum": "dc724af18fbdd4e59189f5fe768a5f8311527050", "dest": "/tmp/test", "gid": 1000, "group": "adrian", "mode": "0664", "owner": "adrian", "path": "/tmp/test", "secontext": "unconfined_u:object_r:user_tmp_t:s0", "size": 7, "state": "file", "uid": 1000}
{'_host': localhost,
 '_result': {'_ansible_no_log': False,
             '_ansible_parsed': True,
             u'changed': False,
             'checksum': u'dc724af18fbdd4e59189f5fe768a5f8311527050',
             'dest': u'/tmp/test',
             u'diff': {u'after': {u'path': u'/tmp/test'},
                       u'before': {u'path': u'/tmp/test'}},
             u'gid': 1000,
             u'group': u'adrian',
             'invocation': {u'module_args': {u'backup': None,
                                             u'content': u'VALUE_SPECIFIED_IN_NO_LOG_PARAMETER',
                                             u'delimiter': None,
                                             u'dest': u'/tmp/test',
                                             u'diff_peek': None,
                                             u'directory_mode': None,
                                             u'follow': False,
                                             u'force': False,
                                             u'group': None,
                                             u'mode': None,
                                             u'original_basename': u'tmp0Dlhas',
                                             u'owner': None,
                                             u'path': u'/tmp/test',
                                             u'recurse': False,
                                             u'regexp': None,
                                             u'remote_src': None,
                                             u'selevel': None,
                                             u'serole': None,
                                             u'setype': None,
                                             u'seuser': None,
                                             u'src': u'tmp0Dlhas',
                                             u'state': None,
                                             u'unsafe_writes': None,
                                             u'validate': None}},
             u'mode': u'0664',
             u'owner': u'adrian',
             u'path': u'/tmp/test',
             u'secontext': u'unconfined_u:object_r:user_tmp_t:s0',
             u'size': 7,
             u'state': u'file',
             u'uid': 1000},
 '_task': TASK: copy initial}
result=<ansible.executor.task_result.TaskResult object at 0x7fc7719e1a90>
result._result[invocation]={u'module_args': {u'directory_mode': None, u'force': False, u'remote_src': None, u'path': u'/tmp/test', u'owner': None, u'follow': False, u'group': None, u'unsafe_writes': None, u'state': None, u'content': u'VALUE_SPECIFIED_IN_NO_LOG_PARAMETER', u'serole': None, u'diff_peek': None, u'setype': None, u'dest': u'/tmp/test', u'selevel': None, u'original_basename': u'tmp0Dlhas', u'regexp': None, u'validate': None, u'src': u'tmp0Dlhas', u'seuser': None, u'recurse': False, u'delimiter': None, u'mode': None, u'backup': None}}
'module_name'
Unable to print: 'module_name'
 [WARNING]: Failure using method (v2_runner_on_ok) in callback plugin (</home/adrian/src/ansible-bug-repro/callback_copy_18232/callback_plugins/custom.CallbackModule object at 0x7fc773fa0a90>): 'module_name'


TASK [copy with force (module default)] ****************************************
ok: [localhost] => {"changed": false, "checksum": "dc724af18fbdd4e59189f5fe768a5f8311527050", "dest": "/tmp/test", "gid": 1000, "group": "adrian", "mode": "0664", "owner": "adrian", "path": "/tmp/test", "secontext": "unconfined_u:object_r:user_tmp_t:s0", "size": 7, "state": "file", "uid": 1000}
{'_host': localhost,
 '_result': {'_ansible_no_log': False,
             '_ansible_parsed': True,
             u'changed': False,
             'checksum': u'dc724af18fbdd4e59189f5fe768a5f8311527050',
             'dest': u'/tmp/test',
             u'diff': {u'after': {u'path': u'/tmp/test'},
                       u'before': {u'path': u'/tmp/test'}},
             u'gid': 1000,
             u'group': u'adrian',
             'invocation': {u'module_args': {u'backup': None,
                                             u'content': u'VALUE_SPECIFIED_IN_NO_LOG_PARAMETER',
                                             u'delimiter': None,
                                             u'dest': u'/tmp/test',
                                             u'diff_peek': None,
                                             u'directory_mode': None,
                                             u'follow': False,
                                             u'force': False,
                                             u'group': None,
                                             u'mode': None,
                                             u'original_basename': u'tmp3bu_lf',
                                             u'owner': None,
                                             u'path': u'/tmp/test',
                                             u'recurse': False,
                                             u'regexp': None,
                                             u'remote_src': None,
                                             u'selevel': None,
                                             u'serole': None,
                                             u'setype': None,
                                             u'seuser': None,
                                             u'src': u'tmp3bu_lf',
                                             u'state': None,
                                             u'unsafe_writes': None,
                                             u'validate': None}},
             u'mode': u'0664',
             u'owner': u'adrian',
             u'path': u'/tmp/test',
             u'secontext': u'unconfined_u:object_r:user_tmp_t:s0',
             u'size': 7,
             u'state': u'file',
             u'uid': 1000},
 '_task': TASK: copy with force (module default)}
result=<ansible.executor.task_result.TaskResult object at 0x7fc77300d510>
result._result[invocation]={u'module_args': {u'directory_mode': None, u'force': False, u'remote_src': None, u'path': u'/tmp/test', u'owner': None, u'follow': False, u'group': None, u'unsafe_writes': None, u'state': None, u'content': u'VALUE_SPECIFIED_IN_NO_LOG_PARAMETER', u'serole': None, u'diff_peek': None, u'setype': None, u'dest': u'/tmp/test', u'selevel': None, u'original_basename': u'tmp3bu_lf', u'regexp': None, u'validate': None, u'src': u'tmp3bu_lf', u'seuser': None, u'recurse': False, u'delimiter': None, u'mode': None, u'backup': None}}
'module_name'
Unable to print: 'module_name'

TASK [copy without force] ******************************************************
ok: [localhost] => {"changed": false, "dest": "/tmp/test", "src": "/tmp/tmp4buGWp"}
{'_host': localhost,
 '_result': {'_ansible_no_log': False,
             'changed': False,
             'dest': u'/tmp/test',
             'invocation': {'module_args': {u'content': u'testing',
                                            u'dest': u'/tmp/test',
                                            u'force': False},
                            'module_name': u'copy'},
             'src': u'/tmp/tmp4buGWp'},
 '_task': TASK: copy without force}
result=<ansible.executor.task_result.TaskResult object at 0x7fc7719e1a90>
result._result[invocation]={'module_name': u'copy', 'module_args': {u'content': u'testing', u'dest': u'/tmp/test', u'force': False}}
module name is copy

PLAY RECAP *********************************************************************
localhost                  : ok=3    changed=0    unreachable=0    failed=0   
```

misc notes...

Looks like the result in the cases that don't set module_name in invocation also set ''_ansible_parsed' to True. 

copy module exists early if dest exists and force is falsey

@justingood 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 this template:
https://raw.githubusercontent.com/ansible/ansible/devel/.github/ISSUE_TEMPLATE.md

[click here for bot help](https://github.com/ansible/ansibullbot/blob/master/ISSUE_HELP.md)
<!--- boilerplate: issue_missing_data --->
You're sneaky, @ansibot. The issue template has been changed since I reported this bug!

Nonetheless, the component is **callbacks**, and I've edited the original request to reflect this.
Alright, I've tracked this down a bit more. The root cause is that the action plugin for `copy` which runs operations on the control host to orchestrate executing both local actions on the control host and remote actions on the remote host is not returning the `dict` containing the `invocation` `dict`, this happens [here](https://github.com/ansible/ansible/blob/20b9ca6e7c572962c6ee4d9dedc8b303f8590c88/lib/ansible/plugins/action/copy.py#L496) where the return from `_copy_file()` is `None` (which happens in the a few scenarios, but in my test because the [file exists and `force` is false](https://github.com/ansible/ansible/blob/20b9ca6e7c572962c6ee4d9dedc8b303f8590c88/lib/ansible/plugins/action/copy.py#L258).

When `force` is `True`, the `_execute_module()` method is called either [here](https://github.com/ansible/ansible/blob/20b9ca6e7c572962c6ee4d9dedc8b303f8590c88/lib/ansible/plugins/action/copy.py#L527) or [here](https://github.com/ansible/ansible/blob/20b9ca6e7c572962c6ee4d9dedc8b303f8590c88/lib/ansible/plugins/action/copy.py#L548), which returns the `dict` containing the `invocation` key.

I'm still not completely sure how to resolve the issue appropriately, but I wanted to update the ticket in the mean time.
@abadger I'm trying to figure out a reasonable way to implement a fix for this without effectively re-implementing (and therefore effectively having to maintain two versions of it) the [`_return_formatted`](https://github.com/ansible/ansible/blob/eb209e92c90d7d8e838356152f763f076148b737/lib/ansible/module_utils/basic.py#L2308) method of the `AnsibleModule` class. Any thoughts/suggestions?
@maxamillion I think you have to pull _return_formatted out of AnsibleModule :-(

This does align with breaking up basic.py if you want to do it, though.  We should talk and make a proposal if that's what we want to do.

Commit message: ensure copy action plugin returns an invocation in result

Fixes #18232

Previously the action plugin for copy, which runs operations on the
control host to orchestrate executing both local actions on the
control host and remote actions on the remote host, is not returning
invocation dict in the result dict, this happens here where the
return from _copy_file() is None

When force is True, the _execute_module() method is called, which
returns the dict containing the invocation key. This patch ensures
there is always an invocation key.

Signed-off-by: Adam Miller <admiller@redhat.com>

Patch to review:
diff --git a/lib/ansible/plugins/action/copy.py b/lib/ansible/plugins/action/copy.py
index b0502bfff448cc..b4b517f1a633bb 100644
--- a/lib/ansible/plugins/action/copy.py
+++ b/lib/ansible/plugins/action/copy.py
@@ -208,6 +208,13 @@ class ActionModule(ActionBase):
 
     TRANSFERS_FILES = True
 
+    def _ensure_invocation(self, result):
+        if result.get('failed', False) and self._play_context.no_log:
+            result['invocation'] = "CENSORED: no_log is set"
+        elif not result.has_key("invocation"):
+            result["invocation"] = self._task.args
+        return result
+
     def _copy_file(self, source_full, source_rel, content, content_tempfile,
                    dest, task_vars, follow):
         decrypt = boolean(self._task.args.get('decrypt', True), strict=False)
@@ -406,7 +413,7 @@ def run(self, tmp=None, task_vars=None):
             del result['failed']
 
         if result.get('failed'):
-            return result
+            return self._ensure_invocation(result)
 
         # Define content_tempfile in case we set it after finding content populated.
         content_tempfile = None
@@ -424,13 +431,13 @@ def run(self, tmp=None, task_vars=None):
             except Exception as err:
                 result['failed'] = True
                 result['msg'] = "could not write content temp file: %s" % to_native(err)
-                return result
+                return self._ensure_invocation(result)
 
         # if we have first_available_file in our vars
         # look up the files and use the first one we find as src
         elif remote_src:
             result.update(self._execute_module(module_name='copy', task_vars=task_vars))
-            return result
+            return self._ensure_invocation(result)
         else:
             # find_needle returns a path that may not have a trailing slash on
             # a directory so we need to determine that now (we use it just
@@ -444,7 +451,7 @@ def run(self, tmp=None, task_vars=None):
                 result['failed'] = True
                 result['msg'] = to_text(e)
                 result['exception'] = traceback.format_exc()
-                return result
+                return self._ensure_invocation(result)
 
             if trailing_slash != source.endswith(os.path.sep):
                 if source[-1] == os.path.sep:
@@ -498,7 +505,7 @@ def run(self, tmp=None, task_vars=None):
 
             if module_return.get('failed'):
                 result.update(module_return)
-                return result
+                return self._ensure_invocation(result)
 
             paths = os.path.split(source_rel)
             dir_path = ''
@@ -528,7 +535,7 @@ def run(self, tmp=None, task_vars=None):
 
             if module_return.get('failed'):
                 result.update(module_return)
-                return result
+                return self._ensure_invocation(result)
 
             module_executed = True
             changed = changed or module_return.get('changed', False)
@@ -550,7 +557,7 @@ def run(self, tmp=None, task_vars=None):
 
             if module_return.get('failed'):
                 result.update(module_return)
-                return result
+                return self._ensure_invocation(result)
 
             changed = changed or module_return.get('changed', False)
 
@@ -567,4 +574,4 @@ def run(self, tmp=None, task_vars=None):
         # Delete tmp path
         self._remove_tmp_path(self._connection._shell.tmpdir)
 
-        return result
+        return self._ensure_invocation(result)


Code review comments:
diff_hunk: @@ -208,6 +208,13 @@ class ActionModule(ActionBase):
 
     TRANSFERS_FILES = True
 
+    def _ensure_invocation(self, result):
+        if result.get('failed', False) and self._play_context.no_log:
+            result['invocation'] = "CENSORED: no_log is set"
+        elif not result.has_key("invocation"):
+            result["invocation"] = self._task.args
+        return result
path: lib/ansible/plugins/action/copy.py
text: @user1:
I don't think the logic is right here.

* For failed==False, I think that the module side handles the play_context's no_log?  (IIRC, we pass that into the module as _ansible_no_log?).
* It feels like we should only be calling this for failed==True.  failed=False should be handled entirely module-side.  So I'd do the failed=True|False check in the calling code and only call this if we've failed.
* The check to add invocation needs to always depend on play_context.no_log being False.  If there's any case where no_log is True and we still add the invocation we'll be violating the security guarantees of no_log.


@user1:
I'd also make this a toplevel function rather than a method because self is unused inside of the function.

@author:
I don't understand what you mean by "module side" in this scenario, the module never gets called in the execution path reported in the issue ticket this is aiming to fix (which is ultimately the problem).

@author:
You mentioned `self` isn't used but I'm referencing `self._task.args`, do you mean the args should just be passed in?

@user1:
@author regarding self.  Oops, I didn't see that when I made that comment.  I was wrong.

Ah, I think I was getting confused because the security issue we recently fixed is also about no_log but it is only about no_log when failed.

however, the logic still seems wrong.  Shouldn't it be something like:
```
if 'invocation' not in result:
    if self._play_context.no_log:
        result['invocation'] = "CENSORED: no_log is set"
    else:
        result["invocation"] = self._task.args


@author:
@user1 yes, that absolutely makes more sense. 👍