Re: Multiple joblogs being created for some jobs

After more research, I found this problem is NOT always occurring for this job.
Also found the source for the 3rd party vendors program.
The job does send many messages to programs message q.
I believe these messages are filling up the program message, which result in the job message q filling, which sometimes results is a CPI2417, but not always.
The job log is not full, but job message.
This job also sends to a dtaq.
If the other job on the system that reads this dataq is not running, the dataq also fills up.
S001NITE19 trp1 message - Storage limit exceeded for data queue PTMDTAQ001.
However, I'm not sure if the filling of the dataq is related.

My next question is does a job have more than one message q, one for the joblog and one for program messages?

CSR ZASNMS BEGSR
*===================================================
* Send message to program's message queue
*===================================================
C IF ZAPGMQ = ' '
C MOVEL ZZPGM ZAPGMQ
C END
* If no message file specified, use default
C IF ZAMSGF = ' '
C MOVEL ZADFMF ZAMSGF
C END
C CALL 'Y2SNMGC'


Paul


-----Original Message-----
From: MIDRANGE-L [mailto:midrange-l-bounces@xxxxxxxxxxxx] On Behalf Of CRPence
Sent: Thursday, August 14, 2014 4:29 PM
To: midrange-l@xxxxxxxxxxxx
Subject: Re: Multiple joblogs being created for some jobs

On 14-Aug-2014 13:44 -0500, Steinmetz, Paul wrote:

With logging set to 4, 0, *MSG, Log CL *yes, could there be messages
that are within the job that don't appear in the joblog, thus filling
up the job message q, causing the message to wrap.

Yes. Not everything that will count against the JMQ storage will be /visible/ in a displayed joblog, and not only because of filtering. A formatted dump of the job's message queue might assist one to infer something, with regard to the full-condition; no help for catching what effects the spooling, though I already described in another reply how finding the invoker of QMHJLOG processing can be done.

FWiW I recall similar cases whereby all joblogs _were_ caused by the *PRTWRAP, and effectively only the last presented any data; all the prior QPJOBLOG spools were either quite small or effectively empty. I no longer recall the details, but supposing... Perhaps: * the jobs spent most of their early processing doing requests that generated a large number of both *Notify and automatic *Reply message types; possibly the algorithm attempting to keep the JobMsgQ from filling does not work aggressively against those message types. The database for example, especially for I\O conditions, heavily relies on notify-messages and their default replies; code that inserts into a unique key access path will get a duplicate key exception manifest first as a notify and default-cancel reply. * I really doubt that *Status messages sent to *EXT account for filling the JMQ, but perhaps the request to CHGJOB
STSMSG(*NONE) [or as established at job initiation from the *USRPRF] could matter.? * CL request messages may also be less aggressively pruned, and while not visible per LOGCLPGM(*NO) [perhaps defined as an attribute in the program, or changed\reset in the job during run-time with CHGJOB], they may /fill/ the JMQ; thus a huge number of loops on a CALL could quickly fill the JMQ, but per no logging of the actual *RQS msg, the displayed joblog shows effectively nothing.

I may be completely mis-remembering, but I think the JMQ may be initially divided into what are effectively /buckets/ whereby different types of messages are deposited into their own buckets; probably at least one bucket for each type [though some types might share a bucket] is maintained as a minimum. As each new message arrives, according to the MsgType the message is stored in the active bucket receiving that type. If there is no active bucket, another bucket is carved-out.
Pruning likely occurs when there is no more room for the current message in the respective bucket. A bucket purposed for a particular message type [except probably a reserve bucket of some minimal size for each message type] may be reclaimed to become a newly active bucket capable of receiving new messages, if all of the specific type of the old messages had been deleted from that assigned location\bucket; any bucket that is found empty can be reused to start filling again with the same message types or be re-purposed for another message type that is being sent but has no room in any existing bucket. As I recall, that implementation is reflected in messaging that warns about /many messages of type &1/ are being sent repeatedly; thus the buckets are likely to skew toward holding those types. One could imagine, if that were the implementation, that any type of message that might not be /deleted/ in the sense required to enable repurposing the buckets, might lead to what migh
t be described as a premature filling of a JMQ.

