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 CPGSKON

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.

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     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     

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.

Collecting a tcpip packet trace on z/OS.

I needed to collect a packet trace to see the details of a ping request. There is a lot of good documentation, but it is spread around, and not linked up.

It looks like a packet trace is associated with an interface or a device/link pair (but it may not be).

Thanks to Erik Janssen who explained that you can format a packet trace suitable for Wireshark. I’ve added his comments below; and to Peter Vels who pointing out some typos which meant some of the the commands did not work!

Overview

  • The TCPIP trace uses z/OS CTRACE capabilities, which requires a procedure (or job) to write trace data into a file.
  • You need some a procedure (or a job) called the trace write, which CTRACE uses to write to a dataset.
  • You need to start the trace writer
    • You can do this with parmlib members,
    • or reply to a WTOR
  • You need to enable the TCPIP trace
  • Recreate the problem
  • Disable the TCPIP trace
  • Stop the trace writer
    • Either with a parmlib member
    • or with a WTOR
  • Use IPCS to format the trace

Create a procedure to collect the trace

See IBM documentation. My JCL is

//CTWTR PROC 
//DELETE  EXEC PGM=IEFBR14 
//TRCOUT01 DD DSNAME=IBMUSER.CTRACE1, 
// SPACE=(CYL,(10),,CONTIG),DISP=(MOD,DELETE) 
//* 
//IEFPROC EXEC PGM=ITTTRCWR,TIME=999 
//TRCOUT01 DD DSNAME=IBMUSER.CTRACE1, 
// SPACE=(CYL,(10),,CONTIG),DISP=(NEW,CATLG) 
//SYSPRINT DD SYSOUT=* 

Notes:

  • You hard code the data set name, you cannot use symbols
  • You cannot pass parameters to it.
  • Do not specify DCB information, the system determines the best blocking.
  • You can specify more than one trace output data set
  • You might want use multiple procedures such as SYS1TCP1, SYS2TCP2, SYS1TCPP etc.

Start the trace writer

Start the trace writer by hand

TRACE CT,WTRSTART=CTWTR

where CTWTR is the name of your procedure.

Activate the trace collecting for the component

TRACE CT,ON,COMP=SYSTCPDA,SUB=(TCPIP) 

Which then issues WTOR and waits for you to respond to it.

R nn,WTR=CTWTR,END 

By having a WTOR you cannot easily automate the command.

Start the trace by parmlib member

TRACE CT,ON,COMP=SYSTCPDA,SUB=(TCPIP),PARM=name

Name is a member of the parmlib concentration. The name must begin with CT. My member is CTTCPS ( CT TCP Start).

This member has

TRACEOPTS                         
  WTRSTART(CTWTR) WRAP            
  ON  WTR(CTWTR)                  

It is one command to issue. It can be used in automation or scripts because it does not use WTOR.

Once the trace has been started

You can use the DISPLAY TRACE z/OS operator command to display the status

D TRACE,WTR=ALL

gave me

  WRITER  STATUS    HEAD  COMPONENT  SUBNAME                      
 --------------------------------------------------------------   
 CTWTR    ACTIVE          SYSTCPDA  TCPIP                         

d trace,comp=all
or
d trace,comp=systcpda

gave me

 COMPONENT     MODE BUFFER HEAD SUBS 
-------------------------------------
 SYSTCPDA      OFF         HEAD    1 
    NO HEAD OPTIONS                  

Define the trace to TCPIP

V TCPIP,TCPIP,PKTTRACE,ON,…. 

Depending on your system you may need to filter what is collected. If this is a one person z/OS image, you might not need to filter.

You can trace by

  • IP address – if the source or target matches. This means you can capture the trace for just one machine.
  • Interface name
  • Link name
  • Destination port number
  • Source port
  • Protocol TCP, ICMP, UDP

You can trace by having the trace data in a file PKTTRON

PKTTRACE 
   INTFNAME=IFPORTCP6 
   PROT=ICMP 
   ON 

and member PKTTROFF

PKTTRACE 
   INTFNAME=IFPORTCP6 
   PROT=ICMP 
   OFF

and use

v tcpip,,obeyfile,USER.Z25A.TCPPARMS(PKTTRON)

or use the trace command, such as

