SYSOUT with JOGLVL(+I) weird wrap of CLASSPATH printout

General discussion on the JZOS batch launcher and toolkit
Post Reply
rschramm
Posts: 17
Joined: Fri Aug 05, 2005 1:23 pm
Location: Indianapolis, IN

SYSOUT with JOGLVL(+I) weird wrap of CLASSPATH printout

Post by rschramm »

Warning.. this may bit of picking nits. :)

So, I am doing a little bit of testing with a java application. I set the LOGLVL='+I' and the output on the CLASSPATH wraps and breaks wierdly.

Here is a copy of the SYSOUT in question:

Code: Select all

JZOSVM14(I): CLASSPATH=/u/TestApp/TestApp.jar:/u/TestApp/lib/commons-collections-3.1.jar:/u/TestApp/lib/commons- 
configuration-1.1.jar:/u/TestApp/lib/commons-httpclient-2.0.2.jar:/u/TestApp/lib/commons-lang-2.1.jar:/u/TestApp/l 
ib/commons-logg                                                                                                          
ing.jar::/u/TestApp/::/u/jzos/application.jar:/u/jzos/junit.jar:/u/jzos/jzos.jar:/u/jzos/jzos_log4j.jar:               
It is just a bit weird to look at. The first 2 lines wrap as I would expect.. but line 3 is.. well.. a bit chopped off.

Any thoughts about why?
Rob Schramm
dovetail
Site Admin
Posts: 2022
Joined: Thu Jul 29, 2004 12:12 pm

Post by dovetail »

All of the line wrapping is actually handled by the C/C++ io library ("text" mode stream files are wrapped onto datasets according to a set of rules defined by the z/OS C library). So, I'm really not sure what is happening.

It would be helpful if you could email me the full job output in a file to dev@jzos.com.


BTW- One way to get the output in a file is to use ftp:

ftp <host>
quote site filetype=jes
get JOBnnnn output.txt
dovetail
Site Admin
Posts: 2022
Joined: Thu Jul 29, 2004 12:12 pm

Post by dovetail »

Its a little strange and at the moment I can't explain it.
The messages are being written to stderr (DD:SYSOUT) using fprintf. What is happening is that apparently the output line is first wrapped at 255 bytes, and then re-wrapped at 121 bytes. I'm at a loss to understand why fprintf() would do that. Perhaps there's a second level of wrapping because of it being a JES dataset?

Fortunately, this behavior is completely harmless, it just looks a little funny.

But its curious, none the less. What happens if you explicitly set the DCB on the SYSOUT file to say DCB=(RECFM=VBA,LRECL=133) ? Maybe this will give us a hint...
Guest

Post by Guest »

I will give it a try and let you know.

I gather from your comments that you have not seen this behavior before.

Any chance it is some sort of LE option?
Guest

Post by Guest »

That fixed it. :D

I coded the DCB on SYSOUT and the output is wrapping correctly now.
rschramm
Posts: 17
Joined: Fri Aug 05, 2005 1:23 pm
Location: Indianapolis, IN

Post by rschramm »

I keep forgetting to log back in to the forum before posting my response. :wink:
Rob Schramm
dovetail
Site Admin
Posts: 2022
Joined: Thu Jul 29, 2004 12:12 pm

Post by dovetail »

Wierd... I can't explain why it would go through two line wrappings otherwise.

Just checking, but did you use DCB=(RECFM=VBA,LRECL=133)? Did it then wrap correctly (and only once) at column 133?

If so, we will probably want to update our sample JCL on the next release.

Also, it seems pointless now that I think about it to use VBA, VB is probably fine since the C library probably will never insert ANSI carriage control.

Thanks.
rschramm
Posts: 17
Joined: Fri Aug 05, 2005 1:23 pm
Location: Indianapolis, IN

Post by rschramm »

Funny you should ask me to confirm:
Here is a copy of the lines from a SDSF display with hex turned on..

Code: Select all

 JZOSVM14(I): CLASSPATH=/u/RaftProxy/RaftProxy.jar:/u/RaftProxy/lib/commons-collections-3.1.jar:/u/RaftProxy/lib/commons-configur   
