[molecule 3.2.0a1] vagrant.py: MODULE FAILURE See stdout/stderr for the exact error

[hswong3i]

Overview

When running with molecule 3.2.0a1 + molecule-vagrant 0.5, when running TASK [Create molecule instance(s)] it coming with following error and stopped, even tough vagrant instance IS successfully created + up + vagrant ssh successfully:

TASK [Create molecule instance(s)] *********************************************
failed: [localhost] (item=instance) => {"ansible_loop_var": "item", "changed": false, "item": {"box": 
"generic/ubuntu2004", "name": "instance"}, "module_stderr": "", "module_stdout": "\n{\"changed\": true, 
\"log\": \n\"/home/hswong3i/.cache/molecule/foobar/default/vagrant-instance.out\", \"Host\": 
\n\"instance\", \"HostName\": \"192.168.121.2\", \"User\": \"vagrant\", \"Port\": \"22\", 
\n\"UserKnownHostsFile\": \"/dev/null\", \"StrictHostKeyChecking\": \"no\", \n\"PasswordAuthentication\":
\"no\", \"IdentityFile\": 
\"/home/hswong3i/.cache/molecule/\nfoobar/default/.vagrant/machines/instance/libvirt/private_key\", 
\n\"IdentitiesOnly\": \"yes\", \"LogLevel\": \"FATAL\", \"invocation\": {\"module_args\": 
\n{\"instance_name\": \"instance\", \"platform_box\": \"generic/ubuntu2004\", \n\"provider_name\": 
\"libvirt\", \"state\": \"up\", \"instance_interfaces\": [], \n\"config_options\": {}, 
\"provider_memory\": 512, \"provider_cpus\": 2, \n\"provider_options\": {}, \"provision\": false, 
\"force_stop\": false, \n\"instance_raw_config_args\": null, \"platform_box_version\": null, 
\n\"platform_box_url\": null, \"provider_override_args\": null, \n\"provider_raw_config_args\": null, 
\"workdir\": null}}}\n", "msg": "MODULE FAILURE\nSee stdout/stderr for the exact error", "rc": 0}

@ssbarnea any idea if it is related to ansible/molecule#2929?

How to Reproduce the Error

hswong3i@hswong3i-XPS-13-9300:/tmp/tmp.2ErGVwAYKe/foobar$ molecule --version
molecule 3.2.0a1 using python 3.8 
    ansible:2.10.3
    delegated:3.2.0a1 from molecule
    docker:0.2.4 from molecule_docker
    podman:0.3.0 from molecule_podman
    vagrant:0.5 from molecule_vagrant

hswong3i@hswong3i-XPS-13-9300:/tmp/tmp.2ErGVwAYKe/foobar$ cat molecule/default/molecule.yml 
---
dependency:
  name: galaxy
driver:
  name: vagrant
  provider:
    name: libvirt
platforms:
  - name: instance
    box: generic/ubuntu2004
provisioner:
  name: ansible
verifier:
  name: ansible

hswong3i@hswong3i-XPS-13-9300:/tmp/tmp.2ErGVwAYKe/foobar$ molecule test
DEBUG    Validating schema /tmp/tmp.2ErGVwAYKe/foobar/molecule/default/molecule.yml.
INFO     default scenario test matrix: dependency, lint, cleanup, destroy, syntax, create, prepare, 
converge, idempotence, side_effect, verify, cleanup, destroy
INFO     Running default > dependency
WARNING  Skipping, missing the requirements file.
WARNING  Skipping, missing the requirements file.
INFO     Running default > lint
INFO     Lint is disabled.
INFO     Running default > cleanup
WARNING  Skipping, cleanup playbook not configured.
INFO     Running default > destroy
DEBUG    Using selector: EpollSelector

PLAY [Destroy] *****************************************************************

TASK [Destroy molecule instance(s)] ********************************************
ok: [localhost] => (item=instance)

TASK [Populate instance config] ************************************************
ok: [localhost]

TASK [Dump instance config] ****************************************************
skipping: [localhost]

PLAY RECAP *********************************************************************
localhost                  : ok=2    changed=0    unreachable=0    failed=0    skipped=1    rescued=0    
ignored=0

INFO     Running default > syntax

playbook: /tmp/tmp.2ErGVwAYKe/foobar/molecule/default/converge.yml
INFO     Running default > create

PLAY [Create] ******************************************************************

TASK [Create molecule instance(s)] *********************************************
failed: [localhost] (item=instance) => {"ansible_loop_var": "item", "changed": false, "item": {"box": 
"generic/ubuntu2004", "name": "instance"}, "module_stderr": "", "module_stdout": "\n{\"changed\": true, 
\"log\": \n\"/home/hswong3i/.cache/molecule/foobar/default/vagrant-instance.out\", \"Host\": 
\n\"instance\", \"HostName\": \"192.168.121.2\", \"User\": \"vagrant\", \"Port\": \"22\", 
\n\"UserKnownHostsFile\": \"/dev/null\", \"StrictHostKeyChecking\": \"no\", \n\"PasswordAuthentication\":
\"no\", \"IdentityFile\": 
\"/home/hswong3i/.cache/molecule/\nfoobar/default/.vagrant/machines/instance/libvirt/private_key\", 
\n\"IdentitiesOnly\": \"yes\", \"LogLevel\": \"FATAL\", \"invocation\": {\"module_args\": 
\n{\"instance_name\": \"instance\", \"platform_box\": \"generic/ubuntu2004\", \n\"provider_name\": 
\"libvirt\", \"state\": \"up\", \"instance_interfaces\": [], \n\"config_options\": {}, 
\"provider_memory\": 512, \"provider_cpus\": 2, \n\"provider_options\": {}, \"provision\": false, 
\"force_stop\": false, \n\"instance_raw_config_args\": null, \"platform_box_version\": null, 
\n\"platform_box_url\": null, \"provider_override_args\": null, \n\"provider_raw_config_args\": null, 
\"workdir\": null}}}\n", "msg": "MODULE FAILURE\nSee stdout/stderr for the exact error", "rc": 0}

PLAY RECAP *********************************************************************
localhost                  : ok=0    changed=0    unreachable=0    failed=1    skipped=0    rescued=0    
ignored=0

CRITICAL Ansible return code was 2, command was: ansible-playbook --inventory 
/home/hswong3i/.cache/molecule/foobar/default/inventory --skip-tags molecule-notest,notest 
/usr/local/lib/python3.8/dist-packages/molecule_vagrant/playbooks/create.yml
WARNING  An error occurred during the test sequence action: 'create'. Cleaning up.
INFO     Running default > cleanup
WARNING  Skipping, cleanup playbook not configured.
INFO     Running default > destroy

PLAY [Destroy] *****************************************************************

TASK [Destroy molecule instance(s)] ********************************************
changed: [localhost] => (item=instance)

TASK [Populate instance config] ************************************************
ok: [localhost]

TASK [Dump instance config] ****************************************************
ok: [localhost]

PLAY RECAP *********************************************************************
localhost                  : ok=3    changed=1    unreachable=0    failed=0    skipped=0    rescued=0    
ignored=0

INFO     Pruning extra files from scenario ephemeral directory

Expected Result

When running with molecule 3.2.0a0 + molecule-vagrant 0.5, everything looks normal:

hswong3i@hswong3i-XPS-13-9300:/tmp/tmp.2ErGVwAYKe/foobar$ molecule --version
molecule 3.2.0a0
    ansible:2.10.3 python:3.8
    delegated:3.2.0a0 from molecule
    docker:0.2.4 from molecule_docker
    podman:0.3.0 from molecule_podman
    vagrant:0.5 from molecule_vagrant

hswong3i@hswong3i-XPS-13-9300:/tmp/tmp.2ErGVwAYKe/foobar$ cat molecule/default/molecule.yml 
---
dependency:
  name: galaxy
driver:
  name: vagrant
  provider:
    name: libvirt
platforms:
  - name: instance
    box: generic/ubuntu2004
provisioner:
  name: ansible
verifier:
  name: ansible

hswong3i@hswong3i-XPS-13-9300:/tmp/tmp.2ErGVwAYKe/foobar$ molecule test
--> Test matrix
---                                                                                                     
default:                                                                                                
  - dependency                                                                                          
  - lint                                                                                                
  - cleanup                                                                                             
  - destroy                                                                                             
  - syntax                                                                                              
  - create                                                                                              
  - prepare                                                                                             
  - converge                                                                                            
  - idempotence                                                                                         
  - side_effect                                                                                         
  - verify                                                                                              
  - cleanup                                                                                             
  - destroy                                                                                             
--> Scenario: 'default'
--> Action: 'dependency'
Skipping, missing the requirements file.
Skipping, missing the requirements file.
--> Scenario: 'default'
--> Action: 'lint'
--> Lint is disabled.
--> Scenario: 'default'
--> Action: 'cleanup'
Skipping, cleanup playbook not configured.
--> Scenario: 'default'
--> Action: 'destroy'

PLAY [Destroy] *****************************************************************

TASK [Destroy molecule instance(s)] ********************************************
ok: [localhost] => (item=instance)

TASK [Populate instance config] ************************************************
ok: [localhost]

TASK [Dump instance config] ****************************************************
skipping: [localhost]

PLAY RECAP *********************************************************************
localhost                  : ok=2    changed=0    unreachable=0    failed=0    skipped=1    rescued=0    ignored=0

--> Scenario: 'default'
--> Action: 'syntax'

playbook: /tmp/tmp.2ErGVwAYKe/foobar/molecule/default/converge.yml
--> Scenario: 'default'
--> Action: 'create'

PLAY [Create] ******************************************************************

TASK [Create molecule instance(s)] *********************************************
changed: [localhost] => (item=instance)

TASK [Populate instance config dict] *******************************************
ok: [localhost] => (item=None)
ok: [localhost]

TASK [Convert instance config dict to a list] **********************************
ok: [localhost]

TASK [Dump instance config] ****************************************************
changed: [localhost]

PLAY RECAP *********************************************************************
localhost                  : ok=4    changed=2    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0

--> Scenario: 'default'
--> Action: 'prepare'

PLAY [Prepare] *****************************************************************

TASK [Bootstrap python for Ansible] ********************************************
ok: [instance]

PLAY RECAP *********************************************************************
instance                   : ok=1    changed=0    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0

--> Scenario: 'default'
--> Action: 'converge'

PLAY [Converge] ****************************************************************

TASK [Gathering Facts] *********************************************************
ok: [instance]

TASK [Include foobar] **********************************************************

PLAY RECAP *********************************************************************
instance                   : ok=1    changed=0    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0

--> Scenario: 'default'
--> Action: 'idempotence'

PLAY [Converge] ****************************************************************

TASK [Gathering Facts] *********************************************************
ok: [instance]

TASK [Include foobar] **********************************************************

PLAY RECAP *********************************************************************
instance                   : ok=1    changed=0    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0

Idempotence completed successfully.
--> Scenario: 'default'
--> Action: 'side_effect'
Skipping, side effect playbook not configured.
--> Scenario: 'default'
--> Action: 'verify'
--> Running Ansible Verifier

PLAY [Verify] ******************************************************************

TASK [Example assertion] *******************************************************
ok: [instance] => {
    "changed": false,
    "msg": "All assertions passed"
}

PLAY RECAP *********************************************************************
instance                   : ok=1    changed=0    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0

Verifier completed successfully.
--> Scenario: 'default'
--> Action: 'cleanup'
Skipping, cleanup playbook not configured.
--> Scenario: 'default'
--> Action: 'destroy'

PLAY [Destroy] *****************************************************************

TASK [Destroy molecule instance(s)] ********************************************
changed: [localhost] => (item=instance)

TASK [Populate instance config] ************************************************
ok: [localhost]

TASK [Dump instance config] ****************************************************
changed: [localhost]

PLAY RECAP *********************************************************************
localhost                  : ok=3    changed=2    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0

--> Pruning extra files from scenario ephemeral directory

[apatard]

sounds weird. The module is returning 0, vagrant is showing the VM as up and still, things are failing. I can reproduce it here but I won't have time to look at it over the week end.

[apatard]

I've yet to understand why but the output of the module get limited to 80 columns (I guess) and this leads to fields like the IdentityFile having a '\n' inside them:

\"no\", \"IdentityFile\": 
\"/home/hswong3i/.cache/molecule/\nfoobar/default/.vagrant/machines/instance/libvirt/private_key\", 

and when ansible tries to interpret that as JSON it fails. That's why we're getting a failure.

[apatard]

Ok. Found it. The vagrant module is using utility functions from molecule and when the split was done, instead of copying them, we're still importing them. With newer molecule, the imported modules are now configuring the module output to use enrich:

console.py:
...
console = Console(
    force_terminal=should_do_markup(), theme=theme, record=True, redirect=True
)
...

And enrich is doing soft wrap by default. So, the module output gets wrapped to 80 columns when ansible is running it, breaking the module output.
A crude fix would be to change the previous line to:

console.py:
...
console = Console(
    force_terminal=should_do_markup(), theme=theme, record=True, redirect=True, soft_wrap=should_do_markup()
)
...

@ssbarnea What's the best option ? Copying the needed functions from molecule.util into vagrant.py module or changing console.py as I'm proposing here ?

[hswong3i]

+1 for changing console.py as I'm proposing here, since this should be the original expected behavior? If the soft_wrap=should_do_markup() could works with both new standard and existing molecule implementation?

[apatard]

I'm not sure what are the exact consequences of this change. I've done a PR to molecule. I hope it'll allow to get more input from knowledgeable people on the issue

[hswong3i]

@apatard as per ansible/molecule#2993, upgrade enrich>=1.2.3 as below working with molecule>=3.2.0a1,<3.3.0

sudo -H pip install --upgrade 'enrich>=1.2.3' 'molecule>=3.2.0a1,<3.3.0'

[sio]

I confirm that enrich 1.2.3 fixes the issue