Capturing and replaying Opentelemetry data

I wanted to create some files so that people could get Opentelemetry, and displaying data working, but also to provide sample data. There are several sites offering configuration files, but not the data to display.

This has an additional challenge. With tools like Jaeger and Grafana, you typically display data “in the last 5 minutes”, or “in the last hour”. If I provide data, then it may be viewed a year later. However with a small bit of Python code I fixed this.

The Opentelemetry collector to capture data

This takes the data from the various sources in the network, and collects the information.

The receiver

receivers:
  otlp:
    protocols:
      grpc:
        endpoint: 0.0.0.0:4317
      http:
        endpoint: 0.0.0.0:4318

The exporter

exporters:
  debug:
    verbosity: normal # basic: basic, normal, detailed

  otlp_http:
    endpoint: "http://jaeger2:4318" # was 4318
    tls:
      insecure: true
  file/in:
      path: /file.in

The magic

service:
  pipelines:
    traces:
      receivers: [otlp] 
#      processors: [transform/timestamps] # I did some transformation of the data
      exporters: [debug,file/in,otlp_http]

The flow

The data came from z/O into the oltp receiver (grpc: endpoint: 0.0.0.0:4317)
The service: traces: receivers…, exporters, says pipe the data from otlp and put it to
- debug – output to the terminal
- file/in – this maps to a file definition file.in
- otlp_http – for Jaeger to use

The docker command

I ran the opentelemetry collector in Docker, and this needs some statements to map from internal names (such as file.in), to the real file.


touch file.in.json
truncate -s 0 file.in.json
chmod 777 file.in.json
docker run --rm  --name ozf \
 --volume "$(pwd)/o2.yaml":/otel-config.yaml \
  -v "$(pwd)/file.in.json":"/file.in" \
  --env COLLECTOR_OTLP_ENABLED=true \
  --publish 4317:4317 \
  --publish 4318:4318 \
  --network otel-jaeger-network \
    otel/opentelemetry-collector-contrib:latest --config otel-config.yaml

The command executed is

otel/opentelemetry-collector-contrib:latest --config otel-config.yaml

Docker will download the code if needed. It will take the latest level of code.

The truncate file -s o resets the file to empty.

The configuration is in otel-config.yaml. The option –volume “$(pwd)/o2.yaml”:/otel-config.yaml maps otel-config.yaml to the file “$(pwd)/o2.yaml”

The yaml configuration file refers to /file.in. This maps to $(pwd)/file.in.json on my file system.

You can then issue commands like

cat file.in.json | jq |less

to look at the data.

The Opentelemetry collector to replay data

As well as receiving data over http, there are other sources, one of which is oltp_json_file which reads opentelemetry data from a file

receivers:
  otlp_json_file:
    include:
      - "/input.json"
    start_at: beginning

The docker command

docker run --rm  --name ozf \
 --volume "$(pwd)/o1.yaml":"/otel-config.yaml" \
  -v "$(pwd)/otel.in.json":"/input.json" \
  --env COLLECTOR_OTLP_ENABLED=true \
  --publish 4317:4317 \
  --publish 4318:4318 \
  --network otel-jaeger-network \
    otel/opentelemetry-collector-contrib:latest --config otel-config.yaml

The data is read from file file otel.in.json in the current directory.

Transforming the date times

The JSON data has start and end times. The display tools display “recent data”, such as the “last 5 minutes”. I wrote some python code to find the earliest time stamp, calculate the data from the time stamp to now, and adjust all the timestamps.

'''
Python  script to adjust the datetimes in an opentelemety json file, so it 
looks as it the data has just been created.

This has been tested on Ubuntu

Format

python3 fixtime filename1 <filename2>

Where 
filename1 is the name of the input file
filename2 is the name of the output file.   The default is otelts.json 

'''
import csv, json
import sys
import json
from datetime import datetime
import json 
import time
earliestTime = 0
if len(sys.argv) < 1:
    print("fixtime adjusts the otel datetime stampts in otel data to look like they've just been created")
    print("The format is fixtime  <inputfile> <outputfile>")
    print("Where the defaults are  inputfile is file.in.json and the outputfile is otel.in.json ")
    sys.exit(0)
