ibm_zos_core icon indicating copy to clipboard operation
ibm_zos_core copied to clipboard

[Bug] [zos_mvs_raw] Verbose output is omitted if rc=0

Open ketankelkar opened this issue 11 months ago • 0 comments

Bug description

I have a playbook where I:

  • create a data set.
  • invoke zos_mvs_raw to LISTCAT the data set
  • delete the data set.

With or without verbose enabled, the output is the same. There is no way for me to see the underlying ZOAU logs.

For example, if I were to call mvscmd on shell with verbose enabled, I see the ZOAU logs printed out at the bottom after the regular LISTCAT output:

1IDCAMS  SYSTEM SERVICES                                           TIME: 19:54:37        03/28/24     PAGE      1
0        
  LISTCAT ENTRIES('KETAN.PRIVATE.ONE')
0NONVSAM ------- KETAN.PRIVATE.ONE
      IN-CAT --- CATALOG.SVPLEX9.MASTER
1IDCAMS  SYSTEM SERVICES                                           TIME: 19:54:37        03/28/24     PAGE      2
0         THE NUMBER OF ENTRIES PROCESSED WAS:
                    AIX -------------------0
                    ALIAS -----------------0
                    CLUSTER ---------------0
                    DATA ------------------0
                    GDG -------------------0
                    INDEX -----------------0
                    NONVSAM ---------------1
                    PAGESPACE -------------0
                    PATH ------------------0
                    SPACE -----------------0
                    USERCATALOG -----------0
                    TAPELIBRARY -----------0
                    TAPEVOLUME ------------0
                    TOTAL -----------------1
0         THE NUMBER OF PROTECTED ENTRIES SUPPRESSED WAS 0
0IDC0001I FUNCTION COMPLETED, HIGHEST CONDITION CODE WAS 0
0        
0IDC0002I IDCAMS PROCESSING COMPLETE. MAXIMUM CONDITION CODE WAS 0
BGYSC0307I Program: <idcams> Arguments: <>
BGYSC0308I DDNames:
BGYSC0333I   SYSIN=stdin
BGYSC0310I   SYSPRINT=*
BGYSC0332I Dynamic allocation succeeded for SYSIN (temporary dataset for stdin)
BGYSC0304I Dynamic allocation succeeded for SYSPRINT (temporary dataset for console)
BGYSC0328I OS Load program IDCAMS  
BGYSC0319I Program is APF authorized
BGYSC0320I Addressing mode: AMODE31
BGYSC0327I Attach Exit code: 0 from IDCAMS
BGYSC0355I Stdin free succeeded for SYSIN
BGYSC0356I Console free succeeded for SYSPRINT

Homework:

(link to code)

program_response = run_zos_program(
                program=program,
                parm=program_parm,
                dd_statements=dd_statements,
                authorized=authorized,
                verbose=verbose,
            )
            if program_response.rc != 0 and program_response.stderr:
                raise ZOSRawError(
                    program,
                    "{0} {1}".format(program_response.stdout, program_response.stderr),
                )

            response = build_response(program_response.rc, dd_statements)
            result["changed"] = True
        except Exception as e:
            result["backups"] = backups
            module.fail_json(msg=repr(e), **result)

In the above snippet from plugins/modules/zos_mvs_raw.py, the run_zos_program function calls either MVSCmd.execute_authorized or MVSCmd.execute, which in turn constructs a command string and passes it to run_command. The run_command function runs the mvscmd and returns a tuple (rc, out, err) (which is packaged into an MVSCmdReponse object as rc, stdout, and stderr).

Notice in the above snippet, where if the rc is not non-zero (ie rc=0), the rc and the dd_statements is passed to a function build_response. The out and err portion of the returned tuple are not captured. The verbose ZOAU logs would be in one of those.

Conversely, upon receiving a non-zero rc, the out and erras well as the rc are raised in an Error (and returned to the user).

