[Bug] zos_operator_action_query reported UnicodeDecodeError when the outstanding messages contain special characters

[cdlwhui]

Is there an existing issue for this?

• There are no existing issues.

Are the dependencies a supported version?

• The dependencies are supported.

IBM Z Open Automation Utilities

v1.2.2

IBM Enterprise Python

v3.11.x

IBM z/OS Ansible core Version

v1.5.0

ansible-version

v2.12.x

z/OS version

v2.5

Ansible module

zos_operator_action_query

Bug description

It failed when using zos_operator_action_query to check a wtor in the following playbook:

  - name: check wtor
    zos_operator_action_query:
      message_id: GEO045A

At the failure time, the outstanding messages in the sysplex are as below.

3414 R K31      *3414 GEO045A Op-assist OK/NOK: ENSURE ALL     
                WORKLOADS ARE DOWN                             
3026 R TP3      *3026 DSI802A SRVS9    REPLY WITH VALID NCCF   
                SYSTEM OPERATOR COMMAND                        
3177 R ST8      *3177 DSI802A SRVS8    REPLY WITH VALID NCCF   
                SYSTEM OPERATOR COMMAND                        
4847 R ST7      *4847 DSI802A SRVS7    REPLY WITH VALID NCCF   
                SYSTEM OPERATOR COMMAND                        
3193 R ST6      *3193 DSI802A SRVS6    REPLY WITH VALID NCCF   
                SYSTEM OPERATOR COMMAND                        
5252 R ST5      *5252 DSI802A SRVS5    REPLY WITH VALID NCCF   
                SYSTEM OPERATOR COMMAND                        
3800 R ST4      *3800 DSI802A SRVS4    REPLY WITH VALID NCCF   
                SYSTEM OPERATOR COMMAND                        
5770 R ST3      *5770 DSI802A SRVS3    REPLY WITH VALID NCCF   
                SYSTEM OPERATOR COMMAND                        
3814 R ST2      *3814 DSI802A SRVS2    REPLY WITH VALID NCCF        
                SYSTEM OPERATOR COMMAND                             
4997 R ST1      *4997 DSI802A SRVS1    REPLY WITH VALID NCCF        
                SYSTEM OPERATOR COMMAND                             
3424 R K32      *3424 CHKLEVEL2: TESTCASE ACTIVE, REPLY TO THIS     
                WTOR TO CANCEL (V03)                                
3423 R K32      *3423 DSI802A SRV32    REPLY WITH VALID NCCF        
                SYSTEM OPERATOR COMMAND                             
3408 R K31      *3408 CHKLEVEL2: TESTCASE ACTIVE, REPLY TO THIS     
                WTOR TO CANCEL (V03)                                
3407 R K31      *3407 DSI802A SRV31    REPLY WITH VALID NCCF        
                SYSTEM OPERATOR COMMAND                             
3392 R ST3      *3392 CHKLEVEL2: TESTCASE ACTIVE, REPLY TO THIS     
                WTOR TO CANCEL (V03)                                