if len(sys.argv) < 2:
   inputFile =  "file.in.json" 
else:
    inputFile  = sys.argv[1]   
if len(sys.argv) < 3:
   outputFile =  "otel.in.json" 
else:
    outputFile  = sys.argv[2]       
timenow = time.time_ns() 
lineno = 0
with open(inputFile, 'r') as file, open(outputFile, 'w') as fout:

    for line in file:
        data = json.loads(line)
        # get the first time - so we can offset all of the time values
        if earliestTime == 0:  # get the first time found in a span
            for d,dvalue in data.items():  # a dict with one item, resourceSpans
                for resourceSpan in dvalue :   # it is a list - do each one
                    scopeSpans= resourceSpan["scopeSpans"]
                    for scopeSpan in scopeSpans:  #"scopeSpans": [ is a list of scopes
                            spans = scopeSpan["spans"]  # a dict
                            # print(spans)
                            for s in spans:  # each span  in the list Only element
                                # s["scopeSpan"] = scopeSpan
                                earliestTime = s["startTimeUnixNano"]
                                delta = timenow- int(earliestTime)
                                break
                            break
                    break
        
        # now process all of the data and add the delta to the time stampb       
        for d,dvalue in data.items():  # a dict with one item resourceSpans                    
            for resourceSpan in dvalue :   # it is a list - do each one
                scopeSpans= resourceSpan["scopeSpans"]                
                for scopeSpan in scopeSpans:  #"scopeSpans": [ is a list of scopes
                    spans = scopeSpan["spans"]  # a dict
                    # print(spans)
                    for s in spans:  # each span  in the list Only element
                        s["startTimeUnixNano"] = int(s["startTimeUnixNano"]) + delta 
                        s["endTimeUnixNano"] = int(s["endTimeUnixNano"])
        # and now write out the updated data  
        jsonstr = json.dumps(data)
        fout.write(jsonstr+"\n")                                 

sys.exit(0)

How does it all fit together?

I ran the otel collector in one terminal, and Jaeger in another.
I stopped both of them
Use python3 fixtime json.file.in otel.in.json This created file otel.in.json.
Started otel
Start jaeger
Look at the data in a web browser pointing to the Jaeger address and port.

Where is my MQ Opentelemetry output from z/SOS?

With Opentelemetry, as work flows through a system, it sends “I am here” data back to a collector, which can process it, and pass it on to other tools to display the information on graphical dashboards.

I spent several days trying to work out why I was not getting any telemetry data from my queue managers.

Basic setup

Check SMF

The telemetry data is written to SMF. You should check it is being collected. The command D SMF gives output like

IFA714I 08.45.27 SMF STATUS          FRAME LAST   F      E   SYS=VS01       
          LOGSTREAM NAME               BUFFERS        STATUS                
        A-IFASMF.DEFAULT                      0       CONNECTED             
        A-IFASMF.COLIN                        0       CONNECTED             
        A-IFASMF.INMEM                  1289792       IN-MEMORY             
        A-IFASMF.MQOTEL                  393304       IN-MEMORY             
        A-IFASMF.T1159                        0       IN-MEMORY

This has some data in the buffers, so it looks like data is being produced.

You can check the SMF option using the command D SMF,O

This gives a lot of information including

INMEM(IFASMF.T1159,TYPE(1159),RESSIZMAX(0128M)) -- PARMLIB     
INMEM(IFASMF.MQOTEL,TYPE(1158),RESSIZMAX(0128M)) -- PARMLIB    
INMEM(IFASMF.INMEM,TYPE(30),RESSIZMAX(0128M)) -- PARMLIB