4DEDEEDFF4C574CDCEEDCEC76A6D88AD99AA6D88AD99AA498976A6D88AD99AA69886899999A6899988A899A6F4F498976A6D88AD99AA69886899999A6899888A9444
019625414D9DA0331227138E1419163796781916379678B119A14191637967813921364465203633533965203B1B119A141916379678139213644652036569749000
 ---------------------------------------------------------------------------------------------------------------------------------- 
 ation-1.1.jar:/u/RaftProxy/lib/commons-httpclient-2.0.2.jar:/u/RaftProxy/lib/commons-lang-2.1.jar:/u/RaftProxy/lib/commons-logg    
48A8996F4F498976A6D88AD99AA69886899999A68AA989889A6F4F4F498976A6D88AD99AA69886899999A698986F4F498976A6D88AD99AA69886899999A699884444
01396501B1B119A1419163796781392136446520833733955302B0B2B119A1419163796781392136446520315702B1B119A141916379678139213644652036770000
 ---------------------------------------------------------------------------------------------------------------------------------- 
 ing.jar::/u/RaftProxy/::/u/jzos/application.jar:/u/jzos/junit.jar:/u/jzos/jzos.jar:/u/jzos/jzos_log4j.jar:                         
48984989776A6D88AD99AA6776A69A9A68999888A899498976A69A9A69A98A498976A69A9A69A9A498976A69A9A69A9A6998F9498974444444444444444444444444
0957B119AA1419163796781AA1411962117739313965B119A1411962114593B119A141196211962B119A141196211962D36741B119A0000000000000000000000000
While the output looks a lot better, there is a x'40' one character too early on 2nd line of output.

The jcl that produced it:

Code: Select all

//SYSOUT   DD SYSOUT=*,         < System stderr
//            DCB=(RECFM=VBA,LRECL=133)        
Interestingly enough the STDERR output with the logging set to debug produces the output correctly:

Code: Select all

 2005/09/01 16:32:14:663 EDT [DEBUG] Java class path: /u/RaftProxy/RaftProxy.jar:/u/RaftProxy/lib/commons-collections-3.1.jar:/u/Raft
4FFFF6FF6FF4FF7FF7FF7FFF4CCE4ACCCECB4D8A84898AA498A8746A6D88AD99AA6D88AD99AA498976A6D88AD99AA69886899999A6899988A899A6F4F498976A6D88A
02005109101016A32A14A66305430D45247D0115103312207138A01419163796781916379678B119A14191637967813921364465203633533965203B1B119A1419163
  ---------------------------------------------------------------------------------------------------------------------------------- 
 Proxy/lib/commons-configuration-1.1.jar:/u/RaftProxy/lib/commons-httpclient-2.0.2.jar:/u/RaftProxy/lib/commons-lang-2.1.jar:/u/RaftP
4D99AA69886899999A6899888A98A8996F4F498976A6D88AD99AA69886899999A68AA989889A6F4F4F498976A6D88AD99AA69886899999A698986F4F498976A6D88AD
0796781392136446520365697491396501B1B119A1419163796781392136446520833733955302B0B2B119A1419163796781392136446520315702B1B119A14191637
  ---------------------------------------------------------------------------------------------------------------------------------- 
 roxy/lib/commons-logging.jar::/u/RaftProxy/::/u/jzos/application.jar:/u/jzos/junit.jar:/u/jzos/jzos.jar:/u/jzos/jzos_log4j.jar:     
499AA69886899999A699888984989776A6D88AD99AA6776A69A9A68999888A899498976A69A9A69A98A498976A69A9A69A9A498976A69A9A69A9A6998F94989744444
0967813921364465203677957B119AA1419163796781AA1411962117739313965B119A1411962114593B119A141196211962B119A141196211962D36741B119A00000

Of course there is another oddity when I am looking down a bit in hex the stack traces in STDERR have a x'05' at the beginning of each line.

Code: Select all

 at java.lang.Thread.run(Thread.java:568)       
08A498A8498984E8988849A94E89888498A87FFF54444444
51301151B3157B389514B945D389514B1151A568D0000000
Rob Schramm
dovetail
Site Admin
Posts: 2022
Joined: Thu Jul 29, 2004 12:12 pm

Post by dovetail »

Wierd. As I mentioned, JZOS just uses fprintf(stderr, ...) to write these messages. There seems to be some wierd bugs in the C library stream->dataset conversion. I'm not sure if it is significant enough to endure the pain of reporting it :-) What's your opinion? I will try to reproduce it with a tiny C-program...