3158 R ST1      *3158  0-     i0    -      a&}  & } q1}  Q&-        
                &   &  y   {P  { {k  CoF {&  H   4&  }              
                 $    $       -                                     
2982 R ST7      *2982 DFS996I *IMS READY*  IMS7                     
2949 R ST5      *2949 DFS996I *IMS READY*  IMS5                     
2935 R ST8      *2935 DFS996I *IMS READY*  IMS8                     
2966 R ST6      *2966 DFS996I *IMS READY*  IMS6                     
2997 R ST2      *2997 DFS996I *IMS READY*  IMS2                    
3043 R ST1      *3043 DFS996I *IMS READY*  IMS1                    
3040 R ST1      *3040 CHKLEVEL2: TESTCASE ACTIVE, REPLY TO THIS    
                WTOR TO CANCEL (V03)                               
2960 R ST6      *2960 CHKLEVEL2: TESTCASE ACTIVE, REPLY TO THIS    
                WTOR TO CANCEL (V03)                               
2992 R ST2      *2992 CHKLEVEL2: TESTCASE ACTIVE, REPLY TO THIS    
                WTOR TO CANCEL (V03)                               
2929 R ST8      *2929 CHKLEVEL2: TESTCASE ACTIVE, REPLY TO THIS    
                WTOR TO CANCEL (V03)                               
2944 R ST5      *2944 CHKLEVEL2: TESTCASE ACTIVE, REPLY TO THIS    
                WTOR TO CANCEL (V03)                               
3008 R ST4      *3008 CHKLEVEL2: TESTCASE ACTIVE, REPLY TO THIS    
                WTOR TO CANCEL (V03)                               
3024 R TP3      *3024 CHKLEVEL2: TESTCASE ACTIVE, REPLY TO THIS    
                WTOR TO CANCEL (V03)                               
2977 R ST7      *2977 CHKLEVEL2: TESTCASE ACTIVE, REPLY TO THIS    
                WTOR TO CANCEL (V03)                               

The playbook can be run successfully when there are no following messages which should be the root cause. The special characters caused the error and it block the whole playbook running and caused the automation job break.
Is there a way to handle the message containing the special charaters without breaking the task running?

3158 R ST1      *3158  0-     i0    -      a&}  & } q1}  Q&-        
                &   &  y   {P  { {k  CoF {&  H   4&  }              
                 $    $    

Playbook verbosity output.

{
  "changed": false,
  "msg": "An unexpected error occurred: UnicodeDecodeError('utf-8', b'ST1        2023142  01:34:54.00             ISF031I CONSOLE ANSI0000 ACTIVATED\\nST1        2023142  01:34:54.00            -D R,A,S \\nST1        2023142  01:34:54.00             IEE112I 01.34.54 PENDING REQUESTS 929\\n                                           RM=31   IM=0     CEM=0     EM=0     RU=0    IR=0    AMRF\\n                                           ID:R/K     T SYSNAME  JOB ID   MESSAGE TEXT\\n                                                 3414 R K31      STC03501 *3414 GEO045A Op-assist OK/NOK: ENSURE\\n                                                                          ALL WORKLOADS ARE DOWN\\n                                                 3026 R TP3               *3026 DSI802A SRVS9    REPLY WITH VALID\\n                                                                           NCCF SYSTEM OPERATOR COMMAND\\n                                                 3177 R ST8               *3177 DSI802A SRVS8    REPLY WITH VALID\\n                                                                           NCCF SYSTEM OPERATOR COMMAND\\n                                                 4847 R ST7               *4847 DSI802A SRVS7    REPLY WITH VALID\\n                                                                           NCCF SYSTEM OPERATOR COMMAND\\n                                                 3193 R ST6               *3193 DSI802A SRVS6    REPLY WITH VALID\\n                                                                           NCCF SYSTEM OPERATOR COMMAND\\n                                                 5252 R ST5               *5252 DSI802A SRVS5    REPLY WITH VALID\\n                                                                           NCCF SYSTEM OPERATOR COMMAND\\n                                                 3800 R ST4      STC57876 *3800 DSI802A SRVS4    REPLY WITH VALID\\n                                                                           NCCF SYSTEM OPERATOR COMMAND\\n                                                 5770 R ST3               *5770 DSI802A SRVS3    REPLY WITH VALID\\n                                                                           NCCF SYSTEM OPERATOR COMMAND\\n                                                 3814 R ST2               *3814 DSI802A SRVS2    REPLY WITH VALID\\n                                                                           NCCF SYSTEM OPERATOR COMMAND\\n                                                 4997 R ST1               *4997 DSI802A SRVS1    REPLY WITH VALID\\n                                                                           NCCF SYSTEM OPERATOR COMMAND\\n                                                 3424 R K32      STC18246 *3424 CHKLEVEL2: TESTCASE ACTIVE, REPLY\\n                                                                           TO THIS WTOR TO CANCEL (V03)\\n                                                 3423 R K32               *3423 DSI802A SRV32    REPLY WITH VALID\\n                                                                           NCCF SYSTEM OPERATOR COMMAND\\n                                                 3408 R K31      STC03412 *3408 CHKLEVEL2: TESTCASE ACTIVE, REPLY\\n                                                                           TO THIS WTOR TO CANCEL (V03)\\n                                                 3407 R K31               *3407 DSI802A SRV31    REPLY WITH VALID\\n                                                                           NCCF SYSTEM OPERATOR COMMAND\\n                                                 3392 R ST3      STC33784 *3392 CHKLEVEL2: TESTCASE ACTIVE, REPLY\\n                                                                           TO THIS WTOR TO CANCEL (V03)\\n                                                 3158 R ST1               *3158 \\xe50-\\x94  \\x02 i0 \\x97\\xd7\\xd9-\\x90\\x8f\\x11\\x8e\\xcc\\x18a&}\\xd8\\x9c&\\xd8}\\x97q1}\\n                                                                          \\x10\\x18Q&-\\xd8\\xa9\\x87\\x93&\\x90\\xd8\\xbd&\\x90\\xd8y\\xa0\\x10\\xd8{P\\x13\\xd8{\\xd8{k\\x01\\xd8CoF\\xd8{&\\xd8\\xd8H\\n                                                                          \\xa0\\xf8\\xc24&\\xf8\\xd8}\\x87 \\xec\\xf8 \\x10\\xec\\xb0\\xcb\\x9c\\xec\\\\\\xb0\\xac\\xa5\\x18\\\\ \\x18\\xf5\\x12\\xf6\\xe5\\xf8-\\xb4\\xa0\\x10\\xc0\\xb5\\x87\\n                                                                           \\n                                                 2982 R ST7      IMS7PL3  *2982 DFS996I *IMS READY*  IMS7\\n                                                 2949 R ST5      STC95265 *2949 DFS996I *IMS READY*  IMS5\\n                                                 2935 R ST8      IMS8PL3  *2935 DFS996I *IMS READY*  IMS8\\n                                                 2966 R ST6      IMS6PL3  *2966 DFS996I *IMS READY*  IMS6\\n                                                 3013 R ST4      STC95255 *3013 DFS996I *IMS READY*  IMS4\\n                                                 2997 R ST2      STC95225 *2997 DFS996I *IMS READY*  IMS2\\n                                                 3043 R ST1      STC95218 *3043 DFS996I *IMS READY*  IMS1\\n                                                 3040 R ST1      STC90525 *3040 CHKLEVEL2: TESTCASE ACTIVE, REPLY\\n                                                                           TO THIS WTOR TO CANCEL (V03)\\n                                                 2960 R ST6      CHKLEVL  *2960 CHKLEVEL2: TESTCASE ACTIVE, REPLY\\n                                                                           TO THIS WTOR TO CANCEL (V03)\\n                                                 2992 R ST2      STC87177 *2992 CHKLEVEL2: TESTCASE ACTIVE, REPLY\\n                                                                           TO THIS WTOR TO CANCEL (V03)\\n                                                 2929 R ST8      CHKLEVL  *2929 CHKLEVEL2: TESTCASE ACTIVE, REPLY\\n                                                                           TO THIS WTOR TO CANCEL (V03)\\n                                                 2944 R ST5      STC85276 *2944 CHKLEVEL2: TESTCASE ACTIVE, REPLY\\n                                                                           TO THIS WTOR TO CANCEL (V03)\\n                                                 3008 R ST4      STC87793 *3008 CHKLEVEL2: TESTCASE ACTIVE, REPLY\\n                                                                           TO THIS WTOR TO CANCEL (V03)\\n                                                 3024 R TP3      STC88164 *3024 CHKLEVEL2: TESTCASE ACTIVE, REPLY\\n                                                                           TO THIS WTOR TO CANCEL (V03)\\n                                                 2977 R ST7      CHKLEVL  *2977 CHKLEVEL2: TESTCASE ACTIVE, REPLY\\n                                                                           TO THIS WTOR TO CANCEL (V03)\\n', 3743, 3744, 'invalid continuation byte')",
  "invocation": {
    "module_args": {
      "message_id": "GEO045A",
      "system": null,
      "job_name": null,
      "message_filter": null
    }
  },
  "_ansible_no_log": false
}

Ansible configuration.

No response

Contents of the inventory

No response

Contents of group_vars or host_vars

No response

[ddimatos]

@cdlwhui - do you happen to have a full traceback (-vvvv) log, I wanted to see where in the stack it occurred because we have come across this (not for this module) in ansible-core later versions and are looking into it. A full traceback would really help pinpoint which part of the stack to focus on.

I suppose there is more to this block we can't see, eg a x01 (Start of Header) because the below seems to have been mapped to a UTF-8 code point.

*3158  0-     i0    -      a&}  & } q1}  Q&-        
                &   &  y   {P  { {k  CoF {&  H   4&  }              
                 $    $       -   

Although not a solution and you probably know this, but you could add ignore_errors: true to avoid the playbook failure in this case.

[cdlwhui]

I do not have full traceback log currently but I can collect it when we hit the issue next time. I think I can also try creating an outstanding message with the same special content above to recreate the problem.
I will provide the log if I can get.

Yes, ignore_errors: true would avoid the playbook failure, but in our playbook the next step will reply the queried outstanding message. So if the query have no normal response, the next step will have to be pending or notify people for manual reply. So we want to see if it could ignore the message containing with special characters and return the other normal message match the query.

[ddimatos]

I could also inject the noted block (below) but those seem to be mapped to a utf-8 code set, its what i can't see that is likely what is causing the issue, for example, you can't see x01.

Any byte stream which cannot be assigned to a UTF-8 text encoding will break the reading of it, this is why I think there is more not visible.

I have an idea where it is happening, we can work from that for now, but if you do get a log that would be super helpful.

*3158  0-     i0    -      a&}  & } q1}  Q&-        
                &   &  y   {P  { {k  CoF {&  H   4&  }              
                 $    $       -   

My assumption without a recreate or backtrace is that this occurred when the response came back and was read by python which encountered a byte that can not be assigned to UTF-8. Thus adding a 'waiting on dependency' tag.

[ddimatos]

@cdlwhui - the output you shared above, it did not obviously come back from Ansible since it broke, how did you get that output? Is that from a x3270? Next time it happens in addition to a traceback could you also run these commands from x3270 d r,a,s and d r,a,jn?

[AnthonyGiorgio]

I'm curious as to how you retrieved the sysplex messages. Did you issue an operator command somehow and copy and paste the output? Was it from SDSF, ZOAU opercmd, or from the console directly? It appears that a corrupted message is on the queue somehow, awaiting a response.

[cdlwhui]

Yes, I had a test to generate the message but it did not hit the issue, query using zos_operator_action_query successed.
The message caused the issue was from one of the old workloads in our enviroment. Alought the visible content between it and the message I generated are the same, the difference is the message I generated can be replied and clear, the message caused the issue can not be replied until the system is shutted down and restarted.

I got the message using 'd r,r' command. I can run the commands d r,a,s and d r,a,jn to get the output when hit next time.

[cdlwhui]

I'm curious as to how you retrieved the sysplex messages. Did you issue an operator command somehow and copy and paste the output? Was it from SDSF, ZOAU opercmd, or from the console directly? It appears that a corrupted message is on the queue somehow, awaiting a response.

I issued operator command 'd r,r' from the console and copied the output. The corrupted message is on the queue but there is nothing happened when just replying it. It disappeared until the LPAR is shutted down and restarted.

[AnthonyGiorgio]

Thank you, that's good to know. It means that ZOAU isn't corrupting anything, but instead is just processing whatever is on the message queue.

I think there is a bigger question as to what can be done with "unprintable" characters here. ZOAU opercmd just prints them to the terminal as-is, other than converting NULL (0x0) bytes to EBCDIC spaces (0x40). I think an argument could be made to handle this better from Python, which doesn't like characters that can't be converted into a string.

[ddimatos]

The teams will be working on resolving this; whenever on z/OS we always have to take into account any byte stream which cannot be assigned to a UTF-8 text encoding will break the contract imposed on us by python which text must be UTF-8 assignable.

Thank you @cdlwhui , and if you encounter this again, the requested information could be of help to us while the teams try to resolve this. We understand the importance of this.

[cdlwhui]

The teams will be working on resolving this; whenever on z/OS we always have to take into account any byte stream which cannot be assigned to a UTF-8 text encoding will break the contract imposed on us by python which text must be UTF-8 assignable.

Thank you @cdlwhui , and if you encounter this again, the requested information could be of help to us while the teams try to resolve this. We understand the importance of this.

You are welcome.
Sure, I will remember to collect the requested info when hitting this again.

[ddimatos]

See the following issues below, they are all related to non-printable UTF-8 chars, essentially chararcetors that don't don't correspond to a UTF-8 value. This is being addressed as noted in ZOAU 1.3 and IBM z/OS Core collection will adopt ZOAU 1.3 in Q1 2024. There is a recreate involving a job submission you can see here. This work is also being tracked in JIRA 9687.

• [Bug] [zos_job_submit] 'utf-8' codec can't decode byte 0xdd error on zos_job_submit module #677
• [Bug] zos_operator_action_query reported UnicodeDecodeError when the outstanding messages contain special characters #776
• [Bug] [zos_job_submit] 'utf-8' codec can't decode byte 0xbb in position 0: invalid start byte" #972

[ddimatos]

@cdlwhui - This work has been scheduled to be tested in iteration 4 (Feb 26th) approximately, reading over the history I don't see that we were able to recreate this, if we knew the unprintable character, we could simulate the response.

When it comes time to evaluate this issue in iteration 4 we have 2 choices, recreate by understanding the unprintable char or if you could take an early development build and evaluate it yourself.

Otherwise, we will have to close this issue and assume since this overlaps with other code we were able to resolve it.

[cdlwhui]

Thank you for the update @ddimatos .
Yes, we have not hit this issue again by now. We can take the build and evaluate ourselves but can not guarantee the evaluation complete in iteration 4 as it need to hit the issue.

If you could not recreate, I think it should be ok to close this and we will keep monitoring in our environment with the fix.

[ddimatos]

@cdlwhui - all I can think of is putting a WTO on the console using some C then reading them, such a test case would probably have to go into our backlog for the time being.

[AnthonyGiorgio]

The ZOAU command opercmd "d ssi" sometimes includes unprintable characters in the output. I don't know how consistent that behavior is, but I see at least on my test system.

[rexemin]

Was unable to test this on our systems. Display commands didn't return unprintable characters and seems like WTO messages automatically filter any that we may introduce ourselves:

When a program issues a WTO macro, the system translates the text; only standard printable EBCDIC characters are passed to MCS-managed display devices. The EBCDIC characters that can be displayed are listed in z/OS MVS Programming: Assembler Services Guide. All other characters are replaced by blanks.

From the WTO docs under the Parameters section.

For now I would ask you @cdlwhui if you could take an early build of v1.10.0-beta.1 and test on your end, if you have the opportunity.

[AnthonyGiorgio]

I've managed to get unprintable characters to display to the console, but that's usually because the offending code has a bug and is displaying raw memory or something. I think there is some filtering going on, but it's not at all layers of the stack. ZOAU has recently started filtering opercmd output to remove unprintable characters. There are also some recent APARs that filter all characters coming across the Python interface.

[cdlwhui]

Was unable to test this on our systems. Display commands didn't return unprintable characters and seems like WTO messages automatically filter any that we may introduce ourselves:

When a program issues a WTO macro, the system translates the text; only standard printable EBCDIC characters are passed to MCS-managed display devices. The EBCDIC characters that can be displayed are listed in z/OS MVS Programming: Assembler Services Guide. All other characters are replaced by blanks.

From the WTO docs under the Parameters section.

For now I would ask you @cdlwhui if you could take an early build of v1.10.0-beta.1 and test on your end, if you have the opportunity.

@rexemin We can take an early build v1.10.0-beta.1 and test on our environment. We have not hit the WTO message for months but it was just the time it occurred again last week. We suspected it might be caused by a RRS test case but has not determined which one. We opened a case to ask for help to identify the cause. If we can recreate it, we will be able to test soon, otherwise, we may need to keep monitoring and test when it occurred again.

For now, I would ask how to get the early build v1.10.0-beta.1? And does it require a specific ZOAU version?

[ddimatos]

@cdlwhui - our dev always has the next release, in this case 1.10.0-beta.1, it still has about 3 weeks of development left for the quarter but is stable, for this offfering, dev is always stable.

You can install directly from our repo with either of these commands:

ansible-galaxy collection install git+https://github.com/ansible-collections/ibm_zos_core.git,dev
ansible-galaxy collection install [email protected]:ansible-collections/ibm_zos_core.git,dev

This version will minimally require zoau 1.3.0.
I hope this helps.

[cdlwhui]

Thank you @ddimatos. Is it able to install this dev version through collections/requirements.yml in ansible AWX?

[ddimatos]

@cdlwhui - while I have not tried to install a development branch using collections/requirements.yml this is possible, I think you would need to clone our repo and adjust the collections/requirements.yml file to something like:

collections:
  - name: https://github.com/cdlwhui/ansible-collections/ibm_zos_core.git
    type: git
    version: dev

Steps:

1. git clone [email protected]:ansible-collections/ibm_zos_core.git
2. git checkout dev
3. <edit file the file collections/requirments.yml to what is shared above>
4. git add .
5. git commit -m "update collections file to point to dev"
6. git push

I believe the current behavior of collections/requirements.yml is to install the latest release, the dev branch is not released or tagged yet so I don't think you can do that with out current collections/requirements.yml.

[fernandofloresg]

This issue has been without update from the user for more than 3 months and still waiting on response, hence I'm closing it due to inactivity.