The playbook:


  vars:
    RC_0_DATA_SET_NAME: "KETAN.ANSIBLE.ONE"

    DATA_SET_TO_LISTCAT: "KETAN.ANSIBLE.SOMEDS"
    IDCAMS_STDIN: " LISTCAT ENTRIES('{{ DATA_SET_TO_LISTCAT | upper }}')"

  tasks:
  - name: create some data set
    block:
      - name: create data set to LISTCAT
        zos_data_set:
          name: "{{ DATA_SET_TO_LISTCAT }}"
          type: SEQ
          state: present
          replace: yes

      - name: mvs raw with verbose with rc=0
        zos_mvs_raw:
          verbose: True
          program_name: idcams
          auth: True
          dds:
            - dd_data_set:
                dd_name: SYSPRINT
                data_set_name: "{{ RC_0_DATA_SET_NAME }}"
                disposition: new
                type: seq
                return_content:
                  type: text
            - dd_input:
                dd_name: SYSIN
                content: "{{ IDCAMS_STDIN }}"
        register: output_rc_0

      - name: print output
        debug:
          msg:
            - "{{ output_rc_0 }}"


    always:
      - name: delete data sets
        zos_data_set:
          name: "{{ item }}"
          state: absent
        loop:
          - "{{ DATA_SET_TO_LISTCAT }}"
          - "{{ RC_0_DATA_SET_NAME }}"

Non-verbose output:


TASK [create data set to LISTCAT] *****************************************************************************************************************************************************************************************************************************
Thursday 28 March 2024  17:36:33 -0700 (0:00:00.007)       0:00:00.007 ******** 
changed: [zvm]

TASK [mvs raw with verbose with rc=0] *************************************************************************************************************************************************************************************************************************
Thursday 28 March 2024  17:36:36 -0700 (0:00:03.767)       0:00:03.775 ******** 
changed: [zvm]

TASK [print output] *******************************************************************************************************************************************************************************************************************************************
Thursday 28 March 2024  17:36:40 -0700 (0:00:03.107)       0:00:06.882 ******** 
ok: [zvm] => {
    "msg": [
        {
            "backups": [],
            "changed": true,
            "dd_names": [
                {
                    "byte_count": 1213,
                    "content": [
                        "\fIDCAMS  SYSTEM SERVICES                                           TIME: 20:36:39        03/28/24     PAGE      1",
                        "",
                        "        ",
                        " LISTCAT ENTRIES('KETAN.ANSIBLE.SOMEDS')",
                        "",
                        "NONVSAM ------- KETAN.ANSIBLE.SOMEDS",
                        "     IN-CAT --- CATALOG.SVPLEX9.MASTER\fIDCAMS  SYSTEM SERVICES                                           TIME: 20:36:39        03/28/24     PAGE      2",
                        "",
                        "         THE NUMBER OF ENTRIES PROCESSED WAS:",
                        "                   AIX -------------------0",
                        "                   ALIAS -----------------0",
                        "                   CLUSTER ---------------0",
                        "                   DATA ------------------0",
                        "                   GDG -------------------0",
                        "                   INDEX -----------------0",
                        "                   NONVSAM ---------------1",
                        "                   PAGESPACE -------------0",
                        "                   PATH ------------------0",
                        "                   SPACE -----------------0",
                        "                   USERCATALOG -----------0",
                        "                   TAPELIBRARY -----------0",
                        "                   TAPEVOLUME ------------0",
                        "                   TOTAL -----------------1",
                        "",
                        "         THE NUMBER OF PROTECTED ENTRIES SUPPRESSED WAS 0",
                        "",
                        "IDC0001I FUNCTION COMPLETED, HIGHEST CONDITION CODE WAS 0",
                        "",
                        "        ",
                        "",
                        "IDC0002I IDCAMS PROCESSING COMPLETE. MAXIMUM CONDITION CODE WAS 0",
                        ""
                    ],
                    "dd_name": "SYSPRINT",
                    "name": "KETAN.ANSIBLE.ONE",
                    "record_count": 32
                }
            ],
            "failed": false,
            "ret_code": {
                "code": 0
            }
        }
    ]
}

See the verbose output below:

IBM z/OS Ansible core Version

v1.10.0-beta.1

IBM Z Open Automation Utilities

v1.3.0

IBM Enterprise Python

v3.11.x (default)

ansible-version

v2.15.x