Btw: I'm guessing that the X'05' is just a tab character coming from the Java stack trace. So this seems fine to me.
rschramm
Posts: 17
Joined: Fri Aug 05, 2005 1:23 pm
Location: Indianapolis, IN

Post by rschramm »

If you could do the test with a small C program... I can do the reporting to IBM about it.

I agree.. it is a bit on the minor side.. but I would like things to be as right as can be. The whole idea of running java and using jzos to redirect the output io streams to jes2 is really cool... I like the idea of being able to show off what the advantages of the mainframe are.
Rob Schramm
dovetail
Site Admin
Posts: 2022
Joined: Thu Jul 29, 2004 12:12 pm

Post by dovetail »

Sounds like a great deal to me!

I'll try to put something a small "C" test case in the next couple of days.

Thanks!
dovetail
Site Admin
Posts: 2022
Joined: Thu Jul 29, 2004 12:12 pm

Post by dovetail »

(here it is)
... a sample C program and JCL to demonstrate this bug (feature?) of the C fprintf function.

If you try it you will see that a lines are first wrapped into 255-character chunks, and then wrapped again to the LRECL of the output dataset. (This explains all of the examples that you posted above if you look closely).

Code: Select all

//WOLF1LW JOB (),'DOVETAIL',CLASS=B,
// MSGCLASS=H,REGION=0M,NOTIFY=WOLF1
//*
//* JCL to compile and run C stderr line-wrap test
//*
//BLD EXEC PROC=CBCCBG,
// CPARM='OPTFILE(DD:CCOPT)',
// BPARM='COMPAT=MIN',
// OUTFILE='WOLF1.LOADLIB(LINEWRAP),DISP=SHR'
//COMPILE.SYSIN DD *





int main(int argc, char** argv) {
    char buf[600];
    char digits[11] = "0123456789";
    int len;
    memset(buf, 0, sizeof(buf));

    // write sucessive lines between 5 and 550 characters in length
    for (len=5; len<=550; len++) {
        // the first 4 characters of each line are "nnn:"
        buf[0] = '\0';
        sprintf(buf, "%3.3d", len);
        buf[3] = ':';
        // each successive line is one digit longer
        buf[len-1] = digits[len % 10];
        fprintf(stderr, "%s\n\n", buf);
    }
}
//COMPILE.CCOPT DD *
LANGLVL(EXTENDED)
FLOAT(IEEE)
TARGET(OSV2R10)
//BIND.SYSPRINT DD DUMMY
//*
//* The following are different options for SYSOUT DCB.
//* (Uncomment the one you want to try)
//*
//* In each case, a line-break is somehow inserted after each
//* 255 bytes that are written in a line (before normal line-wrapping
//* occurs).
//*
//* Note that for RECFM=VB, the max line length should be LRECL-4
//* .. for RECFM=VBA,the max line length should be LRECL-5
//* .. for RECFM=FB, the max line length should be LRECL
//* .. for RECFM=FBA,the max line length should be LRECL-1
//*
//* Question: whats the most efficient for JES Sysout (VB or FB)?
//* Should blksize be specified, or just take default?
//*
//*GO.SYSOUT DD SYSOUT=*
//GO.SYSOUT DD SYSOUT=*,DCB=(RECFM=VBA,LRECL=133)
//*GO.SYSOUT DD SYSOUT=*,DCB=(RECFM=VBA,LRECL=137)
//*GO.SYSOUT DD SYSOUT=*,DCB=(RECFM=VB,LRECL=136)
//*GO.SYSOUT DD SYSOUT=*,DCB=(RECFM=FB,LRECL=132)
//*GO.SYSOUT DD SYSOUT=*,DCB=(RECFM=FBA,LRECL=133)
//
dovetail
Site Admin
Posts: 2022
Joined: Thu Jul 29, 2004 12:12 pm

Post by dovetail »

We reported this to IBM, and they pointed out that this is how it is supposed to work (its not a bug, its a feature!)

Their response:
=================================

The C/C++ Programming Guide documents that stderr, by default, is directed to the Language Environment Message File. There is a chapter specific to Language Environment Message File, and it the section on "Writing to files" it states...

2.15.3 Writing to files

Data written to the z/OS Language Environment message file is always appended to the end of the file.

When the data written is longer than 255 bytes, it is written to the z/OS Language Environment message file 255 bytes at a time, with the
last write possibly less than 255 bytes. No truncation will occur.

=========================================
Post Reply