GSK trace and TCPIP

To track down a TLS setup problem with TN3270 and AT-TLS, I had to collect a System SSL Trace. You can collect data and have it output to the joblog, or the console. This is not good practice as it can produce a lot of output, and it is hard to read the data.

This blog post follows on from Collecting a TCPIP Packet trace on z/OS.

You can use the same CTRACE writer procedure for all your CTRACE work. It is better not to have more than one trace writing to it at a time.

Erik Janssen sent me an email on how to take the CTRACE file and process it in Wireshark. I’ve put his comments at the bottom.

You need to start the GSK Server task

See SSL Server task

My GSKSRVR JCL looks like

//GSKSRVR  PROC  REGSIZE=256M,OUTCLASS='A' 
//*-------------------------------------------------------------------- 
//GO       EXEC  PGM=GSKSRVR,REGION=&REGSIZE,TIME=1440, 
//  PARM=('ENVAR("HOME=/etc/gskssl/server"),TERM(DUMP)                 X
//             / 1>DD:STDOUT 2>DD:STDERR') 
//STDOUT   DD  SYSOUT=&OUTCLASS,DCB=LRECL=250, 
//  FREE=END,SPIN=UNALLOC 
//STDERR   DD  SYSOUT=&OUTCLASS,DCB=LRECL=250, 
//  FREE=END,SPIN=UNALLOC 
//SYSOUT   DD  SYSOUT=&OUTCLASS, 
//  FREE=END,SPIN=UNALLOC 
//CEEDUMP  DD  SYSOUT=&OUTCLASS, 
//  FREE=END,SPIN=UNALLOC 

I did not change any parameters, or defaults.

Start it

s GSKSRVR

It gives

GSK01001I System SSL version 4.4, Service level OA59115.
GSK01003I SSL server initialization complete.

Within the TELNET (TN3270) parameters I had

TelnetParms         ; ATTLS defined secure port 
 TTLSPort 2023      ; 
 DEBUG CONN DETAIL CTRACE 
 DEBUG CONN trace  CTRACE 
 DEBUG TRACE CTRACE
 ConnType Secure    ; Client chooses secure or nonsecure connection. 
EndTelnetParms 

This limits the trace to only port 2023, other ports, such as 0023 were unaffected.

I set up parmlib member for GSK trace, member CTGSKON

TRACEOPTS 
          WTRSTART(ctwtr) 
          on 
          jobname(TCPIP) 
          wtr(ctwtr) 
          OPTIONS('LEVEL=255') 

I turned trace on using

TRACE CT,ON,COMP=GSKSRVR,PARM=CTGSKON

This gave

IEE252I MEMBER CTGSKON FOUND IN USER.Z24C.PARMLIB
GSK01040I SSL component trace started.
ITT038I ALL OF THE TRANSACTIONS REQUESTED VIA THE TRACE CT COMMAND WERE SUCCESSFULLY EXECUTED.

ITT110I INITIALIZATION OF CTRACE WRITER CTWTR COMPLETE.

The CTWTR procedure was started was part of this command.

You stop the trace with

trace CT,off,COMP=GSKSRVR

Wait for the message

ITT038I ALL OF THE TRANSACTIONS REQUESTED VIA THE TRACE CT COMMAND WERE SUCCESSFULLY EXECUTED.

And stop the CTWTR writer using

TRACE CT,WTRSTOP=CTWTR

You should get messages

ITT038I ALL OF THE TRANSACTIONS REQUESTED VIA THE TRACE CT COMMAND WERE SUCCESSFULLY EXECUTED.
IEE839I ST=(ON,0001M,00005M) AS=ON BR=OFF EX=ON MO=OFF MT=(ON,064K)
IEF196I AHL904I THE FOLLOWING TRACE DATASETS CONTAIN TRACE DATA :
IEF196I IBMUSER.CTRACE1
AHL904I THE FOLLOWING TRACE DATASETS CONTAIN TRACE DATA :
IBMUSER.CTRACE1

ITT111I CTRACE WRITER CTWTR TERMINATED BECAUSE OF A WTRSTOP REQUEST.

Process 0201003E Thread 00000001 edit_ciphers
Using server certificate ‘ZZZZ’
…
S0W1 MESSAGE 00000008 15:19:52.223132 SSL_INFO
Job TCPIP Process 0201003E Thread 00000001 read_v3_extended_client_hello
Elliptical curve 0030 is being skipped as it is only supported in TLS 1.3

Setting up PFKeys

I set up some PFKeys to make it easier to issue these commands

In User.parmlib(PFKTAB00) I have