z/OS version

v2.5 (default)

Ansible module

zos_mvs_raw

Playbook verbosity output.

ansible-playbook [core 2.15.5]
  config file = /etc/ansible/ansible.cfg
  configured module search path = ['/Users/ketan/.ansible/plugins/modules', '/usr/share/ansible/plugins/modules']
  ansible python module location = /Users/ketan/venvs/3.11/ansible-2.15/lib/python3.11/site-packages/ansible
  ansible collection location = /Users/ketan/.ansible/collections:/usr/share/ansible/collections
  executable location = /Users/ketan/venvs/3.11/ansible-2.15/bin/ansible-playbook
  python version = 3.11.3 (main, May  1 2023, 16:38:43) [Clang 14.0.3 (clang-1403.0.22.14.1)] (/Users/ketan/venvs/3.11/ansible-2.15/bin/python3.11)
  jinja version = 3.1.2
  libyaml = True
Using /etc/ansible/ansible.cfg as config file
host_list declined parsing /Users/ketan/inventory as it did not pass its verify_file() method
script declined parsing /Users/ketan/inventory as it did not pass its verify_file() method
auto declined parsing /Users/ketan/inventory as it did not pass its verify_file() method
Parsed /Users/ketan/inventory inventory source with ini plugin
redirecting (type: callback) ansible.builtin.profile_tasks to ansible.posix.profile_tasks
Skipping callback 'default', as we already have a stdout callback.
Skipping callback 'minimal', as we already have a stdout callback.
Skipping callback 'oneline', as we already have a stdout callback.

PLAYBOOK: npXzoau13X.yml **************************************************************************************************************************************************************************************************************************************
1 plays in npXzoau13X.yml

PLAY [npX,zoau1.3.X] ******************************************************************************************************************************************************************************************************************************************

TASK [create data set to LISTCAT] *****************************************************************************************************************************************************************************************************************************
task path: /Users/ketan/dev/playbooks/npXzoau13X.yml:47
Thursday 28 March 2024  17:07:21 -0700 (0:00:00.007)       0:00:00.007 ******** 
Using module file /Users/ketan/.ansible/collections/ansible_collections/ibm/ibm_zos_core/plugins/modules/zos_data_set.py
Pipelining is enabled.
<pkstnp9.pok.stglabs.ibm.com> ESTABLISH SSH CONNECTION FOR USER: KETAN
<pkstnp9.pok.stglabs.ibm.com> SSH: EXEC ssh -C -o ControlMaster=auto -o ControlPersist=60s -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o 'User="KETAN"' -o ConnectTimeout=10 -o 'ControlPath="/Users/ketan/.ansible/cp/64a13ee7bc"' pkstnp9.pok.stglabs.ibm.com '/bin/sh -c '"'"'_BPXK_AUTOCVT=ALL _CEE_RUNOPTS='"'"'"'"'"'"'"'"'FILETAG(AUTOCVT,AUTOTAG) POSIX(ON)'"'"'"'"'"'"'"'"' _TAG_REDIR_ERR=txt _TAG_REDIR_IN=txt _TAG_REDIR_OUT=txt LANG=C ZOAU=/global/zoautil/1.3.0.0/bin LIBPATH=/global/zoautil/1.3.0.0/lib/:/global/cyp/3.11/usr/lpp/IBM/cyp/v3r11/pyz/lib:/lib:/usr/lib:. PYTHONPATH=/global/zoautil/1.3.0.0/lib/3.11 PATH=/global/zoautil/1.3.0.0/bin:/global/cyp/3.11/usr/lpp/IBM/cyp/v3r11/pyz/bin:/bin:/usr/sbin:/var/bin:. PYTHONSTDINENCODING=cp1047 /global/cyp/3.11/usr/lpp/IBM/cyp/v3r11/pyz/bin/python3 && sleep 0'"'"''
<pkstnp9.pok.stglabs.ibm.com> (0, b'\n{"changed": true, "message": "", "names": ["KETAN.ANSIBLE.SOMEDS"], "invocation": {"module_args": {"name": "KETAN.ANSIBLE.SOMEDS", "type": "SEQ", "state": "present", "replace": true, "space_type": "M", "space_primary": 5, "space_secondary": 3, "record_format": "FB", "force": false, "batch": null, "sms_management_class": null, "sms_storage_class": null, "sms_data_class": null, "block_size": null, "directory_blocks": null, "record_length": null, "key_offset": null, "key_length": null, "volumes": null, "tmp_hlq": null}}}\n', b'')
changed: [zvm] => {
    "changed": true,
    "invocation": {
        "module_args": {
            "batch": null,
            "block_size": null,
            "directory_blocks": null,
            "force": false,
            "key_length": null,
            "key_offset": null,
            "name": "KETAN.ANSIBLE.SOMEDS",
            "record_format": "FB",
            "record_length": null,
            "replace": true,
            "sms_data_class": null,
            "sms_management_class": null,
            "sms_storage_class": null,
            "space_primary": 5,
            "space_secondary": 3,
            "space_type": "M",
            "state": "present",
            "tmp_hlq": null,
            "type": "SEQ",
            "volumes": null
        }
    },
    "message": "",
    "names": [
        "KETAN.ANSIBLE.SOMEDS"
    ]
}

