AT-TLS on z/OS provides TLS support for applications by magically inserting itself into an application using TCP/IP, without changing the application.
You can collect a trace of AT-TLS starting up, but I was interested in tracing the handshake.
- If syslogd (system wide program for collecting log data) is active, then trace will be written to the Unix file system.
- if syslogd is not active then the data is written to syslog.
- You can configure it so errors get written to syslog and syslogs.
My server COLATTLS started task is a program acting as a TCP/IP program, with Program Control, so my application gets to interface with AT-TLS, extract information and control the connection.
AT-TLS definitions
In my AT-TLS definitions I had
TLSConnectionAction TNCA
{
TTLSCipherParmsRef TLS13TLS12
TTLSSignatureParmsRef TNESigParms
TTLSConnectionAdvancedParmsRef TNCOonAdvParms
CtraceClearText Off
Trace 255
}
This trace statement traces everything. See below for a description of what is traced.
Using syslogd
Syslogd is a daemon for applications, they write data to syslogd, and you configure syslogd to define where the output goes to.
My syslog JCL started task procedure is:
//SYSLOGD PROC
//* Read parms from /etc/syslog.conf
//CONFHFS EXEC PGM=SYSLOGD,REGION=4096K,TIME=NOLIMIT,
// PARM='ENVAR("_CEE_ENVFILE_S=DD:STDENV")/-c -i '
//STDENV DD DUMMY
//SYSPRINT DD SYSOUT=*
//SYSIN DD DUMMY
//SYSERR DD SYSOUT=*
//SYSOUT DD SYSOUT=*
//CEEDUMP DD SYSOUT=*
This reads its control statements from /etc/syslog.conf (the default). See Configuring the syslog daemon. My file has
*.INETD*.*.* /var/log/inetd auth.* /var/log/auth mail.* /var/log//mail -F 640 -D 770 local1.err /var/log/local1 *.err /var/log/errors *.CPAGENT.*.* /var/log/CPAGENT.%Y.%m.%d *.TTLS*.*.* /var/log/TTLS.%Y.%m.%d *.Pagent.*.* /var/log/Pagent.%Y.%m.%d *.TCPIP.*.debug /var/log/TCPIPdebug.%Y.%m.%d *.TCPIP.*.warning /var/log/TCPIP.%Y.%m.%d *.TCPIP.*.err /var/log/TCPIPerr.%Y.%m.%d *.TCPIP.*.info /var/log/TCPIPinfo.%Y.%m.%d *.SYSLOGD*.*.* /var/log/syslogd.%Y.%m.%d *.TN3270*.*.* /var/log/tn3270 *.SSHD*.*.* /var/log/SSHD
The output for *.TCPIP.*.debug goes to a file like /var/log/TCPIPdebug.2023.04.03
The configuration says, for example,
- the output from TCPIP, with priority code debug or less goes to file /var/log/TCPIPdebug…
- the output from TCPIP, with priority code info or less goes to file /var/log/TCPINFO…
- the output from TN3270 goes to /var/log/tn3270 – for all priorities.
Because “debug” is debug or lower, the file will also contain the “info” messages. Some messages are written to multiple files.
Note: although my application started task was called COLATTLS, the ATTLS trace came out from job TCPIP, not COLATTLS.
AT-TLS trace
The trace for application is configured with the TRACE option in definitions. The documentation says (TTLSGroupAction, and TLSEnvironmentAction):
Trace
Specifies the level of AT-TLS tracing. The valid values for n are in the range 0 – 255. The sum of the numbers associated with each level of tracing selected is the value that should be specified as n. If n is an odd number, errors are written to joblog and all other configured traces are sent to syslogd. If this value is specified on the TTLSEnvironmentAction statement, it is used instead of the value from the TTLSGroupAction statement referenced by the same TTLSRule statement.
- 0 – No tracing is enabled.
- 1 (Error) – Errors are traced to the TCP/IP joblog
- 2 (Error) – Errors are traced to syslogd. The messages are issued with syslogd priority code err.
- 4 (Info) – Tracing of when a connection is mapped to an AT-TLS rule and when a secure connection is successfully initiated is enabled. The messages are issued with syslogd priority code info.
- 8 (Event) – Tracing of major events is enabled. The messages are issued with syslogd priority code debug.
- 16 (Flow) – Tracing of system SSL calls is enabled. The messages are issued with syslogd priority code debug.
- 32 (Data) – Tracing of encrypted negotiation and headers is enabled. This traces the negotiation of secure sessions. The messages are issued with syslogd priority code debug.
This means that if tracing the negotiation, it will be written with priority debug. From the *.TCPIP.debug statement in my syslogd definitions, the output will be written to /var/log/TCPIPdebug… .
Info output
The information in the info output looks like (two records for one connections):
Apr 2 17:25:53 S0W1 TTLS[16842781]: 17:25:53 TCPIP
EZD1281I TTLS Map CONNID: 00000032 LOCAL: 10.1.1.2..4000
REMOTE: 10.1.0.2..60742 JOBNAME: COLATTLS USERID: START1
TYPE: InBound STATUS: Appl Control RULE: COLATTLJ ACTIONS:
TNGA TNEA TNCA
This gives information on which rule was selected. For example it gives the local and remote ip address and port; job name and userid. It shows that rule COLATTLJ was used with group TNGA, environment TNEA, and connection TNCA .
Apr 2 17:25:53 S0W1 TTLS[16842781]: 17:25:53 TCPIP
EZD1283I TTLS Event GRPID: 00000007 ENVID: 00000003 CONNID: 00000032
RC: 0 Initial Handshake 0000005011440BB0
0000005011422870 TLSV1.2 C02C
This shows that for the same session (TTLS[16842781]) the initial handshake agreed on the TLS level conversation was at TLS V1.2 and the cipher spec(C02C).
Debug output
For one connection, there were over 130 lines out output in the file.
Some example lines are
EZD1283I TTLS Event GRPID: 00000007 ENVID: 00000000 CONNID: 00000032
RC: 0 Connection InitEZD1284I TTLS Flow GRPID: 00000007 ENVID: 00000004 CONNID: 00000032
RC: 0 Set GSK_KEYRING_FILE(201) start1/TN3270…
EZD1282I TTLS Start GRPID: 00000007 ENVID: 00000003 CONNID:
00000032 Initial Handshake ACTIONS: TNGA TNEA TNCA
HS-ServerWithClientAuthEZD1285I TTLS Data CONNID: 00000032 RECV CIPHER 1603010116
EZD1285I TTLS Data CONNID: 00000032 RECV CIPHER 0100011203031FDDC…
EZD1285I TTLS Data CONNID: 00000032 SEND CIPHER16030309BC0200005…… RC: 0 Call GSK_SECURE_SOCKET_INIT – 0000005011440BB0
… RC: 0 Get GSK_CONNECT_SEC_TYPE(208) – TLSV1.2
… RC: 0 Get GSK_CONNECT_CIPHER_SPEC(207) – C02CYou get
- Events – (trace 8 event)
- the traffic data flowing up and down (trace 32 data)
- the System SSL calls (with return code) (trace 16 flow)
Trace output on syslog – when syslogd not active
Having AT-TLS writing to syslog is not a good idea – it can produce a lot of output. It may be acceptable on a small, low activity, system, tracing the minimum amount of data.
IEF403I COLATTLS - STARTED - TIME=17.16.51
BPXF024I (TCPIP) Apr 2 17:17:03 TTLS 16842781 : 17:17:03 TCPIP
EZD1281I TTLS Map CONNID: 0000002F LOCAL: 10.1.1.2..4000 REMOTE:
10.1.0.2..43012 JOBNAME: COLATTLS USERID: START1 TYPE: InBound
STATUS: Appl Control RULE: COLATTLJ ACTIONS: TNGA TNEA TNCA
BPXF024I (TCPIP) Apr 2 17:17:03 TTLS 16842781 : 17:17:03 TCPIP
EZD1283I TTLS Event GRPID: 00000007 ENVID: 00000000 CONNID: 0000002F
RC: 0 Connection Init
BPXF024I (TCPIP) Apr 2 17:17:03 TTLS 16842781 : 17:17:03 TCPIP
EZD1282I TTLS Start GRPID: 00000007 ENVID: 00000001 CONNID: 00000000
Environment Create ACTIONS: TNGA TNEA **N/A**
BPXF024I (TCPIP) Apr 2 17:17:03 TTLS 16842781 : 17:17:03 TCPIP
EZD1283I TTLS Event GRPID: 00000007 ENVID: 00000002 CONNID: 00000000
RC: 0 Environment Master Create 00000001
BPXF024I (TCPIP) Apr 2 17:17:03 TTLS 16842781 : 17:17:03 TCPIP
EZD1284I TTLS Flow GRPID: 00000007 ENVID: 00000002 CONNID: 0000002F
RC: 0 Call GSK_ENVIRONMENT_OPEN - 0000005011421D10
...
The output was produced with AT-TLS trace was enable, and ATTLS was not using the syslogd daemon.
The text in bold is the initial trace entry.
- BPXF024I (TCPIP) Apr 2 17:17:03 TTLS 16842781 : 17:17:03 TCPIP is written because syslogd is not being used.
- EZD1281I TTLS Map CONNID: 0000002F LOCAL: 10.1.1.2..4000 REMOTE: 10.1.0.2..43012 JOBNAME: COLATTLS USERID: START1 TYPE: InBound provides information about which AT-TLS rule is being used for the connection.
- EZD1284I TTLS Flow GRPID: 00000007 ENVID: 00000002 CONNID: 0000002F RC: 0 Call GSK_ENVIRONMENT_OPEN – 0000005011421D10 shows you information about the system ssl call being used.
ColinPaice 