This shows the MQ SMF records, type 1158 are mapped to name IFASMF.MQOTEL. It may be different on your system.

Check the data gatherer is active

This is a Java program which runs on z/OS and writes to an HTTP connection. I run mine as a started task.

This program does not report any statistics, if it is using CPU, then is may be processing records.

Check the network traffic

I use TLS encryption on my connection to the Opentelemetry collector server running on Linux. Using tools like wireshark on the connection allow you to see the overall traffic, but not the content of the traffic. For example

Shows there is traffic to and from port 4317 on my Linxu box.

The records with length of 8258 contains my Otel traffic
There is also TCP/IP Keep Alive flows every 15 seconds or so.

On the Linux Opentelemetry collector

During setup, I had the collector write to debug, and to a file, so I could see the traffic coming down.

But no data is being produced.

There are two switches that need to be enabled.

The Opentelemetry state is sent as a message property within MQ messages.
There is a property traceparent, which identifies the high level piece of work. The data is of the format

trace identifier ‘-‘ span identifier ‘-‘ flags

Where flags is a two byte character string such as 01.

Format of the flags

If the rightmost bit of the flags is 0, then this signals do not collect any data.
If the rightmost bit of the flags is 1, then do more checks.
- If the queue has an attribute OTELTRAC(ON) (either directly, or as specified at the QMGR level), then emit the otel data
- Else do nothing.

The flag in the traceparent is called SAMPLED, which I found confusing. I didn’t want to sample – I wanted OTEL information for all records!

I had the flags specified as 00 and did not get any output. When I changed it to 01 I got the OTEL data – it was as easy as that.

MQ, JMS and Opentelemetry

I wanted to use Opentelemetry with MQ. One option is to use JMS, and the “code free” Otel support.

This code-free-support intercepts the send and receive methods, intercepts them, and sets up the Otel support (in MQ).

See here for information on the Java Otel instrumentation.

My code

I used the IBM MQ sample JMS programs JMSProducer and JMSConsumer.

export CLASSPATH=/opt/mqm/java/lib/com.ibm.mq.allclient.jar:$CLASSPATH
export CLASSPATH=/opt/mqm/samp/jms/samples:$CLASSPATH
export CLASSPATH=/home/colin/Downloads/opentelemetry-javaagent.jar:$CLASSPATH
export OTEL_JAVAAGENT_ENABLED=true
export OTEL_JAVAAGENT_LOGGING=simple
export OTEL_EXPORTER_OTLP_PROTOCOL=grpc
export OTEL_EXPORTER_OTLP_ENDPOINT=http://10.1.0.2:4317

java -javaagent:/home/colin/Downloads/opentelemetry-javaagent.jar
-Dotel.resource.attributes=service.name=ColinsJMS
-Dotel.traces.exporter=console
/opt/mqm/samp/jms/samples/JmsProducer.java \
-m MQPA -d RSERVER -l SYSTEM.DEF.SVRCONN -h 172.26.1.2 -p 2414

This produced

Jaeger output

Which shows the message passed through MQ and was got (by the server program).

Because the sample JMS program does not allow you to specify a ReplyToQueue manager name, the server cannot send the reply back.

I changed the JMSProducer to specify a replyToQueue, and pass this as part of the message.
I used the JMSConsumer program unchanged.

The updated application

export CLASSPATH=/opt/mqm/samp/jms/samples:$CLASSPATH
export CLASSPATH=/home/colin/Downloads/opentelemetry-javaagent.jar:$CLASSPATH
export OTEL_JAVAAGENT_ENABLED=true
 # export OTEL_JAVAAGENT_LOGGING=simple # default
export OTEL_EXPORTER_OTLP_PROTOCOL=grpc
export OTEL_LOGS_EXPORTER=console
export OTEL_METRICS_EXPORTER=console
export OTEL_EXPORTER_OTLP_ENDPOINT=http://10.1.0.2:4317	
java -javaagent:/home/colin/Downloads/opentelemetry-javaagent.jar \
     -Dotel.resource.attributes=service.name=ColinsJMSProducer \
     -Dotel.traces.exporter=console \
     /opt/mqm/samp/jms/samples/colinProducer.java   \
