Guru: Beefing Up The Job Log, Take Two
August 6, 2018 Ted Holt
In Tracing Routines Explain Why The Computer Did What It Did, I wrote about the usefulness of writing information about program execution to determine why a program run gave certain results. Today I want to present a simpler method than the tracing routines. The tracing routines are not obsolete, but they are powerful and I have found them at times to be overkill.
Just a word about terminology. Since I wrote that article five and a half years ago, my reading has led me to a different understanding of the terms tracing and logging. I’ve since decided that the activity I described in my article was more properly logging, not tracing. For that reason, I use the term logging in this article. In the grand scheme of things, terminology is of little importance.
I often need a way to determine why a program behaved as it did. Sometimes I can use an interactive debugger to accomplish that. Sometimes an interactive debugger won’t answer the purpose, so I resort to logging. IBM i already has an effective logging mechanism — every job has a job log. An easy way, then, to understand program behavior is to write helpful messages into the job log. To do that, I use the Qp0zLprintf API, which Daniel Long shared with me and I wrote about in Beefing Up The Job Log.
Here’s a short program that illustrates the process.
/define LoggingIsOn
H dftactgrp(*no) actgrp(*caller) option(*srcstmt: *nodebugio)
D GrossAmt s 7p 2
D Discount s 7p 2
D Policy s 1a
(. . . more code . . .)
C TAG01 TAG
/if defined(LoggingIsOn)
JobLog ('> TAG TAG01');
/endif
C exsr CalcDiscount
(. . . more code . . .)
C CalcDiscount begsr
/if defined(LoggingIsOn)
JobLog ('> Enter CalcDiscount. Policy=/' + Policy +
'/ GrossAmt=/' + %char(GrossAmt) + '/');
/endif
(. . . more code . . .)
/if defined(LoggingIsOn)
JobLog ('> Leave CalcDiscount, Discount=/' + %char(Discount) + '/');
/endif
C endsr
/if defined(LoggingIsOn)
dcl-proc JobLog;
dcl-pi JobLog;
inMessage varchar(132) const;
end-pi JobLog;
dcl-pr Qp0zLprintf int(10) extproc('Qp0zLprintf');
inMessage pointer options(*string: *nopass) value;
end-pr Qp0zLprintf;
dcl-c EOL const(x'25');
Qp0zLprintf (%trimr(inMessage) + EOL);
end-proc JobLog;
/endif
Let’s look at this code one piece at a time.
/define LoggingIsOn
I use this compiler to include logging during development. When the program goes into production, I change the directive to /undefine so that the logging code does not run in production.
C TAG01 TAG
/if defined(LoggingIsOn)
JobLog ('> TAG TAG01');
/endif
C exsr CalcDiscount
(. . . more code . . .)
C CalcDiscount begsr
/if defined(LoggingIsOn)
JobLog ('> Enter CalcDiscount. Policy=/' + Policy +
'/ GrossAmt=/' + %char(GrossAmt) + '/');
/endif
(. . . more code . . .)
/if defined(LoggingIsOn)
JobLog ('> Leave CalcDiscount. Discount=/' + %char(Discount) + '/');
/endif
C endsr
It is a good to log the tags. Spaghetti code is hard to follow, and logging the tags helps greatly to understand program flow.
You may or may not want to log the entrance to or exit from a subprocedure or a subroutine. In this example, I report that the subroutine to calculate discounts ran, and I log the value of the gross amount and the policy used to calculate the discount. I always surround values with some character, usually a slash or a quotation mark, in case there are embedded blanks of significance in a value.
The leading greater-than signs are not necessary and are only there to make the messages stand out in the job.
To write to the job log, I created a wrapper over Qp0zLprintf. The JobLog subprocedure takes care of the messy details, such as passing a string by pointer and appending a line-feed character to the message.
/if defined(LoggingIsOn)
dcl-proc JobLog;
dcl-pi JobLog;
inMessage varchar(132) const;
end-pi JobLog;
dcl-pr Qp0zLprintf int(10) extproc('Qp0zLprintf');
inMessage pointer options(*string: *nopass) value;
end-pr Qp0zLprintf;
dcl-c EOL const(x'25');
Qp0zLprintf (%trimr(inMessage) + EOL);
end-proc JobLog;
/endif
When I ran this example, the job log had these messages:
> TAG TAG01 > Enter CalcDiscount. Policy=/A/ GrossAmt=/499.49/ > Leave CalcDiscount. Discount=/24.95/
I have two good ways to follow program flow and determine why a program did what it did — the JobLog subprocedure and my trace routines. Both save me a lot of time so that I can do the really important things in life, none of which have anything to do with computers.
RELATED STORIES
Tracing Routines Explain Why The Computer Did What It Did
