Bug 1593772

Foreman Task:

 Input:

---
ansible_inventory: '{"all":{"hosts":["host1.example.com"],"vars":{"action":"shutdown"}},"_meta":{"hostvars":{"host1.example.com":{"foreman":{"ip":"192.168.100.16","ip6":null,"environment_id":null,"environment_name":null,"last_report":"2018-06-20T15:34:41.000Z","mac":"52:54:00:cc:c8:c0","realm_id":null,"realm_name":null,"sp_mac":null,"sp_ip":null,"sp_name":null,"domain_id":1,"domain_name":"example.com","architecture_id":1,"architecture_name":"x86_64","operatingsystem_id":1,"operatingsystem_name":"RHEL
  Server 7.5","subnet_id":null,"subnet_name":null,"subnet6_id":null,"subnet6_name":null,"sp_subnet_id":null,"ptable_id":null,"ptable_name":null,"medium_id":null,"medium_name":null,"pxe_loader":null,"build":false,"comment":null,"disk":null,"installed_at":null,"model_id":2,"hostgroup_id":null,"owner_id":4,"owner_name":"Admin
  User","owner_type":"User","enabled":true,"managed":false,"use_image":null,"image_file":"","uuid":null,"compute_resource_id":null,"compute_resource_name":null,"compute_profile_id":null,"compute_profile_name":null,"capabilities":["build"],"provision_method":"build","certname":"host1.example.com","image_id":null,"image_name":null,"created_at":"2018-06-20T14:53:09.551Z","updated_at":"2018-06-20T15:34:41.793Z","last_compile":"2018-06-20T15:34:36.000Z","global_status":0,"global_status_label":"OK","organization_id":1,"organization_name":"Default
  Organization","location_id":2,"location_name":"Default Location","puppet_status":1,"model_name":"KVM","configuration_status":1,"configuration_status_label":"Active","execution_status":0,"execution_status_label":"Last
  execution succeeded","errata_status":0,"errata_status_label":"All errata applied","subscription_status":0,"subscription_status_label":"Fully
  entitled","name":"host1.example.com","id":2,"puppet_proxy_id":null,"puppet_proxy_name":null,"puppet_ca_proxy_id":null,"puppet_ca_proxy_name":null,"openscap_proxy_id":null,"openscap_proxy_name":null,"puppet_proxy":null,"puppet_ca_proxy":null,"openscap_proxy":null,"hostgroup_name":null,"hostgroup_title":null,"content_facet_attributes":{"id":1,"uuid":"91309802-6995-484e-b48d-9ff137efd8ac","content_view_id":1,"content_view_name":"Default
  Organization View","lifecycle_environment_id":1,"lifecycle_environment_name":"Library","content_source_id":null,"content_source_name":null,"kickstart_repository_id":null,"kickstart_repository_name":null,"errata_counts":{"security":0,"bugfix":0,"enhancement":0,"total":0},"applicable_package_count":0,"upgradable_package_count":0,"content_view":{"id":1,"name":"Default
  Organization View"},"lifecycle_environment":{"id":1,"name":"Library"},"content_source":null,"kickstart_repository":null},"subscription_global_status":0,"subscription_facet_attributes":{"id":1,"uuid":"91309802-6995-484e-b48d-9ff137efd8ac","last_checkin":"2018-06-20T15:18:46.962Z","service_level":"","release_version":null,"autoheal":true,"registered_at":"2018-06-20T14:53:09.000Z","registered_through":"sat.example.com","user":{"id":4,"login":"admin"}}},"foreman_params":{"remote_execution_ssh_keys":["ssh-rsa
  AAAAB3NzaC1yc2EAAAADAQABAAABAQC2jJKA7aoBZb+adG//FLzbHgBFnsGchKQlasAodQ+A4OwXwtp2wJbrQV7TuVoy6WFePZWMuAw9QYYdT4tFuEAAnDQjcSoe1HhL4lKyR1oDpj8E6TtdKHsRGvZvyD0wsqd3/VyXZfk5SNurDh9U4jo96WYzpX4+JK799/Tb8nDQCmWNhFr9kzSz1lhjK0IoFsLkPAK/PedCpZujXZ0M2tv5HL4m+fLPxkoFxOjWQoQPzvccLMLS9IfRf3oI0tugeSSiiLRCYLj45FGnmNY0Rcxl7xKWtBRb5+8s+eQcqjAzdquthMnYG7YICh0XPTKZCli6l9upga8EjwD/QpObYso/
  foreman-proxy.com"],"remote_execution_ssh_user":"root","remote_execution_effective_user_method":"sudo","remote_execution_connect_by_ip":false},"foreman_ansible_roles":[],"ansible_connection":"ssh","ansible_ssh_private_key_file":"~/.ssh/id_rsa_foreman_proxy","ansible_winrm_server_cert_validation":"validate","ansible_become":null,"ansible_user":"root","ansible_ssh_pass":null,"ansible_port":"22","ansible_ssh_port":"22","ansible_ssh_user":"root","remote_execution_ssh_user":"root","remote_execution_effective_user_method":"sudo","remote_execution_ssh_keys":["ssh-rsa
  AAAAB3NzaC1yc2EAAAADAQABAAABAQC2jJKA7aoBZb+adG//FLzbHgBFnsGchKQlasAodQ+A4OwXwtp2wJbrQV7TuVoy6WFePZWMuAw9QYYdT4tFuEAAnDQjcSoe1HhL4lKyR1oDpj8E6TtdKHsRGvZvyD0wsqd3/VyXZfk5SNurDh9U4jo96WYzpX4+JK799/Tb8nDQCmWNhFr9kzSz1lhjK0IoFsLkPAK/PedCpZujXZ0M2tv5HL4m+fLPxkoFxOjWQoQPzvccLMLS9IfRf3oI0tugeSSiiLRCYLj45FGnmNY0Rcxl7xKWtBRb5+8s+eQcqjAzdquthMnYG7YICh0XPTKZCli6l9upga8EjwD/QpObYso/
  foreman-proxy.com"],"remote_execution_connect_by_ip":false}}}}'