-m MQPA -d RSERVER -l SYSTEM.DEF.SVRCONN -h  172.26.1.2 -p 2414 -r CCOLIN

echo "===================================================="

java -javaagent:/home/colin/Downloads/opentelemetry-javaagent.jar \
     -Dotel.resource.attributes=service.name=ColinsJMSConsumer \
     -Dotel.traces.exporter=console \
     /opt/mqm/samp/jms/samples/JmsConsumer.java \
    -m MQPA -d CCOLIN -l SYSTEM.DEF.SVRCONN -h  172.26.1.2 -p 2414

When this ran, the Otel data displayed in Jaeger was

Comments on the output.

The chart shows
- A message is put to an MQ remote queue called RSERVER on queue manager MQPA. This operation takes 20.2 milliseconds.
- The message is got from a queue called CSQ9 (a transmission queue). This flows over the network to queue manager CSQ9.
- The message is put to a queue CSERVER on queue manager CSQ9.
- An application on CSQ9 gets the message, does some processing and puts a reply to queue CCOLIN ( on queue manager MQPA). You cannot see this program in the trace.
- The mover on CSQ9 gets the message from the transmission queue YMQPA and sends it over the network
- The mover on CSQ9 puts the message to queue CCOLIN
- The above processing is very quick.
- The putting JMS program ends, and starts the JMSConsumer program.
- 3.2 seconds after the initial put, the JMSConsumer program gets the message (and the MQGET takes 3.6 ms). The start of the second Java program takes a long time (most of this 3.2 seconds)
There are no entries for the JMS programs themselves. There are only entries for the MQ on z/OS.
Although there were two JMS Java programs involved – the Jaeger output just shows the MQ processing

What next?

Although this has shown that you can easily add Otel processing to your JMS program, the output is lacking.

You can manually instrument your Java program, as described by the Opentelemetry documentation.

How do I save Grafana dash boards?

There is documentation on the internet explaining how to save (share) dashboards. It goes like “from the hamburger icon select share dashboard”. I do not have the hamburger icon. I think this is because I am using the free opensource version.

I found a pointer to a script on the internet

#!/bin/bash