V TCPIP,TCPIP,PKTTRACE,ON,IPADDR=xx.xxx.xxx.xxx

Is trace enabled?

Surprisingly the display trace command (D TCPIP,,DISPLAY,TRACE) does not display the trace. This command is used to display information about network management applications that use the real-time application-controlled TCP/IP trace network management interface (NMI) to obtain real-time network management data from the TCP/IP stack.

You have to display information about the devices or interfaces.

tso netstat devlinks(intfn ifportcp6

Packet Trace Setting:

   Isolate: No                      OptLatencyMode: No
   TempPrefix: All
 Packet Trace Setting:
  Protocol: ICMP              TrRecCnt: 00000000  PckLength: FULL
  Discard:  NONE
  SrcPort:  *                 DestPort: *         PortNum: *
  IpAddr:   *                 SubNet:   *

If there is no trace, then the Packet Trace section is absent.

Stop the TCPIP trace

You can do the the opposite of when you turned it on, for example

V TCPIP,TCPIP,PKTTRACE,OFF,IPADDR=xx.xxx.xxx.xxx

or use an obeyfile, such as member PKTTROFF (see above).

Stop the trace writer

You can either use

  • TRACE CT,ON,COMP=SYSTCPDA,SUB=(TCPIP) 
  • R nn,WTR=DISCONNECT,END
  • TRACE CT,WTRSTOP=CTWTR

Or

TRACE CT,OFF,COMP=SYSTCPDA,SUB=(TCPIP),PARM=CTTCPP

Where parmlib member CTTTCPP has

TRACEOPTS WTRSTOP(CTWTR) 
  OFF 

If you get

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

Then the trace is still active. Check you have stopped collecting the TCPIP trace, and you have issued the stop writer request.

You have to issue

TRACE CT,OFF,COMP=SYSTCPDA,SUB=(TCPIP),PARM=CTTCPP

a second time for the trace to stop, and the writer to stop.

The data set you specified in the WTR JCL may have some data in it.

You need to use IPCS to format it.

  • IPCS option 0 (Specify Defaults) and enter DSNAME(‘IBMUSER.CTRACE1’)  
  • IPCS option 6 (IPCS Subcommand Entry) and enter

This gives output like the following for PING6 to fe80::7:7:7:7.

From Interface    : IFPORTCP6        Device: QDIO Ethernet6   Full=104 
 Tod Clock        : 2022/09/24 11:30:32.614976                Intfx: 81
 Segment #        : 0                Flags:  Ping In                   
 Source           : fe80::4081:88ff:fec5:b624                          
 Destination      : fe80::7:7:7:7                                      
                                     Asid: 0035 TCB: 00000000          
 QID              : 1                                                  
IpHeader: Version : 6                Header Length: 40                 
 Class:           : 00               Flow: 03CE34                      
 Payload Length   : 64                                                 
 Hops             : 64               Protocol: ICMPv6                  
 Source           : fe80::4081:88ff:fec5:b624                          
 Destination      : fe80::7:7:7:7                                      
                                                                       
ICMPv6                                                                 
 Type/Code        : 80/0             ECHO Request                      
 CheckSum         : 1A35 FFFF                                          
 Id               : 0004             Seq: 1                            
 Echo Data        : 56                                                  

Notes:

  • It says From Interface. This shows data was coming from the interface into TCPIP
  • Flags: Ping In this was ping request
  • It came from fe80::4081:88ff:fec5:b624
  • Heading towards fe80::7:7:7:7 on z/OS
To Interface      : IFPORTCP6        Device: QDIO Ethernet6   Full=104  
 Tod Clock        : 2022/09/24 11:30:32.615816                Intfx: 81 
 Segment #        : 0                Flags:  Ping Out                   
 Source           : fe80::7:7:7:7                                       
 Destination      : fe80::4081:88ff:fec5:b624                           
                                     Asid: 0035 TCB: 00000000           
 Next Hop         : fe80::4081:88ff:fec5:b624                           
IpHeader: Version : 6                Header Length: 40                  
 Class:           : 00               Flow: 03CE34                       
 Payload Length   : 64                                                  
 Hops             : 255              Protocol: ICMPv6                   
 Source           : fe80::7:7:7:7                                       
 Destination      : fe80::4081:88ff:fec5:b624                           
                                                                        
ICMPv6                                                                  
 Type/Code        : 81/0             ECHO Reply                         
 CheckSum         : 1935 FFFF                                           
 Id               : 0004             Seq: 1                             
 Echo Data        : 56                                                                                                                                         

Notes:

  • It says To Interface. This shows data was going to the interface from TCPIP
  • Flags: Ping Out this was ping response
  • It came from fe80::7:7:7:7 on z/OS
  • Heading towards fe80::4081:88ff:fec5:b624. This is the same address as the input request.

The above entries are as expected.

I set up an IP address for my IP V6 interface and did a ping to it (ping6 -I tap2 2000::67:1:1:).

This gave me a trace entry

From Interface    : IFPORTCP6        Device: QDIO Ethernet6   Full=104 
 Tod Clock        : 2022/09/24 11:30:25.470408                Intfx: 81
 Segment #        : 0                Flags:  Ping In                   
 Source           : 2a00:23c5:978f:6e01:307a:2e51:9020:afc5            
 Destination      : 2000::67:1:1
...                                       

Notes:

  • It says From Interface. This shows data was coming from the interface into TCPIP
  • Flags: Ping In this was ping request
  • It came from 2a00:23c5:978f:6e01:307a:2e51:9020:afc5. This is different to the previous address of fe80::4081:88ff:fec5:b624 – on the same machine
  • Heading towards 2000::67:1:1. This tells us the data came in on the IFPORTCP6 interface as before.
  • There was no return Ping Out record, so the request was lost in TCPIP on z/OS.

Using Wireshark to look at the packet flow.

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 Erik 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 8000 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) OPTIONS((SNIFFER(3100,TCPDUMP) NOREASSEMBLY) GMT

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. File -> Open.

IPCS in Batch

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

//IBMIPCS JOB 1,MSGCLASS=H 
//DEL  EXEC PGM=IEFBR14 
//SNIFFER  DD DISP=(MOD,DELETE),DSN=COLIN.SNIFFER, 
//     RECFM=VB,LRECL=8000,SPACE=(CYL,(10,10)),BLKSIZE=32000 
//ALLOC  EXEC PGM=IEFBR14 
//SNIFFER  DD DISP=(NEW,CATLG),DSN=COLIN.SNIFFER, 
//     RECFM=VB,LRECL=8000,SPACE=(CYL,(10,10)),BLKSIZE=32000 
//S1  EXEC PGM=IKJEFT01,REGION=0M 
//STEPLIB  DD  DISP=SHR,DSN=SYS1.MIGLIB 
//SNIFFER  DD DISP=SHR,DSN=COLIN.SNIFFER 
//SYSPRINT DD SYSOUT=* 
//SYSTSPRT DD SYSOUT=* 
//SYSPROC    DD  DISP=SHR,DSN=USER.Z24C.CLIST 
//           DD  DISP=SHR,DSN=ADCD.Z24C.CLIST 
//           DD  DISP=SHR,DSN=SYS1.SBLSCLI0 
//IPCSPARM   DD  DISP=SHR,DSN=SYS1.PARMLIB 
//           DD  DISP=SHR,DSN=ADCD.Z24C.PARMLIB 
//IPCSTOC    DD  SYSOUT=* 
//IPCSDDIR   DD  DISP=SHR,DSN=SYS1.DDIR 
//SYSTSIN DD * 
 IPCS NOPARM 
 SETDEF DA('IBMUSER.CTRACE1')                                         
 DROPD                                                                
CTRACE COMP(SYSTCPDA) OPTIONS((SNIFFER(8000,TCPDUMP) NOREASSEMBLY) GMT
/*                                                                    
 CTRACE COMP(SYSTCPDA) SUB((TCPIP)) LOCAL FULL SUB((TCIP)) GMT SHORT 
    

Note: The CTRACE command has to fit on one line.

Collecting a SYSTCIP trace

trace ct,wtrstart=CTWTR

TRACE CT,ON,COMP=SYSTCPIP,SUB=(tcpip),PARM=ctiezbcp

trace ct,wtrstop=CTWTR

 and use

CTRACE COMP(SYSTCPIP) SUB((TCPIP)) LOCAL FULL

to process it in IPCS.