Wednesday, December 14, 2016

Searching the History log using SQL

history_log_info better way to get entries from the history log

I am sure I am not the only person who has received a message, email, or telephone call informing me that there was an error message that happened earlier. When I reply asking for more details it is not uncommon to be told: "I don't know what the error was, I just replied with a C". This, of course, tells me nothing useful to be able to make a diagnosis what and where the error happened. Often it drives me to the History log which I have to search through looking for an error message. Narrowing the possible time frame makes the searching easier, but if the best the message sender can tell me is "earlier this afternoon" or "during the day end run" I am left with a large amount of log data to search through.

IBM has come to my rescue with a DB2 of i (SQL) table function that allows me to search the History log and select the data I want to see. I am not sure if this is part of the IBM i 7.3 TR1 and 7.2 TR5 updates. You can search to see if it is present on your IBM i using the PTF information View, PTF_INFO, to look for relevant PTF:

  • IBM i 7.3 SF99703 Level 3
  • IBM i 7.2 SF99702 Level 14

The HISTORY_LOG_INFO table function when used in its simplest form gives all the same information that looking at the History log does.

SELECT * FROM TABLE(QSYS2.HISTORY_LOG_INFO()) A

Which in my opinion is overwhelming as the History log output.

I can narrow the date and time range, as I can with the History log by using the Table function's two parameters. The parameters are timestamps.

01 SELECT * 
     FROM TABLE(QSYS2.HISTORY_LOG_INFO(CURRENT TIMESTAMP - 1 DAY)) A

02  SELECT * 
      FROM TABLE(QSYS2.HISTORY_LOG_INFO('2016-11-30-06.00.00.000000',
                                        '2016-11-30-12.00.00.000000')) A

Line 1: As only one parameter is used it is assumed that this is the from timestamp. In this case I want to start one day before the current time.

Line 2: I have given two parameters, they must be separated by a comma ( , ).

While this reduces the amount of data I have retrieved I am still left with a lot of log entries I don't care about, for example, successful completion of jobs, etc.

As this is a Table function I can use a SQL Select command to refine the search criteria I use to find the data I want. Before I give examples let me list what I consider to be the useful columns I will be using.

Column name Description
ORDINAL_POSITION Unique number of the entry. The older the entry the lower the number.
MESSAGE_ID Message id.
MESSAGE_TYPE Type of the message. I am not going to list them all here, if you want to know all the possible values see the link provided at the bottom of this post.
SEVERITY Severity of the message.
MESSAGE_TIMESTAMP The timestamp when the message was sent to the History log.
FROM_USER User of the job.
FROM_JOB Full job name.
MESSAGE_TEXT First level message text. This is in a VARGRAPHIC column in CCSID 1200 so I will need to CAST it to make it readable on my IBM i.
MESSAGE_SECOND_LEVEL_TEXT Second level message text. This is in a VARGRAPHIC column in CCSID 1200 so I will need to CAST it to make it readable on my IBM i.

There are other columns, but as I am not going to use them I will refer you to the link at the bottom of this post.

With these columns I can create a Select statement to list all errors in my desired date range.

01  SELECT MESSAGE_ID,
02         MESSAGE_TYPE AS MESSAGE_TYPE
03         SEVERITY
04         MESSAGE_TIMESTAMP AS TIMESTAMP,
05         FROM_USER,
06         FROM_JOB,
07         CAST(MESSAGE_TEXT AS CHAR(200) CCSSID 37)
               AS MESSAGE_TEXT,
08         CAST(MESSAGE_SECOND_LEVEL_TEXT AS CHAR(1000) CCSSID 37)
               AS MESSAGE_TEXT_2
09    FROM TABLE(QSYS2.HISTORY_LOG_INFO('2016-12-03-16.00.00.000000',
                                        '2016-12-03-16.15.00.000000')) A
10   WHERE SEVERITY >= 30
11   ORDER BY ORDINAL_POSITION

I am using the AS, on lines 2, 4, 7, and 8 to give the column labels some more meaningful label. For example, "MESSAGE_TYPE" is easier to understand than "MESSA00001".

Lines 7 and 8: I use the CAST to convert these columns into something I can read.

Line 9: I am giving the date and time range I desire as parameters in the Table function.

Line 10: I only want to know about any log entry with a severity of 30 or greater.

Line 11: I want to sort by oldest first.

This gives me (I have broken it out into separate lines just to display it here).


MESSAGE_ID  MESSAGE_TYPE SEVERITY  TIMESTAMP                   FROM_USER  FROM_JOB
 RNQ1216    INQUIRY           99   2016-12-03-16.09.54.579968  SIMON      026063/SIMON/TESTRPG   
 RNQ1216    INQUIRY           99   2016-12-03-16.10.02.045824  SIMON      026063/SIMON/TESTRPG   
 -          REPLY             99   2016-12-03-16.10.02.099072  SIMON      026052/SIMON/QPADEV0013



MESSAGE_TEXT
Error message CPF4131 appeared during OPEN for file TESTDSPF (C S D F).                
Error message CPF4131 appeared during OPEN for file TESTDSPF (C S D F).                
C                                                                                      


MESSAGE_TEXT_2
&N Cause . . . . . : RPG procedure TESTRPG in program MYLIB/TESTRPG received the message CPF4131
&N Cause . . . . . : RPG procedure TESTRPG in program MYLIB/TESTRPG received the message CPF4131
-


while performing an implicit OPEN operation on file TESTDSPF. The actual file is TESTDSPF.
while performing an implicit OPEN operation on file TESTDSPF. The actual file is TESTDSPF.

The equivalent using the DSPLOG command is.

DSPLOG PERIOD((161000 120316) (161500 120316)) OUTPUT(*PRINT)

I would then have to search the generated spool file to discover:


MSGID    SEV MSG TYPE
RNQ1216  99  INQUIRY      Error message CPF4131 appeared during OPEN for file TESTDSPF (C S D F).
                      TESTRPG    SIMON     026063 QMHSCLVL     0000 16-12-03 16:10:02.913396 SIMON
         99  VALID RPY    C
                      QPADEV0013 SIMON     026052 QMHSCLVL     0000 16-12-03 16:10:02.913409 SIMON

In my opinion using the HISTORY_LOG_INFO gives me what I want a lot quicker and easier than searching through the output from the DSPLOG command. I for one will be using these Table function the next time I get one of those "There was an error and I don't know when" communications.

 

You can learn more about the HISTORY_LOG_INFO Table function from the IBM website here.

 

This article was written for IBM i 7.3 TR1 and should work with 7.2 TR5 too.

6 comments:

  1. Looking forward to it, since I am Rocking 7.1 right now and I just did a search and we do not have that function...

    ReplyDelete
  2. Thank you so much for the article. In terms of logs is there any way to retrieve in 7.1 a Log for a job that is gone?
    Thanks.

    ReplyDelete
  3. Long story short, No. If QPDSPJOB spooled file for the job is no longer in the system or in FIN status, the job is gone.

    ReplyDelete
  4. Another reason to move on from v7r1. I like the ease for looking at log.

    ReplyDelete

To prevent "comment spam" all comments are moderated.
Learn about this website's comments policy here.

Some people have reported that they cannot post a comment using certain computers and browsers. If this is you feel free to use the Contact Form to send me the comment and I will post it for you, please include the title of the post so I know which one to post the comment to.