Creating the simplest AMS on z/OS configuration.

I was recently asked, what is the simplest configuration of certificates on z/OS to get MQ AMS working. This took me a little while to get working, so I thought it was worth documenting. To understand how to configure AMS you need to have a superficial view of what happens under the covers.

As part of writing this up I wrote

What can go wrong with AMS? How long have you got?. This gives some of the unhelpful messages, and what the cause might be.
Using System SSL trace to debug AMS problems. The GSK trace is a life saver.

The short answer

You can have all userid use the same certificate. People in one department could all use the same certificate, which make implementing AMS much easier. You only need one recipient certificate for the team, and not have to manage people joining and leaving the team – which causes a head ache on the systems that send your system messages.

For each user

1 Create a keyring for each user
2 Create the CA certificate
3 Create a signed user certificate with RSA, and keyusage to include DATAENCRYPT.
4 , 5 Connect this certificate to all users. Make it the default certificate
4 , 5 Connect this certificate to all users Connect the CA for this certificate to each user’s keyring.
6 Give each userid UPDATE access to their keyring.

For the queue manager

1 Create a keyring for the AMS started task userid.
2 Connect to the keyring, the certificates of all recipients on this queue manager
3 Connect to the keyring, all CA certificates for userids on the system, and the CAs for user on other platforms.

Refresh the AMS system. f xxxxamsm,refresh.

Simple, what could go wrong?

The longer answer – with explanations

With AMS, you can have

Message integrity. The message is visible in clear text, but you can be confident it has not changed since it was created
Message privacy. The message is encrypted. The message can only be read by people who have access to the private key of one of the specified recipients
Privacy and integrity.

Background

Public and private keys

With modern ciphers, you need a pair of keys. If you encrypt with one key you need its partner to decrypt. You pick one key, and make it available to every one, and this is called the public key. You keep the other one very secure, this is called the private key.

If you encipher something with the public key – then only someone with the private key can decrypt it
If I encrypt something with my private key. Anyone can decrypt it using my public key (you may ask why bother?), but the important bit is that because you had to use my public key – you know the message came from me! We have authentication.

A certificate has a public key in it.

Quick discussion on certificate authorities

You can have self signed certificates. You should not use them, because someone could change or replace it and you would never know.

You can have signed certificates. When you create a signed certificate it creates a checksum of the certificate, and encrypt this checksum with the Certificate Authority’s private key. This encrypted checksum becomes part of the certificate.

When you receive a signed certificate you do the same checksum (and store it temporarily) then you decrypt the encrypted checksum using the CA’s public key – and the two values should match. (This assumes you have the CA certificate.)

Your Certificate Authority certificate could have been created by someone else (The UK Certificate Authority ?), and goes through the same signing process.

The UK’s Certificate Authority certificate could have been signed by someone else… so we have a chain of Certificate Authorities.

The top level in the chain of CAs is self signed.

The players

There is the putter, the getter, and the queue manager. They each need their own key ring.

Message integrity

The message is visible in clear text, but you can be confident it has not changed since it was created.

Put the message

As part of the integrity function, it calculates a checksum of the contents of the message, and encrypts this with the user’s private key. What gets sent is

The original payload
The encrypted checksum
The putter’s certificate
The putter’s CA certificate.

The putter sets up a certificate called UserCert, signed by MyCA. This certificate has certain requirements – such as it must allow data encryption, and contain an RSA public key.

The putter’s keyring needs

the UserCert

This needs to be the default certificate.

If the certificate belongs to the putter’s userid, then it needs read access to the keyring

PERMIT  putter.drq.ams.keyring.LST class(RDATALIB) - 
        ACCESS(READ) ID(putter)

If the certificate does not belongs to the putter’s userid, then it needs update access

PERMIT   putter.drq.ams.keyring.LST class(RDATALIB) - 
        ACCESS(UPDATE) ID(putter)

The UPDATE access says it can read the private key of a certificate which the userid does not own, READ access only gives you access to the public key.

For testing – give every userid UPDATE access to the keyring profile.

Get the message

When the message is got, the queue manager checks the certificate (+CA) in the message is valid, using the CA in the queue manager’s keyring. Then does the same logic as for signing a certificate.

Check the certificate in the message is valid (for example compare the CAs)
Use the public key from the certificate in the message to decrypt the checksum of the message
Do the same checksum calculation.
Compare the two answers. They should match if the message has not been tampered with.

The putter needs

the MyCA certificate.

The keyring is the same as for integrity.

The queue manager needs

The queue manager’s keyring needs the CA of the certificate in the message – so it can compare the it with the one in the message.

The queue manager’s userid needs only read access to its keyring. (Because it does not need access to any private keys.)

The getter needs

an empty keyring. (In practice AMS complains if the userid has an empty keyring because it fails to find the default certificate, so give it a certificate and make it the default).

Message privacy

The message is encrypted. The message can only be read by people who have access to the private key of one of the specified recipients.

With message privacy the following happens when the message is put:

An encryption key is generated using parameters from the putters certificate and the AMS configuration
The message is encrypted with this encryption key
From the MQ AMS definitions, there is a list of recipient’s Distinguished Names, such as CN=USER1,O=MEGACORP, and CN=USER2,OU=TEST,O=MEGACORP.
For each DN in the list, look in the queue manager’s keyring for the certificate with the distinguished name.
- With the found certificate, use its public key to encrypt the encryption key
- Build a list of [Distinguished_Name:encrypted encryption key, ….]
Send this list as part of the payload.

When the message is got, the getter

Extracts the getter’s DN from the getter’s default certificate
Scans the AMS data in the message for the list of [Distinguished_Name:encryption key, ….] for the matching DN
Uses the private key in the default certificate to decrypt the [Distinguished_Name:encryption key, ….], to get the message decryption key.
Use the message decryption key to decrypt the user’s message.

AMS setup

I am using a queue called AMS for my AMS testing. The AMS definitions were

setmqspl -m MQPA -p AMS -e AES128 
-r "CN=COLIN,O=AMS,C=TEST" 
-r "CN=START1,O=AMS,C=TEST" 
dspmqspl -m MQPA

Putter keyring

As with integrity, the putter needs access to the private key.

RACDCERT ID(COLIN )  CONNECT(RING(drq.ams.keyring )  - 
                            ID(COLIN )  - 
                            default - 
                            LABEL('AMS') )

To make the configuration easier (this is the simplest configuration, after all), the user certificate owned by ID(COLIN), and called LABEL(‘AMS’) is used by the getter userid below.

Queue manager keyring

The queue manager needs all CA certificates, and all the recipients certificates. When a recipient is specified, the queue manager’s keyring is searched for the certificate with the matching Distinguished Name. When it is found its public key is used. The private key is not used. The queue manager only requires READ access to the keyring, because it is not accessing private keys.

RACDCERT ID(STCMQ )  CONNECT(RING(drq.ams.keyring )  - 
                            ID(COLIN )  - 
                            LABEL('AMS') ) 
RACDCERT ID(STCMQ )  CONNECT(RING(drq.ams.keyring )  - 
                            CERTAUTH    - 
                            LABEL('NEW-CA') ) 