TASK [mvs raw with verbose with rc=0] *************************************************************************************************************************************************************************************************************************
task path: /Users/ketan/dev/playbooks/npXzoau13X.yml:54
Thursday 28 March 2024  17:07:25 -0700 (0:00:03.808)       0:00:03.815 ******** 
Using module file /Users/ketan/.ansible/collections/ansible_collections/ibm/ibm_zos_core/plugins/modules/zos_mvs_raw.py
Pipelining is enabled.
<pkstnp9.pok.stglabs.ibm.com> ESTABLISH SSH CONNECTION FOR USER: KETAN
<pkstnp9.pok.stglabs.ibm.com> SSH: EXEC ssh -C -o ControlMaster=auto -o ControlPersist=60s -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o 'User="KETAN"' -o ConnectTimeout=10 -o 'ControlPath="/Users/ketan/.ansible/cp/64a13ee7bc"' pkstnp9.pok.stglabs.ibm.com '/bin/sh -c '"'"'_BPXK_AUTOCVT=ALL _CEE_RUNOPTS='"'"'"'"'"'"'"'"'FILETAG(AUTOCVT,AUTOTAG) POSIX(ON)'"'"'"'"'"'"'"'"' _TAG_REDIR_ERR=txt _TAG_REDIR_IN=txt _TAG_REDIR_OUT=txt LANG=C ZOAU=/global/zoautil/1.3.0.0/bin LIBPATH=/global/zoautil/1.3.0.0/lib/:/global/cyp/3.11/usr/lpp/IBM/cyp/v3r11/pyz/lib:/lib:/usr/lib:. PYTHONPATH=/global/zoautil/1.3.0.0/lib/3.11 PATH=/global/zoautil/1.3.0.0/bin:/global/cyp/3.11/usr/lpp/IBM/cyp/v3r11/pyz/bin:/bin:/usr/sbin:/var/bin:. PYTHONSTDINENCODING=cp1047 /global/cyp/3.11/usr/lpp/IBM/cyp/v3r11/pyz/bin/python3 && sleep 0'"'"''
<pkstnp9.pok.stglabs.ibm.com> (0, b'\n{"changed": true, "dd_names": [{"dd_name": "SYSPRINT", "name": "KETAN.ANSIBLE.ONE", "content": ["\\fIDCAMS  SYSTEM SERVICES                                           TIME: 20:07:28        03/28/24     PAGE      1", "", "        ", " LISTCAT ENTRIES(\'KETAN.ANSIBLE.SOMEDS\')", "", "NONVSAM ------- KETAN.ANSIBLE.SOMEDS", "     IN-CAT --- CATALOG.SVPLEX9.MASTER\\fIDCAMS  SYSTEM SERVICES                                           TIME: 20:07:28        03/28/24     PAGE      2", "", "         THE NUMBER OF ENTRIES PROCESSED WAS:", "                   AIX -------------------0", "                   ALIAS -----------------0", "                   CLUSTER ---------------0", "                   DATA ------------------0", "                   GDG -------------------0", "                   INDEX -----------------0", "                   NONVSAM ---------------1", "                   PAGESPACE -------------0", "                   PATH ------------------0", "                   SPACE -----------------0", "                   USERCATALOG -----------0", "                   TAPELIBRARY -----------0", "                   TAPEVOLUME ------------0", "                   TOTAL -----------------1", "", "         THE NUMBER OF PROTECTED ENTRIES SUPPRESSED WAS 0", "", "IDC0001I FUNCTION COMPLETED, HIGHEST CONDITION CODE WAS 0", "", "        ", "", "IDC0002I IDCAMS PROCESSING COMPLETE. MAXIMUM CONDITION CODE WAS 0", ""], "record_count": 32, "byte_count": 1213}], "ret_code": {"code": 0}, "backups": [], "invocation": {"module_args": {"verbose": true, "program_name": "idcams", "auth": true, "dds": [{"dd_data_set": {"dd_name": "SYSPRINT", "data_set_name": "KETAN.ANSIBLE.ONE", "disposition": "new", "type": "seq", "return_content": {"type": "text", "src_encoding": "ibm-1047", "response_encoding": "iso8859-1"}, "reuse": false, "replace": false, "backup": false, "disposition_normal": null, "disposition_abnormal": null, "space_type": null, "space_primary": null, "space_secondary": null, "volumes": null, "sms_management_class": null, "sms_storage_class": null, "sms_data_class": null, "block_size": null, "directory_blocks": null, "key_label": null, "encryption_key_1": null, "encryption_key_2": null, "key_length": null, "key_offset": null, "record_length": null, "record_format": null}, "dd_unix": null, "dd_input": null, "dd_output": null, "dd_vio": null, "dd_concat": null, "dd_dummy": null}, {"dd_input": {"dd_name": "SYSIN", "content": " LISTCAT ENTRIES(\'KETAN.ANSIBLE.SOMEDS\')", "return_content": null}, "dd_data_set": null, "dd_unix": null, "dd_output": null, "dd_vio": null, "dd_concat": null, "dd_dummy": null}], "parm": null, "tmp_hlq": null}}}\n', b'')
changed: [zvm] => {
    "backups": [],
    "changed": true,
    "dd_names": [
        {
            "byte_count": 1213,
            "content": [
                "\fIDCAMS  SYSTEM SERVICES                                           TIME: 20:07:28        03/28/24     PAGE      1",
                "",
                "        ",
                " LISTCAT ENTRIES('KETAN.ANSIBLE.SOMEDS')",
                "",
                "NONVSAM ------- KETAN.ANSIBLE.SOMEDS",
                "     IN-CAT --- CATALOG.SVPLEX9.MASTER\fIDCAMS  SYSTEM SERVICES                                           TIME: 20:07:28        03/28/24     PAGE      2",
                "",
                "         THE NUMBER OF ENTRIES PROCESSED WAS:",
                "                   AIX -------------------0",
                "                   ALIAS -----------------0",
                "                   CLUSTER ---------------0",
                "                   DATA ------------------0",
                "                   GDG -------------------0",
                "                   INDEX -----------------0",
                "                   NONVSAM ---------------1",
                "                   PAGESPACE -------------0",
                "                   PATH ------------------0",
                "                   SPACE -----------------0",
                "                   USERCATALOG -----------0",
                "                   TAPELIBRARY -----------0",
                "                   TAPEVOLUME ------------0",
                "                   TOTAL -----------------1",
                "",
                "         THE NUMBER OF PROTECTED ENTRIES SUPPRESSED WAS 0",
                "",
                "IDC0001I FUNCTION COMPLETED, HIGHEST CONDITION CODE WAS 0",
                "",
                "        ",
                "",
                "IDC0002I IDCAMS PROCESSING COMPLETE. MAXIMUM CONDITION CODE WAS 0",
                ""
            ],
            "dd_name": "SYSPRINT",
            "name": "KETAN.ANSIBLE.ONE",
            "record_count": 32
        }
    ],
    "invocation": {
        "module_args": {
            "auth": true,
            "dds": [
                {
                    "dd_concat": null,
                    "dd_data_set": {
                        "backup": false,
                        "block_size": null,
                        "data_set_name": "KETAN.ANSIBLE.ONE",
                        "dd_name": "SYSPRINT",
                        "directory_blocks": null,
                        "disposition": "new",
                        "disposition_abnormal": null,
                        "disposition_normal": null,
                        "encryption_key_1": null,
                        "encryption_key_2": null,
                        "key_label": null,
                        "key_length": null,
                        "key_offset": null,
                        "record_format": null,
                        "record_length": null,
                        "replace": false,
                        "return_content": {
                            "response_encoding": "iso8859-1",
                            "src_encoding": "ibm-1047",
                            "type": "text"
                        },
                        "reuse": false,
                        "sms_data_class": null,
                        "sms_management_class": null,
                        "sms_storage_class": null,
                        "space_primary": null,
                        "space_secondary": null,
                        "space_type": null,
                        "type": "seq",
                        "volumes": null
                    },
                    "dd_dummy": null,
                    "dd_input": null,
                    "dd_output": null,
                    "dd_unix": null,
                    "dd_vio": null
                },
                {
                    "dd_concat": null,
                    "dd_data_set": null,
                    "dd_dummy": null,
                    "dd_input": {
                        "content": " LISTCAT ENTRIES('KETAN.ANSIBLE.SOMEDS')",
                        "dd_name": "SYSIN",
                        "return_content": null
                    },
                    "dd_output": null,
                    "dd_unix": null,
                    "dd_vio": null
                }
            ],
            "parm": null,
            "program_name": "idcams",
            "tmp_hlq": null,
            "verbose": true
        }
    },
    "ret_code": {
        "code": 0
    }
}