hostname: host1.example.com
script: |-
  ---
  - hosts: all
    tasks:
      - command: |
          echo shutdown host && sleep 3
          shutdown -h now
execution_timeout_interval: 
connection_options:
  retry_interval: 15
  retry_count: 4
proxy_url: https://sat.example.com:9090
proxy_action_name: ForemanRemoteExecutionCore::Actions::RunScript
locale: en
current_user_id: 4

Output:

---
proxy_task_id: eff58205-bdb3-499a-ac7e-5ce4ca2e9942
proxy_output:
  result:
  - output_type: stdout
    output: "\r\nPLAY [all] *********************************************************************\r\n\r\nTASK
      [Gathering Facts] *********************************************************\r\n"
    timestamp: 1529508930.2526293
  - output_type: stdout
    output: "ok: [host1.example.com]\r\n\r\nTASK [command] *****************************************************************\r\n"
    timestamp: 1529508931.2545972
  - output_type: stdout
    output: "changed: [host1.example.com]\r\n\r\nPLAY RECAP *********************************************************************\r\nhost1.example.com
      : ok=2    changed=1    unreachable=0    failed=0   \r\n\r\n"
    timestamp: 1529508932.256341
  runner_id: 84d586f9-152f-4db9-a8c6-afe4abce70cd
  exit_status: 0

Definitely can reproduce. I'll send a PR ASAP

Created redmine issue https://projects.theforeman.org/issues/24163 from this bug

https://github.com/theforeman/foreman_ansible/pull/183

Upstream bug assigned to dlobatog

Upstream bug assigned to dlobatog

This will be fixed in 2.2.2 that we plan to release this week.

FailedQA.

@satellite-6.4.0-10.beta.el7sat.noarch
tfm-rubygem-foreman_ansible-2.2.3-1.el7sat.noarch
tfm-rubygem-foreman_ansible_core-2.1.0-1.el7sat.noarch
rubygem-smart_proxy_ansible-2.0.2-3.el7sat.noarch
ansible-2.6.1-1.el7ae.noarch

Now it is the opposite way:

Though Ansible Power job fails the action is really taken.
Ansible Power job fails since the callback doesn't manage to connect if the host is down/rebooting

-----
PLAY [all] *********************************************************************
   2:
   3:
TASK [Gathering Facts] *********************************************************
   4:
ok: [host1.example.com]
   5:
TASK [command] *****************************************************************
   6:
fatal: [host1.example.com]: UNREACHABLE! => {"changed": false, "msg": "Failed to connect to the host via ssh: Shared connection to host1.example.com closed.\r\n", "unreachable": true}
   7:
to retry, use: --limit @/tmp/foreman-playbook-e219d93d-b801-4320-a78b-a5f85ab8e6ed.retry
   8:
   9:
PLAY RECAP *********************************************************************
  10:
host1.example.com : ok=1 changed=0 unreachable=1 failed=0
  11:
Exit status: 4
------

This job should avoid using callback if it is possible?

Only "shutdown" action has issue, the "restart" action is OK since callback manages to connect before restart:

PLAY [all] *********************************************************************
   2:
   3:
TASK [Gathering Facts] *********************************************************
   4:
ok: [host1.example.com]
   5:
TASK [command] *****************************************************************
   6:
[WARNING]: Module invocation had junk after the JSON data:  Broadcast
   7:
message from root.com (Mon 2018-07-16 09:33:32
   8:
EDT): The system is going down for reboot at Mon 2018-07-16 09:34:32 EDT!
   9:
changed: [host1.example.com]
  10:
  11:
PLAY RECAP *********************************************************************
  12:
host1.example.com : ok=2 changed=1 unreachable=0 failed=0
  13:
Exit status: 0

- hosts: all
  tasks:
    - command: |
        <%= case input('action')
          when 'restart'
            'shutdown -r +1'
          else
            'shutdown -h now'
          end %>

There it is! with restart job waits 1 minute while with shutdown doesn't
So the solution is to change s/now/+1/

second part of fix is in 2.2.4

VERIFIED.

@satellite-6.4.0-10.beta.el7sat.noarch (Snap13)
tfm-rubygem-foreman_ansible-2.2.4-1.el7sat.noarch
tfm-rubygem-foreman_ansible_core-2.1.1-1.el7sat.noarch
rubygem-smart_proxy_ansible-2.0.2-3.el7sat.noarch
ansible-2.6.1-1.el7ae.noarch

Both actions "shutdown" and "restart" are successful since callback manages to connect before restarting/shutting down the host:


   1:
PLAY [all] *********************************************************************
   2:
   3:
TASK [Gathering Facts] *********************************************************
   4:
ok: [host1.example.com]
   5:
   6:
TASK [command] *****************************************************************
   7:
[WARNING]: Module invocation had junk after the JSON data:  Broadcast
   8:
message from root.com (Mon 2018-07-23 11:11:18
   9:
EDT): The system is going down for power-off at Mon 2018-07-23 11:12:18 EDT!
  10:
changed: [host1.example.com]
  11:
  12:
PLAY RECAP *********************************************************************
  13:
host1.example.com : ok=2 changed=1 unreachable=0 failed=0
  14:
Exit status: 0

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2018:2927