RACDCERT ID(STCMQ )  CONNECT(RING(drq.ams.keyring )  - 
                            ID(START1)  - 
                            LABEL('AMS2') )

The getter’s keyring

RACDCERT ID(IBMUSER) CONNECT(RING(drq.ams.keyring )  - 
                            ID(COLIN )   - 
                            default - 
                            LABEL('AMS') ) 

RACDCERT ID(IBMUSER) CONNECT(RING(drq.ams.keyring )  - 
                            CERTAUTH    - 
                            LABEL('NEW-CA') )

In this, the simplex configuration, the user cert is the one owned, and used by the putter. ID(COLIN) label (‘AMS’).

My definitions

Define the certificates

Define the Certificate Authority

This creates the CA called NEW-CA

//IBMRACF  JOB 1,MSGCLASS=H 
//S1  EXEC PGM=IKJEFT01,REGION=0M 
//SYSPRINT DD SYSOUT=* 
//SYSTSPRT DD SYSOUT=* 
//SYSTSIN DD * 

RACDCERT CERTAUTH   DELETE(LABEL('NEW-CA')) 

RACDCERT GENCERT  - 
  CERTAUTH - 
  SUBJECTSDN(CN('NEW-CA')- 
             O('COLIN') - 
             OU('TEST')) - 
  NOTAFTER(   DATE(2030-07-02  ))- 
  KEYUSAGE(          CERTSIGN                     )  - 
  SIZE(2048) - 
  WITHLABEL('NEW-CA') 

RACDCERT CERTAUTH   ALTER (LABEL('NEW_CA')) TRUST 