x=$(curl -u admin:password  http://localhost:3000/api/search?query= )

for uid in $(curl -u admin:password  http://localhost:3000/api/search?query= | jq --raw-output '.[].uid') ; do
  echo $uid
  curl -u admin:panthe0n  "http://localhost:3000/api/dashboards/uid/$uid" > "dashboards/$uid.json"
done

The output was a JSON file. I do not think you can import it back into Grafana (because it says it does not have a matching schema), but at least you can see what the contents were, and manually add them back into Grafana.

There is a more modern API such as

curl -u admin:panthe0n  http://localhost:3000/apis/dashboard.grafana.app/v1/namespaces/default/dashboards?limit=10

which will list all dashboards and their contents.

The modern API allows you to create dashboards – but I’ll leave this till another day.

Opentelemetry: Jaeger handling clock mismatches

I am collecting Opentelemetry data from z/OS and Linux, unfortunately the clocks on the two systems are not synchronised.

When I display the data in Jaeger, instead of looking like

Where the transaction took 56.5 milliseconds, the output looks like it took over 26 seconds.

The z/OS data (MQPA and CSQ9) is all squashed to the right because the z/OS clock is out by about 26 seconds.

How to fix it

Within the Jaeger yaml configuration file you can specify

extensions:
   jaeger_query:
     max_clock_skew_adjust: 30s

This says if it looks like the data has a time skew, and the time is off by less than 30 seconds, then make the timings look sensible.

How does it work?

The Opentelemetry data has information about each span processed. One of the fields is the parent span.

If Jaeger know know that the parent span executed between 13:00:00 and 13:00:01, and the spans from z/OS were for times 13:00:20 to 13:00:21, it looks like the z/OS times are out by 20 seconds, and so Jaeger can compensate for this.

By default max_clock_skew_adjust is 0, so there is no compensation.

Understanding Prometheus queries and why they might not work

I had a query

sum (rate(traces_span_metrics_duration_milliseconds_bucket[1m]) ) by(le) / sum(rate(traces_span_metrics_duration_milliseconds_count[1m]) )

and it returned no data. Why?

I discuss how I debugged this problem in Debugging Prometheus queries

The Prometheus documentation has a sections on queries and data.

Prometheus calculations

Data types

There are different sorts of data in Prometheus

A scalar. This is a single value. It can be a number or a string.
An array or vector. This could be an empty array [], an array with one element [44], or an array with multiple elements [1,2,3]
A time series. This has a time stamp and some data.

Basic calculations

I’ll use division as an example:

Scalar/scalar gives a scalar
Array/scalar gives an array, with result[i] = array[i]/scalar
Array/Array when the arrays are the same size. Result[i] = LeftArray[i]/RightArray[i]
Otherwise no result

Functions

The sum function takes a vector and returns a vector; for example, sum[1,2,3] = [6]
The scalar function acts on a vector and creates a scalar; for example, scalar[6] = 6
The vector function acts on a scalar and returns a vector of size 1; for example, vector(6) gives [6].

Why did the query not return any data

The query

sum (rate(traces_span_metrics_duration_milliseconds_bucket[1m]) ) by(le) / sum(rate(traces_span_metrics_duration_milliseconds_count[1m]) )

The sum() by() produces a vector, with each element of the vector corresponding to each unique value of le (8 elements in my case)
The sum() produces a vector with only one element.

From the basic calculations above an array of size 8/array of size 1 does not produce a result, because the arrays are of different sizes.

Putting scalar() around the second query means the calculation is array/scalar, which does work

sum (rate(traces_span_metrics_duration_milliseconds_bucket[1m]) ) by(le) / scalar(sum(rate(traces_span_metrics_duration_milliseconds_count[1m]) ))

Debugging Prometheus queries

I had a query

sum (rate(traces_span_metrics_duration_milliseconds_bucket[1m]) ) by(le) / sum(rate(traces_span_metrics_duration_milliseconds_count[1m]) )

and it returned no data. Why?

Ive explained the reason for this in Understanding Prometheus queries and why they might not work

Getting started

In Prometheus specify a query

sum (rate(traces_span_metrics_duration_milliseconds_bucket[1m]) ) by(le)

Select explain

and click the enable the query tree view.
This gave me

The traces_span_metrics_duration_milliseconds_bucket returned 96 results.
Hovering over the traces_spans… line shows the unique values of the span_names, le:6, exported_job etc. The image shows the unique values of the span_name.
The rate calculation gave 96 results
The sum by(le) gave 6 results – matching the value in the hover over the traces_span_metrics_duration_milliseconds_bucket

You can click on a box to get an explanation of that box. For example the sum by(le) gave

The second part of the query

The sum returns one value.

The combining the two subqueries

The first part before the query gave 6 results, but the part after the ‘/’ gave 0 results, even though the sum() gave 1 result.

Further down was

This shows the data on the left is a time an array of multiple values (for each le value), but there is only one value on the right hand side, and this is used once. Because there is no value available for the coloured entries – they are dropped.

The problem

I have a vector with multiple elements, and I want to divide it by a vector with only one element. This does not work.

You can use the scalar function to covert a vector with one element to a scalar, and the calculation vector/scalar will work

sum (rate(traces_span_metrics_duration_milliseconds_bucket[1m]) ) by(le) / scalar(sum(rate(traces_span_metrics_duration_milliseconds_count[1m]) )
      )

and the output was

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)