TASK [print output] *******************************************************************************************************************************************************************************************************************************************
task path: /Users/ketan/dev/playbooks/npXzoau13X.yml:91
Thursday 28 March 2024  17:07:29 -0700 (0:00:03.946)       0:00:07.762 ******** 
ok: [zvm] => {
    "msg": [
        {
            "backups": [],
            "changed": true,
            "dd_names": [
                {
                    "byte_count": 1213,
                    "content": [
                        "\fIDCAMS  SYSTEM SERVICES                                           TIME: 20:07:28        03/28/24     PAGE      1",
                        "",
                        "        ",
                        " LISTCAT ENTRIES('KETAN.ANSIBLE.SOMEDS')",
                        "",
                        "NONVSAM ------- KETAN.ANSIBLE.SOMEDS",
                        "     IN-CAT --- CATALOG.SVPLEX9.MASTER\fIDCAMS  SYSTEM SERVICES                                           TIME: 20:07:28        03/28/24     PAGE      2",
                        "",
                        "         THE NUMBER OF ENTRIES PROCESSED WAS:",
                        "                   AIX -------------------0",
                        "                   ALIAS -----------------0",
                        "                   CLUSTER ---------------0",
                        "                   DATA ------------------0",
                        "                   GDG -------------------0",
                        "                   INDEX -----------------0",
                        "                   NONVSAM ---------------1",
                        "                   PAGESPACE -------------0",
                        "                   PATH ------------------0",
                        "                   SPACE -----------------0",
                        "                   USERCATALOG -----------0",
                        "                   TAPELIBRARY -----------0",
                        "                   TAPEVOLUME ------------0",
                        "                   TOTAL -----------------1",
                        "",
                        "         THE NUMBER OF PROTECTED ENTRIES SUPPRESSED WAS 0",
                        "",
                        "IDC0001I FUNCTION COMPLETED, HIGHEST CONDITION CODE WAS 0",
                        "",
                        "        ",
                        "",
                        "IDC0002I IDCAMS PROCESSING COMPLETE. MAXIMUM CONDITION CODE WAS 0",
                        ""
                    ],
                    "dd_name": "SYSPRINT",
                    "name": "KETAN.ANSIBLE.ONE",
                    "record_count": 32
                }
            ],
            "failed": false,
            "ret_code": {
                "code": 0
            }
        }
    ]
}

ketankelkar avatar Mar 29 '24 00:03 ketankelkar