SETROPTS RACLIST(DIGTCERT,DIGTRING ) refresh 
/*

Define the user certificate

The definition below creates the certificate for ID(COLIN) with name LABEL(AMS) and Distinguished Name CN(‘COLIN’) O(‘AMS’) C(‘TEST’).

//IBMRING  JOB 1,MSGCLASS=H 
//* https://www.ibm.com/docs/en/ibm-mq/9.4.x?topic= 
//* zos-connecting-certificates-key-rings-ams 
//S1  EXEC PGM=IKJEFT01,REGION=0M 
//SYSPRINT DD SYSOUT=* 
//SYSTSPRT DD SYSOUT=* 
//SYSTSIN DD * 
RACDCERT DELETE ( LABEL('AMS')) ID(COLIN) 
RACDCERT ID(COLIN ) GENCERT  - 
   SUBJECTSDN(CN('COLIN') O('AMS') C('TEST'))  - 
   WITHLABEL('AMS') SIGNWITH(CERTAUTH LABEL('NEW-CA')) - 
   NOTAFTER(   DATE(2027-08-05) TIME(16:22:00) )  - 
   KEYUSAGE(HANDSHAKE DATAENCRYPT DOCSIGN) 
RACDCERT ID(COLIN ) ALTER (LABEL('AMS')) TRUST 
SETROPTS RACLIST( DIGTCERT)         refresh 
/*

My definitions

I used JCL to (re-)define my keyrings etc. This makes it easier to make one change, and repeat. It also means I can copy them to a different system and they still work.

JCL

//IBMDEFK1 JOB 1,MSGCLASS=H
//* https://www.ibm.com/docs/en/ibm-mq/9.4.x?topic=
//* zos-connecting-certificates-key-rings-ams
//S1 EXEC PGM=IKJEFT01,REGION=0M
//SYSPRINT DD SYSOUT=*
//SYSTSPRT DD SYSOUT=*
//SYSTSIN DD *

List the certificates I use


RACDCERT LIST (LABEL('AMS')) ID(COLIN)
RACDCERT LIST (LABEL('AMS2')) ID(START1)
RACDCERT LIST (LABEL('NEW-CA')) CERTAUTH
RACDCERT LIST (LABEL('NEW-CA2')) CERTAUTH

Delete and define the keyrings.

RACDCERT ID(COLIN) DELRING(drq.ams.keyring)
RACDCERT ID(IBMUSER) DELRING(drq.ams.keyring)
RACDCERT ID(STCMQ) DELRING(drq.ams.keyring)

RACDCERT ID(COLIN) ADDRING(drq.ams.keyring)
RACDCERT ID(IBMUSER) ADDRING(drq.ams.keyring)
RACDCERT ID(STCMQ) ADDRING(drq.ams.keyring)

Connect the certificates for userid COLIN

RACDCERT ID(COLIN )  CONNECT(RING(drq.ams.keyring )  - 
                            ID(COLIN )  - 
                            default - 
                            LABEL('AMS') ) 
RACDCERT ID(COLIN )  CONNECT(RING(drq.ams.keyring )  - 
                            CERTAUTH    - 
                            LABEL('NEW-CA') )

Connect the certificates for userid IBMUSER

RACDCERT ID(IBMUSER) CONNECT(RING(drq.ams.keyring )  - 
                            ID(START1)   - 
                            default - 
                            LABEL('AMS') ) 
RACDCERT ID(IBMUSER) CONNECT(RING(drq.ams.keyring )  - 
                            CERTAUTH    - 
                            LABEL('NEW-CA') )

Connect the certificates for the queue manager.

This has

All the certificates for users specified in encrypted messages with the -r…. definitons
All the certificate authorities used by any certificates

RACDCERT ID(STCMQ )  CONNECT(RING(drq.ams.keyring )  - 
                            ID(COLIN )  - 
                            default - 
                            LABEL('AMS') ) 
RACDCERT ID(STCMQ )  CONNECT(RING(drq.ams.keyring )  - 
                            ID(COLIN )  - 
                            default - 
                            LABEL('AMS2') ) 

RACDCERT ID(STCMQ )  CONNECT(RING(drq.ams.keyring )  - 
                            CERTAUTH    - 
                            LABEL('NEW-CA') ) 
RACDCERT ID(STCMQ )  CONNECT(RING(drq.ams.keyring )  - 
                            CERTAUTH    - 
                            LABEL('NEW-CA2') )

Make these changes visible

SETROPTS RACLIST(DIGTCERT,DIGTRING ) refresh

Give the userids access to the keyrings, and make the changes visible

PERMIT  COLIN.drq.ams.keyring.LST class(RDATALIB)   - 
        ACCESS(UPDATE) ID(COLIN) 
PERMIT   IBMUSER.drq.ams.keyring.LST class(RDATALIB) - 
        ACCESS(UPDATE) ID(IBMUSER) 
PERMIT   STCMQ.drq.ams.keyring.LST class(RDATALIB) - 
        ACCESS(READ) ID(STCMQ  ) 
                                                              
SETROPTS RACLIST(RDATALIB)         refresh

and display the keyrings

RACDCERT LISTRING (     drq.ams.keyring )  id(COLIN) 
RACDCERT LISTRING (     drq.ams.keyring )  id(STCMQ) 
RACDCERT LISTRING (     drq.ams.keyring )  id(IBMUSER)

/*
//

Using System SSL trace to debug AMS problems.

When using MQ AMS to encrypt MQ messages, it has been very frustrating to get messages like

CSQ0217E %MQPA CSQ0COPN Failed to process object ‘recipient public key certificate in recipient keyring’

and not know what the problem is. (Especially when the cause is recipient public key certificate is not in recipient keyring.

System SSL which provides all of the encryption has a trace capability. You enable it when you start AMS, so you have the overhead in normal operation.

It sometimes writes data to a file in Unix, other times you need to start GKSRVR and collect the CTRACE.

With AMS the trace data is written to a file in Unix. Use the unix gsktrace command to format it.

gsktrace gskssl.16777257.trc > gsk

Configuring the trace

In the AMS JCL procedure //ENVARS DD DSN=….,DISP=SHR

I have

####################################################################### 
# 
#  GSKIT Trace 
# 
#  If you are having problems with certificates and missing entries in 
#  key stores you can enable GSKIT trace to help diagnose the problems. 
# 
#  To enable/disable GSKIT trace, un-comment and update the following 
#  environment variables as required. 
# 
#  GSK_TRACE_FILE - Specifies the name of the trace file in Unix 
#                   System Services (USS). Insert the correct user 
#                   name and ensure you set the correct permissions 
#                   on the directories and files to allow the 
#                   user ID in use by IBM MQ for z/OS Advanced 
#                   Message Security to write the resulting trace 
#                   file. The current process identifier is included 
#                   as part of the trace file name when the name 
#                   contains a percent sign (%). The gsktrace command 
#                   can be entered in USS to format the trace: 
# 
#                   e.g. gsktrace gskssl.84017302.tr 
# 
#  GSK_TRACE      - Specifies a bit mask that enables System SSL trace 
#                   options to trace gsk_* calls. All trace options are 
#                   enabled if the bit mask is 0xff and all trace 
#                   options are disabled if the bit mask is 0x00. 
                                                                              
GSK_TRACE_FILE=/tmp/gskssl.%.trc 
#SK_TRACE=0xff     everything    including payloads 
GSK_TRACE=0x0f     just control stuff

If you specify GSK_TRACE=0xff you get a lot of data – including all the application data ( message content + any headers etc).

I found GSK_TRACE=0x0f provides what I need.

A first look at the data

There is data like

08/06/2026-07:00:49 Thd-0 ENTRY gsk_open_keyring(): ---> Keyring 'STCMQ/drq.ams.keyring' 
08/06/2026-07:00:49 Thd-0 ENTRY crypto_generate_random_bytes(): ---> Length 20 
08/06/2026-07:00:49 Thd-0 EXIT crypto_generate_random_bytes(): <--- Exit status 0x00000000 (0) 
08/06/2026-07:00:49 Thd-0 INFO gsk_open_keyring(): Record 'AMS' is the default key 
08/06/2026-07:00:49 Thd-0 INFO gsk_open_keyring(): Identifier 1 assigned to 'AMS' 
08/06/2026-07:00:49 Thd-0 ENTRY gsk_decode_certificate(): ---> 
08/06/2026-07:00:49 Thd-0 EXIT gsk_decode_certificate(): <--- Exit status 0x00000000 (0) 
08/06/2026-07:00:49 Thd-0 INFO gsk_open_keyring(): Identifier 2 assigned to 'NEW-CA' 
08/06/2026-07:00:49 Thd-0 ENTRY gsk_decode_certificate(): ---> 
08/06/2026-07:00:49 Thd-0 EXIT gsk_decode_certificate(): <--- Exit status 0x00000000 (0) 
08/06/2026-07:00:49 Thd-0 INFO gsk_open_keyring(): Identifier 3 assigned to 'DOCZOSCA' 
08/06/2026-07:00:49 Thd-0 ENTRY gsk_decode_certificate(): ---> 
08/06/2026-07:00:49 Thd-0 EXIT gsk_decode_certificate(): <--- Exit status 0x00000000 (0) 
08/06/2026-07:00:49 Thd-0 INFO gsk_open_keyring(): Identifier 4 assigned to 'AMS2' 
08/06/2026-07:00:49 Thd-0 ENTRY gsk_decode_certificate(): ---> 
08/06/2026-07:00:49 Thd-0 EXIT gsk_decode_certificate(): <--- Exit status 0x00000000 (0) 
08/06/2026-07:00:49 Thd-0 ENTRY gsk_decode_certificate_extension(): ---> Decoding
08/06/2026-07:00:49 Thd-0 EXIT gsk_decode_certificate_extension(): <--- Exit status 
08/06/2026-07:00:49 Thd-0 ENTRY gsk_decode_certificate_extension(): ---> Decoding
08/06/2026-07:00:49 Thd-0 EXIT gsk_decode_certificate_extension(): <--- Exit status 
08/06/2026-07:00:49 Thd-0 INFO gsk_build_issuer_chains(): Record 'NEW-CA' is issuer for ...
08/06/2026-07:00:49 Thd-0 INFO gsk_build_issuer_chains(): Record 'NEW-CA' is self-signed 
08/06/2026-07:00:49 Thd-0 INFO gsk_build_issuer_chains(): Record 'DOCZOSCA' is self-signed 
08/06/2026-07:00:49 Thd-0 ENTRY gsk_decode_certificate_extension(): ---> Decoding ...
08/06/2026-07:00:49 Thd-0 EXIT gsk_decode_certificate_extension(): <--- Exit status ... 
08/06/2026-07:00:49 Thd-0 INFO gsk_build_issuer_chains(): No issuer found for record 'AMS2' 
08/06/2026-07:00:49 Thd-0 EXIT gsk_open_keyring(): <--- Exit status 0x00000000 (0) Handle...

I ignore the date
I use the time to match the records to when the problem occurred. It is HH:MM:SS granularity
Thd-0, Thd-15. Work runs on AMS tasks. A task can run work for any userid. I’ve often found one thread does the processing for the putters and the getters. You have to guess when one piece of work ends, and the next starts.
ENTRY/EXIT/INFO this is the entry, exit, or just some information about the function
gsk_open_keyring() is the function. This is described in Cryptographic Services System Secure Sockets Layer Programming (SC14-7495-60) which I think is only available in PDF format.

The trace shows records between

ENTRY gsk_open_keyring(): —> Keyring ‘STCMQ/drq.ams.keyring’
EXIT gsk_open_keyring(): <— Exit status 0x00000000

Showing the function gsk_open_keyring(): worked successfully.

It shows the elements on the keyring

INFO gsk_open_keyring(): Record 'AMS' is the default key
INFO gsk_open_keyring(): Identifier 1 assigned to 'AMS'
INFO gsk_open_keyring(): Identifier 2 assigned to 'NEW-CA'
INFO gsk_open_keyring(): Identifier 3 assigned to 'DOCZOSCA'
INFO gsk_open_keyring(): Identifier 4 assigned to 'AMS2'

How do you find the problem?

You might have the time of day when the problem occurred. The trace is only HH:MM:SS, so there may be a lot of records.

I use ISPF edit.

X ALL
Find ‘Exit status’ all
exclude ‘Exit status 0x00000000’ all

This shows just the Exit status which are non zero. This should localise the problem.

Periodically it uses a new file – so check you are using the latest file.

Some records showing a problem

 ENTRY gsk_validate_certificate(): ---> Data source count=1 
 ENTRY gsk_validate_certificate_mode(): ---> Data source count=1,...
 ENTRY cms_validate_certificate_mode_int(): ---> Data source count=1,...
 INFO cms_validate_certificate_mode_int(): validate root=566,...
 ENTRY gsk_name_to_dn(): ---> 
 EXIT gsk_name_to_dn(): <--- Exit status 0x00000000 (0) DN: CN=START1,O=AMS,C=TEST 
 INFO cms_validate_certificate_mode_int(): Validating CN=START1,O=AMS,C=TEST 
 INFO cms_validate_certificate_mode_int(): No Signature Algorithm List Provided 
 ENTRY gsk_decode_certificate_extension(): ---> Decoding certificate extension type 2 
 EXIT gsk_decode_certificate_extension(): <--- Exit status 0x00000000 (0) 
 INFO get_issuer_certificate(): Using AuthorityKeyIdentifier to locate issuer 
 ENTRY gsk_name_to_dn(): ---> 
 EXIT gsk_name_to_dn(): <--- Exit status 0x00000000 (0) DN: CN=NEW-CA2,OU=TEST,O=COLIN 
 INFO get_issuer_certificate(): Using issuer CN=NEW-CA2,OU=TEST,O=COLIN 
 ENTRY gsk_get_record_by_subject_mode(): ---> Handle 275787C0 
 EXIT gsk_get_record_by_subject_mode(): <--- Exit status 0x0335300e (53817358) 
 ERROR validate_certificate(): Unable to get issuer certificate: Error 0x03353024 
 ERROR validate_certificate_mode(): Unable to validate certificate: Error 0x03353024

This shows data is being processed from the message.

ENTRY gsk_name_to_dn(): —> shows data was passed in to routine to convert from the transmission (internal) format DN to a readable name
EXIT gsk_name_to_dn(): <— Exit status 0x00000000 (0) DN: CN=START1,O=AMS,C=TEST The output name is CN=START1,O=AMS,C=TEST
INFO get_issuer_certificate(): get the issuer name from the certificate
EXIT gsk_name_to_dn(): <— Exit status 0x00000000 (0) DN: CN=NEW-CA2,OU=TEST,O=COLIN this is the decoded issuer name
INFO get_issuer_certificate(): Using issuer CN=NEW-CA2,OU=TEST,O=COLIN look for the certificate with this DN in the keyring
EXIT gsk_get_record_by_subject_mode(): <— Exit status 0x0335300e It could not find the record in the keyring with the given subject DN.
Looking in the documentation gives 0335300E : Record not found.

What can go wrong when using AMS – how long have you got?

There are many moving parts for AMS, and it is easy to get it wrong. The error messages produced often do not describe the problem.

This is a work in progress. If you have other problems, please let me know. I am expecting people to search with their symptoms, rather than read this document.

One day I’ll produce a list

reason 03353026; Failed to process object ‘pkcs7 enveloped data message.’; see ….

Bad key definition. User’s certificate has the wrong certificate type (such as Elliptic)

CSQ0215E %MQPA CSQ0CPUT Message protection failed, return code 00000008, reason 03353026
CSQ0217E %MQPA CSQ0CPUT Failed to process object ‘pkcs7 enveloped data message.’

From the GSK trace

ERROR gsk_make_enveloped_data_content_extended(): keyUsage does not allow key encipherment
EXIT gsk_make_enveloped_data_content_extended(): <— Exit status 0x03353026 (53817382)

The key does not have Keyusage(dataencryption).

A key defined as NISTECC does not support data encryption. You have to use RSA or ICSF.

User’s certificate expired

During MQPUT

CSQ0215E %MQPA CSQ0CPUT Message protection failed, return code 00000008, reason 03353022
CSQ0217E %MQPA CSQ0CPUT Failed to process object ‘public key certificate’

During MQGET

The certificate in the message has expired, and the certificate in the keyring has expired

CSQ0216E %MQPA CSQ0CGET Message unprotection failed, return code 00000008, reason 03353033
CSQ0217E %MQPA CSQ0CGET Failed to process object ‘pkcs7 confidentiality msg’
CSQ0209E %MQPA CSQ0CMDQ Message for AMS sent to error queue, MQRC=2063 (MQRC_SECURITY_ERROR)

Certificate Authority has expired

User’s certificate is not trusted

CSQ0214E %MQPA CSQ0COPN Message protection initialization failed, return code 12, reason 0335300E
CSQ0217E %MQPA CSQ0COPN Failed to process object ‘DEFAULT key in keyring COLIN/drq.ams.keyring’

Note: After changing a certificate to TRUST I used

RACDCERT ID(COLIN ) ALTER (LABEL('AMS')) NOTRUST 
SETROPTS RACLIST(DIGTCERT,DIGTRING ) refresh 
SETROPTS RACLIST(RDATALIB)         refresh

and

 f mqpaamsm,refresh

QM is missing a CA certificate

CSQ0216E %MQPA CSQ0CGET Message unprotection failed, return code 00000008, reason 03353024
CSQ0217E %MQPA CSQ0CGET Failed to process object ‘signer’s certificate’
CSQ0209E %MQPA CSQ0CMDQ Message for AMSI sent to error queue, MQRC=2063 (MQRC_SECURITY_ERROR)

RACDCERT ID(STCMQ )  CONNECT(RING(drq.ams.keyring )  - 
                            CERTAUTH    - 
                            LABEL('NEW-CA') )

CSQ0215E %MQPA CSQ0CPUT Message protection failed, return code 00000008, reason 03353024
CSQ0217E %MQPA CSQ0CPUT Failed to process object ‘public key certificate’.

During encryption, the CA for a recipient is not in the queue manager’s keyring.

QM is missing a recipient’s certificate

CSQ0214E %MQPA CSQ0COPN Message protection initialization failed, return code 12, reason 0335300E
CSQ0217E %MQPA CSQ0COPN Failed to process object ‘recipient public key certificate in recipient keyring’

Action:

Either add the certificate to the queue manager’s keyring, (and issue the f xxxxamsm,refresh command), or remove the DN from the recipient list.

Getters userid does not have access to the private certificate in the keyring

CSQ0214E %MQPA CSQ0COPN Message protection initialization failed, return code 12, reason 03353033
CSQ0217E %MQPA CSQ0COPN Failed to process object ‘not available’

Check the keyring for the user has a valid entry.

The userid is trying to get a message, but the list of recipients does not include the user’s DN.

Getter does not have a certificate to decypt a message

CSQ0214E %MQPA CSQ0COPN Message protection initialization failed, return code 12, reason 03353033
CSQ0217E %MQPA CSQ0COPN Failed to process object ‘not available’

The user is trying to get a message, but is not in the list of recipients

CSQ0214E %MQPA CSQ0COPN Message protection initialization failed, return code 12, reason 03353033
CSQ0217E %MQPA CSQ0COPN Failed to process object ‘not available’

The getter does not have the CA for its certificate in its keyring (to validate the incoming message)

CSQ0216E %MQPA CSQ0CGET Message unprotection failed, return code 00000008, reason 03353033                              
CSQ0217E %MQPA CSQ0CGET Failed to process object 'pkcs7 confidentiality msg'                               
CSQ0209E %MQPA CSQ0CMDQ Message for AMS sent to error queue, MQRC=2063 (MQRC_SECURITY_ERROR)

Understanding the Prometheus data model

I had been using Prometheus to display Opentelemetry data from MQ on z/OS, but was having problems getting it to display what I wanted. I realised I did not understand how Prometheus stores and uses its data.

Prometheus handles time stamp data very well, “At this time, here are the metrics”. Prometheus provides the capability to display the data in many formats.

I found this course very clear and helpful. I did not read it end to end, but went to the topics of interest.

There is a discussion about metrics from Opentelemetry which you might wish to read after understanding the basics.

There are different sorts of data

Some numbers go up and down

The value of the depth of a queue can go up and down, and you are usually interested in the value at a certain time.

If you have the queue depth at the start of an interval, and at the end of the interval, you cannot take the average of the values. For example if the depth of the queue at midnight is 1000, and at one minute afterwards the queue is emptied, and stays empty till 1 AM, when it gets to depth 1000 – the “average” does not mean anything.

Some numbers just increase

An example of numbers that just increase, is the number of requests processed since the application started. The absolute number is not important, because the longer the application is active, the larger the number. The graph is just a line that goes up. You are more interested in questions like “how many requests happened in the last half hour”. This requires two values at different times.

With the requests, you might have the count of the requests, and also the sum of the duration of the requests. To find the average you calculate the sum/count. This is a true, but unhelpful statement.

If your application has been active for a week, calculating sum/count will give you the overall average. After midnight when there is no transaction activity, the average stays the same, non-zero value. This is a boring metric.

It is more interesting to take a time range, for example 1 minute, and calculate the sum of the durations of records in this hour/count of records in this minute. Then at the end of every minute, display the average value for the preceding minute. Interesting charts include

The number of requests in the last minute
The average response time during the last minute.

The key lesson when using these ever increasing values, is you take two time stamps and do calculations on the differences between the the two times.

Instance data and range data

Prometheus has two “types” of data. Instance value where there is one time stamp involved (what is the value at this time?), and Range values where more than one timestamp is involved, for example the increase of a value between two timestamps.

Some functions need a scalar (instance) value, other functions need a range value of two timestamps.

With some functions, I kept using Instance value data – when I should have been using Range values. So I wrote this blog post to help me understand the data model.

Data has attributes

A data item has information

The label, such as count_of_requests, or sum_of_durations
Value, this could be a integer, or a string (“OK”)
A timestamp
Attributes. Prometheus calls these dimensions, other products call these, tags or meta-data. These should be enough to identify the source, and attributes about the source which might be interesting in analysis or reports.

Example data

Below is some example data

Label	Timestamp	Value	Attributes.
total_count_requests	… 19:30:04.123456	6000	{jobname=”MYJOB”, request=”database”}
total_count_requests	… 20:00:00.987654	7000	{jobname=”MYJOB”, request=”database”}
total_duration_requests	… 19:30:04.123456	90000	{jobname=”MYJOB”, request=”database”}
total_duration_requests	… 20:00:00.987654	95000	{jobname=”MYJOB”, request=”database”}
total_count_requests	… 19:30:04.123456	400	{jobname=”MYJOB”, request=”webserver”}
total_duration_requests	… 19:30:04.123456	4000	{jobname=”MYJOB”, request=”webserver”}
total_count_requests	… 19:45:04.123456	200	{server=”MYSERVER”}
total_duration_requests	… 19:45:04.123456	2000	{server=”MYSERVER”}

There are metrics with labels total_count_requests and total_duration_requests.
The labels can refer to different applications, such as jobname=MYJOB, and server=MYSERVER
For jobname=MYJOB, there are requests=database, and data=webserver.

Focusing on the data you want

If you display “total_count_requests”, you will get a graph showing the data for all total_count_requests data, including both jobname=”MYJOB” and server=”MYSERVER”

You can use

total_count_requests{jobname="MYJOB"}

This will display only the total count requests where jobname=”MYJOB”. In the chart you will get a layer for each unique combination of attributes, so a layer for requests=”database” and a layer for requests=”webserver”.

You could use

total_count_requests{jobname="MYJOB",requests="database"}

to further restrict what is displayed.

Interpreting the data

I am working with metrics traces_span_metrics_duration_milliseconds_sum, and traces_span_metrics_duration_milliseconds_count. I’ll shorten these to _sum and _count.

If you have two data values, count of requests, and duration of requests, you can calculate the average time per requests: _sum/_count.
If these values are cumulative, that is they are not reset periodically, then you need to be careful how you interpret the data. The average value will be the average value of all requests. Overnight when there are no requests being processed, the average value remains constant.

What people are more interested in is the change between two points in time, and calculating the average.

You can aggregate the data such as _sum[1m] and _count[1m] which returns the sum of the data values in the 1 minute interval.

If _sum[1m] has range values [20,40,60], and _count[1m] has range values [1,2,5] then _sum[1m] / _count[1m] is iterate over the value, _sum[i]/_count[i], which produces [20,20,12]

You can use the increase function which takes two sets of timestamp records.

increase(traces_span_metrics_duration_milliseconds_sum[1m])
/
increase(traces_span_metrics_duration_milliseconds_count[1m])

This says take the _sum data, and put it into time buckets 1 minute wide, then calculate the increase in the value of each bucket

increase(traces_span_metrics_duration_milliseconds_sum[1m]) returns an array of the increase the sum of the time in each 1 minute time interval.
increase(traces_span_metrics_duration_milliseconds_count[1m]) returns an array of the count of requests that happened each 1 minute time interval.

The increase(_sum[1m])/increase(_count[1m]) shows the average time for each request in each 1 minute windows.

If you want to find the average for all requests

sum(increase(traces_span_metrics_duration_milliseconds_sum[1m]))
/
sum(increase(traces_span_metrics_duration_milliseconds_count[1m]))

Note: You can also use

sum(rate(traces_span_metrics_duration_milliseconds_sum[1m]))
/
sum(rate(traces_span_metrics_duration_milliseconds_count[1m]))

This is computed as ((delta(_sum)/1m) /((delta(_count)/1m) – the time interval cancels out to give delta(_sum)/delta(_count) which is the same as increase(…)/increase(…).

Displaying the sum(increase….)/sum(…) in Grafana, you can use explain query – and it gave

sum(increase(traces_span_metrics_duration_milliseconds_sum[1m])) / (sum(increase(traces_span_metrics_duration_milliseconds_count[1m])))
- Fetch all series matching metric name and label filters.
increase(<expr>[1m])
- Calculates the increase in the time series in the range vector. Breaks in monotonicity (such as counter resets due to target restarts) are automatically adjusted for. The increase is extrapolated to cover the full time range as specified in the range vector selector, so that it is possible to get a non-integer result even if a counter increases only by integer increments.
sum(<expr>)
- Calculates sum over the dimensions.

The basic data point

A data point has

a metric name, such as “requestActiveTime”, “traceCount”, “traceSum”
a timestamp – of when the data point was created
a value – depending on the metric, it could be a string, a counter (which only increases), or a numeric value (which can go up and down)
dimensions/tags/attributes/labels. Zero or more meta data keyword=values pairs, such as “jobName=MYJOB”, “activity=database”

The smallest database

	time t0	time t1	time t2
requestCount (task=”job1″)	5	6	7
requestCount (task=”job2″)	7	9	10
requestSum (task=”job1″)	24	30	25
requestSum(task=”job2″	30	50	60

Displaying data

Display all data

If you display requestCount in Prometheus

requestCount

you will get 3 data pairs: (time t0, 5+7), (time t1,6+9), (time t2,7+10). This is the data displayed for all requestCount records at that timestamp added together. Prometheus can display the data in a table, or in a graph.

Tools like Prometheus and Grafana, select a window of data, so you can select the last 5 minutes, the last hour, or specify a date-time range.

You can request a subset of information

You can select which rows you want

requestCount{task="job1"}

You will get 3 pairs of data items: (time t0,5), (time t1,6), (time t2,7) This is all of the rows for requestCount with task=”job1″ (in the current selected time range).

If you refresh the display, the data will gradually move left and fall off the screen, as the time stamps fall out of the current display window.

You can display groups of data

by (task) (requestCount)

Will produce 6 pairs of data times

Job1: (time t0,5), (time t1,6), (time t2,7)
job2: (time t0,7), (time t1,9), (time t2,10)

Applying functions

You can use

sum(requestCount)
sum by (task) (requestCount)

Instant values and range values

The data pairs above are called instance values – values from that particular instant in time. Some functions act on a range of time stamps. You can specify a timestamp range by specifying [5m] after the metric name, for a 5 minute range.

rate(requestCount{task="job1"}[5m])

with

	time t0	time t1	time t2
requestCount (task=”job1″)	5	6	7

Where the above rate statement is the Per-second rate of increase, averaged over last 5 minutes. With rate() you pass in a time duration which covers a range of timestamps. Prometheus will process the data to match what you specify.

The documentation says for rate

rate(v range-vector) calculates the per-second average rate of increase of the time series in the range vector.

More complex data

You might have some data points with multiple dimensions “jobname=…” and “userid=…”. Prometheus will output a record for every unique set of dimensions.

You can use

by(task) (jobrequestCount)

will produce records for each unique task – and ignore any other dimensions.

You can explicitly ignore dimensions

without(userid) (jobrequestCount)

if there were many dimensions, only the userid dimension would be excluded from the displays.

You can do calculations on time ranges

You can do

requestSum/requestCount

requestSum[1m]/requestCount[1m]

The requestSum[1m]/requestCount[1m] produces an array where the timestamp increases every minute.

Handing lots of data

There may be many thousands of OTEL records produced a second, from one system. Keeping this data for many months means there could be a lot of data to be stored, and would lead to expensive processing at display time.

Data can be aggregated

A simple aggregation is for the front end OTEL records processing system, to produce every 30 seconds (for example) one record with the sum, and the count of records. This means you get one record every 30 seconds – compare to 10,000 individual records.

This may not provide the right level of information. A better way is the use of buckets, where each record is accumulated.

Some real data

startTime:...
endTime:...

"count": "64",
"sum": 73.024271,
"bucketCounts": [
    "0",
    "8",
   "55",
    "1",
    "0",
    "0",
    "0",
    "0"
 ],
 "explicitBounds": [
     0.1,
     1,
     2,
     6,
    10,
   100,
   250
 ],
...

You can calculate the average ( sum/count).

This has a range of buckets 0 ms to 0.1 ms, 0.1 to 1, 1 to 2 … and how many elements were in that bucket

You can plot the data and get a “profile” like

If the profile changes significantly over time, then you need to investigate why.

What 5 spans had longest time?

I found the data displayed had 20 layers in the graph – too many to be able to see and manage. When investigating problems, you are interested in the long times – and can ignore the small times. You can use the display the top k values using the topk function.

The query in Grafana which includes topk(Select largest k elements by sample value)

topk by(__name__) (5, 
   sum by(span_name) (increase(traces_span_metrics_duration_milliseconds_sum  [1m]))) / 
  (sum by(span_name) (increase(traces_span_metrics_duration_milliseconds_count[1m]))
)

gave me

Where the yellow/brown is MQPUT RSERVER, and the purple is MQPUT to COLIN2.

It shows that some resources always took a long time(green), and some resources only occasionally took a longer time (yellow).

Processing Opentelemetry data – what’s missing (or is hard)

I’ve spent several weeks implementing Opentelemetry, and although it works, I feel there are bits missing, rather than “wow, what a perfect solution”. I tried to put myself in the position of supporting an enterprise customer who has many critical business applications, across many systems and platforms. The customer wants to be able to identify problems, before their end users notice, and before the end users flood social media with complaints.

Below are my thoughts on what I have learned. I may be totally wrong; maybe I didn’t know about some facilities which would solve the problems. If you know differently – please tell me. I love getting feedback – and I will update the documents.

I want to see the business view not the detailed plumbing view

Problem:

I’ve been to visit customers, and been allowed to visit their “mission control”. This is like the mission control for a moon landing. There are perhaps 200 screens showing all aspects of the business from the application throughput, through to the temperature of the water in the cooling systems. A screen can be selected and displayed “full screen” so every one can see it.

How I see the Opentelemetry data.

By default the information reported in Opentelemetry dashboards shows the plumbing; This database table, that CICS transaction, this MQ queue.

The business wants to know about “online banking”, or a function like “credit user’s account”, and not the name of a CICS transaction. Some services are common to all business applications, such as logon, and move_money. Some services are business application specific, such as “ATM statistics”.

One solution

An input stream of OTEL information can be fanned out to multiple streams. You might have one stream for “Enterprise monitoring”, and another stream for “CICS monitoring”, or “MQ monitoring.

The Opentelemetry collector can fan out the data to a CICS Grafana, an MQ grafana, and a z/OS grafana. Each of these grafanas has been configured to provide the information that the CICS, MQ, and z/OS people need to see.

The Opentelemetry collect can transform the input data, from “MQGET COLIN” to the name of a business application.

- set(span.name,"Payroll MQPA app gets the reply") where span.name == "MQGET COLIN"
- set(span.name,"Creditcheck application GET")     where span.name == "MQGET CSERVER"

A different approach

When displaying data in Prometheus or Grafana, you can select which data is included in the displays.

For example if you have specified tracestate when you created your OTEL data, you could have one window for when w3.tracestate=”APPL=MYAPPL”, and another window with w3.tracestate=”APPL=ONLINE BANKING”.

Half the information is not available

Problem.

The aim of the Opentelementry is to identify where work is being delayed, and why. However it only reports on how long a piece of work took.

For any work request there are two components

The transaction is doing something, reading a file, sending a request etc
Waiting for something. This could be the response to a request. The work could be waiting, for example, because of insufficient resources (the CPU is too busy), or there is a long network round trip time.

The Opentelementry dashboard only reports on when something is being done (a database update has been done). It does not report on the waiting. Often the waiting is the longest part of a transaction. As a result the dashboard is not reporting all the facts.

If you consider the simplest application where an application queues some work, and the work executes at a later date. For example a CICS transaction schedules another CICS transaction in another CICS region on a different LPAR in the sysplex. The started transaction may be delayed because too many other requests are queued up.

The business transaction is:

Run a CICS transaction ABCD – which issue a START of transaction WXYZ. The whole transaction takes 1 millisecond elapsed time.
There is some delay due to getting the request to the remote system, and a delay until the transaction can run
After 10 milliseconds, transaction WXYX runs, which takes 1 millisecond.

The dashboards will report

Transaction ABCD 1ms
Transaction WXYZ 1m

So shows the business transaction taking 2 ms.

It does not always show the 10 ms delay before the work was scheduled. (it depends on what data is generated)

If the time before transaction WXYZ increases to 20ms – the dashboards do not show it.
If the transaction ABCD takes longer (perhaps it had a longer database request), then it would show up.

Answer:

I wrote some Python code which creates a new Opentelemetry record covering the gap between two records, so from the start of transaction WXYZ back to the end of its parent. This gave me three records in my dashboard

Transaction ABCD 1ms
Delay before transaction WXYZ starts 10 ms
Transaction WXYZ 1m

This could be done properly by writing a processing stage in GO in Opentelemetry.

There is too much information

Problem: Too many layers in the cake

In simplest typical MQ transaction, I have 8 items displayed on the dashboard

Client application puts a message to a queue
The mover gets the message and sends it to the remote system
The mover on the remote system puts the message to the queue
The server application gets the message
The server puts the reply
…

On the dashboard it shows the average time for each of these, but it is hard to tell which colour is for which action.

Answer:

You can say display the top n values. ( I used 4). If something takes longer than usual, it will appear in the list – and so the list will have a new colour – and you can see something is different.

Problem: you are using too many values

Each data record has a value (such as duration) and “dimension” (or attributes) of the record, such as Originating system, Opentelemetry instance, Span-name(such as transaction ABCD).

By default if you display the data, there will be a “layer” in the cake for every unique combination of dimensions.

If you have 50 different CICS transactions, you will have 50 slices. You can select which attributes to select by, and can group them by regular expression.

The problem is if the span is called “CHECK USERID xxxxxxx ” or MQPUT CSQX……” where there is a span for each userid checked, and for every MQ dynamic queue. The number of these depends on activity. It is hard to display the data so you can get useful data out of it.

Answer:

In the Opentelemetry collector you can use a transformation to set(or add) a value depending on the contents of a field. The following checks the name of an MQ Queue. If the queue name starts CSQX. then consider it a dynamic queue and give these entries the generic name CSQX*

set(span.name,"MQPUT *CSQX") where Substring(attributes["span,name], 0, 11) = "MQPUT CSQX."

See Understanding the OpenTelemetry Transform Language

The statement would replace all span names starting with MQPUT CSQX. with the string MQPUT *CSQX, and so be obvious this is a substituted name.

Drilling down on outliers

When a problem occurs (the duration of the business transaction take much longer than usual), you want to be able to drill down, and find out why.

Problem: Drilling down to find the root cause is hard

Jaeger display

If you are using Jaeger display to display the business transaction response time, you may spot outliers, and be able to click on one, and see the profile of the data.

You cannot select a time range, only the last 5m, 15m, 1h etc. You may have millions of records in 1 hour, and I do not think Jaeger is up to it, because it suggests processing 20 records.

Grafana display

Grafana displays aggregated information, so does not have individual records. You can see the time interval when the long durations occurred.

Answer:

You can configure Grafana links. When you click on a data item, a pop up giving information about that point is displayed. You can configure links which can be selected. For example select the Jaeger display of this service, between the two time stamps selected.

This was not easy to set up – because the links did not display every time. When it works it works well.

You can configure links to pass a URL and parameters from the data, or take an action.

Start here for processing Opentelemetry data – visualisation in Grafana.

I’ve written a High level view of Opentelemetry, and visualising Opentelemetry data in Jaeger.

This blog post is about the Opentelemetry aggregated data, and displaying it in Grafana.

Prometheus accepts metric data from sources like Opentelemetry, but it does not take the raw Opentelemetry “log” data from application directly into Prometheus. There is a component System Performance Measuring(SPM) which takes the OTEL log data and creates metrics. It runs in Opentelemetry collector, or the Jaeger program. (I think running it in Opentelemetry collector is better, because running it in Jaeger did not immediatelygive me all of the records)

The SPM code takes each record

extracts hinformation from the OTEL logs. For example the service name, the span name, and others fields that have been configured in the configuration file

Conceptually the SPM code takes all the records received in a time interval – say 10 seconds, and creates two records

traces_span_metrics_duration_milliseconds_count
traces_span_metrics_duration_milliseconds_sum

and copies in the default dimensions (meta data) and which additional dimensions have been configured to be included. My simplistic view would have had one record with both the sum and the count, but this is not how it is done. There is a lot of additional data for each of the generated records, but I cannot find how to use it.

See here for information

The span metrics processor works by inspecting every received span and computing the total count and the duration of spans for every unique combination of dimensions. Dimensions can be the service name, the operation, the span kind, the status code and any attribute present in the span.

You can display the data in Prometheus, but you can do so much more with Grafana. I did Unit Testing with Grafana, and my System Testing using Grafana, because Grafana can save queries and dashboards.

It will help if you are familiar with the Prometheus data model.

First query

The values traces_span_metrics_duration_milliseconds_sum and traces_span_metrics_duration_milliseconds_count are ever increasing.

To find the average value over 1 minute intervals use (see here for an explanation)

increase(traces_span_metrics_duration_milliseconds_sum[1m])/ increase(traces_span_metrics_duration_milliseconds_count[1m])

If you move the mouse over a colour, it gives you information about that point (see the purple data below). The pop-up shows it is for an MQPUT to CSERVER for queue manager (=service name) CSQ9, with a duration of 1.52 ms.

Below the chart is all the data for the items.

There is data on the chart for every combination of dimensions/parameters/meta data. These items include information like

service.name: CSQ9
span.name: MQPUT CSERVER
span.kind: SPAN_KIND_PRODUCER
status.code: STATUS_CODE_UNSET
collector.instance.id: 2e1c51fc-7f54-4da5-aa9f-9c3cac190103
w3.tracestate: rojo=MODEL – this is what I passed on the trace data.

I had some data with service.name MQPA, and different span.names

This is for all resources

You can select which records are displayed, for example

rate(traces_span_metrics_duration_milliseconds_sum{w3_tracestate= "rojo=MODEL"}[$__rate_interval])

Selects those with the property w3.tracestate = “rojo=MODEL”. I specified this by setting the MQ message propery

tracestate=rojo=MODEL

You can control which parameters are passed from the original records into the aggregated records. See the dimensions parameter in the span_metrics: definitions.

Set up data source

You can set up different data sources. I have one for Prometheus, and one or Jaeger. Once you have configured them you can use explore to look at the data.

Set up dashboards

You can set up dashboard to display the data in different ways.

You specify the data source, and then how you want the data formatted, typically I use a timeline.

You can use Builder |code to define your query. With builder you define the query through a GUI. With code you specify the query.

You can define multiple queries which display on the same windows. You can hide/unhide the data from each query, by selecting/unselecting the query.

You could define one query for w3_tracestate= “appl=OnlineBanking”, and another for w3_tracestate= “appl=OfflineBanking”.

Time ranges

From a pull down you can select “last 5 minutes”, “last 15 minutes”, or you can specify a date and time range. This means you can go back to a previous days data.

I have it refreshing the data every 5 seconds, and the graph data gradually creeps left, until the data falls out of the displayed time range.

Data links

On each page you can set up data links. If you hover your graphic cursor over a data item, it shows the data item’s attributes in a pop up window. You can also configure data links, which appear on in the pop up window, so you can link to another URL, passing data from the data items.

In the figure below, I graphed the top 4 span_names with the highest average value. It has a data link called colins jaeger2

By clicking on the “colins jaeger2” it invoked the URL, and passed the __from and __to times, in the URL.

Start here for processing Opentelemetry data – visualisation in Jaeger

Ive written

Jaeger

Jaeger is a component which does two things

Visualises the data – see the image at the top of the blog post
Can aggregates the data for Grafana to use

Visualise the data

By default it displays 20 entries

and shows information about the individual points

This shows there were two queue manager CSQ9 and MQPA, there were 8 spans (recorded data)the duration if each item, and the date. ( I think the date format is wrong .. you want hh:mm:ss – because you know what the day and date are!

If you click on the blue Trace Name – you get a detailed picture for that trace point of where the time was spent

There is a limited search capability. You can display data going back 5 minutes, last 15 minutes etc.

You can limit how many records are displayed.

Displaying 100 records over half an hour gave me

If you click on an outlier you get the details of that point

You can click on each Service & Operation and see all the attributes associated with the record. For example z/OS image name, message persistence, size of message etc.

The challenges with using Jaeger visualisation

What transaction is this for ?

I ran two different transactions at the same time. The data displayed was the same as above. I could not identify which trace record was for which transaction.

If you display the details, the “title” such as MQPA MQPUT RSERVER gives you a clue as to which transaction the data is for.

Whoops missed it

If you have a low transaction rate, then if you display the last 10 minutes, you may get all of the data.

If you are doing a high transaction rate, and need to go back half an hour, there may be so much data you cannot find the entries of interest.

Start here for processing Opentelemetry data

I’ve spend a few weeks trying to generate and use Opentelemetry data. My salesman’s vision does not match the practice. Below is what I have learned from hands on. It shows the typical usage of displaying Opentelemetry data using Jaeger and Grafana. What I say may be wrong, if so please tell me and I’ll correct it.

There are follow-on posts

Start here for processing Opentelemetry data – visualisation in Jaeger
Start here for processing Opentelemetry data – visualisation in Grafana
Processing Opentelemetry data – what’s missing (or is hard) – the gap between the vision and real life.

What is opentelemetry?

As work moves through a system it reports where it is. A central collector takes this data and can display where the work item spent its time.

This shows an application putting a message to an MQ queue, on queue manager MQPA, flowing through to a server on queue manager on CSQ9, and a response flowing back.

The overall transaction time was 71 ms.

The architecture

On z/OS the OTEL data is written to SMF. There is a Java application which runs on z/OS, which reads from SMF, and sends it to an Opentelemetry collector (running on my Linux laptop).

The Opentelemetry collector generates data in the form for “standard” packages Prometheus and Grafana to process, and display dashboards of the information.

There are two data models for sending data between components

The Opentelemetry collector has a push model. The recipient is a web server, and the OTEL collector sends JSON data over a POST request to the HTTP server.
Grafana has a pull model. It periodically sends a request to its providers saying “send me data on ….”

Prometheus has a database, which has a web server for capturing the data from the Opentelemetry client. Prometheus saves the timestamp data efficiently. Prometheus provides another web server to respond to the “send me data …” from Grafana.

Prometheus accepts metric data from sources like Opentelemetry, but it does not take the raw Opentelemetry “log” data directly into Prometheus – I think of Prometheus as a database.

Grafana takes data from many sources (such as Prometheus) and displays dash boards, which typically are time sequences of data. See below.

There is another component Jaeger, which converts the data from OTEL into data suitable for Grafana.

I expect people will use Grafana for overall monitoring, and Jaeger to dig down into a time range.

Note 1: You cannot go directly from Opentelemetry to Grafana, because Opentelemetry only provides a push model.
Note 2: You can write your own components to process the data from Opentelemetry.

Grafana

A typical chart showing where time was spent

There are many layer – each one is for a unique span name and dimensions (meta data). There is a pop up with information about where the graphical cursor is. The information shows for queue manager MQPA, the MQPUT to RSERVER took 0.635 milliseconds.

Overall the work took between 7 and 4 milliseconds.

You can display multiple charts in a dashboard

This shows the average times for the different spans ( MQGET COLIN), and the count of “transactions”.

The MQPUT to CSERVER was highest, and about 1.2 milliseconds.

For more information on Grafa see Start here for processing Opentelemetry data – visualisation in Grafana

Jaeger

Jaeger is a component which does two things

Visualises the data – see the image at the top of the blog post.
Can aggregates the data for Grafana to use

Visualise the data in Jaeger

By default it displays 20 entries

and

This shows there were two queue manager CSQ9 and MQPA, there were 8 spans (recorded data) the duration if each item, and the date. ( I think the date format is wrong .. you want hh:mm:ss – because you know what the day and date are!

If you click on the blue Trace Name or a blue dot – you get a detailed picture of where the time was spent

For more information on displaying data in Jaeger see Start here for processing Opentelemetry data – visualisation in Jaeger

How does a C program wait for a short random time?

As part of getting a workload with a varying response time, I wanted the server to wait for a short amount of time between processing requests. This was pretty easy, but there were a couple of challenges

The code

#ifndef __timespec_struct
  #define __timespec_struct 1
  struct timespec
      {
      time_t tv_sec;
      long   tv_nsec;
      };
#endif


struct timespec randomWait;     

#undef  RAND_MAX
#define RAND_MAX 100
j = RAND_MAX;  
int myrand = rand();
printf("Random number %i %i\n",myrand,j);

randomWait.tv_sec = 0 ;
randomWait.tv_nsec = myrand * 1000000; 

nanosleep(randomWait, NULL);  // if specified

Define timespec structure

The documentation for nanosleep gave some example code. When I used it, I got a compile error

"struct timespec" is undefined.

I found it easier to define the timespec structure myself.

Set the upper limit for the random number.

You do not pass the upper limit to the rand() function. The value is taken from the #DEFINE RAN_MAX. (A strange way of doing it). The default upper limit is 32767.

To set your own limit, you need to #undef, then #define with the new value.

Setting the random time

The timespec structure has the value in seconds and nanoseconds. Because I wanted a random wait in milliseconds, I used random_value * 1000000 to convert to nano seconds.

Why can’t I change my Linux terminal environment from a script

I wanted to configure my terminal sessions, with a tab label to say what the window is, and colour them, so I get a visual clue.

For example I have a script

PS1='[\e]0;Opentel\a]\u@\$ '
docker run --rm  --name ozf \
    ...
    otel/opentelemetry-collector-contrib:latest --config opentransform.yaml

If I enter the PS1 command in the window – it changes tab’s label.

If I put it in a shell script, I execute the commands to change my tab and run the docker image, but it does not change the tab’s label. Why not?

The source command (or the . command) treats the commands in the file, as if I had entered them at the terminal.
With the bash or shell, the command creates a new shell, and then executes commands inside it. Once the command finishes, the shell is destroyed, but the original shell is unchanged.g

Another of the it is obvious when you know the reason.