But then I should have seen 158 CPI2417 - Job message queue for
978872/TRP1/S001NITE19 has been wrapped.

I agree, *if* the origin of the other spooled joblog(s) were per the Print Wrap (*PRTWRAP) effect. Again, likely easily determined what effects each of the spooling requests using service\debug\addbkp\wrkjob.

There must be something else that I am missing.

Missing, are end-user tooling to help figure out what fills a JMQ.
The joblog spooling that occurs outside of *PRTWRAP and *ENDJOB are most likely obtained using the Display Job Log (DSPJOBLOG) with OUTPUT(*PRINT); I do not recall any callable methods\API to produce a spooled joblog outside of that CL command. The _command exit_ features and object auditing [for command-string] both can assist to find usages in a particular job; and presumably also the invoking program.

FWiW: Might be interesting to review what SNDLOGMSG in TPIC08XXP is doing; besides of course, the visible RETURN statement logged as a request message, showing in the message quoted below. Interesting, based solely on the apparent /Send Log Message/ moniker.

Regards, Chuck

Steinmetz, Paul on Thursday, August 14, 2014 2:11 PM wrote:

Same job on production LPAR does not wrap, only 1 joblog.
Logging is set the same on both LPARS.

Logging level is:

Message logging:
Level . . . . . . . . . . . . . . . . . . . . . : 4
Severity . . . . . . . . . . . . . . . . . . . : 0
Text . . . . . . . . . . . . . . . . . . . . . : *MSG
Log CL program commands . . . . . . . . . . . . . : *YES
Job log output . . . . . . . . . . . . . . . . . : *JOBEND

Creation times for the joblogs are every 21 seconds.
There is no overlap.
The beginning and end time of each message does not match the creation time of the QPJOBLOG.
Only the final 159 spoolfile matches.
The final joblog is 62 times larger (5,164 pages) then 2 thru 158 (81
pages)


CPF1124 Information 00 08/12/14 11:05:56.716813
QWTPIIPP QSYS 04C0 *EXT *N
Message: Job 978872/TRP1/S001NITE19 started on 08/12/14 at 11:05:56
*NONE Command 08/12/14 11:09:46.483656
QCADRV QSYS 03BA YOBSYSDTE TPNI08XXP 002B
Message: 2104 - RTVSYSVAL SYSVAL(QMINUTE) RTNVAR(&MINUTE)
*NONE Command 08/12/14 11:09:46.483700
QCADRV QSYS 03BA YOBSYSDTE TPNI08XXP 0032
Message: 2105 - RTVSYSVAL SYSVAL(QSECOND) RTNVAR(&SECOND)
*NONE Command 08/12/14 11:10:17.400577
QCLRTNE QSYS 0058 SNDLOGMSG TPIC08XXP 001D
Message: - RETURN /* RETURN due to end of CL program
*NONE Command 08/12/14 13:29:49.543490
QCADRV QSYS 03BA IGI0101CL TPIC08XXP 000F
Message: 2700 - RTVJOBA CURUSER(&USER)
CPF1164 Completion 00 08/12/14 14:04:29.274001
QWTMCEOJ QSYS 014A *EXT
Message: Job 978872/TRP1/S001NITE19 ended on 08/12/14 at 14:04:29;

--
This is the Midrange Systems Technical Discussion (MIDRANGE-L) mailing list To post a message email: MIDRANGE-L@xxxxxxxxxxxx To subscribe, unsubscribe, or change list options,
visit: http://lists.midrange.com/mailman/listinfo/midrange-l
or email: MIDRANGE-L-request@xxxxxxxxxxxx Before posting, please take a moment to review the archives at http://archive.midrange.com/midrange-l.