...
PFKTAB TABLE(CTRACE) 
    PFK(4) CMD('S GSKSRVR') CON(Y) 
    PFK(5) CMD('TRACE CT,ON,COMP=GSKSRVR,PARM=CTGSKON') 
    PFK(6) CMD('TRACE CT,OFF,COMP=GSKSRVR') 
    PFK(7) CMD('TRACE CT,WTRSTOP=CTWTR') 

I activate these keys using

K N,PFK=CTRACE
D PFK

                                                                  
IEE235I 10.05.03 PFK DISPLAY 729                                        
PFK DEFINITIONS FOR CONSOLE L700     - TABLE=CTRACE   IN PFKTAB00       
KEY# CON ------------------------- DEFINITION ------------------------  
  1      NOT DEFINED                                                    
  2      NOT DEFINED                                                    
  3      NOT DEFINED                                                    
  4  YES S GSKSRVR                                                      
  5   NO TRACE CT,ON,COMP=GSKSRVR,PARM=CTGSKON                          
  6   NO TRACE CT,OFF,COMP=GSKSRVR                                      
  7   NO TRACE CT,WTRSTOP=CTWTR                                         

Format the data using IPCS

If there is data in the file, you can use IPCS to format it.

The IPCS command is

CTRACE COMP(GSKSRVR) FULL ALL

You get output like

S0W1      MESSAGE   00000008  15:19:52.221020  SSL_INFO                 
  Job TCPIP     Process 0201003E  Thread 00000001  read_v3_client_hello 
  Received CLIENT-HELLO message                                         
                                                                        
S0W1      DUMP      00000020  15:19:52.221414  SSL_ASCII_DUMP           
  Job TCPIP     Process 0201003E  Thread 00000001  read_v3_client_hello 
  CLIENT-HELLO message                                                  
    00000000: 010001FC 03030C33 81E156C3 DF4693DD   *.......3..V..F..*  
    00000010: 621CA636 8A75BDF0 26F3DE8F 831B78BC   *b..6.u..&.....x.*
...
S0W1      MESSAGE   00000008  15:19:52.226897  SSL_INFO                  
  Job TCPIP    

Using batch IPCS

I used the following JCL

//IBMIPCS JOB 1,MSGCLASS=H 
//S1  EXEC PGM=IKJEFT01,REGION=0M 
//STEPLIB  DD  DISP=SHR,DSN=SYS1.MIGLIB 
//SYSPRINT DD SYSOUT=* 
//SYSTSPRT DD SYSOUT=* 
//SYSPROC    DD  DISP=SHR,DSN=USER.Z31B.CLIST 
//           DD  DISP=SHR,DSN=ADCD.Z31B.CLIST 
//           DD  DISP=SHR,DSN=SYS1.SBLSCLI0 
//IPCSPARM   DD  DISP=SHR,DSN=SYS1.PARMLIB 
//           DD  DISP=SHR,DSN=ADCD.Z31B.PARMLIB 
//IPCSTOC    DD  SYSOUT=* 
//IPCSDDIR   DD  DISP=SHR,DSN=SYS1.DDIR 
//SYSTSIN DD * 
 IPCS NOPARM 
 SETDEF DA('IBMUSER.CTRACE1') 
 DROPD 
 CTRACE COMP(GSKSRVR) FULL ALL 
/* 

Getting the data into Wireshark format.

Wireshark is an excellent tool for doing network trace, and decoding the flows. You can also is it to process the CTRACE data. Thanks for Eril Janssen for the instructions below on how to get from CTRACE to Wireshark.

You need to use the CTRACE SNIFFER option. This writes to the file with DDNAME of SNIFFER

Allocate a VB 1600 LRECL dataset and allocate it to a ddname, for example SNIFFER
ALLOC DD(SNIFFER) DS(<some dsname>) SHR
From IPCS you can now:

CTRACE COMP(SYSTCPDA) GMT SHORT  OPTIONS((SNIFFER(1600,TCPDUMP) NOREASSEMBLY)) DS(‘<the trace ds>’)

The formatted trace will now be in <some dsname>. Do a binary transfer to your pc and you show be able to open the trace in wireshark.

I tend to use IPCS in batch (so I do not get the lock on the trace file, (grin)).

Problems

I was using CTRACE, the IPCS, then CTRACE etc. Sometimes the CTRACE writer would not start (or stop). This can be because you are still in IPCS, and IPCS has a lock on the dataset, or you have quit from IPCS, and TSO still has a lock on the data set. I used =X to get out of the ISPF session, and this usually freed it up.

I could it was easiest to run IPCS in batch – it saved lots of typing, and starting/stopping CTRACE when I had got it wrong.

There may still be a timing window, where the trace writer would not stop. When I stopped gsksrvr, the trace writer stopped.