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

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

WITH DATA;

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"

FROM QTEMP.QHST 

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.

Signon Server

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              

  083074/QUSER/QRWTSRVR.                                                      

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.

---