Prestart Job Messages
This article reviews the messages sent by various types of prestart jobs and provide examples of how to gather useful information from these messages.
By Dawn May01/04/2019
Many prestart jobs log messages to both the job log and the history log. This article will review the messages sent by various types of prestart jobs and provide examples of how to gather useful information from these messages.
As the number of users connecting to your partition increases, you may notice a lot of messages logged to the history log. The messages from these server jobs may be distracting if you are looking for other messages. When using DSPLOG, you can use the MSGID parameter along with the MSGIDSLT(*OMIT) parameter to omit messages you’re not interested in. You can also use the History Log task in Navigator for i to display the history log. It also supports omitting messages you don’t want to review.
Host Servers History Log Messages
The host servers all log similar messages to the job log and the history log.
When a work request is received, the server job logs a CPIAD09 message to the history log.
The CPIAD09 message text is:
User USERNAME from client 127.0.0.1 connected to job 123456/QUSER/QZDASOINIT in subsystem QUSRWRK in QSYS on 11/12/18 00:13:23.
These messages can be useful to gain insight into what users are connecting to your partition. They can also be useful for determining where in the network the requests are coming from. Using the QSYS2.HISTORY_LOG_INFO() service, you can summarize information from these messages.
The following example shows how to determine which users connect to the system.
In this example, I first create a table in QTEMP to hold the results from the QSYS.HISTORY_LOG_INFO() service, using a WHERE clause to only return the CPIAD09 messages. This will make subsequent queries run faster since we are working with fewer messages. You can optionally specify start and end times on the QSYS2.HISTORY_LOG_INFO() service.
CREATE TABLE QTEMP.QHST AS
(SELECT * FROM TABLE(QSYS2.HISTORY_LOG_INFO()) x WHERE MESSAGE_ID = 'CPIAD09')
Now I can run various queries to review the messages from prestart jobs. The SQL statement below provides a summary of which users connected to which host server jobs. This SQL statement retrieves all the CPIAD09 messages, parses out the job name, then groups the results for each server type by current user profile.
SELECT COUNT(*) AS "Total",
SUBSTRING(FROM_JOB, LOCATE('/', SUBSTRING(FROM_JOB, 8))+8) as "Job",
FROM_USER AS "Current User"
WHERE MESSAGE_ID = 'CPIAD09'
GROUP BY SUBSTRING(FROM_JOB, LOCATE('/', SUBSTRING(FROM_JOB, 8))+8), FROM_USER
ORDER BY 1 DESC;
The results will be similar to this:
You can expand upon this example by reviewing the connections by remote IP address or subsystem. You could use the MESSAGE_TIMESTAMP to determine when users are connecting or calculate rates during specific time frames.
There is one anomaly in the CPIAD09 messages sent to the history log. If you are routing work to subsystems by user profile, you will discover there are two CPIAD09 messages in the history log for each connection. Both of the CPIAD09 messages are sent from a server job in the QUSRWRK subsystem, making the ability to do effective analysis as I’ve reviewed above limited.
I have submitted an RFE, Routing Work by User Profile results in two CPIAD09 Message in QHST, both sent from a job in QUSRWRK, to request a change to this behavior. If you agree this is a good change, vote for the RFE.
The following screen capture shows these two messages as viewed with Navigator for i.
Host Servers Job Log Messages
The host servers (with the exception of the file server) log message CPIAD02 - User USER from client 127.0.0.1 connected to server - to the job log. The USER name is the current user profile. If the job ends unexpectedly and a job log is produced, this message in the job log is useful since it tells you who was using the job at the time of the failure. In addition, this message tells you where the client connected from, whether internal in the system (loopback or 127.0.0.1) or the remote IP address of the client.
The Signon Server (QZSOSIGN) job logs CPIAD0B to the history log and to the job log. This message has additional information regarding the type of sign on request that was handled.
Message . . . . : *SIGNON server job &3/&2/&1 processing request for user &4
on &5 in subsystem &6 in &7.
Cause . . . . . : The *SIGNON server is processing request &8 for user &4.
The types of requests supported are as follows:
1 -- Retrieve Signon Information
2 -- Change Password
3 -- Generate Authentication Token
4 -- Generate Authentication Token on Behalf of Another User
5 -- Start Server
DDM/DRDA Server (QRWTSRVR) Job Log Messages
The DDM/DRDA server behaves similar to the host servers, but rather than the CPIAD09 message sent to the history log, CPI3E34 is sent. The message text is identical to CPIAD09.
The DDM/DRDA job log has message CPI9162:
Target job assigned to handle DDM connection started by source system over TCP/IP.
If you are routing work by user profile using the QSYS2.SET_SERVER_SBS_ROUTING() procedure, the DDM/DRDA server job log logs information about this in the job log with CPI9164.
Message . . . . : Database connection rerouted from target job
Cause . . . . . : User profile DAWNM was configured to reroute incoming
distributed data management (DDM) TCP/IP connections using that user profile
to a user specified subsystem QUSRWRK. This connection was rerouted from
target job 083074/QUSER/QRWTSRVR to target job 083075/QUSER/QRWTSRVR. This
may also occur if the user profile is a member of a group profile or
supplemental group profile that has been configured to reroute incoming
distributed data management (DDM) TCP/IP connections.
SQL Server (QSQSRVR) Job Log Messages
The current user of the job is logged to the job log as a completion message with no message ID:
User Profile = QSECOFR.
In addition, CPF9898 - SERVER MODE CONNECTING JOB IS 123456/JOBNAME/JOBUSER is logged to the job log. This message is very useful since it tells you which job is using SQL Server Mode to run the request in the QSQSRVR job.
Access Client Solutions provides an example SQL statement to review SQL Server Mode use:
-- category: IBM i Services
-- description: Work Management - Active Job info - SQL Server Mode study
-- Find active QSQSRVR jobs and the owning application job
WITH tt(authorization_name, job_name, cpu_time, total_disk_io_count)
AS (SELECT authorization_name, job_name, cpu_time, total_disk_io_count
FROM TABLE(qsys2.active_job_info(SUBSYSTEM_LIST_FILTER => 'QSYSWRK', JOB_NAME_FILTER
=> 'QSQSRVR')) x)
SELECT authorization_name, ss.message_text, job_name, cpu_time, total_disk_io_count
FROM tt, TABLE(qsys2.joblog_info(job_name)) ss
WHERE message_id = 'CPF9898' AND from_program = 'QSQSRVR'
ORDER BY CPU_TIME DESC;
This service returns results similar to the following:
File Server (QPWFSERVSO) Messages
The file server job (QPWFSERVSO) logs the CPIAD09 message to the history log, like the rest of the host servers.
It also logs CPIAD12 to the job log, which is similar to the CPIAD02 message the other host servers send.
Servicing user profile USER from client LOOPBACK.
Client Special Registers
Client special registers are logged to the job log with message SQL799C. An example application that uses client special registers is Access Client Solutions Run SQL Scripts. The following is an example of what you see in the job log:
The following special registers have been set:
CLIENT_ACCTNG: Mac OS X;SSL=true;admin_user=false, CLIENT_APPLNAME: IBM i Access Client Solutions - Run SQL Scripts, CLIENT_PROGRAMID: file:/Volumes/MyHD/IBM%20i%20Work%20Files/%20IBM%20i%20Access/IBMiAccess_v1r1/acsbundle.jar, CLIENT_USERID: dawnmay, CLIENT_WRKSTNNAME: 65-78-2-50.s560.c3-0.nyr-cbr3.nyr.ny.cable.rcncustomer.com
Other applications that use client special registers will have them logged to the job log as well. Read the blog Use Client Special Registers for more information on them.
Of course, for every job, the CPF1124, job started, and the CPF1164, job ended, messages are also logged to the history log. Note that for prestart jobs, the performance metrics in the CPF1164 message, such as CPU time used and temporary storage used, are the total for the life of the job.
About the author
Dawn May is an IBM i consultant. She owns Dawn May Consulting, LLC in the Greater Boston area. Dawn is a former IBM senior technical staff member.
See more by Dawn May